IntegrityError: duplicate key value violates unique constraint "silk_response_request_id_key"

[synotna]

After activating silk certain urls began erring with:

IntegrityError: duplicate key value violates unique constraint "silk_response_request_id_key"
DETAIL: Key (request_id)=(1166) already exists.

Sentry stack trace: http://toolbox1.tedc.de:9000/bidev/esldj/group/131/

[mtford90]

Hi Antony,

Sorry that you're having issues, I'll have a look into this when I get a chance - is it the latest version? I only ask as I saw this myself in the past and thought I'd fixed it...

Cheers.

[synotna]

Latest version from pypi (0.3.1)

Thanks!

[mtford90]

Hi Antony,

So far had no success in replicating this... can you tell me more about your setup? I've only tested Silk in production with gunicorn. (max. 5 workers)

The problem appears to be >1 Response object being assigned to a Request object. Makes no sense for a HTTP request to have two HTTP responses.

The way this works is that a Request model is created in the process_request method of the middleware. A Response model is then created in process_response when the response is sent. Silk makes use of a thread local to store this information as well as the SQL queries and hence assumes that a new thread is created for each request.

It could be something to do with the thread locals. The only other thing that makes sense to me would be that process_response is getting called twice. Not sure how this could happen though...

[joaofrancese]

I am getting this exception a lot when I use Django with Apache and mod_wsgi (Windows).
Please ignore my commit above, it didn't work.

[joaofrancese]

The last commit apparently has fixed it.

[sabine]

I'm encountering the same issue.

I'm using

• 7 gunicorn workers behind nginx with SSL and http -> https and www -> non-www redirects configured
• 'django.middleware.locale.LocaleMiddleware' before 'silk.middleware.SilkyMiddleware' (I noticed that placing LocaleMiddleware after SilkyMiddleware doesn't work)
• silk via pip install -e git+https://github.com/mtford90/silk.git#egg=silk

In addition I want to say that I love this thing. Encountering this issue is no big deal to me since I can run django-silk on the development server without issues.

[mtford90]

@grumpi glad you're finding it useful!

I think there's something fundamentally wrong with the way in which requests are constructed and saved down to the db. @joaofrancese apparently fixed this by appending DataCollector().clear() to the process_response method of the middleware.

I don't really understand how this would help, as my understanding is that process_request and process_response are each called once in the request lifecycle, with the DataCollector being discarded along with the thread anyway... Perhaps I have a misunderstanding here?

[sabine]

Hmm, I've been looking through the code but I can't put my finger on something specific that's broken - I know too little about threading in Python. Still, my gut feeling says that doing this via threading and a Singleton-ish pattern might be unnecessarily dangerous. There's probably a more robust/simple way to keep the DataCollector available to record the data throughout the request-response cycle.

[mtford90]

Yeah, it always did feel kind of iffy, however never really found a better solution. It also probably makes Silk incompatible with any kind of coroutine framework like gevent...

At the end of the day tho, Silk must have some kind of lifecycle-wide object with which to work with. If there is an object that only exists per request lifecycle as opposed to a thread local maybe that can be hijacked for this purpose instead. It would be more generic and would work whether or not threads or coroutine based servers are used.

[sabine]

Ok, apparently django-debug-toolbar also works with thread local data. Means, they don't seem to have a simpler way to do it either.

Apparently, django-debug-toolbar stores the "toolbar" object (which contains "panels" that act as data collectors for all the things they record) in the middleware object. And they use the current thread's identifier to access it (https://github.com/django-debug-toolbar/django-debug-toolbar/blob/master/debug_toolbar/middleware.py).

At least that seems to be a way to get rid of the Singleton - and dealing with threading in the same way they do is pretty likely to not be wrong - considering django-debug-toolbar seems to be pretty stable.

Edit: Apparently it's also possible to do something like threading.local().data_collector = DataCollector(request) to set up a DataCollector for the current thread. But I'm really clueless here. Just poking around in the dark, throwing around ideas I see elsewhere. :)

[mtford90]

Hmmm, I wonder if django debug toolbar is compatible with coroutine-based servers then? Maybe they have two implementations and switch between them, don't have time to look right now tho.

You're right tho, the singleton thang is pretty gross and I will probably just rewrite the whole data collection workflow at some point. I think the issue with duplicate request idents is probably an issue with the data collector itself and not the thread local in this case.

I'll try and come up with a better design within next few days if I get a chacne, and sure, appreciate the ideas, feel free to keep em coming :P

