[thirdparty/git.git] / t / t0211-trace2-perf.sh

#!/bin/sh

test_description='test trace2 facility (perf target)'

TEST_PASSES_SANITIZE_LEAK=false
. ./test-lib.sh

# Turn off any inherited trace2 settings for this test.
sane_unset GIT_TRACE2 GIT_TRACE2_PERF GIT_TRACE2_EVENT
sane_unset GIT_TRACE2_PERF_BRIEF
sane_unset GIT_TRACE2_CONFIG_PARAMS

# Add t/helper directory to PATH so that we can use a relative
# path to run nested instances of test-tool.exe (see 004child).
# This helps with HEREDOC comparisons later.
TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
PATH="$TTDIR:$PATH" && export PATH

# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
# Warning: to do the actual diff/comparison, so the HEREDOCs here
# Warning: only cover our actual calls to test-tool and/or git.
# Warning: So you may see extra lines in artifact files when
# Warning: interactively debugging.

V=$(git version | sed -e 's/^git version //') && export V

# There are multiple trace2 targets: normal, perf, and event.
# Trace2 events will/can be written to each active target (subject
# to whatever filtering that target decides to do).
# Test each target independently.
#
# Defer setting GIT_TRACE2_PERF until the actual command we want to
# test because hidden git and test-tool commands in the test
# harness can contaminate our output.

# Enable "brief" feature which turns off the prefix:
#     "<clock> <file>:<line> | <nr_parents> | "
GIT_TRACE2_PERF_BRIEF=1 && export GIT_TRACE2_PERF_BRIEF

# Repeat some of the t0210 tests using the perf target stream instead of
# the normal stream.
#
# Tokens here of the form _FIELD_ have been replaced in the observed output.

# Verb 001return
#
# Implicit return from cmd_<verb> function propagates <code>.

test_expect_success 'perf stream, return code 0' '
	test_when_finished "rm trace.perf actual expect" &&
	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	cat >expect <<-EOF &&
		d0|main|version|||||$V
		d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
		d0|main|cmd_name|||||trace2 (trace2)
		d0|main|exit||_T_ABS_|||code:0
		d0|main|atexit||_T_ABS_|||code:0
	EOF
	test_cmp expect actual
'

test_expect_success 'perf stream, return code 1' '
	test_when_finished "rm trace.perf actual expect" &&
	test_must_fail env GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	cat >expect <<-EOF &&
		d0|main|version|||||$V
		d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1
		d0|main|cmd_name|||||trace2 (trace2)
		d0|main|exit||_T_ABS_|||code:1
		d0|main|atexit||_T_ABS_|||code:1
	EOF
	test_cmp expect actual
'

# Verb 003error
#
# To the above, add multiple 'error <msg>' events

test_expect_success 'perf stream, error event' '
	test_when_finished "rm trace.perf actual expect" &&
	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	cat >expect <<-EOF &&
		d0|main|version|||||$V
		d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
		d0|main|cmd_name|||||trace2 (trace2)
		d0|main|error|||||hello world
		d0|main|error|||||this is a test
		d0|main|exit||_T_ABS_|||code:0
		d0|main|atexit||_T_ABS_|||code:0
	EOF
	test_cmp expect actual
'

# Verb 004child
#
# Test nested spawning of child processes.
#
# Conceptually, this looks like:
#    P1: TT trace2 004child
#    P2: |--- TT trace2 004child
#    P3:      |--- TT trace2 001return 0
#
# Which should generate events:
#    P1: version
#    P1: start
#    P1: cmd_name
#    P1: child_start
#        P2: version
#        P2: start
#        P2: cmd_name
#        P2: child_start
#            P3: version
#            P3: start
#            P3: cmd_name
#            P3: exit
#            P3: atexit
#        P2: child_exit
#        P2: exit
#        P2: atexit
#    P1: child_exit
#    P1: exit
#    P1: atexit

test_expect_success 'perf stream, child processes' '
	test_when_finished "rm trace.perf actual expect" &&
	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	cat >expect <<-EOF &&
		d0|main|version|||||$V
		d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
		d0|main|cmd_name|||||trace2 (trace2)
		d0|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 004child test-tool trace2 001return 0]
		d1|main|version|||||$V
		d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
		d1|main|cmd_name|||||trace2 (trace2/trace2)
		d1|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 001return 0]
		d2|main|version|||||$V
		d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
		d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
		d2|main|exit||_T_ABS_|||code:0
		d2|main|atexit||_T_ABS_|||code:0
		d1|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
		d1|main|exit||_T_ABS_|||code:0
		d1|main|atexit||_T_ABS_|||code:0
		d0|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
		d0|main|exit||_T_ABS_|||code:0
		d0|main|atexit||_T_ABS_|||code:0
	EOF
	test_cmp expect actual
'

sane_unset GIT_TRACE2_PERF_BRIEF

