Show More
@@ -1,137 +1,142 b'' | |||||
1 | # logtoprocess.py - send ui.log() data to a subprocess |
|
1 | # logtoprocess.py - send ui.log() data to a subprocess | |
2 | # |
|
2 | # | |
3 | # Copyright 2016 Facebook, Inc. |
|
3 | # Copyright 2016 Facebook, Inc. | |
4 | # |
|
4 | # | |
5 | # This software may be used and distributed according to the terms of the |
|
5 | # This software may be used and distributed according to the terms of the | |
6 | # GNU General Public License version 2 or any later version. |
|
6 | # GNU General Public License version 2 or any later version. | |
7 | """send ui.log() data to a subprocess (EXPERIMENTAL) |
|
7 | """send ui.log() data to a subprocess (EXPERIMENTAL) | |
8 |
|
8 | |||
9 | This extension lets you specify a shell command per ui.log() event, |
|
9 | This extension lets you specify a shell command per ui.log() event, | |
10 | sending all remaining arguments to as environment variables to that command. |
|
10 | sending all remaining arguments to as environment variables to that command. | |
11 |
|
11 | |||
12 | Each positional argument to the method results in a `MSG[N]` key in the |
|
12 | Each positional argument to the method results in a `MSG[N]` key in the | |
13 | environment, starting at 1 (so `MSG1`, `MSG2`, etc.). Each keyword argument |
|
13 | environment, starting at 1 (so `MSG1`, `MSG2`, etc.). Each keyword argument | |
14 | is set as a `OPT_UPPERCASE_KEY` variable (so the key is uppercased, and |
|
14 | is set as a `OPT_UPPERCASE_KEY` variable (so the key is uppercased, and | |
15 | prefixed with `OPT_`). The original event name is passed in the `EVENT` |
|
15 | prefixed with `OPT_`). The original event name is passed in the `EVENT` | |
16 | environment variable, and the process ID of mercurial is given in `HGPID`. |
|
16 | environment variable, and the process ID of mercurial is given in `HGPID`. | |
17 |
|
17 | |||
18 | So given a call `ui.log('foo', 'bar', 'baz', spam='eggs'), a script configured |
|
18 | So given a call `ui.log('foo', 'bar', 'baz', spam='eggs'), a script configured | |
19 | for the `foo` event can expect an environment with `MSG1=bar`, `MSG2=baz`, and |
|
19 | for the `foo` event can expect an environment with `MSG1=bar`, `MSG2=baz`, and | |
20 | `OPT_SPAM=eggs`. |
|
20 | `OPT_SPAM=eggs`. | |
21 |
|
21 | |||
22 | Scripts are configured in the `[logtoprocess]` section, each key an event name. |
|
22 | Scripts are configured in the `[logtoprocess]` section, each key an event name. | |
23 | For example:: |
|
23 | For example:: | |
24 |
|
24 | |||
25 | [logtoprocess] |
|
25 | [logtoprocess] | |
26 | commandexception = echo "$MSG2$MSG3" > /var/log/mercurial_exceptions.log |
|
26 | commandexception = echo "$MSG2$MSG3" > /var/log/mercurial_exceptions.log | |
27 |
|
27 | |||
28 | would log the warning message and traceback of any failed command dispatch. |
|
28 | would log the warning message and traceback of any failed command dispatch. | |
29 |
|
29 | |||
30 | Scripts are run asynchronously as detached daemon processes; mercurial will |
|
30 | Scripts are run asynchronously as detached daemon processes; mercurial will | |
31 | not ensure that they exit cleanly. |
|
31 | not ensure that they exit cleanly. | |
32 |
|
32 | |||
33 | """ |
|
33 | """ | |
34 |
|
34 | |||
35 | from __future__ import absolute_import |
|
35 | from __future__ import absolute_import | |
36 |
|
36 | |||
37 | import itertools |
|
37 | import itertools | |
38 | import os |
|
38 | import os | |
39 | import subprocess |
|
39 | import subprocess | |
40 | import sys |
|
40 | import sys | |
41 |
|
41 | |||
42 | from mercurial import ( |
|
42 | from mercurial import ( | |
43 | pycompat, |
|
43 | pycompat, | |
44 | ) |
|
44 | ) | |
45 |
|
45 | |||
46 | from mercurial.utils import ( |
|
46 | from mercurial.utils import ( | |
47 | procutil, |
|
47 | procutil, | |
48 | ) |
|
48 | ) | |
49 |
|
49 | |||
50 | # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for |
|
50 | # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for | |
51 | # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should |
|
51 | # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should | |
52 | # be specifying the version(s) of Mercurial they are tested with, or |
|
52 | # be specifying the version(s) of Mercurial they are tested with, or | |
53 | # leave the attribute unspecified. |
|
53 | # leave the attribute unspecified. | |
54 | testedwith = 'ships-with-hg-core' |
|
54 | testedwith = 'ships-with-hg-core' | |
55 |
|
55 | |||
56 | def uisetup(ui): |
|
56 | def uisetup(ui): | |
57 | if pycompat.iswindows: |
|
57 | if pycompat.iswindows: | |
58 | # no fork on Windows, but we can create a detached process |
|
58 | # no fork on Windows, but we can create a detached process | |
59 | # https://msdn.microsoft.com/en-us/library/windows/desktop/ms684863.aspx |
|
59 | # https://msdn.microsoft.com/en-us/library/windows/desktop/ms684863.aspx | |
60 | # No stdlib constant exists for this value |
|
60 | # No stdlib constant exists for this value | |
61 | DETACHED_PROCESS = 0x00000008 |
|
61 | DETACHED_PROCESS = 0x00000008 | |
62 | _creationflags = DETACHED_PROCESS | subprocess.CREATE_NEW_PROCESS_GROUP |
|
62 | _creationflags = DETACHED_PROCESS | subprocess.CREATE_NEW_PROCESS_GROUP | |
63 |
|
63 | |||
64 | def runshellcommand(script, env): |
|
64 | def runshellcommand(script, env): | |
65 | # we can't use close_fds *and* redirect stdin. I'm not sure that we |
|
65 | # we can't use close_fds *and* redirect stdin. I'm not sure that we | |
66 | # need to because the detached process has no console connection. |
|
66 | # need to because the detached process has no console connection. | |
67 | subprocess.Popen( |
|
67 | subprocess.Popen( | |
68 | procutil.tonativestr(script), |
|
68 | procutil.tonativestr(script), | |
69 | shell=True, env=procutil.tonativeenv(env), close_fds=True, |
|
69 | shell=True, env=procutil.tonativeenv(env), close_fds=True, | |
70 | creationflags=_creationflags) |
|
70 | creationflags=_creationflags) | |
71 | else: |
|
71 | else: | |
72 | def runshellcommand(script, env): |
|
72 | def runshellcommand(script, env): | |
73 | # double-fork to completely detach from the parent process |
|
73 | # double-fork to completely detach from the parent process | |
74 | # based on http://code.activestate.com/recipes/278731 |
|
74 | # based on http://code.activestate.com/recipes/278731 | |
75 | pid = os.fork() |
|
75 | pid = os.fork() | |
76 | if pid: |
|
76 | if pid: | |
77 | # parent |
|
77 | # parent | |
78 | return |
|
78 | return | |
79 | # subprocess.Popen() forks again, all we need to add is |
|
79 | # subprocess.Popen() forks again, all we need to add is | |
80 | # flag the new process as a new session. |
|
80 | # flag the new process as a new session. | |
81 | if sys.version_info < (3, 2): |
|
81 | if sys.version_info < (3, 2): | |
82 | newsession = {'preexec_fn': os.setsid} |
|
82 | newsession = {'preexec_fn': os.setsid} | |
83 | else: |
|
83 | else: | |
84 | newsession = {'start_new_session': True} |
|
84 | newsession = {'start_new_session': True} | |
85 | try: |
|
85 | try: | |
86 |
# connect std |
|
86 | # connect std* to devnull to make sure the subprocess can't | |
87 |
# muck up th |
|
87 | # muck up these stream for mercurial. | |
|
88 | # Connect all the streams to be more close to Windows behavior | |||
|
89 | # and pager will wait for scripts to end if we don't do that | |||
|
90 | nullrfd = open(os.devnull, 'r') | |||
|
91 | nullwfd = open(os.devnull, 'w') | |||
88 | subprocess.Popen( |
|
92 | subprocess.Popen( | |
89 | procutil.tonativestr(script), |
|
93 | procutil.tonativestr(script), | |
90 |
shell=True, stdin= |
|
94 | shell=True, stdin=nullrfd, | |
|
95 | stdout=nullwfd, stderr=nullwfd, | |||
91 | env=procutil.tonativeenv(env), |
|
96 | env=procutil.tonativeenv(env), | |
92 | close_fds=True, **newsession) |
|
97 | close_fds=True, **newsession) | |
93 | finally: |
|
98 | finally: | |
94 | # mission accomplished, this child needs to exit and not |
|
99 | # mission accomplished, this child needs to exit and not | |
95 | # continue the hg process here. |
|
100 | # continue the hg process here. | |
96 | os._exit(0) |
|
101 | os._exit(0) | |
97 |
|
102 | |||
98 | class logtoprocessui(ui.__class__): |
|
103 | class logtoprocessui(ui.__class__): | |
99 | def log(self, event, *msg, **opts): |
|
104 | def log(self, event, *msg, **opts): | |
100 | """Map log events to external commands |
|
105 | """Map log events to external commands | |
101 |
|
106 | |||
102 | Arguments are passed on as environment variables. |
|
107 | Arguments are passed on as environment variables. | |
103 |
|
108 | |||
104 | """ |
|
109 | """ | |
105 | script = self.config('logtoprocess', event) |
|
110 | script = self.config('logtoprocess', event) | |
106 | if script: |
|
111 | if script: | |
107 | if msg: |
|
112 | if msg: | |
108 | # try to format the log message given the remaining |
|
113 | # try to format the log message given the remaining | |
109 | # arguments |
|
114 | # arguments | |
110 | try: |
|
115 | try: | |
111 | # Python string formatting with % either uses a |
|
116 | # Python string formatting with % either uses a | |
112 | # dictionary *or* tuple, but not both. If we have |
|
117 | # dictionary *or* tuple, but not both. If we have | |
113 | # keyword options, assume we need a mapping. |
|
118 | # keyword options, assume we need a mapping. | |
114 | formatted = msg[0] % (opts or msg[1:]) |
|
119 | formatted = msg[0] % (opts or msg[1:]) | |
115 | except (TypeError, KeyError): |
|
120 | except (TypeError, KeyError): | |
116 | # Failed to apply the arguments, ignore |
|
121 | # Failed to apply the arguments, ignore | |
117 | formatted = msg[0] |
|
122 | formatted = msg[0] | |
118 | messages = (formatted,) + msg[1:] |
|
123 | messages = (formatted,) + msg[1:] | |
119 | else: |
|
124 | else: | |
120 | messages = msg |
|
125 | messages = msg | |
121 | # positional arguments are listed as MSG[N] keys in the |
|
126 | # positional arguments are listed as MSG[N] keys in the | |
122 | # environment |
|
127 | # environment | |
123 | msgpairs = ( |
|
128 | msgpairs = ( | |
124 | ('MSG{0:d}'.format(i), str(m)) |
|
129 | ('MSG{0:d}'.format(i), str(m)) | |
125 | for i, m in enumerate(messages, 1)) |
|
130 | for i, m in enumerate(messages, 1)) | |
126 | # keyword arguments get prefixed with OPT_ and uppercased |
|
131 | # keyword arguments get prefixed with OPT_ and uppercased | |
127 | optpairs = ( |
|
132 | optpairs = ( | |
128 | ('OPT_{0}'.format(key.upper()), str(value)) |
|
133 | ('OPT_{0}'.format(key.upper()), str(value)) | |
129 | for key, value in opts.iteritems()) |
|
134 | for key, value in opts.iteritems()) | |
130 | env = dict(itertools.chain(procutil.shellenviron().items(), |
|
135 | env = dict(itertools.chain(procutil.shellenviron().items(), | |
131 | msgpairs, optpairs), |
|
136 | msgpairs, optpairs), | |
132 | EVENT=event, HGPID=str(os.getpid())) |
|
137 | EVENT=event, HGPID=str(os.getpid())) | |
133 | runshellcommand(script, env) |
|
138 | runshellcommand(script, env) | |
134 | return super(logtoprocessui, self).log(event, *msg, **opts) |
|
139 | return super(logtoprocessui, self).log(event, *msg, **opts) | |
135 |
|
140 | |||
136 | # Replace the class for this instance and all clones created from it: |
|
141 | # Replace the class for this instance and all clones created from it: | |
137 | ui.__class__ = logtoprocessui |
|
142 | ui.__class__ = logtoprocessui |
@@ -1,124 +1,124 b'' | |||||
1 | #require no-windows |
|
1 | #require no-windows | |
2 |
|
2 | |||
3 | ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat" |
|
3 | ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat" | |
4 | to hg commands, to wait for the output, if you want to test its output. |
|
4 | to hg commands, to wait for the output, if you want to test its output. | |
5 | Otherwise the test will be flaky. |
|
5 | Otherwise the test will be flaky. | |
6 |
|
6 | |||
7 | Test if logtoprocess correctly captures command-related log calls. |
|
7 | Test if logtoprocess correctly captures command-related log calls. | |
8 |
|
8 | |||
9 | $ hg init |
|
9 | $ hg init | |
10 | $ cat > $TESTTMP/foocommand.py << EOF |
|
10 | $ cat > $TESTTMP/foocommand.py << EOF | |
11 | > from __future__ import absolute_import |
|
11 | > from __future__ import absolute_import | |
12 | > from mercurial import registrar |
|
12 | > from mercurial import registrar | |
13 | > cmdtable = {} |
|
13 | > cmdtable = {} | |
14 | > command = registrar.command(cmdtable) |
|
14 | > command = registrar.command(cmdtable) | |
15 | > configtable = {} |
|
15 | > configtable = {} | |
16 | > configitem = registrar.configitem(configtable) |
|
16 | > configitem = registrar.configitem(configtable) | |
17 | > configitem('logtoprocess', 'foo', |
|
17 | > configitem('logtoprocess', 'foo', | |
18 | > default=None, |
|
18 | > default=None, | |
19 | > ) |
|
19 | > ) | |
20 | > @command(b'foo', []) |
|
20 | > @command(b'foo', []) | |
21 | > def foo(ui, repo): |
|
21 | > def foo(ui, repo): | |
22 | > ui.log('foo', 'a message: %(bar)s\n', bar='spam') |
|
22 | > ui.log('foo', 'a message: %(bar)s\n', bar='spam') | |
23 | > EOF |
|
23 | > EOF | |
24 | $ cp $HGRCPATH $HGRCPATH.bak |
|
24 | $ cp $HGRCPATH $HGRCPATH.bak | |
25 | $ cat >> $HGRCPATH << EOF |
|
25 | $ cat >> $HGRCPATH << EOF | |
26 | > [extensions] |
|
26 | > [extensions] | |
27 | > logtoprocess= |
|
27 | > logtoprocess= | |
28 | > foocommand=$TESTTMP/foocommand.py |
|
28 | > foocommand=$TESTTMP/foocommand.py | |
29 | > [logtoprocess] |
|
29 | > [logtoprocess] | |
30 | > command=(echo 'logtoprocess command output:'; |
|
30 | > command=(echo 'logtoprocess command output:'; | |
31 | > echo "\$EVENT"; |
|
31 | > echo "\$EVENT"; | |
32 | > echo "\$MSG1"; |
|
32 | > echo "\$MSG1"; | |
33 | > echo "\$MSG2") > $TESTTMP/command.log |
|
33 | > echo "\$MSG2") > $TESTTMP/command.log | |
34 | > commandfinish=(echo 'logtoprocess commandfinish output:'; |
|
34 | > commandfinish=(echo 'logtoprocess commandfinish output:'; | |
35 | > echo "\$EVENT"; |
|
35 | > echo "\$EVENT"; | |
36 | > echo "\$MSG1"; |
|
36 | > echo "\$MSG1"; | |
37 | > echo "\$MSG2"; |
|
37 | > echo "\$MSG2"; | |
38 | > echo "\$MSG3") > $TESTTMP/commandfinish.log |
|
38 | > echo "\$MSG3") > $TESTTMP/commandfinish.log | |
39 | > foo=(echo 'logtoprocess foo output:'; |
|
39 | > foo=(echo 'logtoprocess foo output:'; | |
40 | > echo "\$EVENT"; |
|
40 | > echo "\$EVENT"; | |
41 | > echo "\$MSG1"; |
|
41 | > echo "\$MSG1"; | |
42 | > echo "\$OPT_BAR") > $TESTTMP/foo.log |
|
42 | > echo "\$OPT_BAR") > $TESTTMP/foo.log | |
43 | > EOF |
|
43 | > EOF | |
44 |
|
44 | |||
45 | Running a command triggers both a ui.log('command') and a |
|
45 | Running a command triggers both a ui.log('command') and a | |
46 | ui.log('commandfinish') call. The foo command also uses ui.log. |
|
46 | ui.log('commandfinish') call. The foo command also uses ui.log. | |
47 |
|
47 | |||
48 | Use sort to avoid ordering issues between the various processes we spawn: |
|
48 | Use sort to avoid ordering issues between the various processes we spawn: | |
49 | $ hg foo |
|
49 | $ hg foo | |
50 | $ sleep 0.2 |
|
50 | $ sleep 0.2 | |
51 | $ cat $TESTTMP/command.log | sort |
|
51 | $ cat $TESTTMP/command.log | sort | |
52 |
|
52 | |||
53 | command |
|
53 | command | |
54 | foo |
|
54 | foo | |
55 | foo |
|
55 | foo | |
56 | logtoprocess command output: |
|
56 | logtoprocess command output: | |
57 |
|
57 | |||
58 | #if no-chg |
|
58 | #if no-chg | |
59 | $ cat $TESTTMP/commandfinish.log | sort |
|
59 | $ cat $TESTTMP/commandfinish.log | sort | |
60 |
|
60 | |||
61 | 0 |
|
61 | 0 | |
62 | commandfinish |
|
62 | commandfinish | |
63 | foo |
|
63 | foo | |
64 | foo exited 0 after * seconds (glob) |
|
64 | foo exited 0 after * seconds (glob) | |
65 | logtoprocess commandfinish output: |
|
65 | logtoprocess commandfinish output: | |
66 | $ cat $TESTTMP/foo.log | sort |
|
66 | $ cat $TESTTMP/foo.log | sort | |
67 |
|
67 | |||
68 | a message: spam |
|
68 | a message: spam | |
69 | foo |
|
69 | foo | |
70 | logtoprocess foo output: |
|
70 | logtoprocess foo output: | |
71 | spam |
|
71 | spam | |
72 | #endif |
|
72 | #endif | |
73 |
|
73 | |||
74 | Confirm that logging blocked time catches stdio properly: |
|
74 | Confirm that logging blocked time catches stdio properly: | |
75 | $ cp $HGRCPATH.bak $HGRCPATH |
|
75 | $ cp $HGRCPATH.bak $HGRCPATH | |
76 | $ cat >> $HGRCPATH << EOF |
|
76 | $ cat >> $HGRCPATH << EOF | |
77 | > [extensions] |
|
77 | > [extensions] | |
78 | > logtoprocess= |
|
78 | > logtoprocess= | |
79 | > pager= |
|
79 | > pager= | |
80 | > [logtoprocess] |
|
80 | > [logtoprocess] | |
81 | > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > $TESTTMP/uiblocked.log |
|
81 | > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > $TESTTMP/uiblocked.log | |
82 | > [ui] |
|
82 | > [ui] | |
83 | > logblockedtimes=True |
|
83 | > logblockedtimes=True | |
84 | > EOF |
|
84 | > EOF | |
85 |
|
85 | |||
86 | $ hg log |
|
86 | $ hg log | |
87 | $ sleep 0.2 |
|
87 | $ sleep 0.2 | |
88 | $ cat $TESTTMP/uiblocked.log |
|
88 | $ cat $TESTTMP/uiblocked.log | |
89 | uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re) |
|
89 | uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re) | |
90 |
|
90 | |||
91 | Try to confirm that pager wait on logtoprocess: |
|
91 | Try to confirm that pager wait on logtoprocess: | |
92 |
|
92 | |||
93 | Add a script that wait on a file to appears for 5 seconds, if it sees it touch |
|
93 | Add a script that wait on a file to appears for 5 seconds, if it sees it touch | |
94 | another file or die after 5 seconds. If the scripts is awaited by hg, the |
|
94 | another file or die after 5 seconds. If the scripts is awaited by hg, the | |
95 | script will die after the timeout before we could touch the file and the |
|
95 | script will die after the timeout before we could touch the file and the | |
96 | resulting file will not exists. If not, we will touch the file and see it. |
|
96 | resulting file will not exists. If not, we will touch the file and see it. | |
97 |
|
97 | |||
98 | $ cat > $TESTTMP/wait-output.sh << EOF |
|
98 | $ cat > $TESTTMP/wait-output.sh << EOF | |
99 | > #!/bin/sh |
|
99 | > #!/bin/sh | |
100 | > for i in \`$TESTDIR/seq.py 50\`; do |
|
100 | > for i in \`$TESTDIR/seq.py 50\`; do | |
101 | > if [ -f "$TESTTMP/wait-for-touched" ]; |
|
101 | > if [ -f "$TESTTMP/wait-for-touched" ]; | |
102 | > then |
|
102 | > then | |
103 | > touch "$TESTTMP/touched"; |
|
103 | > touch "$TESTTMP/touched"; | |
104 | > break; |
|
104 | > break; | |
105 | > else |
|
105 | > else | |
106 | > sleep 0.1; |
|
106 | > sleep 0.1; | |
107 | > fi |
|
107 | > fi | |
108 | > done |
|
108 | > done | |
109 | > EOF |
|
109 | > EOF | |
110 | $ chmod +x $TESTTMP/wait-output.sh |
|
110 | $ chmod +x $TESTTMP/wait-output.sh | |
111 |
|
111 | |||
112 | $ cat >> $HGRCPATH << EOF |
|
112 | $ cat >> $HGRCPATH << EOF | |
113 | > [extensions] |
|
113 | > [extensions] | |
114 | > logtoprocess= |
|
114 | > logtoprocess= | |
115 | > pager= |
|
115 | > pager= | |
116 | > [logtoprocess] |
|
116 | > [logtoprocess] | |
117 | > commandfinish=$TESTTMP/wait-output.sh |
|
117 | > commandfinish=$TESTTMP/wait-output.sh | |
118 | > EOF |
|
118 | > EOF | |
119 | $ hg version -q --pager=always |
|
119 | $ hg version -q --pager=always | |
120 | Mercurial Distributed SCM (version *) (glob) |
|
120 | Mercurial Distributed SCM (version *) (glob) | |
121 | $ touch $TESTTMP/wait-for-touched |
|
121 | $ touch $TESTTMP/wait-for-touched | |
122 | $ sleep 0.2 |
|
122 | $ sleep 0.2 | |
123 | $ test -f $TESTTMP/touched && echo "SUCCESS Pager is not waiting on ltp" || echo "FAIL Pager is waiting on ltp" |
|
123 | $ test -f $TESTTMP/touched && echo "SUCCESS Pager is not waiting on ltp" || echo "FAIL Pager is waiting on ltp" | |
124 |
|
|
124 | SUCCESS Pager is not waiting on ltp |
General Comments 0
You need to be logged in to leave comments.
Login now