This is an archive of the discontinued Mercurial Phabricator instance.

Differential D4820

logtoprocess: sends the canonical command name to the subprocess
ClosedPublic

Authored by lothiraldan on Oct 1 2018, 12:13 PM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
Commits
rHG106adc261492: logtoprocess: sends the canonical command name to the subprocess
Summary

One of the use-case of logtoprocess is to monitor command duration. With the
current code, we only get whatever command name the user typed (either
abbreviated or aliased).

This makes analytics on the collected data more difficult. Stores the
canonical command name in the request object. Pass the stored canonical name
in the req.ui.log("commandfinish", ...) call as keyword argument to not
break potential string formatting.

Pass the value as the environment variable named LTP_COMMAND to the called
script.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

lothiraldan created this revision.Oct 1 2018, 12:13 PM
yuja added a subscriber: yuja.Oct 3 2018, 9:04 AM

+def extsetup():
+ # this is to get the canonical name of the command: "commit", not "ci"
+ def wrapdispatch(orig, *args, kwargs):
+ encoding.environ.pop("LTP_COMMAND", None)
+ return orig(*args, kwargs)
+
+ def wrapruncommand(orig, *args, kwargs):
+ encoding.environ["LTP_COMMAND"] = args[2]
+ return orig(*args, kwargs)
+
+ extensions.wrapfunction(dispatch,'dispatch',wrapdispatch)
+ extensions.wrapfunction(dispatch,'runcommand',wrapruncommand)

It's scary to update the environment variables globally and pass
LTP_COMMAND in to any child processes.

Can you add a proper way to teach the command name to the logtoprocess
extension, by ui.log() for example?

Also, the word LTP isn't used anywhere. It'll need a better name, and
should be documented.

lothiraldan added a comment.Oct 4 2018, 1:58 AM
In D4820#73256, @yuja wrote:

+def extsetup():
+ # this is to get the canonical name of the command: "commit", not "ci"
+ def wrapdispatch(orig, *args, kwargs):
+ encoding.environ.pop("LTP_COMMAND", None)
+ return orig(*args, kwargs)
+
+ def wrapruncommand(orig, *args, kwargs):
+ encoding.environ["LTP_COMMAND"] = args[2]
+ return orig(*args, kwargs)
+
+ extensions.wrapfunction(dispatch,'dispatch',wrapdispatch)
+ extensions.wrapfunction(dispatch,'runcommand',wrapruncommand)

It's scary to update the environment variables globally and pass
LTP_COMMAND in to any child processes.
Can you add a proper way to teach the command name to the logtoprocess
extension, by ui.log() for example?
Also, the word LTP isn't used anywhere. It'll need a better name, and
should be documented.

I tried to pass it to the ui.log() but didn't find a clean way to transfer it from dispatch._dispatch to dispatch.dispatch. I tried storing it in the ui object but without luck.

Do you think it would be ok to store it in the request object?

yuja added a comment.Oct 4 2018, 9:15 AM
I tried to pass it to the `ui.log()` but didn't find a clean way to transfer it from `dispatch._dispatch` to `dispatch.dispatch`. I tried storing it in the ui object but without luck.
Do you think it would be ok to store it in the `request` object?

If that helps, yes. I think using request object is better than abusing ui,
given the command lifetime is quite the same as the request.

lothiraldan edited the summary of this revision. (Show Details)Oct 16 2018, 11:10 AM
lothiraldan updated this revision to Diff 12161.
yuja added a comment.Oct 18 2018, 9:16 AM
  • a/hgext/logtoprocess.py

+++ b/hgext/logtoprocess.py
@@ -40,6 +40,9 @@
import sys
from mercurial import (
+ dispatch,
+ encoding,
+ extensions,

Unused.

@@ -110,6 +113,12 @@

script = self.config('logtoprocess', event)
if script:
    if msg:

+
+ # extract the canonical command from the passed opts
+ canonical_command = opts.pop("canonical_command", None)
+ if canonical_command is None:
+ canonical_command = ""
+

  1. try to format the log message given the remaining
  2. arguments try:

@@ -134,7 +143,8 @@

    for key, value in opts.iteritems())
env = dict(itertools.chain(procutil.shellenviron().items(),
                           msgpairs, optpairs),
  • EVENT=event, HGPID=str(os.getpid()))

+ EVENT=event, HGPID=str(os.getpid()),
+ LTP_COMMAND=canonical_command)

As I said before, LTP_* doesn't sound great. Can't we simply pass in
canonical_command as OPT_CANONICAL_COMMAND? If we really want to name
it other than OPT_*, please document it.

And I noticed there's no test. Can you add some?

