Greins should configure root logger #14

Open
markdoliner opened this Issue Dec 8, 2011 · 8 comments

Comments

Projects
None yet
2 participants

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.

Possible implementation 4

Maybe the gunicorn error log should log everything, not just gunicorn.error?

Possible implementation 3

I implemented this one. It's not bad!

diff --git a/etc/init/greins b/etc/init/greins
index c20c5db..2af39db 100755
--- a/etc/init/greins
+++ b/etc/init/greins
@@ -73,6 +73,7 @@ start() {
     $exec -D \
       -p $pidfile \
       --log-file $GREINS_LOG_FILE \
+      --logger-class greins.greinslogging.GreinsLogger \
       -u $GREINS_USER -g $GREINS_GROUP \
       -b $GREINS_BIND_ADDR \
       $GREINS_OPTIONS \
diff --git a/greins/greinslogging.py b/greins/greinslogging.py
new file mode 100644
index 0000000..e1377f8
--- /dev/null
+++ b/greins/greinslogging.py
@@ -0,0 +1,16 @@
+import logging
+
+from gunicorn import glogging
+
+class GreinsLogger(glogging.Logger):
+
+    def __init__(self, cfg):
+        super(self.__class__, self).__init__(cfg)
+
+        # Remove the handler for gunicorn.error
+        h = self._get_gunicorn_handler(self.error_log)
+        self.error_log.handlers.remove(h)
+
+        # Change self.error_log to log at the root level
+        self.error_log = logging.getLogger()
+        super(self.__class__, self).setup(cfg)

Should probably add this to GreinsLogger.init:

# Make sure access log entries don't show up in our error log
self.access_log.propagate = False

I still consider that a bug in gunicorn.

@tilgovi tilgovi added a commit that referenced this issue Mar 27, 2012

@tilgovi Randall Leeds + tilgovi add greins.GreinsLogger
This change makes it easier to use the gunicorn log for application
messages. Everything is overridable and configurable as before, but by
default greins will use a new logging class, `greins.GreinsLogger`.

The `GreinsLogger` class is just like the logger from gunicorn, except
it configures a handler on the root logger which forwards to the
handler for the 'gunicorn.error' logger and uses a formatter that
includes the package name of the source of each log message.

Reported by Mark Doliner (#14).
ad474cb

@tilgovi tilgovi added a commit that referenced this issue Mar 27, 2012

@tilgovi Randall Leeds + tilgovi add greins.app.GreinsLogger
This change makes it easier to use the gunicorn log for application
messages. Everything is overridable and configurable as before, but by
default greins will use a new logging class, `greins.GreinsLogger`.

The `GreinsLogger` class is just like the logger from gunicorn, except
it configures a handler on the root logger which forwards to the
handler for the 'gunicorn.error' logger and uses a formatter that
includes the package name of the source of each log message.

Reported by Mark Doliner (#14).
9fc1f61
Collaborator

tilgovi commented Mar 27, 2012

Apologies for the two referenced commits, only the second is valid (I force pushed, shhh, don't tell).
I like this solution, because it creates the handler only once but re-targets it properly whenever logging is reconfigured and is very unobtrusive with changing the gunicorn logger.

Mark, what think you? Merge?

I'm not super familiar with greins or gunicorn, but that looks reasonable to me. FYI I think the logging.Formatter import isn't used.

@tilgovi tilgovi added a commit that referenced this issue Mar 28, 2012

@tilgovi Randall Leeds + tilgovi add greins.app.GreinsLogger
This change makes it easier to use the gunicorn log for application
messages. Everything is overridable and configurable as before, but by
default greins will use a new logging class, `greins.GreinsLogger`.

The `GreinsLogger` class is just like the logger from gunicorn, except
it configures a handler on the root logger which forwards to the
handler for the 'gunicorn.error' logger and uses a formatter that
includes the package name of the source of each log message.

Reported by Mark Doliner (#14).
877430e
Collaborator

tilgovi commented Mar 28, 2012

Fixed (877430e). Thanks, Mark! Solid addition.

tilgovi closed this Mar 28, 2012

Yay, thanks

tilgovi reopened this Apr 3, 2012

Collaborator

tilgovi commented Apr 3, 2012

i'm not convinced I'm 100% satisfied with the way this works. Leaving open for now.

tilgovi was assigned Apr 3, 2012

tilgovi removed their assignment Mar 12, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment