t/t0211-trace2-perf.sh

   1 #!/bin/sh
   2
   3 test_description='test trace2 facility (perf target)'
   4
   5 TEST_PASSES_SANITIZE_LEAK=false
   6 . ./test-lib.sh
   7
   8 # Turn off any inherited trace2 settings for this test.
   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
  12
  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
  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 #
  32 # Defer setting GIT_TRACE2_PERF until the actual command we want to
  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> | "
  38 GIT_TRACE2_PERF_BRIEF=1 && export GIT_TRACE2_PERF_BRIEF
  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" &&
  51         GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
  52         perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
  53         cat >expect <<-EOF &&
  54                 d0|main|version|||||$V
  55                 d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
  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" &&
  65         test_must_fail env GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
  66         perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
  67         cat >expect <<-EOF &&
  68                 d0|main|version|||||$V
  69                 d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1
  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" &&
  83         GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
  84         perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
  85         cat >expect <<-EOF &&
  86                 d0|main|version|||||$V
  87                 d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
  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" &&
 129         GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
 130         perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
 131         cat >expect <<-EOF &&
 132                 d0|main|version|||||$V
 133                 d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
 134                 d0|main|cmd_name|||||trace2 (trace2)
 135                 d0|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 004child test-tool trace2 001return 0]
 136                 d1|main|version|||||$V
 137                 d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
 138                 d1|main|cmd_name|||||trace2 (trace2/trace2)
 139                 d1|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 001return 0]
 140                 d2|main|version|||||$V
 141                 d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
 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
 155 sane_unset GIT_TRACE2_PERF_BRIEF
 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
 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
 206 test_expect_success PTHREADS 'stopwatch timer test/test2' '
 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
 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
 252 test_expect_success PTHREADS 'global counter test/test2' '
 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
 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
 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 #
 323 test_expect_success 'expect def_params for query command' '
 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 #
 340 test_expect_success 'expect def_params for remote-curl and _run_dashed_' '
 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 #
 369 test_expect_success 'expect def_params for http-fetch and _run_dashed_' '
 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
 473 test_expect_success 'expect def_params during nested git alias expansion' '
 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
 521 test_done