Should it be impossible for a session dict to return more than one value for a key?

Using Django Mystery Errors
1

In my project, I store the serial number of the device that logs in it’s session. However in the code that gets the value from the session:

SESSION_SERIAL_NUMBER = 'terminal_serial_number'

user._serial_number = request.session.get(SESSION_SERIAL_NUMBER, '')

Very occasionally throws an error. The part that baffles me is:

get() returned more than one Session – it returned more than 20!

How can a dict return more than one result, I don’t know how to debug that?

Note: When I query the database django_sessions table with the given sessionid, it only returns one row.

Heres the error:

Internal Server Error: /accounts/login/

ProgrammingError at /accounts/login/
no results to fetch

Traceback (most recent call last):
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 180, in _get_session
    return self._session_cache

During handling of the above exception ('SessionStore' object has no attribute '_session_cache'), another exception occurred:
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "./dist/terminals/middleware.py", line 11, in __call__
    user._serial_number = request.session.get(SESSION_SERIAL_NUMBER, '')
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 65, in get
    return self._session.get(key, default)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 185, in _get_session
    self._session_cache = self.load()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/db.py", line 43, in load
    s = self._get_session_from_db()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/db.py", line 32, in _get_session_from_db
    return self.model.objects.get(
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/query.py", line 443, in get
    raise self.model.MultipleObjectsReturned(

During handling of the above exception (get() returned more than one Session -- it returned more than 20!), another exception occurred:
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 180, in _get_session
    return self._session_cache

During handling of the above exception ('SessionStore' object has no attribute '_session_cache'), another exception occurred:
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/utils.py", line 97, in inner
    return func(*args, **kwargs)

The above exception (no results to fetch) was the direct cause of the following exception:
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/utils/deprecation.py", line 126, in __call__
    response = response or self.get_response(request)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/core/handlers/exception.py", line 49, in inner
    response = response_for_exception(request, exc)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/core/handlers/exception.py", line 110, in response_for_exception
    response = handle_uncaught_exception(request, get_resolver(get_urlconf()), sys.exc_info())
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/core/handlers/exception.py", line 149, in handle_uncaught_exception
    return callback(request)
  File "./core/base/views.py", line 152, in error_500_view
    response = render(request, "core.base/500.html", context=context)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/shortcuts.py", line 19, in render
    content = loader.render_to_string(template_name, context, request, using=using)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/template/loader.py", line 62, in render_to_string
    return template.render(context, request)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/template/backends/django.py", line 61, in render
    return self.template.render(context)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/template/base.py", line 174, in render
    with context.bind_template(self):
  File "/usr/lib/python3.8/contextlib.py", line 113, in __enter__
    return next(self.gen)
  File "/home/company/.venv/project/lib/python3.8/site-packages/debug_toolbar/panels/templates/panel.py", line 46, in _request_context_bind_template
    context = processor(self.request)
  File "./core/base/context_processors.py", line 13, in project
    menu = get_plug_menu(request.user)
  File "./dist/plug/menu.py", line 58, in get_plug_menu
    if user.is_anonymous or user.is_terminal:
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/utils/functional.py", line 248, in inner
    self._setup()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/utils/functional.py", line 384, in _setup
    self._wrapped = self._setupfunc()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/auth/middleware.py", line 25, in <lambda>
    request.user = SimpleLazyObject(lambda: get_user(request))
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/auth/middleware.py", line 11, in get_user
    request._cached_user = auth.get_user(request)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/auth/__init__.py", line 177, in get_user
    user_id = _get_user_session_key(request)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/auth/__init__.py", line 60, in _get_user_session_key
    return get_user_model()._meta.pk.to_python(request.session[SESSION_KEY])
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 50, in __getitem__
    return self._session[key]
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/base.py", line 185, in _get_session
    self._session_cache = self.load()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/db.py", line 43, in load
    s = self._get_session_from_db()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/contrib/sessions/backends/db.py", line 32, in _get_session_from_db
    return self.model.objects.get(
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/query.py", line 435, in get
    num = len(clone)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/query.py", line 262, in __len__
    self._fetch_all()
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/query.py", line 1354, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/query.py", line 51, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1234, in execute_sql
    return list(result)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1678, in cursor_iter
    for rows in iter((lambda: cursor.fetchmany(itersize)), sentinel):
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1678, in <lambda>
    for rows in iter((lambda: cursor.fetchmany(itersize)), sentinel):
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/utils.py", line 97, in inner
    return func(*args, **kwargs)
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/home/company/.venv/project/lib/python3.8/site-packages/django/db/utils.py", line 97, in inner
    return func(*args, **kwargs)

Exception Type: ProgrammingError at /accounts/login/
Exception Value: no results to fetch
Request information:
USER: AnonymousUser

This is the middleware it sits in:

from dist.terminals.apps import SESSION_SERIAL_NUMBER

class UserSerialNumberMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response
        # One-time configuration and initialization.

    def __call__(self, request):
        user = request.user
        user._serial_number = request.session.get(SESSION_SERIAL_NUMBER, '')
        response = self.get_response(request)
        return response

I thought it was a bug, and raised a ticket due to the fact its just a dictionary lookup, it seems like quite an atomic action. I suspected it must be a bug not the code, since the code is basically set a key in the session, then read the key. However the issue was closed because they don’t think its a bug. Any ideas on how t debug it or angles on how to try figure out the issue?

2

You’re looking in the wrong place for the issue.

In the expression:

the session.get is a dict retrieval and not a database retrieval. You’re not going to get that error from a dict.

The problem would be occurring when Django is trying to retrieve the row from the Sessions table based on the session_key and getting multiple rows. (In other words, when evaluating the request.session part of the expression, not the session.get part.)

Examine your Sessions table and see if you’ve got more than one row with the same session_key value with an expire_date in the future.

1 Like
3

Thanks Ken for explaining to me its a DB error. I looked at the sessions table, and the session_key field is the primary key, with a unique constraint. So I still don’t see how 20 results could be returned for the given session key, with a unique constrain. When I query the DB, I could not find a duplicate entry.

4

Actually, looking at the full traceback more closely, I can see a couple of different possibilities.

You show that you’re using some custom middleware. Does this reside after the entries for SessionMiddleware and AuthenticationMiddleware?

Have you verified that the session ID being passed in the cookie is present in the database?

5

Thanks for the quick reply! Yes session is before Auth, which is before this custo middleware.

for x in MIDDLEWARE:
    print(x)

Prints:

core.base.middleware.cache.DefaultCacheHeaderMiddleware
django.contrib.sessions.middleware.SessionMiddleware  <--- Session
django.middleware.common.CommonMiddleware
django.middleware.csrf.CsrfViewMiddleware
django.contrib.auth.middleware.AuthenticationMiddleware  <--- Auth
core.accounts.middleware.RequireLoginCheck
django.contrib.messages.middleware.MessageMiddleware
django.contrib.sites.middleware.CurrentSiteMiddleware
dist.terminals.middleware.UserSerialNumberMiddleware  <--- This here is the custom middleware
admin_reorder.middleware.ModelAdminReorder

I checked it against https://docs.djangoproject.com/en/stable/ref/middleware/#middleware-ordering and the order seems correct.

When I querried the DB, I found one entry for the given session key. It happened again, and I made some changes to the session model admin, to allow me to search in the model admin instead of querying the DB for it, so there where some restarts (which also runs manage.py clearsessions automatically), and this time there was not an entry, so maybe it got cleared with my changes to try debug it. I have not figured out how to reproduce the bug yet.

6

Heres some more information, whereever it tries to look up the user on a given session id, I email myself the match count. Just before these emails, there were only 2 session keys in the table (I cleaned it out), then this happened. Any other ideas or angles of things to try?

It doesnt make sense to me to say theres one match, then 10, then 582. It only emails me when there are multiple objects returned, so when it says 1, it means there was multiple returned one line ahead, then it querried the DB, and got 10.

Heres the custom session backend for the logging:

import logging

from django.contrib.sessions.backends.db import SessionStore as SessionStoreDb
from django.core.exceptions import SuspiciousOperation
from django.utils import timezone
from django.conf import settings


class SessionStore(SessionStoreDb):
    def _get_session_from_db(self):
        try:
            return self.model.objects.get(
                session_key=self.session_key,
                expire_date__gt=timezone.now()
            )
        except (self.model.DoesNotExist, SuspiciousOperation) as e:
            if isinstance(e, SuspiciousOperation):
                logger = logging.getLogger('django.security.%s' % e.__class__.__name__)
                logger.warning(str(e))
            self._session_key = None
        except self.model.MultipleObjectsReturned as e:
            from django.contrib.sessions.models import Session
            from core.base.models import SysEvent
            count = Session.objects.filter(session_key=self.session_key, expire_date__gt=timezone.now()).count()
            SysEvent.record(
                name="Terminal Session Get Error",
                note=f"Session key: {self.session_key}, match count: {count}",
                email=True,
                log=True,
            )
            if settings.DEBUG:
                print('\n-----------------------------------------------------')
                print('\n-----------------------------------------------------')
                print('\n-----------------------------------------------------')
                breakpoint()
                print('AUTH MULT ERROR AGAIN')

image
image1323×783 121 KB

7

I agree - this really does appear odd (to say the least).

What database are you using for the session store?

8

PostgreSQL. I can never get the error to occur during debug, but happens quite often with a deployed setup (with sadly no debugging).

9

And heres the demo session table related to those errors. One more session has been added since.

image
image2155×778 116 KB

10

Have you made any changes to the PostgreSQL configuration settings such as changing the transaction isolation setting or using some type of enhanced cacheing software or changed anything with your production database that would make it a non-default configuration?

It looks like you’re running Python 3.8 from the traceback, what version of Django, PostgreSQL and psycopg2?

11 
$ psql -V
psql (PostgreSQL) 12.5 (Ubuntu 12.5-0ubuntu0.20.04.1)

psycopg2==2.9.3

The only Db changes I perform are:

        run_sql_root(f"ALTER ROLE {username} SET client_encoding TO 'utf8'")
        run_sql_root(f"ALTER ROLE {username} SET default_transaction_isolation TO 'read committed'")
        run_sql_root(f"ALTER ROLE {username} SET timezone TO 'UTC'")

I see read_commited is the default anyway.

I do have save every request True:

SESSION_COOKIE_AGE = 31 * 24 * 3600  # 1  month, default is 1209600 (2 weeks, in seconds)
# SESSION_ENGINE = 'django.contrib.sessions.backends.db'  # This is the default
SESSION_ENGINE = 'core.accounts.sessions'  # Temp backend while debugging
SESSION_SAVE_EVERY_REQUEST = True

I am using memcache, but not for the database, only for some page views, it does almost nothing.

12

I’ve never seen any behavior like this.

I’d take a really hard look at the custom middleware. I’d also be trying hard to recreate this in a development environment, which may need to have multiple browsers making concurrent requests.

I’d also be looking to identify any differences between your production and development environments. Without being able to recreate this in an environment that you can explore in, this is going to be difficult.

Unfortunately, I don’t have any other advice to give.

1 Like
14

Hi Ken,

Out of interest, restructured the code in quite a few ways so that the error would not happen, but nothing helped. I finally gave in and rebuilt the server and I have not seen the issues since. I

After installing formatting, reinstalling the OS, rebuilding the server, I have not seen the error again. I think something got corrupt in the postgres side.

Thanks so much again for the help!

1 Like