# Now test without environment variables and get all Trace2 settings
# from the global config.

test_expect_success 'using global config, perf stream, return code 0' '
	test_when_finished "rm trace.perf actual expect" &&
	test_config_global trace2.perfBrief 1 &&
	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	test-tool trace2 001return 0 &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	cat >expect <<-EOF &&
		d0|main|version|||||$V
		d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
		d0|main|cmd_name|||||trace2 (trace2)
		d0|main|exit||_T_ABS_|||code:0
		d0|main|atexit||_T_ABS_|||code:0
	EOF
	test_cmp expect actual
'

# Exercise the stopwatch timers in a loop and confirm that we have
# as many start/stop intervals as expected.  We cannot really test the
# actual (total, min, max) timer values, so we have to assume that they
# are good, but we can verify the interval count.
#
# The timer "test/test1" should only emit a global summary "timer" event.
# The timer "test/test2" should emit per-thread "th_timer" events and a
# global summary "timer" event.

have_timer_event () {
	thread=$1 event=$2 category=$3 name=$4 intervals=$5 file=$6 &&

	pattern="d0|${thread}|${event}||||${category}|name:${name} intervals:${intervals}" &&

	grep "${pattern}" ${file}
}

test_expect_success 'stopwatch timer test/test1' '
	test_when_finished "rm trace.perf actual" &&
	test_config_global trace2.perfBrief 1 &&
	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

	# Use the timer "test1" 5 times from "main".
	test-tool trace2 100timer 5 10 &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

	have_timer_event "main" "timer" "test" "test1" 5 actual
'

test_expect_success PTHREADS 'stopwatch timer test/test2' '
	test_when_finished "rm trace.perf actual" &&
	test_config_global trace2.perfBrief 1 &&
	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

	# Use the timer "test2" 5 times each in 3 threads.
	test-tool trace2 101timer 5 10 3 &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

	# So we should have 3 per-thread events of 5 each.
	have_timer_event "th01:ut_101" "th_timer" "test" "test2" 5 actual &&
	have_timer_event "th02:ut_101" "th_timer" "test" "test2" 5 actual &&
	have_timer_event "th03:ut_101" "th_timer" "test" "test2" 5 actual &&

	# And we should have 15 total uses.
	have_timer_event "main" "timer" "test" "test2" 15 actual
'

# Exercise the global counters and confirm that we get the expected values.
#
# The counter "test/test1" should only emit a global summary "counter" event.
# The counter "test/test2" could emit per-thread "th_counter" events and a
# global summary "counter" event.

have_counter_event () {
	thread=$1 event=$2 category=$3 name=$4 value=$5 file=$6 &&

	pattern="d0|${thread}|${event}||||${category}|name:${name} value:${value}" &&

	grep "${patern}" ${file}
}

test_expect_success 'global counter test/test1' '
	test_when_finished "rm trace.perf actual" &&
	test_config_global trace2.perfBrief 1 &&
	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

	# Use the counter "test1" and add n integers.
	test-tool trace2 200counter 1 2 3 4 5 &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

	have_counter_event "main" "counter" "test" "test1" 15 actual
'

test_expect_success PTHREADS 'global counter test/test2' '
	test_when_finished "rm trace.perf actual" &&
	test_config_global trace2.perfBrief 1 &&
	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&

	# Add 2 integers to the counter "test2" in each of 3 threads.
	test-tool trace2 201counter 7 13 3 &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&

	# So we should have 3 per-thread events of 5 each.
	have_counter_event "th01:ut_201" "th_counter" "test" "test2" 20 actual &&
	have_counter_event "th02:ut_201" "th_counter" "test" "test2" 20 actual &&
	have_counter_event "th03:ut_201" "th_counter" "test" "test2" 20 actual &&

	# And we should have a single event with the total across all threads.
	have_counter_event "main" "counter" "test" "test2" 60 actual
'

test_expect_success 'unsafe URLs are redacted by default' '
	test_when_finished \
		"rm -r actual trace.perf unredacted.perf clone clone2" &&

	test_config_global \
		"url.$(pwd).insteadOf" https://user:pwd@example.com/ &&
	test_config_global trace2.configParams "core.*,remote.*.url" &&

	GIT_TRACE2_PERF="$(pwd)/trace.perf" \
		git clone https://user:pwd@example.com/ clone &&
	! grep user:pwd trace.perf &&

	GIT_TRACE2_REDACT=0 GIT_TRACE2_PERF="$(pwd)/unredacted.perf" \
		git clone https://user:pwd@example.com/ clone2 &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <unredacted.perf >actual &&
	grep "d0|main|start|.* clone https://user:pwd@example.com" actual &&
	grep "d0|main|def_param|.*|remote.origin.url:https://user:pwd@example.com" actual
'

