hgweb: log error before attempting I/O

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.

Differential Revision: https://phab.mercurial-scm.org/D5749

tests/filtertraceback.py

@@ -0,0 +1,29 b''
+#!/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='')

mercurial/hgweb/server.py

@@ -101,9 +101,8 b' class _httprequesthandler(httpservermod.'
         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 b' class _httprequesthandler(httpservermod.'
             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()
 

tests/test-hgweb.t

@@ -910,7 +910,20 b' Test signal-safe-lock in web and non-web'
 
 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 b' Uncaught exceptions result in a logged e'
   [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
 

tests/test-http-bad-server.t

@@ -207,7 +207,7 b' Now do a variation using POST to send ar'
 
   $ 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 b' Now do a variation using POST to send ar'
   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 b' Server sends a single character from the'
 
   $ 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 b' Server sends a single character from the'
   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 b' Server sends an incomplete capabilities '
 
   $ 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 b' Server sends an incomplete capabilities '
   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 b' TODO this output is horrible'
 
   $ 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 b' TODO this output is horrible'
   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 b' TODO client spews a stack due to uncaugh'
 
   $ 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 b' TODO client spews a stack due to uncaugh'
   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 b' TODO this output is terrible'
 
   $ 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 b' TODO this output is terrible'
   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 b' Server stops before it sends transfer en'
 
   $ 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 b' Server sends empty HTTP body for getbund'
 
   $ 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 b' Server sends empty HTTP body for getbund'
   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 b' Server sends partial compression string'
 
   $ 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 b' Server sends partial compression string'
   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 b' Server sends partial bundle2 header magi'
 
   $ 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 b' Server sends incomplete bundle2 stream p'
 
   $ 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 b' Server sends incomplete bundle2 stream p'
   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 b' Servers stops after bundle2 stream param'
 
   $ 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 b' Servers stops after bundle2 stream param'
   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 b' Server stops sending after bundle2 part '
 
   $ 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 b' Server stops sending after bundle2 part '
   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 b' Server stops sending after bundle2 part '
 
   $ 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 b' Server stops sending after bundle2 part '
   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 b' Server stops after bundle2 part payload '
 
   $ 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 b' Server stops after bundle2 part payload '
   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 b' Server stops sending in middle of bundle'
 
   $ 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 b' Server stops sending in middle of bundle'
   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 b' Server stops sending after 0 length payl'
 
   $ 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 b' Server stops sending after 0 length payl'
   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 b' This is before the 0 size chunked transf'
 
   $ 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 b' This is before the 0 size chunked transf'
   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 b' Server sends a size 0 chunked-transfer s'
 
   $ 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 b' Server sends a size 0 chunked-transfer s'
   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