[sabine]

Django-debug-toolbar discourages using the toolbar in production. When I glanced through its code and docs, I didn't notice anything talking specifically about multithreading.

Take your time to think things through, it's always bad to make rushed decisions.

What I really like about this app is how I can collect data over multiple views in the background so I can quickly assess where things are slowest. I have a pretty complex site and I only started with Django in April, so I've got a good deal of inefficient code that I need to refactor as more people start using the site. I'm pretty sure the python profiling will come in handy at some point as well.

[mtford90]

Yeah I certainly intended for this to be used in production - in fact I made it for that purpose for my own apps having been unhappy with new relic etc. But certainly wouldn't advise until it's more stable.

If you do need to use this in production right now you could add a broad exception catch to the data collector where the requests are saved. That means you'll just miss a request occasionally when this bug hits.

[sabine]

I'm not in a hurry, I still have features to code and improve and my user base is so tiny that inefficiency doesn't bring me down. Just catching and discarding the exceptions on silky sounds like a good way to live with it for now. :)

[miguelfg]

Hi,

Same problem here :-(
Here the trace in case it helps:

Traceback (most recent call last):

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/core/handlers/base.py", line 199, in get_response
    response = middleware_method(request, response)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/silk/middleware.py", line 105, in process_response
    self._process_response(response)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/silk/middleware.py", line 94, in _process_response
    silk_response = ResponseModelFactory(response).construct_response_model()

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/silk/model_factory.py", line 246, in construct_response_model
    body=b)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/manager.py", line 157, in create
    return self.get_queryset().create(**kwargs)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/query.py", line 322, in create
    obj.save(force_insert=True, using=self.db)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/base.py", line 545, in save
    force_update=force_update, update_fields=update_fields)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/base.py", line 573, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/base.py", line 654, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/base.py", line 687, in _do_insert
    using=using, raw=raw)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/manager.py", line 232, in _insert
    return insert_query(self.model, objs, fields, **kwargs)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/query.py", line 1514, in insert_query
    return query.get_compiler(using=using).execute_sql(return_id)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 903, in execute_sql
    cursor.execute(sql, params)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/utils.py", line 99, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)

  File "/home/project_name/.virtualenvs/project_name/local/lib/python2.7/site-packages/django/db/backends/util.py", line 53, in execute
    return self.cursor.execute(sql, params)

IntegrityError: duplicate key value violates unique constraint "silk_response_request_id_key"
DETAIL:  Key (request_id)=(7) already exists.

====================
> pip freeze | grep silk
django-silk==0.4

====================

And we are using nginx with supervisor.

The current solution is catching the exception error and forget about it?

[mtford90]

@miguelfg Yeah for now catch that exception and ignore it.

I'm gonna nail this bug for good this weekend! Have been meaning to for ages.

[miguelfg]

@mtford90 I've wrap it in a try/except clause and it's working to me on the server.

Here is my custom_silk_middleware.py:

import json
from django.utils import timezone

from silk.collector import DataCollector
from silk.profiling.profiler import silk_meta_profiler
from silk import models
from silk.middleware import SilkyMiddleware
from silk.model_factory import ResponseModelFactory, Logger


class CustomResponseModelFactory(ResponseModelFactory):

    def construct_response_model(self):
        assert self.request, 'Cant construct a response model if there is no request model'
        Logger.debug('Creating response model for request model with pk %s' % self.request.pk)
        b, content = self.body()
        raw_headers = self.response._headers
        headers = {}
        for k, v in raw_headers.items():
            try:
                header, val = v
            except ValueError:
                header, val = k, v
            finally:
                headers[header] = val
        try:
            silky_response = models.Response.objects.create(request=self.request,
                                                            status_code=self.response.status_code,
                                                            encoded_headers=json.dumps(headers),
                                                            body=b)
        except Exception as e:
            Logger.error('Silk error: {}'.format(e.message))
        # Text fields are encoded as UTF-8 in Django and hence will try to coerce
        # anything to we pass to UTF-8. Some stuff like binary will fail.
        try:
            silky_response.raw_body = content
        except UnicodeDecodeError:
            Logger.debug('NYI: Saving of binary response body')  # TODO
        return silky_response


