blackbox: fix rotation with chg

The added test will show:

  $ $PYTHON showsize.py .hg/blackbox*
  .hg/blackbox.log: < 500
  .hg/blackbox.log.1: < 500
  .hg/blackbox.log.2: < 500
  .hg/blackbox.log.3: < 500
  .hg/blackbox.log.4: < 500
  .hg/blackbox.log.5: >= 500

with previous code.

The issue is caused by blackbox caching file objects *by path*, and the
rotation size check could run on a wrong file object (i.e. it should check
"blackbox.log", but `filehandles["blackbox.log"]` contains a file object
that has been renamed to "blackbox.log.5").

This patch removes the "filehandlers" global cache added by 45313f5a3a8c to
solve the issue.

I think the original patch was trying to make different ui objects use a same
file object if their blackbox.log path is the same. In theory it could also
be problematic in the rotation case. Anyway, that should become unnecessary
after D650.

Differential Revision: https://phab.mercurial-scm.org/D648

hgext/blackbox.py

@@ -1,265 +1,252 b''
 # blackbox.py - log repository events to a file for post-mortem debugging
 #
 # Copyright 2010 Nicolas Dumazet
 # Copyright 2013 Facebook, Inc.
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 """log repository events to a blackbox for debugging
 
 Logs event information to .hg/blackbox.log to help debug and diagnose problems.
 The events that get logged can be configured via the blackbox.track config key.
 
 Examples::
 
   [blackbox]
   track = *
   # dirty is *EXPENSIVE* (slow);
   # each log entry indicates `+` if the repository is dirty, like :hg:`id`.
   dirty = True
   # record the source of log messages
   logsource = True
 
   [blackbox]
   track = command, commandfinish, commandexception, exthook, pythonhook
 
   [blackbox]
   track = incoming
 
   [blackbox]
   # limit the size of a log file
   maxsize = 1.5 MB
   # rotate up to N log files when the current one gets too big
   maxfiles = 3
 
 """
 
 from __future__ import absolute_import
 
 import errno
 import re
 
 from mercurial.i18n import _
 from mercurial.node import hex
 
 from mercurial import (
     registrar,
     ui as uimod,
     util,
 )
 
 # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
 # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should
 # be specifying the version(s) of Mercurial they are tested with, or
 # leave the attribute unspecified.
 testedwith = 'ships-with-hg-core'
 
 cmdtable = {}
 command = registrar.command(cmdtable)
 
 configtable = {}
 configitem = registrar.configitem(configtable)
 
 configitem('blackbox', 'dirty',
     default=False,
 )
 configitem('blackbox', 'maxsize',
     default='1 MB',
 )
 configitem('blackbox', 'logsource',
     default=False,
 )
 
 lastui = None
 
-filehandles = {}
-
-def _openlog(vfs):
-    path = vfs.join('blackbox.log')
-    if path in filehandles:
-        return filehandles[path]
-    filehandles[path] = fp = vfs('blackbox.log', 'a')
-    return fp
-
-def _closelog(vfs):
-    path = vfs.join('blackbox.log')
-    fp = filehandles[path]
-    del filehandles[path]
-    fp.close()
-
 def wrapui(ui):
     class blackboxui(ui.__class__):
         def __init__(self, src=None):
             super(blackboxui, self).__init__(src)
             if src is None:
                 self._partialinit()
             else:
                 self._bbfp = getattr(src, '_bbfp', None)
                 self._bbinlog = False
                 self._bbrepo = getattr(src, '_bbrepo', None)
                 self._bbvfs = getattr(src, '_bbvfs', None)
 
         def _partialinit(self):
             if util.safehasattr(self, '_bbvfs'):
                 return
             self._bbfp = None
             self._bbinlog = False
             self._bbrepo = None
             self._bbvfs = None
 
         def copy(self):
             self._partialinit()
             return self.__class__(self)
 
         @util.propertycache
         def track(self):
             return self.configlist('blackbox', 'track', ['*'])
 
         def _openlogfile(self):
             def rotate(oldpath, newpath):
                 try:
                     self._bbvfs.unlink(newpath)
                 except OSError as err:
                     if err.errno != errno.ENOENT:
                         self.debug("warning: cannot remove '%s': %s\n" %
                                    (newpath, err.strerror))
                 try:
                     if newpath:
                         self._bbvfs.rename(oldpath, newpath)
                 except OSError as err:
                     if err.errno != errno.ENOENT:
                         self.debug("warning: cannot rename '%s' to '%s': %s\n" %
                                    (newpath, oldpath, err.strerror))
 
