multiple processors logging to same rotate file

Question

I hit a problem with my nginx+uwsgi+django site. I know it's nothing special to django+uwsgi, should be something with logging module itself.

Within my site, I use RotatingFileHandler to log special entries, but, when uwsgi running with multiple worker processors,today i find that, multiple log files are changing at the same time. For example, here is file snippet:

[root@speed logs]# ls -lth
total 18M
-rw-rw-rw- 1 root root  2.1M Sep 14 19:44 backend.log.7
-rw-rw-rw- 1 root root  1.3M Sep 14 19:43 backend.log.6
-rw-rw-rw- 1 root root  738K Sep 14 19:43 backend.log.3
-rw-rw-rw- 1 root root  554K Sep 14 19:43 backend.log.1
-rw-rw-rw- 1 root root 1013K Sep 14 19:42 backend.log.4
-rw-rw-rw- 1 root root  837K Sep 14 19:41 backend.log.5
-rw-rw-rw- 1 root root  650K Sep 14 19:40 backend.log.2
-rw-rw-rw- 1 root root  656K Sep 14 19:40 backend.log
-rw-r--r-- 1 root root   10M Sep 13 10:11 backend.log.8
-rw-r--r-- 1 root root     0 Aug 21 15:53 general.log
[root@speed-app logs]#

Actually, I set rotate file to 10M perfile and upto 10 files.

I googled a lot and many people hit this before, seems logging module itself cannot support this.

And I find someone mentioned ConcurrentLogHandler(https://pypi.python.org/pypi/ConcurrentLogHandler/0.9.1). Anybody uses this guy before? I see it's based on file lock, I don't know if this guy's performance is good enouth.

Or anyone has better idea to log multiple uwsig instances to same rotated file ?

Thanks. Wesley

Answer 1

Just for the heck of it, here is a complete solution example which uses python StreamHandler, uWSGI "daemonized file logging", and logrotate daemon to log to file with rotation.

As you will see, uWSGI logging captures stdout/stderr from your app and redirects it either to stdout/stderr (by default) or to other logger/handlers as defined.

Setup Django/uWSGI

Your Django settings.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s - %(process)s - %(levelname)s - %(name)s : %(message)s',
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    },
}

Somewhere in your code

log = logging.getLogger(__name__)
log.info("test log!")

Run uWSGI with some logging params

$ uwsgi --http :9090 --chdir=`pwd -P` --wsgi-file=wsgi.py \
    --daemonize=test.log \  # daemonize AND set log file
    --log-maxsize=10000  \  # a 10k file rotate
    --workers=4             # start 4 workers

Output

Excerpt of test.log

*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 79755)
spawned uWSGI worker 1 (pid: 79813, cores: 1)
spawned uWSGI worker 2 (pid: 79814, cores: 1)
spawned uWSGI worker 3 (pid: 79815, cores: 1)
spawned uWSGI worker 4 (pid: 79816, cores: 1)
spawned uWSGI http 1 (pid: 79817)
2015-10-12 07:55:48,458 - 79816 - INFO - testapp.views : test log!
2015-10-12 07:55:51,440 - 79813 - INFO - testapp.views : test log!
2015-10-12 07:55:51,965 - 79814 - INFO - testapp.views : test log!
2015-10-12 07:55:52,810 - 79815 - INFO - testapp.views : test log!

In the same dir, after a while:

-rw-r-----   1 big  staff   1.0K Oct 12 09:56 test.log
-rw-r-----   1 big  staff    11K Oct 12 09:55 test.log.1444636554

Logrotate

Alternatively, to handle rotating the files yourself, omit the --log-maxsize parameter and use a logrotate config file (/etc/logrotate.d/uwsgi-test-app):

/home/demo/test_django/*log {
    rotate 10
    size 10k
    daily
    compress
    delaycompress
}

Please note, the above values are for example sake, you probably don't want the rotate size at 10k. For more info on the logrotate format, see an example blog post.