Show More
@@ -1,276 +1,274 | |||||
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 | ui as uimod, |
|
55 | ui as uimod, | |
56 | util, |
|
56 | util, | |
57 | ) |
|
57 | ) | |
58 | from mercurial.utils import ( |
|
58 | from mercurial.utils import ( | |
59 | dateutil, |
|
59 | dateutil, | |
60 | procutil, |
|
60 | procutil, | |
61 | ) |
|
61 | ) | |
62 |
|
62 | |||
63 | # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for |
|
63 | # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for | |
64 | # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should |
|
64 | # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should | |
65 | # be specifying the version(s) of Mercurial they are tested with, or |
|
65 | # be specifying the version(s) of Mercurial they are tested with, or | |
66 | # leave the attribute unspecified. |
|
66 | # leave the attribute unspecified. | |
67 | testedwith = 'ships-with-hg-core' |
|
67 | testedwith = 'ships-with-hg-core' | |
68 |
|
68 | |||
69 | cmdtable = {} |
|
69 | cmdtable = {} | |
70 | command = registrar.command(cmdtable) |
|
70 | command = registrar.command(cmdtable) | |
71 |
|
71 | |||
72 | configtable = {} |
|
72 | configtable = {} | |
73 | configitem = registrar.configitem(configtable) |
|
73 | configitem = registrar.configitem(configtable) | |
74 |
|
74 | |||
75 | configitem('blackbox', 'dirty', |
|
75 | configitem('blackbox', 'dirty', | |
76 | default=False, |
|
76 | default=False, | |
77 | ) |
|
77 | ) | |
78 | configitem('blackbox', 'maxsize', |
|
78 | configitem('blackbox', 'maxsize', | |
79 | default='1 MB', |
|
79 | default='1 MB', | |
80 | ) |
|
80 | ) | |
81 | configitem('blackbox', 'logsource', |
|
81 | configitem('blackbox', 'logsource', | |
82 | default=False, |
|
82 | default=False, | |
83 | ) |
|
83 | ) | |
84 | configitem('blackbox', 'maxfiles', |
|
84 | configitem('blackbox', 'maxfiles', | |
85 | default=7, |
|
85 | default=7, | |
86 | ) |
|
86 | ) | |
87 | configitem('blackbox', 'track', |
|
87 | configitem('blackbox', 'track', | |
88 | default=lambda: ['*'], |
|
88 | default=lambda: ['*'], | |
89 | ) |
|
89 | ) | |
90 | configitem('blackbox', 'date-format', |
|
90 | configitem('blackbox', 'date-format', | |
91 | default='%Y/%m/%d %H:%M:%S', |
|
91 | default='%Y/%m/%d %H:%M:%S', | |
92 | ) |
|
92 | ) | |
93 |
|
93 | |||
94 | _lastlogger = None |
|
94 | _lastlogger = None | |
95 |
|
95 | |||
96 | def _openlogfile(ui, vfs): |
|
96 | def _openlogfile(ui, vfs): | |
97 | def rotate(oldpath, newpath): |
|
97 | def rotate(oldpath, newpath): | |
98 | try: |
|
98 | try: | |
99 | vfs.unlink(newpath) |
|
99 | vfs.unlink(newpath) | |
100 | except OSError as err: |
|
100 | except OSError as err: | |
101 | if err.errno != errno.ENOENT: |
|
101 | if err.errno != errno.ENOENT: | |
102 | ui.debug("warning: cannot remove '%s': %s\n" % |
|
102 | ui.debug("warning: cannot remove '%s': %s\n" % | |
103 | (newpath, err.strerror)) |
|
103 | (newpath, err.strerror)) | |
104 | try: |
|
104 | try: | |
105 | if newpath: |
|
105 | if newpath: | |
106 | vfs.rename(oldpath, newpath) |
|
106 | vfs.rename(oldpath, newpath) | |
107 | except OSError as err: |
|
107 | except OSError as err: | |
108 | if err.errno != errno.ENOENT: |
|
108 | if err.errno != errno.ENOENT: | |
109 | ui.debug("warning: cannot rename '%s' to '%s': %s\n" % |
|
109 | ui.debug("warning: cannot rename '%s' to '%s': %s\n" % | |
110 | (newpath, oldpath, err.strerror)) |
|
110 | (newpath, oldpath, err.strerror)) | |
111 |
|
111 | |||
112 | maxsize = ui.configbytes('blackbox', 'maxsize') |
|
112 | maxsize = ui.configbytes('blackbox', 'maxsize') | |
113 | name = 'blackbox.log' |
|
113 | name = 'blackbox.log' | |
114 | if maxsize > 0: |
|
114 | if maxsize > 0: | |
115 | try: |
|
115 | try: | |
116 | st = vfs.stat(name) |
|
116 | st = vfs.stat(name) | |
117 | except OSError: |
|
117 | except OSError: | |
118 | pass |
|
118 | pass | |
119 | else: |
|
119 | else: | |
120 | if st.st_size >= maxsize: |
|
120 | if st.st_size >= maxsize: | |
121 | path = vfs.join(name) |
|
121 | path = vfs.join(name) | |
122 | maxfiles = ui.configint('blackbox', 'maxfiles') |
|
122 | maxfiles = ui.configint('blackbox', 'maxfiles') | |
123 | for i in pycompat.xrange(maxfiles - 1, 1, -1): |
|
123 | for i in pycompat.xrange(maxfiles - 1, 1, -1): | |
124 | rotate(oldpath='%s.%d' % (path, i - 1), |
|
124 | rotate(oldpath='%s.%d' % (path, i - 1), | |
125 | newpath='%s.%d' % (path, i)) |
|
125 | newpath='%s.%d' % (path, i)) | |
126 | rotate(oldpath=path, |
|
126 | rotate(oldpath=path, | |
127 | newpath=maxfiles > 0 and path + '.1') |
|
127 | newpath=maxfiles > 0 and path + '.1') | |
128 | return vfs(name, 'a') |
|
128 | return vfs(name, 'a') | |
129 |
|
129 | |||
130 | if True: |
|
130 | class blackboxlogger(object): | |
131 | class blackboxlogger(object): |
|
131 | def __init__(self, ui): | |
132 | def __init__(self, ui): |
|
132 | self.track = ui.configlist('blackbox', 'track') | |
133 | self.track = ui.configlist('blackbox', 'track') |
|
|||
134 |
|
133 | |||
135 |
|
|
134 | @property | |
136 |
|
|
135 | def _bbvfs(self): | |
137 |
|
|
136 | vfs = None | |
138 |
|
|
137 | repo = getattr(self, '_bbrepo', None) | |
139 |
|
|
138 | if repo: | |
140 |
|
|
139 | vfs = repo.vfs | |
141 |
|
|
140 | if not vfs.isdir('.'): | |
142 |
|
|
141 | vfs = None | |
143 |
|
|
142 | return vfs | |
144 |
|
143 | |||
145 |
|
|
144 | def log(self, ui, event, msg, opts): | |
146 |
|
|
145 | global _lastlogger | |
147 |
|
|
146 | if not '*' in self.track and not event in self.track: | |
148 |
|
|
147 | return | |
149 |
|
148 | |||
150 |
|
|
149 | if self._bbvfs: | |
151 |
|
|
150 | _lastlogger = self | |
152 |
|
|
151 | elif _lastlogger and _lastlogger._bbvfs: | |
153 |
|
|
152 | # certain logger instances exist outside the context of | |
154 |
|
|
153 | # a repo, so just default to the last blackbox logger that | |
155 |
|
|
154 | # was seen. | |
156 |
|
|
155 | pass | |
157 |
|
|
156 | else: | |
158 |
|
|
157 | return | |
159 |
|
|
158 | _lastlogger._log(ui, event, msg, opts) | |
160 |
|
159 | |||
161 |
|
|
160 | def _log(self, ui, event, msg, opts): | |
162 |
|
|
161 | if getattr(self, '_bbinlog', False): | |
163 |
|
|
162 | # recursion and failure guard | |
164 |
|
|
163 | return | |
165 |
|
|
164 | self._bbinlog = True | |
166 |
|
|
165 | default = ui.configdate('devel', 'default-date') | |
167 |
|
|
166 | date = dateutil.datestr(default, ui.config('blackbox', 'date-format')) | |
168 | ui.config('blackbox', 'date-format')) |
|
167 | user = procutil.getuser() | |
169 |
|
|
168 | pid = '%d' % procutil.getpid() | |
170 | pid = '%d' % procutil.getpid() |
|
169 | formattedmsg = msg[0] % msg[1:] | |
171 | formattedmsg = msg[0] % msg[1:] |
|
170 | rev = '(unknown)' | |
172 | rev = '(unknown)' |
|
171 | changed = '' | |
173 | changed = '' |
|
172 | ctx = self._bbrepo[None] | |
174 | ctx = self._bbrepo[None] |
|
173 | parents = ctx.parents() | |
175 | parents = ctx.parents() |
|
174 | rev = ('+'.join([hex(p.node()) for p in parents])) | |
176 | rev = ('+'.join([hex(p.node()) for p in parents])) |
|
175 | if (ui.configbool('blackbox', 'dirty') and | |
177 | if (ui.configbool('blackbox', 'dirty') and |
|
176 | ctx.dirty(missing=True, merge=False, branch=False)): | |
178 | ctx.dirty(missing=True, merge=False, branch=False)): |
|
177 | changed = '+' | |
179 | changed = '+' |
|
178 | if ui.configbool('blackbox', 'logsource'): | |
180 | if ui.configbool('blackbox', 'logsource'): |
|
179 | src = ' [%s]' % event | |
181 | src = ' [%s]' % event |
|
180 | else: | |
182 |
|
|
181 | src = '' | |
183 | src = '' |
|
182 | try: | |
184 | try: |
|
183 | fmt = '%s %s @%s%s (%s)%s> %s' | |
185 | fmt = '%s %s @%s%s (%s)%s> %s' |
|
184 | args = (date, user, rev, changed, pid, src, formattedmsg) | |
186 | args = (date, user, rev, changed, pid, src, formattedmsg) |
|
185 | with _openlogfile(ui, self._bbvfs) as fp: | |
187 | with _openlogfile(ui, self._bbvfs) as fp: |
|
186 | fp.write(fmt % args) | |
188 | fp.write(fmt % args) |
|
187 | except (IOError, OSError) as err: | |
189 | except (IOError, OSError) as err: |
|
188 | ui.debug('warning: cannot write to blackbox.log: %s\n' % | |
190 | ui.debug('warning: cannot write to blackbox.log: %s\n' % |
|
189 | encoding.strtolocal(err.strerror)) | |
191 | encoding.strtolocal(err.strerror)) |
|
190 | # do not restore _bbinlog intentionally to avoid failed | |
192 | # do not restore _bbinlog intentionally to avoid failed |
|
191 | # logging again | |
193 | # logging again |
|
192 | else: | |
194 |
else |
|
193 | self._bbinlog = False | |
195 | self._bbinlog = False |
|
|||
196 |
|
194 | |||
197 |
|
|
195 | def setrepo(self, repo): | |
198 |
|
|
196 | self._bbrepo = repo | |
199 |
|
197 | |||
200 | def wrapui(ui): |
|
198 | def wrapui(ui): | |
201 | class blackboxui(ui.__class__): |
|
199 | class blackboxui(ui.__class__): | |
202 | def __init__(self, src=None): |
|
200 | def __init__(self, src=None): | |
203 | super(blackboxui, self).__init__(src) |
|
201 | super(blackboxui, self).__init__(src) | |
204 | if src and r'_bblogger' in src.__dict__: |
|
202 | if src and r'_bblogger' in src.__dict__: | |
205 | self._bblogger = src._bblogger |
|
203 | self._bblogger = src._bblogger | |
206 |
|
204 | |||
207 | # trick to initialize logger after configuration is loaded, which |
|
205 | # trick to initialize logger after configuration is loaded, which | |
208 | # can be replaced later with blackboxlogger(ui) in uisetup(), where |
|
206 | # can be replaced later with blackboxlogger(ui) in uisetup(), where | |
209 | # both user and repo configurations should be available. |
|
207 | # both user and repo configurations should be available. | |
210 | @util.propertycache |
|
208 | @util.propertycache | |
211 | def _bblogger(self): |
|
209 | def _bblogger(self): | |
212 | return blackboxlogger(self) |
|
210 | return blackboxlogger(self) | |
213 |
|
211 | |||
214 | def debug(self, *msg, **opts): |
|
212 | def debug(self, *msg, **opts): | |
215 | super(blackboxui, self).debug(*msg, **opts) |
|
213 | super(blackboxui, self).debug(*msg, **opts) | |
216 | if self.debugflag: |
|
214 | if self.debugflag: | |
217 | self.log('debug', '%s', ''.join(msg)) |
|
215 | self.log('debug', '%s', ''.join(msg)) | |
218 |
|
216 | |||
219 | def log(self, event, *msg, **opts): |
|
217 | def log(self, event, *msg, **opts): | |
220 | super(blackboxui, self).log(event, *msg, **opts) |
|
218 | super(blackboxui, self).log(event, *msg, **opts) | |
221 | self._bblogger.log(self, event, msg, opts) |
|
219 | self._bblogger.log(self, event, msg, opts) | |
222 |
|
220 | |||
223 | ui.__class__ = blackboxui |
|
221 | ui.__class__ = blackboxui | |
224 | uimod.ui = blackboxui |
|
222 | uimod.ui = blackboxui | |
225 |
|
223 | |||
226 | def uisetup(ui): |
|
224 | def uisetup(ui): | |
227 | wrapui(ui) |
|
225 | wrapui(ui) | |
228 |
|
226 | |||
229 | def reposetup(ui, repo): |
|
227 | def reposetup(ui, repo): | |
230 | # During 'hg pull' a httppeer repo is created to represent the remote repo. |
|
228 | # During 'hg pull' a httppeer repo is created to represent the remote repo. | |
231 | # It doesn't have a .hg directory to put a blackbox in, so we don't do |
|
229 | # It doesn't have a .hg directory to put a blackbox in, so we don't do | |
232 | # the blackbox setup for it. |
|
230 | # the blackbox setup for it. | |
233 | if not repo.local(): |
|
231 | if not repo.local(): | |
234 | return |
|
232 | return | |
235 |
|
233 | |||
236 | logger = getattr(ui, '_bblogger', None) |
|
234 | logger = getattr(ui, '_bblogger', None) | |
237 | if logger: |
|
235 | if logger: | |
238 | logger.setrepo(repo) |
|
236 | logger.setrepo(repo) | |
239 |
|
237 | |||
240 | # Set _lastlogger even if ui.log is not called. This gives blackbox a |
|
238 | # Set _lastlogger even if ui.log is not called. This gives blackbox a | |
241 | # fallback place to log. |
|
239 | # fallback place to log. | |
242 | global _lastlogger |
|
240 | global _lastlogger | |
243 | if _lastlogger is None: |
|
241 | if _lastlogger is None: | |
244 | _lastlogger = logger |
|
242 | _lastlogger = logger | |
245 |
|
243 | |||
246 | repo._wlockfreeprefix.add('blackbox.log') |
|
244 | repo._wlockfreeprefix.add('blackbox.log') | |
247 |
|
245 | |||
248 | @command('blackbox', |
|
246 | @command('blackbox', | |
249 | [('l', 'limit', 10, _('the number of events to show')), |
|
247 | [('l', 'limit', 10, _('the number of events to show')), | |
250 | ], |
|
248 | ], | |
251 | _('hg blackbox [OPTION]...'), |
|
249 | _('hg blackbox [OPTION]...'), | |
252 | helpcategory=command.CATEGORY_MAINTENANCE, |
|
250 | helpcategory=command.CATEGORY_MAINTENANCE, | |
253 | helpbasic=True) |
|
251 | helpbasic=True) | |
254 | def blackbox(ui, repo, *revs, **opts): |
|
252 | def blackbox(ui, repo, *revs, **opts): | |
255 | '''view the recent repository events |
|
253 | '''view the recent repository events | |
256 | ''' |
|
254 | ''' | |
257 |
|
255 | |||
258 | if not repo.vfs.exists('blackbox.log'): |
|
256 | if not repo.vfs.exists('blackbox.log'): | |
259 | return |
|
257 | return | |
260 |
|
258 | |||
261 | limit = opts.get(r'limit') |
|
259 | limit = opts.get(r'limit') | |
262 | fp = repo.vfs('blackbox.log', 'r') |
|
260 | fp = repo.vfs('blackbox.log', 'r') | |
263 | lines = fp.read().split('\n') |
|
261 | lines = fp.read().split('\n') | |
264 |
|
262 | |||
265 | count = 0 |
|
263 | count = 0 | |
266 | output = [] |
|
264 | output = [] | |
267 | for line in reversed(lines): |
|
265 | for line in reversed(lines): | |
268 | if count >= limit: |
|
266 | if count >= limit: | |
269 | break |
|
267 | break | |
270 |
|
268 | |||
271 | # count the commands by matching lines like: 2013/01/23 19:13:36 root> |
|
269 | # count the commands by matching lines like: 2013/01/23 19:13:36 root> | |
272 | if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): |
|
270 | if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): | |
273 | count += 1 |
|
271 | count += 1 | |
274 | output.append(line) |
|
272 | output.append(line) | |
275 |
|
273 | |||
276 | ui.status('\n'.join(reversed(output))) |
|
274 | ui.status('\n'.join(reversed(output))) |
General Comments 0
You need to be logged in to leave comments.
Login now