[uWSGI] duplicate logs lines going to /var/log/uwsgi.log

[Jeff Dyke]

I have multiple application servers running python code under uWSGI. I'm
currently not making use of any of the uWSGI python
library....strictly executing python functions with werkzeug for simple
routing. These servers writes all log lines to a network logging facility
on another server with a custom format.

What i'm seeing is that after a period of time, which i believe to be
random , the log lines are also written to /var/log/uwsgi.log, but in a
basic format, example:

INFO:pil:SMS - sent to XXXXXXXXX - response status: queued

in the network logger the line looks like:

[2013-03-07 21:02:45,689] 192.168.NN.XX pil INFO 29 sms send_text SMS -
sent to XXXXXXXXX - response status: queued

I started the server at 17:56:37, so this took about 3 hours to start
this behavior. Likely executing about 3000 jobs.

Logically, I can see how this would happen, if a new handler were added to
the list of available log handlers, but we don't configure this anywhere
and why does it log locally? The logger is loaded at the module level, so
either at start up or when at least the first request comes through.
Modules/functions that run underneath this service import the _LOG from the
main wsgi file, so as not to use logging.getLogger() more then once.

I've found that its a bit more than a simple annoyance, the load on these
servers, which normally hover around .5-1 spike to > 6 (4 core machine) and
the uwsgi service then needs to be restarted.

Has any one experienced this? I have two servers running on the the latest
LTS 1.4.8 and an older version 1.2.3, both exhibit the same behaviour.

Hopefully that makes sense...any ideas are greatly appreciated. Config
file follows:

Thanks!
Jeff

<uwsgi>
<gid>33</gid>
<uid>33</uid>
<listen>256</listen>
<single-interpreter></single-interpreter>
<socket>127.0.0.1:9001</socket>
<python-path>/usr/local/lib/python2.7/dist-packages</python-path>
<processes>16</processes>
<master/>
<no-orphans></no-orphans>
<disable-logging />
</uwsgi>

[Roberto De Ioris]

Post by Jeff Dyke
I have multiple application servers running python code under uWSGI. I'm
currently not making use of any of the uWSGI python
library....strictly executing python functions with werkzeug for simple
routing. These servers writes all log lines to a network logging facility
on another server with a custom format.
What i'm seeing is that after a period of time, which i believe to be
random , the log lines are also written to /var/log/uwsgi.log, but in a
INFO:pil:SMS - sent to XXXXXXXXX - response status: queued
[2013-03-07 21:02:45,689] 192.168.NN.XX pil INFO 29 sms send_text SMS -
sent to XXXXXXXXX - response status: queued
I started the server at 17:56:37, so this took about 3 hours to start
this behavior. Likely executing about 3000 jobs.
Logically, I can see how this would happen, if a new handler were added to
the list of available log handlers, but we don't configure this anywhere
and why does it log locally? The logger is loaded at the module level, so
either at start up or when at least the first request comes through.
Modules/functions that run underneath this service import the _LOG from the
main wsgi file, so as not to use logging.getLogger() more then once.
I've found that its a bit more than a simple annoyance, the load on these
servers, which normally hover around .5-1 spike to > 6 (4 core machine) and
the uwsgi service then needs to be restarted.
Has any one experienced this? I have two servers running on the the latest
LTS 1.4.8 and an older version 1.2.3, both exhibit the same behaviour.
Hopefully that makes sense...any ideas are greatly appreciated. Config
Thanks!
Jeff
<uwsgi>
<gid>33</gid>
<uid>33</uid>
<listen>256</listen>
<single-interpreter></single-interpreter>
<socket>127.0.0.1:9001</socket>
<python-path>/usr/local/lib/python2.7/dist-packages</python-path>
<processes>16</processes>
<master/>
<no-orphans></no-orphans>
<disable-logging />
</uwsgi>

You have to take in account that uWSGI maps the fd 1/2 (stdout,stderr) to
its logging system. While i am not sure to follow your configuration (i do
not understand how you add python loggers at runtime) i suppose some
print() or some console logger is writing to fd 1 or 2.