Patchwork [1,of,3] test-ssh: add some flush() to make output deterministic

login
register
mail settings
Submitter Yuya Nishihara
Date May 7, 2018, 1:11 p.m.
Message ID <2be95f3cc4f8a4b59f7c.1525698682@mimosa>
Download mbox | patch
Permalink /patch/31299/
State Accepted
Headers show

Comments

Yuya Nishihara - May 7, 2018, 1:11 p.m.
# HG changeset patch
# User Yuya Nishihara <yuya@tcha.org>
# Date 1521963557 -32400
#      Sun Mar 25 16:39:17 2018 +0900
# Node ID 2be95f3cc4f8a4b59f7c50af093ea033d1d09c5e
# Parent  04ceb267271a45ae08352d76a9e91f8037ce53e7
test-ssh: add some flush() to make output deterministic

We shouldn't rely on buffering mode/state of file handles.
Gregory Szorc - May 11, 2018, 9:08 p.m.
On Mon, May 7, 2018 at 6:11 AM, Yuya Nishihara <yuya@tcha.org> wrote:

> # HG changeset patch
> # User Yuya Nishihara <yuya@tcha.org>
> # Date 1521963557 -32400
> #      Sun Mar 25 16:39:17 2018 +0900
> # Node ID 2be95f3cc4f8a4b59f7c50af093ea033d1d09c5e
> # Parent  04ceb267271a45ae08352d76a9e91f8037ce53e7
> test-ssh: add some flush() to make output deterministic
>
> We shouldn't rely on buffering mode/state of file handles.
>

I'm accepting this and understand why we need a flush() to make behavior
deterministic.

However, I think we should consider adding the flush() to the code that
invokes the hooks - not the hooks themselves. In theory, hook output is
streamed to clients. So if we want to ensure hook output is seen by clients
soon after it is generated, I think we should be flushing output
automatically when invoking hooks. In the context of wire protocol
requests, perhaps we should always be making the ui object unbuffered?