-            fp = _openlog(self._bbvfs)
             maxsize = self.configbytes('blackbox', 'maxsize')
+            name = 'blackbox.log'
             if maxsize > 0:
-                st = self._bbvfs.fstat(fp)
-                if st.st_size >= maxsize:
-                    path = fp.name
-                    _closelog(self._bbvfs)
-                    maxfiles = self.configint('blackbox', 'maxfiles', 7)
-                    for i in xrange(maxfiles - 1, 1, -1):
-                        rotate(oldpath='%s.%d' % (path, i - 1),
-                               newpath='%s.%d' % (path, i))
-                    rotate(oldpath=path,
-                           newpath=maxfiles > 0 and path + '.1')
-                    fp = _openlog(self._bbvfs)
-            return fp
+                try:
+                    st = self._bbvfs.stat(name)
+                except OSError:
+                    pass
+                else:
+                    if st.st_size >= maxsize:
+                        path = self._bbvfs.join(name)
+                        maxfiles = self.configint('blackbox', 'maxfiles', 7)
+                        for i in xrange(maxfiles - 1, 1, -1):
+                            rotate(oldpath='%s.%d' % (path, i - 1),
+                                   newpath='%s.%d' % (path, i))
+                        rotate(oldpath=path,
+                               newpath=maxfiles > 0 and path + '.1')
+            return self._bbvfs(name, 'a')
 
         def _bbwrite(self, fmt, *args):
             self._bbfp.write(fmt % args)
             self._bbfp.flush()
 
         def log(self, event, *msg, **opts):
             global lastui
             super(blackboxui, self).log(event, *msg, **opts)
             self._partialinit()
 
             if not '*' in self.track and not event in self.track:
                 return
 
             if self._bbfp:
                 ui = self
             elif self._bbvfs:
                 try:
                     self._bbfp = self._openlogfile()
                 except (IOError, OSError) as err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
                     del self._bbvfs
                     self._bbfp = None
                 ui = self
             else:
                 # certain ui instances exist outside the context of
                 # a repo, so just default to the last blackbox that
                 # was seen.
                 ui = lastui
 
             if not ui or not ui._bbfp:
                 return
             if not lastui or ui._bbrepo:
                 lastui = ui
             if ui._bbinlog:
                 # recursion guard
                 return
             try:
                 ui._bbinlog = True
                 default = self.configdate('devel', 'default-date')
                 date = util.datestr(default, '%Y/%m/%d %H:%M:%S')
                 user = util.getuser()
                 pid = '%d' % util.getpid()
                 formattedmsg = msg[0] % msg[1:]
                 rev = '(unknown)'
                 changed = ''
                 if ui._bbrepo:
                     ctx = ui._bbrepo[None]
                     parents = ctx.parents()
                     rev = ('+'.join([hex(p.node()) for p in parents]))
                     if (ui.configbool('blackbox', 'dirty') and
                         ctx.dirty(missing=True, merge=False, branch=False)):
                         changed = '+'
                 if ui.configbool('blackbox', 'logsource'):
                     src = ' [%s]' % event
                 else:
                     src = ''
                 try:
                     ui._bbwrite('%s %s @%s%s (%s)%s> %s',
                         date, user, rev, changed, pid, src, formattedmsg)
                 except IOError as err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
             finally:
                 ui._bbinlog = False
 
         def setrepo(self, repo):
             self._bbfp = None
             self._bbinlog = False
             self._bbrepo = repo
             self._bbvfs = repo.vfs
 
     ui.__class__ = blackboxui
     uimod.ui = blackboxui
 
 def uisetup(ui):
     wrapui(ui)
 
 def reposetup(ui, repo):
     # During 'hg pull' a httppeer repo is created to represent the remote repo.
     # It doesn't have a .hg directory to put a blackbox in, so we don't do
     # the blackbox setup for it.
     if not repo.local():
         return
 
     if util.safehasattr(ui, 'setrepo'):
         ui.setrepo(repo)
     repo._wlockfreeprefix.add('blackbox.log')
 
 @command('^blackbox',
     [('l', 'limit', 10, _('the number of events to show')),
     ],
     _('hg blackbox [OPTION]...'))
 def blackbox(ui, repo, *revs, **opts):
     '''view the recent repository events
     '''
 
     if not repo.vfs.exists('blackbox.log'):
         return
 
     limit = opts.get('limit')
     fp = repo.vfs('blackbox.log', 'r')
     lines = fp.read().split('\n')
 
     count = 0
     output = []
     for line in reversed(lines):
         if count >= limit:
             break
 
         # count the commands by matching lines like: 2013/01/23 19:13:36 root>
         if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
             count += 1
         output.append(line)
 
     ui.status('\n'.join(reversed(output)))

tests/test-blackbox.t

@@ -1,232 +1,286 b''
 setup
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > blackbox=
   > mock=$TESTDIR/mockblackbox.py
   > mq=
   > [alias]
   > confuse = log --limit 3
   > EOF
   $ hg init blackboxtest
   $ cd blackboxtest
 
 command, exit codes, and duration
 
   $ echo a > a
   $ hg add a
   $ hg blackbox --config blackbox.dirty=True
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000+ (5000)> blackbox
 
 alias expansion is logged
   $ hg confuse
   $ hg blackbox
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> add a exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000+ (5000)> blackbox
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000+ (5000)> blackbox --config *blackbox.dirty=True* exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> confuse
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> alias 'confuse' expands to 'log --limit 3'
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> confuse exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
 
 incoming change tracking
 
 create two heads to verify that we only see one change in the log later
   $ hg commit -ma
   $ hg up null
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   $ echo b > b
   $ hg commit -Amb
   adding b
   created new head
 
 clone, commit, pull
   $ hg clone . ../blackboxtest2
   updating to branch default
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo c > c
   $ hg commit -Amc
   adding c
   $ cd ../blackboxtest2
   $ hg pull
   pulling from $TESTTMP/blackboxtest (glob)
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
   $ hg blackbox -l 6
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pull
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated served branch cache in * seconds (glob)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote served branch cache with 1 labels and 2 nodes
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> 1 incoming changes - new heads: d02f48003e62
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pull exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
 
 we must not cause a failure if we cannot write to the log
 
   $ hg rollback
   repository tip rolled back to revision 1 (undo pull)
 
   $ mv .hg/blackbox.log .hg/blackbox.log-
   $ mkdir .hg/blackbox.log
   $ hg --debug incoming
   warning: cannot write to blackbox.log: * (glob)
   comparing with $TESTTMP/blackboxtest (glob)
   query 1; heads
   searching for changes
   all local heads known remotely
   changeset:   2:d02f48003e62c24e2659d97d30f2a83abe5d5d51
   tag:         tip
   phase:       draft
   parent:      1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06
   parent:      -1:0000000000000000000000000000000000000000
   manifest:    2:ab9d46b053ebf45b7996f2922b9893ff4b63d892
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   files+:      c
   extra:       branch=default
   description:
   c
   
   
   $ hg pull
   pulling from $TESTTMP/blackboxtest (glob)
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
 
 a failure reading from the log is fatal
 
   $ hg blackbox -l 3
   abort: *$TESTTMP/blackboxtest2/.hg/blackbox.log* (glob)
   [255]
 
   $ rmdir .hg/blackbox.log
   $ mv .hg/blackbox.log- .hg/blackbox.log
 
 backup bundles get logged
 
   $ touch d
   $ hg commit -Amd
   adding d
   created new head
   $ 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 6
   1970/01/01 00:00:00 bob @73f6ee326b27d820b0472f1a825e3a50f3dc489b (5000)> strip tip
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg (glob)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> updated base branch cache in * seconds (glob)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> wrote base branch cache with 1 labels and 2 nodes
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> strip tip exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> blackbox -l 6
 
 extension and python hooks - use the eol extension for a pythonhook
 
   $ echo '[extensions]' >> .hg/hgrc
   $ echo 'eol=' >> .hg/hgrc
   $ echo '[hooks]' >> .hg/hgrc
   $ echo 'update = echo hooked' >> .hg/hgrc
   $ hg update
   The fsmonitor extension is incompatible with the eol extension and has been disabled. (fsmonitor !)
   hooked
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   updated to "d02f48003e62: c"
   1 other heads for branch "default"
   $ cat >> .hg/hgrc <<EOF
   > [extensions]
   > # disable eol, because it is not needed for subsequent tests
   > # (in addition, keeping it requires extra care for fsmonitor)
   > eol=!
   > EOF
   $ hg blackbox -l 6
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> update (no-chg !)
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> writing .hg/cache/tags2-visible with 0 tags
   1970/01/01 00:00:00 bob @6563da9dcf87b1949716e38ff3e3dfaa3198eb06 (5000)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
   1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> exthook-update: echo hooked finished in * seconds (glob)
   1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> update exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> serve --cmdserver chgunix --address $TESTTMP.chgsock/server.* --daemon-postexec 'chdir:/' (glob) (chg !)
   1970/01/01 00:00:00 bob @d02f48003e62c24e2659d97d30f2a83abe5d5d51 (5000)> blackbox -l 6
 
 log rotation
 
   $ echo '[blackbox]' >> .hg/hgrc
   $ echo 'maxsize = 20 b' >> .hg/hgrc
   $ echo 'maxfiles = 3' >> .hg/hgrc
   $ hg status
   $ hg status
   $ hg status
   $ hg tip -q
   2:d02f48003e62
   $ ls .hg/blackbox.log*
   .hg/blackbox.log
   .hg/blackbox.log.1
   .hg/blackbox.log.2
   $ cd ..
 
   $ hg init blackboxtest3
   $ cd blackboxtest3
   $ hg blackbox
   1970/01/01 00:00:00 bob @0000000000000000000000000000000000000000 (5000)> blackbox
   $ mv .hg/blackbox.log .hg/blackbox.log-
   $ mkdir .hg/blackbox.log
   $ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\
   > os.rename(".hg/blackbox.log-", ".hg/blackbox.log")\
   > \1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py
   $ $PYTHON $TESTDIR/blackbox-readonly-dispatch.py
   running: add foo
   result: 0
   running: commit -m commit1 -d 2000-01-01 foo
   result: None
   running: commit -m commit2 -d 2000-01-02 foo
   result: None
   running: log -r 0
   changeset:   0:0e4634943879
   user:        test
   date:        Sat Jan 01 00:00:00 2000 +0000
   summary:     commit1
   
   result: None
   running: log -r tip
   changeset:   1:45589e459b2e
   tag:         tip
   user:        test
   date:        Sun Jan 02 00:00:00 2000 +0000
   summary:     commit2
   
   result: None
   $ hg blackbox
   1970/01/01 00:00:00 bob @0e46349438790c460c5c9f7546bfcd39b267bbd2 (5000)> commit -m commit2 -d 2000-01-02 foo
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> updated served branch cache in * seconds (glob)
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> wrote served branch cache with 1 labels and 1 nodes
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> commit -m commit2 -d 2000-01-02 foo exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> log -r 0
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> writing .hg/cache/tags2-visible with 0 tags
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> log -r 0 exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> log -r tip
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> log -r tip exited 0 after * seconds (glob)
   1970/01/01 00:00:00 bob @45589e459b2edfbf3dbde7e01f611d2c1e7453d7 (5000)> blackbox
 
 Test log recursion from dirty status check
 
   $ cat > ../r.py <<EOF
   > from mercurial import context, error, extensions
   > x=[False]
   > def status(orig, *args, **opts):
   >     args[0].repo().ui.log("broken", "recursion?")
   >     return orig(*args, **opts)
   > def reposetup(ui, repo):
   >     extensions.wrapfunction(context.basectx, 'status', status)
   > EOF
   $ hg id --config extensions.x=../r.py --config blackbox.dirty=True
   45589e459b2e tip
 
 cleanup
   $ cd ..
