Bug 6110 - excessive logging to blackbox.log
Summary: excessive logging to blackbox.log
Status: RESOLVED FIXED
Alias: None
Product: Mercurial
Classification: Unclassified
Component: blackbox (show other bugs)
Version: 4.9
Hardware: PC Linux
: wish bug
Assignee: Bugzilla
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-04-02 17:10 UTC by Mitchell Plamann
Modified: 2019-07-26 00:01 UTC (History)
3 users (show)

See Also:
Python Version: ---


Attachments
Blackbox output when running via chg (7.35 KB, text/plain)
2019-04-02 17:10 UTC, Mitchell Plamann
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mitchell Plamann 2019-04-02 17:10 UTC
Created attachment 2039 [details]
Blackbox output when running via chg

Beginning in hg 4.9, a lot of extra data is being written to the blackbox.log file. This makes it difficult to read through a blackbox, and makes each log entry take up much more space on disk.

In 4.8 and before, running 

$ HGRCPATH= hg log -r . --config extensions.blackbox=

would output something like this in the blackbox:

> log -r .
> log -r . exited 0 after 0.94 seconds


Now in 4.9, extra lines are printed out for each command, for each extension that is enabled. 

$ HGRCPATH= hg log -r . --config extensions.blackbox=

now outputs something like this in the blackbox:

>   > reposetup for blackbox took 33.86 us
> > all reposetup took 9.248 ms
> log -r . --config 'extensions.blackbox='
> log -r . --config 'extensions.blackbox=' exited 0 after 0.05 seconds

The lines about extensions setup seem like debugging output that should not be enabled by default. This example is small, but this gets noisier as more extensions are enabled.


The problem gets far worse when chg is used. This command:

$ HGRCPATH= chg log -r . --config extensions.blackbox=

outputs 55 lines to the blackbox.log (an example is attached)
Comment 1 Martin von Zweigbergk 2019-04-02 17:24 UTC
As a workaround, you can set something like this (that's what my team does):

[blackbox]
track = command,commandalias,commandexception,commandfinish
Comment 2 Augie Fackler 2019-04-08 14:27 UTC
I'm definitely sympathetic to this. Should we add a 'debug' category to blackbox (topic begins with debug?) that we exclude by default?
Comment 3 Martin von Zweigbergk 2019-04-09 13:36 UTC
Or maybe we should back out (part of?) https://www.mercurial-scm.org/repo/hg/rev/6f2510b581a0?
Comment 4 Martin von Zweigbergk 2019-04-09 13:38 UTC
Yuya, you wrote that patch. Thoughts? My impression was that that commit was part of a series that removed some reference cycle. Can we move the logs back to ui.debug() and still not have that reference cycle (if I even remember that correctly)?
Comment 5 HG Bot 2019-07-18 14:20 UTC
Fixed by https://mercurial-scm.org/repo/hg/rev/56132ebd14c6
Valentin Gatien-Baron <valentin.gatienbaron@gmail.com>
blackbox: disable extremely verbose logging (issue6110)

This is maybe not the best way to go about fixing this, but anything
is better than the status quo.

Differential Revision: https://phab.mercurial-scm.org/D6611

(please test the fix)
Comment 6 Bugzilla 2019-07-26 00:01 UTC
Bug was set to TESTING for 7 days, resolving