>
> 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
> @@ -161,10 +161,12 @@ Test pushing to a server that has a pret
>    > import sys
>    > def hook1line(ui, repo, **kwargs):
>    >     ui.write(b'ui.write 1 line\n')
> +  >     ui.flush()
>    >     return 1
>    > def hook2lines(ui, repo, **kwargs):
>    >     ui.write(b'ui.write 2 lines 1\n')
>    >     ui.write(b'ui.write 2 lines 2\n')
> +  >     ui.flush()
>    >     return 1
>    > def hook1lineflush(ui, repo, **kwargs):
>    >     ui.write(b'ui.write 1 line flush\n')
> @@ -181,21 +183,31 @@ Test pushing to a server that has a pret
>    >     ui.write_err(b'ui.write_err 1\n')
>    >     ui.write(b'ui.write 2\n')
>    >     ui.write_err(b'ui.write_err 2\n')
> +  >     ui.flush()
>    >     return 1
>    > def hookprintstdout(ui, repo, **kwargs):
>    >     print('printed line')
> +  >     sys.stdout.flush()
>    >     return 1
>    > def hookprintandwrite(ui, repo, **kwargs):
>    >     print('print 1')
> +  >     sys.stdout.flush()
>    >     ui.write(b'ui.write 1\n')
> +  >     ui.flush()
>    >     print('print 2')
> +  >     sys.stdout.flush()
>    >     ui.write(b'ui.write 2\n')
> +  >     ui.flush()
>    >     return 1
>    > def hookprintstderrandstdout(ui, repo, **kwargs):
>    >     print('stdout 1')
> +  >     sys.stdout.flush()
>    >     print('stderr 1', file=sys.stderr)
> +  >     sys.stderr.flush()
>    >     print('stdout 2')
> +  >     sys.stdout.flush()
>    >     print('stderr 2', file=sys.stderr)
> +  >     sys.stderr.flush()
>    >     return 1
>    > EOF
>
> @@ -1046,10 +1058,10 @@ Mixed print() and ui.write() are both ca
>    e>     adding manifests\n
>    e>     adding file changes\n
>    e>     added 1 changesets with 1 changes to 1 files\n
> +  e>     print 1\n
>    e>     ui.write 1\n
> +  e>     print 2\n
>    e>     ui.write 2\n
> -  e>     print 1\n
> -  e>     print 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.fail hook failed\n
> @@ -1106,10 +1118,10 @@ Mixed print() and ui.write() are both ca
>    e>     adding manifests\n
>    e>     adding file changes\n
>    e>     added 1 changesets with 1 changes to 1 files\n
> +  e>     print 1\n
>    e>     ui.write 1\n
> +  e>     print 2\n
>    e>     ui.write 2\n
> -  e>     print 1\n
> -  e>     print 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.fail hook failed\n
> @@ -1180,10 +1192,10 @@ print() to stdout and stderr both get ca
>    e>     adding manifests\n
>    e>     adding file changes\n
>    e>     added 1 changesets with 1 changes to 1 files\n
> +  e>     stdout 1\n
>    e>     stderr 1\n
> +  e>     stdout 2\n
>    e>     stderr 2\n
> -  e>     stdout 1\n
> -  e>     stdout 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.fail hook failed\n
> @@ -1240,10 +1252,10 @@ print() to stdout and stderr both get ca
>    e>     adding manifests\n
>    e>     adding file changes\n
>    e>     added 1 changesets with 1 changes to 1 files\n
> +  e>     stdout 1\n
>    e>     stderr 1\n
> +  e>     stdout 2\n
>    e>     stderr 2\n
> -  e>     stdout 1\n
> -  e>     stdout 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.fail hook failed\n
> @@ -1731,10 +1743,10 @@ Shell and Python hooks writing to stdout
>    e>     shell stderr 1\n
>    e>     shell stdout 2\n
>    e>     shell stderr 2\n
> +  e>     stdout 1\n
>    e>     stderr 1\n
> +  e>     stdout 2\n
>    e>     stderr 2\n
> -  e>     stdout 1\n
> -  e>     stdout 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.b hook failed\n
> @@ -1795,10 +1807,10 @@ Shell and Python hooks writing to stdout
>    e>     shell stderr 1\n
>    e>     shell stdout 2\n
>    e>     shell stderr 2\n
> +  e>     stdout 1\n
>    e>     stderr 1\n
> +  e>     stdout 2\n
>    e>     stderr 2\n
> -  e>     stdout 1\n
> -  e>     stdout 2\n
>    e>     transaction abort!\n
>    e>     rollback completed\n
>    e>     abort: pretxnchangegroup.b hook failed\n
> diff --git a/tests/test-ssh.t b/tests/test-ssh.t
> --- a/tests/test-ssh.t
> +++ b/tests/test-ssh.t
> @@ -272,12 +272,14 @@ a bad, evil hook that prints to stdout
>    $ cat <<EOF > $TESTTMP/badhook
>    > import sys
>    > sys.stdout.write("KABOOM\n")
> +  > sys.stdout.flush()
>    > EOF
>
>    $ cat <<EOF > $TESTTMP/badpyhook.py
>    > import sys
>    > def hook(ui, repo, hooktype, **kwargs):
>    >     sys.stdout.write("KABOOM IN PROCESS\n")
> +  >     sys.stdout.flush()
>    > EOF
>
>    $ cat <<EOF >> ../remote/.hg/hgrc
> @@ -456,6 +458,7 @@ stderr from remote commands should be pr
>    > def wrappedpush(orig, repo, *args, **kwargs):
>    >     res = orig(repo, *args, **kwargs)
>    >     repo.ui.write('local stdout\n')
> +  >     repo.ui.flush()
>    >     return res
>    >
>    > def extsetup(ui):
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
>
Yuya Nishihara - May 12, 2018, 1:42 a.m.
On Fri, 11 May 2018 14:08:18 -0700, Gregory Szorc wrote:
> On Mon, May 7, 2018 at 6:11 AM, Yuya Nishihara <yuya@tcha.org> wrote:
> 
> > # HG changeset patch
> > # User Yuya Nishihara <yuya@tcha.org>
> > # Date 1521963557 -32400
> > #      Sun Mar 25 16:39:17 2018 +0900
> > # Node ID 2be95f3cc4f8a4b59f7c50af093ea033d1d09c5e
> > # Parent  04ceb267271a45ae08352d76a9e91f8037ce53e7
> > test-ssh: add some flush() to make output deterministic
> >
> > We shouldn't rely on buffering mode/state of file handles.
> >
> 
> I'm accepting this and understand why we need a flush() to make behavior
> deterministic.

