blackbox: automatically rotate log files

If enabled, log rotation prevents the amount of space used by the
blackbox log from growing without bound. This becomes important in
cases where there are a lot of busy repositories managed by humans
and automation on many machines.

In large deployments, we cannot reasonably track all the repos where
blackbox logs need to be managed, so it is safer to have blackbox
manage its own logs than to move responsibility to an external tool
such as logrotate.

This change adds two configuration keys:

* blackbox.maxsize is the maximum allowable size of the current log

* blackbox.maxfiles is the number of log files to maintain

hgext/blackbox.py

@@ -1,119 +1,157 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 = *
 
   [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 mercurial import util, cmdutil
 from mercurial.i18n import _
-import os, re
+import errno, os, re
 
 cmdtable = {}
 command = cmdutil.command(cmdtable)
 testedwith = 'internal'
 lastblackbox = None
 
 def wrapui(ui):
     class blackboxui(ui.__class__):
         @util.propertycache
         def track(self):
             return self.configlist('blackbox', 'track', ['*'])
 
+        def _openlogfile(self):
+            def rotate(oldpath, newpath):
+                try:
+                    os.unlink(newpath)
+                except OSError, err:
+                    if err.errno != errno.ENOENT:
+                        self.debug("warning: cannot remove '%s': %s\n" %
+                                   (newpath, err.strerror))
+                try:
+                    if newpath:
+                        os.rename(oldpath, newpath)
+                except OSError, err:
+                    if err.errno != errno.ENOENT:
+                        self.debug("warning: cannot rename '%s' to '%s': %s\n" %
+                                   (newpath, oldpath, err.strerror))
+
+            fp = self._bbopener('blackbox.log', 'a')
+            maxsize = self.configbytes('blackbox', 'maxsize', 1048576)
+            if maxsize > 0:
+                st = os.fstat(fp.fileno())
+                if st.st_size >= maxsize:
+                    path = fp.name
+                    fp.close()
+                    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 = self._bbopener('blackbox.log', 'a')
+            return fp
+
         def log(self, event, *msg, **opts):
             global lastblackbox
             super(blackboxui, self).log(event, *msg, **opts)
 
             if not '*' in self.track and not event in self.track:
                 return
 
             if util.safehasattr(self, '_blackbox'):
                 blackbox = self._blackbox
             elif util.safehasattr(self, '_bbopener'):
                 try:
-                    self._blackbox = self._bbopener('blackbox.log', 'a')
+                    self._blackbox = self._openlogfile()
                 except (IOError, OSError), err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
                     del self._bbopener
                     self._blackbox = None
                 blackbox = self._blackbox
             else:
                 # certain ui instances exist outside the context of
                 # a repo, so just default to the last blackbox that
                 # was seen.
                 blackbox = lastblackbox
 
             if blackbox:
                 date = util.datestr(None, '%Y/%m/%d %H:%M:%S')
                 user = util.getuser()
                 formattedmsg = msg[0] % msg[1:]
                 try:
                     blackbox.write('%s %s> %s' % (date, user, formattedmsg))
                 except IOError, err:
                     self.debug('warning: cannot write to blackbox.log: %s\n' %
                                err.strerror)
                 lastblackbox = blackbox
 
         def setrepo(self, repo):
             self._bbopener = repo.opener
 
     ui.__class__ = 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
 
     ui.setrepo(repo)
 
 @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 os.path.exists(repo.join('blackbox.log')):
         return
 
     limit = opts.get('limit')
     blackbox = repo.opener('blackbox.log', 'r')
     lines = blackbox.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,135 +1,150 b''
 setup
   $ cat > mock.py <<EOF
   > from mercurial import util
   > 
   > def makedate():
   >     return 0, 0
   > def getuser():
   >     return 'bob'
   > # mock the date and user apis so the output is always the same
   > def uisetup(ui):
   >     util.makedate = makedate
   >     util.getuser = getuser
   > EOF
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > blackbox=
   > mock=`pwd`/mock.py
   > mq=
   > EOF
   $ hg init blackboxtest
   $ cd blackboxtest
 
 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 exited 0 after * seconds (glob)
 
 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 3
   1970/01/01 00:00:00 bob> pull
   1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62
   1970/01/01 00:00:00 bob> pull exited None after * seconds (glob)
 
 we must not cause a failure if we cannot write to the log
 
   $ hg rollback
   repository tip rolled back to revision 1 (undo pull)
   $ chmod 000 .hg/blackbox.log
   $ hg --debug incoming
   warning: cannot write to blackbox.log: Permission denied
   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 fine
 
   $ hg blackbox -l 3
   abort: Permission denied: $TESTTMP/blackboxtest2/.hg/blackbox.log
   [255]
 
   $ chmod 600 .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 3
   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> strip exited 0 after * seconds (glob)
 
 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
   hooked
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg blackbox -l 4
   1970/01/01 00:00:00 bob> update
   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 False after * seconds (glob)
 
+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
+
 cleanup
   $ cd ..