Patchwork blackbox: add pid to output

# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1441650704 25200
#      Mon Sep 07 11:31:44 2015 -0700
# Node ID 9a9e7437460958362bf2637f145184a31332e78d
# Parent  32124f63ab48a9fbc1f5da5c0439a82de48e35c6
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.

On Mon, Sep 07, 2015 at 12:10:53PM -0700, Durham Goode wrote:
> # HG changeset patch
> # User Durham Goode <durham@fb.com>
> # Date 1441650704 25200
> #      Mon Sep 07 11:31:44 2015 -0700
> # Node ID 9a9e7437460958362bf2637f145184a31332e78d
> # Parent  32124f63ab48a9fbc1f5da5c0439a82de48e35c6
> blackbox: add pid to output

good idea, queued

>
> 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.
>
> diff --git a/hgext/blackbox.py b/hgext/blackbox.py
> --- a/hgext/blackbox.py
> +++ b/hgext/blackbox.py
> @@ -107,9 +107,11 @@ def wrapui(ui):
>              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)
> diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
> --- a/tests/test-blackbox.t
> +++ b/tests/test-blackbox.t
> @@ -13,8 +13,8 @@ command, exit codes, and duration
>    $ 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 @@ clone, commit, pull
>    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 @@ backup bundles get logged
>    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 @@ extension and python hooks - use the eol
>    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
>
> 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 @@ Hiding a non-tip changeset should change
>    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 @@ Hiding another changeset should cause th
>    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 @@ Resolving tags on an unfiltered repo wri
>    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)
> 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 @@ Tag cache debug info written to blackbox
>    $ 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 @@ Failure to acquire lock results in no wr
>    $ 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 @@ Extra junk data at the end should get ov
>    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 @@ Errors writing to .hgtags fnodes cache a
>    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 @@ Errors writing to .hgtags fnodes cache a
>    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 @@ Stripping doesn't truncate the tags cach
>    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 @@ Stripping doesn't truncate the tags cach
>    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
>
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> https://selenic.com/mailman/listinfo/mercurial-devel