Patchwork D2720: debugcommands: introduce actions to perform deterministic reads

login
register
mail settings
Submitter phabricator
Date March 8, 2018, 1:37 a.m.
Message ID <differential-rev-PHID-DREV-ujyxuznhvtz2cin6or7g-req@phab.mercurial-scm.org>
Download mbox | patch
Permalink /patch/29112/
State Superseded
Headers show

Comments

phabricator - March 8, 2018, 1:37 a.m.
indygreg created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  "readavailable" is useful as a debugging device to see what data is
  available on a pipe. But the mechanism isn't deterministic because
  what's available on a pipe is highly conditional on timing, system
  load, OS behavior, etc. This makes it not suitable for tests.
  
  We introduce "ereadline," "read," and "eread" for performing
  deterministic I/O operations (at least on blocking file descriptors).
  We convert uses of "readavailable" in tests to use the new
  primitives. This should hopefully make these tests deterministic.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

AFFECTED FILES
  mercurial/debugcommands.py
  tests/test-ssh-proto-unbundle.t
  tests/test-ssh-proto.t

CHANGE DETAILS




To: indygreg, #hg-reviewers
Cc: mercurial-devel
phabricator - March 9, 2018, 5:33 a.m.
mharbison72 added a comment.


  This patch seems to deadlock on Windows when running test-ssh-proto-unbundle.t.  There are two python processes idling:
  
  c:\Python27\python.exe c:/Users/Matt/projects/hg/hg --verbose debugwireproto --localssh --noreadstderr
  CWD: C:\Users\Matt\AppData\Local\Temp\hgtests.1mtivg\child1\test-ssh-proto-unbundle.t\no-bundle1\
  
  and
  
  c:\Python27\python.exe c:/Users/Matt/projects/hg/hg -R C:\Users\Matt\AppData\Local\Temp\hgtests.1mtivg\child1\test-ssh-proto-unbundle.t\no-bundle1 debugserve --sshstdio
  CWD: C:\Users\Matt\AppData\Local\Temp\hgtests.1mtivg\child1\test-ssh-proto-unbundle.t\no-bundle1\
  
  Past experience says that something needs to be flushed- stdout (and maybe stderr?) are full buffered on Windows IIRC.  The following failure with this patch might also point to that:
  
    --- c:/Users/Matt/projects/hg/tests/test-ssh-proto.t
    +++ c:/Users/Matt/projects/hg/tests/test-ssh-proto.t.err
    @@ -100,12 +100,12 @@
       $ hg debugserve --sshstdio --logiofd 1 << EOF
       > hello
       > EOF
    -  o> write(4) -> 4:
    -  o>     384\n
    -  o> write(384) -> 384:
    -  o>     capabilities: lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS_SERVER$unbundle=HG10GZ,HG10BZ,HG10UN\n
       384
       capabilities: lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS_SERVER$ unbundle=HG10GZ,HG10BZ,HG10UN
    +  o> write(4) -> 4:
    +  o>     384\n
    +  o> write(384) -> 384:
    +  o>     capabilities: lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS_SERVER$ unbundle=HG10GZ,HG10BZ,HG10UN\n
       o> flush() -> None
    
       $ hg debugserve --sshstdio --logiofile $TESTTMP/io << EOF

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 4:14 p.m.
indygreg added a comment.


  In https://phab.mercurial-scm.org/D2720#44221, @mharbison72 wrote:
  
  > This patch seems to deadlock on Windows when running test-ssh-proto-unbundle.t.  There are two python processes idling:
  >
  > Past experience says that something needs to be flushed- stdout (and maybe stderr?) are full buffered on Windows IIRC.  The following failure with this patch might also point to that:
  
  
  Hmmm.
  
  We explicitly create the pipes between the processes as unbuffered (`bufsize=0`). That being said, I would not at all be surprised if we need to throw a `flush()` in here somewhere.
  
  Could you please run the test with `run-tests.py -d` and see where it is deadlocking?
  
  The test failure due to the `o>` block is likely due to buffering or a race condition when writing to stdout of the `hg debugwireproto` process. I'll look into that after we fix the deadlock (since fixing might change order of things and I don't want to debug this in a system that is changing).

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 5:38 p.m.
mharbison72 added a comment.


  In https://phab.mercurial-scm.org/D2720#44288, @indygreg wrote:
  
  > In https://phab.mercurial-scm.org/D2720#44221, @mharbison72 wrote:
  >
  > > This patch seems to deadlock on Windows when running test-ssh-proto-unbundle.t.  There are two python processes idling:
  > >
  > > Past experience says that something needs to be flushed- stdout (and maybe stderr?) are full buffered on Windows IIRC.  The following failure with this patch might also point to that:
  >
  >
  > Hmmm.
  >
  > We explicitly create the pipes between the processes as unbuffered (`bufsize=0`). That being said, I would not at all be surprised if we need to throw a `flush()` in here somewhere.
  >
  > Could you please run the test with `run-tests.py -d` and see where it is deadlocking?
  >
  > The test failure due to the `o>` block is likely due to buffering or a race condition when writing to stdout of the `hg debugwireproto` process. I'll look into that after we fix the deadlock (since fixing might change order of things and I don't want to debug this in a system that is changing).
  
  
  It looks like the middle of line 84.  Here's the relevant output, from the start of the stuck command on 43 (the off-by-one in the SALT line is odd, but the other lines are line that too, so I assume it's a zero based index thing):
  
    + echo SALT1520615870 42 0
    SALT1520615870 42 0
    + debugwireproto
    ++ cat -
    + commands='command unbundle
    # This is "force" in hex.
        heads 666f726365
        PUSHFILE ../initial.v1.hg
    eread 115'
    + echo 'testing ssh1'
    testing ssh1
    ++ hg log -r tip -T '{node}'
    + tip=0000000000000000000000000000000000000000
    + echo 'command unbundle
    # This is "force" in hex.
        heads 666f726365
        PUSHFILE ../initial.v1.hg
    eread 115'
    + hg --verbose debugwireproto --localssh --noreadstderr
    creating ssh peer from handshake results
    i> write(104) -> 104:
    i>     hello\n
    i>     between\n
    i>     pairs 81\n
    i>     0000000000000000000000000000000000000000-0000000000000000000000000000000000000000
    i> flush() -> None
    o> readline() -> 4:
    o>     384\n
    o> readline() -> 384:
    o>     capabilities: lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=
    generaldelta,revlogv1 bundle2=HG20%0Abookmarks%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror
    %3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Aphases%3Dheads%0Apushkey%0Arem
    ote-changegroup%3Dhttp%2Chttps unbundle=HG10GZ,HG10BZ,HG10UN\n
    o> readline() -> 2:
    o>     1\n
    o> readline() -> 1:
    o>     \n
    sending unbundle command
    i> write(9) -> 9:
    i>     unbundle\n
    i> write(9) -> 9:
    i>     heads 10\n
    i> write(10) -> 10: 666f726365
    i> flush() -> None
    o> readline() -> 2:
    o>     0\n
    i> write(4) -> 4:
    i>     426\n
    i> write(426) -> 426:
    i>     HG10UN\x00\x00\x00\x9eh\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x0
    0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
    x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
    x00>cba485ca3678256e044428f70f58291196f6e9de\n
    i>     test\n
    i>     0 0\n
    i>     foo\n
    i>     \n
    i>     initial\x00\x00\x00\x00\x00\x00\x00\x8d\xcb\xa4\x85\xca6x%n\x04D(\xf7\x0fX)\x11\x96\xf6\xe9\xde\x00\x00
    \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
    00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x
    00\x00\x00\x00\x00\x00\x00-foo\x00362fef284ce2ca02aecc8de6d5e8a1c3af0556fe\n
    i>     \x00\x00\x00\x00\x00\x00\x00\x07foo\x00\x00\x00b6/\xef(L\xe2\xca\x02\xae\xcc\x8d\xe6\xd5\xe8\xa1\xc3\xa
    f\x05V\xfe\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
    \x00\x00\x00\x00\x00\x00\x00\x00\

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 7:14 p.m.
indygreg added a comment.


  In https://phab.mercurial-scm.org/D2720#44293, @mharbison72 wrote:
  
  > i> write(4) -> 4:
  >  i>     426\n
  >  i> write(426) -> 426:
  >  i>     HG10UN\x00\x00\x00\x9eh\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x0
  >  0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
  >  x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
  >  x00>cba485ca3678256e044428f70f58291196f6e9de\n
  >  i>     test\n
  >  i>     0 0\n
  >  i>     foo\n
  >  i>     \n
  >  i>     initial\x00\x00\x00\x00\x00\x00\x00\x8d\xcb\xa4\x85\xca6x%n\x04D(\xf7\x0fX)\x11\x96\xf6\xe9\xde\x00\x00
  >  \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
  >  00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x
  >  00\x00\x00\x00\x00\x00\x00-foo\x00362fef284ce2ca02aecc8de6d5e8a1c3af0556fe\n
  >  i>     \x00\x00\x00\x00\x00\x00\x00\x07foo\x00\x00\x00b6/\xef(L\xe2\xca\x02\xae\xcc\x8d\xe6\xd5\xe8\xa1\xc3\xa
  >  f\x05V\xfe\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  >  \x00\x00\x00\x00\x00\x00\x00\x00\
  >
  >  
  
  
  This is a wonky place to hang! For context, this is processing a `command unbundle` line. The lines that follow should be:
  
    i> write(2) -> 2:
    i>     0\n
    i> flush() -> None
    o> readline() -> 2:
    o>     0\n
    o> readline() -> 2:
    o>     1\n
    o> read(1) -> 1: 0
    result: 0
    remote output: 
    e> read(115) -> 115:
    e>     abort: incompatible Mercurial client; bundle2 required\n
    e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
  
  What happens under the hood during pushes is we send out chunks containing the bundle followed by an empty chunk. That code is:
  
    for d in iter(lambda: fp.read(4096), ''):
        self._writeframed(d)
    self._writeframed("", flush=True)
  
  That empty chunk is apparently not getting sent. Or its logging is not getting written/printed.
  
  This patch shouldn't have changed any behavior with regard to this part of the I/O. So I'm scratching my head over how this caused deadlock. Are you sure you can bisect it to this patch.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 7:39 p.m.
mharbison72 added a comment.


  In https://phab.mercurial-scm.org/D2720#44350, @indygreg wrote:
  
  > In https://phab.mercurial-scm.org/D2720#44293, @mharbison72 wrote:
  >
  > > i> write(4) -> 4:
  > >  i>     426\n
  > >  i> write(426) -> 426:
  > >  i>     HG10UN\x00\x00\x00\x9eh\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x0
  > >  0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
  > >  x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
  > >  x00>cba485ca3678256e044428f70f58291196f6e9de\n
  > >  i>     test\n
  > >  i>     0 0\n
  > >  i>     foo\n
  > >  i>     \n
  > >  i>     initial\x00\x00\x00\x00\x00\x00\x00\x8d\xcb\xa4\x85\xca6x%n\x04D(\xf7\x0fX)\x11\x96\xf6\xe9\xde\x00\x00
  > >  \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
  > >  00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x
  > >  00\x00\x00\x00\x00\x00\x00-foo\x00362fef284ce2ca02aecc8de6d5e8a1c3af0556fe\n
  > >  i>     \x00\x00\x00\x00\x00\x00\x00\x07foo\x00\x00\x00b6/\xef(L\xe2\xca\x02\xae\xcc\x8d\xe6\xd5\xe8\xa1\xc3\xa
  > >  f\x05V\xfe\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  > >  \x00\x00\x00\x00\x00\x00\x00\x00\
  > >
  > >  
  >
  >
  > This is a wonky place to hang! For context, this is processing a `command unbundle` line. The lines that follow should be:
  >
  >   i> write(2) -> 2:
  >   i>     0\n
  >   i> flush() -> None
  >   o> readline() -> 2:
  >   o>     0\n
  >   o> readline() -> 2:
  >   o>     1\n
  >   o> read(1) -> 1: 0
  >   result: 0
  >   remote output: 
  >   e> read(115) -> 115:
  >   e>     abort: incompatible Mercurial client; bundle2 required\n
  >   e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
  >   
  >
  > What happens under the hood during pushes is we send out chunks containing the bundle followed by an empty chunk. That code is:
  >
  >   for d in iter(lambda: fp.read(4096), ''):
  >       self._writeframed(d)
  >   self._writeframed("", flush=True)
  >
  >
  > That empty chunk is apparently not getting sent. Or its logging is not getting written/printed.
  >
  > This patch shouldn't have changed any behavior with regard to this part of the I/O. So I'm scratching my head over how this caused deadlock. Are you sure you can bisect it to this patch.
  
  
  Yep.  I imported this with `hg phapread --stack`, and can run the https://phab.mercurial-scm.org/D2719 in 50 seconds or so.  The debug run of this I let hang out for 20 minutes before killing it.
  
  Here's the neighboring failure from https://phab.mercurial-scm.org/D2719, because I can't explain the AWOL output.  (But that shouldn't have stopped stdout above mid stream.)
  
    --- e:/Projects/hg/tests/test-ssh-proto-unbundle.t
    +++ e:/Projects/hg/tests/test-ssh-proto-unbundle.t.err
    @@ -93,9 +93,6 @@
       o> read(1) -> 1: 0
       result: 0
       remote output:
    -  e> read(-1) -> 115:
    -  e>     abort: incompatible Mercurial client; bundle2 required\n
    -  e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
    
       testing ssh2
       creating ssh peer from handshake results
    @@ -143,9 +140,6 @@
       o> read(1) -> 1: 0
       result: 0
       remote output:
    -  e> read(-1) -> 115:
    -  e>     abort: incompatible Mercurial client; bundle2 required\n
    -  e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
    
       $ cd ..

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 8:25 p.m.
indygreg added a comment.


  My only explanation is this is stdout output buffering and things are really hanging on the next read operation.
  
  Maybe try sprinkling some `ui.fout.flush()` and/or `util.stdout.flush()` and/or `sys.stdout.flush()` calls throughout the debug command? Maybe at the first thing in the loop that evaluates commands to execute?

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 10:13 p.m.
mharbison72 added a comment.


  In https://phab.mercurial-scm.org/D2720#44396, @indygreg wrote:
  
  > My only explanation is this is stdout output buffering and things are really hanging on the next read operation.
  >
  > Maybe try sprinkling some `ui.fout.flush()` and/or `util.stdout.flush()` and/or `sys.stdout.flush()` calls throughout the debug command? Maybe at the first thing in the loop that evaluates commands to execute?
  
  
  Both `util.stdout.flush()` and `ui.fout.flush()` get a little further in the same command; `sys.stdout.flush()` has no effect, when added at the top of the loop.  But then it stalls on remote output:
  
    ...
    o> readline() -> 2:
    o>     0\n
    i> write(4) -> 4:
    i>     426\n
    i> write(426) -> 426:
    i>     HG10UN\x00\x00\x00\x9eh\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x0
    0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
    x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
    x00>cba485ca3678256e044428f70f58291196f6e9de\n
    i>     test\n
    i>     0 0\n
    i>     foo\n
    i>     \n
    i>     initial\x00\x00\x00\x00\x00\x00\x00\x8d\xcb\xa4\x85\xca6x%n\x04D(\xf7\x0fX)\x11\x96\xf6\xe9\xde\x00\x00
    \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
    00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f\x00\x00\x00\x00\x
    00\x00\x00\x00\x00\x00\x00-foo\x00362fef284ce2ca02aecc8de6d5e8a1c3af0556fe\n
    i>     \x00\x00\x00\x00\x00\x00\x00\x07foo\x00\x00\x00b6/\xef(L\xe2\xca\x02\xae\xcc\x8d\xe6\xd5\xe8\xa1\xc3\xa
    f\x05V\xfe\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
    \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00h\x98b\x13\xbdD\x85\xeaQS55\xe3\xfc\x9ex\x00zq\x1f
    \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x020\n
    i>     \x00\x00\x00\x00\x00\x00\x00\x00
    i> write(2) -> 2:
    i>     0\n
    i> flush() -> None
    o> readline() -> 2:
    o>     0\n
    o> readline() -> 2:
    o>     1\n
    o> read(1) -> 1: 0
    result: 0
    remote output:
  
  So I added a self.flush() inside ui._write() because I figured this is a problem on the remote end (and probably not localized like the debug command), but that didn't do anything.  (ui._write_err() already flushes, and has a comment about stderr may be buffered on Windows.)
  
  IDK if this means anything, but when it is stuck and I hit Ctrl + C, instead of terminating the test, the test simply continues with the script, and then hangs on the next 'remote output:' line.  Typically, Ctrl + C ends the test runner.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 9, 2018, 10:51 p.m.
mharbison72 added a comment.


  
  
  > IDK if this means anything, but when it is stuck and I hit Ctrl+C, instead of terminating the test, the test simply continues with the script, and then hangs on the next 'remote output:' line.  Typically, Ctrl+C ends the test runner.
  
  A couple of more tidbits on this:
  
  1. When I hit Ctrl+C, it *does* print the shell prompt, but the process keeps printing test output after it, so I missed it.  When it jams, I can hit Ctrl+C again to get it going again.
  2. I did that all the way through the test, and eventually it got to the last one, which prints:
  
    i> write(2) -> 2:
    i>     0\n
    i> flush() -> None
    o> readline() -> 2:
    o>     0\n
    o> readline() -> 2:
    o>     1\n
    o> read(1) -> 1: 1
    result: 1
    remote output:
    e> read(152) -> 152:
    e>     adding changesets\n
    e>     adding manifests\n
    e>     adding file changes\n
    e>     added 1 changesets with 1 changes to 1 files\n
    e>     ui.write 1\n
    e>     ui.write_err 1\n
    e>     ui.write 2\n
    e>     ui.write_err 2\n
    + '[' -n 1 ']'
    + hg --config extensions.strip= strip --no-backup -r 'all() - ::0000000000000000000000000000000000000000'
    + echo SALT1520635194 2034 0
    SALT1520635194 2034 0
  
  Note the exit code is 1 here.  So is it possible that the debug command is having trouble reading bytes from an empty stderr in the initial cases?

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 10, 2018, 6:28 p.m.
mharbison72 added a comment.


  At this point, I've narrowed it down to stderr.  I misunderstood the 'noreadstderr', and wondered why we were bothering to pipe stderr if True.  So I set it to os.devnull, and the test sails through.  (But it does drop all "e>" lines, so that's not an actual solution.)
  
  Is there some way to send a signal to a python process to get it to dump its stacks, like Ctrl+\ in java?  Sprinkling random prints and flushes hasn't been fruitful so far.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 10, 2018, 6:30 p.m.
indygreg added a comment.


  See the `contrib/showstack.py` extension for registering SIGQUIT and SIGINFO signals to dump the active stack. Not sure if that works on Windows though.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: mharbison72, mercurial-devel
phabricator - March 13, 2018, 12:12 a.m.
indygreg added a subscriber: yuja.
indygreg added a comment.


  I removed the test changes from this. So we should be able to land it without causing chaos to Windows tests. It may conflict with other patches that @yuja and @mharbison72 have in flight though.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: yuja, mharbison72, mercurial-devel
phabricator - March 13, 2018, 12:36 a.m.
mharbison72 added a comment.


  Sounds good to me.  I think the only thing I have inflight is the patch with explicit flushes in the observer.  I haven't tried Yuya's series yet, because I'm not sure where it fits into the other stuff inflight.  I don't mind mopping this up after it lands.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2720

To: indygreg, #hg-reviewers
Cc: yuja, mharbison72, mercurial-devel

Patch

diff --git a/tests/test-ssh-proto.t b/tests/test-ssh-proto.t
--- a/tests/test-ssh-proto.t
+++ b/tests/test-ssh-proto.t
@@ -1118,7 +1118,8 @@ 
   >     upgrade another-token proto=irrelevant\n
   >     hello\n
   > readline
-  > readavailable
+  > ereadline
+  > ereadline
   > EOF
   using raw connection to peer
   i> write(153) -> 153:
@@ -1138,8 +1139,9 @@ 
   i>     hello\n
   o> readline() -> 1:
   o>     \n
-  e> read(-1) -> 42:
+  e> readline() -> 40:
   e>     cannot upgrade protocols multiple times\n
+  e> readline() -> 2:
   e>     -\n
 
 Malformed upgrade request line (not exactly 3 space delimited tokens)
@@ -1221,35 +1223,39 @@ 
   >     upgrade token proto=exp-ssh-v2-0001\n
   >     invalid\n
   > readline
-  > readavailable
+  > ereadline
+  > ereadline
   > EOF
   using raw connection to peer
   i> write(44) -> 44:
   i>     upgrade token proto=exp-ssh-v2-0001\n
   i>     invalid\n
   o> readline() -> 1:
   o>     \n
-  e> read(-1) -> 46:
+  e> readline() -> 44:
   e>     malformed handshake protocol: missing hello\n
+  e> readline() -> 2:
   e>     -\n
 
   $ hg debugwireproto --localssh --peer raw << EOF
   > raw
   >     upgrade token proto=exp-ssh-v2-0001\n
   >     hello\n
   >     invalid\n
   > readline
-  > readavailable
+  > ereadline
+  > ereadline
   > EOF
   using raw connection to peer
   i> write(50) -> 50:
   i>     upgrade token proto=exp-ssh-v2-0001\n
   i>     hello\n
   i>     invalid\n
   o> readline() -> 1:
   o>     \n
-  e> read(-1) -> 48:
+  e> readline() -> 46:
   e>     malformed handshake protocol: missing between\n
+  e> readline() -> 2:
   e>     -\n
 
   $ hg debugwireproto --localssh --peer raw << EOF
@@ -1259,7 +1265,8 @@ 
   >     between\n
   >     invalid\n
   > readline
-  > readavailable
+  > ereadline
+  > ereadline
   > EOF
   using raw connection to peer
   i> write(58) -> 58:
@@ -1269,8 +1276,9 @@ 
   i>     invalid\n
   o> readline() -> 1:
   o>     \n
-  e> read(-1) -> 49:
+  e> readline() -> 47:
   e>     malformed handshake protocol: missing pairs 81\n
+  e> readline() -> 2:
   e>     -\n
 
 Legacy commands are not exposed to version 2 of protocol
diff --git a/tests/test-ssh-proto-unbundle.t b/tests/test-ssh-proto-unbundle.t
--- a/tests/test-ssh-proto-unbundle.t
+++ b/tests/test-ssh-proto-unbundle.t
@@ -45,7 +45,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 115
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -93,7 +93,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 115:
+  e> read(115) -> 115:
   e>     abort: incompatible Mercurial client; bundle2 required\n
   e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
   
@@ -143,7 +143,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 115:
+  e> read(115) -> 115:
   e>     abort: incompatible Mercurial client; bundle2 required\n
   e>     (see https://www.mercurial-scm.org/wiki/IncompatibleClient)\n
 
@@ -212,7 +212,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 196
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -260,7 +260,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 196:
+  e> read(196) -> 196:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -316,7 +316,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 196:
+  e> read(196) -> 196:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -338,7 +338,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 218
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -386,7 +386,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 218:
+  e> read(218) -> 218:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -443,7 +443,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 218:
+  e> read(218) -> 218:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -466,7 +466,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 202
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -514,7 +514,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 202:
+  e> read(202) -> 202:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -570,7 +570,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 202:
+  e> read(202) -> 202:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -592,7 +592,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 206
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -640,7 +640,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 206:
+  e> read(206) -> 206:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -697,7 +697,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 206:
+  e> read(206) -> 206:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -720,7 +720,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 232
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -768,7 +768,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 232:
+  e> read(232) -> 232:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -827,7 +827,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 232:
+  e> read(232) -> 232:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -852,7 +852,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 193
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -900,7 +900,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 193:
+  e> read(193) -> 193:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -956,7 +956,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 193:
+  e> read(193) -> 193:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -978,7 +978,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 218
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1026,7 +1026,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 218:
+  e> read(218) -> 218:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1085,7 +1085,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 218:
+  e> read(218) -> 218:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1110,7 +1110,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 216
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1158,7 +1158,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 216:
+  e> read(216) -> 216:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1217,7 +1217,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 216:
+  e> read(216) -> 216:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1248,7 +1248,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 212
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1296,7 +1296,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 212:
+  e> read(212) -> 212:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1353,7 +1353,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 212:
+  e> read(212) -> 212:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1377,7 +1377,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 212
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1425,7 +1425,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 212:
+  e> read(212) -> 212:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1482,7 +1482,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 212:
+  e> read(212) -> 212:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1508,7 +1508,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 230
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1556,7 +1556,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 230:
+  e> read(230) -> 230:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1615,7 +1615,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 230:
+  e> read(230) -> 230:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1649,7 +1649,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 273
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1697,7 +1697,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 273:
+  e> read(273) -> 273:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1760,7 +1760,7 @@ 
   o> read(1) -> 1: 0
   result: 0
   remote output: 
-  e> read(-1) -> 273:
+  e> read(273) -> 273:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1789,7 +1789,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 100
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1837,7 +1837,7 @@ 
   o> read(1) -> 1: 1
   result: 1
   remote output: 
-  e> read(-1) -> 100:
+  e> read(100) -> 100:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1889,7 +1889,7 @@ 
   o> read(1) -> 1: 1
   result: 1
   remote output: 
-  e> read(-1) -> 100:
+  e> read(100) -> 100:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -1919,7 +1919,7 @@ 
   > # This is "force" in hex.
   >     heads 666f726365
   >     PUSHFILE ../initial.v1.hg
-  > readavailable
+  > eread 152
   > EOF
   testing ssh1
   creating ssh peer from handshake results
@@ -1967,7 +1967,7 @@ 
   o> read(1) -> 1: 1
   result: 1
   remote output: 
-  e> read(-1) -> 152:
+  e> read(152) -> 152:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
@@ -2023,7 +2023,7 @@ 
   o> read(1) -> 1: 1
   result: 1
   remote output: 
-  e> read(-1) -> 152:
+  e> read(152) -> 152:
   e>     adding changesets\n
   e>     adding manifests\n
   e>     adding file changes\n
diff --git a/mercurial/debugcommands.py b/mercurial/debugcommands.py
--- a/mercurial/debugcommands.py
+++ b/mercurial/debugcommands.py
@@ -2683,6 +2683,21 @@ 
 
     Read a line of output from the server. If there are multiple output
     pipes, reads only the main pipe.
+
+    ereadline
+    ---------
+
+    Like ``readline``, but read from the stderr pipe, if available.
+
+    read <X>
+    --------
+
+    ``read()`` N bytes from the server's main output pipe.
+
+    eread <X>
+    ---------
+
+    ``read()`` N bytes from the server's stderr pipe, if available.
     """
     opts = pycompat.byteskwargs(opts)
 
@@ -2831,6 +2846,14 @@ 
                 util.readpipe(stderr)
         elif action == 'readline':
             stdout.readline()
+        elif action == 'ereadline':
+            stderr.readline()
+        elif action.startswith('read '):
+            count = int(action.split(' ', 1)[1])
+            stdout.read(count)
+        elif action.startswith('eread '):
+            count = int(action.split(' ', 1)[1])
+            stderr.read(count)
         else:
             raise error.Abort(_('unknown action: %s') % action)