# Confirm that the requested command produces a "cmd_name" and a
# set of "def_param" events.
#
try_simple () {
	test_when_finished "rm prop.perf actual" &&

	cmd=$1 &&
	cmd_name=$2 &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
			$cmd &&
	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	grep "d0|main|cmd_name|.*|$cmd_name" actual &&
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual
}

# Representative mainstream builtin Git command dispatched
# in run_builtin() in git.c
#
test_expect_success 'expect def_params for normal builtin command' '
	try_simple "git version" "version"
'

# Representative query command dispatched in handle_options()
# in git.c
#
test_expect_success 'expect def_params for query command' '
	try_simple "git --man-path" "_query_"
'

# remote-curl.c does not use the builtin setup in git.c, so confirm
# that executables built from remote-curl.c emit def_params.
#
# Also tests the dashed-command handling where "git foo" silently
# spawns "git-foo".  Make sure that both commands should emit
# def_params.
#
# Pass bogus arguments to remote-https and allow the command to fail
# because we don't actually have a remote to fetch from.  We just want
# to see the run-dashed code run an executable built from
# remote-curl.c rather than git.c.  Confirm that we get def_param
# events from both layers.
#
test_expect_success 'expect def_params for remote-curl and _run_dashed_' '
	test_when_finished "rm prop.perf actual" &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	test_might_fail env \
		ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
		git remote-http x y &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&

	grep "d0|main|cmd_name|.*|_run_dashed_" actual &&
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual &&

	grep "d1|main|cmd_name|.*|remote-curl" actual &&
	grep "d1|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual
'

# Similarly, `git-http-fetch` is not built from git.c so do a
# trivial fetch so that the main git.c run-dashed code spawns
# an executable built from http-fetch.c.  Confirm that we get
# def_param events from both layers.
#
test_expect_success 'expect def_params for http-fetch and _run_dashed_' '
	test_when_finished "rm prop.perf actual" &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	test_might_fail env \
		ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
		git http-fetch --stdin file:/// <<-EOF &&
	EOF

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&

	grep "d0|main|cmd_name|.*|_run_dashed_" actual &&
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual &&

	grep "d1|main|cmd_name|.*|http-fetch" actual &&
	grep "d1|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual
'

# Historically, alias expansion explicitly emitted the def_param
# events (independent of whether the command was a builtin, a Git
# command or arbitrary shell command) so that it wasn't dependent
# upon the unpeeling of the alias. Let's make sure that we preserve
# the net effect.
#
test_expect_success 'expect def_params during git alias expansion' '
	test_when_finished "rm prop.perf actual" &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	test_config_global "alias.xxx" "version" &&

	ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
			git xxx &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&

	# "git xxx" is first mapped to "git-xxx" and the child will fail.
	grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual &&

	# We unpeel that and substitute "version" into "xxx" (giving
	# "git version") and update the cmd_name event.
	grep "d0|main|cmd_name|.*|_run_git_alias_ (_run_dashed_/_run_git_alias_)" actual &&

	# These def_param events could be associated with either of the
	# above cmd_name events.  It does not matter.
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual &&

	# The "git version" child sees a different cmd_name hierarchy.
	# Also test the def_param (only for completeness).
	grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_git_alias_/version)" actual &&
	grep "d1|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual
'

test_expect_success 'expect def_params during shell alias expansion' '
	test_when_finished "rm prop.perf actual" &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	test_config_global "alias.xxx" "!git version" &&

	ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
			git xxx &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&

	# "git xxx" is first mapped to "git-xxx" and the child will fail.
	grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual &&

	# We unpeel that and substitute "git version" for "git xxx" (as a
	# shell command.  Another cmd_name event is emitted as we unpeel.
	grep "d0|main|cmd_name|.*|_run_shell_alias_ (_run_dashed_/_run_shell_alias_)" actual &&

	# These def_param events could be associated with either of the
	# above cmd_name events.  It does not matter.
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual &&

	# We get the following only because we used a git command for the
	# shell command. In general, it could have been a shell script and
	# we would see nothing.
	#
	# The child knows the cmd_name hierarchy so it includes it.
	grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_shell_alias_/version)" actual &&
	grep "d1|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual
'

