diff --git a/mercurial/hgweb/server.py b/mercurial/hgweb/server.py --- a/mercurial/hgweb/server.py +++ b/mercurial/hgweb/server.py @@ -101,9 +101,8 @@ 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 @@ -112,6 +111,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() 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/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/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,7 +262,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 @@ -267,6 +271,10 @@ 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,7 +688,7 @@ $ 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) @@ -660,6 +696,10 @@ 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,7 +717,7 @@ $ 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) @@ -685,6 +725,10 @@ 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,7 +746,7 @@ $ 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) @@ -711,6 +755,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)\\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 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