Basically I inserted flush() where crossing underlying file objects, e.g.
between print() and ui.write(). Some of the last ui.flush() might be
unnecessary. OTOH, writing to sys.std* in in-process hooks is API violation,
so we wouldn't have to care seriously about that.

> However, I think we should consider adding the flush() to the code that
> invokes the hooks - not the hooks themselves. In theory, hook output is
> streamed to clients. So if we want to ensure hook output is seen by clients
> soon after it is generated, I think we should be flushing output
> automatically when invoking hooks. In the context of wire protocol
> requests, perhaps we should always be making the ui object unbuffered?

Maybe we can simply do ui.flush() at the end of runhooks()? It wouldn't be
easy to change the buffering mode of open files.
Gregory Szorc - May 12, 2018, 3:35 a.m.
On Fri, May 11, 2018 at 6:42 PM, Yuya Nishihara <yuya@tcha.org> wrote:

> On Fri, 11 May 2018 14:08:18 -0700, Gregory Szorc wrote:
> > On Mon, May 7, 2018 at 6:11 AM, Yuya Nishihara <yuya@tcha.org> wrote:
> >
> > > # HG changeset patch
> > > # User Yuya Nishihara <yuya@tcha.org>
> > > # Date 1521963557 -32400
> > > #      Sun Mar 25 16:39:17 2018 +0900
> > > # Node ID 2be95f3cc4f8a4b59f7c50af093ea033d1d09c5e
> > > # Parent  04ceb267271a45ae08352d76a9e91f8037ce53e7
> > > test-ssh: add some flush() to make output deterministic
> > >
> > > We shouldn't rely on buffering mode/state of file handles.
> > >
> >
> > I'm accepting this and understand why we need a flush() to make behavior
> > deterministic.
>
> Basically I inserted flush() where crossing underlying file objects, e.g.
> between print() and ui.write(). Some of the last ui.flush() might be
> unnecessary. OTOH, writing to sys.std* in in-process hooks is API
> violation,
> so we wouldn't have to care seriously about that.
>

IIRC we only recently made print() and sys.std* writing an API violation.
Or maybe it always was and we happened to go out of our way to make it work.

For the record, the I/O tests in this file (which I wrote) were to
basically tease out behavior so refactoring would uncover changes. If we
want to change behavior so e.g. sys.stdout() writes aren't intercepted and
treated as hook output, I'm totally fine with that. We may want to issue a
deprecation warning for a cycle first though. Or wrap sys.stdout during
hook evaluation so any writes result in a warning message being written to
the hook output.

Alternatively, we could more strongly tie sys.stdout to ui.fout during hook
evaluation so we're *not* crossing file objects. But the code here is a bit
gnarly. I'm not sure if I trust any more hacks in this area. I'd rather
force the use of ui.write() for hook output.


>
> > However, I think we should consider adding the flush() to the code that
> > invokes the hooks - not the hooks themselves. In theory, hook output is
> > streamed to clients. So if we want to ensure hook output is seen by
> clients
> > soon after it is generated, I think we should be flushing output
> > automatically when invoking hooks. In the context of wire protocol
> > requests, perhaps we should always be making the ui object unbuffered?
>
> Maybe we can simply do ui.flush() at the end of runhooks()? It wouldn't be
> easy to change the buffering mode of open files.
>