lothiraldan added a comment.Oct 22 2018, 8:53 AM
In D4820#77055, @yuja wrote:
  • a/hgext/logtoprocess.py

+++ b/hgext/logtoprocess.py
@@ -40,6 +40,9 @@
import sys
from mercurial import (
+ dispatch,
+ encoding,
+ extensions,

Unused.

@@ -110,6 +113,12 @@

script = self.config('logtoprocess', event)
if script:
    if msg:

+
+ # extract the canonical command from the passed opts
+ canonical_command = opts.pop("canonical_command", None)
+ if canonical_command is None:
+ canonical_command = ""
+

  1. try to format the log message given the remaining
  2. arguments try:

@@ -134,7 +143,8 @@

    for key, value in opts.iteritems())
env = dict(itertools.chain(procutil.shellenviron().items(),
                           msgpairs, optpairs),
  • EVENT=event, HGPID=str(os.getpid()))

+ EVENT=event, HGPID=str(os.getpid()),
+ LTP_COMMAND=canonical_command)

As I said before, LTP_* doesn't sound great. Can't we simply pass in
canonical_command as OPT_CANONICAL_COMMAND? If we really want to name
it other than OPT_*, please document it.

I misunderstood your previous comment, the canonical command is now sent as OPT_CANONICAL_COMMAND, I still need to process it in a dedicated manner and I've detailed why in the comment associated.

And I noticed there's no test. Can you add some?

I have updated the patch with a test and removed the unused imports.

yuja added a comment.Oct 22 2018, 9:28 AM

+ # extract the canonical command from the passed opts.
+ # we need to pop it up from the opts else the msg will try
+ # being formatted using the passed opts.

Oops, that's probably a bug. IIUC, **opts is just ancillary data, and
the msg[0] should always be parameterized by msg[1:]. That's how blackbox
works.

Can you send a separate patch to fix the issue?

lothiraldan added a parent revision: D5180: logtoprocess: fix message formatting.Oct 22 2018, 9:56 AM
In D4820#77397, @yuja wrote:

+ # extract the canonical command from the passed opts.
+ # we need to pop it up from the opts else the msg will try
+ # being formatted using the passed opts.

Oops, that's probably a bug. IIUC, **opts is just ancillary data, and
the msg[0] should always be parameterized by msg[1:]. That's how blackbox
works.
Can you send a separate patch to fix the issue?

Done, I hope the stack was correctly saved because I had to to it through the interface, phabsend didn't worked.

Closed by commit rHG106adc261492: logtoprocess: sends the canonical command name to the subprocess (authored by lothiraldan). · Explain WhyOct 22 2018, 11:56 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mmercurial/dispatch.py (9 lines)
Mtests/test-logtoprocess.t (16 lines)

Diff 12308

mercurial/dispatch.py

# remember options pre-parsed by _earlyparseopts() # remember options pre-parsed by _earlyparseopts()
self.earlyoptions = {} self.earlyoptions = {}
# reposetups which run before extensions, useful for chg to pre-fill # reposetups which run before extensions, useful for chg to pre-fill
# low-level repo state (for example, changelog) before extensions. # low-level repo state (for example, changelog) before extensions.
self.prereposetups = prereposetups or [] self.prereposetups = prereposetups or []
# store the parsed and canonical command
self.canonical_command = None
def _runexithandlers(self): def _runexithandlers(self):
exc = None exc = None
handlers = self.ui._exithandlers handlers = self.ui._exithandlers
try: try:
while handlers: while handlers:
func, args, kwargs = handlers.pop() func, args, kwargs = handlers.pop()
try: try:
func(*args, **kwargs) func(*args, **kwargs)
finally: finally:
duration = util.timer() - starttime duration = util.timer() - starttime
req.ui.flush() req.ui.flush()
if req.ui.logblockedtimes: if req.ui.logblockedtimes:
req.ui._blockedtimes['command_duration'] = duration * 1000 req.ui._blockedtimes['command_duration'] = duration * 1000
req.ui.log('uiblocked', 'ui blocked ms', req.ui.log('uiblocked', 'ui blocked ms',
**pycompat.strkwargs(req.ui._blockedtimes)) **pycompat.strkwargs(req.ui._blockedtimes))
req.ui.log("commandfinish", "%s exited %d after %0.2f seconds\n", req.ui.log("commandfinish", "%s exited %d after %0.2f seconds\n",
msg, ret & 255, duration) msg, ret & 255, duration,
canonical_command=req.canonical_command)
try: try:
req._runexithandlers() req._runexithandlers()
except: # exiting, so no re-raises except: # exiting, so no re-raises
ret = ret or -1 ret = ret or -1
return ret return ret
def _runcatch(req): def _runcatch(req):
with tracing.log('dispatch._runcatch'): with tracing.log('dispatch._runcatch'):
# check for fallback encoding # check for fallback encoding
fallback = lui.config('ui', 'fallbackencoding') fallback = lui.config('ui', 'fallbackencoding')
if fallback: if fallback:
encoding.fallbackencoding = fallback encoding.fallbackencoding = fallback
fullargs = args fullargs = args
cmd, func, args, options, cmdoptions = _parse(lui, args) cmd, func, args, options, cmdoptions = _parse(lui, args)
# store the canonical command name in request object for later access
req.canonical_command = cmd
if options["config"] != req.earlyoptions["config"]: if options["config"] != req.earlyoptions["config"]:
raise error.Abort(_("option --config may not be abbreviated!")) raise error.Abort(_("option --config may not be abbreviated!"))
if options["cwd"] != req.earlyoptions["cwd"]: if options["cwd"] != req.earlyoptions["cwd"]:
raise error.Abort(_("option --cwd may not be abbreviated!")) raise error.Abort(_("option --cwd may not be abbreviated!"))
if options["repository"] != req.earlyoptions["repository"]: if options["repository"] != req.earlyoptions["repository"]:
raise error.Abort(_( raise error.Abort(_(
"option -R has to be separated from other options (e.g. not " "option -R has to be separated from other options (e.g. not "
"-qR) and --repository may only be abbreviated as --repo!")) "-qR) and --repository may only be abbreviated as --repo!"))

