Django 2.2.6: Model.objects.get() _sometimes_ times out and generates a burst of SQL statements ending with "LIMIT 21"

[rubnov]

Hi all, 

I’m rather new to Django and have encountered an issue in Django’s ORM behaviour which I find very strange.

Our Django app (Django 2.2.6) implements an API used by mobile apps. We are using Postgresql database and use token authentication. For reasons I will not get into, we have a custom authentication method which validates the token in the HTTP header. This is done in the dispatch() method of our `ApiBaseView` class. Here is the relevant code from that class: 

     def dispatch(self, request, *args, **kwargs):
              ...
              if self.authorization_required:
                     self.check_auth_header(request)
              …

      def check_auth_header(self, request):
               authorization = request.META.get('HTTP_AUTHORIZATION’)
               if not authorization:
                   raise ApiError(401, _('Authorization header required!'))

               try:
                   token = base64.b64decode(authorization.split(' ')[1]).decode()
               except (IndexError, ValueError, TypeError):
                   raise ApiError(http.client.BAD_REQUEST, _('Wrong Authorization header format'))

               try:
                   user = User.objects.defer(
                       'settings',
                       'service_data',

                       'stats',
                       'line_stats',
                       'destination_stats',
                       'country_stats',
                       'carrier_stats'
                   ).get(
                       token=token, is_active=True
                   )
               except User.DoesNotExist:
                   logger.debug('No user found for authorization header: {}'.format(authorization))
                   raise ApiError(401, _('No user found’))

               self.user = user

While running a load-test, which fires a lot of requests generated by different clients, the app hangs after a few minutes on the following ORM query in the check_auth_header() method above:

         user = User.objects.defer(
                       'settings',
                       'service_data',

                       'stats',
                       'line_stats',
                       'destination_stats',
                       'country_stats',
                       'carrier_stats'
                   ).get(
                       token=token, is_active=True
                   )

With `django.db.backends` logger enabled, the console log simply stops for over a minute (during which the app is unresponsive), and then resumes. The log then shows a burst of SQL queries along with the django.db.utils.OperationalError exception that occurred:

# client request accepted here:
b'2019-10-13T08:59:59.425035 request    d5cbb088-ed97-11e9-84ad-0242ac1b0004  1 /api/v3/trips/45575/update +0:00:00 '
# log immediately freezes for some time, then resumes below (notice the timestamp gap):

DEBUG 2019-10-13 09:01:17,192 9:140053582601032 django.db.backends (0.002) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,192 9:140053582601032 django.db.backends (0.002) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,204 9:140053582601032 django.db.backends (0.008) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user"  LIMIT 21; args=()
DEBUG 2019-10-13 09:01:17,204 9:140053582601032 django.db.backends (0.008) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user"  LIMIT 21; args=()
DEBUG 2019-10-13 09:01:17,212 9:140053582601032 django.db.backends (0.003) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,212 9:140053582601032 django.db.backends (0.003) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,219 9:140053582601032 django.db.backends (0.002) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,219 9:140053582601032 django.db.backends (0.002) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,228 9:140053582601032 django.db.backends (0.003) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
DEBUG 2019-10-13 09:01:17,228 9:140053582601032 django.db.backends (0.003) SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')  LIMIT 21; args=(True, 'da4cc086128f3878b466dd2693de544efec2e1f1105e59afd872a3cbd0925e76')
ERROR 2019-10-13 09:01:17,331 9:140053582601032 django.request Internal Server Error: /api/v3/trips/45678/update
Traceback (most recent call last):
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 217, in ensure_connection
   self.connect()
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 195, in connect
   self.connection = self.get_new_connection(conn_params)
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/postgresql/base.py", line 178, in get_new_connection
   connection = Database.connect(**conn_params)
 File "/usr/local/lib/python3.6/site-packages/psycopg2/__init__.py", line 130, in connect
   conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
psycopg2.OperationalError: could not connect to server: Connection timed out
 Is the server running on host "192.168.1.19" and accepting
 TCP/IP connections on port 6432?


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
 File "/usr/local/lib/python3.6/site-packages/django/core/handlers/exception.py", line 34, in inner
   response = get_response(request)
 File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py", line 115, in _get_response
   response = self.process_exception_by_middleware(e, request)
 File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py", line 113, in _get_response
   response = wrapped_callback(request, *callback_args, **callback_kwargs)
 File "/usr/local/lib/python3.6/site-packages/django/views/generic/base.py", line 71, in view
   return self.dispatch(request, *args, **kwargs)
 File "/usr/local/lib/python3.6/site-packages/django/utils/decorators.py", line 45, in _wrapper
   return bound_method(*args, **kwargs)
 File "/usr/local/lib/python3.6/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
   return view_func(*args, **kwargs)
 File "/code/gopublic/apps/api/generic.py", line 123, in dispatch
   self.check_auth_header(request)
 File "/code/gopublic/apps/api/generic.py", line 202, in check_auth_header
   token=token, is_active=True
 File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 402, in get
   num = len(clone)
 File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 256, in __len__
   self._fetch_all()
 File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 1242, in _fetch_all
   self._result_cache = list(self._iterable_class(self))
 File "/usr/local/lib/python3.6/site-packages/django/db/models/query.py", line 55, in __iter__
   results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
 File "/usr/local/lib/python3.6/site-packages/django/db/models/sql/compiler.py", line 1098, in execute_sql
   cursor = self.connection.cursor()
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 256, in cursor
   return self._cursor()
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 233, in _cursor
   self.ensure_connection()
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 217, in ensure_connection
   self.connect()
 File "/usr/local/lib/python3.6/site-packages/django/db/utils.py", line 89, in __exit__
   raise dj_exc_value.with_traceback(traceback) from exc_value
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 217, in ensure_connection
   self.connect()
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/base/base.py", line 195, in connect
   self.connection = self.get_new_connection(conn_params)
 File "/usr/local/lib/python3.6/site-packages/django/db/backends/postgresql/base.py", line 178, in get_new_connection
   connection = Database.connect(**conn_params)
 File "/usr/local/lib/python3.6/site-packages/psycopg2/__init__.py", line 130, in connect
   conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
django.db.utils.OperationalError: could not connect to server: Connection timed out
 Is the server running on host "192.168.1.19" and accepting
 TCP/IP connections on port 6432?

The exception is quite clear: django.db.utils.OperationalError: could not connect to server: Connection timed out, but what’s not clear is why it happens sporadically / inconsistently only every few minutes, while usually User.objects.get() works just fine. Also what is very strange is the burst of SQL queries following that “timeout” period. All these queries seemingly originating from the ORM query of User.objects.get() that was made, but they all end with “LIMIT 21” which doesn’t align with our expectation for the single-object query. Rather, they match a query for multiple objects. I am not sure if this strange burst of queries is what’s causing the timeout or a result of it, nor why the “LIMIT 21” is there. There does seem to be a match, though, between these “LIMIT 21” queries and the timeout because during “normal” operation the query generated by User.objects.get() in our check_auth_header() method is of this form: 

SELECT "users_user"."id", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."email", "users_user"."username", "users_user"."first_name", "users_user"."last_name", "users_user"."gender", "users_user"."bio", "users_user"."birthday", "users_user"."is_active", "users_user"."is_staff", "users_user"."moderator", "users_user"."current_ip", "users_user"."date_joined", "users_user"."date_active", "users_user"."confirmed", "users_user"."confirmation_key", "users_user"."confirmation_created", "users_user"."country", "users_user"."language", "users_user"."image", "users_user"."background_image", "users_user"."token", "users_user"."firebase_token", "users_user"."tutorial_id", "users_user"."monitoring", "users_user"."unique_vehicles_used", "users_user"."average_emissions_per_km", "users_user"."trips_since_award", "users_user"."has_app", "users_user"."user_agent", "users_user"."build_number", "users_user"."initial_purchase_date", "users_user"."welcome_email_sent", "users_user"."freemium_quota_reached_date", "users_user"."freemium_quota_reached_count", "users_user"."freemium_announcement_email_sent", "users_user"."freemium_announcement_email_datetime", "users_user"."customer_id" FROM "users_user" WHERE ("users_user"."is_active" = true AND "users_user"."token" = 'd74f1de01d1d5b1d6bfc9017d73418515a2ddc2da5d8ad994fd2f5f0e073235e’)

I am hoping someone can help me understand what may be going on here or at least point me in a direction to look for clues. 

Thank you,

R. Rubnov