##// END OF EJS Templates
blackbox: initialize logger with repo instance...
Yuya Nishihara -
r40797:567e164f default
parent child Browse files
Show More
@@ -1,245 +1,239 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, repo):
143 self._repo = None
143 self._repo = repo
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 = self._repo.vfs
149 if self._repo:
149 if not vfs.isdir('.'):
150 vfs = self._repo.vfs
150 vfs = None
151 if not vfs.isdir('.'):
152 vfs = None
153 return vfs
151 return vfs
154
152
155 def tracked(self, event):
153 def tracked(self, event):
156 return b'*' in self._trackedevents or event in self._trackedevents
154 return b'*' in self._trackedevents or event in self._trackedevents
157
155
158 def log(self, ui, event, msg, opts):
156 def log(self, ui, event, msg, opts):
159 if self._bbvfs:
157 if self._bbvfs:
160 _lastlogger.logger = self
158 _lastlogger.logger = self
161 else:
159 else:
162 return
160 return
163
161
164 default = ui.configdate('devel', 'default-date')
162 default = ui.configdate('devel', 'default-date')
165 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
163 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
166 user = procutil.getuser()
164 user = procutil.getuser()
167 pid = '%d' % procutil.getpid()
165 pid = '%d' % procutil.getpid()
168 rev = '(unknown)'
166 rev = '(unknown)'
169 changed = ''
167 changed = ''
170 ctx = self._repo[None]
168 ctx = self._repo[None]
171 parents = ctx.parents()
169 parents = ctx.parents()
172 rev = ('+'.join([hex(p.node()) for p in parents]))
170 rev = ('+'.join([hex(p.node()) for p in parents]))
173 if (ui.configbool('blackbox', 'dirty') and
171 if (ui.configbool('blackbox', 'dirty') and
174 ctx.dirty(missing=True, merge=False, branch=False)):
172 ctx.dirty(missing=True, merge=False, branch=False)):
175 changed = '+'
173 changed = '+'
176 if ui.configbool('blackbox', 'logsource'):
174 if ui.configbool('blackbox', 'logsource'):
177 src = ' [%s]' % event
175 src = ' [%s]' % event
178 else:
176 else:
179 src = ''
177 src = ''
180 try:
178 try:
181 fmt = '%s %s @%s%s (%s)%s> %s'
179 fmt = '%s %s @%s%s (%s)%s> %s'
182 args = (date, user, rev, changed, pid, src, msg)
180 args = (date, user, rev, changed, pid, src, msg)
183 with _openlogfile(ui, self._bbvfs) as fp:
181 with _openlogfile(ui, self._bbvfs) as fp:
184 fp.write(fmt % args)
182 fp.write(fmt % args)
185 except (IOError, OSError) as err:
183 except (IOError, OSError) as err:
186 # deactivate this to avoid failed logging again
184 # deactivate this to avoid failed logging again
187 self._trackedevents.clear()
185 self._trackedevents.clear()
188 ui.debug('warning: cannot write to blackbox.log: %s\n' %
186 ui.debug('warning: cannot write to blackbox.log: %s\n' %
189 encoding.strtolocal(err.strerror))
187 encoding.strtolocal(err.strerror))
190
188
191 def setrepo(self, repo):
192 self._repo = repo
193
194 def uipopulate(ui):
189 def uipopulate(ui):
195 ui.setlogger(b'blackbox', _lastlogger)
190 ui.setlogger(b'blackbox', _lastlogger)
196
191
197 def reposetup(ui, repo):
192 def reposetup(ui, repo):
198 # During 'hg pull' a httppeer repo is created to represent the remote repo.
193 # 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
194 # It doesn't have a .hg directory to put a blackbox in, so we don't do
200 # the blackbox setup for it.
195 # the blackbox setup for it.
201 if not repo.local():
196 if not repo.local():
202 return
197 return
203
198
204 # Since blackbox.log is stored in the repo directory, the logger should be
199 # Since blackbox.log is stored in the repo directory, the logger should be
205 # instantiated per repository.
200 # instantiated per repository.
206 logger = blackboxlogger(ui)
201 logger = blackboxlogger(ui, repo)
207 ui.setlogger(b'blackbox', logger)
202 ui.setlogger(b'blackbox', logger)
208 logger.setrepo(repo)
209
203
210 # Set _lastlogger even if ui.log is not called. This gives blackbox a
204 # Set _lastlogger even if ui.log is not called. This gives blackbox a
211 # fallback place to log
205 # fallback place to log
212 if _lastlogger.logger is None:
206 if _lastlogger.logger is None:
213 _lastlogger.logger = logger
207 _lastlogger.logger = logger
214
208
215 repo._wlockfreeprefix.add('blackbox.log')
209 repo._wlockfreeprefix.add('blackbox.log')
216
210
217 @command('blackbox',
211 @command('blackbox',
218 [('l', 'limit', 10, _('the number of events to show')),
212 [('l', 'limit', 10, _('the number of events to show')),
219 ],
213 ],
220 _('hg blackbox [OPTION]...'),
214 _('hg blackbox [OPTION]...'),
221 helpcategory=command.CATEGORY_MAINTENANCE,
215 helpcategory=command.CATEGORY_MAINTENANCE,
222 helpbasic=True)
216 helpbasic=True)
223 def blackbox(ui, repo, *revs, **opts):
217 def blackbox(ui, repo, *revs, **opts):
224 '''view the recent repository events
218 '''view the recent repository events
225 '''
219 '''
226
220
227 if not repo.vfs.exists('blackbox.log'):
221 if not repo.vfs.exists('blackbox.log'):
228 return
222 return
229
223
230 limit = opts.get(r'limit')
224 limit = opts.get(r'limit')
231 fp = repo.vfs('blackbox.log', 'r')
225 fp = repo.vfs('blackbox.log', 'r')
232 lines = fp.read().split('\n')
226 lines = fp.read().split('\n')
233
227
234 count = 0
228 count = 0
235 output = []
229 output = []
236 for line in reversed(lines):
230 for line in reversed(lines):
237 if count >= limit:
231 if count >= limit:
238 break
232 break
239
233
240 # count the commands by matching lines like: 2013/01/23 19:13:36 root>
234 # 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):
235 if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
242 count += 1
236 count += 1
243 output.append(line)
237 output.append(line)
244
238
245 ui.status('\n'.join(reversed(output)))
239 ui.status('\n'.join(reversed(output)))
General Comments 0
You need to be logged in to leave comments. Login now