test_expect_success 'expect def_params during nested git alias expansion' '
	test_when_finished "rm prop.perf actual" &&

	test_config_global "trace2.configParams" "cfg.prop.*" &&
	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&

	test_config_global "cfg.prop.foo" "red" &&

	test_config_global "alias.xxx" "yyy" &&
	test_config_global "alias.yyy" "version" &&

	ENV_PROP_FOO=blue \
		GIT_TRACE2_PERF="$(pwd)/prop.perf" \
			git xxx &&

	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&

	# "git xxx" is first mapped to "git-xxx" and try to spawn "git-xxx"
	# and the child will fail.
	grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual &&
	grep "d0|main|child_start|.*|.* class:dashed argv:\[git-xxx\]" actual &&

	# We unpeel that and substitute "yyy" into "xxx" (giving "git yyy")
	# and spawn "git-yyy" and the child will fail.
	grep "d0|main|alias|.*|alias:xxx argv:\[yyy\]" actual &&
	grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_/_run_dashed_)" actual &&
	grep "d0|main|child_start|.*|.* class:dashed argv:\[git-yyy\]" actual &&

	# We unpeel that and substitute "version" into "xxx" (giving
	# "git version") and update the cmd_name event.
	grep "d0|main|alias|.*|alias:yyy argv:\[version\]" actual &&
	grep "d0|main|cmd_name|.*|_run_git_alias_ (_run_dashed_/_run_dashed_/_run_git_alias_)" actual &&

	# These def_param events could be associated with any of the
	# above cmd_name events.  It does not matter.
	grep "d0|main|def_param|.*|cfg.prop.foo:red" actual >actual.matches &&
	grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual &&

	# However, we do not want them repeated each time we unpeel.
	test_line_count = 1 actual.matches &&

	# The "git version" child sees a different cmd_name hierarchy.
	# Also test the def_param (only for completeness).
	grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_dashed_/_run_git_alias_/version)" actual &&
	grep "d1|main|def_param|.*|cfg.prop.foo:red" actual &&
	grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual
'

test_done
Commit	Line	Data
a15860dc JH	1	#!/bin/sh
	2
	3	test_description='test trace2 facility (perf target)'
0033ab3f	4
c73e7f80	5	TEST_PASSES_SANITIZE_LEAK=false
a15860dc JH	6	. ./test-lib.sh
a15860dc JH	7
bce9db6d	8	# Turn off any inherited trace2 settings for this test.
e4b75d6a SG	9	sane_unset GIT_TRACE2 GIT_TRACE2_PERF GIT_TRACE2_EVENT
	10	sane_unset GIT_TRACE2_PERF_BRIEF
	11	sane_unset GIT_TRACE2_CONFIG_PARAMS
bce9db6d	12
a15860dc JH	13	# Add t/helper directory to PATH so that we can use a relative
	14	# path to run nested instances of test-tool.exe (see 004child).
	15	# This helps with HEREDOC comparisons later.
	16	TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
	17	PATH="$TTDIR:$PATH" && export PATH
	18
	19	# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
	20	# Warning: to do the actual diff/comparison, so the HEREDOCs here
	21	# Warning: only cover our actual calls to test-tool and/or git.
	22	# Warning: So you may see extra lines in artifact files when
	23	# Warning: interactively debugging.
	24
a15860dc JH	25	V=$(git version \| sed -e 's/^git version //') && export V
	26
	27	# There are multiple trace2 targets: normal, perf, and event.
	28	# Trace2 events will/can be written to each active target (subject
	29	# to whatever filtering that target decides to do).
	30	# Test each target independently.
	31	#
e4b75d6a	32	# Defer setting GIT_TRACE2_PERF until the actual command we want to
a15860dc JH	33	# test because hidden git and test-tool commands in the test
	34	# harness can contaminate our output.
	35
	36	# Enable "brief" feature which turns off the prefix:
	37	# "<clock> <file>:<line> \| <nr_parents> \| "
e4b75d6a	38	GIT_TRACE2_PERF_BRIEF=1 && export GIT_TRACE2_PERF_BRIEF
a15860dc JH	39
	40	# Repeat some of the t0210 tests using the perf target stream instead of
	41	# the normal stream.
	42	#
	43	# Tokens here of the form _FIELD_ have been replaced in the observed output.
	44
	45	# Verb 001return
	46	#
	47	# Implicit return from cmd_<verb> function propagates <code>.
	48
	49	test_expect_success 'perf stream, return code 0' '
	50	test_when_finished "rm trace.perf actual expect" &&
e4b75d6a	51	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
a15860dc JH	52	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	53	cat >expect <<-EOF &&
	54	d0\|main\|version\|\|\|\|\|$V
39f43177	55	d0\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 001return 0
a15860dc JH	56	d0\|main\|cmd_name\|\|\|\|\|trace2 (trace2)
	57	d0\|main\|exit\|\|_T_ABS_\|\|\|code:0
	58	d0\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	59	EOF
	60	test_cmp expect actual
	61	'
	62
	63	test_expect_success 'perf stream, return code 1' '
	64	test_when_finished "rm trace.perf actual expect" &&
e4b75d6a	65	test_must_fail env GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
a15860dc JH	66	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	67	cat >expect <<-EOF &&
	68	d0\|main\|version\|\|\|\|\|$V
