D5749: hgweb: log error before attempting I/O
indygreg (Gregory Szorc)
phabricator at mercurial-scm.org
Wed Jan 30 20:56:29 UTC 2019
indygreg created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.
REVISION SUMMARY
Previously, an uncaught exception during HTTP request serving would
attempt to send an error response then log the exception.
If an exception occurred during I/O, this exception would be
raised and the original exception wouldn't be logged.
This commit changes behavior so the original exception is logged
first, before we attempt to do anything else. This ensures the
exception is logged.
This change resulted in new tracebacks appearing in various tests.
Because tracebacks can vary between Python versions, we added a
simple script to filter the stack part of traceback lines. This
makes testing much simpler, as we don't need to glob over lines
and make lines conditional.
REPOSITORY
rHG Mercurial
REVISION DETAIL
https://phab.mercurial-scm.org/D5749
AFFECTED FILES
mercurial/hgweb/server.py
tests/filtertraceback.py
tests/test-hgweb.t
tests/test-http-bad-server.t
CHANGE DETAILS
diff --git a/tests/test-http-bad-server.t b/tests/test-http-bad-server.t
--- a/tests/test-http-bad-server.t
+++ b/tests/test-http-bad-server.t
@@ -207,7 +207,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(329 from 65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(296 from -1) -> (27) Accept-Encoding: identity\r\n
readline(269 from -1) -> (35) accept: application/mercurial-0.1\r\n
@@ -241,6 +241,10 @@
readline(* from -1) -> (2) \r\n (glob)
read(* from 28) -> (*) cmds=* (glob)
read limit reached, closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=batch': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after receiving N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -258,15 +262,19 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
readline(-1) -> (2?) host: localhost:$HGPORT\r\n (glob)
readline(-1) -> (49) user-agent: mercurial/proto-1.0 (Mercurial 4.2)\r\n
readline(-1) -> (2) \r\n
write(1 from 36) -> (0) H
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=capabilities': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -283,7 +291,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -298,6 +306,10 @@
write(2 from 2) -> (20) \r\n
write(20 from 450) -> (0) batch branchmap bund
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=capabilities': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
$ rm -f error.log
@@ -318,7 +330,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -346,6 +358,10 @@
write(37 from 37) -> (22) Date: $HTTP_DATE$\r\n
write(22 from 41) -> (0) Content-Type: applicat
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=batch': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -366,7 +382,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -397,6 +413,10 @@
write(2 from 2) -> (24) \r\n
write(24 from 42) -> (0) 96ee1d7354c4ad7372047672
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=batch': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
$ rm -f error.log
@@ -418,7 +438,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -462,6 +482,10 @@
write(37 from 37) -> (33) Date: $HTTP_DATE$\r\n
write(33 from 41) -> (0) Content-Type: application/mercuri
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -478,10 +502,10 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -4 error.log
- write(41 from 41) -> (25) Content-Type: application/mercurial-0.2\r\n
- write(25 from 28) -> (0) Transfer-Encoding: chunke
- write limit reached; closing socket
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -4
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -499,7 +523,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -545,6 +569,10 @@
write(28 from 28) -> (2) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (0) \r\n
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(36) -> HTTP/1.1 500 Internal Server Error\r\n
$ rm -f error.log
@@ -562,7 +590,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ cat error.log
+ $ cat error.log | "$PYTHON" $TESTDIR/filtertraceback.py
readline(65537) -> (33) GET /?cmd=capabilities HTTP/1.1\r\n
readline(-1) -> (27) Accept-Encoding: identity\r\n
readline(-1) -> (35) accept: application/mercurial-0.1\r\n
@@ -611,6 +639,10 @@
write(9 from 9) -> (9) 4\r\nnone\r\n
write(9 from 9) -> (0) 4\r\nHG20\r\n
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -628,13 +660,17 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -7 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -11
write(28 from 28) -> (23) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (21) \r\n
write(6 from 6) -> (15) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (6) 4\r\nnone\r\n
write(6 from 9) -> (0) 4\r\nHG2
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -652,14 +688,18 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -8 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -12
write(28 from 28) -> (32) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (30) \r\n
write(6 from 6) -> (24) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (15) 4\r\nnone\r\n
write(9 from 9) -> (6) 4\r\nHG20\r\n
write(6 from 9) -> (0) 4\\r\\n\x00\x00\x00 (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -677,14 +717,18 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -8 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -12
write(28 from 28) -> (35) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (33) \r\n
write(6 from 6) -> (27) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (18) 4\r\nnone\r\n
write(9 from 9) -> (9) 4\r\nHG20\r\n
write(9 from 9) -> (0) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -702,15 +746,19 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -9 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -13
write(28 from 28) -> (44) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (42) \r\n
write(6 from 6) -> (36) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (27) 4\r\nnone\r\n
write(9 from 9) -> (18) 4\r\nHG20\r\n
write(9 from 9) -> (9) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write(9 from 9) -> (0) 4\\r\\n\x00\x00\x00)\\r\\n (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -731,7 +779,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -10 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -14
write(28 from 28) -> (91) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (89) \r\n
write(6 from 6) -> (83) 1\\r\\n\x04\\r\\n (esc)
@@ -741,6 +789,10 @@
write(9 from 9) -> (47) 4\\r\\n\x00\x00\x00)\\r\\n (esc)
write(47 from 47) -> (0) 29\\r\\n\x0bCHANGEGROUP\x00\x00\x00\x00\x01\x01\x07\x02 \x01version02nbchanges1\\r\\n (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -761,7 +813,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -11 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -15
write(2 from 2) -> (110) \r\n
write(6 from 6) -> (104) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (95) 4\r\nnone\r\n
@@ -772,6 +824,10 @@
write(9 from 9) -> (12) 4\\r\\n\x00\x00\x01\xd2\\r\\n (esc)
write(12 from 473) -> (0) 1d2\\r\\n\x00\x00\x00\xb2\x96\xee\x1d (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -792,7 +848,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -12 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -16
write(28 from 28) -> (573) Transfer-Encoding: chunked\r\n
write(2 from 2) -> (571) \r\n
write(6 from 6) -> (565) 1\\r\\n\x04\\r\\n (esc)
@@ -804,6 +860,10 @@
write(9 from 9) -> (473) 4\\r\\n\x00\x00\x01\xd2\\r\\n (esc)
write(473 from 473) -> (0) 1d2\\r\\n\x00\x00\x00\xb2\x96\xee\x1dsT\xc4\xadsr\x04vr\xc3j\x1fV\x1e:jL\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x96\xee\x1dsT\xc4\xadsr\x04vr\xc3j\x1fV\x1e:jL\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00>6a3df4de388f3c4f8e28f4f9a814299a3cbb5f50\\ntest\\n0 0\\nfoo\\n\\ninitial\x00\x00\x00\x00\x00\x00\x00\xa1j=\xf4\xde8\x8f<O\x8e(\xf4\xf9\xa8\x14)\x9a<\xbb_P\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x96\xee\x1dsT\xc4\xadsr\x04vr\xc3j\x1fV\x1e:jL\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00-foo\x00b80de5d138758541c5f05265ad144ab9fa86d1db\\n\x00\x00\x00\x00\x00\x00\x00\x07foo\x00\x00\x00h\xb8\\r\xe5\xd18u\x85A\xc5\xf0Re\xad\x14J\xb9\xfa\x86\xd1\xdb\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x96\xee\x1dsT\xc4\xadsr\x04vr\xc3j\x1fV\x1e:jL\x00\x00\x00\x00\x00\x00\x00\x00\\r\\n (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -827,7 +887,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -13 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -17
write(6 from 6) -> (596) 1\\r\\n\x04\\r\\n (esc)
write(9 from 9) -> (587) 4\r\nnone\r\n
write(9 from 9) -> (578) 4\r\nHG20\r\n
@@ -840,6 +900,10 @@
write(9 from 9) -> (13) 4\\r\\n\x00\x00\x00 \\r\\n (esc)
write(13 from 38) -> (0) 20\\r\\n\x08LISTKEYS (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -863,7 +927,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -22 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -26
write(9 from 9) -> (851) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write(9 from 9) -> (842) 4\\r\\n\x00\x00\x00)\\r\\n (esc)
write(47 from 47) -> (795) 29\\r\\n\x0bCHANGEGROUP\x00\x00\x00\x00\x01\x01\x07\x02 \x01version02nbchanges1\\r\\n (esc)
@@ -885,6 +949,10 @@
write(9 from 9) -> (9) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write(9 from 9) -> (0) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
@@ -907,7 +975,7 @@
$ killdaemons.py $DAEMON_PIDS
- $ tail -23 error.log
+ $ "$PYTHON" $TESTDIR/filtertraceback.py < error.log | tail -27
write(9 from 9) -> (854) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write(9 from 9) -> (845) 4\\r\\n\x00\x00\x00)\\r\\n (esc)
write(47 from 47) -> (798) 29\\r\\n\x0bCHANGEGROUP\x00\x00\x00\x00\x01\x01\x07\x02 \x01version02nbchanges1\\r\\n (esc)
@@ -930,6 +998,10 @@
write(9 from 9) -> (3) 4\\r\\n\x00\x00\x00\x00\\r\\n (esc)
write(3 from 5) -> (0) 0\r\n
write limit reached; closing socket
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=getbundle': (glob)
+ Traceback (most recent call last):
+ Exception: connection closed after sending N bytes
+
write(27) -> 15\r\nInternal Server Error\r\n
$ rm -f error.log
diff --git a/tests/test-hgweb.t b/tests/test-hgweb.t
--- a/tests/test-hgweb.t
+++ b/tests/test-hgweb.t
@@ -910,7 +910,20 @@
errors
- $ cat errors.log
+ $ cat errors.log | "$PYTHON" $TESTDIR/filtertraceback.py
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/?cmd=spam': (glob)
+ Traceback (most recent call last):
+ error: [Errno 104] $ECONNRESET$
+
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/spam': (glob)
+ Traceback (most recent call last):
+ error: [Errno 104] $ECONNRESET$
+
+ $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/spam/tip/foo': (glob)
+ Traceback (most recent call last):
+ error: [Errno 104] $ECONNRESET$
+
+ $ rm -f errors.log
Uncaught exceptions result in a logged error and canned HTTP response
@@ -925,8 +938,11 @@
[1]
$ killdaemons.py
- $ head -1 errors.log
+ $ cat errors.log | "$PYTHON" $TESTDIR/filtertraceback.py
.* Exception happened during processing request '/raiseerror': (re)
+ Traceback (most recent call last):
+ AttributeError: I am an uncaught error!
+
Uncaught exception after partial content sent
diff --git a/tests/filtertraceback.py b/tests/filtertraceback.py
new file mode 100755
--- /dev/null
+++ b/tests/filtertraceback.py
@@ -0,0 +1,29 @@
+#!/usr/bin/env python
+
+# Filters traceback lines from stdin.
+
+from __future__ import absolute_import, print_function
+
+import sys
+
+state = 'none'
+
+for line in sys.stdin:
+ if state == 'none':
+ if line.startswith('Traceback '):
+ state = 'tb'
+
+ elif state == 'tb':
+ if line.startswith(' File '):
+ state = 'file'
+ continue
+
+ elif not line.startswith(' '):
+ state = 'none'
+
+ elif state == 'file':
+ # Ignore lines after " File "
+ state = 'tb'
+ continue
+
+ print(line, end='')
diff --git a/mercurial/hgweb/server.py b/mercurial/hgweb/server.py
--- a/mercurial/hgweb/server.py
+++ b/mercurial/hgweb/server.py
@@ -101,17 +101,20 @@
try:
self.do_write()
except Exception:
- self._start_response(r"500 Internal Server Error", [])
- self._write(b"Internal Server Error")
- self._done()
+ # I/O below could raise another exception. So log the original
+ # exception first to ensure it is recorded.
tb = r"".join(traceback.format_exception(*sys.exc_info()))
# We need a native-string newline to poke in the log
# message, because we won't get a newline when using an
# r-string. This is the easy way out.
newline = chr(10)
self.log_error(r"Exception happened during processing "
r"request '%s':%s%s", self.path, newline, tb)
+ self._start_response(r"500 Internal Server Error", [])
+ self._write(b"Internal Server Error")
+ self._done()
+
def do_PUT(self):
self.do_POST()
To: indygreg, #hg-reviewers
Cc: mercurial-devel
More information about the Mercurial-devel
mailing list