# HG changeset patch # User timeless # Date 1454512709 0 # Node ID ab6468270b830f70b5b79dff0c4550fd8e0bfda2 # Parent 142891ab6e892bb3df64a15512400adba734ba23 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 -r 142891ab6e89 -r ab6468270b83 hgext/blackbox.py --- a/hgext/blackbox.py Wed Feb 03 18:15:18 2016 +0000 +++ b/hgext/blackbox.py Wed Feb 03 15:18:29 2016 +0000 @@ -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 -r 142891ab6e89 -r ab6468270b83 tests/test-blackbox.t --- a/tests/test-blackbox.t Wed Feb 03 18:15:18 2016 +0000 +++ b/tests/test-blackbox.t Wed Feb 03 15:18:29 2016 +0000 @@ -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 @@ -43,12 +44,13 @@ adding file changes added 1 changesets with 1 changes to 1 files (run 'hg update' to get a working copy) - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) we must not cause a failure if we cannot write to the log @@ -104,12 +106,13 @@ $ hg strip tip 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 + $ hg blackbox -l 6 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 6 (glob) extension and python hooks - use the eol extension for a pythonhook @@ -120,12 +123,13 @@ $ hg update hooked 1 files updated, 0 files merged, 0 files removed, 0 files unresolved - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) log rotation @@ -146,6 +150,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 $ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\nos.rename(".hg/blackbox.log-", ".hg/blackbox.log")\n\1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py @@ -174,6 +179,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 -r 142891ab6e89 -r ab6468270b83 tests/test-obsolete-tag-cache.t --- a/tests/test-obsolete-tag-cache.t Wed Feb 03 18:15:18 2016 +0000 +++ b/tests/test-obsolete-tag-cache.t Wed Feb 03 15:18:29 2016 +0000 @@ -67,11 +67,12 @@ 042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2 55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1 - $ hg blackbox -l 4 + $ hg blackbox -l 5 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 5 (glob) Hiding another changeset should cause the filtered hash to change @@ -86,11 +87,12 @@ 5 2942a772f72a444bef4bef13874d515f50fa27b6 2fce1eec33263d08a4d04293960fc73a555230e4 042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2 - $ hg blackbox -l 4 + $ hg blackbox -l 5 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 5 (glob) Resolving tags on an unfiltered repo writes a separate tags cache @@ -106,8 +108,9 @@ 55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1 d75775ffbc6bca1794d300f5571272879bd280da test2 - $ hg blackbox -l 4 + $ hg blackbox -l 5 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 5 (glob) diff -r 142891ab6e89 -r ab6468270b83 tests/test-tags.t --- a/tests/test-tags.t Wed Feb 03 18:15:18 2016 +0000 +++ b/tests/test-tags.t Wed Feb 03 15:18:29 2016 +0000 @@ -136,12 +136,13 @@ $ rm -f .hg/cache/tags2-visible .hg/cache/hgtagsfnodes1 $ hg identify b9154636be93 tip - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) Failure to acquire lock results in no write @@ -149,12 +150,13 @@ $ echo 'foo:1' > .hg/wlock $ hg identify b9154636be93 tip - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) $ fnodescacheexists no fnodes cache @@ -348,12 +350,13 @@ tip 5:8dbfe60eff30 bar 1:78391a272241 - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) #if unix-permissions no-root Errors writing to .hgtags fnodes cache are silently ignored @@ -368,12 +371,13 @@ tip 6:b968051b5cf3 bar 1:78391a272241 - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) $ chmod a+w .hg/cache/hgtagsfnodes1 @@ -382,12 +386,13 @@ tip 6:b968051b5cf3 bar 1:78391a272241 - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) $ f --size .hg/cache/hgtagsfnodes1 .hg/cache/hgtagsfnodes1: size=168 @@ -410,11 +415,12 @@ tip 4:0c192d7d5e6b bar 1:78391a272241 - $ hg blackbox -l 4 + $ hg blackbox -l 5 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=120 @@ -426,12 +432,13 @@ tip 5:035f65efb448 bar 1:78391a272241 - $ hg blackbox -l 5 + $ hg blackbox -l 6 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 6 (glob) $ f --size .hg/cache/hgtagsfnodes1 .hg/cache/hgtagsfnodes1: size=144