39f43177	69	d0\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 001return 1
a15860dc JH	70	d0\|main\|cmd_name\|\|\|\|\|trace2 (trace2)
	71	d0\|main\|exit\|\|_T_ABS_\|\|\|code:1
	72	d0\|main\|atexit\|\|_T_ABS_\|\|\|code:1
	73	EOF
	74	test_cmp expect actual
	75	'
	76
	77	# Verb 003error
	78	#
	79	# To the above, add multiple 'error <msg>' events
	80
	81	test_expect_success 'perf stream, error event' '
	82	test_when_finished "rm trace.perf actual expect" &&
e4b75d6a	83	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
a15860dc JH	84	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	85	cat >expect <<-EOF &&
	86	d0\|main\|version\|\|\|\|\|$V
39f43177	87	d0\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
a15860dc JH	88	d0\|main\|cmd_name\|\|\|\|\|trace2 (trace2)
	89	d0\|main\|error\|\|\|\|\|hello world
	90	d0\|main\|error\|\|\|\|\|this is a test
	91	d0\|main\|exit\|\|_T_ABS_\|\|\|code:0
	92	d0\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	93	EOF
	94	test_cmp expect actual
	95	'
	96
	97	# Verb 004child
	98	#
	99	# Test nested spawning of child processes.
	100	#
	101	# Conceptually, this looks like:
	102	# P1: TT trace2 004child
	103	# P2: \|--- TT trace2 004child
	104	# P3: \|--- TT trace2 001return 0
	105	#
	106	# Which should generate events:
	107	# P1: version
	108	# P1: start
	109	# P1: cmd_name
	110	# P1: child_start
	111	# P2: version
	112	# P2: start
	113	# P2: cmd_name
	114	# P2: child_start
	115	# P3: version
	116	# P3: start
	117	# P3: cmd_name
	118	# P3: exit
	119	# P3: atexit
	120	# P2: child_exit
	121	# P2: exit
	122	# P2: atexit
	123	# P1: child_exit
	124	# P1: exit
	125	# P1: atexit
	126
	127	test_expect_success 'perf stream, child processes' '
	128	test_when_finished "rm trace.perf actual expect" &&
e4b75d6a	129	GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
a15860dc JH	130	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	131	cat >expect <<-EOF &&
	132	d0\|main\|version\|\|\|\|\|$V
39f43177	133	d0\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
a15860dc	134	d0\|main\|cmd_name\|\|\|\|\|trace2 (trace2)
742ed633	135	d0\|main\|child_start\|\|_T_ABS_\|\|\|[ch0] class:? argv:[test-tool trace2 004child test-tool trace2 001return 0]
a15860dc	136	d1\|main\|version\|\|\|\|\|$V
39f43177	137	d1\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 004child test-tool trace2 001return 0
a15860dc	138	d1\|main\|cmd_name\|\|\|\|\|trace2 (trace2/trace2)
742ed633	139	d1\|main\|child_start\|\|_T_ABS_\|\|\|[ch0] class:? argv:[test-tool trace2 001return 0]
a15860dc	140	d2\|main\|version\|\|\|\|\|$V
39f43177	141	d2\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 001return 0
a15860dc JH	142	d2\|main\|cmd_name\|\|\|\|\|trace2 (trace2/trace2/trace2)
	143	d2\|main\|exit\|\|_T_ABS_\|\|\|code:0
	144	d2\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	145	d1\|main\|child_exit\|\|_T_ABS_\|_T_REL_\|\|[ch0] pid:_PID_ code:0
	146	d1\|main\|exit\|\|_T_ABS_\|\|\|code:0
	147	d1\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	148	d0\|main\|child_exit\|\|_T_ABS_\|_T_REL_\|\|[ch0] pid:_PID_ code:0
	149	d0\|main\|exit\|\|_T_ABS_\|\|\|code:0
	150	d0\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	151	EOF
	152	test_cmp expect actual
	153	'
	154
e4b75d6a	155	sane_unset GIT_TRACE2_PERF_BRIEF
bce9db6d JH	156
	157	# Now test without environment variables and get all Trace2 settings
	158	# from the global config.
	159
	160	test_expect_success 'using global config, perf stream, return code 0' '
	161	test_when_finished "rm trace.perf actual expect" &&
	162	test_config_global trace2.perfBrief 1 &&
	163	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	164	test-tool trace2 001return 0 &&
	165	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	166	cat >expect <<-EOF &&
	167	d0\|main\|version\|\|\|\|\|$V
	168	d0\|main\|start\|\|_T_ABS_\|\|\|_EXE_ trace2 001return 0
	169	d0\|main\|cmd_name\|\|\|\|\|trace2 (trace2)
	170	d0\|main\|exit\|\|_T_ABS_\|\|\|code:0
	171	d0\|main\|atexit\|\|_T_ABS_\|\|\|code:0
	172	EOF
	173	test_cmp expect actual
	174	'
	175
