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
$ cat >> fakepager.py <<EOF
> import sys
> printed = False
> for line in sys.stdin:
> sys.stdout.write('paged! %r\n' % line)
> printed = True
> if not printed:
> sys.stdout.write('paged empty output!\n')
> EOF
Enable ui.formatted because pager won't fire without it, and set up
pager and tell it to use our fake pager that lets us see when the
pager was running.
$ cat >> $HGRCPATH <<EOF
> [ui]
> formatted = yes
> color = no
> [pager]
> pager = "$PYTHON" $TESTTMP/fakepager.py
> EOF
$ hg init repo
$ cd repo
$ echo a >> a
$ hg add a
$ hg ci -m 'add a'
$ for x in `"$PYTHON" $TESTDIR/seq.py 1 10`; do
> echo a $x >> a
> hg ci -m "modify a $x"
> done
By default diff and log are paged, but id is not:
$ hg diff -c 2 --pager=yes
paged! 'diff -r f4be7687d414 -r bce265549556 a\n'
paged! '--- a/a\tThu Jan 01 00:00:00 1970 +0000\n'
paged! '+++ b/a\tThu Jan 01 00:00:00 1970 +0000\n'
paged! '@@ -1,2 +1,3 @@\n'
paged! ' a\n'
paged! ' a 1\n'
paged! '+a 2\n'
$ hg log --limit 2
paged! 'changeset: 10:46106edeeb38\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
paged! 'changeset: 9:6dd8ea7dd621\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 9\n'
paged! '\n'
$ hg id
46106edeeb38 tip
We can control the pager from the config
$ hg log --limit 1 --config 'ui.paginate=False'
changeset: 10:46106edeeb38
tag: tip
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 10
$ hg log --limit 1 --config 'ui.paginate=0'
changeset: 10:46106edeeb38
tag: tip
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 10
$ hg log --limit 1 --config 'ui.paginate=1'
paged! 'changeset: 10:46106edeeb38\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
explicit --pager=on should take precedence over other configurations
(issue5580)
$ cat >> $HGRCPATH <<EOF
> [ui]
> paginate = false
> EOF
$ hg log --limit 1 --pager=on
paged! 'changeset: 10:46106edeeb38\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
$ cat >> $HGRCPATH <<EOF
> [ui]
> # true is default value of ui.paginate
> paginate = true
> EOF
$ hg log --limit 1 --pager=off
changeset: 10:46106edeeb38
tag: tip
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 10
We can enable the pager on id:
BROKEN: should be paged
$ hg --config pager.attend-id=yes id
46106edeeb38 tip
Setting attend-$COMMAND to a false value works, even with pager in
core:
$ hg --config pager.attend-diff=no diff -c 2
diff -r f4be7687d414 -r bce265549556 a
--- a/a Thu Jan 01 00:00:00 1970 +0000
+++ b/a Thu Jan 01 00:00:00 1970 +0000
@@ -1,2 +1,3 @@
a
a 1
+a 2
Command aliases should have same behavior as main command
$ hg history --limit 2
paged! 'changeset: 10:46106edeeb38\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
paged! 'changeset: 9:6dd8ea7dd621\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 9\n'
paged! '\n'
Abbreviated command alias should also be paged
$ hg hist -l 1
paged! 'changeset: 10:46106edeeb38\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
Attend for an abbreviated command does not work
$ hg --config pager.attend-ident=true ident
46106edeeb38 tip
$ hg --config extensions.pager= --config pager.attend-ident=true ident
46106edeeb38 tip
Pager should not start if stdout is not a tty.
$ hg log -l1 -q --config ui.formatted=False
10:46106edeeb38
Pager should be disabled if pager.pager is empty (otherwise the output would
be silently lost.)
$ hg log -l1 -q --config pager.pager=
10:46106edeeb38
Pager with color enabled allows colors to come through by default,
even though stdout is no longer a tty.
$ cat >> $HGRCPATH <<EOF
> [ui]
> color = always
> [color]
> mode = ansi
> EOF
$ hg log --limit 3
paged! '\x1b[0;33mchangeset: 10:46106edeeb38\x1b[0m\n'
paged! 'tag: tip\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 10\n'
paged! '\n'
paged! '\x1b[0;33mchangeset: 9:6dd8ea7dd621\x1b[0m\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 9\n'
paged! '\n'
paged! '\x1b[0;33mchangeset: 8:cff05a6312fe\x1b[0m\n'
paged! 'user: test\n'
paged! 'date: Thu Jan 01 00:00:00 1970 +0000\n'
paged! 'summary: modify a 8\n'
paged! '\n'
#if no-chg
An invalid pager command name is reported sensibly if we don't have to
use shell=True in the subprocess call:
$ hg log --limit 3 --config pager.pager=this-command-better-never-exist
missing pager command 'this-command-better-never-exist', skipping pager
\x1b[0;33mchangeset: 10:46106edeeb38\x1b[0m (esc)
tag: tip
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 10
\x1b[0;33mchangeset: 9:6dd8ea7dd621\x1b[0m (esc)
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 9
\x1b[0;33mchangeset: 8:cff05a6312fe\x1b[0m (esc)
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: modify a 8
#endif
A complicated pager command gets worse behavior. Bonus points if you can
improve this.
$ hg log --limit 3 \
> --config pager.pager='this-command-better-never-exist --seriously' \
> 2>/dev/null || true
Pager works with shell aliases.
$ cat >> $HGRCPATH <<EOF
> [alias]
> echoa = !echo a
> EOF
$ hg echoa
a
BROKEN: should be paged
$ hg --config pager.attend-echoa=yes echoa
a
Pager works with hg aliases including environment variables.
$ cat >> $HGRCPATH <<'EOF'
> [alias]
> printa = log -T "$A\n" -r 0
> EOF
$ A=1 hg --config pager.attend-printa=yes printa
paged! '1\n'
$ A=2 hg --config pager.attend-printa=yes printa
paged! '2\n'
Something that's explicitly attended is still not paginated if the
pager is globally set to off using a flag:
$ A=2 hg --config pager.attend-printa=yes printa --pager=no
2
Pager should not override the exit code of other commands
$ cat >> $TESTTMP/fortytwo.py <<'EOF'
> from mercurial import commands, registrar
> cmdtable = {}
> command = registrar.command(cmdtable)
> @command(b'fortytwo', [], b'fortytwo', norepo=True)
> def fortytwo(ui, *opts):
> ui.write(b'42\n')
> return 42
> EOF
$ cat >> $HGRCPATH <<'EOF'
> [extensions]
> fortytwo = $TESTTMP/fortytwo.py
> EOF
$ hg fortytwo --pager=on
paged! '42\n'
[42]
A command that asks for paging using ui.pager() directly works:
$ hg blame a
paged! ' 0: a\n'
paged! ' 1: a 1\n'
paged! ' 2: a 2\n'
paged! ' 3: a 3\n'
paged! ' 4: a 4\n'
paged! ' 5: a 5\n'
paged! ' 6: a 6\n'
paged! ' 7: a 7\n'
paged! ' 8: a 8\n'
paged! ' 9: a 9\n'
paged! '10: a 10\n'
but not with HGPLAIN
$ HGPLAIN=1 hg blame a
0: a
1: a 1
2: a 2
3: a 3
4: a 4
5: a 5
6: a 6
7: a 7
8: a 8
9: a 9
10: a 10
explicit flags work too:
$ hg blame --pager=no a
0: a
1: a 1
2: a 2
3: a 3
4: a 4
5: a 5
6: a 6
7: a 7
8: a 8
9: a 9
10: a 10
A command with --output option:
$ hg cat -r0 a
paged! 'a\n'
$ hg cat -r0 a --output=-
paged! 'a\n'
$ hg cat -r0 a --output=out
$ hg export -r0
paged! '# HG changeset patch\n'
paged! '# User test\n'
paged! '# Date 0 0\n'
paged! '# Thu Jan 01 00:00:00 1970 +0000\n'
paged! '# Node ID 1f0dee641bb7258c56bd60e93edfa2405381c41e\n'
paged! '# Parent 0000000000000000000000000000000000000000\n'
paged! 'add a\n'
paged! '\n'
paged! '\x1b[0;1mdiff -r 000000000000 -r 1f0dee641bb7 a\x1b[0m\n'
paged! '\x1b[0;31;1m--- /dev/null\tThu Jan 01 00:00:00 1970 +0000\x1b[0m\n'
paged! '\x1b[0;32;1m+++ b/a\tThu Jan 01 00:00:00 1970 +0000\x1b[0m\n'
paged! '\x1b[0;35m@@ -0,0 +1,1 @@\x1b[0m\n'
paged! '\x1b[0;32m+a\x1b[0m\n'
$ hg export -r0 -o -
paged! '# HG changeset patch\n'
paged! '# User test\n'
paged! '# Date 0 0\n'
paged! '# Thu Jan 01 00:00:00 1970 +0000\n'
paged! '# Node ID 1f0dee641bb7258c56bd60e93edfa2405381c41e\n'
paged! '# Parent 0000000000000000000000000000000000000000\n'
paged! 'add a\n'
paged! '\n'
paged! '\x1b[0;1mdiff -r 000000000000 -r 1f0dee641bb7 a\x1b[0m\n'
paged! '\x1b[0;31;1m--- /dev/null\tThu Jan 01 00:00:00 1970 +0000\x1b[0m\n'
paged! '\x1b[0;32;1m+++ b/a\tThu Jan 01 00:00:00 1970 +0000\x1b[0m\n'
paged! '\x1b[0;35m@@ -0,0 +1,1 @@\x1b[0m\n'
paged! '\x1b[0;32m+a\x1b[0m\n'
$ hg export -r0 -o out
$ rm out
Put annotate in the ignore list for pager:
$ cat >> $HGRCPATH <<EOF
> [pager]
> ignore = annotate
> EOF
$ hg blame a
0: a
1: a 1
2: a 2
3: a 3
4: a 4
5: a 5
6: a 6
7: a 7
8: a 8
9: a 9
10: a 10
During pushbuffer, pager should not start:
$ cat > $TESTTMP/pushbufferpager.py <<EOF
> def uisetup(ui):
> ui.pushbuffer()
> ui.pager(b'mycmd')
> ui.write(b'content\n')
> ui.write(ui.popbuffer())
> EOF
$ echo append >> a
$ hg --config extensions.pushbuffer=$TESTTMP/pushbufferpager.py status --color=off
content
paged! 'M a\n'
Environment variables like LESS and LV are set automatically:
$ cat > $TESTTMP/printlesslv.py <<EOF
> from __future__ import absolute_import
> import os
> import sys
> sys.stdin.read()
> for name in ['LESS', 'LV']:
> sys.stdout.write(('%s=%s\n') % (name, os.environ.get(name, '-')))
> sys.stdout.flush()
> EOF
$ cat >> $HGRCPATH <<EOF
> [alias]
> noop = log -r 0 -T ''
> [ui]
> formatted=1
> [pager]
> pager = "$PYTHON" $TESTTMP/printlesslv.py
> EOF
$ unset LESS
$ unset LV
$ hg noop --pager=on
LESS=FRX
LV=-c
$ LESS=EFGH hg noop --pager=on
LESS=EFGH
LV=-c