Patchwork [4,of,7] blackbox: flush output file descriptor

login
register
mail settings
Submitter timeless@mozdev.org
Date Feb. 3, 2016, 9:40 p.m.
Message ID <7d55ab6425b5b8836560.1454535646@waste.org>
Download mbox | patch
Permalink /patch/12964/
State Superseded
Commit ab6468270b830f70b5b79dff0c4550fd8e0bfda2
Delegated to: Yuya Nishihara
Headers show

Comments

timeless@mozdev.org - Feb. 3, 2016, 9:40 p.m.
# HG changeset patch
# User timeless <timeless@mozdev.org>
# Date 1454512709 0
#      Wed Feb 03 15:18:29 2016 +0000
# Node ID 7d55ab6425b5b8836560e0de40e20e47c762a0f9
# Parent  552c58b545c24037fcf09d4ca39c65628bd1c654
blackbox: flush output file descriptor

Without this, when there are multiple ui views, each blackbox
will have its own file handle, and the logging will be in
a really bad order.

Also, because of the way blackbox works, it never closes its
file handles, which means the last output before exit is
often lost.
Yuya Nishihara - Feb. 7, 2016, 2:40 p.m.
On Wed, 03 Feb 2016 15:40:46 -0600, timeless wrote:
> # HG changeset patch
> # User timeless <timeless@mozdev.org>
> # Date 1454512709 0
> #      Wed Feb 03 15:18:29 2016 +0000
> # Node ID 7d55ab6425b5b8836560e0de40e20e47c762a0f9
> # Parent  552c58b545c24037fcf09d4ca39c65628bd1c654
> blackbox: flush output file descriptor
> 
> Without this, when there are multiple ui views, each blackbox
> will have its own file handle, and the logging will be in
> a really bad order.
> 
> Also, because of the way blackbox works, it never closes its
> file handles, which means the last output before exit is
> often lost.
> 
> diff --git a/hgext/blackbox.py b/hgext/blackbox.py
> --- a/hgext/blackbox.py
> +++ b/hgext/blackbox.py
> @@ -112,6 +112,7 @@
>                  try:
>                      blackbox.write('%s %s (%s)> %s' %
>                                     (date, user, pid, formattedmsg))
> +                    blackbox.flush()

This looks good.

> @@ -107,11 +108,11 @@
>    0 files updated, 0 files merged, 1 files removed, 0 files unresolved
>    saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
>    $ hg blackbox -l 5
> -  1970/01/01 00:00:00 bob (*)> strip tip (glob)
>    1970/01/01 00:00:00 bob (*)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
>    1970/01/01 00:00:00 bob (*)> updated base branch cache in * seconds (glob)
>    1970/01/01 00:00:00 bob (*)> wrote base branch cache with 1 labels and 2 nodes (glob)
>    1970/01/01 00:00:00 bob (*)> strip tip exited 0 after * seconds (glob)
> +  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)

Can you update tests to include the first line? "-l 5" here was chosen to
show the log of "strip tip".

Patch

diff --git a/hgext/blackbox.py b/hgext/blackbox.py
--- a/hgext/blackbox.py
+++ b/hgext/blackbox.py
@@ -112,6 +112,7 @@ 
                 try:
                     blackbox.write('%s %s (%s)> %s' %
                                    (date, user, pid, formattedmsg))
+                    blackbox.flush()
                 except IOError as err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -15,6 +15,7 @@ 
   $ hg blackbox
   1970/01/01 00:00:00 bob (*)> add a (glob)
   1970/01/01 00:00:00 bob (*)> add a exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox (glob)
 
 incoming change tracking
 
@@ -44,11 +45,11 @@ 
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> pull (glob)
   1970/01/01 00:00:00 bob (*)> updated served branch cache in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
   1970/01/01 00:00:00 bob (*)> 1 incoming changes - new heads: d02f48003e62 (glob)
   1970/01/01 00:00:00 bob (*)> pull exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
 we must not cause a failure if we cannot write to the log
 
@@ -107,11 +108,11 @@ 
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> strip tip (glob)
   1970/01/01 00:00:00 bob (*)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
   1970/01/01 00:00:00 bob (*)> updated base branch cache in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> wrote base branch cache with 1 labels and 2 nodes (glob)
   1970/01/01 00:00:00 bob (*)> strip tip exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
 extension and python hooks - use the eol extension for a pythonhook
 
@@ -123,11 +124,11 @@ 
   hooked
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> update (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
   1970/01/01 00:00:00 bob (*)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> exthook-update: echo hooked finished in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> update exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
 log rotation
 
@@ -148,6 +149,7 @@ 
   $ hg init blackboxtest3
   $ cd blackboxtest3
   $ hg blackbox
+  1970/01/01 00:00:00 bob (*)> blackbox (glob)
   $ mv .hg/blackbox.log .hg/blackbox.log-
   $ mkdir .hg/blackbox.log
   $ perl -pne 'if (/test1/) {s/^/#/; next} if (/commit2/) { print qq{os.rmdir(".hg/blackbox.log")\nos.rename(".hg/blackbox.log-", ".hg/blackbox.log")\n} }' $TESTDIR/test-dispatch.py > ../test-dispatch.py
@@ -176,6 +178,7 @@ 
   $ hg blackbox
   1970/01/01 00:00:00 bob (*)> blackbox (glob)
   1970/01/01 00:00:00 bob (*)> blackbox exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox (glob)
 
 cleanup
   $ cd ..
diff --git a/tests/test-obsolete-tag-cache.t b/tests/test-obsolete-tag-cache.t
--- a/tests/test-obsolete-tag-cache.t
+++ b/tests/test-obsolete-tag-cache.t
@@ -68,10 +68,10 @@ 
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
 
   $ hg blackbox -l 4
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 2 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 4 (glob)
 
 Hiding another changeset should cause the filtered hash to change
 
@@ -87,10 +87,10 @@ 
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
 
   $ hg blackbox -l 4
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> 1/1 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 4 (glob)
 
 Resolving tags on an unfiltered repo writes a separate tags cache
 
@@ -107,7 +107,7 @@ 
   d75775ffbc6bca1794d300f5571272879bd280da test2
 
   $ hg blackbox -l 4
-  1970/01/01 00:00:00 bob (*)> --hidden tags (glob)
   1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2 with 3 tags (glob)
   1970/01/01 00:00:00 bob (*)> --hidden tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 4 (glob)
diff --git a/tests/test-tags.t b/tests/test-tags.t
--- a/tests/test-tags.t
+++ b/tests/test-tags.t
@@ -137,11 +137,11 @@ 
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> identify (glob)
   1970/01/01 00:00:00 bob (*)> writing 48 bytes to cache/hgtagsfnodes1 (glob)
   1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> identify exited 0 after ?.?? seconds (glob)
+  1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
 Failure to acquire lock results in no write
 
@@ -150,11 +150,11 @@ 
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> identify (glob)
   1970/01/01 00:00:00 bob (*)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired (glob)
   1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
   $ fnodescacheexists
   no fnodes cache
@@ -349,11 +349,11 @@ 
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
   1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
 #if unix-permissions no-root
 Errors writing to .hgtags fnodes cache are silently ignored
@@ -369,11 +369,11 @@ 
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1' (glob)
   1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
   $ chmod a+w .hg/cache/hgtagsfnodes1
 
@@ -383,11 +383,11 @@ 
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
   1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=168
@@ -411,10 +411,10 @@ 
   bar                                1:78391a272241
 
   $ hg blackbox -l 4
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
   1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 4 (glob)
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=120
@@ -427,11 +427,11 @@ 
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
   1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
   1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
   1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
   1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144