Download Raw Diff

Details

Reviewers

None

Group 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

Lint Skipped

Unit

Unit Tests Skipped

Event Timeline

lothiraldan created this revision.Oct 1 2018, 12:13 PM

Herald added a reviewer: hg-reviewers. · View Herald TranscriptOct 1 2018, 12:13 PM

Herald added a subscriber: mercurial-devel. · View Herald Transcript

+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.

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?

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.

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 = ""
+

try to format the log message given the remaining

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 updated this revision to Diff 12296.Oct 22 2018, 8:51 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 = ""
+

try to format the log message given the remaining

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.

+ # 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 updated this revision to Diff 12298.Oct 22 2018, 9:55 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.

lothiraldan updated this revision to Diff 12307.Oct 22 2018, 11:54 AM

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.

Diff	ID	Description	Created	Lint	Unit
Base		Base
Diff 1	11521		Oct 1 2018, 12:13 PM	★	★
Diff 2	12161		Oct 16 2018, 11:10 AM	★	★
Diff 3	12296		Oct 22 2018, 8:51 AM	★	★
Diff 4	12298		Oct 22 2018, 9:55 AM	★	★
Diff 5	12307		Oct 22 2018, 11:53 AM	★	★
Diff 6	12308	rHG106adc2614922a24adc1e662ea78c83ec19aa4bf	Oct 22 2018, 9:51 AM	★	★

Commit	Parents	Author	Summary	Date
		Boris Feld		Oct 1 2018, 11:53 AM

	Status	Author	Revision
	Closed	lothiraldan	D4820 logtoprocess: sends the canonical command name to the subprocess
	Closed	lothiraldan	D5180 logtoprocess: fix message formatting

Diff 12296

hgext/logtoprocess.py

	"""Map log events to external commands			"""Map log events to external commands

	Arguments are passed on as environment variables.			Arguments are passed on as environment variables.

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

				# 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.
				canonical_command = opts.pop("canonical_command", None)
				if canonical_command is None:
				canonical_command = ""

	# try to format the log message given the remaining			# try to format the log message given the remaining
	# arguments			# arguments
	try:			try:
	# Python string formatting with % either uses a			# Python string formatting with % either uses a
	# dictionary or tuple, but not both. If we have			# dictionary or tuple, but not both. If we have
	# keyword options, assume we need a mapping.			# keyword options, assume we need a mapping.
	formatted = msg[0] % (opts or msg[1:])			formatted = msg[0] % (opts or msg[1:])
	except (TypeError, KeyError):			except (TypeError, KeyError):
	# Failed to apply the arguments, ignore			# Failed to apply the arguments, ignore
	formatted = msg[0]			formatted = msg[0]
	messages = (formatted,) + msg[1:]			messages = (formatted,) + msg[1:]
	else:			else:
	messages = msg			messages = msg
	# positional arguments are listed as MSG[N] keys in the			# positional arguments are listed as MSG[N] keys in the
	# environment			# environment
	msgpairs = (			msgpairs = (
	('MSG{0:d}'.format(i), str(m))			('MSG{0:d}'.format(i), str(m))
	for i, m in enumerate(messages, 1))			for i, m in enumerate(messages, 1))
	# keyword arguments get prefixed with OPT_ and uppercased			# keyword arguments get prefixed with OPT_ and uppercased
	optpairs = (			optpairs = (
	('OPT_{0}'.format(key.upper()), str(value))			('OPT_{0}'.format(key.upper()), str(value))
	for key, value in opts.iteritems())			for key, value in opts.iteritems())
	env = dict(itertools.chain(procutil.shellenviron().items(),			env = dict(itertools.chain(procutil.shellenviron().items(),
	msgpairs, optpairs),			msgpairs, optpairs),
	EVENT=event, HGPID=str(os.getpid()))			EVENT=event, HGPID=str(os.getpid()),
				OPT_CANONICAL_COMMAND=canonical_command)
	runshellcommand(script, env)			runshellcommand(script, env)
	return super(logtoprocessui, self).log(event, msg, *opts)			return super(logtoprocessui, self).log(event, msg, *opts)

	# Replace the class for this instance and all clones created from it:			# Replace the class for this instance and all clones created from it:
	ui.__class__ = logtoprocessui			ui.__class__ = logtoprocessui

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: %(bar)s\n', bar='spam')			> ui.log('foo', 'a message: %(bar)s\n', bar='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 "\$OPT_BAR") > $TESTTMP/foo.log			> echo "\$OPT_BAR") > $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 0.2			$ sleep 0.2
	$ 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

			Path	Packages
M			hgext/logtoprocess.py (11 lines)
M			mercurial/dispatch.py (9 lines)
M			tests/test-logtoprocess.t (16 lines)

This is an archive of the discontinued Mercurial Phabricator instance.

logtoprocess: sends the canonical command name to the subprocess
ClosedPublic

Details

Diff Detail

Event Timeline

Revision Contents
Changeset List

Diff 12296

hgext/logtoprocess.py

mercurial/dispatch.py

tests/test-logtoprocess.t

This is an archive of the discontinued Mercurial Phabricator instance.

logtoprocess: sends the canonical command name to the subprocessClosedPublic

Details

Diff Detail

Event Timeline

Revision ContentsChangeset List

Diff 12296

hgext/logtoprocess.py

mercurial/dispatch.py

tests/test-logtoprocess.t

logtoprocess: sends the canonical command name to the subprocess
ClosedPublic

Revision Contents
Changeset List