[Bug 4336] New: stderr from ssh not flushed after command

mercurial-bugs at selenic.com mercurial-bugs at selenic.com
Wed Aug 13 22:48:39 CDT 2014


http://bz.selenic.com/show_bug.cgi?id=4336

          Priority: normal
            Bug ID: 4336
                CC: mercurial-devel at selenic.com
          Assignee: bugzilla at selenic.com
           Summary: stderr from ssh not flushed after command
          Severity: bug
    Classification: Unclassified
                OS: Linux
          Reporter: gregory.szorc at gmail.com
          Hardware: PC
            Status: UNCONFIRMED
           Version: 3.1
         Component: Mercurial
           Product: Mercurial

I have an extension that's piggybacking on top of `hg push`. It invokes a
separate wire protocol command (pushreview) after the unbundle, listkey, and
pushkey commands that constitute a built-in push. As part of this command, it
does some ui.write()ing.

What I'm seeing is out-of-order printing of messages between OS X and Linux. OS
X does the right thing. However, on Linux, I'm seeing the stderr output (the
"remote:" prefixed messages sent in return from the unbundle command) printed
*after* my command output.

On OS X:

$ hg push --debug
  pushing to ssh://user@dummy/$TESTTMP/server
  running python
"/Users/gps/src/hgcustom/version-control-tools/pylib/mercurial-support/dummyssh"
user at dummy 'hg -R $TESTTMP/server serve --stdio'
  sending hello command
  sending between command
  remote: 169
  remote: capabilities: lookup changegroupsubset branchmap pushkey known
getbundle unbundlehash batch stream unbundle=HG10GZ,HG10BZ,HG10UN
httpheader=1024 reviewboard pullreviews
  remote: 1
  query 1; heads
  sending batch command
  searching for changes
  all remote heads known locally
  preparing listkeys for "phases"
  sending listkeys command
  2 changesets found
  list of changesets:
  775aa9c61e2bacff3f20f2e7fef54062038c8328
  c90aa97490e2048e34287d62f4a98f47acea4bac
  sending unbundle command
  bundling: 1/2 changesets (50.00%)
  bundling: 2/2 changesets (100.00%)
  bundling: 1/2 manifests (50.00%)
  bundling: 2/2 manifests (100.00%)
  bundling: foo1 1/2 files (50.00%)
  bundling: foo2 2/2 files (100.00%)
  remote: adding changesets
  remote: adding manifests
  remote: adding file changes
  remote: added 2 changesets with 2 changes to 2 files
  preparing listkeys for "phases"
  sending listkeys command
  preparing pushkey for "phases:274cf95ba54c5a10b258b1d05a1be63e312e3573"
  sending pushkey command
  try to push obsolete markers to remote
  checking for updated bookmarks
  preparing listkeys for "bookmarks"
  sending listkeys command
  submitting 2 changesets for review
  sending pushreview command

  changeset:  1:775aa9c61e2b
  summary:    Bug 123 - Foo 1
  review:     http://localhost:$HGPORT1/r/2 (pending)

  changeset:  2:c90aa97490e2
  summary:    Bug 123 - Foo 2
  review:     http://localhost:$HGPORT1/r/3 (pending)

  review id:  bz://123/mynick
  review url: http://localhost:$HGPORT1/r/1 (pending)

However on OS X I get the "remote:" prefixed lines later on:

$ hg push --debug
  pushing to ssh://user@dummy/$TESTTMP/server
  running python "/version-control-tools/pylib/mercurial-support/dummyssh"
user at dummy 'hg -R $TESTTMP/server serve --stdio'
  sending hello command
  sending between command
  remote: 169
  remote: capabilities: lookup changegroupsubset branchmap pushkey known
getbundle unbundlehash batch stream unbundle=HG10GZ,HG10BZ,HG10UN
httpheader=1024 reviewboard pullreviews
  remote: 1
  query 1; heads
  sending batch command
  searching for changes
  all remote heads known locally
  2 changesets found
  list of changesets:
  775aa9c61e2bacff3f20f2e7fef54062038c8328
  c90aa97490e2048e34287d62f4a98f47acea4bac
  sending unbundle command
  bundling: 1/2 changesets (50.00%)
  bundling: 2/2 changesets (100.00%)
  bundling: 1/2 manifests (50.00%)
  bundling: 2/2 manifests (100.00%)
  bundling: foo1 1/2 files (50.00%)
  bundling: foo2 2/2 files (100.00%)
  preparing listkeys for "phases"
  sending listkeys command
  preparing pushkey for "phases:274cf95ba54c5a10b258b1d05a1be63e312e3573"
  sending pushkey command
  try to push obsolete markers to remote
  checking for updated bookmarks
  preparing listkeys for "bookmarks"
  sending listkeys command
  submitting 2 changesets for review
  sending pushreview command

  changeset:  1:775aa9c61e2b
  summary:    Bug 123 - Foo 1
  review:     http://localhost:$HGPORT1/r/2 (pending)

  changeset:  2:c90aa97490e2
  summary:    Bug 123 - Foo 2
  review:     http://localhost:$HGPORT1/r/3 (pending)

  review id:  bz://123/mynick
  review url: http://localhost:$HGPORT1/r/1 (pending)
  remote: adding changesets
  remote: adding manifests
  remote: adding file changes
  remote: added 2 changesets with 2 changes to 2 files

It seems like the SSH process's stderr stream isn't being flushed or read after
each command.

When I insert breakpoints, I discover that the lines from unbundle ("adding
changesets" etc) aren't read until sshpeer.cleanup() is called as part of
sshpeer.__del__(). This seems to reliably occur after commands.push() has
completed.

I've tried inserting remote.readerr() throughout sshpeer and the push code to
try to get these lines to display. But they never show up.

I've tried inserting flushes of stderr in sshserver. But again, the data never
seems to get to the other side of the pipe.

I thought that maybe the pipe was buffering things. I changed the
implementation of util.Popen4() so bufsize=0. No difference.

I thought that maybe my dummyssh Python script was buffering. But stderr is
unbuffered in Python.

At this point, I /think/ I've tried all the normal approaches to debugging I/O
problems like this and have nothing to show for it. I'm baffled as to why OS X
and Linux have different behavior. Usually their POSIX I/O behaviors are very
similar. Perhaps this is a CPython oddity. I'm running Python 2.7.6 on Ubuntu
14.04 and 2.7.8 on OS X 10.9.4.

I'll keep trying to find the golden combination of flushes and polling to
figure this out...

-- 
You are receiving this mail because:
You are on the CC list for the bug.


More information about the Mercurial-devel mailing list