That seems like a reasonable change. Or we could wrap ui.write() so it
automatically does a .flush().
Yuya Nishihara - May 13, 2018, 2:25 a.m.
On Fri, 11 May 2018 20:35:03 -0700, Gregory Szorc wrote:
> On Fri, May 11, 2018 at 6:42 PM, Yuya Nishihara <yuya@tcha.org> wrote:
> 
> > On Fri, 11 May 2018 14:08:18 -0700, Gregory Szorc wrote:
> > > On Mon, May 7, 2018 at 6:11 AM, Yuya Nishihara <yuya@tcha.org> wrote:
> > >
> > > > # HG changeset patch
> > > > # User Yuya Nishihara <yuya@tcha.org>
> > > > # Date 1521963557 -32400
> > > > #      Sun Mar 25 16:39:17 2018 +0900
> > > > # Node ID 2be95f3cc4f8a4b59f7c50af093ea033d1d09c5e
> > > > # Parent  04ceb267271a45ae08352d76a9e91f8037ce53e7
> > > > test-ssh: add some flush() to make output deterministic
> > > >
> > > > We shouldn't rely on buffering mode/state of file handles.
> > > >
> > >
> > > I'm accepting this and understand why we need a flush() to make behavior
> > > deterministic.
> >
> > Basically I inserted flush() where crossing underlying file objects, e.g.
> > between print() and ui.write(). Some of the last ui.flush() might be
> > unnecessary. OTOH, writing to sys.std* in in-process hooks is API
> > violation,
> > so we wouldn't have to care seriously about that.
> 
> IIRC we only recently made print() and sys.std* writing an API violation.
> Or maybe it always was and we happened to go out of our way to make it work.
> 
> For the record, the I/O tests in this file (which I wrote) were to
> basically tease out behavior so refactoring would uncover changes. If we
> want to change behavior so e.g. sys.stdout() writes aren't intercepted and
> treated as hook output, I'm totally fine with that. We may want to issue a
> deprecation warning for a cycle first though. Or wrap sys.stdout during
> hook evaluation so any writes result in a warning message being written to
> the hook output.
> 
> Alternatively, we could more strongly tie sys.stdout to ui.fout during hook
> evaluation so we're *not* crossing file objects. But the code here is a bit
> gnarly. I'm not sure if I trust any more hacks in this area. I'd rather
> force the use of ui.write() for hook output.

IMHO, the current best-effort way is good enough. Any in-process hook outputs
are delivered to client even if print() is used instead of ui.write(). We just
don't guarantee print()s and ui.write()s are serialized in order.

Patch

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
@@ -161,10 +161,12 @@  Test pushing to a server that has a pret
   > import sys
   > def hook1line(ui, repo, **kwargs):
   >     ui.write(b'ui.write 1 line\n')
+  >     ui.flush()
   >     return 1
   > def hook2lines(ui, repo, **kwargs):
   >     ui.write(b'ui.write 2 lines 1\n')
   >     ui.write(b'ui.write 2 lines 2\n')
+  >     ui.flush()
   >     return 1
   > def hook1lineflush(ui, repo, **kwargs):
   >     ui.write(b'ui.write 1 line flush\n')
@@ -181,21 +183,31 @@  Test pushing to a server that has a pret
   >     ui.write_err(b'ui.write_err 1\n')
   >     ui.write(b'ui.write 2\n')
   >     ui.write_err(b'ui.write_err 2\n')
+  >     ui.flush()
   >     return 1
   > def hookprintstdout(ui, repo, **kwargs):
   >     print('printed line')
+  >     sys.stdout.flush()
   >     return 1
   > def hookprintandwrite(ui, repo, **kwargs):
   >     print('print 1')
+  >     sys.stdout.flush()
   >     ui.write(b'ui.write 1\n')
+  >     ui.flush()
   >     print('print 2')
+  >     sys.stdout.flush()
   >     ui.write(b'ui.write 2\n')
+  >     ui.flush()
   >     return 1
   > def hookprintstderrandstdout(ui, repo, **kwargs):
   >     print('stdout 1')