8ad57564 JH	176	# Exercise the stopwatch timers in a loop and confirm that we have
	177	# as many start/stop intervals as expected. We cannot really test the
	178	# actual (total, min, max) timer values, so we have to assume that they
	179	# are good, but we can verify the interval count.
	180	#
	181	# The timer "test/test1" should only emit a global summary "timer" event.
	182	# The timer "test/test2" should emit per-thread "th_timer" events and a
	183	# global summary "timer" event.
	184
	185	have_timer_event () {
	186	thread=$1 event=$2 category=$3 name=$4 intervals=$5 file=$6 &&
	187
	188	pattern="d0\|${thread}\|${event}\|\|\|\|${category}\|name:${name} intervals:${intervals}" &&
	189
	190	grep "${pattern}" ${file}
	191	}
	192
	193	test_expect_success 'stopwatch timer test/test1' '
	194	test_when_finished "rm trace.perf actual" &&
	195	test_config_global trace2.perfBrief 1 &&
	196	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	197
	198	# Use the timer "test1" 5 times from "main".
	199	test-tool trace2 100timer 5 10 &&
	200
	201	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	202
	203	have_timer_event "main" "timer" "test" "test1" 5 actual
	204	'
	205
e48a21df	206	test_expect_success PTHREADS 'stopwatch timer test/test2' '
8ad57564 JH	207	test_when_finished "rm trace.perf actual" &&
	208	test_config_global trace2.perfBrief 1 &&
	209	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	210
	211	# Use the timer "test2" 5 times each in 3 threads.
	212	test-tool trace2 101timer 5 10 3 &&
	213
	214	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	215
	216	# So we should have 3 per-thread events of 5 each.
	217	have_timer_event "th01:ut_101" "th_timer" "test" "test2" 5 actual &&
	218	have_timer_event "th02:ut_101" "th_timer" "test" "test2" 5 actual &&
	219	have_timer_event "th03:ut_101" "th_timer" "test" "test2" 5 actual &&
	220
	221	# And we should have 15 total uses.
	222	have_timer_event "main" "timer" "test" "test2" 15 actual
	223	'
	224
81071626 JH	225	# Exercise the global counters and confirm that we get the expected values.
	226	#
	227	# The counter "test/test1" should only emit a global summary "counter" event.
	228	# The counter "test/test2" could emit per-thread "th_counter" events and a
	229	# global summary "counter" event.
	230
	231	have_counter_event () {
	232	thread=$1 event=$2 category=$3 name=$4 value=$5 file=$6 &&
	233
	234	pattern="d0\|${thread}\|${event}\|\|\|\|${category}\|name:${name} value:${value}" &&
	235
	236	grep "${patern}" ${file}
	237	}
	238
	239	test_expect_success 'global counter test/test1' '
	240	test_when_finished "rm trace.perf actual" &&
	241	test_config_global trace2.perfBrief 1 &&
	242	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	243
	244	# Use the counter "test1" and add n integers.
	245	test-tool trace2 200counter 1 2 3 4 5 &&
	246
	247	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	248
	249	have_counter_event "main" "counter" "test" "test1" 15 actual
	250	'
	251
e48a21df	252	test_expect_success PTHREADS 'global counter test/test2' '
81071626 JH	253	test_when_finished "rm trace.perf actual" &&
	254	test_config_global trace2.perfBrief 1 &&
	255	test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
	256
	257	# Add 2 integers to the counter "test2" in each of 3 threads.
	258	test-tool trace2 201counter 7 13 3 &&
	259
	260	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
	261
	262	# So we should have 3 per-thread events of 5 each.
	263	have_counter_event "th01:ut_201" "th_counter" "test" "test2" 20 actual &&
	264	have_counter_event "th02:ut_201" "th_counter" "test" "test2" 20 actual &&
	265	have_counter_event "th03:ut_201" "th_counter" "test" "test2" 20 actual &&
	266
	267	# And we should have a single event with the total across all threads.
	268	have_counter_event "main" "counter" "test" "test2" 60 actual
	269	'
	270
c73e7f80 JH	271	test_expect_success 'unsafe URLs are redacted by default' '
	272	test_when_finished \
	273	"rm -r actual trace.perf unredacted.perf clone clone2" &&
	274
	275	test_config_global \
	276	"url.$(pwd).insteadOf" https://user:pwd@example.com/ &&
	277	test_config_global trace2.configParams "core.,remote..url" &&
	278
	279	GIT_TRACE2_PERF="$(pwd)/trace.perf" \
	280	git clone https://user:pwd@example.com/ clone &&
	281	! grep user:pwd trace.perf &&
	282
	283	GIT_TRACE2_REDACT=0 GIT_TRACE2_PERF="$(pwd)/unredacted.perf" \
	284	git clone https://user:pwd@example.com/ clone2 &&
	285	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <unredacted.perf >actual &&
	286	grep "d0\|main\|start\|.* clone https://user:pwd@example.com" actual &&
	287	grep "d0\|main\|def_param\|.*\|remote.origin.url:https://user:pwd@example.com" actual
	288	'
	289
