blackbox: prevent failed I/O from causing hg to abort

Instead, we simply print a warning message if opening the blackbox log
file fails, or if writing to it fails.

hgext/blackbox.py

@@ -1,106 +1,115 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
 
 """
 
 from mercurial import util, cmdutil
 from mercurial.i18n import _
 import os, getpass, re
 
 cmdtable = {}
 command = cmdutil.command(cmdtable)
 testedwith = 'internal'
 lastblackbox = None
 
 def wrapui(ui):
     class blackboxui(ui.__class__):
         @util.propertycache
         def track(self):
             return ui.configlist('blackbox', 'track', ['*'])
 
         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
             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 = getpass.getuser()
                 formattedmsg = msg[0] % msg[1:]
-                blackbox.write('%s %s> %s' % (date, user, formattedmsg))
+                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._blackbox = repo.opener('blackbox.log', 'a')
+            try:
+                self._blackbox = repo.opener('blackbox.log', 'a')
+            except IOError, err:
+                self.debug('warning: cannot write to blackbox.log: %s\n' %
+                           err.strerror)
+                self._blackbox = None
 
     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,94 +1,136 b''
 setup
   $ cat > mock.py <<EOF
   > from mercurial import util
   > import getpass
   > 
   > 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
   >     getpass.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
+  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
+  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)
 
 cleanup
   $ cd ..