DatabaseError with ddtrace

[szaboat]

Traceback (most recent call last):
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/signup/views/signup.py", line 199, in edu_school_reg
    token = EDUVerifyToken.objects.create_token(email=email, domain=domain, name=data['name'], plan_family=data['plan_family'], action=action, upgrade_email=upgrade_email, user_id=user_id, school_data=school_data)
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/signup/models.py", line 69, in create_token
    token.save()
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/signup/models.py", line 99, in save
    super(EDUVerifyToken, self).save(**kwargs)
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/models/base.py", line 734, in save
    force_update=force_update, update_fields=update_fields)
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/models/base.py", line 759, in save_base
    with transaction.atomic(using=using, savepoint=False):
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/transaction.py", line 150, in __enter__
    if not connection.get_autocommit():
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/base/base.py", line 286, in get_autocommit
    self.ensure_connection()
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/base/base.py", line 130, in ensure_connection
    self.connect()
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/base/base.py", line 121, in connect
    self.init_connection_state()
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/mysql/base.py", line 282, in init_connection_state
    with self.cursor() as cursor:
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/ddtrace/contrib/django/db.py", line 35, in cursor
    return TracedCursor(tracer, conn, conn._datadog_original_cursor())
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/base/base.py", line 160, in cursor
    self.validate_thread_sharing()
  File "/opt/prezi/signup/versions/318-db1a27e562e267603c55ea13e8db46b29d715834/virtualenv/local/lib/python2.7/site-packages/django/db/backends/base/base.py", line 421, in validate_thread_sharing
    % (self.alias, self._thread_ident, thread.get_ident()))
DatabaseError: DatabaseWrapper objects created in a thread can only be used in that same thread. The object with alias 'default' was created in thread id 40345840 and this is thread id 76693744.

ddtrace created a DatabaseWrapper in a different thread. And an exception is raised when the save called on the model.

Current dependencies

gunicorn==19.3
MySQL-python==1.2.5
ddtrace==0.11.0
datadog==0.19.0

[palazzem]

Hello @szaboat ! can you check if you still have this issue with the latest version? https://github.com/DataDog/dd-trace-py/releases/tag/v0.11.1

We did a change in how Django is instrumented (I see you're using also Django), so maybe that problem was connected with another one. If it's not working, let us know so we can investigate more. Thank you!

[szaboat]

DatabaseError: DatabaseWrapper objects created in a thread can only be used in that same thread. The object with alias 'default' was created in thread id 28065872 and this is thread id 119261136.
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "signup/views/signup.py", line 200, in edu_school_reg
    token = EDUVerifyToken.objects.create_token(email=email, domain=domain, name=data['name'], plan_family=data['plan_family'], action=action, upgrade_email=upgrade_email, user_id=user_id, school_data=school_data)
  File "signup/models.py", line 69, in create_token
    token.save()
  File "signup/models.py", line 99, in save
    super(EDUVerifyToken, self).save(**kwargs)
  File "django/db/models/base.py", line 734, in save
    force_update=force_update, update_fields=update_fields)
  File "django/db/models/base.py", line 759, in save_base
    with transaction.atomic(using=using, savepoint=False):
  File "django/db/transaction.py", line 150, in __enter__
    if not connection.get_autocommit():
  File "django/db/backends/base/base.py", line 286, in get_autocommit
    self.ensure_connection()
  File "django/db/backends/base/base.py", line 130, in ensure_connection
    self.connect()
  File "django/db/backends/base/base.py", line 121, in connect
    self.init_connection_state()
  File "django/db/backends/mysql/base.py", line 282, in init_connection_state
    with self.cursor() as cursor:
  File "ddtrace/contrib/django/db.py", line 51, in cursor
    return TracedCursor(tracer, conn, conn._datadog_original_cursor())
  File "django/db/backends/base/base.py", line 160, in cursor
    self.validate_thread_sharing()
  File "django/db/backends/base/base.py", line 421, in validate_thread_sharing
    % (self.alias, self._thread_ident, thread.get_ident()))

