lfs: log information about Internal Server Errors reported in the Batch API
Reporting a 500 and then not leaving any traces on the server seems like a
receipe for frustration. There's similar log writing in hgweb.server.do_POST().
That doesn't write directly to the wsgi.errors object, so it doesn't seem worth
trying to refactor.
It does seem like earlier stack frames are missing for some reason.
--- a/hgext/lfs/wireprotolfsserver.py Sat Apr 07 12:48:21 2018 -0400
+++ b/hgext/lfs/wireprotolfsserver.py Fri Apr 13 12:39:54 2018 -0400
@@ -10,6 +10,7 @@
import datetime
import errno
import json
+import traceback
from mercurial.hgweb import (
common as hgwebcommon,
@@ -63,6 +64,19 @@
res.headers[b'Content-Type'] = b'text/plain; charset=utf-8'
res.setbodybytes(b'')
+def _logexception(req):
+ """Write information about the current exception to wsgi.errors."""
+ tb = pycompat.sysbytes(traceback.format_exc())
+ errorlog = req.rawenv[r'wsgi.errors']
+
+ uri = b''
+ if req.apppath:
+ uri += req.apppath
+ uri += b'/' + req.dispatchpath
+
+ errorlog.write(b"Exception happened while processing request '%s':\n%s" %
+ (uri, tb))
+
def _processbatchrequest(repo, req, res):
"""Handle a request for the Batch API, which is the gateway to granting file
access.
@@ -179,6 +193,8 @@
verifies = store.verify(oid)
except IOError as inst:
if inst.errno != errno.ENOENT:
+ _logexception(req)
+
rsp['error'] = {
'code': 500,
'message': inst.strerror or 'Internal Server Server'
--- a/tests/test-lfs-serve-access.t Sat Apr 07 12:48:21 2018 -0400
+++ b/tests/test-lfs-serve-access.t Fri Apr 13 12:39:54 2018 -0400
@@ -289,6 +289,18 @@
$LOCALIP - - [$LOGDATE$] "GET /.hg/lfs/objects/276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d HTTP/1.1" 500 - (glob)
$ grep -v ' File "' $TESTTMP/errors.log
+ $LOCALIP - - [$ERRDATE$] HG error: Exception happened while processing request '/.git/info/lfs/objects/batch': (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: Traceback (most recent call last): (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: verifies = store.verify(oid) (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: raise IOError(errno.EIO, '%s: I/O error' % oid) (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: IOError: [Errno 5] f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e: I/O error (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: Exception happened while processing request '/.git/info/lfs/objects/batch': (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: Traceback (most recent call last): (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: verifies = store.verify(oid) (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: raise IOError(errno.EIO, '%s: I/O error' % oid) (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: IOError: [Errno 5] b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c: I/O error (glob)
+ $LOCALIP - - [$ERRDATE$] HG error: (glob)
$LOCALIP - - [$ERRDATE$] Exception happened during processing request '/.hg/lfs/objects/b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c': (glob)
Traceback (most recent call last):
self.do_write()