Update the log formatting.

Different date format to remove sub-second timing.
Added process id's to all log messages.
Updated various log messages.

gunicorn/arbiter.py

@@ -84,8 +84,8 @@ class Arbiter(object):
         self.init_signals()
         self.LISTENER = create_socket(self.conf)
         self.pidfile = self.opts.get("pidfile")
-        self.log.info("Booted Arbiter: %s" % os.getpid())
+        self.log.info("Arbiter booted")
-        self.log.info("Listening on socket: %s" % self.LISTENER)
+        self.log.info("Listening at: %s" % self.LISTENER)
         
     def _del_pidfile(self):
         self._pidfile = None
@@ -159,7 +159,7 @@ class Arbiter(object):
             self.SIG_QUEUE.append(sig)
             self.wakeup()
         else:
-            self.log.warn("Ignoring rapid signaling: %s" % sig)
+            self.log.warn("Dropping signal: %s" % sig)
 
     def run(self):
         """ main master loop. Launch to start the master"""
@@ -193,7 +193,7 @@ class Arbiter(object):
             except KeyboardInterrupt:
                 break
             except Exception:
-                self.log.info("Unhandled exception in main loop. [%s]" %  
+                self.log.info("Unhandled exception in main loop:\n%s" %  
                             traceback.format_exc())
                 self.stop(False)
                 if self.pidfile:
@@ -201,7 +201,7 @@ class Arbiter(object):
                 sys.exit(-1)
 
         self.stop()
-        self.log.info("%s is shutting down." % self.master_name)
+        self.log.info("Shutting down: %s" % self.master_name)
         if self.pidfile:
             self.unlink_pidfile(self.pidfile)
         sys.exit(0)
@@ -214,7 +214,7 @@ class Arbiter(object):
     def handle_hup(self):
         """ HUP handling . We relaunch gracefully the workers and app while 
         reloading configuration."""
-        self.log.info("%s hang up." % self.master_name)
+        self.log.info("Hang up: %s" % self.master_name)
         self.reexec()
         raise StopIteration
         
@@ -258,7 +258,7 @@ class Arbiter(object):
             self.logger.info("graceful stop of workers")
             self.kill_workers(True)
         else:
-            self.log.info("SIGWINCH ignored. not daemonized")
+            self.log.info("SIGWINCH ignored. Not daemonized")
     
     def wakeup(self):
         """ Wake up the arbiter by writing to the PIPE"""
@@ -325,7 +325,7 @@ class Arbiter(object):
             diff = time.time() - os.fstat(worker.tmp.fileno()).st_ctime
             if diff <= self.timeout:
                 continue
-            self.log.error("%s (pid:%s) timed out." % (worker, pid))
+            self.log.error("Worker timed out: %s (pid:%s)" % (worker, pid))
             self.kill_worker(pid, signal.SIGKILL)
     
     def reap_workers(self):
@@ -379,7 +379,8 @@ class Arbiter(object):
             worker_pid = os.getpid()
             try:
                 util._setproctitle("worker [%s]" % self.proc_name)
-                self.log.debug("Worker %s booting" % worker_pid)
+                self.log.debug("Booting worker: %s (age: %s)" % (
+                                                i, self.worker_age))
                 self.conf.after_fork(self, worker)
                 worker.run()
                 sys.exit(0)
@@ -389,7 +390,7 @@ class Arbiter(object):
                 self.log.exception("Exception in worker process.")
                 sys.exit(-1)
             finally:
-                self.log.info("Worker %s exiting." % worker_pid)
+                self.log.info("Worker exiting: %s (pid: %s)" % (i, worker_pid))
                 try:
                     worker.tmp.close()
                     os.unlink(worker.tmpname)

gunicorn/config.py

@@ -27,12 +27,11 @@ class Config(object):
         group=None,
         
         after_fork=lambda server, worker: server.log.info(
-                        "worker=%s spawned pid=%s" % (worker.id, str(worker.pid))),
+            "Worker spawned: %s (pid: %s)" % (worker.id, worker.pid)),
         
-        before_fork=lambda server, worker: server.log.info(
+        before_fork=lambda server, worker: True,
-                        "worker=%s spawning" % worker.id),
+
-                        
+        before_exec=lambda server: server.log.info("Forked child, reexecuting")
-        before_exec=lambda server: server.log.info("forked child, reexecuting")
     )
     
     def __init__(self, cmdopts, path=None):
@@ -160,4 +159,4 @@ class Config(object):
         
     def before_exec(self, *args):
         return self._hook("before_exec", *args)
-                  
+                  

gunicorn/main.py

@@ -66,8 +66,10 @@ def configure_logging(opts):
 
     logger = logging.getLogger('gunicorn')
     logger.setLevel(loglevel)
+    format = r"%(asctime)s [%(process)d] [%(levelname)s] %(message)s"
+    datefmt = r"%Y/%m/%d %H:%M:%S"
     for h in handlers:
-        h.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s %(message)s"))
+        h.setFormatter(logging.Formatter(format, datefmt))
         logger.addHandler(h)
 
 def daemonize():

gunicorn/worker.py

@@ -60,7 +60,6 @@ class Worker(object):
         signal.signal(signal.SIGINT, self.handle_exit)
         
     def handle_usr1(self, sig, frame):
-        self.log.info("USR1")
         self.nr = -65536;
         try:
             map(lambda p: p.close(), self.PIPE)
@@ -124,7 +123,7 @@ class Worker(object):
             
             # If our parent changed then we shut down.
             if self.ppid != os.getppid():
-                self.log.info("Parent process changed. Closing %s" % self)
+                self.log.info("Parent changed, shutting down: %s" % self)
                 return
             
             try:
@@ -159,11 +158,11 @@ class Worker(object):
             http.Response(client, response, req).send()
         except socket.error, e:
             if e[0] != errno.EPIPE:
-                self.log.exception("Error processing request. [%s]" % str(e))
+                self.log.exception("Error processing request.")
             else:
                 self.log.warn("Ignoring EPIPE")
         except Exception, e:
-            self.log.exception("Error processing request. [%s]" % str(e))
+            self.log.exception("Error processing request.")
             try:            
                 # Last ditch attempt to notify the client of an error.
                 mesg = "HTTP/1.0 500 Internal Server Error\r\n\r\n"