+
+#if chg
+
+when using chg, blackbox.log should get rotated correctly
+
+  $ cat > $TESTTMP/noop.py << EOF
+  > from __future__ import absolute_import
+  > import time
+  > from mercurial import registrar, scmutil
+  > cmdtable = {}
+  > command = registrar.command(cmdtable)
+  > @command('noop')
+  > def noop(ui, repo):
+  >     pass
+  > EOF
+
+  $ hg init blackbox-chg
+  $ cd blackbox-chg
+
+  $ cat > .hg/hgrc << EOF
+  > [blackbox]
+  > maxsize = 500B
+  > [extensions]
+  > # extension change forces chg to restart
+  > noop=$TESTTMP/noop.py
+  > EOF
+
+  $ $PYTHON -c 'print("a" * 400)' > .hg/blackbox.log
+  $ chg noop
+  $ chg noop
+  $ chg noop
+  $ chg noop
+  $ chg noop
+
+  $ cat > showsize.py << 'EOF'
+  > import os, sys
+  > limit = 500
+  > for p in sys.argv[1:]:
+  >     size = os.stat(p).st_size
+  >     if size >= limit:
+  >         desc = '>='
+  >     else:
+  >         desc = '<'
+  >     print('%s: %s %d' % (p, desc, limit))
+  > EOF
+
+  $ $PYTHON showsize.py .hg/blackbox*
+  .hg/blackbox.log: < 500
+  .hg/blackbox.log.1: >= 500
+  .hg/blackbox.log.2: >= 500
+
+  $ cd ..
+
+#endif