0c1c3c86 JH	290	# Confirm that the requested command produces a "cmd_name" and a
	291	# set of "def_param" events.
	292	#
	293	try_simple () {
	294	test_when_finished "rm prop.perf actual" &&
	295
	296	cmd=$1 &&
	297	cmd_name=$2 &&
	298
	299	test_config_global "trace2.configParams" "cfg.prop.*" &&
	300	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
	301
	302	test_config_global "cfg.prop.foo" "red" &&
	303
	304	ENV_PROP_FOO=blue \
	305	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
	306	$cmd &&
	307	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	308	grep "d0\|main\|cmd_name\|.*\|$cmd_name" actual &&
	309	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	310	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
	311	}
	312
	313	# Representative mainstream builtin Git command dispatched
	314	# in run_builtin() in git.c
	315	#
	316	test_expect_success 'expect def_params for normal builtin command' '
	317	try_simple "git version" "version"
	318	'
	319
	320	# Representative query command dispatched in handle_options()
	321	# in git.c
	322	#
6111252c	323	test_expect_success 'expect def_params for query command' '
0c1c3c86 JH	324	try_simple "git --man-path" "_query_"
	325	'
	326
	327	# remote-curl.c does not use the builtin setup in git.c, so confirm
	328	# that executables built from remote-curl.c emit def_params.
	329	#
	330	# Also tests the dashed-command handling where "git foo" silently
	331	# spawns "git-foo". Make sure that both commands should emit
	332	# def_params.
	333	#
	334	# Pass bogus arguments to remote-https and allow the command to fail
	335	# because we don't actually have a remote to fetch from. We just want
	336	# to see the run-dashed code run an executable built from
	337	# remote-curl.c rather than git.c. Confirm that we get def_param
	338	# events from both layers.
	339	#
6111252c	340	test_expect_success 'expect def_params for remote-curl and _run_dashed_' '
0c1c3c86 JH	341	test_when_finished "rm prop.perf actual" &&
	342
	343	test_config_global "trace2.configParams" "cfg.prop.*" &&
	344	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
	345
	346	test_config_global "cfg.prop.foo" "red" &&
	347
	348	test_might_fail env \
	349	ENV_PROP_FOO=blue \
	350	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
	351	git remote-http x y &&
	352
	353	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	354
	355	grep "d0\|main\|cmd_name\|.*\|_run_dashed_" actual &&
	356	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	357	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual &&
	358
	359	grep "d1\|main\|cmd_name\|.*\|remote-curl" actual &&
	360	grep "d1\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	361	grep "d1\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
	362	'
	363
	364	# Similarly, `git-http-fetch` is not built from git.c so do a
	365	# trivial fetch so that the main git.c run-dashed code spawns
	366	# an executable built from http-fetch.c. Confirm that we get
	367	# def_param events from both layers.
	368	#
6111252c	369	test_expect_success 'expect def_params for http-fetch and _run_dashed_' '
0c1c3c86 JH	370	test_when_finished "rm prop.perf actual" &&
	371
	372	test_config_global "trace2.configParams" "cfg.prop.*" &&
	373	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
	374
	375	test_config_global "cfg.prop.foo" "red" &&
	376
	377	test_might_fail env \
	378	ENV_PROP_FOO=blue \
	379	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
	380	git http-fetch --stdin file:/// <<-EOF &&
	381	EOF
	382
	383	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	384
	385	grep "d0\|main\|cmd_name\|.*\|_run_dashed_" actual &&
	386	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	387	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual &&
	388
	389	grep "d1\|main\|cmd_name\|.*\|http-fetch" actual &&
	390	grep "d1\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	391	grep "d1\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
	392	'
	393
	394	# Historically, alias expansion explicitly emitted the def_param
	395	# events (independent of whether the command was a builtin, a Git
	396	# command or arbitrary shell command) so that it wasn't dependent
	397	# upon the unpeeling of the alias. Let's make sure that we preserve
	398	# the net effect.
	399	#
	400	test_expect_success 'expect def_params during git alias expansion' '
	401	test_when_finished "rm prop.perf actual" &&
	402
	403	test_config_global "trace2.configParams" "cfg.prop.*" &&
	404	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
	405
	406	test_config_global "cfg.prop.foo" "red" &&
	407
	408	test_config_global "alias.xxx" "version" &&
	409
	410	ENV_PROP_FOO=blue \
	411	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
	412	git xxx &&
	413
	414	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	415
	416	# "git xxx" is first mapped to "git-xxx" and the child will fail.
	417	grep "d0\|main\|cmd_name\|.*\|_run_dashed_ (_run_dashed_)" actual &&
	418
	419	# We unpeel that and substitute "version" into "xxx" (giving
	420	# "git version") and update the cmd_name event.
	421	grep "d0\|main\|cmd_name\|.*\|_run_git_alias_ (_run_dashed_/_run_git_alias_)" actual &&
	422
	423	# These def_param events could be associated with either of the
	424	# above cmd_name events. It does not matter.
	425	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	426	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual &&
	427
	428	# The "git version" child sees a different cmd_name hierarchy.
	429	# Also test the def_param (only for completeness).
	430	grep "d1\|main\|cmd_name\|.*\|version (_run_dashed_/_run_git_alias_/version)" actual &&
	431	grep "d1\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	432	grep "d1\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
	433	'