Unfortunately it's not working and we are getting the same error with v0.11.1.

ddtrace 0.11.1
django 1.8.16
python  2.7.3

[palazzem]

@szaboat ok it wasn't connected to this problem. Let me schedule some work on it, so that I can reach you back with a realistic ETA for the fix. Thanks for reporting that!

[the-mace]

Same issue for me, cant use ddtrace the way this is.

[palazzem]

Hello @the-mace and @szaboat! We'll start working on this issue next week so that it will be part of the next bugfix release! We'll keep you updated on this thread in case we need more details to properly reproduce the problem.

Thank you very much!

[babus]

@palazzem Any update on this? We're evaluating datadog on our Python3.6 infrastructure and this is a blocker atm.

ddtrace==0.12.0
Django==1.11.13
uWSGI==2.0.17
gevent==1.2.2

Here is the supervisord config for uwsgi+gevent+django app which is reverse proxied with nginx.

[program:uwsgi]                                                                             
command=/home/vagrant/env3.6/bin/ddtrace-run /home/vagrant/env3.6/bin/uwsgi                 
        --socket=/tmp/uwsgi.sock                                                            
        --chdir=/home/vagrant/upcomer-backend                                               
        --module=upcomer.wsgi:application                                                   
        --master --pidfile=/tmp/uwsgi-master.pid                                            
        --processes=1                                                                       
        --enable-threads                                                                    
        --gevent-early-monkey-patch                                                         
        --max-requests=5000                                                                 
        --harakiri=30                                                                       
        --vacuum                                                                            
        --venv=/home/vagrant/env3.6                                                         
        --logto=/var/log/uwsgi.log                                                          
        --chmod-socket=666                                                                  
        --gevent=1000                                                                       
        --py-tracebacker=/tmp/tbsocket                                                      
        --ignore-sigpipe                                                                    
        --ignore-write-errors                                                               
        --disable-write-exception                                                           
directory=/home/vagrant/upcomer-backend                                                     
numprocs=1                                                                                  
autostart=true                                                                              
autorestart=unexpected                                                                      
startsecs=1                                                                                 
startretries=3                                                                              
exitcodes=0,2                                                                               
killasgroup=false                                                                           
stdout_logfile=/var/log/uwsgi.out                                                           
stdout_logfile_maxbytes=10MB                                                                
stdout_logfile_backups=10                                                                   

We tried disabling gevent to see if that resolves the issue but it didn't. It's not working with the default django postgres db engine too. @szaboat Did you find the fix?

[szaboat]

@babu-upcomer unfortunately not and it also became a blocker for us. we didn't have time to debug it, so we are not using dd-trace now. sad but true.

[palazzem]

Hello @babu-upcomer and thanks for sharing your details! We're actually planning to make some changes for this instrumentation because it doesn't play very well on some use cases. Unfortunately it's taking a bit more time because we need to investigate how to make it work even for use cases we're already supporting.

@szaboat I'm sorry about that! One thing I would like to ask is if you're using gevent too. Also, would you like to help us to test the fix once it's out?

I'll keep you both updated!

[babus]

@szaboat Ok. Till then following your blog post here we have done only the integration in the Django settings without encapsulating ddtrace-run with the wsgi server command. That is,

INSTALLED_APPS = [
  # your Django apps...
  'ddtrace.contrib.django',
]

and can see partial traces, sometimes the 'web' service dashboard shows django.request and most of the times it shows django.cache under the same 'web'. And also the request breakup is not up-to the satisfactory level. It shows only the cache and db calls but not any external HTTP API calls in the same request for example.

Also is it mandatory to encapsulate the wsgi server command with ddtrace-run or just adding 'ddtrace.contrib.django' in the INSTALLED_APPS would be enough? This part is never been clear in any of your docs as I can see the partial traces even without configuring ddtrace-run.

