2013-02-13 22:54:52 +04:00
|
|
|
# blackbox.py - log repository events to a file for post-mortem debugging
|
2013-02-13 02:08:33 +04:00
|
|
|
#
|
2013-02-13 22:54:52 +04:00
|
|
|
# Copyright 2010 Nicolas Dumazet
|
2013-02-13 02:08:33 +04:00
|
|
|
# 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.
|
2016-02-09 18:44:13 +03:00
|
|
|
|
2013-05-09 06:37:20 +04:00
|
|
|
Examples::
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
[blackbox]
|
|
|
|
track = *
|
2016-03-01 13:43:52 +03:00
|
|
|
# dirty is *EXPENSIVE* (slow);
|
|
|
|
# each log entry indicates `+` if the repository is dirty, like :hg:`id`.
|
2016-02-09 18:44:13 +03:00
|
|
|
dirty = True
|
2016-02-11 22:38:26 +03:00
|
|
|
# record the source of log messages
|
|
|
|
logsource = True
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
[blackbox]
|
|
|
|
track = command, commandfinish, commandexception, exthook, pythonhook
|
|
|
|
|
|
|
|
[blackbox]
|
|
|
|
track = incoming
|
|
|
|
|
2013-04-19 03:17:59 +04:00
|
|
|
[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
|
|
|
|
|
2013-02-13 02:08:33 +04:00
|
|
|
"""
|
|
|
|
|
2016-02-10 04:30:38 +03:00
|
|
|
from __future__ import absolute_import
|
|
|
|
|
|
|
|
import errno
|
|
|
|
import re
|
|
|
|
|
2013-02-13 02:08:33 +04:00
|
|
|
from mercurial.i18n import _
|
2016-02-09 22:16:06 +03:00
|
|
|
from mercurial.node import hex
|
|
|
|
|
2016-02-10 04:30:38 +03:00
|
|
|
from mercurial import (
|
2018-03-02 20:02:38 +03:00
|
|
|
error,
|
2016-01-09 17:07:20 +03:00
|
|
|
registrar,
|
2016-02-03 07:54:40 +03:00
|
|
|
ui as uimod,
|
2016-02-10 04:30:38 +03:00
|
|
|
util,
|
|
|
|
)
|
2013-02-13 02:08:33 +04:00
|
|
|
|
2016-08-23 18:26:08 +03:00
|
|
|
# Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
|
2015-04-28 23:44:37 +03:00
|
|
|
# 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.
|
2016-08-23 18:26:08 +03:00
|
|
|
testedwith = 'ships-with-hg-core'
|
2017-06-17 14:41:28 +03:00
|
|
|
|
|
|
|
cmdtable = {}
|
|
|
|
command = registrar.command(cmdtable)
|
|
|
|
|
2017-06-17 14:21:06 +03:00
|
|
|
configtable = {}
|
|
|
|
configitem = registrar.configitem(configtable)
|
|
|
|
|
2017-06-30 04:28:11 +03:00
|
|
|
configitem('blackbox', 'dirty',
|
|
|
|
default=False,
|
|
|
|
)
|
2017-06-17 14:21:06 +03:00
|
|
|
configitem('blackbox', 'maxsize',
|
2017-06-18 21:49:08 +03:00
|
|
|
default='1 MB',
|
2017-06-17 14:21:06 +03:00
|
|
|
)
|
2017-06-30 04:28:18 +03:00
|
|
|
configitem('blackbox', 'logsource',
|
|
|
|
default=False,
|
|
|
|
)
|
2017-10-11 23:51:23 +03:00
|
|
|
configitem('blackbox', 'maxfiles',
|
|
|
|
default=7,
|
|
|
|
)
|
2017-10-08 21:11:34 +03:00
|
|
|
configitem('blackbox', 'track',
|
2017-10-11 16:25:57 +03:00
|
|
|
default=lambda: ['*'],
|
2017-10-08 21:11:34 +03:00
|
|
|
)
|
2017-06-17 14:21:06 +03:00
|
|
|
|
2016-02-03 20:05:04 +03:00
|
|
|
lastui = None
|
2013-02-13 02:08:33 +04:00
|
|
|
|
flake8: enable F821 check
Summary:
This check is useful and detects real errors (ex. fbconduit). Unfortunately
`arc lint` will run it with both py2 and py3 so a lot of py2 builtins will
still be warned.
I didn't find a clean way to disable py3 check. So this diff tries to fix them.
For `xrange`, the change was done by a script:
```
import sys
import redbaron
headertypes = {'comment', 'endl', 'from_import', 'import', 'string',
'assignment', 'atomtrailers'}
xrangefix = '''try:
xrange(0)
except NameError:
xrange = range
'''
def isxrange(x):
try:
return x[0].value == 'xrange'
except Exception:
return False
def main(argv):
for i, path in enumerate(argv):
print('(%d/%d) scanning %s' % (i + 1, len(argv), path))
content = open(path).read()
try:
red = redbaron.RedBaron(content)
except Exception:
print(' warning: failed to parse')
continue
hasxrange = red.find('atomtrailersnode', value=isxrange)
hasxrangefix = 'xrange = range' in content
if hasxrangefix or not hasxrange:
print(' no need to change')
continue
# find a place to insert the compatibility statement
changed = False
for node in red:
if node.type in headertypes:
continue
# node.insert_before is an easier API, but it has bugs changing
# other "finally" and "except" positions. So do the insert
# manually.
# # node.insert_before(xrangefix)
line = node.absolute_bounding_box.top_left.line - 1
lines = content.splitlines(1)
content = ''.join(lines[:line]) + xrangefix + ''.join(lines[line:])
changed = True
break
if changed:
# "content" is faster than "red.dumps()"
open(path, 'w').write(content)
print(' updated')
if __name__ == "__main__":
sys.exit(main(sys.argv[1:]))
```
For other py2 builtins that do not have a py3 equivalent, some `# noqa`
were added as a workaround for now.
Reviewed By: DurhamG
Differential Revision: D6934535
fbshipit-source-id: 546b62830af144bc8b46788d2e0fd00496838939
2018-02-10 04:31:44 +03:00
|
|
|
try:
|
|
|
|
xrange(0)
|
|
|
|
except NameError:
|
|
|
|
xrange = range
|
|
|
|
|
2017-09-21 21:10:20 +03:00
|
|
|
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)
|
2017-10-11 23:51:23 +03:00
|
|
|
maxfiles = ui.configint('blackbox', 'maxfiles')
|
2017-09-21 21:10:20 +03:00
|
|
|
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 vfs(name, 'a')
|
|
|
|
|
2013-02-13 02:08:33 +04:00
|
|
|
def wrapui(ui):
|
|
|
|
class blackboxui(ui.__class__):
|
2017-09-07 07:12:27 +03:00
|
|
|
@property
|
|
|
|
def _bbvfs(self):
|
2017-09-21 21:03:37 +03:00
|
|
|
vfs = None
|
2017-09-07 07:12:27 +03:00
|
|
|
repo = getattr(self, '_bbrepo', None)
|
|
|
|
if repo:
|
2017-09-21 21:03:37 +03:00
|
|
|
vfs = repo.vfs
|
|
|
|
if not vfs.isdir('.'):
|
|
|
|
vfs = None
|
|
|
|
return vfs
|
2017-09-07 07:12:27 +03:00
|
|
|
|
2013-02-13 02:08:33 +04:00
|
|
|
@util.propertycache
|
|
|
|
def track(self):
|
2017-10-08 21:11:34 +03:00
|
|
|
return self.configlist('blackbox', 'track')
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
def log(self, event, *msg, **opts):
|
2016-02-03 20:05:04 +03:00
|
|
|
global lastui
|
2013-02-13 02:08:33 +04:00
|
|
|
super(blackboxui, self).log(event, *msg, **opts)
|
|
|
|
|
|
|
|
if not '*' in self.track and not event in self.track:
|
|
|
|
return
|
|
|
|
|
2018-04-17 06:42:00 +03:00
|
|
|
if not msg or not msg[0]:
|
|
|
|
return
|
|
|
|
|
2017-09-07 07:08:59 +03:00
|
|
|
if self._bbvfs:
|
2016-02-03 20:05:04 +03:00
|
|
|
ui = self
|
2013-02-13 02:08:33 +04:00
|
|
|
else:
|
|
|
|
# certain ui instances exist outside the context of
|
|
|
|
# a repo, so just default to the last blackbox that
|
|
|
|
# was seen.
|
2016-02-03 20:05:04 +03:00
|
|
|
ui = lastui
|
2013-02-13 02:08:33 +04:00
|
|
|
|
2017-09-07 07:08:59 +03:00
|
|
|
if not ui:
|
2016-03-08 23:34:59 +03:00
|
|
|
return
|
2017-09-21 21:03:37 +03:00
|
|
|
vfs = ui._bbvfs
|
|
|
|
if not vfs:
|
|
|
|
return
|
|
|
|
|
2017-09-19 01:56:08 +03:00
|
|
|
repo = getattr(ui, '_bbrepo', None)
|
|
|
|
if not lastui or repo:
|
2016-03-08 23:34:59 +03:00
|
|
|
lastui = ui
|
2017-09-19 01:56:08 +03:00
|
|
|
if getattr(ui, '_bbinlog', False):
|
2017-09-07 07:08:59 +03:00
|
|
|
# recursion and failure guard
|
2016-03-08 23:34:59 +03:00
|
|
|
return
|
2017-09-07 07:23:38 +03:00
|
|
|
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 repo:
|
2018-03-02 20:02:38 +03:00
|
|
|
try:
|
|
|
|
ctx = repo[None]
|
|
|
|
parents = ctx.parents()
|
|
|
|
rev = ('+'.join([hex(p.node()) for p in parents]))
|
|
|
|
except error.Abort:
|
|
|
|
# This can happen if the dirstate file is sufficiently
|
|
|
|
# corrupt that we can't extract the parents. In that case,
|
|
|
|
# just don't set the rev.
|
|
|
|
pass
|
2017-09-07 07:23:38 +03:00
|
|
|
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 = ''
|
2016-03-08 23:34:59 +03:00
|
|
|
try:
|
2017-09-07 07:23:38 +03:00
|
|
|
fmt = '%s %s @%s%s (%s)%s> %s'
|
|
|
|
args = (date, user, rev, changed, pid, src, formattedmsg)
|
2017-09-21 21:10:20 +03:00
|
|
|
with _openlogfile(ui, vfs) as fp:
|
2018-04-17 06:42:02 +03:00
|
|
|
line = fmt % args
|
|
|
|
if not line.endswith('\n'):
|
|
|
|
line += '\n'
|
|
|
|
fp.write(line)
|
2017-09-07 07:23:38 +03:00
|
|
|
except (IOError, OSError) as err:
|
|
|
|
self.debug('warning: cannot write to blackbox.log: %s\n' %
|
|
|
|
err.strerror)
|
|
|
|
# do not restore _bbinlog intentionally to avoid failed
|
|
|
|
# logging again
|
|
|
|
else:
|
|
|
|
ui._bbinlog = False
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
def setrepo(self, repo):
|
2016-02-09 22:16:06 +03:00
|
|
|
self._bbrepo = repo
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
ui.__class__ = blackboxui
|
2016-02-03 07:54:40 +03:00
|
|
|
uimod.ui = blackboxui
|
2013-02-13 02:08:33 +04:00
|
|
|
|
|
|
|
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
|
|
|
|
|
2013-05-23 04:38:24 +04:00
|
|
|
if util.safehasattr(ui, 'setrepo'):
|
|
|
|
ui.setrepo(repo)
|
2017-09-19 02:01:03 +03:00
|
|
|
|
|
|
|
# Set lastui even if ui.log is not called. This gives blackbox a
|
|
|
|
# fallback place to log.
|
|
|
|
global lastui
|
|
|
|
if lastui is None:
|
|
|
|
lastui = ui
|
|
|
|
|
2017-07-11 13:38:17 +03:00
|
|
|
repo._wlockfreeprefix.add('blackbox.log')
|
2013-02-09 21:09:46 +04:00
|
|
|
|
|
|
|
@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
|
|
|
|
'''
|
|
|
|
|
2016-02-08 03:47:36 +03:00
|
|
|
if not repo.vfs.exists('blackbox.log'):
|
2013-02-09 21:09:46 +04:00
|
|
|
return
|
|
|
|
|
2017-10-22 21:22:47 +03:00
|
|
|
limit = opts.get(r'limit')
|
2016-02-08 06:37:26 +03:00
|
|
|
fp = repo.vfs('blackbox.log', 'r')
|
|
|
|
lines = fp.read().split('\n')
|
2013-02-09 21:09:46 +04:00
|
|
|
|
|
|
|
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)))
|