434
435	test_expect_success 'expect def_params during shell alias expansion' '
436	test_when_finished "rm prop.perf actual" &&
437
438	test_config_global "trace2.configParams" "cfg.prop.*" &&
439	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
440
441	test_config_global "cfg.prop.foo" "red" &&
442
443	test_config_global "alias.xxx" "!git version" &&
444
445	ENV_PROP_FOO=blue \
446	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
447	git xxx &&
448
449	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
450
451	# "git xxx" is first mapped to "git-xxx" and the child will fail.
452	grep "d0\|main\|cmd_name\|.*\|_run_dashed_ (_run_dashed_)" actual &&
453
454	# We unpeel that and substitute "git version" for "git xxx" (as a
455	# shell command. Another cmd_name event is emitted as we unpeel.
456	grep "d0\|main\|cmd_name\|.*\|_run_shell_alias_ (_run_dashed_/_run_shell_alias_)" actual &&
457
458	# These def_param events could be associated with either of the
459	# above cmd_name events. It does not matter.
460	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
461	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual &&
462
463	# We get the following only because we used a git command for the
464	# shell command. In general, it could have been a shell script and
465	# we would see nothing.
466	#
467	# The child knows the cmd_name hierarchy so it includes it.
468	grep "d1\|main\|cmd_name\|.*\|version (_run_dashed_/_run_shell_alias_/version)" actual &&
469	grep "d1\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
470	grep "d1\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
471	'
472
520cf668	473	test_expect_success 'expect def_params during nested git alias expansion' '
0c1c3c86 JH	474	test_when_finished "rm prop.perf actual" &&
	475
	476	test_config_global "trace2.configParams" "cfg.prop.*" &&
	477	test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" &&
	478
	479	test_config_global "cfg.prop.foo" "red" &&
	480
	481	test_config_global "alias.xxx" "yyy" &&
	482	test_config_global "alias.yyy" "version" &&
	483
	484	ENV_PROP_FOO=blue \
	485	GIT_TRACE2_PERF="$(pwd)/prop.perf" \
	486	git xxx &&
	487
	488	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <prop.perf >actual &&
	489
	490	# "git xxx" is first mapped to "git-xxx" and try to spawn "git-xxx"
	491	# and the child will fail.
	492	grep "d0\|main\|cmd_name\|.*\|_run_dashed_ (_run_dashed_)" actual &&
	493	grep "d0\|main\|child_start\|.\|. class:dashed argv:\[git-xxx\]" actual &&
	494
	495	# We unpeel that and substitute "yyy" into "xxx" (giving "git yyy")
	496	# and spawn "git-yyy" and the child will fail.
	497	grep "d0\|main\|alias\|.*\|alias:xxx argv:\[yyy\]" actual &&
	498	grep "d0\|main\|cmd_name\|.*\|_run_dashed_ (_run_dashed_/_run_dashed_)" actual &&
	499	grep "d0\|main\|child_start\|.\|. class:dashed argv:\[git-yyy\]" actual &&
	500
	501	# We unpeel that and substitute "version" into "xxx" (giving
	502	# "git version") and update the cmd_name event.
	503	grep "d0\|main\|alias\|.*\|alias:yyy argv:\[version\]" actual &&
	504	grep "d0\|main\|cmd_name\|.*\|_run_git_alias_ (_run_dashed_/_run_dashed_/_run_git_alias_)" actual &&
	505
	506	# These def_param events could be associated with any of the
	507	# above cmd_name events. It does not matter.
	508	grep "d0\|main\|def_param\|.*\|cfg.prop.foo:red" actual >actual.matches &&
	509	grep "d0\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual &&
	510
	511	# However, we do not want them repeated each time we unpeel.
	512	test_line_count = 1 actual.matches &&
	513
	514	# The "git version" child sees a different cmd_name hierarchy.
	515	# Also test the def_param (only for completeness).
	516	grep "d1\|main\|cmd_name\|.*\|version (_run_dashed_/_run_dashed_/_run_git_alias_/version)" actual &&
	517	grep "d1\|main\|def_param\|.*\|cfg.prop.foo:red" actual &&
	518	grep "d1\|main\|def_param\|.*\|ENV_PROP_FOO:blue" actual
	519	'
	520
a15860dc	521	test_done