Re: [PATCH 2 of 5] lfs: log information about Internal Server Errors reported in the Batch API

2018-04-14 Thread Yuya Nishihara
On Fri, 13 Apr 2018 18:04:34 -0400, Matt Harbison wrote:
> # HG changeset patch
> # User Matt Harbison 
> # Date 1523637594 14400
> #  Fri Apr 13 12:39:54 2018 -0400
> # Node ID 54c1ab20ed7fbf415d087e6e94ca273d172046e8
> # Parent  1d394ac0efd4aa4f61f428fbac140fe57398f0b8
> lfs: log information about Internal Server Errors reported in the Batch API

> +def _logexception(req):
> +"""Write information about the current exception to wsgi.errors."""
> +tb = traceback.format_exc()
> +# We need a native-string newline to poke in the log
> +# message, because we won't get a newline when using an
> +# r-string. This is the easy way out.
> +newline = chr(10)
> +errorlog = req.rawenv[r'wsgi.errors']
> +
> +uri = ''
> +if req.apppath:
> +uri += req.apppath
> +uri += b'/' + req.dispatchpath
> +
> +errorlog.write(r"Exception happened while processing request "
> +   r"'%s':%s%s" % (uri.decode('latin-1'), newline, tb))

errorlog is a binary stream as far as I can tell from our codebase. We'll
instead have to convert tb to bytes by pycompat.sysbytes().
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel


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

2018-04-13 Thread Matt Harbison
# HG changeset patch
# User Matt Harbison 
# Date 1523637594 14400
#  Fri Apr 13 12:39:54 2018 -0400
# Node ID 54c1ab20ed7fbf415d087e6e94ca273d172046e8
# Parent  1d394ac0efd4aa4f61f428fbac140fe57398f0b8
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.  The log writing was cargoculted from do_POST() in
hgweb.server.  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.

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,23 @@ 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 = traceback.format_exc()
+# We need a native-string newline to poke in the log
+# message, because we won't get a newline when using an
+# r-string. This is the easy way out.
+newline = chr(10)
+errorlog = req.rawenv[r'wsgi.errors']
+
+uri = ''
+if req.apppath:
+uri += req.apppath
+uri += b'/' + req.dispatchpath
+
+errorlog.write(r"Exception happened while processing request "
+   r"'%s':%s%s" % (uri.decode('latin-1'), newline, tb))
+
 def _processbatchrequest(repo, req, res):
 """Handle a request for the Batch API, which is the gateway to granting 
file
 access.
@@ -179,6 +197,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
@@ -291,6 +291,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()
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel