[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