##// END OF EJS Templates
blackbox: do not nullify repo to deactivate the logger on failure...
Yuya Nishihara -
r40796:3ede5d17 default
parent child Browse files
Show More
@@ -1,245 +1,245 b''
1 # blackbox.py - log repository events to a file for post-mortem debugging
1 # blackbox.py - log repository events to a file for post-mortem debugging
2 #
2 #
3 # Copyright 2010 Nicolas Dumazet
3 # Copyright 2010 Nicolas Dumazet
4 # Copyright 2013 Facebook, Inc.
4 # Copyright 2013 Facebook, Inc.
5 #
5 #
6 # This software may be used and distributed according to the terms of the
6 # This software may be used and distributed according to the terms of the
7 # GNU General Public License version 2 or any later version.
7 # GNU General Public License version 2 or any later version.
8
8
9 """log repository events to a blackbox for debugging
9 """log repository events to a blackbox for debugging
10
10
11 Logs event information to .hg/blackbox.log to help debug and diagnose problems.
11 Logs event information to .hg/blackbox.log to help debug and diagnose problems.
12 The events that get logged can be configured via the blackbox.track config key.
12 The events that get logged can be configured via the blackbox.track config key.
13
13
14 Examples::
14 Examples::
15
15
16 [blackbox]
16 [blackbox]
17 track = *
17 track = *
18 # dirty is *EXPENSIVE* (slow);
18 # dirty is *EXPENSIVE* (slow);
19 # each log entry indicates `+` if the repository is dirty, like :hg:`id`.
19 # each log entry indicates `+` if the repository is dirty, like :hg:`id`.
20 dirty = True
20 dirty = True
21 # record the source of log messages
21 # record the source of log messages
22 logsource = True
22 logsource = True
23
23
24 [blackbox]
24 [blackbox]
25 track = command, commandfinish, commandexception, exthook, pythonhook
25 track = command, commandfinish, commandexception, exthook, pythonhook
26
26
27 [blackbox]
27 [blackbox]
28 track = incoming
28 track = incoming
29
29
30 [blackbox]
30 [blackbox]
31 # limit the size of a log file
31 # limit the size of a log file
32 maxsize = 1.5 MB
32 maxsize = 1.5 MB
33 # rotate up to N log files when the current one gets too big
33 # rotate up to N log files when the current one gets too big
34 maxfiles = 3
34 maxfiles = 3
35
35
36 [blackbox]
36 [blackbox]
37 # Include nanoseconds in log entries with %f (see Python function
37 # Include nanoseconds in log entries with %f (see Python function
38 # datetime.datetime.strftime)
38 # datetime.datetime.strftime)
39 date-format = '%Y-%m-%d @ %H:%M:%S.%f'
39 date-format = '%Y-%m-%d @ %H:%M:%S.%f'
40
40
41 """
41 """
42
42
43 from __future__ import absolute_import
43 from __future__ import absolute_import
44
44
45 import errno
45 import errno
46 import re
46 import re
47
47
48 from mercurial.i18n import _
48 from mercurial.i18n import _
49 from mercurial.node import hex
49 from mercurial.node import hex
50
50
51 from mercurial import (
51 from mercurial import (
52 encoding,
52 encoding,
53 pycompat,
53 pycompat,
54 registrar,
54 registrar,
55 )
55 )
56 from mercurial.utils import (
56 from mercurial.utils import (
57 dateutil,
57 dateutil,
58 procutil,
58 procutil,
59 )
59 )
60
60
61 # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
61 # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
62 # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should
62 # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should
63 # be specifying the version(s) of Mercurial they are tested with, or
63 # be specifying the version(s) of Mercurial they are tested with, or
64 # leave the attribute unspecified.
64 # leave the attribute unspecified.
65 testedwith = 'ships-with-hg-core'
65 testedwith = 'ships-with-hg-core'
66
66
67 cmdtable = {}
67 cmdtable = {}
68 command = registrar.command(cmdtable)
68 command = registrar.command(cmdtable)
69
69
70 configtable = {}
70 configtable = {}
71 configitem = registrar.configitem(configtable)
71 configitem = registrar.configitem(configtable)
72
72
73 configitem('blackbox', 'dirty',
73 configitem('blackbox', 'dirty',
74 default=False,
74 default=False,
75 )
75 )
76 configitem('blackbox', 'maxsize',
76 configitem('blackbox', 'maxsize',
77 default='1 MB',
77 default='1 MB',
78 )
78 )
79 configitem('blackbox', 'logsource',
79 configitem('blackbox', 'logsource',
80 default=False,
80 default=False,
81 )
81 )
82 configitem('blackbox', 'maxfiles',
82 configitem('blackbox', 'maxfiles',
83 default=7,
83 default=7,
84 )
84 )
85 configitem('blackbox', 'track',
85 configitem('blackbox', 'track',
86 default=lambda: ['*'],
86 default=lambda: ['*'],
87 )
87 )
88 configitem('blackbox', 'date-format',
88 configitem('blackbox', 'date-format',
89 default='%Y/%m/%d %H:%M:%S',
89 default='%Y/%m/%d %H:%M:%S',
90 )
90 )
91
91
92 def _openlogfile(ui, vfs):
92 def _openlogfile(ui, vfs):
93 def rotate(oldpath, newpath):
93 def rotate(oldpath, newpath):
94 try:
94 try:
95 vfs.unlink(newpath)
95 vfs.unlink(newpath)
96 except OSError as err:
96 except OSError as err:
97 if err.errno != errno.ENOENT:
97 if err.errno != errno.ENOENT:
98 ui.debug("warning: cannot remove '%s': %s\n" %
98 ui.debug("warning: cannot remove '%s': %s\n" %
99 (newpath, err.strerror))
99 (newpath, err.strerror))
100 try:
100 try:
101 if newpath:
101 if newpath:
102 vfs.rename(oldpath, newpath)
102 vfs.rename(oldpath, newpath)
103 except OSError as err:
103 except OSError as err:
104 if err.errno != errno.ENOENT:
104 if err.errno != errno.ENOENT:
105 ui.debug("warning: cannot rename '%s' to '%s': %s\n" %
105 ui.debug("warning: cannot rename '%s' to '%s': %s\n" %
106 (newpath, oldpath, err.strerror))
106 (newpath, oldpath, err.strerror))
107
107
108 maxsize = ui.configbytes('blackbox', 'maxsize')
108 maxsize = ui.configbytes('blackbox', 'maxsize')
109 name = 'blackbox.log'
109 name = 'blackbox.log'
110 if maxsize > 0:
110 if maxsize > 0:
111 try:
111 try:
112 st = vfs.stat(name)
112 st = vfs.stat(name)
113 except OSError:
113 except OSError:
114 pass
114 pass
115 else:
115 else:
116 if st.st_size >= maxsize:
116 if st.st_size >= maxsize:
117 path = vfs.join(name)
117 path = vfs.join(name)
118 maxfiles = ui.configint('blackbox', 'maxfiles')
118 maxfiles = ui.configint('blackbox', 'maxfiles')
119 for i in pycompat.xrange(maxfiles - 1, 1, -1):
119 for i in pycompat.xrange(maxfiles - 1, 1, -1):
120 rotate(oldpath='%s.%d' % (path, i - 1),
120 rotate(oldpath='%s.%d' % (path, i - 1),
121 newpath='%s.%d' % (path, i))
121 newpath='%s.%d' % (path, i))
122 rotate(oldpath=path,
122 rotate(oldpath=path,
123 newpath=maxfiles > 0 and path + '.1')
123 newpath=maxfiles > 0 and path + '.1')
124 return vfs(name, 'a')
124 return vfs(name, 'a')
125
125
126 class proxylogger(object):
126 class proxylogger(object):
127 """Forward log events to another logger to be set later"""
127 """Forward log events to another logger to be set later"""
128
128
129 def __init__(self):
129 def __init__(self):
130 self.logger = None
130 self.logger = None
131
131
132 def tracked(self, event):
132 def tracked(self, event):
133 return self.logger is not None and self.logger.tracked(event)
133 return self.logger is not None and self.logger.tracked(event)
134
134
135 def log(self, ui, event, msg, opts):
135 def log(self, ui, event, msg, opts):
136 assert self.logger is not None
136 assert self.logger is not None
137 self.logger.log(ui, event, msg, opts)
137 self.logger.log(ui, event, msg, opts)
138
138
139 _lastlogger = proxylogger()
139 _lastlogger = proxylogger()
140
140
141 class blackboxlogger(object):
141 class blackboxlogger(object):
142 def __init__(self, ui):
142 def __init__(self, ui):
143 self._repo = None
143 self._repo = None
144 self._trackedevents = set(ui.configlist('blackbox', 'track'))
144 self._trackedevents = set(ui.configlist('blackbox', 'track'))
145
145
146 @property
146 @property
147 def _bbvfs(self):
147 def _bbvfs(self):
148 vfs = None
148 vfs = None
149 if self._repo:
149 if self._repo:
150 vfs = self._repo.vfs
150 vfs = self._repo.vfs
151 if not vfs.isdir('.'):
151 if not vfs.isdir('.'):
152 vfs = None
152 vfs = None
153 return vfs
153 return vfs
154
154
155 def tracked(self, event):
155 def tracked(self, event):
156 return b'*' in self._trackedevents or event in self._trackedevents
156 return b'*' in self._trackedevents or event in self._trackedevents
157
157
158 def log(self, ui, event, msg, opts):
158 def log(self, ui, event, msg, opts):
159 if self._bbvfs:
159 if self._bbvfs:
160 _lastlogger.logger = self
160 _lastlogger.logger = self
161 else:
161 else:
162 return
162 return
163
163
164 default = ui.configdate('devel', 'default-date')
164 default = ui.configdate('devel', 'default-date')
165 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
165 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
166 user = procutil.getuser()
166 user = procutil.getuser()
167 pid = '%d' % procutil.getpid()
167 pid = '%d' % procutil.getpid()
168 rev = '(unknown)'
168 rev = '(unknown)'
169 changed = ''
169 changed = ''
170 ctx = self._repo[None]
170 ctx = self._repo[None]
171 parents = ctx.parents()
171 parents = ctx.parents()
172 rev = ('+'.join([hex(p.node()) for p in parents]))
172 rev = ('+'.join([hex(p.node()) for p in parents]))
173 if (ui.configbool('blackbox', 'dirty') and
173 if (ui.configbool('blackbox', 'dirty') and
174 ctx.dirty(missing=True, merge=False, branch=False)):
174 ctx.dirty(missing=True, merge=False, branch=False)):
175 changed = '+'
175 changed = '+'
176 if ui.configbool('blackbox', 'logsource'):
176 if ui.configbool('blackbox', 'logsource'):
177 src = ' [%s]' % event
177 src = ' [%s]' % event
178 else:
178 else:
179 src = ''
179 src = ''
180 try:
180 try:
181 fmt = '%s %s @%s%s (%s)%s> %s'
181 fmt = '%s %s @%s%s (%s)%s> %s'
182 args = (date, user, rev, changed, pid, src, msg)
182 args = (date, user, rev, changed, pid, src, msg)
183 with _openlogfile(ui, self._bbvfs) as fp:
183 with _openlogfile(ui, self._bbvfs) as fp:
184 fp.write(fmt % args)
184 fp.write(fmt % args)
185 except (IOError, OSError) as err:
185 except (IOError, OSError) as err:
186 # deactivate this to avoid failed logging again
186 # deactivate this to avoid failed logging again
187 self._repo = None
187 self._trackedevents.clear()
188 ui.debug('warning: cannot write to blackbox.log: %s\n' %
188 ui.debug('warning: cannot write to blackbox.log: %s\n' %
189 encoding.strtolocal(err.strerror))
189 encoding.strtolocal(err.strerror))
190
190
191 def setrepo(self, repo):
191 def setrepo(self, repo):
192 self._repo = repo
192 self._repo = repo
193
193
194 def uipopulate(ui):
194 def uipopulate(ui):
195 ui.setlogger(b'blackbox', _lastlogger)
195 ui.setlogger(b'blackbox', _lastlogger)
196
196
197 def reposetup(ui, repo):
197 def reposetup(ui, repo):
198 # During 'hg pull' a httppeer repo is created to represent the remote repo.
198 # During 'hg pull' a httppeer repo is created to represent the remote repo.
199 # It doesn't have a .hg directory to put a blackbox in, so we don't do
199 # It doesn't have a .hg directory to put a blackbox in, so we don't do
200 # the blackbox setup for it.
200 # the blackbox setup for it.
201 if not repo.local():
201 if not repo.local():
202 return
202 return
203
203
204 # Since blackbox.log is stored in the repo directory, the logger should be
204 # Since blackbox.log is stored in the repo directory, the logger should be
205 # instantiated per repository.
205 # instantiated per repository.
206 logger = blackboxlogger(ui)
206 logger = blackboxlogger(ui)
207 ui.setlogger(b'blackbox', logger)
207 ui.setlogger(b'blackbox', logger)
208 logger.setrepo(repo)
208 logger.setrepo(repo)
209
209
210 # Set _lastlogger even if ui.log is not called. This gives blackbox a
210 # Set _lastlogger even if ui.log is not called. This gives blackbox a
211 # fallback place to log
211 # fallback place to log
212 if _lastlogger.logger is None:
212 if _lastlogger.logger is None:
213 _lastlogger.logger = logger
213 _lastlogger.logger = logger
214
214
215 repo._wlockfreeprefix.add('blackbox.log')
215 repo._wlockfreeprefix.add('blackbox.log')
216
216
217 @command('blackbox',
217 @command('blackbox',
218 [('l', 'limit', 10, _('the number of events to show')),
218 [('l', 'limit', 10, _('the number of events to show')),
219 ],
219 ],
220 _('hg blackbox [OPTION]...'),
220 _('hg blackbox [OPTION]...'),
221 helpcategory=command.CATEGORY_MAINTENANCE,
221 helpcategory=command.CATEGORY_MAINTENANCE,
222 helpbasic=True)
222 helpbasic=True)
223 def blackbox(ui, repo, *revs, **opts):
223 def blackbox(ui, repo, *revs, **opts):
224 '''view the recent repository events
224 '''view the recent repository events
225 '''
225 '''
226
226
227 if not repo.vfs.exists('blackbox.log'):
227 if not repo.vfs.exists('blackbox.log'):
228 return
228 return
229
229
230 limit = opts.get(r'limit')
230 limit = opts.get(r'limit')
231 fp = repo.vfs('blackbox.log', 'r')
231 fp = repo.vfs('blackbox.log', 'r')
232 lines = fp.read().split('\n')
232 lines = fp.read().split('\n')
233
233
234 count = 0
234 count = 0
235 output = []
235 output = []
236 for line in reversed(lines):
236 for line in reversed(lines):
237 if count >= limit:
237 if count >= limit:
238 break
238 break
239
239
240 # count the commands by matching lines like: 2013/01/23 19:13:36 root>
240 # count the commands by matching lines like: 2013/01/23 19:13:36 root>
241 if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
241 if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
242 count += 1
242 count += 1
243 output.append(line)
243 output.append(line)
244
244
245 ui.status('\n'.join(reversed(output)))
245 ui.status('\n'.join(reversed(output)))
General Comments 0
You need to be logged in to leave comments. Login now