info messages logged as error by apache mod_wsgi server

[sethhillbrand]

I am running syncserver 1.5 using Apache 2.2, mod_wsgi 3.3. When clients connect to the server, the error log fills with info level messages even though I have the log level in apache set to "warn".

From Apache's error log:

[Fri Jun 20 11:03:31 2014] [error] INFO:mozsvc.metrics:{"code": 200, "request_time": 0.005326032638549805, "remoteAddressChain": ["130.86.92.7"], "agent": "Firefox/30.0 FxSync/1.32.0.20140605174243.desktop", "syncstorage.storage.sql.pool.get": 4.315376281738281e-05, "syncstorage.storage.sql.db.execute": 0.002168893814086914, "path": "https://hostname:port/storage/1.5/1/storage/meta/global", "method": "PUT"}

[rfk]

Sounds like it's not respecting the setting in apache - can you please share how you configure it in apache and I'll take a look?

[sethhillbrand]

Here is the apache site file with minor edits. The log quoted above is from the ffsync_error.log file.

DocumentRoot DIRECTORY/syncserver
<Directory DIRECTORY/syncserver>
    Order deny,allow
    Allow from all
</Directory>

WSGIProcessGroup GROUP
WSGIDaemonProcess ffsync user=USER group=GROUP processes=2 threads=25
WSGIPassAuthorization On
WSGIScriptAlias / DIRECTORY/syncserver/syncserver.wsgi

ErrorLog ${APACHE_LOG_DIR}/ffsync_error.log
LogLevel warn

CustomLog ${APACHE_LOG_DIR}/ffsync_access.log combined

SSLEngine on

SSLCertificateKeyFile ###Keyfile###
SSLCertificateFile ###CertificateFile###
SSLCACertificatePath ###PATH###
SSLCACertificateFile ###PATH###

<FilesMatch "\.(cgi|shtml|phtml|php)$">
    SSLOptions +StdEnvVars
</FilesMatch>
<Directory /usr/lib/cgi-bin>
    SSLOptions +StdEnvVars
</Directory>

[highball-it]

I have the same problem running syncserver 1.6 with Apache/2.4.10 with mod_wsgi.
The entrys look like this:

[Wed Oct 07 12:59:50.890662 2015] [wsgi:error] [pid 6130] INFO:mozsvc.metrics:{"code": 200, "request_time": 0.009422063827514648, "remoteAddressChain": ["xx.xx.xx.xx"], "agent": "Firefox/41.0.1 FxSync/1.43.0.20150929144111.desktop", "syncstorage.storage.sql.pool.get": 7.605552673339844e-05, "syncstorage.storage.sql.db.execute": 0.0029218196868896484, "path": "https://token.domain.tld/storage/1.5/1/storage/bookmarks", "method": "GET"}

@rfk Could you give a hint which part of the apache configurations isn't respected? Or did @sethhillbrand found a solution?

Thanks in advance.

[rfk]

TBH I don't know that much about mod_wsgi, but looking at this again, I wonder if it's because the syncserver code calls logging.basicConfig which IIUC will send log message to stderr:

https://github.com/mozilla-services/syncserver/blob/master/syncserver/__init__.py#L95

You could try adding a "loggers" config section in your syncserver.ini file, following the format here:

https://docs.python.org/2/library/logging.config.html#logging-config-fileformat

And e.g. redirect them to stdout or to a separate file.

[highball-it]

I think your assumption is correct. In the second paragraph [1] it says:

"Messages that are logged by a WSGI application via the 'wsgi.errors' object passed through to the application in the WSGI environment are also logged. These will got to the virtual host error log file if it exists..."

For me, as a solution I set the loglevel to loggin.ERROR:
https://github.com/mozilla-services/syncserver/blob/master/syncserver/__init__.py#L95

[1] https://code.google.com/p/modwsgi/wiki/DebuggingTechniques#Apache_Error_Log_Files

[godfuture]

As info logs in error log file seems odd, and I say it because I had quite some issues installing syncserver reading this error log, I ask myself if Mozilla will solve this issue or everyone has to tackle it on their own...

PS: I did not really get through the logger configuration. But if it might be solved by configuration, why not Mozilla to provide the config? ....just askin...

[rfk]

Let's just change it to log at WARN by default, I don't recall ever finding the info logs to be that useful. #79

I also encountered this issue now (using syncserver@1.5.2. Just to make things clear: You say that for this version, this behaviour is normal and I can safetly ignore it until it gets fixed in future releases?

[rfk]

I can safetly ignore it

Yes.

until it gets fixed in future releases

Thanks for the reminder that I should explicitly make a new tag; expect a 1.6.0 tag shortly.

Thank you kindly for that fast response @rfk :)