+  >     sys.stdout.flush()
   >     print('stderr 1', file=sys.stderr)
+  >     sys.stderr.flush()
   >     print('stdout 2')
+  >     sys.stdout.flush()
   >     print('stderr 2', file=sys.stderr)
+  >     sys.stderr.flush()
   >     return 1
   > EOF
 
@@ -1046,10 +1058,10 @@  Mixed print() and ui.write() are both ca
   e>     adding manifests\n
   e>     adding file changes\n
   e>     added 1 changesets with 1 changes to 1 files\n
+  e>     print 1\n
   e>     ui.write 1\n
+  e>     print 2\n
   e>     ui.write 2\n
-  e>     print 1\n
-  e>     print 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.fail hook failed\n
@@ -1106,10 +1118,10 @@  Mixed print() and ui.write() are both ca
   e>     adding manifests\n
   e>     adding file changes\n
   e>     added 1 changesets with 1 changes to 1 files\n
+  e>     print 1\n
   e>     ui.write 1\n
+  e>     print 2\n
   e>     ui.write 2\n
-  e>     print 1\n
-  e>     print 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.fail hook failed\n
@@ -1180,10 +1192,10 @@  print() to stdout and stderr both get ca
   e>     adding manifests\n
   e>     adding file changes\n
   e>     added 1 changesets with 1 changes to 1 files\n
+  e>     stdout 1\n
   e>     stderr 1\n
+  e>     stdout 2\n
   e>     stderr 2\n
-  e>     stdout 1\n
-  e>     stdout 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.fail hook failed\n
@@ -1240,10 +1252,10 @@  print() to stdout and stderr both get ca
   e>     adding manifests\n
   e>     adding file changes\n
   e>     added 1 changesets with 1 changes to 1 files\n
+  e>     stdout 1\n
   e>     stderr 1\n
+  e>     stdout 2\n
   e>     stderr 2\n
-  e>     stdout 1\n
-  e>     stdout 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.fail hook failed\n
@@ -1731,10 +1743,10 @@  Shell and Python hooks writing to stdout
   e>     shell stderr 1\n
   e>     shell stdout 2\n
   e>     shell stderr 2\n
+  e>     stdout 1\n
   e>     stderr 1\n
+  e>     stdout 2\n
   e>     stderr 2\n
-  e>     stdout 1\n
-  e>     stdout 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.b hook failed\n
@@ -1795,10 +1807,10 @@  Shell and Python hooks writing to stdout
   e>     shell stderr 1\n
   e>     shell stdout 2\n
   e>     shell stderr 2\n
+  e>     stdout 1\n
   e>     stderr 1\n
+  e>     stdout 2\n
   e>     stderr 2\n
-  e>     stdout 1\n
-  e>     stdout 2\n
   e>     transaction abort!\n
   e>     rollback completed\n
   e>     abort: pretxnchangegroup.b hook failed\n
diff --git a/tests/test-ssh.t b/tests/test-ssh.t
--- a/tests/test-ssh.t
+++ b/tests/test-ssh.t
@@ -272,12 +272,14 @@  a bad, evil hook that prints to stdout
   $ cat <<EOF > $TESTTMP/badhook
   > import sys
   > sys.stdout.write("KABOOM\n")
+  > sys.stdout.flush()
   > EOF
 
   $ cat <<EOF > $TESTTMP/badpyhook.py
   > import sys
   > def hook(ui, repo, hooktype, **kwargs):
   >     sys.stdout.write("KABOOM IN PROCESS\n")
+  >     sys.stdout.flush()
   > EOF
 
   $ cat <<EOF >> ../remote/.hg/hgrc
@@ -456,6 +458,7 @@  stderr from remote commands should be pr
   > def wrappedpush(orig, repo, *args, **kwargs):
   >     res = orig(repo, *args, **kwargs)
   >     repo.ui.write('local stdout\n')
+  >     repo.ui.flush()
   >     return res
   > 
   > def extsetup(ui):