Patchwork [2,of,5,V2] lfs: log information about Internal Server Errors reported in the Batch API

login
register
mail settings
Submitter Matt Harbison
Date April 14, 2018, 6:47 p.m.
Message ID <f5420feae687abf2e16e.1523731654@Envy>
Download mbox | patch
Permalink /patch/31056/
State Accepted
Headers show

Comments

Matt Harbison - April 14, 2018, 6:47 p.m.
# HG changeset patch
# User Matt Harbison <matt_harbison@yahoo.com>
# Date 1523637594 14400
#      Fri Apr 13 12:39:54 2018 -0400
# Node ID f5420feae687abf2e16e8444c385bdac9eedfeab
# Parent  a83bc37bcf3da077f78bf3377b88b61d328bd4ce
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.

Patch

diff --git a/hgext/lfs/wireprotolfsserver.py b/hgext/lfs/wireprotolfsserver.py
--- a/hgext/lfs/wireprotolfsserver.py
+++ b/hgext/lfs/wireprotolfsserver.py
@@ -10,6 +10,7 @@  from __future__ import absolute_import
 import datetime
 import errno
 import json
+import traceback
 
 from mercurial.hgweb import (
     common as hgwebcommon,
@@ -63,6 +64,19 @@  def _sethttperror(res, code, message=Non
     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 @@  def _batchresponseobjects(req, objects, 
             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'
diff --git a/tests/test-lfs-serve-access.t b/tests/test-lfs-serve-access.t
--- a/tests/test-lfs-serve-access.t
+++ b/tests/test-lfs-serve-access.t
@@ -289,6 +289,18 @@  Test a checksum failure during the proce
   $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()