lfs: fix the stall and corruption issue when concurrently uploading blobs
We've avoided the issue up to this point by gating worker usage with an
experimental config. See 10e62d5efa73, and the thread linked there for some of
the initial diagnosis, but essentially some data was being read from the blob
before an error occurred and `keepalive` retried, but didn't rewind the file
pointer. So the leading data was lost from the blob on the server, and the
connection stalled, trying to send more data than available.
In trying to recreate this, I was unable to do so uploading from Windows to
CentOS 7. But it reproduced every time going from CentOS 7 to another CentOS 7
over https.
I found recent fixes in the FaceBook repo to address this[1][2]. The commit
message for the first is:
The KeepAlive HTTP implementation is bugged in it's retry logic, it supports
reading from a file pointer, but doesn't support rewinding of the seek cursor
when it performs a retry. So it can happen that an upload fails for whatever
reason and will then 'hang' on the retry event.
The sequence of events that get triggered are:
- Upload file A, goes OK. Keep-Alive caches connection.
- Upload file B, fails due to (for example) failing Keep-Alive, but LFS file
pointer has been consumed for the upload and fd has been closed.
- Retry for file B starts, sets the Content-Length properly to the expected
file size, but since file pointer has been consumed no data will be uploaded,
causing the server to wait for the uploaded data until either client or
server reaches a timeout, making it seem as our mercurial process hangs.
This is just a stop-gap measure to prevent this behavior from blocking Mercurial
(LFS has retry logic). A proper solutions need to be build on top of this
stop-gap measure: for upload from file pointers, we should support fseek() on
the interface. Since we expect to consume the whole file always anyways, this
should be safe. This way we can seek back to the beginning on a retry.
I ported those two patches, and it works. But I see that `url._sendfile()` does
a rewind on `httpsendfile` objects[3], so maybe it's better to keep this all in
one place and avoid a second seek. We may still want the first FaceBook patch
as extra protection for this problem in general. The other two uses of
`httpsendfile` are in the wire protocol to upload bundles, and to upload
largefiles. Neither of these appear to use a worker, and I'm not sure why
workers seem to trigger this, or if this could have happened without a worker.
Since `httpsendfile` already has a `close()` method, that is dropped. That
class also explicitly says there's no `__len__` attribute, so that is removed
too. The override for `read()` is necessary to avoid the progressbar usage per
file.
[1] https://github.com/facebookexperimental/eden/commit/c350d6536d90c044c837abdd3675185644481469
[2] https://github.com/facebookexperimental/eden/commit/77f0d3fd0415e81b63e317e457af9c55c46103ee
[3] https://www.mercurial-scm.org/repo/hg/file/5.2.2/mercurial/url.py#l176
Differential Revision: https://phab.mercurial-scm.org/D7962
$ filterlog () {
> sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!'
> }
ensure that failing ui.atexit handlers report sensibly
$ cat > $TESTTMP/bailatexit.py <<EOF
> from mercurial import util
> def bail():
> raise RuntimeError('ui.atexit handler exception')
>
> def extsetup(ui):
> ui.atexit(bail)
> EOF
$ hg -q --config extensions.bailatexit=$TESTTMP/bailatexit.py \
> help help
hg help [-eck] [-s PLATFORM] [TOPIC]
show help for a given topic or a help overview
error in exit handlers:
Traceback (most recent call last):
File "*/mercurial/dispatch.py", line *, in _runexithandlers (glob)
func(*args, **kwargs)
File "$TESTTMP/bailatexit.py", line *, in bail (glob)
raise RuntimeError('ui.atexit handler exception')
RuntimeError: ui.atexit handler exception
[255]
$ rm $TESTTMP/bailatexit.py
another bad extension
$ echo 'raise Exception("bit bucket overflow")' > badext.py
$ abspathexc=`pwd`/badext.py
$ cat >baddocext.py <<EOF
> """
> baddocext is bad
> """
> EOF
$ abspathdoc=`pwd`/baddocext.py
$ cat <<EOF >> $HGRCPATH
> [extensions]
> gpg =
> hgext.gpg =
> badext = $abspathexc
> baddocext = $abspathdoc
> badext2 =
> EOF
$ hg -q help help 2>&1 |grep extension
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
*** failed to import extension badext2: No module named *badext2* (glob)
show traceback
$ hg -q help help --traceback 2>&1 | egrep ' extension|^Exception|Traceback|ImportError|ModuleNotFound'
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
Traceback (most recent call last):
Exception: bit bucket overflow
*** failed to import extension badext2: No module named *badext2* (glob)
Traceback (most recent call last):
ImportError: No module named badext2 (no-py3 !)
ImportError: No module named 'hgext.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py36 !)
Traceback (most recent call last): (py3 !)
ImportError: No module named 'hgext3rd.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext3rd.badext2' (py36 !)
Traceback (most recent call last): (py3 !)
ImportError: No module named 'badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'badext2' (py36 !)
names of extensions failed to load can be accessed via extensions.notloaded()
$ cat <<EOF > showbadexts.py
> from mercurial import commands, extensions, registrar
> cmdtable = {}
> command = registrar.command(cmdtable)
> @command(b'showbadexts', norepo=True)
> def showbadexts(ui, *pats, **opts):
> ui.write(b'BADEXTS: %s\n' % b' '.join(sorted(extensions.notloaded())))
> EOF
$ hg --config extensions.badexts=showbadexts.py showbadexts 2>&1 | grep '^BADEXTS'
BADEXTS: badext badext2
#if no-extraextensions
show traceback for ImportError of hgext.name if devel.debug.extensions is set
$ (hg help help --traceback --debug --config devel.debug.extensions=yes 2>&1) \
> | grep -v '^ ' \
> | filterlog \
> | egrep 'extension..[^p]|^Exception|Traceback|ImportError|^YYYY|not import|ModuleNotFound'
YYYY/MM/DD HH:MM:SS (PID)> loading extensions
YYYY/MM/DD HH:MM:SS (PID)> - processing 5 entries
YYYY/MM/DD HH:MM:SS (PID)> - loading extension: gpg
YYYY/MM/DD HH:MM:SS (PID)> > gpg extension loaded in * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - validating extension tables: gpg
YYYY/MM/DD HH:MM:SS (PID)> - invoking registered callbacks: gpg
YYYY/MM/DD HH:MM:SS (PID)> > callbacks completed in * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - loading extension: badext
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
Traceback (most recent call last):
Exception: bit bucket overflow
YYYY/MM/DD HH:MM:SS (PID)> - loading extension: baddocext
YYYY/MM/DD HH:MM:SS (PID)> > baddocext extension loaded in * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - validating extension tables: baddocext
YYYY/MM/DD HH:MM:SS (PID)> - invoking registered callbacks: baddocext
YYYY/MM/DD HH:MM:SS (PID)> > callbacks completed in * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - loading extension: badext2
YYYY/MM/DD HH:MM:SS (PID)> - could not import hgext.badext2 (No module named *badext2*): trying hgext3rd.badext2 (glob)
Traceback (most recent call last):
ImportError: No module named badext2 (no-py3 !)
ImportError: No module named 'hgext.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py36 !)
YYYY/MM/DD HH:MM:SS (PID)> - could not import hgext3rd.badext2 (No module named *badext2*): trying badext2 (glob)
Traceback (most recent call last):
ImportError: No module named badext2 (no-py3 !)
ImportError: No module named 'hgext.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py36 !)
Traceback (most recent call last): (py3 !)
ImportError: No module named 'hgext3rd.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext3rd.badext2' (py36 !)
*** failed to import extension badext2: No module named *badext2* (glob)
Traceback (most recent call last):
ImportError: No module named 'hgext.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext.badext2' (py36 !)
Traceback (most recent call last): (py3 !)
ImportError: No module named 'hgext3rd.badext2' (py3 no-py36 !)
ModuleNotFoundError: No module named 'hgext3rd.badext2' (py36 !)
Traceback (most recent call last): (py3 !)
ModuleNotFoundError: No module named 'badext2' (py36 !)
ImportError: No module named 'badext2' (py3 no-py36 !)
ImportError: No module named badext2 (no-py3 !)
YYYY/MM/DD HH:MM:SS (PID)> > loaded 2 extensions, total time * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
YYYY/MM/DD HH:MM:SS (PID)> - running uisetup for gpg
YYYY/MM/DD HH:MM:SS (PID)> > uisetup for gpg took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - running uisetup for baddocext
YYYY/MM/DD HH:MM:SS (PID)> > uisetup for baddocext took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
YYYY/MM/DD HH:MM:SS (PID)> - running extsetup for gpg
YYYY/MM/DD HH:MM:SS (PID)> > extsetup for gpg took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - running extsetup for baddocext
YYYY/MM/DD HH:MM:SS (PID)> > extsetup for baddocext took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
YYYY/MM/DD HH:MM:SS (PID)> > extension baddocext take a total of * to load (glob)
YYYY/MM/DD HH:MM:SS (PID)> > extension gpg take a total of * to load (glob)
YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
#endif
confirm that there's no crash when an extension's documentation is bad
$ hg help --keyword baddocext
*** failed to import extension badext from $TESTTMP/badext.py: bit bucket overflow
*** failed to import extension badext2: No module named *badext2* (glob)
Topics:
extensions Using Additional Features