[palazzem]

ddtrace-run script is just a wrapper that tries to patch all recognized frameworks and libraries. If you're adding the Django app as you've suggested, you'll get the same result but only Django is instrumented. I have a couple of questions not entirely related to this issue (but worth for our investigation):

1. because you see sometimes the django.request and sometimes django.cache, do you know what is calling the cache system outside the scope of a request? maybe a Django command or another integration?
2. about external HTTP API calls, what are you using inside Django to make these calls? we actually offer the stdlib and requests integration that should track these calls for you. If you can explain a bit more, I may provide some suggestions to increase the request breakdown.
3. the encapsulation via ddtrace-run is not mandatory. You can instrument your libraries using the snippets defined in our documentation. You'll obtain the same result. If not, then more work on ddtrace-run script must be done and this is why we started scheduling more work on it. Since we're collecting such feedbacks, would you prefer wrapping everything via ddtrace-run, or do you prefer enabling each single integration via patch() API / Django app?

Thank you for the feedbacks!

[babus]

1. We do use django-channels for websockets which uses redis as the cache layer. So probably that could be a reason as it uses the same django settings. And that's why encapsulating ddtrace-run over uwsgi or gunicorn or celery workers would make more sense than configuring it in the settings.py as it will be shared by many other apps/services.

2. Yes, they are made from requests lib. Not even a single HTTP request is being traced as a metric across thousands of requests logged. Probably it is not patched when configuring through settings.py.

3. We would prefer to use ddtrace-run as we can control what needs to be traced under a particular service. For example, I would like to see uwsgi and celery as different services in the dashboard. And saying so, when using uwsgi/gunicorn along with --gevent or any other event loop and --processes, anyone would prefer to measure the concurrency and see the traces per process if possible. For example, "How many requests per second being served by 'uwgi-proc-1' in the last 1 hour?". It might be too much to demand and involve a lot of technicalities but these are the basics anyone would think of.

[palazzem]

OK thanks for all the details. I'll proceed the investigation and will reach you back today with more questions. Actually I think I've reproduced the problem with your configurations. I'll keep you all updated!

[palazzem]

After investigating the problem, I may have found the root cause (or at least one of them). For now, let's focus in using the ddtrace-run script without causing the DatabaseError exception. Do you have a way to test this PR (#481) and see if the problem is here again?

If the application runs as expected, we can say the issue is solved. Then we can chat about other remaining issues that are (if I didn't miss something):

• sometimes you see django.request and sometimes django.cache
• requests not instrumented -> when using ddtrace-run script you can enable the instrumentation using the following environment variable

DATADOG_PATCH_MODULES=requests:true ddtrace-run uwsgi [...]

Using only the Django app, will not instrument other libraries. Thanks for pushing the resolution of this (critical) issue.

cc @szaboat @babu-upcomer @the-mace

[babus]

@palazzem I'll test in my local and let you know.

[palazzem]

Thank you very much!

[babus]

@palazzem Can't install from that PR. I guess your fork is not public. How could I install that commit using pip or should I wait till it is merged with origin master?

[palazzem]

I think you can install it via pip:

$ pip install git+https://github.com/DataDog/dd-trace-py@palazzem/django-remove-signals

or in your requirements.txt file:

git+https://github.com/DataDog/dd-trace-py@palazzem/django-remove-signals

Does it work using https?

[babus]

Tested in my local, it worked. The error is not occurring. Btw, when you said the request is not automatically patched and needs to be patched manually, can it be set in the django settings module? Like this,

DATADOG_PATCH_MODULES = {
    'request': True,
}

Because we have a tens of workers and other python manage.py commands being spawned up along with the uwsgi web server. All share the common django settings.py and setting this there would be more easier.

[palazzem]

@babu-upcomer great! I'm going to merge that PR closing this issue then. I'll move the chat in another thread so I can provide a better support for this other problem. I'll ping you there: #485

Thank you very much everyone and feel free to re-open the issue if you think it's not solved! The release will be out this week. Sorry for the delay in the release, but we prefer to verify with the community that the problem is really solved, and it took a bit more.

[babus]

This issue started reappearing from ddtrace 0.16. We are stuck with 0.15.0. Using Django+gunicorn with gevent workers.

[babus]

@palazzem Any update?

[palazzem]

Hello @babu-upcomer !
We'll start investigating this issue again, even though it's very weird it surfaced again. @majorgreys can you double check in case we have a regression?

Thanks to report that! we'll reach you back as soon we have news to share!

[babus]

"/opt/python/bin/gunicornlaunch":
        mode: "000755"
        owner: root
        group: root
        content: |
          #!/bin/bash

          # Trying to override the /tmp permissions.
          chmod -R 777 /tmp

          # Launch Gunicorn server
          # The purpose of this script is to set some environment variables before
          # launching Gunicorn server.
          source /opt/python/current/env

          if [ -f /etc/elasticbeanstalk/set-ulimit.sh ]; then
              source /etc/elasticbeanstalk/set-ulimit.sh
          fi

          exec /opt/python/run/venv/bin/ddtrace-run /opt/python/run/venv/bin/gunicorn \
            --worker-class=gevent \
            --workers=4 \
            --worker-connections=1000 \
            --bind=unix:/opt/python/log/gunicorn.sock \
            --chdir=/opt/python/current/app \
            --access-logfile=/var/log/gunicorn-access.log \
            --error-logfile=/var/log/gunicorn-error.log \
            --log-level=debug \
            --pythonpath=/opt/python/current/app \
            app_backend.wsgi:application

    "/opt/python/etc/supervisor-conf/interface-servers.conf":
        mode: "000644"
        owner: root
        group: root
        content: |
          [program:gunicorn]
          environment=DATADOG_PATCH_MODULES="gevent:true,requests:true,celery:true",DJANGO_SETTINGS_MODULE=upcomer.settings
          command=/opt/python/bin/gunicornlaunch
          directory=/opt/python/current/app
          numprocs=1
          process_name=%(program_name)s%(process_num)d
          autostart=true
          autorestart=unexpected
          startsecs=1                   ; number of secs prog must stay running (def. 1)
          startretries=3                ; max # of serial start failures (default 3)
          exitcodes=0,2                 ; 'expected' exit codes for process (default 0,2)
          killasgroup=false             ; SIGKILL the UNIX process group (def false)
          stdout_logfile=/var/log/gunicorn.out
          stdout_logfile_maxbytes=10MB   ; max # logfile bytes b4 rotation (default 50MB)
          stdout_logfile_backups=10     ; # of stdout logfile backups (default 10)

          [group:interface-servers]
          programs=gunicorn

requirements.txt

@palazzem This is our current stack. We switched to gunicorn+gevent workers later but again stuck with the 0.15.

[DocX]

[Solution included]

We had similar problem. Running gunicorn + geven as worker class. With using the out-of-the-box ddtrace-run command, we started getting the DatabaseWrapper errors.

Our stack:

Django==1.8.19
djangorestframework==3.4.7
django-filter==0.10.0
MySQL-python==1.2.5
django-simple-history==1.7.0
gunicorn==19.10.0
gevent==1.2
ddtrace==0.40.0

Solution
We found this solution. In the starter script, we tell ddtrace to not patch django automatically, and to patch gevent automatically (i.e. in both cases opposite of the default):

export DATADOG_PATCH_MODULES="gevent:true,django:false"

ddtrace-run gunicorn ...

Then in the django app settings.py, we patch the django manually (this ensures that the patch is applied in each individual worker, rather than in the root process:

# settings.py

from ddtrace import config, patch
patch(django=True)

Hope it helps someone to not waste a week debugging this :D