9

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

4
  • 1
    my offer use a logger server on localhost and send every log request.
    – dsgdfg
    Commented Sep 14, 2015 at 12:23
  • this works same way as sysloghandler, eh?
    – Wesley
    Commented Sep 14, 2015 at 12:46
  • Syslog is what I use most often; even without resorting to "advanced" servers (e.g rsyslog), you can set it up quickly with logrotate. There is also method recommended in python docs which uses Queue (example | packaged)
    – tutuDajuju
    Commented Oct 11, 2015 at 17:32
  • Incidently, uWSGI documentation on logging explains their implementation and gives examples.
    – tutuDajuju
    Commented Oct 11, 2015 at 17:36

2 Answers 2

7

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.

2
  • Hi, thanks for detailed reply, but have you tried when uwsgi workers are more than 1?
    – Wesley
    Commented Oct 12, 2015 at 6:10
  • I have verified uWSGI works as intended with 4 processes all logging nicely (in turns) to same file, which is rotated once size is reached. The example has been updated to show the new output
    – tutuDajuju
    Commented Oct 12, 2015 at 8:05
1

If you have to use python's logrotation (when multiple gunicorn processes are pointing to the same log file) then you should make sure that the main log file is only edited and not renamed, moved etc during rotation. For this, you copy the main log file and then clear it out!

Snippet for rollover method (edit in logging.handlers.RotatingFileHandler's code)

def doRollover(self):
    self.stream.close()
    if self.backupCount > 0:
        for i in range(self.backupCount - 1, 0, -1):
            sfn = "%s.%d" % (self.baseFilename, i)
            dfn = "%s.%d" % (self.baseFilename, i + 1)
            if os.path.exists(sfn):
                if os.path.exists(dfn):
                    os.remove(dfn)
                os.rename(sfn, dfn)
        dfn = self.baseFilename + ".1"
        if os.path.exists(dfn):
            os.remove(dfn)
        # os.rename(self.baseFilename, dfn) # Intead of this
        # Do this
        shutil.copyfile(self.baseFilename, dfn)
        open(self.baseFilename, 'w').close()
    if self.encoding:
        self.stream = codecs.open(self.baseFilename, "w", self.encoding)
    else:
        self.stream = open(self.baseFilename, "w")

Then you can create your logger like this:

logger = logging.getLogger(logfile_name)
logfile = '{}/{}.log'.format(logfile_folder, logfile_name)
handler = RotatingFileHandler(
    logfile, maxBytes=maxBytes, backupCount=10
)
formatter = logging.Formatter(format, "%Y-%m-%d_%H:%M:%S")
formatter.converter = time.gmtime
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO)
logger.isEnabledFor = lambda level: True
logger.propagate = 0

logger.warning("This is a log")
1
  • You save my life. A little update on your method. Since py3.3, there is a rotator attribute for you to override that pieces of code. docs.python.org/3/library/…
    – Mond Wan
    Commented Apr 1, 2020 at 10:09

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.