Mercurial > hg-stable

changeset 26185:e8f9dffca36f

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
blackbox: add pid to output This adds the process id to the line header for the blackbox output. This is useful for distinguishing processes when using the blackbox on a server and many processes are writing to the blackbox at once.
author Durham Goode <durham@fb.com>
date Mon, 07 Sep 2015 11:31:44 -0700
parents 327d09f0b5d4
children eb2187ebdf8a
files hgext/blackbox.py tests/test-blackbox.t tests/test-obsolete-tag-cache.t tests/test-tags.t
diffstat 4 files changed, 66 insertions(+), 64 deletions(-) [+]
line wrap: on
line diff
--- a/hgext/blackbox.py	Mon Sep 07 17:08:35 2015 -0700
+++ b/hgext/blackbox.py	Mon Sep 07 11:31:44 2015 -0700
@@ -107,9 +107,11 @@
             if blackbox:
                 date = util.datestr(None, '%Y/%m/%d %H:%M:%S')
                 user = util.getuser()
+                pid = str(os.getpid())
                 formattedmsg = msg[0] % msg[1:]
                 try:
-                    blackbox.write('%s %s> %s' % (date, user, formattedmsg))
+                    blackbox.write('%s %s (%s)> %s' %
+                                   (date, user, pid, formattedmsg))
                 except IOError as err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
--- a/tests/test-blackbox.t	Mon Sep 07 17:08:35 2015 -0700
+++ b/tests/test-blackbox.t	Mon Sep 07 11:31:44 2015 -0700
@@ -13,8 +13,8 @@
   $ echo a > a
   $ hg add a
   $ hg blackbox
-  1970/01/01 00:00:00 bob> add a
-  1970/01/01 00:00:00 bob> add a exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (*)> add a (glob)
+  1970/01/01 00:00:00 bob (*)> add a exited 0 after * seconds (glob)
 
 incoming change tracking
 
@@ -44,11 +44,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
-  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
-  1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62
-  1970/01/01 00:00:00 bob> pull exited 0 after * seconds (glob)
+  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)
 
 we must not cause a failure if we cannot write to the log
 
@@ -106,11 +106,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
-  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
-  1970/01/01 00:00:00 bob> strip tip exited 0 after * seconds (glob)
+  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)
 
 extension and python hooks - use the eol extension for a pythonhook
 
@@ -122,11 +122,11 @@
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   hooked
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob> update
-  1970/01/01 00:00:00 bob> writing .hg/cache/tags2-visible with 0 tags
-  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 (*)> 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)
 
 log rotation
 
--- a/tests/test-obsolete-tag-cache.t	Mon Sep 07 17:08:35 2015 -0700
+++ b/tests/test-obsolete-tag-cache.t	Mon Sep 07 11:31:44 2015 -0700
@@ -68,10 +68,10 @@
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
 
   $ hg blackbox -l 4
-  1970/01/01 00:00:00 bob> tags
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
 
 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
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
 
 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
-  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
-  1970/01/01 00:00:00 bob> --hidden tags exited 0 after * seconds (glob)
+  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)
--- a/tests/test-tags.t	Mon Sep 07 17:08:35 2015 -0700
+++ b/tests/test-tags.t	Mon Sep 07 11:31:44 2015 -0700
@@ -137,11 +137,11 @@
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob> identify
-  1970/01/01 00:00:00 bob> writing 48 bytes to cache/hgtagsfnodes1
-  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
-  1970/01/01 00:00:00 bob> identify exited 0 after ?.?? seconds (glob)
+  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)
 
 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
-  1970/01/01 00:00:00 bob> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired
-  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
-  1970/01/01 00:00:00 bob> identify exited 0 after * seconds (glob)
+  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)
 
   $ fnodescacheexists
   no fnodes cache
@@ -349,11 +349,11 @@
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob> tags
-  1970/01/01 00:00:00 bob> writing 24 bytes to cache/hgtagsfnodes1
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
 
 #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
-  1970/01/01 00:00:00 bob> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1'
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
 
   $ 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
-  1970/01/01 00:00:00 bob> writing 24 bytes to cache/hgtagsfnodes1
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
 
   $ 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
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (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)
 
   $ 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
-  1970/01/01 00:00:00 bob> writing 24 bytes to cache/hgtagsfnodes1
-  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
-  1970/01/01 00:00:00 bob> tags exited 0 after * seconds (glob)
+  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)
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144