tunnistamo Django admin log in fails using SOCIAL_AUTH_GITHUB_KEY, SOCIAL_AUTH_GITHUB_SECRET and ALLOW_CROSS_SITE_SESSION_COOKIE=True

[karisal-anders]

Steps how to reproduce issue:

• Add line 127.0.0.1 tunnistamo-backend into your hosts file and make sure the change takes effect (Possibly reboot to make extra sure)
  • /etc/hosts on Mac OS X and Linux
  • /Windows/System32/drivers/etc/hosts on Windows 10
• git clone https://github.com/City-of-Helsinki/tunnistamo.git testing-tunnistamo
• cd testing-tunnistamo
• git checkout dbb0795e7f7e2bae5d9e93682c88e8e9ed9d35a1 (This is the most recent commit in develop branch on 2023-02-17)
• cp docker-compose.env.yaml.template docker-compose.env.yaml
• Open https://github.com/settings/developers/ in a web browser
  • Click "New OAuth App" button
  • Set "Application name" to local tunnistamo
  • Set "Homepage URL" to http://tunnistamo-backend:8000
  • Set "Application description" to Local tunnistamo for e.g. palvelutarjotin-admin
  • Set "Authorization callback URL" to http://tunnistamo-backend:8000/accounts/github/login/callback/
  • Click "Register application"
  • Open the created "local tunnistamo" OAuth App
  • Copy the client ID and put it into docker-compose.env.yaml as SOCIAL_AUTH_GITHUB_KEY=<client ID value>, e.g. SOCIAL_AUTH_GITHUB_KEY=2a78b94f1512dfbd4173
  • Click "Generate a new client secret"
  • Copy the client secret and put it into docker-compose.env.yaml as SOCIAL_AUTH_GITHUB_SECRET=<client secret value>, e.g. SOCIAL_AUTH_GITHUB_SECRET=e54f49ebd2e727af1da32f296e04671c9989364e
  • Add ALLOW_CROSS_SITE_SESSION_COOKIE=True into docker-compose.env.yaml (Tried without adding this and the bug didn't appear so this is involved!)
• docker-compose up --build
• Open Google Chrome in incognito mode to make sure it starts from a clean slate
  • Open http://tunnistamo-backend:8000/admin/login/
  • Set username to admin, password to admin and click "Log in" button
    • Avot! Nothing happens, the form clears but user is not logged in

Debugging

If you set tunnistamo/settings.py logging levels to DEBUG you can get more info:

diff

diff --git a/tunnistamo/settings.py b/tunnistamo/settings.py
index 113b2da..92ad3a9 100644
--- a/tunnistamo/settings.py
+++ b/tunnistamo/settings.py
@@ -336,22 +336,22 @@ LOGGING = {
     'loggers': {
         'django': {
             'handlers': ['console'],
-            'level': 'WARNING',
+            'level': 'DEBUG',
             'propagate': False,
         },
         'generic': {
             'handlers': ['console'],
-            'level': 'WARNING',
+            'level': 'DEBUG',
             'propagate': False,
         },
         'requests': {
             'handlers': ['console'],
-            'level': 'WARNING',
+            'level': 'DEBUG',
             'propagate': False,
         },
         'sorl.thumbnail': {
             'handlers': ['console'],
-            'level': 'WARNING',
+            'level': 'DEBUG',
             'propagate': False,
         },
         '': {

With the above logging level changes trying to log in to Django admin with admin/admin gives:

log

tunnistamo-backend | utils 2023-02-17 10:36:53,080 DEBUG (0.002) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."username", "users_user"."email", "users_user"."is_staff", "users_user"."is_active", "users_user"."date_joined", "users_user"."uuid", "users_user"."department_name", "users_user"."first_name", "users_user"."last_name", "users_user"."primary_sid", "users_user"."last_login_backend" FROM "users_user" WHERE "users_user"."username" = 'admin' LIMIT 21; args=('admin',)
tunnistamo-backend | utils 2023-02-17 10:36:53,208 DEBUG (0.002) SELECT (1) AS "a" FROM "django_session" WHERE "django_session"."session_key" = 'ty0o843p7qwsczsuzsotkleclvejp9er' LIMIT 1; args=('ty0o843p7qwsczsuzsotkleclvejp9er',)
tunnistamo-backend | utils 2023-02-17 10:36:53,210 DEBUG (0.001) INSERT INTO "django_session" ("session_key", "session_data", "expire_date") VALUES ('ty0o843p7qwsczsuzsotkleclvejp9er', 'e30:1pSy6n:24RUA6dlQXR7li9MJgjw_Rp5IClbSIeVIraiVr_w9Is', '2023-03-03T10:36:53.208660+00:00'::timestamptz); args=('ty0o843p7qwsczsuzsotkleclvejp9er', 'e30:1pSy6n:24RUA6dlQXR7li9MJgjw_Rp5IClbSIeVIraiVr_w9Is', datetime.datetime(2023, 3, 3, 10, 36, 53, 208660, tzinfo=<UTC>))
tunnistamo-backend | utils 2023-02-17 10:36:53,214 DEBUG (0.002) UPDATE "users_user" SET "last_login" = '2023-02-17T10:36:53.211632+00:00'::timestamptz WHERE "users_user"."id" = 1; args=(datetime.datetime(2023, 2, 17, 10, 36, 53, 211632, tzinfo=<UTC>), 1)
tunnistamo-backend | utils 2023-02-17 10:36:53,216 DEBUG (0.002) INSERT INTO "users_tunnistamosession" ("id", "data", "user_id", "created_at", "ended_at") VALUES ('31bfdbd5-193a-47b8-8d36-a612aaf48c2e'::uuid, NULL, 1, '2023-02-17T10:36:53.214428+00:00'::timestamptz, NULL); args=(UUID('31bfdbd5-193a-47b8-8d36-a612aaf48c2e'), None, 1, datetime.datetime(2023, 2, 17, 10, 36, 53, 214428, tzinfo=<UTC>), None)
tunnistamo-backend | utils 2023-02-17 10:36:53,218 DEBUG (0.001) UPDATE "users_tunnistamosession" SET "data" = '{"django_session_key": "ty0o843p7qwsczsuzsotkleclvejp9er"}', "user_id" = 1, "created_at" = '2023-02-17T10:36:53.214428+00:00'::timestamptz, "ended_at" = NULL WHERE "users_tunnistamosession"."id" = '31bfdbd5-193a-47b8-8d36-a612aaf48c2e'::uuid; args=('{"django_session_key": "ty0o843p7qwsczsuzsotkleclvejp9er"}', 1, datetime.datetime(2023, 2, 17, 10, 36, 53, 214428, tzinfo=<UTC>), UUID('31bfdbd5-193a-47b8-8d36-a612aaf48c2e'))
tunnistamo-backend | utils 2023-02-17 10:36:53,222 DEBUG (0.001) UPDATE "django_session" SET "session_data" = '.eJxVjssOgjAQRf-layH0QTu4dO83kJnOIPhoEwor478L0YUu7-vkPlWP6zL2a5G5n1gdlVaHX48w3iTtAV8xXXIdc1rmieq9Un_TUp8zy_307f4BRizjtm4huCDSgG8MDI7ZaorcsgnUduS08xB9Z8EBkdmUh4DC3uqmE0LwG3RZU5rKgo_cFyllyunzeCMNTNxWurNYuUBQAVtfodcGcXAQjajXG_wESsg:1pSy6n:esuRd63N3D0t0XbfQ0LZbTACWH1QmY182XcajB1nCNI', "expire_date" = '2023-03-03T10:36:53.221199+00:00'::timestamptz WHERE "django_session"."session_key" = 'ty0o843p7qwsczsuzsotkleclvejp9er'; args=('.eJxVjssOgjAQRf-layH0QTu4dO83kJnOIPhoEwor478L0YUu7-vkPlWP6zL2a5G5n1gdlVaHX48w3iTtAV8xXXIdc1rmieq9Un_TUp8zy_307f4BRizjtm4huCDSgG8MDI7ZaorcsgnUduS08xB9Z8EBkdmUh4DC3uqmE0LwG3RZU5rKgo_cFyllyunzeCMNTNxWurNYuUBQAVtfodcGcXAQjajXG_wESsg:1pSy6n:esuRd63N3D0t0XbfQ0LZbTACWH1QmY182XcajB1nCNI', datetime.datetime(2023, 3, 3, 10, 36, 53, 221199, tzinfo=<UTC>), 'ty0o843p7qwsczsuzsotkleclvejp9er')
tunnistamo-backend | basehttp 2023-02-17 10:36:53,223 INFO "POST /admin/login/ HTTP/1.1" 302 0
tunnistamo-backend | basehttp 2023-02-17 10:36:53,228 INFO "GET /admin/ HTTP/1.1" 302 0
tunnistamo-backend | base 2023-02-17 10:36:53,281 DEBUG Exception while resolving variable 'subtitle' in template 'admin/hel_login.html'.
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 829, in _resolve_lookup
tunnistamo-backend |     current = current[bit]
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/context.py", line 83, in __getitem__
tunnistamo-backend |     raise KeyError(key)
tunnistamo-backend | KeyError: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 835, in _resolve_lookup
tunnistamo-backend |     if isinstance(current, BaseContext) and getattr(type(current), bit):
tunnistamo-backend | AttributeError: type object 'RequestContext' has no attribute 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 843, in _resolve_lookup
tunnistamo-backend |     current = current[int(bit)]
tunnistamo-backend | ValueError: invalid literal for int() with base 10: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 848, in _resolve_lookup
tunnistamo-backend |     raise VariableDoesNotExist("Failed lookup for key "
tunnistamo-backend | django.template.base.VariableDoesNotExist: Failed lookup for key [subtitle] in [{'True': True, 'False': False, 'None': None}, {'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x7fd9e8bb5550>>, 'request': <WSGIRequest: GET '/admin/login/?next=/admin/'>, 'user': <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser object at 0x7fd9e95669d0>>, 'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x7fd9e9578130>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x7fd9e9566280>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'SUCCESS': 25, 'WARNING': 30, 'ERROR': 40}, 'backends': <LazyDict: <function backends.<locals>.<lambda> at 0x7fd9e9ee2d30>>, 'REDIRECT_FIELD_NAME': 'next', 'REDIRECT_FIELD_VALUE': '/admin/', 'REDIRECT_QUERYSTRING': 'next=/admin/'}, {}, {'form': <AdminAuthenticationForm bound=False, valid=Unknown, fields=(username;password)>, 'view': <django.contrib.auth.views.LoginView object at 0x7fd9e97cfc40>, 'site_title': 'Django site admin', 'site_header': 'example.com admin', 'site_url': '/', 'has_permission': False, 'available_apps': [], 'is_popup': False, 'is_nav_sidebar_enabled': True, 'site_type': 'dev', 'redirect_path': '/admin/', 'helsinki_provider_installed': False, 'grappelli_installed': False, 'base_site_template': 'admin/base_site_default.html', 'title': 'Log in', 'app_path': '/admin/login/?next=/admin/', 'username': '', 'next': '/admin/', 'site': <Site: example.com>, 'site_name': 'example.com', 'LANGUAGE_CODE': 'en', 'LANGUAGE_BIDI': False}, {'block': <Block Node: title. Contents: [<IfNode>, <Variable Node: title>, <TextNode: ' | '>, <Variable Node: site_title|default:_('Django site admin')>]>}]
tunnistamo-backend | base 2023-02-17 10:36:53,286 DEBUG Exception while resolving variable 'subtitle' in template 'admin/hel_login.html'.
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 829, in _resolve_lookup
tunnistamo-backend |     current = current[bit]
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/context.py", line 83, in __getitem__
tunnistamo-backend |     raise KeyError(key)
tunnistamo-backend | KeyError: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 835, in _resolve_lookup
tunnistamo-backend |     if isinstance(current, BaseContext) and getattr(type(current), bit):
tunnistamo-backend | AttributeError: type object 'RequestContext' has no attribute 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 843, in _resolve_lookup
tunnistamo-backend |     current = current[int(bit)]
tunnistamo-backend | ValueError: invalid literal for int() with base 10: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 848, in _resolve_lookup
tunnistamo-backend |     raise VariableDoesNotExist("Failed lookup for key "
tunnistamo-backend | django.template.base.VariableDoesNotExist: Failed lookup for key [subtitle] in [{'True': True, 'False': False, 'None': None}, {'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x7fd9e8bb5550>>, 'request': <WSGIRequest: GET '/admin/login/?next=/admin/'>, 'user': <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser object at 0x7fd9e95669d0>>, 'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x7fd9e9578130>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x7fd9e9566280>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'SUCCESS': 25, 'WARNING': 30, 'ERROR': 40}, 'backends': <LazyDict: <function backends.<locals>.<lambda> at 0x7fd9e9ee2d30>>, 'REDIRECT_FIELD_NAME': 'next', 'REDIRECT_FIELD_VALUE': '/admin/', 'REDIRECT_QUERYSTRING': 'next=/admin/'}, {}, {'form': <AdminAuthenticationForm bound=False, valid=Unknown, fields=(username;password)>, 'view': <django.contrib.auth.views.LoginView object at 0x7fd9e97cfc40>, 'site_title': 'Django site admin', 'site_header': 'example.com admin', 'site_url': '/', 'has_permission': False, 'available_apps': [], 'is_popup': False, 'is_nav_sidebar_enabled': True, 'site_type': 'dev', 'redirect_path': '/admin/', 'helsinki_provider_installed': False, 'grappelli_installed': False, 'base_site_template': 'admin/base_site_default.html', 'title': 'Log in', 'app_path': '/admin/login/?next=/admin/', 'username': '', 'next': '/admin/', 'site': <Site: example.com>, 'site_name': 'example.com', 'LANGUAGE_CODE': 'en', 'LANGUAGE_BIDI': False}, {'block': <Block Node: content_subtitle. Contents: [<IfNode>]>}]
tunnistamo-backend | basehttp 2023-02-17 10:36:53,298 INFO "GET /admin/login/?next=/admin/ HTTP/1.1" 200 2232
tunnistamo-backend | basehttp 2023-02-17 10:36:53,329 INFO "GET /sso/static/admin/css/base.css HTTP/1.1" 200 19513
tunnistamo-backend | basehttp 2023-02-17 10:36:53,335 INFO "GET /sso/static/admin/css/nav_sidebar.css HTTP/1.1" 200 2271
tunnistamo-backend | basehttp 2023-02-17 10:36:53,340 INFO "GET /sso/static/admin/css/login.css HTTP/1.1" 200 939
tunnistamo-backend | basehttp 2023-02-17 10:36:53,343 INFO "GET /sso/static/admin/css/fonts.css HTTP/1.1" 200 423
tunnistamo-backend | basehttp 2023-02-17 10:36:53,343 INFO "GET /sso/static/admin/js/nav_sidebar.js HTTP/1.1" 200 1360
tunnistamo-backend | basehttp 2023-02-17 10:36:53,347 INFO "GET /sso/static/admin/css/responsive.css HTTP/1.1" 200 18545
tunnistamo-backend | basehttp 2023-02-17 10:36:53,396 INFO "GET /sso/static/admin/fonts/Roboto-Regular-webfont.woff HTTP/1.1" 200 85876
tunnistamo-backend | basehttp 2023-02-17 10:36:53,403 INFO "GET /sso/static/admin/fonts/Roboto-Light-webfont.woff HTTP/1.1" 200 85692

The most pertinent section of the log seems to be:

tunnistamo-backend | base 2023-02-17 10:36:53,286 DEBUG Exception while resolving variable 'subtitle' in template 'admin/hel_login.html'.
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 829, in _resolve_lookup
tunnistamo-backend |     current = current[bit]
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/context.py", line 83, in __getitem__
tunnistamo-backend |     raise KeyError(key)
tunnistamo-backend | KeyError: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 835, in _resolve_lookup
tunnistamo-backend |     if isinstance(current, BaseContext) and getattr(type(current), bit):
tunnistamo-backend | AttributeError: type object 'RequestContext' has no attribute 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 843, in _resolve_lookup
tunnistamo-backend |     current = current[int(bit)]
tunnistamo-backend | ValueError: invalid literal for int() with base 10: 'subtitle'
tunnistamo-backend |
tunnistamo-backend | During handling of the above exception, another exception occurred:
tunnistamo-backend |
tunnistamo-backend | Traceback (most recent call last):
tunnistamo-backend |   File "/usr/local/lib/python3.9/site-packages/django/template/base.py", line 848, in _resolve_lookup
tunnistamo-backend |     raise VariableDoesNotExist("Failed lookup for key "
tunnistamo-backend | django.template.base.VariableDoesNotExist: Failed lookup for key [subtitle] in [{'True': True, 'False': False, 'None': None}, {'csrf_token': <SimpleLazyObject: <function csrf.<locals>._get_val at 0x7fd9e8bb5550>>, 'request': <WSGIRequest: GET '/admin/login/?next=/admin/'>, 'user': <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser object at 0x7fd9e95669d0>>, 'perms': <django.contrib.auth.context_processors.PermWrapper object at 0x7fd9e9578130>, 'messages': <django.contrib.messages.storage.fallback.FallbackStorage object at 0x7fd9e9566280>, 'DEFAULT_MESSAGE_LEVELS': {'DEBUG': 10, 'INFO': 20, 'SUCCESS': 25, 'WARNING': 30, 'ERROR': 40}, 'backends': <LazyDict: <function backends.<locals>.<lambda> at 0x7fd9e9ee2d30>>, 'REDIRECT_FIELD_NAME': 'next', 'REDIRECT_FIELD_VALUE': '/admin/', 'REDIRECT_QUERYSTRING': 'next=/admin/'}, {}, {'form': <AdminAuthenticationForm bound=False, valid=Unknown, fields=(username;password)>, 'view': <django.contrib.auth.views.LoginView object at 0x7fd9e97cfc40>, 'site_title': 'Django site admin', 'site_header': 'example.com admin', 'site_url': '/', 'has_permission': False, 'available_apps': [], 'is_popup': False, 'is_nav_sidebar_enabled': True, 'site_type': 'dev', 'redirect_path': '/admin/', 'helsinki_provider_installed': False, 'grappelli_installed': False, 'base_site_template': 'admin/base_site_default.html', 'title': 'Log in', 'app_path': '/admin/login/?next=/admin/', 'username': '', 'next': '/admin/', 'site': <Site: example.com>, 'site_name': 'example.com', 'LANGUAGE_CODE': 'en', 'LANGUAGE_BIDI': False}, {'block': <Block Node: content_subtitle. Contents: [<IfNode>]>}]

• Googling with the error messages found Django issue #32681 https://code.djangoproject.com/ticket/32681 which has been fixed in https://code.djangoproject.com/changeset/4e5bbb6ef2287126badd32842b239f4a8a7394ca/
• Checked that django 3.2.16 had at least the test_render_views_no_subtitle test from django's 4e5bbb6ef2287126badd32842b239f4a8a7394ca merged into it.
• Checked that the django version inside the docker container is django 3.2.16 by
  • docker-compose exec django bash
    • python
      • import django
      • django.VERSION → gives (3, 2, 16, 'final', 0)
• So it seems this problem should not be present in django 3.2.16 but it is (Didn't check exactly that whether all the changes were incorporated from the django issue #32681 into django 3.2.16 release and whether its test_render_views_no_subtitle test passes)

Screenshots

After trying to log in with admin/admin