search

heliumdatacommons / auth_microservice

Microservice which abstracts out OAuth2/OpenID exchanges and token management from applications
4 stars 5 forks source link

Problem getting subject_by_nonce #42

Open RubenGarcia opened 5 years ago

RubenGarcia commented 5 years ago

When following the tutorial https://github.com/heliumdatacommons/auth_microservice/wiki/API-and-Use in the "manual login" section, I'm getting curl -k "https://my auth_microservice server/subject_by_nonce?block=60&nonce="

I am getting an immediate response, with error 404, of no token which meets required criteria

The authorization_url is good and I get either a window to login or a message saying I'm already logged in.

RubenGarcia commented 5 years ago

The nonces are stored correctly at the database in the table token_service_nonce

theferrit32 commented 5 years ago

@RubenGarcia is there anything in the auth_microservice.log output that says a more specific cause of the failure? I would guess that the _prune_invalid function in views.py might be the culprit. So the token is getting stored but then on the next request it is checked for validity and comes up as invalid.

RubenGarcia commented 5 years ago

Here is the output of the system, as I interact with it:

python3 /usr/local/lib/python3.5/dist-packages/auth_microservice/manage.py runserver

[23/Aug/2019 08:13:38] INFO [root:48] Trying to load django secret key from /usr/local/lib/python3.5/dist-packages/.django.key [23/Aug/2019 08:13:38] INFO [root:106] reading DB key from /etc/auth_microservice/db.key [23/Aug/2019 08:13:38] DEBUG [root:40] sensitive false: non-templated message read db_key and created crypt instance: %s [23/Aug/2019 08:13:38] INFO [root:123] reading admin key from /etc/auth_microservice/admin.key [23/Aug/2019 08:13:38] DEBUG [root:40] sensitive false: non-templated message read admin_key: %s [23/Aug/2019 08:13:38] INFO [root:73] generate django database configuration [23/Aug/2019 08:13:38] INFO [root:138] loading JSON configuration from /etc/auth_microservice/config.json [23/Aug/2019 08:13:39] INFO [root:48] Trying to load django secret key from /usr/local/lib/python3.5/dist-packages/.django.key [23/Aug/2019 08:13:39] INFO [root:106] reading DB key from /etc/auth_microservice/db.key [23/Aug/2019 08:13:39] DEBUG [root:40] sensitive false: non-templated message read db_key and created crypt instance: %s [23/Aug/2019 08:13:39] INFO [root:123] reading admin key from /etc/auth_microservice/admin.key [23/Aug/2019 08:13:39] DEBUG [root:40] sensitive false: non-templated message read admin_key: %s [23/Aug/2019 08:13:39] INFO [root:73] generate django database configuration [23/Aug/2019 08:13:39] INFO [root:138] loading JSON configuration from /etc/auth_microservice/config.json Performing system checks...

System check identified no issues (0 silenced). August 23, 2019 - 08:13:39 Django version 1.8.7, using settings 'auth_microservice.settings' Starting development server at http://127.0.0.1:8000/ Quit the server with CONTROL-C.

-----In another window: curl -k "http://localhost:8000/authorize?provider=keycloak_openid&scope=openid%20email%20profile"

{"authorization_url": "https://KEYCLOAK/auth/realms/REALM/protocol/openid-connect/auth?nonce=30c70c07c557219148666ae3a471d27fdabe4d70a81168e13980fc225b61fda2&state=edd1a94d923acbdcf7f4e11619ab9459a6699272a40e7f7c2f9dd63deef3890e&redirect_uri=http://REDIRECT:8090/authcallback&client_id=irods-auth-plugin&&scope=openid%20email%20profile&response_type=code&access_type=offline&prompt=login%20consent", "nonce": "30c70c07c557219148666ae3a471d27fdabe4d70a81168e13980fc225b61fda2"}