class CustomSilkyMiddleware(SilkyMiddleware):

    def _process_response(self, response):
        with silk_meta_profiler():
            collector = DataCollector()
            collector.stop_python_profiler()
            silk_request = collector.request
            if silk_request:
                silk_response = CustomResponseModelFactory(response).construct_response_model()
                silk_response.save()
                silk_request.end_time = timezone.now()
                collector.finalise()
                silk_request.save()
            else:
                Logger.error('No request model was available when processing response. Did something go wrong in process_request/process_view?')

And my MIDDLEWARE var in settings has this now:

('middleware.custom_silk_profiling.CustomSilkyMiddleware',)

[miguelfg]

I added as a gist, it looks better -> https://gist.github.com/miguelfg/ec23abf454babc5e6e81

[mtford90]

@miguelfg Great. I'll everyone know this is fixed via this issue once complete

[mtford90]

I am hoping that is fixed now. Requests & Responses now have guids as the primary key, generated python side which should hopefully fix the conflicts. Will be available in next release later today.

[karabijavad]

still getting this error (when i run a unit test)

Traceback (most recent call last):
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/core/handlers/base.py", line 204, in get_response
    response = middleware_method(request, response)
  File "/home/javad/.pyenv/versions/django-rentapplication/src/django-silk/silk/middleware.py", line 116, in process_response
    self._process_response(response)
  File "/home/javad/.pyenv/versions/django-rentapplication/src/django-silk/silk/middleware.py", line 104, in _process_response
    silk_response = ResponseModelFactory(response).construct_response_model()
  File "/home/javad/.pyenv/versions/django-rentapplication/src/django-silk/silk/model_factory.py", line 246, in construct_response_model
    body=b)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/manager.py", line 92, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/query.py", line 372, in create
    obj.save(force_insert=True, using=self.db)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/base.py", line 590, in save
    force_update=force_update, update_fields=update_fields)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/base.py", line 618, in save_base
    updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/base.py", line 699, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/base.py", line 732, in _do_insert
    using=using, raw=raw)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/manager.py", line 92, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/query.py", line 921, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 920, in execute_sql
    cursor.execute(sql, params)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/backends/utils.py", line 65, in execute
    return self.cursor.execute(sql, params)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/home/javad/.pyenv/versions/django-rentapplication/local/lib/python2.7/site-packages/django/db/backends/utils.py", line 65, in execute
    return self.cursor.execute(sql, params)
IntegrityError: duplicate key value violates unique constraint "silk_response_request_id_key"
DETAIL:  Key (request_id)=(16e97114-e211-11e4-a8f3-e8b1fca5bb85) already exists.

[mtford90]

Damn it!

[mtford90]

Ok, I will need to rethink the way that this is done - @karabijavad what django version are you using? Also what server? Is it threaded or async?

[karabijavad]

1.7, and whatever manage.py test uses

[mtford90]

Oh it's happening during test runs... I hadn't thought about that, I wonder if there is something special about the way in which mock requests are setup that cause duplicates. Still doesn't make sense though I don't understand how a duplicate GUID can be created... :D

[avelis]

@digitaldavenyc @reidransom 9c6c8dd was recently made when I realized I was checking the presence of the request attribute on the Request model. In hindsight that made no sense. I could always go back one commit on the branch, however I am not sure when it could produce True to skip the if check.

[avelis]

@digitaldavenyc & @reidransom In the effort of keeping momentum going on this, I have merged the uuid4 branch into master.

I believe the changes made can start to reduce the amount of errors that users are witnessing.

[reidransom]

Unapplying/reapplying migrations seems to have fixed things for me- "would be 404s" are no longer causing 500s. @avelis @digitaldavenyc Thank you!

[digitaldavenyc]

@reidransom happy to assist

[digitaldavenyc]

@avelis I don't think this was resolved, the error is back. Working with a brand new docker container and database locally and the IntegrityError is showing up on all requests. I forced an update to the master branch on github just make sure I'm on the latest and rebuilt, the error is persisting.

[avelis]

@digitaldavenyc Never fear. The bug that will not die is here. So, as I understand it. It's for every request? Instead of just intermittently?

[digitaldavenyc]

@avelis It's on every request

[avelis]

@digitaldavenyc The only resolution I can think of is completely overhauling the request/response middleware behavior and only save the request object when I want to save the response object.

[avelis]

@digitaldavenyc and @reidransom I have removed the addition if logic check in: 3bc0545

[mtford90]

Lots of stabbing in the dark with this issue. Just an idea but I think an integration test that replicates this would help i.e. spin up a Django app on an affected server and blast it with requests until this error shows its ugly face. Could be included in the travis build. It would at least speed up the back and forth on this?

