Problem getting subject_by_nonce

[RubenGarcia]

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=<RANDOM_NONCE_STRING from previous step>"

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]

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

[theferrit32]

@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]

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]

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]

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]

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.