When there are not token cached, PEP try to ask Keystone without token

[jcalderin]

The first time PEP tries to ask for information to keystone, PEP hasnt got any token stored in the cache, but it tries to use an empty token to connect to PEP.

Because of the retries, the consequence is, the PEP log in to Keystone and then do the same consult.

There is no an error, but yes an enhancement to check if there are any token before to ask to Keystone for information about the user.

Log first ask from PEP to Keystone

time=2015-01-07T15:12:42.890Z | lvl=INFO | corr=n/a | trans=n/a | op=n/a | msg=Creating proxy
time=2015-01-07T15:12:42.917Z | lvl=INFO | corr=n/a | trans=n/a | op=n/a | msg=Listening on port 1025
time=2015-01-07T15:12:42.917Z | lvl=INFO | corr=n/a | trans=n/a | op=n/a | msg=Redirecting to host 192.168.1.37 and port 1027
time=2015-01-07T15:12:42.917Z | lvl=DEBUG | corr=n/a | trans=n/a | op=n/a | msg=Loading access validation Templates
time=2015-01-07T15:12:42.922Z | lvl=INFO | corr=n/a | trans=n/a | op=n/a | msg=Proxy started
Loading middlewares
Server started
time=2015-01-07T15:12:47.859Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Extracting action from the URL "/v1/queryContext"
time=2015-01-07T15:12:47.861Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Retrieving user from keystone:  {
    "url": "http://192.168.1.37:5001/v3/auth/tokens",
    "method": "GET",
    "json": {},
    "headers": {
        "X-Subject-Token": "MIIC2QYJKoZIhvcNAQcCoIICyjCCAsYCAQExCTAHBgUrDgMCGjCCAS8GCSqGSIb3DQEHAaCCASAEggEceyJ0b2tlbiI6IHsiaXNzdWVkX2F0IjogIjIwMTUtMDEtMDdUMTU6MTI6NDcuODAyNTg1WiIsICJleHRyYXMiOiB7fSwgIm1ldGhvZHMiOiBbInBhc3N3b3JkIl0sICJleHBpcmVzX2F0IjogIjIwMTUtMDEtMDdUMTY6MTI6NDcuODAyNTUyWiIsICJ1c2VyIjogeyJkb21haW4iOiB7ImlkIjogIjIzMGExZmQ0NzkzMTRiZmM4ZWVkZWU5NGIwZjBhZjczIiwgIm5hbWUiOiAiYXRsYW50aWMifSwgImlkIjogIjk1ZGI2MDZiM2Q4ZjQxMmVhYzgyNGY3YzVmZjcyNWI0IiwgIm5hbWUiOiAib2N0b3B1cyJ9fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEAYtk10Id9floMScR7bQRU8XXOOlOHsN3NIuki+guijBFijjo7fguSIV6HR7d1hta5Z-SXprdqES2jc4ntECcZXl3ZsuwLxsKRRoDRPS8TrDDuw6Ow2C8VulSOWG1Mxh4D4-P7h2CAs3j4cAOzuv9YYCL+J-ibsKPgAyc56r5ftOvgtm3YyNSgia1Unqq4b4RIUVIyQsbhgHtWcWIGJDSOZ2oGFJM7Tvmu-x8kPcDD27OEASEyf93be30D3RVMFtQ40lTluoG2f16PVhBfY6DnPoPE-Y1-vs30m58AF1nWPCfc9EzHB8T1TwbJjW5jw++CmUDQXISGx6uRNUWMEy9fJQ=="
    }
}
time=2015-01-07T15:12:47.951Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Keystone response retrieving user:

 {
    "error": {
        "message": "The request you have made requires authentication.",
        "code": 401,
        "title": "Unauthorized"
    }
}
time=2015-01-07T15:12:47.951Z | lvl=ERROR | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Invalid token: null
time=2015-01-07T15:12:47.952Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Authenticating against Keystone {
    "url": "http://192.168.1.37:5001/v3/auth/tokens",
    "method": "POST",
    "json": {
        "auth": {
            "identity": {
                "methods": [
                    "password"
                ],
                "password": {
                    "user": {
                        "domain": {
                            "name": "admin_domain"
                        },
                        "name": "pep",
                        "password": "pep"
                    }
                }
            },
            "scope": {
                "domain": {
                    "name": "admin_domain"
                }
            }
        }
    }
}
time=2015-01-07T15:12:48.139Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Keystone response authenticating PEP:

 {
    "token": {
        "domain": {
            "id": "71693d05e4e24b879fafe0f6b1e62287",
            "name": "admin_domain"
        },
        "methods": [
            "password"
        ],
        "roles": [
            {
                "id": "6e8fb291930d43299800d5372ff58b7e",
                "name": "service"
            }
        ],
        "expires_at": "2015-01-07T16:12:48.100360Z",
        "catalog": [],
        "extras": {},
        "user": {
            "domain": {
                "id": "71693d05e4e24b879fafe0f6b1e62287",
                "name": "admin_domain"
            },
            "id": "ae37f927f9da41189f12306c3e90cd32",
            "name": "pep"
        },
        "issued_at": "2015-01-07T15:12:48.100391Z"
    }
}
time=2015-01-07T15:12:48.139Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Authentication to keystone success:
{
    "token": {
        "domain": {
            "id": "71693d05e4e24b879fafe0f6b1e62287",
            "name": "admin_domain"
        },
        "methods": [
            "password"
        ],
        "roles": [
            {
                "id": "6e8fb291930d43299800d5372ff58b7e",
                "name": "service"
            }
        ],
        "expires_at": "2015-01-07T16:12:48.100360Z",
        "catalog": [],
        "extras": {},
        "user": {
            "domain": {
                "id": "71693d05e4e24b879fafe0f6b1e62287",
                "name": "admin_domain"
            },
            "id": "ae37f927f9da41189f12306c3e90cd32",
            "name": "pep"
        },
        "issued_at": "2015-01-07T15:12:48.100391Z"
    }
}


