diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py index 7ddd4ab8f1..973532f975 100644 --- a/gunicorn/arbiter.py +++ b/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): """\ diff --git a/gunicorn/sock.py b/gunicorn/sock.py index cc6c589a6e..ce8bd2482f 100644 --- a/gunicorn/sock.py +++ b/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 diff --git a/gunicorn/workers/_gaiohttp.py b/gunicorn/workers/_gaiohttp.py index cdce4be759..15b3d5df15 100644 --- a/gunicorn/workers/_gaiohttp.py +++ b/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): diff --git a/gunicorn/workers/async.py b/gunicorn/workers/async.py index a3a0f91293..300ac56bd0 100644 --- a/gunicorn/workers/async.py +++ b/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 diff --git a/gunicorn/workers/base.py b/gunicorn/workers/base.py index f16c0e95e9..0912ecbbf1 100644 --- a/gunicorn/workers/base.py +++ b/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. diff --git a/gunicorn/workers/gthread.py b/gunicorn/workers/gthread.py index 5f918e2e74..33f67e11b8 100644 --- a/gunicorn/workers/gthread.py +++ b/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 diff --git a/gunicorn/workers/sync.py b/gunicorn/workers/sync.py index 1d2ce2f60b..0adc17540f 100644 --- a/gunicorn/workers/sync.py +++ b/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) diff --git a/tests/test_arbiter.py b/tests/test_arbiter.py index 5ab6e9205b..9b5f54330e 100644 --- a/tests/test_arbiter.py +++ b/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)]