gunicorn: Use exc_info liberally

The argument is documented in [1], and we've been using it in some
cases since 410bcfa (Fix statsd logging to work on Python 3,
2015-04-20, benoitc#1010).  This commit goes through all of our log calls and
makes sure we're using it consistently.

For more examples of using exc_info instead of direct traceback calls,
see 0acfb55 (Let logging module handle traceback printing,
2016-02-05, benoitc#1201).  The traceback call I'm removing snuck in later
with f4842a5 (Log exception occurring during worker exit, 2016-05-04,
benoitc#1254).

I'm removing the "Error processing SSL request" debug messages,
because those will be handled by the subsequent handle_error call.
We've had them, for reasons that I'm not clear on, since 1198cc2
(handle ssl connections, 2012-12-14).

I've restored logging in the URI-less Worker.handle_error 500 case,
since that was broken in 79011d0 (Include request URL in error
message, 2015-07-08, benoitc#1071) but not restored in 1ccebab (prevent
crash when reporting an error, 2016-03-22, benoitc#1231).

Tests for the lines I've touched may be more trouble than they're
worth.  I've worked up one for a broken worker_exit hook to show what
they look like, but left the others untested for now.

[1]: https://docs.python.org/2/library/logging.html#logging.Logger.debug

gunicorn/arbiter.py

@@ -11,7 +11,6 @@
 import signal
 import sys
 import time
-import traceback
 
 from gunicorn.errors import HaltServer, AppImportError
 from gunicorn.pidfile import Pidfile
@@ -590,8 +589,8 @@ def spawn_worker(self):
             print("%s" % e, file=sys.stderr)
             sys.stderr.flush()
             sys.exit(self.APP_LOAD_ERROR)
-        except:
-            self.log.exception("Exception in worker process")
+        except Exception as e:
+            self.log.exception("Exception in worker process", exc_info=e)
             if not worker.booted:
                 sys.exit(self.WORKER_BOOT_ERROR)
             sys.exit(-1)
@@ -600,9 +599,8 @@ def spawn_worker(self):
             try:
                 worker.tmp.close()
                 self.cfg.worker_exit(self, worker)
-            except:
-                self.log.warning("Exception during worker exit:\n%s",
-                                  traceback.format_exc())
+            except Exception as e:
+                self.log.warning("Exception during worker exit", exc_info=e)
 
     def spawn_workers(self):
         """\

gunicorn/glogging.py

@@ -18,7 +18,6 @@
 import socket
 import sys
 import threading
-import traceback
 
 from gunicorn import util
 from gunicorn.six import PY3, string_types
@@ -350,8 +349,8 @@ def access(self, resp, req, environ, request_time):
 
         try:
             self.access_log.info(self.cfg.access_log_format, safe_atoms)
-        except:
-            self.error(traceback.format_exc())
+        except Exception as error:
+            self.error('access logging failed', exc_info=error)
 
     def now(self):
         """ return date in Apache Common Log Format """

gunicorn/sock.py

@@ -66,7 +66,7 @@ def close(self):
         try:
             self.sock.close()
         except socket.error as e:
-            self.log.info("Error while closing socket %s", str(e))
+            self.log.info("Error while closing socket", exc_info=e)
 
         self.sock = None
 

gunicorn/workers/_gaiohttp.py

@@ -82,8 +82,8 @@ def close(self):
         try:
             if hasattr(self.wsgi, 'close'):
                 yield from self.wsgi.close()
-        except:
-            self.log.exception('Process shutdown exception')
+        except Exception as e:
+            self.log.exception('Process shutdown exception', exc_info=e)
 
     @asyncio.coroutine
     def _run(self):

gunicorn/workers/async.py

@@ -55,9 +55,9 @@ def handle(self, listener, client, addr):
                             req.proxy_protocol_info = proxy_protocol_info
                         self.handle_request(listener_name, req, client, addr)
             except http.errors.NoMoreData as e:
-                self.log.debug("Ignored premature client disconnection. %s", e)
+                self.log.debug("Ignored premature client disconnection", exc_info=e)
             except StopIteration as e:
-                self.log.debug("Closing connection. %s", e)
+                self.log.debug("Closing connection", exc_info=e)
             except ssl.SSLError:
                 # pass to next try-except level
                 six.reraise(*sys.exc_info())
@@ -71,11 +71,10 @@ def handle(self, listener, client, addr):
                 self.log.debug("ssl connection closed")
                 client.close()
             else:
-                self.log.debug("Error processing SSL request.")
                 self.handle_error(req, client, addr, e)
         except EnvironmentError as e:
             if e.errno not in (errno.EPIPE, errno.ECONNRESET):
-                self.log.exception("Socket error processing request.")
+                self.log.exception("Socket error processing request", exc_info=e)
             else:
                 if e.errno == errno.ECONNRESET:
                     self.log.debug("Ignoring connection reset")
@@ -127,11 +126,11 @@ def handle_request(self, listener_name, req, sock, addr):
             # If the original exception was a socket.error we delegate
             # handling it to the caller (where handle() might ignore it)
             six.reraise(*sys.exc_info())
-        except Exception:
+        except Exception as error:
             if resp and resp.headers_sent:
                 # If the requests have already been sent, we should close the
                 # connection to indicate the error.
-                self.log.exception("Error handling request")
+                self.log.exception("Error handling request", exc_info=error)
                 try:
                     sock.shutdown(socket.SHUT_RDWR)
                     sock.close()
@@ -142,6 +141,6 @@ def handle_request(self, listener_name, req, sock, addr):
         finally:
             try:
                 self.cfg.post_request(self, req, environ, resp)
-            except Exception:
-                self.log.exception("Exception in post_request hook")
+            except Exception as error:
+                self.log.exception("Exception in post_request hook", exc_info=error)
         return True

gunicorn/workers/base.py

@@ -139,7 +139,7 @@ def load_wsgi(self):
             if self.cfg.reload == 'off':
                 raise
 
-            self.log.exception(e)
+            self.log.exception(e, exec_info=e)
 
             # fix from PR #1228
             # storing the traceback into exc_tb will create a circular reference.
@@ -235,7 +235,10 @@ def handle_error(self, req, client, addr, exc):
             self.log.debug(msg.format(ip=addr[0], error=str(exc)))
         else:
             if hasattr(req, "uri"):
-                self.log.exception("Error handling request %s", req.uri)
+                self.log.exception("Error handling request %s", req.uri, exc_info=exc)
+            else:
+                self.log.exception("Error handling request", exc_info=exc)
+
             status_int = 500
             reason = "Internal Server Error"
             mesg = ""
@@ -252,8 +255,8 @@ def handle_error(self, req, client, addr, exc):
 
         try:
             util.write_error(client, status_int, reason, mesg)
-        except:
-            self.log.debug("Failed to send error message.")
+        except Exception as error:
+            self.log.debug("Failed to send error message", exc_info=error)
 
     def handle_winch(self, sig, fname):
         # Ignore SIGWINCH in worker. Fixes a crash on OpenBSD.

gunicorn/workers/gthread.py

@@ -294,12 +294,11 @@ def handle(self, conn):
                 self.log.debug("ssl connection closed")
                 conn.sock.close()
             else:
-                self.log.debug("Error processing SSL request.")
                 self.handle_error(req, conn.sock, conn.client, e)
 
         except EnvironmentError as e:
             if e.errno not in (errno.EPIPE, errno.ECONNRESET):
-                self.log.exception("Socket error processing request.")
+                self.log.exception("Socket error processing request", exc_info=e)
             else:
                 if e.errno == errno.ECONNRESET:
                     self.log.debug("Ignoring connection reset")
@@ -351,11 +350,11 @@ def handle_request(self, req, conn):
         except EnvironmentError:
             # pass to next try-except level
             six.reraise(*sys.exc_info())
-        except Exception:
+        except Exception as error:
             if resp and resp.headers_sent:
                 # If the requests have already been sent, we should close the
                 # connection to indicate the error.
-                self.log.exception("Error handling request")
+                self.log.exception("Error handling request", exc_info=error)
                 try:
                     conn.sock.shutdown(socket.SHUT_RDWR)
                     conn.sock.close()
@@ -366,7 +365,7 @@ def handle_request(self, req, conn):
         finally:
             try:
                 self.cfg.post_request(self, req, environ, resp)
-            except Exception:
-                self.log.exception("Exception in post_request hook")
+            except Exception as error:
+                self.log.exception("Exception in post_request hook", exc_info=error)
 
         return True

gunicorn/workers/sync.py

@@ -134,15 +134,14 @@ def handle(self, listener, client, addr):
             req = six.next(parser)
             self.handle_request(listener, req, client, addr)
         except http.errors.NoMoreData as e:
-            self.log.debug("Ignored premature client disconnection. %s", e)
+            self.log.debug("Ignored premature client disconnection", exc_info=e)
         except StopIteration as e:
-            self.log.debug("Closing connection. %s", e)
+            self.log.debug("Closing connection", exc_info=e)
         except ssl.SSLError as e:
             if e.args[0] == ssl.SSL_ERROR_EOF:
                 self.log.debug("ssl connection closed")
                 client.close()
             else:
-                self.log.debug("Error processing SSL request.")
                 self.handle_error(req, client, addr, e)
         except EnvironmentError as e:
             if e.errno not in (errno.EPIPE, errno.ECONNRESET):
@@ -189,11 +188,11 @@ def handle_request(self, listener, req, client, addr):
         except EnvironmentError:
             # pass to next try-except level
             six.reraise(*sys.exc_info())
-        except Exception:
+        except Exception as error:
             if resp and resp.headers_sent:
                 # If the requests have already been sent, we should close the
                 # connection to indicate the error.
-                self.log.exception("Error handling request")
+                self.log.exception("Error handling request", exc_info=error)
                 try:
                     client.shutdown(socket.SHUT_RDWR)
                     client.close()
@@ -204,5 +203,5 @@ def handle_request(self, listener, req, client, addr):
         finally:
             try:
                 self.cfg.post_request(self, req, environ, resp)
-            except Exception:
-                self.log.exception("Exception in post_request hook")
+            except Exception as error:
+                self.log.exception("Exception in post_request hook", exc_info=error)

tests/test_arbiter.py

@@ -130,6 +130,33 @@ def test_arbiter_calls_worker_exit(mock_os_fork):
     arbiter.cfg.worker_exit.assert_called_with(arbiter, mock_worker)
 
 
+@mock.patch('os.fork')
+def test_arbiter_logs_worker_exit_errors(mock_os_fork):
+    mock_os_fork.return_value = 0
+
+    error = ValueError('testing')
+    class WorkerExit(object):
+        @staticmethod
+        def worker_exit(arbiter, worker):
+            raise error
+
+        def get(self):
+            return self.worker_exit
+
+    arbiter = gunicorn.arbiter.Arbiter(DummyApplication())
+    arbiter.cfg.settings['worker_exit'] = WorkerExit()
+    arbiter.pid = None
+    mock_worker = mock.Mock()
+    arbiter.worker_class = mock.Mock(return_value=mock_worker)
+    arbiter.log = mock.Mock()
+    try:
+        arbiter.spawn_worker()
+    except SystemExit:
+        pass
+    arbiter.log.warning.assert_called_with(
+        'Exception during worker exit', exc_info=error)
+
+
 @mock.patch('os.waitpid')
 def test_arbiter_reap_workers(mock_os_waitpid):
     mock_os_waitpid.side_effect = [(42, 0), (0, 0)]