time=2015-01-07T15:12:48.140Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Retrieving user from keystone:  {
    "url": "http://192.168.1.37:5001/v3/auth/tokens",
    "method": "GET",
    "json": {},
    "headers": {
        "X-Auth-Token": "MIIDgAYJKoZIhvcNAQcCoIIDcTCCA20CAQExCTAHBgUrDgMCGjCCAdYGCSqGSIb3DQEHAaCCAccEggHDeyJ0b2tlbiI6IHsiZG9tYWluIjogeyJpZCI6ICI3MTY5M2QwNWU0ZTI0Yjg3OWZhZmUwZjZiMWU2MjI4NyIsICJuYW1lIjogImFkbWluX2RvbWFpbiJ9LCAibWV0aG9kcyI6IFsicGFzc3dvcmQiXSwgInJvbGVzIjogW3siaWQiOiAiNmU4ZmIyOTE5MzBkNDMyOTk4MDBkNTM3MmZmNThiN2UiLCAibmFtZSI6ICJzZXJ2aWNlIn1dLCAiZXhwaXJlc19hdCI6ICIyMDE1LTAxLTA3VDE2OjEyOjQ4LjEwMDM2MFoiLCAiY2F0YWxvZyI6IFtdLCAiZXh0cmFzIjoge30sICJ1c2VyIjogeyJkb21haW4iOiB7ImlkIjogIjcxNjkzZDA1ZTRlMjRiODc5ZmFmZTBmNmIxZTYyMjg3IiwgIm5hbWUiOiAiYWRtaW5fZG9tYWluIn0sICJpZCI6ICJhZTM3ZjkyN2Y5ZGE0MTE4OWYxMjMwNmMzZTkwY2QzMiIsICJuYW1lIjogInBlcCJ9LCAiaXNzdWVkX2F0IjogIjIwMTUtMDEtMDdUMTU6MTI6NDguMTAwMzkxWiJ9fTGCAYEwggF9AgEBMFwwVzELMAkGA1UEBhMCVVMxDjAMBgNVBAgMBVVuc2V0MQ4wDAYDVQQHDAVVbnNldDEOMAwGA1UECgwFVW5zZXQxGDAWBgNVBAMMD3d3dy5leGFtcGxlLmNvbQIBATAHBgUrDgMCGjANBgkqhkiG9w0BAQEFAASCAQDGBMCah1HwtBeimO7LV3xcCpkQYbJuZisK-KZr9IeUQdcQWEF3pCvnfGhiq3godogR6KT2AmZKBRWjXPx0NfTmlKtz5MUBfIU5QRRJUVZlLGoFJsSig5+QrpxF+779lSkMyx4rVBahRjrOvvQvgZWUudDPPdeQ6CLqLRcPpv+uiC3w41nh6WP6Sp7OpQ-4Q5sYYs2YTkyaDWQHyPIATo9vh4JXuKOOw-ZqU2b6jsuVCRktNgCenRpIg+6UQwctH51OWocwOrFPAjf28UWzEteKxBj3vaa+o8CbR7X9EB4oJaia0N9oxy5yBtWHtLix0ivN9RZA2Az-T5lUIOBv-AEQ",
        "X-Subject-Token": "MIIC2QYJKoZIhvcNAQcCoIICyjCCAsYCAQExCTAHBgUrDgMCGjCCAS8GCSqGSIb3DQEHAaCCASAEggEceyJ0b2tlbiI6IHsiaXNzdWVkX2F0IjogIjIwMTUtMDEtMDdUMTU6MTI6NDcuODAyNTg1WiIsICJleHRyYXMiOiB7fSwgIm1ldGhvZHMiOiBbInBhc3N3b3JkIl0sICJleHBpcmVzX2F0IjogIjIwMTUtMDEtMDdUMTY6MTI6NDcuODAyNTUyWiIsICJ1c2VyIjogeyJkb21haW4iOiB7ImlkIjogIjIzMGExZmQ0NzkzMTRiZmM4ZWVkZWU5NGIwZjBhZjczIiwgIm5hbWUiOiAiYXRsYW50aWMifSwgImlkIjogIjk1ZGI2MDZiM2Q4ZjQxMmVhYzgyNGY3YzVmZjcyNWI0IiwgIm5hbWUiOiAib2N0b3B1cyJ9fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEAYtk10Id9floMScR7bQRU8XXOOlOHsN3NIuki+guijBFijjo7fguSIV6HR7d1hta5Z-SXprdqES2jc4ntECcZXl3ZsuwLxsKRRoDRPS8TrDDuw6Ow2C8VulSOWG1Mxh4D4-P7h2CAs3j4cAOzuv9YYCL+J-ibsKPgAyc56r5ftOvgtm3YyNSgia1Unqq4b4RIUVIyQsbhgHtWcWIGJDSOZ2oGFJM7Tvmu-x8kPcDD27OEASEyf93be30D3RVMFtQ40lTluoG2f16PVhBfY6DnPoPE-Y1-vs30m58AF1nWPCfc9EzHB8T1TwbJjW5jw++CmUDQXISGx6uRNUWMEy9fJQ=="
    }
}
time=2015-01-07T15:12:48.164Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=Keystone response retrieving user:

 {
    "token": {
        "issued_at": "2015-01-07T15:12:47.802585Z",
        "extras": {},
        "methods": [
            "password"
        ],
        "expires_at": "2015-01-07T16:12:47.802552Z",
        "user": {
            "domain": {
                "id": "230a1fd479314bfc8eedee94b0f0af73",
                "name": "atlantic"
            },
            "id": "95db606b3d8f412eac824f7c5ff725b4",
            "name": "octopus"
        }
    }
}
time=2015-01-07T15:12:48.164Z | lvl=DEBUG | corr=28ba07ff-2023-468e-99c5-d804e1c1ba12 | trans=28ba07ff-2023-468e-99c5-d804e1c1ba12 | op=/v1/queryContext | msg=User response from Keystone:
{
    "token": {
        "issued_at": "2015-01-07T15:12:47.802585Z",
        "extras": {},
        "methods": [
            "password"
        ],
        "expires_at": "2015-01-07T16:12:47.802552Z",
        "user": {
            "domain": {
                "id": "230a1fd479314bfc8eedee94b0f0af73",
                "name": "atlantic"
            },
            "id": "95db606b3d8f412eac824f7c5ff725b4",
            "name": "octopus"
        }
    }
}