Show More
@@ -1,115 +1,115 | |||||
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 | Examples: |
|
13 | Examples: | |
14 |
|
14 | |||
15 | [blackbox] |
|
15 | [blackbox] | |
16 | track = * |
|
16 | track = * | |
17 |
|
17 | |||
18 | [blackbox] |
|
18 | [blackbox] | |
19 | track = command, commandfinish, commandexception, exthook, pythonhook |
|
19 | track = command, commandfinish, commandexception, exthook, pythonhook | |
20 |
|
20 | |||
21 | [blackbox] |
|
21 | [blackbox] | |
22 | track = incoming |
|
22 | track = incoming | |
23 |
|
23 | |||
24 | """ |
|
24 | """ | |
25 |
|
25 | |||
26 | from mercurial import util, cmdutil |
|
26 | from mercurial import util, cmdutil | |
27 | from mercurial.i18n import _ |
|
27 | from mercurial.i18n import _ | |
28 |
import os, |
|
28 | import os, re | |
29 |
|
29 | |||
30 | cmdtable = {} |
|
30 | cmdtable = {} | |
31 | command = cmdutil.command(cmdtable) |
|
31 | command = cmdutil.command(cmdtable) | |
32 | testedwith = 'internal' |
|
32 | testedwith = 'internal' | |
33 | lastblackbox = None |
|
33 | lastblackbox = None | |
34 |
|
34 | |||
35 | def wrapui(ui): |
|
35 | def wrapui(ui): | |
36 | class blackboxui(ui.__class__): |
|
36 | class blackboxui(ui.__class__): | |
37 | @util.propertycache |
|
37 | @util.propertycache | |
38 | def track(self): |
|
38 | def track(self): | |
39 | return ui.configlist('blackbox', 'track', ['*']) |
|
39 | return ui.configlist('blackbox', 'track', ['*']) | |
40 |
|
40 | |||
41 | def log(self, event, *msg, **opts): |
|
41 | def log(self, event, *msg, **opts): | |
42 | global lastblackbox |
|
42 | global lastblackbox | |
43 | super(blackboxui, self).log(event, *msg, **opts) |
|
43 | super(blackboxui, self).log(event, *msg, **opts) | |
44 |
|
44 | |||
45 | if not '*' in self.track and not event in self.track: |
|
45 | if not '*' in self.track and not event in self.track: | |
46 | return |
|
46 | return | |
47 |
|
47 | |||
48 | if util.safehasattr(self, '_blackbox'): |
|
48 | if util.safehasattr(self, '_blackbox'): | |
49 | blackbox = self._blackbox |
|
49 | blackbox = self._blackbox | |
50 | else: |
|
50 | else: | |
51 | # certain ui instances exist outside the context of |
|
51 | # certain ui instances exist outside the context of | |
52 | # a repo, so just default to the last blackbox that |
|
52 | # a repo, so just default to the last blackbox that | |
53 | # was seen. |
|
53 | # was seen. | |
54 | blackbox = lastblackbox |
|
54 | blackbox = lastblackbox | |
55 |
|
55 | |||
56 | if blackbox: |
|
56 | if blackbox: | |
57 | date = util.datestr(None, '%Y/%m/%d %H:%M:%S') |
|
57 | date = util.datestr(None, '%Y/%m/%d %H:%M:%S') | |
58 |
user = |
|
58 | user = util.getuser() | |
59 | formattedmsg = msg[0] % msg[1:] |
|
59 | formattedmsg = msg[0] % msg[1:] | |
60 | try: |
|
60 | try: | |
61 | blackbox.write('%s %s> %s' % (date, user, formattedmsg)) |
|
61 | blackbox.write('%s %s> %s' % (date, user, formattedmsg)) | |
62 | except IOError, err: |
|
62 | except IOError, err: | |
63 | self.debug('warning: cannot write to blackbox.log: %s\n' % |
|
63 | self.debug('warning: cannot write to blackbox.log: %s\n' % | |
64 | err.strerror) |
|
64 | err.strerror) | |
65 | lastblackbox = blackbox |
|
65 | lastblackbox = blackbox | |
66 |
|
66 | |||
67 | def setrepo(self, repo): |
|
67 | def setrepo(self, repo): | |
68 | try: |
|
68 | try: | |
69 | self._blackbox = repo.opener('blackbox.log', 'a') |
|
69 | self._blackbox = repo.opener('blackbox.log', 'a') | |
70 | except IOError, err: |
|
70 | except IOError, err: | |
71 | self.debug('warning: cannot write to blackbox.log: %s\n' % |
|
71 | self.debug('warning: cannot write to blackbox.log: %s\n' % | |
72 | err.strerror) |
|
72 | err.strerror) | |
73 | self._blackbox = None |
|
73 | self._blackbox = None | |
74 |
|
74 | |||
75 | ui.__class__ = blackboxui |
|
75 | ui.__class__ = blackboxui | |
76 |
|
76 | |||
77 | def uisetup(ui): |
|
77 | def uisetup(ui): | |
78 | wrapui(ui) |
|
78 | wrapui(ui) | |
79 |
|
79 | |||
80 | def reposetup(ui, repo): |
|
80 | def reposetup(ui, repo): | |
81 | # During 'hg pull' a httppeer repo is created to represent the remote repo. |
|
81 | # During 'hg pull' a httppeer repo is created to represent the remote repo. | |
82 | # It doesn't have a .hg directory to put a blackbox in, so we don't do |
|
82 | # It doesn't have a .hg directory to put a blackbox in, so we don't do | |
83 | # the blackbox setup for it. |
|
83 | # the blackbox setup for it. | |
84 | if not repo.local(): |
|
84 | if not repo.local(): | |
85 | return |
|
85 | return | |
86 |
|
86 | |||
87 | ui.setrepo(repo) |
|
87 | ui.setrepo(repo) | |
88 |
|
88 | |||
89 | @command('^blackbox', |
|
89 | @command('^blackbox', | |
90 | [('l', 'limit', 10, _('the number of events to show')), |
|
90 | [('l', 'limit', 10, _('the number of events to show')), | |
91 | ], |
|
91 | ], | |
92 | _('hg blackbox [OPTION]...')) |
|
92 | _('hg blackbox [OPTION]...')) | |
93 | def blackbox(ui, repo, *revs, **opts): |
|
93 | def blackbox(ui, repo, *revs, **opts): | |
94 | '''view the recent repository events |
|
94 | '''view the recent repository events | |
95 | ''' |
|
95 | ''' | |
96 |
|
96 | |||
97 | if not os.path.exists(repo.join('blackbox.log')): |
|
97 | if not os.path.exists(repo.join('blackbox.log')): | |
98 | return |
|
98 | return | |
99 |
|
99 | |||
100 | limit = opts.get('limit') |
|
100 | limit = opts.get('limit') | |
101 | blackbox = repo.opener('blackbox.log', 'r') |
|
101 | blackbox = repo.opener('blackbox.log', 'r') | |
102 | lines = blackbox.read().split('\n') |
|
102 | lines = blackbox.read().split('\n') | |
103 |
|
103 | |||
104 | count = 0 |
|
104 | count = 0 | |
105 | output = [] |
|
105 | output = [] | |
106 | for line in reversed(lines): |
|
106 | for line in reversed(lines): | |
107 | if count >= limit: |
|
107 | if count >= limit: | |
108 | break |
|
108 | break | |
109 |
|
109 | |||
110 | # count the commands by matching lines like: 2013/01/23 19:13:36 root> |
|
110 | # count the commands by matching lines like: 2013/01/23 19:13:36 root> | |
111 | if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): |
|
111 | if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): | |
112 | count += 1 |
|
112 | count += 1 | |
113 | output.append(line) |
|
113 | output.append(line) | |
114 |
|
114 | |||
115 | ui.status('\n'.join(reversed(output))) |
|
115 | ui.status('\n'.join(reversed(output))) |
@@ -1,136 +1,135 | |||||
1 | setup |
|
1 | setup | |
2 | $ cat > mock.py <<EOF |
|
2 | $ cat > mock.py <<EOF | |
3 | > from mercurial import util |
|
3 | > from mercurial import util | |
4 | > import getpass |
|
|||
5 | > |
|
4 | > | |
6 | > def makedate(): |
|
5 | > def makedate(): | |
7 | > return 0, 0 |
|
6 | > return 0, 0 | |
8 | > def getuser(): |
|
7 | > def getuser(): | |
9 | > return 'bob' |
|
8 | > return 'bob' | |
10 | > # mock the date and user apis so the output is always the same |
|
9 | > # mock the date and user apis so the output is always the same | |
11 | > def uisetup(ui): |
|
10 | > def uisetup(ui): | |
12 | > util.makedate = makedate |
|
11 | > util.makedate = makedate | |
13 |
> |
|
12 | > util.getuser = getuser | |
14 | > EOF |
|
13 | > EOF | |
15 | $ cat >> $HGRCPATH <<EOF |
|
14 | $ cat >> $HGRCPATH <<EOF | |
16 | > [extensions] |
|
15 | > [extensions] | |
17 | > blackbox= |
|
16 | > blackbox= | |
18 | > mock=`pwd`/mock.py |
|
17 | > mock=`pwd`/mock.py | |
19 | > mq= |
|
18 | > mq= | |
20 | > EOF |
|
19 | > EOF | |
21 | $ hg init blackboxtest |
|
20 | $ hg init blackboxtest | |
22 | $ cd blackboxtest |
|
21 | $ cd blackboxtest | |
23 |
|
22 | |||
24 | command, exit codes, and duration |
|
23 | command, exit codes, and duration | |
25 |
|
24 | |||
26 | $ echo a > a |
|
25 | $ echo a > a | |
27 | $ hg add a |
|
26 | $ hg add a | |
28 | $ hg blackbox |
|
27 | $ hg blackbox | |
29 | 1970/01/01 00:00:00 bob> add a |
|
28 | 1970/01/01 00:00:00 bob> add a | |
30 | 1970/01/01 00:00:00 bob> add exited 0 after * seconds (glob) |
|
29 | 1970/01/01 00:00:00 bob> add exited 0 after * seconds (glob) | |
31 |
|
30 | |||
32 | incoming change tracking |
|
31 | incoming change tracking | |
33 |
|
32 | |||
34 | create two heads to verify that we only see one change in the log later |
|
33 | create two heads to verify that we only see one change in the log later | |
35 | $ hg commit -ma |
|
34 | $ hg commit -ma | |
36 | $ hg up null |
|
35 | $ hg up null | |
37 | 0 files updated, 0 files merged, 1 files removed, 0 files unresolved |
|
36 | 0 files updated, 0 files merged, 1 files removed, 0 files unresolved | |
38 | $ echo b > b |
|
37 | $ echo b > b | |
39 | $ hg commit -Amb |
|
38 | $ hg commit -Amb | |
40 | adding b |
|
39 | adding b | |
41 | created new head |
|
40 | created new head | |
42 |
|
41 | |||
43 | clone, commit, pull |
|
42 | clone, commit, pull | |
44 | $ hg clone . ../blackboxtest2 |
|
43 | $ hg clone . ../blackboxtest2 | |
45 | updating to branch default |
|
44 | updating to branch default | |
46 | 1 files updated, 0 files merged, 0 files removed, 0 files unresolved |
|
45 | 1 files updated, 0 files merged, 0 files removed, 0 files unresolved | |
47 | $ echo c > c |
|
46 | $ echo c > c | |
48 | $ hg commit -Amc |
|
47 | $ hg commit -Amc | |
49 | adding c |
|
48 | adding c | |
50 | $ cd ../blackboxtest2 |
|
49 | $ cd ../blackboxtest2 | |
51 | $ hg pull |
|
50 | $ hg pull | |
52 | pulling from $TESTTMP/blackboxtest (glob) |
|
51 | pulling from $TESTTMP/blackboxtest (glob) | |
53 | searching for changes |
|
52 | searching for changes | |
54 | adding changesets |
|
53 | adding changesets | |
55 | adding manifests |
|
54 | adding manifests | |
56 | adding file changes |
|
55 | adding file changes | |
57 | added 1 changesets with 1 changes to 1 files |
|
56 | added 1 changesets with 1 changes to 1 files | |
58 | (run 'hg update' to get a working copy) |
|
57 | (run 'hg update' to get a working copy) | |
59 | $ hg blackbox -l 3 |
|
58 | $ hg blackbox -l 3 | |
60 | 1970/01/01 00:00:00 bob> pull |
|
59 | 1970/01/01 00:00:00 bob> pull | |
61 | 1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62 |
|
60 | 1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62 | |
62 | 1970/01/01 00:00:00 bob> pull exited None after * seconds (glob) |
|
61 | 1970/01/01 00:00:00 bob> pull exited None after * seconds (glob) | |
63 |
|
62 | |||
64 | we must not cause a failure if we cannot write to the log |
|
63 | we must not cause a failure if we cannot write to the log | |
65 |
|
64 | |||
66 | $ hg rollback |
|
65 | $ hg rollback | |
67 | repository tip rolled back to revision 1 (undo pull) |
|
66 | repository tip rolled back to revision 1 (undo pull) | |
68 | $ chmod 000 .hg/blackbox.log |
|
67 | $ chmod 000 .hg/blackbox.log | |
69 | $ hg --debug incoming |
|
68 | $ hg --debug incoming | |
70 | warning: cannot write to blackbox.log: Permission denied |
|
69 | warning: cannot write to blackbox.log: Permission denied | |
71 | comparing with $TESTTMP/blackboxtest |
|
70 | comparing with $TESTTMP/blackboxtest | |
72 | query 1; heads |
|
71 | query 1; heads | |
73 | searching for changes |
|
72 | searching for changes | |
74 | all local heads known remotely |
|
73 | all local heads known remotely | |
75 | changeset: 2:d02f48003e62c24e2659d97d30f2a83abe5d5d51 |
|
74 | changeset: 2:d02f48003e62c24e2659d97d30f2a83abe5d5d51 | |
76 | tag: tip |
|
75 | tag: tip | |
77 | phase: draft |
|
76 | phase: draft | |
78 | parent: 1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06 |
|
77 | parent: 1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06 | |
79 | parent: -1:0000000000000000000000000000000000000000 |
|
78 | parent: -1:0000000000000000000000000000000000000000 | |
80 | manifest: 2:ab9d46b053ebf45b7996f2922b9893ff4b63d892 |
|
79 | manifest: 2:ab9d46b053ebf45b7996f2922b9893ff4b63d892 | |
81 | user: test |
|
80 | user: test | |
82 | date: Thu Jan 01 00:00:00 1970 +0000 |
|
81 | date: Thu Jan 01 00:00:00 1970 +0000 | |
83 | files+: c |
|
82 | files+: c | |
84 | extra: branch=default |
|
83 | extra: branch=default | |
85 | description: |
|
84 | description: | |
86 | c |
|
85 | c | |
87 |
|
86 | |||
88 |
|
87 | |||
89 | $ hg pull |
|
88 | $ hg pull | |
90 | pulling from $TESTTMP/blackboxtest |
|
89 | pulling from $TESTTMP/blackboxtest | |
91 | searching for changes |
|
90 | searching for changes | |
92 | adding changesets |
|
91 | adding changesets | |
93 | adding manifests |
|
92 | adding manifests | |
94 | adding file changes |
|
93 | adding file changes | |
95 | added 1 changesets with 1 changes to 1 files |
|
94 | added 1 changesets with 1 changes to 1 files | |
96 | (run 'hg update' to get a working copy) |
|
95 | (run 'hg update' to get a working copy) | |
97 |
|
96 | |||
98 | a failure reading from the log is fine |
|
97 | a failure reading from the log is fine | |
99 |
|
98 | |||
100 | $ hg blackbox -l 3 |
|
99 | $ hg blackbox -l 3 | |
101 | abort: Permission denied: $TESTTMP/blackboxtest2/.hg/blackbox.log |
|
100 | abort: Permission denied: $TESTTMP/blackboxtest2/.hg/blackbox.log | |
102 | [255] |
|
101 | [255] | |
103 |
|
102 | |||
104 | $ chmod 600 .hg/blackbox.log |
|
103 | $ chmod 600 .hg/blackbox.log | |
105 |
|
104 | |||
106 | backup bundles get logged |
|
105 | backup bundles get logged | |
107 |
|
106 | |||
108 | $ touch d |
|
107 | $ touch d | |
109 | $ hg commit -Amd |
|
108 | $ hg commit -Amd | |
110 | adding d |
|
109 | adding d | |
111 | created new head |
|
110 | created new head | |
112 | $ hg strip tip |
|
111 | $ hg strip tip | |
113 | 0 files updated, 0 files merged, 1 files removed, 0 files unresolved |
|
112 | 0 files updated, 0 files merged, 1 files removed, 0 files unresolved | |
114 | saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob) |
|
113 | saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob) | |
115 | $ hg blackbox -l 3 |
|
114 | $ hg blackbox -l 3 | |
116 | 1970/01/01 00:00:00 bob> strip tip |
|
115 | 1970/01/01 00:00:00 bob> strip tip | |
117 | 1970/01/01 00:00:00 bob> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob) |
|
116 | 1970/01/01 00:00:00 bob> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob) | |
118 | 1970/01/01 00:00:00 bob> strip exited 0 after * seconds (glob) |
|
117 | 1970/01/01 00:00:00 bob> strip exited 0 after * seconds (glob) | |
119 |
|
118 | |||
120 | extension and python hooks - use the eol extension for a pythonhook |
|
119 | extension and python hooks - use the eol extension for a pythonhook | |
121 |
|
120 | |||
122 | $ echo '[extensions]' >> .hg/hgrc |
|
121 | $ echo '[extensions]' >> .hg/hgrc | |
123 | $ echo 'eol=' >> .hg/hgrc |
|
122 | $ echo 'eol=' >> .hg/hgrc | |
124 | $ echo '[hooks]' >> .hg/hgrc |
|
123 | $ echo '[hooks]' >> .hg/hgrc | |
125 | $ echo 'update = echo hooked' >> .hg/hgrc |
|
124 | $ echo 'update = echo hooked' >> .hg/hgrc | |
126 | $ hg update |
|
125 | $ hg update | |
127 | hooked |
|
126 | hooked | |
128 | 1 files updated, 0 files merged, 0 files removed, 0 files unresolved |
|
127 | 1 files updated, 0 files merged, 0 files removed, 0 files unresolved | |
129 | $ hg blackbox -l 4 |
|
128 | $ hg blackbox -l 4 | |
130 | 1970/01/01 00:00:00 bob> update |
|
129 | 1970/01/01 00:00:00 bob> update | |
131 | 1970/01/01 00:00:00 bob> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob) |
|
130 | 1970/01/01 00:00:00 bob> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob) | |
132 | 1970/01/01 00:00:00 bob> exthook-update: echo hooked finished in * seconds (glob) |
|
131 | 1970/01/01 00:00:00 bob> exthook-update: echo hooked finished in * seconds (glob) | |
133 | 1970/01/01 00:00:00 bob> update exited False after * seconds (glob) |
|
132 | 1970/01/01 00:00:00 bob> update exited False after * seconds (glob) | |
134 |
|
133 | |||
135 | cleanup |
|
134 | cleanup | |
136 | $ cd .. |
|
135 | $ cd .. |
General Comments 0
You need to be logged in to leave comments.
Login now