Mercurial > hg

changeset 37690:726c4102db9e

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
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.
author Matt Harbison <matt_harbison@yahoo.com>
date Fri, 13 Apr 2018 12:39:54 -0400
parents a7dbda94c86a
children d241e6632669
files hgext/lfs/wireprotolfsserver.py tests/test-lfs-serve-access.t
diffstat 2 files changed, 28 insertions(+), 0 deletions(-) [+]
line wrap: on
line diff
--- 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()