blackbox.py
278 lines
| 8.0 KiB
| text/x-python
|
PythonLexer
/ hgext / blackbox.py
|
r18676 | # blackbox.py - log repository events to a file for post-mortem debugging | ||
|
r18669 | # | ||
|
r18676 | # Copyright 2010 Nicolas Dumazet | ||
|
r18669 | # 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. | ||||
|
r28246 | |||
|
r19162 | Examples:: | ||
|
r18669 | |||
[blackbox] | ||||
track = * | ||||
|
r28303 | # dirty is *EXPENSIVE* (slow); | ||
# each log entry indicates `+` if the repository is dirty, like :hg:`id`. | ||||
|
r28246 | dirty = True | ||
|
r28305 | # record the source of log messages | ||
logsource = True | ||||
|
r18669 | |||
[blackbox] | ||||
track = command, commandfinish, commandexception, exthook, pythonhook | ||||
[blackbox] | ||||
track = incoming | ||||
|
r19066 | [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 | ||||
|
r40466 | [blackbox] | ||
# Include nanoseconds in log entries with %f (see Python function | ||||
# datetime.datetime.strftime) | ||||
date-format = '%Y-%m-%d @ %H:%M:%S.%f' | ||||
|
r18669 | """ | ||
|
r28090 | from __future__ import absolute_import | ||
import errno | ||||
import re | ||||
|
r18669 | from mercurial.i18n import _ | ||
|
r28245 | from mercurial.node import hex | ||
|
r28090 | from mercurial import ( | ||
|
r35685 | encoding, | ||
|
r38806 | pycompat, | ||
|
r32337 | registrar, | ||
|
r28248 | ui as uimod, | ||
|
r28090 | util, | ||
) | ||||
|
r37138 | from mercurial.utils import ( | ||
dateutil, | ||||
procutil, | ||||
) | ||||
|
r18669 | |||
|
r29841 | # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for | ||
|
r25186 | # 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. | ||||
|
r29841 | testedwith = 'ships-with-hg-core' | ||
r33129 | ||||
cmdtable = {} | ||||
command = registrar.command(cmdtable) | ||||
r33130 | configtable = {} | |||
configitem = registrar.configitem(configtable) | ||||
r33186 | configitem('blackbox', 'dirty', | |||
default=False, | ||||
) | ||||
r33130 | configitem('blackbox', 'maxsize', | |||
r33131 | default='1 MB', | |||
r33130 | ) | |||
r33187 | configitem('blackbox', 'logsource', | |||
default=False, | ||||
) | ||||
|
r34746 | configitem('blackbox', 'maxfiles', | ||
default=7, | ||||
) | ||||
|
r34518 | configitem('blackbox', 'track', | ||
|
r34584 | default=lambda: ['*'], | ||
|
r34518 | ) | ||
|
r40466 | configitem('blackbox', 'date-format', | ||
default='%Y/%m/%d %H:%M:%S', | ||||
) | ||||
r33130 | ||||
|
r40679 | _lastlogger = None | ||
|
r18669 | |||
|
r34301 | def _openlogfile(ui, vfs): | ||
def rotate(oldpath, newpath): | ||||
try: | ||||
vfs.unlink(newpath) | ||||
except OSError as err: | ||||
if err.errno != errno.ENOENT: | ||||
ui.debug("warning: cannot remove '%s': %s\n" % | ||||
(newpath, err.strerror)) | ||||
try: | ||||
if newpath: | ||||
vfs.rename(oldpath, newpath) | ||||
except OSError as err: | ||||
if err.errno != errno.ENOENT: | ||||
ui.debug("warning: cannot rename '%s' to '%s': %s\n" % | ||||
(newpath, oldpath, err.strerror)) | ||||
maxsize = ui.configbytes('blackbox', 'maxsize') | ||||
name = 'blackbox.log' | ||||
if maxsize > 0: | ||||
try: | ||||
st = vfs.stat(name) | ||||
except OSError: | ||||
pass | ||||
else: | ||||
if st.st_size >= maxsize: | ||||
path = vfs.join(name) | ||||
|
r34746 | maxfiles = ui.configint('blackbox', 'maxfiles') | ||
|
r38806 | for i in pycompat.xrange(maxfiles - 1, 1, -1): | ||
|
r34301 | rotate(oldpath='%s.%d' % (path, i - 1), | ||
newpath='%s.%d' % (path, i)) | ||||
rotate(oldpath=path, | ||||
newpath=maxfiles > 0 and path + '.1') | ||||
return vfs(name, 'a') | ||||
|
r40681 | class blackboxlogger(object): | ||
def __init__(self, ui): | ||||
|
r40682 | self._repo = None | ||
|
r40683 | self._inlog = False | ||
|
r40684 | self._trackedevents = set(ui.configlist('blackbox', 'track')) | ||
|
r40680 | |||
|
r40681 | @property | ||
def _bbvfs(self): | ||||
vfs = None | ||||
|
r40682 | if self._repo: | ||
vfs = self._repo.vfs | ||||
|
r40681 | if not vfs.isdir('.'): | ||
vfs = None | ||||
return vfs | ||||
|
r34112 | |||
|
r40684 | def tracked(self, event): | ||
return b'*' in self._trackedevents or event in self._trackedevents | ||||
|
r40681 | def log(self, ui, event, msg, opts): | ||
global _lastlogger | ||||
|
r40684 | if not self.tracked(event): | ||
|
r40681 | return | ||
|
r18669 | |||
|
r40681 | if self._bbvfs: | ||
_lastlogger = self | ||||
elif _lastlogger and _lastlogger._bbvfs: | ||||
# certain logger instances exist outside the context of | ||||
# a repo, so just default to the last blackbox logger that | ||||
# was seen. | ||||
pass | ||||
else: | ||||
return | ||||
_lastlogger._log(ui, event, msg, opts) | ||||
|
r34300 | |||
|
r40681 | def _log(self, ui, event, msg, opts): | ||
|
r40683 | if self._inlog: | ||
|
r40681 | # recursion and failure guard | ||
return | ||||
|
r40683 | self._inlog = True | ||
|
r40681 | default = ui.configdate('devel', 'default-date') | ||
date = dateutil.datestr(default, ui.config('blackbox', 'date-format')) | ||||
user = procutil.getuser() | ||||
pid = '%d' % procutil.getpid() | ||||
formattedmsg = msg[0] % msg[1:] | ||||
rev = '(unknown)' | ||||
changed = '' | ||||
|
r40682 | ctx = self._repo[None] | ||
|
r40681 | 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: | ||||
fmt = '%s %s @%s%s (%s)%s> %s' | ||||
args = (date, user, rev, changed, pid, src, formattedmsg) | ||||
with _openlogfile(ui, self._bbvfs) as fp: | ||||
fp.write(fmt % args) | ||||
except (IOError, OSError) as err: | ||||
ui.debug('warning: cannot write to blackbox.log: %s\n' % | ||||
encoding.strtolocal(err.strerror)) | ||||
|
r40683 | # do not restore _inlog intentionally to avoid failed | ||
|
r40681 | # logging again | ||
else: | ||||
|
r40683 | self._inlog = False | ||
|
r18669 | |||
|
r40681 | def setrepo(self, repo): | ||
|
r40682 | self._repo = repo | ||
|
r18669 | |||
|
r40680 | def wrapui(ui): | ||
class blackboxui(ui.__class__): | ||||
def __init__(self, src=None): | ||||
super(blackboxui, self).__init__(src) | ||||
if src and r'_bblogger' in src.__dict__: | ||||
self._bblogger = src._bblogger | ||||
# trick to initialize logger after configuration is loaded, which | ||||
# can be replaced later with blackboxlogger(ui) in uisetup(), where | ||||
# both user and repo configurations should be available. | ||||
@util.propertycache | ||||
def _bblogger(self): | ||||
return blackboxlogger(self) | ||||
def debug(self, *msg, **opts): | ||||
super(blackboxui, self).debug(*msg, **opts) | ||||
if self.debugflag: | ||||
self.log('debug', '%s', ''.join(msg)) | ||||
def log(self, event, *msg, **opts): | ||||
super(blackboxui, self).log(event, *msg, **opts) | ||||
self._bblogger.log(self, event, msg, opts) | ||||
|
r18669 | ui.__class__ = blackboxui | ||
|
r28248 | uimod.ui = blackboxui | ||
|
r18669 | |||
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 | ||||
|
r40680 | logger = getattr(ui, '_bblogger', None) | ||
if logger: | ||||
|
r40679 | logger.setrepo(repo) | ||
|
r34277 | |||
|
r40679 | # Set _lastlogger even if ui.log is not called. This gives blackbox a | ||
|
r34277 | # fallback place to log. | ||
|
r40679 | global _lastlogger | ||
if _lastlogger is None: | ||||
_lastlogger = logger | ||||
|
r34277 | |||
|
r33436 | repo._wlockfreeprefix.add('blackbox.log') | ||
|
r18673 | |||
|
r40331 | @command('blackbox', | ||
|
r18673 | [('l', 'limit', 10, _('the number of events to show')), | ||
], | ||||
|
r40329 | _('hg blackbox [OPTION]...'), | ||
|
r40331 | helpcategory=command.CATEGORY_MAINTENANCE, | ||
helpbasic=True) | ||||
|
r18673 | def blackbox(ui, repo, *revs, **opts): | ||
'''view the recent repository events | ||||
''' | ||||
|
r28026 | if not repo.vfs.exists('blackbox.log'): | ||
|
r18673 | return | ||
|
r34973 | limit = opts.get(r'limit') | ||
|
r28244 | fp = repo.vfs('blackbox.log', 'r') | ||
lines = fp.read().split('\n') | ||||
|
r18673 | |||
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))) | ||||