---The log of this interaction: [[23/Aug/2019 08:15:16] DEBUG [root:221] No HTTP_AUTHORIZATION [23/Aug/2019 08:15:16] DEBUG [root:300] invalid api key, ignoring return_to param [23/Aug/2019 08:15:16] DEBUG [root:274] adding callback waiter with uid None, scopes ['openid', 'email', 'profile'], provider keycloak_openid, return_to None [23/Aug/2019 08:15:16] DEBUG [root:123] No additional_scopes config from openid provider, returning default [] [23/Aug/2019 08:15:16] DEBUG [root:113] Got https://KEYCLOAK/auth/realms/REALM/protocol/openid-connect/auth for authorization_endpoint from provider keycloak_openid openid metadata [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 08:15:16] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 08:15:16] "GET /authorize?provider=keycloak_openid&scope=openid%20email%20profile HTTP/1.1" 200 491 ----------end log of first interaction

RubenGarcia commented 5 years ago

Second interaction:

curl -k "http://localhost:8000/subject_by_nonce?block=60&nonce=30c70c07c557219148666ae3a471d27fdabe4d70a81168e13980fc225b61fda2"

no token which meets required criteria

------Log of the interaction: [23/Aug/2019 08:18:26] DEBUG [root:165] querying for tokens nonce: 30c70c07c557219148666ae3a471d27fdabe4d70a81168e13980fc225b61fda2 [23/Aug/2019 08:18:26] DEBUG [root:27] HttpResponseNotFound no token which meets required criteria [23/Aug/2019 08:18:26] "GET /subject_by_nonce?block=60&nonce=30c70c07c557219148666ae3a471d27fdabe4d70a81168e13980fc225b61fda2 HTTP/1.1" 404 38

RubenGarcia commented 5 years ago

I downloaded the code clean from your repository, and added code to see the tokens pre-and post-validation. Both return 0 tokens, so validation is not an issue. Log follows:

[23/Aug/2019 09:14:33] INFO [root:48] Trying to load django secret key from /usr/local/lib/python3.5/dist-packages/.django.key [23/Aug/2019 09:14:33] INFO [root:106] reading DB key from /etc/auth_microservice/db.key [23/Aug/2019 09:14:33] DEBUG [root:40] sensitive false: non-templated message read db_key and created crypt instance: %s [23/Aug/2019 09:14:33] INFO [root:123] reading admin key from /etc/auth_microservice/admin.key [23/Aug/2019 09:14:33] DEBUG [root:40] sensitive false: non-templated message read admin_key: %s [23/Aug/2019 09:14:33] INFO [root:73] generate django database configuration [23/Aug/2019 09:14:33] INFO [root:138] loading JSON configuration from /etc/auth_microservice/config.json [23/Aug/2019 09:14:34] INFO [root:48] Trying to load django secret key from /usr/local/lib/python3.5/dist-packages/.django.key [23/Aug/2019 09:14:34] INFO [root:106] reading DB key from /etc/auth_microservice/db.key [23/Aug/2019 09:14:34] DEBUG [root:40] sensitive false: non-templated message read db_key and created crypt instance: %s [23/Aug/2019 09:14:34] INFO [root:123] reading admin key from /etc/auth_microservice/admin.key [23/Aug/2019 09:14:34] DEBUG [root:40] sensitive false: non-templated message read admin_key: %s [23/Aug/2019 09:14:34] INFO [root:73] generate django database configuration [23/Aug/2019 09:14:34] INFO [root:138] loading JSON configuration from /etc/auth_microservice/config.json Performing system checks...

System check identified no issues (0 silenced). [23/Aug/2019 09:14:34] DEBUG [django.db.backends:89] (0.001) SELECT c.relname, c.relkind FROM pg_catalog.pg_class c LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace WHERE c.relkind IN ('r', 'v') AND n.nspname NOT IN ('pg_catalog', 'pg_toast') AND pg_catalog.pg_table_is_visible(c.oid); args=None [23/Aug/2019 09:14:34] DEBUG [django.db.backends:89] (0.000) SELECT "django_migrations"."app", "django_migrations"."name" FROM "django_migrations"; args=() August 23, 2019 - 09:14:34 Django version 1.8.7, using settings 'auth_microservice.settings' Starting development server at http://127.0.0.1:8000/ Quit the server with CONTROL-C.

[23/Aug/2019 09:14:39] DEBUG [root:165] querying for tokens nonce: 343bd945ac5d35dc02854d6ef88cf0fe8d71de88f5d2aeb1ed521294c9bfb17f [23/Aug/2019 09:14:39] DEBUG [django.db.backends:89] (0.003) SELECT "token_service_token"."id", "token_service_token"."user_id", "token_service_token"."access_token", "token_service_token"."refresh_token", "token_service_token"."expires", "token_service_token"."provider", "token_service_token"."issuer", "token_service_token"."enabled", "token_service_token"."access_token_hash" FROM "token_service_token" INNER JOIN "token_service_token_nonce" ON ( "token_service_token"."id" = "token_service_token_nonce"."token_id" ) INNER JOIN "token_service_nonce" ON ( "token_service_token_nonce"."nonce_id" = "token_service_nonce"."id" ) WHERE "token_service_nonce"."value" = '343bd945ac5d35dc02854d6ef88cf0fe8d71de88f5d2aeb1ed521294c9bfb17f' ORDER BY "token_service_token"."expires" ASC; args=('343bd945ac5d35dc02854d6ef88cf0fe8d71de88f5d2aeb1ed521294c9bfb17f',) [23/Aug/2019 09:14:39] DEBUG [root:168] in _get_tokens_by_nonce, after filter, tokens: 0 [23/Aug/2019 09:14:39] DEBUG [root:172] in _get_tokens_by_nonce, after validate, tokens: 0 [23/Aug/2019 09:14:39] DEBUG [root:27] HttpResponseNotFound no token which meets required criteria [23/Aug/2019 09:14:39] "GET /subject_by_nonce?block=60&nonce=343bd945ac5d35dc02854d6ef88cf0fe8d71de88f5d2aeb1ed521294c9bfb17f HTTP/1.1" 404 38

[23/Aug/2019 09:15:10] DEBUG [root:226] No HTTP_AUTHORIZATION [23/Aug/2019 09:15:10] DEBUG [root:305] invalid api key, ignoring return_to param [23/Aug/2019 09:15:10] DEBUG [root:271] adding callback waiter with uid None, scopes ['openid', 'email', 'profile'], provider keycloak_openid, return_to None [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.002) SELECT COUNT() AS "__count" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid'; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_oidcmetadatacache"."id", "token_service_oidcmetadatacache"."value", "token_service_oidcmetadatacache"."retrieval_time", "token_service_oidcmetadatacache"."provider" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid' LIMIT 1; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_oidcmetadatacache"."id", "token_service_oidcmetadatacache"."value", "token_service_oidcmetadatacache"."retrieval_time", "token_service_oidcmetadatacache"."provider" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid' LIMIT 1; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [root:122] No additional_scopes config from openid provider, returning default [] [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.001) SELECT "token_service_nonce"."id", "token_service_nonce"."value", "token_service_nonce"."creation_time" FROM "token_service_nonce"; args=() [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_nonce"."id", "token_service_nonce"."value", "token_service_nonce"."creation_time" FROM "token_service_nonce"; args=() [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.001) INSERT INTO "token_service_nonce" ("value", "creation_time") VALUES ('8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09', '2019-08-23T09:15:10.831795+00:00'::timestamptz) RETURNING "token_service_nonce"."id"; args=('8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09', datetime.datetime(2019, 8, 23, 9, 15, 10, 831795, tzinfo=)) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) INSERT INTO "token_service_nonce" ("value", "creation_time") VALUES ('c0e11944c89c2a3a982e9b202ec68c37631d5602ed5b065a015ea479ab8cf99a', '2019-08-23T09:15:10.839146+00:00'::timestamptz) RETURNING "token_service_nonce"."id"; args=('c0e11944c89c2a3a982e9b202ec68c37631d5602ed5b065a015ea479ab8cf99a', datetime.datetime(2019, 8, 23, 9, 15, 10, 839146, tzinfo=)) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT COUNT() AS "__count" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid'; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_oidcmetadatacache"."id", "token_service_oidcmetadatacache"."value", "token_service_oidcmetadatacache"."retrieval_time", "token_service_oidcmetadatacache"."provider" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid' LIMIT 1; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_oidcmetadatacache"."id", "token_service_oidcmetadatacache"."value", "token_service_oidcmetadatacache"."retrieval_time", "token_service_oidcmetadatacache"."provider" FROM "token_service_oidcmetadatacache" WHERE "token_service_oidcmetadatacache"."provider" = 'keycloak_openid' LIMIT 1; args=('keycloak_openid',) [23/Aug/2019 09:15:10] DEBUG [root:112] Got https://keycloak.it4i.cz/auth/realms/LRZ-LDAP/protocol/openid-connect/auth for authorization_endpoint from provider keycloak_openid openid metadata [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.001) INSERT INTO "token_service_pendingcallback" ("uid", "state", "nonce", "provider", "url", "return_to", "creation_time") VALUES ('', 'ueVyT1dViOA5pN0AYlnrY1LB+CegE6wI7II3/mCv6gbiUzwXAGrKUjOhxay/8/LwEPPboq1SATuM39sTzwtM2kIempp2HEHwewtAgfLHASwVoxB8NKkwWmxRT+DZTu9T', 'w6++Gz8fqCqdQwXz9lLS6Velo5oCl3XOxNJDT9ypgyBamIZZVQMu86XKNOUs59wFrxe93e6NisTEF2tFSZ61PrlhQFFf+7XKrP/7Hl8Xx5Ov91MOimb8k7FRF5elcz2q', 'keycloak_openid', 'I3YecOqbEpkXZJQZ6p5dCiJt68sE1BZwJT4S1/bteiAzX0T1ySNHojx7ScyG2xZ5N1juldIL14a8rxQZkXp01PqiSmeXCEKdBVgyLMQOa2AziC0mUrfeeVwTbe9f0PpHlZuUPGs20Lb+14tITrIMVYjLPAyw/k/K5bI5Dis+AocRvxbnJjtlEt5K+U8+ccmSlIylWF+xhqHu81MrAxx1T5525ZWamJ1BMx4ccwhM1eRXsd57hUG3W85/eAxAPnwARAkB2lQYS+gJpJrnLV1XzCpphN+boThSiiBEBmvj38T4AtbzJAJZLAvTruGrdz9STOofQ2bVFun7J3Z/6PtzBqH5jMYoGWqclAj/AN9xZ+CyqUD1zrrYU0Gjc9yI+c7+gVv017++4laur0sYWNeaGwlPkSFbbIAca3gXPloFAkO7N8pMcT1xuIACmT4Uu9bNAHzEPcn/ZohVmUqtusaYdDVg6BUuUbzw946W9Ev1koe1c6kFyL3gzhNKYlBMvdPVDBtN3c4ORNoKMCPUxvw5yqbYzjuEjEwcz8MMtpoj6NU=', 'nV2xxlayFJZn8LjTVKQ31GL61r04cZ1QOD5lr7ZL9EM=', '2019-08-23T09:15:10.849842+00:00'::timestamptz) RETURNING "token_service_pendingcallback"."id"; args=('', 'ueVyT1dViOA5pN0AYlnrY1LB+CegE6wI7II3/mCv6gbiUzwXAGrKUjOhxay/8/LwEPPboq1SATuM39sTzwtM2kIempp2HEHwewtAgfLHASwVoxB8NKkwWmxRT+DZTu9T', 'w6++Gz8fqCqdQwXz9lLS6Velo5oCl3XOxNJDT9ypgyBamIZZVQMu86XKNOUs59wFrxe93e6NisTEF2tFSZ61PrlhQFFf+7XKrP/7Hl8Xx5Ov91MOimb8k7FRF5elcz2q', 'keycloak_openid', 'I3YecOqbEpkXZJQZ6p5dCiJt68sE1BZwJT4S1/bteiAzX0T1ySNHojx7ScyG2xZ5N1juldIL14a8rxQZkXp01PqiSmeXCEKdBVgyLMQOa2AziC0mUrfeeVwTbe9f0PpHlZuUPGs20Lb+14tITrIMVYjLPAyw/k/K5bI5Dis+AocRvxbnJjtlEt5K+U8+ccmSlIylWF+xhqHu81MrAxx1T5525ZWamJ1BMx4ccwhM1eRXsd57hUG3W85/eAxAPnwARAkB2lQYS+gJpJrnLV1XzCpphN+boThSiiBEBmvj38T4AtbzJAJZLAvTruGrdz9STOofQ2bVFun7J3Z/6PtzBqH5jMYoGWqclAj/AN9xZ+CyqUD1zrrYU0Gjc9yI+c7+gVv017++4laur0sYWNeaGwlPkSFbbIAca3gXPloFAkO7N8pMcT1xuIACmT4Uu9bNAHzEPcn/ZohVmUqtusaYdDVg6BUuUbzw946W9Ev1koe1c6kFyL3gzhNKYlBMvdPVDBtN3c4ORNoKMCPUxvw5yqbYzjuEjEwcz8MMtpoj6NU=', 'nV2xxlayFJZn8LjTVKQ31GL61r04cZ1QOD5lr7ZL9EM=', datetime.datetime(2019, 8, 23, 9, 15, 10, 849842, tzinfo=)) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.001) SELECT "token_service_scope"."id", "token_service_scope"."name" FROM "token_service_scope" WHERE "token_service_scope"."name" = 'openid'; args=('openid',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.001) SELECT "token_service_pendingcallback_scopes"."scope_id" FROM "token_service_pendingcallback_scopes" WHERE ("token_service_pendingcallback_scopes"."scope_id" IN (1) AND "token_service_pendingcallback_scopes"."pendingcallback_id" = 16); args=(1, 16) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) INSERT INTO "token_service_pendingcallback_scopes" ("pendingcallback_id", "scope_id") VALUES (16, 1); args=(16, 1) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_scope"."id", "token_service_scope"."name" FROM "token_service_scope" WHERE "token_service_scope"."name" = 'email'; args=('email',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_pendingcallback_scopes"."scope_id" FROM "token_service_pendingcallback_scopes" WHERE ("token_service_pendingcallback_scopes"."scope_id" IN (2) AND "token_service_pendingcallback_scopes"."pendingcallback_id" = 16); args=(2, 16) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) INSERT INTO "token_service_pendingcallback_scopes" ("pendingcallback_id", "scope_id") VALUES (16, 2); args=(16, 2) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_scope"."id", "token_service_scope"."name" FROM "token_service_scope" WHERE "token_service_scope"."name" = 'profile'; args=('profile',) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) SELECT "token_service_pendingcallback_scopes"."scope_id" FROM "token_service_pendingcallback_scopes" WHERE ("token_service_pendingcallback_scopes"."scope_id" IN (3) AND "token_service_pendingcallback_scopes"."pendingcallback_id" = 16); args=(3, 16) [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) INSERT INTO "token_service_pendingcallback_scopes" ("pendingcallback_id", "scope_id") VALUES (16, 3); args=(16, 3) [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value value: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt plaintext: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message crypt.encrypt iv: %s [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message encrypted [%s] to [%s] [23/Aug/2019 09:15:10] DEBUG [root:40] sensitive false: non-templated message EncryptedTextField.get_prep_value(%s) -> %s [23/Aug/2019 09:15:10] DEBUG [django.db.backends:89] (0.000) UPDATE "token_service_pendingcallback" SET "uid" = '', "state" = 'yTY2tFsz1L4esHNN/3dZZIRwlCaMHf2a4iT1PUHFmPZvBf7FjT4dP4BvCOibh4pvt0EADF9wMDdbjKWMabAIbd+1V07EkHFsIpxmeESkncxS9vrcGfBNAfB8jnEVoYvD', "nonce" = '/llkAkTazT3Vc1Mpa4+dk3q5IAU6KGkMG6E0ZsPQ5H9IPjQqc11Mqk0ULjATvDFFOh9xuvjBcmVt4EXdpP3QRKm6wQ1RpYCkkTZn1w3YsQZkuFD6sHLBTqKAYpQDtohx', "provider" = 'keycloak_openid', "url" = 'XALP0X256ZSp9aZT6xDFKtOtCY+4CwIG5af62yN/IxHXLsDnvEt7X9icnD1iw+dNLD52JFFJtxqxd0vOGbT2Pie6k8fNcOj0dJ7c/WLOdQDlYcne+5tVTHaLU84lcbLY3iRx3cox9J0lU99+/d88TUf9uX1lVEM0Hk/rUHVShJSgye+GSnahGfXiovhiWzu4ElQbECp2PvumQKc0kljyF1s1569zY+3RuB+XQOg+ZV5tBxJjQ1ZzEaePhjNwGo3zT3jfB4Ef10ReGBuX0uIUk3v+cgghyETyu1DcRLNTDQeTZag80suh1HGUP3LUtIeoWHoMb/c/saVf+qnPYW/CzO7wO8vfjDS7YqGMjCjoolGwuKMkVj6kPqN8V5fDlzmfVAguncDMZSk+lBkR3aift2Zc+KoUsoAiujEdeDnFMa2LLNwE7rnCU6YsB4v1OQNuFhz4DZsqW4gONxc530CumiKc9rGy4jzRocfnfEB+f3Lp0YcVIdlcyfsfp2ev8pGeYcVJn7huzOFJLlDyxbbOF1vBn0qtBy/XQjZRl2nB55k=', "return_to" = 'r2mCghhulO3lnwQqs2ZwVSOfWzxCEwwJGvLVUN04Qxk=', "creation_time" = '2019-08-23T09:15:10.849842+00:00'::timestamptz WHERE "token_service_pendingcallback"."id" = 16; args=('', 'yTY2tFsz1L4esHNN/3dZZIRwlCaMHf2a4iT1PUHFmPZvBf7FjT4dP4BvCOibh4pvt0EADF9wMDdbjKWMabAIbd+1V07EkHFsIpxmeESkncxS9vrcGfBNAfB8jnEVoYvD', '/llkAkTazT3Vc1Mpa4+dk3q5IAU6KGkMG6E0ZsPQ5H9IPjQqc11Mqk0ULjATvDFFOh9xuvjBcmVt4EXdpP3QRKm6wQ1RpYCkkTZn1w3YsQZkuFD6sHLBTqKAYpQDtohx', 'keycloak_openid', 'XALP0X256ZSp9aZT6xDFKtOtCY+4CwIG5af62yN/IxHXLsDnvEt7X9icnD1iw+dNLD52JFFJtxqxd0vOGbT2Pie6k8fNcOj0dJ7c/WLOdQDlYcne+5tVTHaLU84lcbLY3iRx3cox9J0lU99+/d88TUf9uX1lVEM0Hk/rUHVShJSgye+GSnahGfXiovhiWzu4ElQbECp2PvumQKc0kljyF1s1569zY+3RuB+XQOg+ZV5tBxJjQ1ZzEaePhjNwGo3zT3jfB4Ef10ReGBuX0uIUk3v+cgghyETyu1DcRLNTDQeTZag80suh1HGUP3LUtIeoWHoMb/c/saVf+qnPYW/CzO7wO8vfjDS7YqGMjCjoolGwuKMkVj6kPqN8V5fDlzmfVAguncDMZSk+lBkR3aift2Zc+KoUsoAiujEdeDnFMa2LLNwE7rnCU6YsB4v1OQNuFhz4DZsqW4gONxc530CumiKc9rGy4jzRocfnfEB+f3Lp0YcVIdlcyfsfp2ev8pGeYcVJn7huzOFJLlDyxbbOF1vBn0qtBy/XQjZRl2nB55k=', 'r2mCghhulO3lnwQqs2ZwVSOfWzxCEwwJGvLVUN04Qxk=', datetime.datetime(2019, 8, 23, 9, 15, 10, 849842, tzinfo=), 16) [23/Aug/2019 09:15:10] "GET /authorize?provider=keycloak_openid&scope=openid%20email%20profile HTTP/1.1" 200 491

[23/Aug/2019 09:15:51] DEBUG [root:165] querying for tokens nonce: 8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09 [23/Aug/2019 09:15:51] DEBUG [django.db.backends:89] (0.004) SELECT "token_service_token"."id", "token_service_token"."user_id", "token_service_token"."access_token", "token_service_token"."refresh_token", "token_service_token"."expires", "token_service_token"."provider", "token_service_token"."issuer", "token_service_token"."enabled", "token_service_token"."access_token_hash" FROM "token_service_token" INNER JOIN "token_service_token_nonce" ON ( "token_service_token"."id" = "token_service_token_nonce"."token_id" ) INNER JOIN "token_service_nonce" ON ( "token_service_token_nonce"."nonce_id" = "token_service_nonce"."id" ) WHERE "token_service_nonce"."value" = '8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09' ORDER BY "token_service_token"."expires" ASC; args=('8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09',) [23/Aug/2019 09:15:51] DEBUG [root:168] in _get_tokens_by_nonce, after filter, tokens: 0 [23/Aug/2019 09:15:51] DEBUG [root:172] in _get_tokens_by_nonce, after validate, tokens: 0 [23/Aug/2019 09:15:51] DEBUG [root:27] HttpResponseNotFound no token which meets required criteria [23/Aug/2019 09:15:51] "GET /subject_by_nonce?block=60&nonce=8821191bcd7ab08bdfad01085aaf70d0f2c2d610cb9cbad10512b55e812fcf09 HTTP/1.1" 404 38

RubenGarcia commented 5 years ago

I was told the issue was "most likely due to missing SSL key and certificate in irods service account environment which has to be set (quite unintuitive) in /var/lib/irods/.irods/irods_environment.json." I will investigate this next.