[digitaldavenyc]

@mtford90 I agree, all the guessing is not helping resolve this, however, a heavy load isn't really the cause for this error to appear either, at least from my experience. Happened on the first request.

An overhaul of the request/response might be needed but we don't really know so I think rebuilding that before knowing why would be premature. I'd be happy to contribute to some unit tests that help testing for the IntegrityError.

[reidransom]

@mtford90 @digitaldavenyc When I was testing last week, the errors went away for a bit after dropping and recreating the database table. After a day or so, they came back consistently. While the error is not directly caused by heavy load, a smoke test should still reliably reproduce it.

[mtford90]

Aye, when I suggested heavy load it was to ensure reproduction as opposed to implying only heavy load caused it.

I really really wish I could take this myself but not only am I swamped but I haven't written a line of python for around 10 months now... Any volunteers? 😄

[slavasav]

Hi, one more affected here. Django 1.9, MySQL DB.

[alexanderatallah]

I got rid of most of the errors by moving SilkyMiddleware to the end of my MIDDLEWARE_CLASSES. The errors appeared on URLs without trailing slashes. I set APPEND_SLASH to True, also

But I still get the same error for every static file requested, like favicon.ico (which exists) and robots.txt (which doesn't).

Please help!

[avelis]

@alexanderatallah Could you share which version of Django you are using?

[alexanderatallah]

@avelis yes, here are a couple dependencies:

Django==1.8.2
djangorestframework==3.1.0
django-celery==3.1.17
djrill==2.0
psycopg2==2.5.4
gunicorn==19.1.1

[alexanderatallah]

@avelis actually the most recent update might have fixed it. I had to run python manage.py silk_clear_request_log first, though

[avelis]

@alexanderatallah Clearing the request log might make sense. It would appear that the collector was storing stale data in the result of a 404. Commit: 4355083 addresses that exact scenario. Let me know if it persists again. This issue has become the ultimate zombie bug for me.

[avelis]

@digitaldavenyc @nikicat @slavasav @reidransom @jvlomax Anyone available to see if the latest Commit: 4355083 has resolved this issue for you? It might require running the management command silk_clear_request_log.

[dvinegla]

@avelis, It works for me.
thank you very much!

[auvipy]

hopefully this is resolved in master?

[auvipy]

@avelis lets close it for now

[avelis]

For closure, any release 0.6.2 or newer should have this issue addressed.

[tyc85]

Hi all,
Despite this being closed for a while, I am seeing the problem on macOS, python 3.7 (same problem for 3.6 and 3.8 as well). It doesn't even take a loaded requests to emerge, and of course the code somehow catch the exception and move on without throwing, but it flooded the logs and likely means the intended feature/behavior is not going to work. I was wondering what I can help to fix this issue.

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/silk/middleware.py", line 139, in process_response
    self._process_response(request, response)
  File "/usr/local/lib/python3.7/contextlib.py", line 74, in inner
    return func(*args, **kwds)
  File "/usr/local/lib/python3.7/site-packages/silk/middleware.py", line 118, in _process_response
    silk_response = ResponseModelFactory(response).construct_response_model()
  File "/usr/local/lib/python3.7/site-packages/silk/model_factory.py", line 319, in construct_response_model
    body=b
  File "/usr/local/lib/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/query.py", line 422, in create
    obj.save(force_insert=True, using=self.db)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/base.py", line 741, in save
    force_update=force_update, update_fields=update_fields)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/base.py", line 779, in save_base
    force_update, using, update_fields,
  File "/usr/local/lib/python3.7/site-packages/django/db/models/base.py", line 870, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/base.py", line 908, in _do_insert
    using=using, raw=raw)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/query.py", line 1186, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "/usr/local/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1375, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.7/site-packages/django/db/backends/utils.py", line 99, in execute
    return super().execute(sql, params)
  File "/usr/local/lib/python3.7/site-packages/sentry_sdk/integrations/django/__init__.py", line 472, in execute
    return real_execute(self, sql, params)
  File "/usr/local/lib/python3.7/site-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/usr/local/lib/python3.7/site-packages/django/db/backends/utils.py", line 76, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.7/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.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.IntegrityError: duplicate key value violates unique constraint "silk_response_request_id_key"
DETAIL:  Key (request_id)=(3edb5734-11ef-4256-a5e8-bcb6afb71e1a) already exists.