Mercurial > hg
view tests/test-logtoprocess.t @ 34107:4f60720cf0df
blackbox: fix rotation with chg
The added test will show:
$ $PYTHON showsize.py .hg/blackbox*
.hg/blackbox.log: < 500
.hg/blackbox.log.1: < 500
.hg/blackbox.log.2: < 500
.hg/blackbox.log.3: < 500
.hg/blackbox.log.4: < 500
.hg/blackbox.log.5: >= 500
with previous code.
The issue is caused by blackbox caching file objects *by path*, and the
rotation size check could run on a wrong file object (i.e. it should check
"blackbox.log", but `filehandles["blackbox.log"]` contains a file object
that has been renamed to "blackbox.log.5").
This patch removes the "filehandlers" global cache added by 45313f5a3a8c to
solve the issue.
I think the original patch was trying to make different ui objects use a same
file object if their blackbox.log path is the same. In theory it could also
be problematic in the rotation case. Anyway, that should become unnecessary
after D650.
Differential Revision: https://phab.mercurial-scm.org/D648
author | Jun Wu <quark@fb.com> |
---|---|
date | Wed, 06 Sep 2017 19:27:30 -0700 |
parents | e98dab3fafbc |
children | df78b1a24094 |
line wrap: on
line source
#require no-windows ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat" to hg commands, to wait for the output, if you want to test its output. Otherwise the test will be flaky. Test if logtoprocess correctly captures command-related log calls. $ hg init $ cat > $TESTTMP/foocommand.py << EOF > from __future__ import absolute_import > from mercurial import registrar > cmdtable = {} > command = registrar.command(cmdtable) > @command(b'foo', []) > def foo(ui, repo): > ui.log('foo', 'a message: %(bar)s\n', bar='spam') > EOF $ cp $HGRCPATH $HGRCPATH.bak $ cat >> $HGRCPATH << EOF > [extensions] > logtoprocess= > foocommand=$TESTTMP/foocommand.py > [logtoprocess] > command=echo 'logtoprocess command output:'; > echo "\$EVENT"; > echo "\$MSG1"; > echo "\$MSG2" > commandfinish=echo 'logtoprocess commandfinish output:'; > echo "\$EVENT"; > echo "\$MSG1"; > echo "\$MSG2"; > echo "\$MSG3" > foo=echo 'logtoprocess foo output:'; > echo "\$EVENT"; > echo "\$MSG1"; > echo "\$OPT_BAR" > EOF Running a command triggers both a ui.log('command') and a ui.log('commandfinish') call. The foo command also uses ui.log. Use sort to avoid ordering issues between the various processes we spawn: $ hg foo | cat | sort 0 a message: spam command commandfinish foo foo foo foo foo exited 0 after * seconds (glob) logtoprocess command output: logtoprocess commandfinish output: logtoprocess foo output: spam Confirm that logging blocked time catches stdio properly: $ cp $HGRCPATH.bak $HGRCPATH $ cat >> $HGRCPATH << EOF > [extensions] > logtoprocess= > pager= > [logtoprocess] > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > [ui] > logblockedtimes=True > EOF $ hg log | cat uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)