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.

hgext/lfs/wireprotolfsserver.py

@@ -1,291 +1,307 b''
 # wireprotolfsserver.py - lfs protocol server side implementation
 #
 # Copyright 2018 Matt Harbison <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 from __future__ import absolute_import
 
 import datetime
 import errno
 import json
+import traceback
 
 from mercurial.hgweb import (
     common as hgwebcommon,
 )
 
 from mercurial import (
     pycompat,
 )
 
 HTTP_OK = hgwebcommon.HTTP_OK
 HTTP_CREATED = hgwebcommon.HTTP_CREATED
 HTTP_BAD_REQUEST = hgwebcommon.HTTP_BAD_REQUEST
 HTTP_NOT_FOUND = hgwebcommon.HTTP_NOT_FOUND
 
 def handlewsgirequest(orig, rctx, req, res, checkperm):
     """Wrap wireprotoserver.handlewsgirequest() to possibly process an LFS
     request if it is left unprocessed by the wrapped method.
     """
     if orig(rctx, req, res, checkperm):
         return True
 
     if not rctx.repo.ui.configbool('experimental', 'lfs.serve'):
         return False
 
     if not req.dispatchpath:
         return False
 
     try:
         if req.dispatchpath == b'.git/info/lfs/objects/batch':
             checkperm(rctx, req, 'pull')
             return _processbatchrequest(rctx.repo, req, res)
         # TODO: reserve and use a path in the proposed http wireprotocol /api/
         #       namespace?
         elif req.dispatchpath.startswith(b'.hg/lfs/objects'):
             return _processbasictransfer(rctx.repo, req, res,
                                          lambda perm:
                                                 checkperm(rctx, req, perm))
         return False
     except hgwebcommon.ErrorResponse as e:
         # XXX: copied from the handler surrounding wireprotoserver._callhttp()
         #      in the wrapped function.  Should this be moved back to hgweb to
         #      be a common handler?
         for k, v in e.headers:
             res.headers[k] = v
         res.status = hgwebcommon.statusmessage(e.code, pycompat.bytestr(e))
         res.setbodybytes(b'0\n%s\n' % pycompat.bytestr(e))
         return True
 
 def _sethttperror(res, code, message=None):
     res.status = hgwebcommon.statusmessage(code, message=message)
     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.
 
     https://github.com/git-lfs/git-lfs/blob/master/docs/api/batch.md
     """
 
     # Mercurial client request:
     #
     #   HOST: localhost:$HGPORT
     #   ACCEPT: application/vnd.git-lfs+json
     #   ACCEPT-ENCODING: identity
     #   USER-AGENT: git-lfs/2.3.4 (Mercurial 4.5.2+1114-f48b9754f04c+20180316)
     #   Content-Length: 125
     #   Content-Type: application/vnd.git-lfs+json
     #
     #   {
     #     "objects": [
     #       {
     #         "oid": "31cf...8e5b"
     #         "size": 12
     #       }
     #     ]
     #     "operation": "upload"
     #  }
 
     if (req.method != b'POST'
         or req.headers[b'Content-Type'] != b'application/vnd.git-lfs+json'
         or req.headers[b'Accept'] != b'application/vnd.git-lfs+json'):
         # TODO: figure out what the proper handling for a bad request to the
         #       Batch API is.
         _sethttperror(res, HTTP_BAD_REQUEST, b'Invalid Batch API request')
         return True
 
     # XXX: specify an encoding?
     lfsreq = json.loads(req.bodyfh.read())
 
     # If no transfer handlers are explicitly requested, 'basic' is assumed.
     if 'basic' not in lfsreq.get('transfers', ['basic']):
         _sethttperror(res, HTTP_BAD_REQUEST,
                       b'Only the basic LFS transfer handler is supported')
         return True
 
     operation = lfsreq.get('operation')
     if operation not in ('upload', 'download'):
         _sethttperror(res, HTTP_BAD_REQUEST,
                       b'Unsupported LFS transfer operation: %s' % operation)
         return True
 
     localstore = repo.svfs.lfslocalblobstore
 
     objects = [p for p in _batchresponseobjects(req, lfsreq.get('objects', []),
                                                 operation, localstore)]
 
     rsp = {
         'transfer': 'basic',
         'objects': objects,
     }
 
     res.status = hgwebcommon.statusmessage(HTTP_OK)
     res.headers[b'Content-Type'] = b'application/vnd.git-lfs+json'
     res.setbodybytes(pycompat.bytestr(json.dumps(rsp)))
 
     return True
 
 def _batchresponseobjects(req, objects, action, store):
     """Yield one dictionary of attributes for the Batch API response for each
     object in the list.
 
     req: The parsedrequest for the Batch API request
     objects: The list of objects in the Batch API object request list
     action: 'upload' or 'download'
     store: The local blob store for servicing requests"""
 
     # Successful lfs-test-server response to solict an upload:
     # {
     #    u'objects': [{
     #       u'size': 12,
     #       u'oid': u'31cf...8e5b',
     #       u'actions': {
     #           u'upload': {
     #               u'href': u'http://localhost:$HGPORT/objects/31cf...8e5b',
     #               u'expires_at': u'0001-01-01T00:00:00Z',
     #               u'header': {
     #                   u'Accept': u'application/vnd.git-lfs'
     #               }
     #           }
     #       }
     #    }]
     # }
 
     # TODO: Sort out the expires_at/expires_in/authenticated keys.
 
     for obj in objects:
         # Convert unicode to ASCII to create a filesystem path
         oid = obj.get('oid').encode('ascii')
         rsp = {
             'oid': oid,
             'size': obj.get('size'),  # XXX: should this check the local size?
             #'authenticated': True,
         }
 
         exists = True
         verifies = False
 
         # Verify an existing file on the upload request, so that the client is
         # solicited to re-upload if it corrupt locally.  Download requests are
         # also verified, so the error can be flagged in the Batch API response.
         # (Maybe we can use this to short circuit the download for `hg verify`,
         # IFF the client can assert that the remote end is an hg server.)
         # Otherwise, it's potentially overkill on download, since it is also
         # verified as the file is streamed to the caller.
         try:
             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'
                 }
                 yield rsp
                 continue
 
             exists = False
 
         # Items are always listed for downloads.  They are dropped for uploads
         # IFF they already exist locally.
         if action == 'download':
             if not exists:
                 rsp['error'] = {
                     'code': 404,
                     'message': "The object does not exist"
                 }
                 yield rsp
                 continue
 
             elif not verifies:
                 rsp['error'] = {
                     'code': 422,   # XXX: is this the right code?
                     'message': "The object is corrupt"
                 }
                 yield rsp
                 continue
 
         elif verifies:
             yield rsp  # Skip 'actions': already uploaded
             continue
 
         expiresat = datetime.datetime.now() + datetime.timedelta(minutes=10)
 
         rsp['actions'] = {
             '%s' % action: {
                 'href': '%s%s/.hg/lfs/objects/%s'
                     % (req.baseurl, req.apppath, oid),
                 # datetime.isoformat() doesn't include the 'Z' suffix
                 "expires_at": expiresat.strftime('%Y-%m-%dT%H:%M:%SZ'),
                 'header': {
                     # The spec doesn't mention the Accept header here, but avoid
                     # a gratuitous deviation from lfs-test-server in the test
                     # output.
                     'Accept': 'application/vnd.git-lfs'
                 }
             }
         }
 
         yield rsp
 
 def _processbasictransfer(repo, req, res, checkperm):
     """Handle a single file upload (PUT) or download (GET) action for the Basic
     Transfer Adapter.
 
     After determining if the request is for an upload or download, the access
     must be checked by calling ``checkperm()`` with either 'pull' or 'upload'
     before accessing the files.
 
     https://github.com/git-lfs/git-lfs/blob/master/docs/api/basic-transfers.md
     """
 
     method = req.method
     oid = req.dispatchparts[-1]
     localstore = repo.svfs.lfslocalblobstore
 
     if len(req.dispatchparts) != 4:
         _sethttperror(res, HTTP_NOT_FOUND)
         return True
 
     if method == b'PUT':
         checkperm('upload')
 
         # TODO: verify Content-Type?
 
         existed = localstore.has(oid)
 
         # TODO: how to handle timeouts?  The body proxy handles limiting to
         #       Content-Length, but what happens if a client sends less than it
         #       says it will?
 
         # TODO: download() will abort if the checksum fails.  It should raise
         #       something checksum specific that can be caught here, and turned
         #       into an http code.
         localstore.download(oid, req.bodyfh)
 
         statusmessage = hgwebcommon.statusmessage
         res.status = statusmessage(HTTP_OK if existed else HTTP_CREATED)
 
         # There's no payload here, but this is the header that lfs-test-server
         # sends back.  This eliminates some gratuitous test output conditionals.
         res.headers[b'Content-Type'] = b'text/plain; charset=utf-8'
         res.setbodybytes(b'')
 
         return True
     elif method == b'GET':
         checkperm('pull')
 
         res.status = hgwebcommon.statusmessage(HTTP_OK)
         res.headers[b'Content-Type'] = b'application/octet-stream'
 
         # TODO: figure out how to send back the file in chunks, instead of
         #       reading the whole thing.
         res.setbodybytes(localstore.read(oid))
 
         return True
     else:
         _sethttperror(res, HTTP_BAD_REQUEST,
                       message=b'Unsupported LFS transfer method: %s' % method)
         return True

tests/test-lfs-serve-access.t

@@ -1,334 +1,346 b''
 #require serve no-reposimplestore
 
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > lfs=
   > [lfs]
   > track=all()
   > [web]
   > push_ssl = False
   > allow-push = *
   > EOF
 
 Serving LFS files can experimentally be turned off.  The long term solution is
 to support the 'verify' action in both client and server, so that the server can
 tell the client to store files elsewhere.
 
   $ hg init server
   $ hg --config "lfs.usercache=$TESTTMP/servercache" \
   >    --config experimental.lfs.serve=False -R server serve -d \
   >    -p $HGPORT --pid-file=hg.pid -A $TESTTMP/access.log -E $TESTTMP/errors.log
   $ cat hg.pid >> $DAEMON_PIDS
 
 Uploads fail...
 
   $ hg init client
   $ echo 'this-is-an-lfs-file' > client/lfs.bin
   $ hg -R client ci -Am 'initial commit'
   adding lfs.bin
   $ hg -R client push http://localhost:$HGPORT
   pushing to http://localhost:$HGPORT/
   searching for changes
   abort: LFS HTTP error: HTTP Error 400: no such method: .git (action=upload)!
   [255]
 
 ... so do a local push to make the data available.  Remove the blob from the
 default cache, so it attempts to download.
   $ hg --config "lfs.usercache=$TESTTMP/servercache" \
   >    --config "lfs.url=null://" \
   >    -R client push -q server
   $ mv `hg config lfs.usercache` $TESTTMP/servercache
 
 Downloads fail...
 
   $ hg clone http://localhost:$HGPORT httpclone
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   new changesets 525251863cad
   updating to branch default
   abort: LFS HTTP error: HTTP Error 400: no such method: .git (action=download)!
   [255]
 
   $ $PYTHON $RUNTESTDIR/killdaemons.py $DAEMON_PIDS
 
   $ cat $TESTTMP/access.log $TESTTMP/errors.log
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D525251863cad618e55d483555f3d00a2ca99597e x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=phases x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=bookmarks x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 400 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=getbundle HTTP/1.1" 200 - x-hgarg-1:bookmarks=1&bundlecaps=HG20%2Cbundle2%3DHG20%250Abookmarks%250Achangegroup%253D01%252C02%252C03%250Adigests%253Dmd5%252Csha1%252Csha512%250Aerror%253Dabort%252Cunsupportedcontent%252Cpushraced%252Cpushkey%250Ahgtagsfnodes%250Alistkeys%250Aphases%253Dheads%250Apushkey%250Aremote-changegroup%253Dhttp%252Chttps%250Arev-branch-cache%250Astream%253Dv2&cg=1&common=0000000000000000000000000000000000000000&heads=525251863cad618e55d483555f3d00a2ca99597e&listkeys=bookmarks&phases=1 x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 400 - (glob)
 
 Blob URIs are correct when --prefix is used
 
   $ rm -f $TESTTMP/access.log $TESTTMP/errors.log
   $ hg --config "lfs.usercache=$TESTTMP/servercache" -R server serve -d \
   >    -p $HGPORT --pid-file=hg.pid --prefix=subdir/mount/point \
   >    -A $TESTTMP/access.log -E $TESTTMP/errors.log
   $ cat hg.pid >> $DAEMON_PIDS
 
   $ hg --config lfs.url=http://localhost:$HGPORT/subdir/mount/point/.git/info/lfs \
   >    clone --debug http://localhost:$HGPORT/subdir/mount/point cloned2
   using http://localhost:$HGPORT/subdir/mount/point
   sending capabilities command
   query 1; heads
   sending batch command
   requesting all changes
   sending getbundle command
   bundle2-input-bundle: with-transaction
   bundle2-input-part: "changegroup" (params: 1 mandatory 1 advisory) supported
   adding changesets
   add changeset 525251863cad
   adding manifests
   adding file changes
   adding lfs.bin revisions
   added 1 changesets with 1 changes to 1 files
   calling hook pretxnchangegroup.lfs: hgext.lfs.checkrequireslfs
   bundle2-input-part: total payload size 648
   bundle2-input-part: "listkeys" (params: 1 mandatory) supported
   bundle2-input-part: "phase-heads" supported
   bundle2-input-part: total payload size 24
   bundle2-input-part: "cache:rev-branch-cache" supported
   bundle2-input-part: total payload size 39
   bundle2-input-bundle: 3 parts total
   checking for updated bookmarks
   updating the branch cache
   new changesets 525251863cad
   updating to branch default
   resolving manifests
    branchmerge: False, force: False, partial: False
    ancestor: 000000000000, local: 000000000000+, remote: 525251863cad
   Status: 200
   Content-Length: 371
   Content-Type: application/vnd.git-lfs+json
   Date: $HTTP_DATE$
   Server: testing stub value
   {
     "objects": [
       {
         "actions": {
           "download": {
             "expires_at": "$ISO_8601_DATE_TIME$"
             "header": {
               "Accept": "application/vnd.git-lfs"
             }
             "href": "http://localhost:$HGPORT/subdir/mount/point/.hg/lfs/objects/f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e"
           }
         }
         "oid": "f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e"
         "size": 20
       }
     ]
     "transfer": "basic"
   }
   lfs: downloading f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e (20 bytes)
   Status: 200
   Content-Length: 20
   Content-Type: application/octet-stream
   Date: $HTTP_DATE$
   Server: testing stub value
   lfs: adding f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e to the usercache
   lfs: processed: f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e
    lfs.bin: remote created -> g
   getting lfs.bin
   lfs: found f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e in the local lfs store
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
 
   $ $PYTHON $RUNTESTDIR/killdaemons.py $DAEMON_PIDS
 
   $ cat $TESTTMP/access.log $TESTTMP/errors.log
   $LOCALIP - - [$LOGDATE$] "GET /subdir/mount/point?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /subdir/mount/point?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /subdir/mount/point?cmd=getbundle HTTP/1.1" 200 - x-hgarg-1:bookmarks=1&bundlecaps=HG20%2Cbundle2%3DHG20%250Abookmarks%250Achangegroup%253D01%252C02%252C03%250Adigests%253Dmd5%252Csha1%252Csha512%250Aerror%253Dabort%252Cunsupportedcontent%252Cpushraced%252Cpushkey%250Ahgtagsfnodes%250Alistkeys%250Aphases%253Dheads%250Apushkey%250Aremote-changegroup%253Dhttp%252Chttps%250Arev-branch-cache%250Astream%253Dv2&cg=1&common=0000000000000000000000000000000000000000&heads=525251863cad618e55d483555f3d00a2ca99597e&listkeys=bookmarks&phases=1 x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /subdir/mount/point/.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /subdir/mount/point/.hg/lfs/objects/f03217a32529a28a42d03b1244fe09b6e0f9fd06d7b966d4d50567be2abe6c0e HTTP/1.1" 200 - (glob)
 
   $ cat >> $TESTTMP/lfsstoreerror.py <<EOF
   > import errno
   > from hgext.lfs import blobstore
   > 
   > _numverifies = 0
   > _readerr = True
   > 
   > def reposetup(ui, repo):
   >     # Nothing to do with a remote repo
   >     if not repo.local():
   >         return
   > 
   >     store = repo.svfs.lfslocalblobstore
   >     class badstore(store.__class__):
   >         def download(self, oid, src):
   >             '''Called in the server to handle reading from the client in a
   >             PUT request.'''
   >             origread = src.read
   >             def _badread(nbytes):
   >                 # Simulate bad data/checksum failure from the client
   >                 return b'0' * len(origread(nbytes))
   >             src.read = _badread
   >             super(badstore, self).download(oid, src)
   > 
   >         def _read(self, vfs, oid, verify):
   >             '''Called in the server to read data for a GET request, and then
   >             calls self._verify() on it before returning.'''
   >             global _readerr
   >             # One time simulation of a read error
   >             if _readerr:
   >                 _readerr = False
   >                 raise IOError(errno.EIO, '%s: I/O error' % oid)
   >             # Simulate corrupt content on client download
   >             blobstore._verify(oid, 'dummy content')
   > 
   >         def verify(self, oid):
   >             '''Called in the server to populate the Batch API response,
   >             letting the client re-upload if the file is corrupt.'''
   >             # Fail verify in Batch API for one clone command and one push
   >             # command with an IOError.  Then let it through to access other
   >             # functions.  Checksum failure is tested elsewhere.
   >             global _numverifies
   >             _numverifies += 1
   >             if _numverifies <= 2:
   >                 raise IOError(errno.EIO, '%s: I/O error' % oid)
   >             return super(badstore, self).verify(oid)
   > 
   >     store.__class__ = badstore
   > EOF
 
   $ rm -rf `hg config lfs.usercache`
   $ rm -f $TESTTMP/access.log $TESTTMP/errors.log
   $ hg --config "lfs.usercache=$TESTTMP/servercache" \
   >    --config extensions.lfsstoreerror=$TESTTMP/lfsstoreerror.py \
   >    -R server serve -d \
   >    -p $HGPORT1 --pid-file=hg.pid -A $TESTTMP/access.log -E $TESTTMP/errors.log
   $ cat hg.pid >> $DAEMON_PIDS
 
 Test an I/O error in localstore.verify() (Batch API) with GET
 
   $ hg clone http://localhost:$HGPORT1 httpclone2
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   new changesets 525251863cad
   updating to branch default
   abort: LFS server error for "lfs.bin": Internal server error!
   [255]
 
 Test an I/O error in localstore.verify() (Batch API) with PUT
 
   $ echo foo > client/lfs.bin
   $ hg -R client ci -m 'mod lfs'
   $ hg -R client push http://localhost:$HGPORT1
   pushing to http://localhost:$HGPORT1/
   searching for changes
   abort: LFS server error for "unknown": Internal server error!
   [255]
 TODO: figure out how to associate the file name in the error above
 
 Test a bad checksum sent by the client in the transfer API
 
   $ hg -R client push http://localhost:$HGPORT1
   pushing to http://localhost:$HGPORT1/
   searching for changes
   abort: HTTP error: HTTP Error 500: Internal Server Error (oid=b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c, action=upload)!
   [255]
 
   $ echo 'test lfs file' > server/lfs3.bin
   $ hg --config experimental.lfs.disableusercache=True \
   >    -R server ci -Aqm 'another lfs file'
   $ hg -R client pull -q http://localhost:$HGPORT1
 
 Test an I/O error during the processing of the GET request
 
   $ hg --config lfs.url=http://localhost:$HGPORT1/.git/info/lfs \
   >    -R client update -r tip
   abort: HTTP error: HTTP Error 500: Internal Server Error (oid=276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d, action=download)!
   [255]
 
 Test a checksum failure during the processing of the GET request
 
   $ hg --config lfs.url=http://localhost:$HGPORT1/.git/info/lfs \
   >    -R client update -r tip
   abort: HTTP error: HTTP Error 500: Internal Server Error (oid=276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d, action=download)!
   [255]
 
   $ $PYTHON $RUNTESTDIR/killdaemons.py $DAEMON_PIDS
 
   $ cat $TESTTMP/access.log
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=getbundle HTTP/1.1" 200 - x-hgarg-1:bookmarks=1&bundlecaps=HG20%2Cbundle2%3DHG20%250Abookmarks%250Achangegroup%253D01%252C02%252C03%250Adigests%253Dmd5%252Csha1%252Csha512%250Aerror%253Dabort%252Cunsupportedcontent%252Cpushraced%252Cpushkey%250Ahgtagsfnodes%250Alistkeys%250Aphases%253Dheads%250Apushkey%250Aremote-changegroup%253Dhttp%252Chttps%250Arev-branch-cache%250Astream%253Dv2&cg=1&common=0000000000000000000000000000000000000000&heads=525251863cad618e55d483555f3d00a2ca99597e&listkeys=bookmarks&phases=1 x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D392c05922088bacf8e68a6939b480017afbf245d x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=phases x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=bookmarks x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=branchmap HTTP/1.1" 200 - x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=bookmarks x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D392c05922088bacf8e68a6939b480017afbf245d x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=phases x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=bookmarks x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=branchmap HTTP/1.1" 200 - x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=listkeys HTTP/1.1" 200 - x-hgarg-1:namespace=bookmarks x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "PUT /.hg/lfs/objects/b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c HTTP/1.1" 500 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=capabilities HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=batch HTTP/1.1" 200 - x-hgarg-1:cmds=heads+%3Bknown+nodes%3D392c05922088bacf8e68a6939b480017afbf245d x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "GET /?cmd=getbundle HTTP/1.1" 200 - x-hgarg-1:bookmarks=1&bundlecaps=HG20%2Cbundle2%3DHG20%250Abookmarks%250Achangegroup%253D01%252C02%252C03%250Adigests%253Dmd5%252Csha1%252Csha512%250Aerror%253Dabort%252Cunsupportedcontent%252Cpushraced%252Cpushkey%250Ahgtagsfnodes%250Alistkeys%250Aphases%253Dheads%250Apushkey%250Aremote-changegroup%253Dhttp%252Chttps%250Arev-branch-cache%250Astream%253Dv2&cg=1&common=525251863cad618e55d483555f3d00a2ca99597e&heads=506bf3d83f78c54b89e81c6411adee19fdf02156+525251863cad618e55d483555f3d00a2ca99597e&listkeys=bookmarks&phases=1 x-hgproto-1:0.1 0.2 comp=$USUAL_COMPRESSIONS$ partial-pull (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $LOCALIP - - [$LOGDATE$] "GET /.hg/lfs/objects/276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d HTTP/1.1" 500 - (glob)
   $LOCALIP - - [$LOGDATE$] "POST /.git/info/lfs/objects/batch HTTP/1.1" 200 - (glob)
   $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()
       self.do_hgweb()
       for chunk in self.server.application(env, self._start_response):
       for r in self._runwsgi(req, res, repo):
       rctx, req, res, self.check_perm)
       return func(*(args + a), **kw)
       lambda perm:
       localstore.download(oid, req.bodyfh)
       super(badstore, self).download(oid, src)
       raise error.Abort(_('corrupt remote lfs object: %s') % oid)
   Abort: corrupt remote lfs object: b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c
   
   $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/.hg/lfs/objects/276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d': (glob)
   Traceback (most recent call last):
       self.do_write()
       self.do_hgweb()
       for chunk in self.server.application(env, self._start_response):
       for r in self._runwsgi(req, res, repo):
       rctx, req, res, self.check_perm)
       return func(*(args + a), **kw)
       lambda perm:
       res.setbodybytes(localstore.read(oid))
       blob = self._read(self.vfs, oid, verify)
       raise IOError(errno.EIO, '%s: I/O error' % oid)
   IOError: [Errno 5] 276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d: I/O error
   
   $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/.hg/lfs/objects/276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d': (glob)
   Traceback (most recent call last):
       self.do_write()
       self.do_hgweb()
       for chunk in self.server.application(env, self._start_response):
       for r in self._runwsgi(req, res, repo):
       rctx, req, res, self.check_perm)
       return func(*(args + a), **kw)
       lambda perm:
       res.setbodybytes(localstore.read(oid))
       blob = self._read(self.vfs, oid, verify)
       blobstore._verify(oid, 'dummy content')
       hint=_('run hg verify'))
   Abort: detected corrupt lfs object: 276f73cfd75f9fb519810df5f5d96d6594ca2521abd86cbcd92122f7d51a1f3d