opencensus-python: Django server is not running with AzureLogHandler
Describe your environment.
Python 3.7.6
Django==2.2.13
django-cors-headers==3.2.0
django-extensions==2.2.5
django-filter==2.2.0
django-rest-swagger==0.3.10
django-sslserver==0.22
django-treebeard==4.3
djangorestframework==3.10.3
djangorestframework-csv==2.1.0
djangorestframework-jwt==1.11.0
opencensus==0.7.7
opencensus-context==0.1.1
opencensus-ext-azure==1.0.2
opencensus-ext-django==0.7.2
Steps to reproduce.
Add AzureLogHandler to Django LOGGING config in order to export all logs to Azure :
Django LOGGING config :
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(asctime)s %(levelname).3s %(process)d %(name)s : %(message)s',
},
'simple': {
'format': '%(asctime)s %(levelname)-7s : %(message)s',
},
},
'filters': {
'require_debug_false': {
'()': 'django.utils.log.RequireDebugFalse',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'formatter': 'verbose',
},
'azure': {
'formatter': 'simple',
'class': 'opencensus.ext.azure.log_exporter.AzureLogHandler',
'connection_string': 'InstrumentationKey=XXXX-XXXX-XXXX-XXXX'
},
'mail_admins': {
'level': 'ERROR',
'filters': ['require_debug_false'],
'class': 'django.utils.log.AdminEmailHandler'
}
},
'loggers': {
'': {
'level': os.environ.get('LOGLEVEL', 'INFO'),
'handlers': ['console', 'azure'],
},
'devdebug': {
'handlers': ['console'],
'level': 'INFO',
'propagate': False,
},
'django': {
'handlers': ['console', 'mail_admins'],
'level': os.environ.get('LOGLEVEL', 'INFO'),
'propagate': False,
}
},
}
What is the expected behavior?
When running manage.py runsslserver localhost:53215, the server should run and must be accessible :
curl -v http://127.0.0.1:53215/
* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 53215 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1:53215
> User-Agent: curl/7.58.0
> Accept: */*
>
* Recv failure: Connection reset by peer
* stopped the pause stream!
* Closing connection 0
curl: (56) Recv failure: Connection reset by peer
What is the actual behavior?
When running manage.py runsslserver localhost:53215, the server run (without error log) but is not accessible :
curl -v http://127.0.0.1:53215/
* Trying 127.0.0.1...
* TCP_NODELAY set
* connect to 127.0.0.1 port 53215 failed: Connection refused
* Failed to connect to 127.0.0.1 port 53215: Connection refused
* Closing connection 0
curl: (7) Failed to connect to 127.0.0.1 port 53215: Connection refused
About this issue
- Original URL
- State: closed
- Created 4 years ago
- Reactions: 3
- Comments: 30 (15 by maintainers)
My workaround is to set ‘disable_existing_loggers’: True,
There seems to be a deadlock. Where azureloghandler sends an message with requests, which uses urllib3. Urllib3 tries to log this event, but when checking logging level it waits on the lock of logging to be released. At the same time the main thread is configuring logging and it locks during the close of previous loggers.
@lzchen I can confirm there’s an issue with the AzureLogHandler when using Django’s runserver. We had the same problem within a project. I’ve been able to reproduce the issue with the most basic django project (./manage.py startproject) with:
requirements.txt:
logging config in project settings:
With that, if you launch the runserver (./manage.py runserver), the runserver will hang forever, and not respond to anything.
I’ve tried debugging a bit, it seems it’s stuck when trying to acquire a lock in the logging lib. Here’s the stacktrace:
A few notes:
The issue was reproduced with both Python 3.7+ and Python 3.8+ (on MacOS & Ubuntu)
The bug disappears when running the app with gunicorn.
The bug also disappears when changing the level of django logger from ‘INFO’ to ‘WARNING’.
It seems that it blocks whenever a log is emitted ‘early’ in the launching of Django’s runserver. For instance, if you change the loggers config to that:
It will work again. Probably because Django’s ‘early’ INFO logs in the runserver were not send to azure. But if you add a basic app, like polls in the Django tutorials, and put the following code in the init.py of the polls folder:
The runserver will get stuck again. If you remove this, and put ‘regular’ logs in the polls app, it will be ok. It really looks like it’s due to emitting logs to Azure during the initialization of Django’s runserver.
I hope this helps !