##// END OF EJS Templates
blackbox: extract global last logger to proxylogger class...
Yuya Nishihara -
r40795:37d6ee46 default
parent child Browse files
Show More
@@ -1,242 +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 _lastlogger = None
93
94 def _openlogfile(ui, vfs):
92 def _openlogfile(ui, vfs):
95 def rotate(oldpath, newpath):
93 def rotate(oldpath, newpath):
96 try:
94 try:
97 vfs.unlink(newpath)
95 vfs.unlink(newpath)
98 except OSError as err:
96 except OSError as err:
99 if err.errno != errno.ENOENT:
97 if err.errno != errno.ENOENT:
100 ui.debug("warning: cannot remove '%s': %s\n" %
98 ui.debug("warning: cannot remove '%s': %s\n" %
101 (newpath, err.strerror))
99 (newpath, err.strerror))
102 try:
100 try:
103 if newpath:
101 if newpath:
104 vfs.rename(oldpath, newpath)
102 vfs.rename(oldpath, newpath)
105 except OSError as err:
103 except OSError as err:
106 if err.errno != errno.ENOENT:
104 if err.errno != errno.ENOENT:
107 ui.debug("warning: cannot rename '%s' to '%s': %s\n" %
105 ui.debug("warning: cannot rename '%s' to '%s': %s\n" %
108 (newpath, oldpath, err.strerror))
106 (newpath, oldpath, err.strerror))
109
107
110 maxsize = ui.configbytes('blackbox', 'maxsize')
108 maxsize = ui.configbytes('blackbox', 'maxsize')
111 name = 'blackbox.log'
109 name = 'blackbox.log'
112 if maxsize > 0:
110 if maxsize > 0:
113 try:
111 try:
114 st = vfs.stat(name)
112 st = vfs.stat(name)
115 except OSError:
113 except OSError:
116 pass
114 pass
117 else:
115 else:
118 if st.st_size >= maxsize:
116 if st.st_size >= maxsize:
119 path = vfs.join(name)
117 path = vfs.join(name)
120 maxfiles = ui.configint('blackbox', 'maxfiles')
118 maxfiles = ui.configint('blackbox', 'maxfiles')
121 for i in pycompat.xrange(maxfiles - 1, 1, -1):
119 for i in pycompat.xrange(maxfiles - 1, 1, -1):
122 rotate(oldpath='%s.%d' % (path, i - 1),
120 rotate(oldpath='%s.%d' % (path, i - 1),
123 newpath='%s.%d' % (path, i))
121 newpath='%s.%d' % (path, i))
124 rotate(oldpath=path,
122 rotate(oldpath=path,
125 newpath=maxfiles > 0 and path + '.1')
123 newpath=maxfiles > 0 and path + '.1')
126 return vfs(name, 'a')
124 return vfs(name, 'a')
127
125
126 class proxylogger(object):
127 """Forward log events to another logger to be set later"""
128
129 def __init__(self):
130 self.logger = None
131
132 def tracked(self, event):
133 return self.logger is not None and self.logger.tracked(event)
134
135 def log(self, ui, event, msg, opts):
136 assert self.logger is not None
137 self.logger.log(ui, event, msg, opts)
138
139 _lastlogger = proxylogger()
140
128 class blackboxlogger(object):
141 class blackboxlogger(object):
129 def __init__(self, ui):
142 def __init__(self, ui):
130 self._repo = None
143 self._repo = None
131 self._trackedevents = set(ui.configlist('blackbox', 'track'))
144 self._trackedevents = set(ui.configlist('blackbox', 'track'))
132
145
133 @property
146 @property
134 def _bbvfs(self):
147 def _bbvfs(self):
135 vfs = None
148 vfs = None
136 if self._repo:
149 if self._repo:
137 vfs = self._repo.vfs
150 vfs = self._repo.vfs
138 if not vfs.isdir('.'):
151 if not vfs.isdir('.'):
139 vfs = None
152 vfs = None
140 return vfs
153 return vfs
141
154
142 def tracked(self, event):
155 def tracked(self, event):
143 return b'*' in self._trackedevents or event in self._trackedevents
156 return b'*' in self._trackedevents or event in self._trackedevents
144
157
145 def log(self, ui, event, msg, opts):
158 def log(self, ui, event, msg, opts):
146 global _lastlogger
147 if self._bbvfs:
159 if self._bbvfs:
148 _lastlogger = self
160 _lastlogger.logger = self
149 elif _lastlogger and _lastlogger._bbvfs:
150 # certain logger instances exist outside the context of
151 # a repo, so just default to the last blackbox logger that
152 # was seen.
153 pass
154 else:
161 else:
155 return
162 return
156 _lastlogger._log(ui, event, msg, opts)
157
163
158 def _log(self, ui, event, msg, opts):
159 default = ui.configdate('devel', 'default-date')
164 default = ui.configdate('devel', 'default-date')
160 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
165 date = dateutil.datestr(default, ui.config('blackbox', 'date-format'))
161 user = procutil.getuser()
166 user = procutil.getuser()
162 pid = '%d' % procutil.getpid()
167 pid = '%d' % procutil.getpid()
163 rev = '(unknown)'
168 rev = '(unknown)'
164 changed = ''
169 changed = ''
165 ctx = self._repo[None]
170 ctx = self._repo[None]
166 parents = ctx.parents()
171 parents = ctx.parents()
167 rev = ('+'.join([hex(p.node()) for p in parents]))
172 rev = ('+'.join([hex(p.node()) for p in parents]))
168 if (ui.configbool('blackbox', 'dirty') and
173 if (ui.configbool('blackbox', 'dirty') and
169 ctx.dirty(missing=True, merge=False, branch=False)):
174 ctx.dirty(missing=True, merge=False, branch=False)):
170 changed = '+'
175 changed = '+'
171 if ui.configbool('blackbox', 'logsource'):
176 if ui.configbool('blackbox', 'logsource'):
172 src = ' [%s]' % event
177 src = ' [%s]' % event
173 else:
178 else:
174 src = ''
179 src = ''
175 try:
180 try:
176 fmt = '%s %s @%s%s (%s)%s> %s'
181 fmt = '%s %s @%s%s (%s)%s> %s'
177 args = (date, user, rev, changed, pid, src, msg)
182 args = (date, user, rev, changed, pid, src, msg)
178 with _openlogfile(ui, self._bbvfs) as fp:
183 with _openlogfile(ui, self._bbvfs) as fp:
179 fp.write(fmt % args)
184 fp.write(fmt % args)
180 except (IOError, OSError) as err:
185 except (IOError, OSError) as err:
181 # deactivate this to avoid failed logging again
186 # deactivate this to avoid failed logging again
182 self._repo = None
187 self._repo = None
183 ui.debug('warning: cannot write to blackbox.log: %s\n' %
188 ui.debug('warning: cannot write to blackbox.log: %s\n' %
184 encoding.strtolocal(err.strerror))
189 encoding.strtolocal(err.strerror))
185
190
186 def setrepo(self, repo):
191 def setrepo(self, repo):
187 self._repo = repo
192 self._repo = repo
188
193
189 def uipopulate(ui):
194 def uipopulate(ui):
190 ui.setlogger(b'blackbox', blackboxlogger(ui))
195 ui.setlogger(b'blackbox', _lastlogger)
191
196
192 def reposetup(ui, repo):
197 def reposetup(ui, repo):
193 # 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.
194 # 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
195 # the blackbox setup for it.
200 # the blackbox setup for it.
196 if not repo.local():
201 if not repo.local():
197 return
202 return
198
203
199 # 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
200 # instantiated per repository.
205 # instantiated per repository.
201 logger = blackboxlogger(ui)
206 logger = blackboxlogger(ui)
202 ui.setlogger(b'blackbox', logger)
207 ui.setlogger(b'blackbox', logger)
203 if logger:
208 logger.setrepo(repo)
204 logger.setrepo(repo)
205
209
206 # 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
207 # fallback place to log.
211 # fallback place to log
208 global _lastlogger
212 if _lastlogger.logger is None:
209 if _lastlogger is None:
213 _lastlogger.logger = logger
210 _lastlogger = logger
211
214
212 repo._wlockfreeprefix.add('blackbox.log')
215 repo._wlockfreeprefix.add('blackbox.log')
213
216
214 @command('blackbox',
217 @command('blackbox',
215 [('l', 'limit', 10, _('the number of events to show')),
218 [('l', 'limit', 10, _('the number of events to show')),
216 ],
219 ],
217 _('hg blackbox [OPTION]...'),
220 _('hg blackbox [OPTION]...'),
218 helpcategory=command.CATEGORY_MAINTENANCE,
221 helpcategory=command.CATEGORY_MAINTENANCE,
219 helpbasic=True)
222 helpbasic=True)
220 def blackbox(ui, repo, *revs, **opts):
223 def blackbox(ui, repo, *revs, **opts):
221 '''view the recent repository events
224 '''view the recent repository events
222 '''
225 '''
223
226
224 if not repo.vfs.exists('blackbox.log'):
227 if not repo.vfs.exists('blackbox.log'):
225 return
228 return
226
229
227 limit = opts.get(r'limit')
230 limit = opts.get(r'limit')
228 fp = repo.vfs('blackbox.log', 'r')
231 fp = repo.vfs('blackbox.log', 'r')
229 lines = fp.read().split('\n')
232 lines = fp.read().split('\n')
230
233
231 count = 0
234 count = 0
232 output = []
235 output = []
233 for line in reversed(lines):
236 for line in reversed(lines):
234 if count >= limit:
237 if count >= limit:
235 break
238 break
236
239
237 # 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>
238 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):
239 count += 1
242 count += 1
240 output.append(line)
243 output.append(line)
241
244
242 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