tests/test-logtoprocess.t

> from mercurial import registrar > from mercurial import registrar
> cmdtable = {} > cmdtable = {}
> command = registrar.command(cmdtable) > command = registrar.command(cmdtable)
> configtable = {} > configtable = {}
> configitem = registrar.configitem(configtable) > configitem = registrar.configitem(configtable)
> configitem('logtoprocess', 'foo', > configitem('logtoprocess', 'foo',
> default=None, > default=None,
> ) > )
> @command(b'foo', []) > @command(b'foobar', [])
> def foo(ui, repo): > def foo(ui, repo):
> ui.log('foo', 'a message: %s\n', 'spam') > ui.log('foo', 'a message: %s\n', 'spam')
> EOF > EOF
$ cp $HGRCPATH $HGRCPATH.bak $ cp $HGRCPATH $HGRCPATH.bak
$ cat >> $HGRCPATH << EOF $ cat >> $HGRCPATH << EOF
> [extensions] > [extensions]
> logtoprocess= > logtoprocess=
> foocommand=$TESTTMP/foocommand.py > foocommand=$TESTTMP/foocommand.py
> [logtoprocess] > [logtoprocess]
> command=(echo 'logtoprocess command output:'; > command=(echo 'logtoprocess command output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$MSG2") > $TESTTMP/command.log > echo "\$MSG2") > $TESTTMP/command.log
> commandfinish=(echo 'logtoprocess commandfinish output:'; > commandfinish=(echo 'logtoprocess commandfinish output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$MSG2"; > echo "\$MSG2";
> echo "\$MSG3") > $TESTTMP/commandfinish.log > echo "\$MSG3";
> echo "canonical: \$OPT_CANONICAL_COMMAND") > $TESTTMP/commandfinish.log
> foo=(echo 'logtoprocess foo output:'; > foo=(echo 'logtoprocess foo output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$MSG2") > $TESTTMP/foo.log > echo "\$MSG2") > $TESTTMP/foo.log
> EOF > EOF
Running a command triggers both a ui.log('command') and a Running a command triggers both a ui.log('command') and a
ui.log('commandfinish') call. The foo command also uses ui.log. ui.log('commandfinish') call. The foo command also uses ui.log.
Use sort to avoid ordering issues between the various processes we spawn: Use sort to avoid ordering issues between the various processes we spawn:
$ hg foo $ hg fooba
$ sleep 1 $ sleep 1
$ cat $TESTTMP/command.log | sort $ cat $TESTTMP/command.log | sort
command command
foo fooba
foo fooba
logtoprocess command output: logtoprocess command output:
#if no-chg #if no-chg
$ cat $TESTTMP/commandfinish.log | sort $ cat $TESTTMP/commandfinish.log | sort
0 0
canonical: foobar
commandfinish commandfinish
foo fooba
foo exited 0 after * seconds (glob) fooba exited 0 after * seconds (glob)
logtoprocess commandfinish output: logtoprocess commandfinish output:
$ cat $TESTTMP/foo.log | sort $ cat $TESTTMP/foo.log | sort
a message: spam a message: spam
foo foo
logtoprocess foo output: logtoprocess foo output:
spam spam
#endif #endif