mirror of
https://github.com/facebook/sapling.git
synced 2024-10-10 08:47:12 +03:00
f9958ca35a
Summary: This change introduces two new metadata types, Category and Transience, and a mechanism for Category to provide a default Fault and Transience, which can be overriden by the user. Also introduces a mechanism for attempting to log exceptions which occur during exception logging, falling back to the previous behavior of just swallowing the exception on failure. Reviewed By: DurhamG Differential Revision: D22677565 fbshipit-source-id: 1cf75ca1e2a65964a0ede1f072439378a46bd391
281 lines
10 KiB
Perl
281 lines
10 KiB
Perl
#chg-compatible
|
|
|
|
Setup. SCM_SAMPLING_FILEPATH needs to be cleared as some environments may
|
|
have it set.
|
|
|
|
$ unset SCM_SAMPLING_FILEPATH
|
|
|
|
$ mkcommit() {
|
|
> echo "$1" > "$1"
|
|
> hg add "$1"
|
|
> echo "add $1" > msg
|
|
> echo "" >> msg
|
|
> hg ci -l msg
|
|
> }
|
|
Init the repo
|
|
$ hg init testrepo
|
|
$ cd testrepo
|
|
$ mkcommit a
|
|
Create an extension that logs every commit and also call repo.revs twice
|
|
|
|
Create an extension that logs the call to commit
|
|
$ cat > $TESTTMP/logcommit.py << EOF
|
|
> from edenscm.mercurial import extensions, localrepo
|
|
> def cb(sample):
|
|
> return len(sample)
|
|
> def _commit(orig, repo, *args, **kwargs):
|
|
> repo.ui.log("commit", "match filter", k=1, a={"hi":"ho"})
|
|
> repo.ui.log("foo", "does not match filter", k=1, a={"hi":"ho"})
|
|
> repo.ui.log("commit", "message %s", "string", k=1, a={"hi":"ho"})
|
|
> return orig(repo, *args, **kwargs)
|
|
> def extsetup(ui):
|
|
> extensions.wrapfunction(localrepo.localrepository, 'commit', _commit)
|
|
> @ui.atexit
|
|
> def handler():
|
|
> ui._measuredtimes['atexit_measured'] += 7
|
|
> ui.warn("atexit handler executed\n")
|
|
> EOF
|
|
|
|
|
|
Set up the extension and set a log file
|
|
We include only the 'commit' key, only the events with that key will be
|
|
logged
|
|
$ cat >> $HGRCPATH << EOF
|
|
> [ui]
|
|
> logmeasuredtimes=True
|
|
> [sampling]
|
|
> key.commit=commit_table
|
|
> key.measuredtimes=measuredtimes
|
|
> [extensions]
|
|
> sampling=
|
|
> EOF
|
|
$ LOGDIR=$TESTTMP/logs
|
|
$ mkdir $LOGDIR
|
|
$ echo "logcommit=$TESTTMP/logcommit.py" >> $HGRCPATH
|
|
$ echo "[sampling]" >> $HGRCPATH
|
|
$ echo "filepath = $LOGDIR/samplingpath.txt" >> $HGRCPATH
|
|
|
|
Do a couple of commits. We expect to log two messages per call to repo.commit.
|
|
$ mkdir a_topdir && cd a_topdir
|
|
$ mkcommit b
|
|
atexit handler executed
|
|
atexit handler executed
|
|
$ mkcommit c
|
|
atexit handler executed
|
|
atexit handler executed
|
|
>>> from edenscm.mercurial import pycompat
|
|
>>> import json
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read()
|
|
>>> for record in data.strip("\0").split("\0"):
|
|
... parsedrecord = json.loads(record)
|
|
... if parsedrecord['category'] == 'commit_table':
|
|
... print(' '.join([parsedrecord["data"]["msg"], parsedrecord["category"]]))
|
|
... assert len(parsedrecord["data"]) == 4
|
|
... elif parsedrecord['category'] == 'measuredtimes':
|
|
... print('atexit_measured: ', ", ".join(sorted(parsedrecord['data'])))
|
|
atexit_measured: atexit_measured, command_duration, fswalk_time, metrics_type, stdio_blocked (no-fsmonitor !)
|
|
atexit_measured: atexit_measured, command_duration, fsmonitorwalk_time, metrics_type, stdio_blocked, watchmanquery_time (fsmonitor !)
|
|
match filter commit_table
|
|
message string commit_table
|
|
atexit_measured: atexit_measured, command_duration, fswalk_time, metrics_type, stdio_blocked (no-fsmonitor !)
|
|
atexit_measured: atexit_measured, command_duration, fswalk_time, metrics_type, stdio_blocked (no-fsmonitor !)
|
|
atexit_measured: atexit_measured, command_duration, fsmonitorwalk_time, metrics_type, stdio_blocked, watchmanquery_time (fsmonitor !)
|
|
atexit_measured: atexit_measured, command_duration, fsmonitorwalk_time, metrics_type, stdio_blocked, watchmanquery_time (fsmonitor !)
|
|
match filter commit_table
|
|
message string commit_table
|
|
atexit_measured: atexit_measured, command_duration, fswalk_time, metrics_type, stdio_blocked (no-fsmonitor !)
|
|
atexit_measured: atexit_measured, command_duration, fsmonitorwalk_time, metrics_type, stdio_blocked, watchmanquery_time (fsmonitor !)
|
|
|
|
Test topdir logging:
|
|
$ setconfig sampling.logtopdir=True
|
|
$ setconfig sampling.key.command_info=command_info
|
|
$ hg st > /dev/null
|
|
atexit handler executed
|
|
>>> from edenscm.mercurial import json
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> print([json.loads(d)["data"]["topdir"] for d in data if "topdir" in d])
|
|
['a_topdir']
|
|
|
|
Test env-var logging:
|
|
$ setconfig sampling.env_vars=TEST_VAR1,TEST_VAR2
|
|
$ setconfig sampling.key.env_vars=env_vars
|
|
$ export TEST_VAR1=abc
|
|
$ export TEST_VAR2=def
|
|
$ hg st > /dev/null
|
|
atexit handler executed
|
|
>>> import json, pprint
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> for jsonstr in data:
|
|
... entry = json.loads(jsonstr)
|
|
... if entry["category"] == "env_vars":
|
|
... for k in sorted(entry["data"].keys()):
|
|
... print("%s: %s" % (k, entry["data"][k]))
|
|
env_test_var1: abc
|
|
env_test_var2: def
|
|
metrics_type: env_vars
|
|
|
|
Test exception logging:
|
|
$ setconfig sampling.key.exceptions=exceptions
|
|
|
|
$ > $LOGDIR/samplingpath.txt
|
|
$ hg debugthrowrustexception 2>&1 | egrep -v '^ '
|
|
\*\* Mercurial Distributed SCM * has crashed: (glob)
|
|
atexit handler executed
|
|
Traceback (most recent call last):
|
|
*RustError: intentional error for debugging with message 'intentional_error' (glob)
|
|
>>> import json, pprint
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> for jsonstr in data:
|
|
... entry = json.loads(jsonstr)
|
|
... if entry["category"] == "exceptions":
|
|
... for k in sorted(entry["data"].keys()):
|
|
... print("%s: %s" % (k, entry["data"][k]))
|
|
category: programming
|
|
exception_msg: intentional error for debugging with message 'intentional_error'
|
|
exception_type: RustError
|
|
fault: request
|
|
metrics_type: exceptions
|
|
rust_error_type: taggederror::IntentionalError
|
|
transience: permanent
|
|
|
|
$ > $LOGDIR/samplingpath.txt
|
|
$ hg debugthrowrustbail 2>&1 | egrep -v '^ '
|
|
\*\* Mercurial Distributed SCM * has crashed: (glob)
|
|
atexit handler executed
|
|
Traceback (most recent call last):
|
|
*RustError: intentional bail with format params (glob)
|
|
>>> import json, pprint
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> for jsonstr in data:
|
|
... entry = json.loads(jsonstr)
|
|
... if entry["category"] == "exceptions":
|
|
... for k in sorted(entry["data"].keys()):
|
|
... print("%s: %s" % (k, entry["data"][k]))
|
|
category: programming
|
|
exception_msg: intentional bail with format params
|
|
exception_type: RustError
|
|
fault: request
|
|
metrics_type: exceptions
|
|
rust_error_type: taggederror::FakeTypeNameForTesting
|
|
transience: permanent
|
|
|
|
$ > $LOGDIR/samplingpath.txt
|
|
$ hg debugthrowexception 2>&1 | egrep -v '^ '
|
|
\*\* Mercurial Distributed SCM * has crashed: (glob)
|
|
atexit handler executed
|
|
Traceback (most recent call last):
|
|
*IntentionalError: intentional failure in debugthrowexception (glob)
|
|
>>> import json, pprint
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> for jsonstr in data:
|
|
... entry = json.loads(jsonstr)
|
|
... if entry["category"] == "exceptions":
|
|
... for k in sorted(entry["data"].keys()):
|
|
... print("%s: %s" % (k, entry["data"][k]))
|
|
category: programming
|
|
exception_msg: intentional failure in debugthrowexception
|
|
exception_type: IntentionalError
|
|
fault: request
|
|
metrics_type: exceptions
|
|
rust_error_type: None
|
|
transience: permanent
|
|
|
|
$ > $LOGDIR/samplingpath.txt
|
|
$ enable rebase histedit
|
|
$ hg rebase
|
|
abort: nothing to rebase
|
|
atexit handler executed
|
|
[255]
|
|
|
|
Note: Errors raised by the dispatch logic aren't logged here:
|
|
$ hg st --nonexistant > /dev/null
|
|
abort: option --nonexistant not recognized
|
|
[255]
|
|
>>> import json, pprint
|
|
>>> with open("$LOGDIR/samplingpath.txt") as f:
|
|
... data = f.read().strip("\0").split("\0")
|
|
>>> for jsonstr in data:
|
|
... entry = json.loads(jsonstr)
|
|
... if entry["category"] == "exceptions":
|
|
... for k in sorted(entry["data"].keys()):
|
|
... print("%s: %s" % (k, entry["data"][k]))
|
|
category: None
|
|
exception_msg: nothing to rebase
|
|
exception_type: NoMergeDestAbort
|
|
fault: None
|
|
metrics_type: exceptions
|
|
rust_error_type: None
|
|
transience: None
|
|
|
|
Test ui.metrics.gauge API
|
|
$ cat > $TESTTMP/a.py << EOF
|
|
> def reposetup(ui, repo):
|
|
> ui.metrics.gauge("foo_a", 1)
|
|
> ui.metrics.gauge("foo_b", 2)
|
|
> ui.metrics.gauge("foo_b", len(repo))
|
|
> ui.metrics.gauge("bar")
|
|
> ui.metrics.gauge("bar")
|
|
> EOF
|
|
$ SCM_SAMPLING_FILEPATH=$TESTTMP/a.txt hg log -r null -T '.\n' --config extensions.gauge=$TESTTMP/a.py --config sampling.key.metrics=aaa
|
|
.
|
|
atexit handler executed
|
|
>>> import os, json
|
|
>>> with open(os.path.join(os.environ["TESTTMP"], "a.txt"), "r") as f:
|
|
... lines = f.read().split("\0")
|
|
... for line in lines:
|
|
... if "foo" in line:
|
|
... obj = json.loads(line)
|
|
... category = obj["category"]
|
|
... data = obj["data"]
|
|
... print("category: %s" % category)
|
|
... for k, v in sorted(data.items()):
|
|
... print(" %s=%s" % (k, v))
|
|
category: aaa
|
|
bar=2
|
|
foo_a=1
|
|
foo_b=5
|
|
metrics_type=metrics
|
|
|
|
Metrics can be printed if devel.print-metrics is set:
|
|
$ hg log -r null -T '.\n' --config extensions.gauge=$TESTTMP/a.py --config devel.print-metrics=1
|
|
.
|
|
atexit handler executed
|
|
{ metrics : { bar : 2, foo : { a : 1, b : 5}}}
|
|
|
|
Metrics is logged to blackbox:
|
|
|
|
$ setconfig blackbox.track=metrics
|
|
$ hg log -r null -T '.\n' --config extensions.gauge=$TESTTMP/a.py
|
|
.
|
|
atexit handler executed
|
|
$ hg blackbox --no-timestamp --no-sid --pattern '{"legacy_log":{"service":"metrics"}}'
|
|
[legacy][metrics] {'metrics': {'bar': 2, 'foo': {'a': 1, 'b': 5}}}
|
|
[legacy][metrics] {'metrics': {'bar': 2, 'foo': {'a': 1, 'b': 5}}}
|
|
[legacy][metrics] {'metrics': {'bar': 2, 'foo': {'a': 1, 'b': 5}}}
|
|
atexit handler executed
|
|
|
|
Invalid format strings don't crash Mercurial
|
|
|
|
$ SCM_SAMPLING_FILEPATH=$TESTTMP/invalid.txt hg --config sampling.key.invalid=invalid debugsh -c 'repo.ui.log("invalid", "invalid format %s %s", "single")'
|
|
atexit handler executed
|
|
>>> import os, json
|
|
>>> with open(os.path.join(os.environ["TESTTMP"], "invalid.txt"), "r") as f:
|
|
... lines = f.read().split("\0")
|
|
... for line in lines:
|
|
... if "invalid" in line:
|
|
... obj = json.loads(line)
|
|
... category = obj["category"]
|
|
... data = obj["data"]
|
|
... print("category: %s" % category)
|
|
... for k, v in sorted(data.items()):
|
|
... print(" %s=%s" % (k, v))
|
|
category: invalid
|
|
metrics_type=invalid
|
|
msg=invalid format %s %s single
|