meebo/greins — Issue #14: Greins should configure root logger
Author: markdoliner
Created: 2011-12-08 20:25:18+00:00
State: open

Let's talk about logging!

## Who's responsible?
I think _something_ should configure a root logger, so that messages from greins apps get logged. The question is: who's responsible for configuring it?

I don't think greins apps should be responsible, because they're basically just libraries and they don't care how they're invoked (is that accurate?). Also, there can be many greins apps, but only one root logger. It doesn't make sense for all of them to try to configure the root logger.

I don't think gunicorn should be responsible, because greins is effectively using gunicorn as a library, and libraries shouldn't configure the root logger. Although, gunicorn.workers.base DOES attach to signals, which is usually something that the app does and not something libraries do.

I think greins should be responsible for this. greins is the harness that's running all this stuff. It's the thing the sysadmin interacts with. It's the thing that gets configured.

## Possible implementation 1
Greins could piggyback off the gunicorn error log. One thing that's a little goofy is, because we're re-using gunicorn's log handler, we have to turn off propagation for the error log to avoid duplicate logs from gunicorn. On the plus side, this is a really small change.

diff --git a/greins/app.py b/greins/app.py
index 5550268..6fffffb 100644
--- a/greins/app.py
+++ b/greins/app.py
@@ -31,6 +31,11 @@ class GreinsApplication(WSGIApplication):
self._hooks = {}
self._hooks_lock = None

+ # Configure the root logger to log to the gunicorn error log
+ gunicorn_error_logger = logging.getLogger('gunicorn.error')
+ logging.getLogger().handlers = gunicorn_error_logger.handlers
+ gunicorn_error_logger.propagate = False
+
def setup_hooks(self):
"""
Set up server hook proxies

## Possible implementation 2
Forsake the gunicorn error log and do it ourselves. I think this approach is cleaner, but it has some bugs:
1. When I "service greins reload," my logger gets added twice, so log lines are duplicated. Reloading against causes log lines to be triplicated. Etc. Fixable.
2. When I "service greins restart," stuff that should go to greins.log actually goes to access_log. I don't understand this at all. Probably fixable.
3. I think this won't re-open the log when the process receives SIG USR1. Might not be fixable. But using WatchedFileHandler makes this not an issue?

diff --git a/etc/init/greins b/etc/init/greins
index c20c5db..01bda44 100755
--- a/etc/init/greins
+++ b/etc/init/greins
@@ -72,7 +72,7 @@ start() {
status_q -p $pidfile $prog && log_warning_msg "already running" && exit 0
$exec -D \
-p $pidfile \
- --log-file $GREINS_LOG_FILE \
+ --greins-log-file $GREINS_LOG_FILE \
-u $GREINS_USER -g $GREINS_GROUP \
-b $GREINS_BIND_ADDR \
$GREINS_OPTIONS \
diff --git a/greins/app.py b/greins/app.py
index 5550268..68e4181 100644
--- a/greins/app.py
+++ b/greins/app.py
@@ -1,6 +1,7 @@
import glob
import inspect
import logging
+from logging.handlers import WatchedFileHandler
import os.path
import sys
import textwrap
@@ -8,6 +9,7 @@ import traceback

from gunicorn.app.wsgiapp import WSGIApplication
from gunicorn.config import make_settings
+from gunicorn.glogging import Logger
from gunicorn.util import import_app

from greins.reloader import Reloader
@@ -31,6 +33,15 @@ class GreinsApplication(WSGIApplication):
self._hooks = {}
self._hooks_lock = None

+ if opts.greinslog:
+ logging.getLogger('gunicorn.access').propagate = False
+ hdlr = WatchedFileHandler(opts.greinslog)
+ hdlr.setFormatter(logging.Formatter(Logger.error_fmt, Logger.datefmt))
+ loglevel = Logger.LOG_LEVELS.get(opts.greinsloglevel.lower(), logging.INFO)
+ rootlogger = logger.getLogger()
+ rootlogger.addHandler(hdlr)
+ rootlogger.setLevel(loglevel)
+
def setup_hooks(self):
"""
Set up server hook proxies
diff --git a/greins/greinslog.py b/greins/greinslog.py
new file mode 100644
index 0000000..d9fd288
--- /dev/null
+++ b/greins/greinslog.py
@@ -0,0 +1,31 @@
+import gunicorn.config
+
+class GreinsLogSetting(gunicorn.config.Setting):
+ name = 'greinslog'
+ section = 'Greins'
+ cli = ['--greins-log-file']
+ meta = "FILE"
+ validator = validate_string
+ desc = '''\
+ The file to log all messages to.
+ '''
+
+class Loglevel(Setting):
+ name = "greinsloglevel"
+ section = "Greins"
+ cli = ["--greins-log-level"]
+ meta = "LEVEL"
+ validator = validate_string
+ default = "info"
+ desc = """\
+ The granularity of Error log outputs.
+
+ Valid level names are:
+
+ * debug
+ * info
+ * warning
+ * error
+ * critical
+ """
+

## Possible implementation 3
Have greins give gunicorn a custom logger_class? This would allow us to rotate our log when the app receives SIG USR1 (because gunicorn is listening for this signal, not greins). The downside of this is that we lose the access log. Or maybe we could re-implement it? Or maybe our logger class could inherit from gunicorn.glogger and tweak things as needed?

## Other stuff
I think it's a bug that gunicorn doesn't set logging.getLogger('gunicorn.access').propagate = False. gunicorn is hijacking the logging API to write the access log. That's fine... but these log messages are not typical application log messages, and therefore should not propagate up to the root logger. Do you agree? If so I can file an issue with the gunicorn project.