| 1 | #!/bin/sh |
| 2 | |
| 3 | test_description='test trace2 facility (normal target)' |
| 4 | |
| 5 | . ./test-lib.sh |
| 6 | |
| 7 | # Turn off any inherited trace2 settings for this test. |
| 8 | sane_unset GIT_TRACE2 GIT_TRACE2_PERF GIT_TRACE2_EVENT |
| 9 | sane_unset GIT_TRACE2_BRIEF |
| 10 | sane_unset GIT_TRACE2_CONFIG_PARAMS |
| 11 | |
| 12 | # Add t/helper directory to PATH so that we can use a relative |
| 13 | # path to run nested instances of test-tool.exe (see 004child). |
| 14 | # This helps with HEREDOC comparisons later. |
| 15 | TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR |
| 16 | PATH="$TTDIR:$PATH" && export PATH |
| 17 | |
| 18 | # Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe |
| 19 | # Warning: to do the actual diff/comparison, so the HEREDOCs here |
| 20 | # Warning: only cover our actual calls to test-tool and/or git. |
| 21 | # Warning: So you may see extra lines in artifact files when |
| 22 | # Warning: interactively debugging. |
| 23 | |
| 24 | V=$(git version | sed -e 's/^git version //') && export V |
| 25 | |
| 26 | # There are multiple trace2 targets: normal, perf, and event. |
| 27 | # Trace2 events will/can be written to each active target (subject |
| 28 | # to whatever filtering that target decides to do). |
| 29 | # This script tests the normal target in isolation. |
| 30 | # |
| 31 | # Defer setting GIT_TRACE2 until the actual command line we want to test |
| 32 | # because hidden git and test-tool commands run by the test harness |
| 33 | # can contaminate our output. |
| 34 | |
| 35 | # Enable "brief" feature which turns off "<clock> <file>:<line> " prefix. |
| 36 | GIT_TRACE2_BRIEF=1 && export GIT_TRACE2_BRIEF |
| 37 | |
| 38 | # Basic tests of the trace2 normal stream. Since this stream is used |
| 39 | # primarily with printf-style debugging/tracing, we do limited testing |
| 40 | # here. |
| 41 | # |
| 42 | # We do confirm the following API features: |
| 43 | # [] the 'version <v>' event |
| 44 | # [] the 'start <argv>' event |
| 45 | # [] the 'cmd_name <name>' event |
| 46 | # [] the 'exit <time> code:<code>' event |
| 47 | # [] the 'atexit <time> code:<code>' event |
| 48 | # |
| 49 | # Fields of the form _FIELD_ are tokens that have been replaced (such |
| 50 | # as the elapsed time). |
| 51 | |
| 52 | # Verb 001return |
| 53 | # |
| 54 | # Implicit return from cmd_<verb> function propagates <code>. |
| 55 | |
| 56 | scrub_normal () { |
| 57 | # Scrub the variable fields from the normal trace2 output to make |
| 58 | # testing easier: |
| 59 | # |
| 60 | # 1. Various messages include an elapsed time in the middle of the |
| 61 | # message. Replace the time with a placeholder to simplify our |
| 62 | # HEREDOC in the test script. |
| 63 | # |
| 64 | # 2. We expect: |
| 65 | # |
| 66 | # start <argv0> [<argv1> [<argv2> [...]]] |
| 67 | # |
| 68 | # where argv0 might be a relative or absolute path, with or |
| 69 | # without quotes, and platform dependent. Replace argv0 with a |
| 70 | # token for HEREDOC matching in the test script. |
| 71 | # |
| 72 | # 3. Likewise, the 'cmd_path' message breaks out argv[0]. |
| 73 | # |
| 74 | # This line is only emitted when RUNTIME_PREFIX is defined, |
| 75 | # so just omit it for testing purposes. |
| 76 | # |
| 77 | # 4. 'cmd_ancestry' output depends on how the test is run and |
| 78 | # is not relevant to the features we are testing here. |
| 79 | # Ancestry tests are covered in t0213-trace2-ancestry.sh instead. |
| 80 | sed \ |
| 81 | -e 's/elapsed:[0-9]*\.[0-9][0-9]*\([eE][-+]\{0,1\}[0-9][0-9]*\)\{0,1\}/elapsed:_TIME_/g' \ |
| 82 | -e "s/^start '[^']*' \(.*\)/start _EXE_ \1/" \ |
| 83 | -e 's/^start [^ ][^ ]* \(.*\)/start _EXE_ \1/' \ |
| 84 | -e '/^cmd_path/d' \ |
| 85 | -e '/^cmd_ancestry/d' |
| 86 | } |
| 87 | |
| 88 | test_expect_success 'normal stream, return code 0' ' |
| 89 | test_when_finished "rm trace.normal actual expect" && |
| 90 | GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 001return 0 && |
| 91 | scrub_normal <trace.normal >actual && |
| 92 | cat >expect <<-EOF && |
| 93 | version $V |
| 94 | start _EXE_ trace2 001return 0 |
| 95 | cmd_name trace2 (trace2) |
| 96 | exit elapsed:_TIME_ code:0 |
| 97 | atexit elapsed:_TIME_ code:0 |
| 98 | EOF |
| 99 | test_cmp expect actual |
| 100 | ' |
| 101 | |
| 102 | test_expect_success 'normal stream, return code 1' ' |
| 103 | test_when_finished "rm trace.normal actual expect" && |
| 104 | test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 001return 1 && |
| 105 | scrub_normal <trace.normal >actual && |
| 106 | cat >expect <<-EOF && |
| 107 | version $V |
| 108 | start _EXE_ trace2 001return 1 |
| 109 | cmd_name trace2 (trace2) |
| 110 | exit elapsed:_TIME_ code:1 |
| 111 | atexit elapsed:_TIME_ code:1 |
| 112 | EOF |
| 113 | test_cmp expect actual |
| 114 | ' |
| 115 | |
| 116 | test_expect_success 'automatic filename' ' |
| 117 | test_when_finished "rm -r traces actual expect" && |
| 118 | mkdir traces && |
| 119 | GIT_TRACE2="$(pwd)/traces" test-tool trace2 001return 0 && |
| 120 | scrub_normal <"$(ls traces/*)" >actual && |
| 121 | cat >expect <<-EOF && |
| 122 | version $V |
| 123 | start _EXE_ trace2 001return 0 |
| 124 | cmd_name trace2 (trace2) |
| 125 | exit elapsed:_TIME_ code:0 |
| 126 | atexit elapsed:_TIME_ code:0 |
| 127 | EOF |
| 128 | test_cmp expect actual |
| 129 | ' |
| 130 | |
| 131 | # Verb 002exit |
| 132 | # |
| 133 | # Explicit exit(code) from within cmd_<verb> propagates <code>. |
| 134 | |
| 135 | test_expect_success 'normal stream, exit code 0' ' |
| 136 | test_when_finished "rm trace.normal actual expect" && |
| 137 | GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 002exit 0 && |
| 138 | scrub_normal <trace.normal >actual && |
| 139 | cat >expect <<-EOF && |
| 140 | version $V |
| 141 | start _EXE_ trace2 002exit 0 |
| 142 | cmd_name trace2 (trace2) |
| 143 | exit elapsed:_TIME_ code:0 |
| 144 | atexit elapsed:_TIME_ code:0 |
| 145 | EOF |
| 146 | test_cmp expect actual |
| 147 | ' |
| 148 | |
| 149 | test_expect_success 'normal stream, exit code 1' ' |
| 150 | test_when_finished "rm trace.normal actual expect" && |
| 151 | test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 002exit 1 && |
| 152 | scrub_normal <trace.normal >actual && |
| 153 | cat >expect <<-EOF && |
| 154 | version $V |
| 155 | start _EXE_ trace2 002exit 1 |
| 156 | cmd_name trace2 (trace2) |
| 157 | exit elapsed:_TIME_ code:1 |
| 158 | atexit elapsed:_TIME_ code:1 |
| 159 | EOF |
| 160 | test_cmp expect actual |
| 161 | ' |
| 162 | |
| 163 | # Verb 003error |
| 164 | # |
| 165 | # To the above, add multiple 'error <msg>' events |
| 166 | |
| 167 | test_expect_success 'normal stream, error event' ' |
| 168 | test_when_finished "rm trace.normal actual expect" && |
| 169 | GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 003error "hello world" "this is a test" && |
| 170 | scrub_normal <trace.normal >actual && |
| 171 | cat >expect <<-EOF && |
| 172 | version $V |
| 173 | start _EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\'' |
| 174 | cmd_name trace2 (trace2) |
| 175 | error hello world |
| 176 | error this is a test |
| 177 | exit elapsed:_TIME_ code:0 |
| 178 | atexit elapsed:_TIME_ code:0 |
| 179 | EOF |
| 180 | test_cmp expect actual |
| 181 | ' |
| 182 | |
| 183 | # Verb 007bug |
| 184 | # |
| 185 | # Check that BUG writes to trace2 |
| 186 | |
| 187 | test_expect_success 'BUG messages are written to trace2' ' |
| 188 | test_when_finished "rm trace.normal actual expect" && |
| 189 | test_must_fail env GIT_TRACE2="$(pwd)/trace.normal" test-tool trace2 007bug && |
| 190 | scrub_normal <trace.normal >actual && |
| 191 | cat >expect <<-EOF && |
| 192 | version $V |
| 193 | start _EXE_ trace2 007bug |
| 194 | cmd_name trace2 (trace2) |
| 195 | error the bug message |
| 196 | exit elapsed:_TIME_ code:99 |
| 197 | atexit elapsed:_TIME_ code:99 |
| 198 | EOF |
| 199 | test_cmp expect actual |
| 200 | ' |
| 201 | |
| 202 | test_expect_success 'bug messages with BUG_if_bug() are written to trace2' ' |
| 203 | test_when_finished "rm trace.normal actual expect" && |
| 204 | test_expect_code 99 env GIT_TRACE2="$(pwd)/trace.normal" \ |
| 205 | test-tool trace2 008bug 2>err && |
| 206 | cat >expect <<-\EOF && |
| 207 | a bug message |
| 208 | another bug message |
| 209 | an explicit BUG_if_bug() following bug() call(s) is nice, but not required |
| 210 | EOF |
| 211 | sed "s/^.*: //" <err >actual && |
| 212 | test_cmp expect actual && |
| 213 | |
| 214 | scrub_normal <trace.normal >actual && |
| 215 | cat >expect <<-EOF && |
| 216 | version $V |
| 217 | start _EXE_ trace2 008bug |
| 218 | cmd_name trace2 (trace2) |
| 219 | error a bug message |
| 220 | error another bug message |
| 221 | error an explicit BUG_if_bug() following bug() call(s) is nice, but not required |
| 222 | exit elapsed:_TIME_ code:99 |
| 223 | atexit elapsed:_TIME_ code:99 |
| 224 | EOF |
| 225 | test_cmp expect actual |
| 226 | ' |
| 227 | |
| 228 | test_expect_success 'bug messages without explicit BUG_if_bug() are written to trace2' ' |
| 229 | test_when_finished "rm trace.normal actual expect" && |
| 230 | test_expect_code 99 env GIT_TRACE2="$(pwd)/trace.normal" \ |
| 231 | test-tool trace2 009bug_BUG 2>err && |
| 232 | cat >expect <<-\EOF && |
| 233 | a bug message |
| 234 | another bug message |
| 235 | had bug() call(s) in this process without explicit BUG_if_bug() |
| 236 | EOF |
| 237 | sed "s/^.*: //" <err >actual && |
| 238 | test_cmp expect actual && |
| 239 | |
| 240 | scrub_normal <trace.normal >actual && |
| 241 | cat >expect <<-EOF && |
| 242 | version $V |
| 243 | start _EXE_ trace2 009bug_BUG |
| 244 | cmd_name trace2 (trace2) |
| 245 | error a bug message |
| 246 | error another bug message |
| 247 | error on exit(): had bug() call(s) in this process without explicit BUG_if_bug() |
| 248 | exit elapsed:_TIME_ code:99 |
| 249 | atexit elapsed:_TIME_ code:99 |
| 250 | EOF |
| 251 | test_cmp expect actual |
| 252 | ' |
| 253 | |
| 254 | test_expect_success 'bug messages followed by BUG() are written to trace2' ' |
| 255 | test_when_finished "rm trace.normal actual expect" && |
| 256 | test_expect_code 99 env GIT_TRACE2="$(pwd)/trace.normal" \ |
| 257 | test-tool trace2 010bug_BUG 2>err && |
| 258 | cat >expect <<-\EOF && |
| 259 | a bug message |
| 260 | a BUG message |
| 261 | EOF |
| 262 | sed "s/^.*: //" <err >actual && |
| 263 | test_cmp expect actual && |
| 264 | |
| 265 | scrub_normal <trace.normal >actual && |
| 266 | cat >expect <<-EOF && |
| 267 | version $V |
| 268 | start _EXE_ trace2 010bug_BUG |
| 269 | cmd_name trace2 (trace2) |
| 270 | error a bug message |
| 271 | error a BUG message |
| 272 | exit elapsed:_TIME_ code:99 |
| 273 | atexit elapsed:_TIME_ code:99 |
| 274 | EOF |
| 275 | test_cmp expect actual |
| 276 | ' |
| 277 | |
| 278 | test_expect_success 'a valueless true configuration variable is handled' ' |
| 279 | test_when_finished "rm -f trace2.normal actual expect" && |
| 280 | echo >expect && |
| 281 | GIT_TRACE2="$(pwd)/trace2.normal" \ |
| 282 | GIT_TRACE2_CONFIG_PARAMS=foo.true \ |
| 283 | git -c foo.true config foo.true >actual && |
| 284 | test_cmp expect actual |
| 285 | ' |
| 286 | |
| 287 | sane_unset GIT_TRACE2_BRIEF |
| 288 | |
| 289 | # Now test without environment variables and get all Trace2 settings |
| 290 | # from the global config. |
| 291 | |
| 292 | test_expect_success 'using global config, normal stream, return code 0' ' |
| 293 | test_when_finished "rm trace.normal actual expect" && |
| 294 | test_config_global trace2.normalBrief 1 && |
| 295 | test_config_global trace2.normalTarget "$(pwd)/trace.normal" && |
| 296 | test-tool trace2 001return 0 && |
| 297 | scrub_normal <trace.normal >actual && |
| 298 | cat >expect <<-EOF && |
| 299 | version $V |
| 300 | start _EXE_ trace2 001return 0 |
| 301 | cmd_name trace2 (trace2) |
| 302 | exit elapsed:_TIME_ code:0 |
| 303 | atexit elapsed:_TIME_ code:0 |
| 304 | EOF |
| 305 | test_cmp expect actual |
| 306 | ' |
| 307 | |
| 308 | test_expect_success 'using global config with include' ' |
| 309 | test_when_finished "rm trace.normal actual expect real.gitconfig" && |
| 310 | test_config_global trace2.normalBrief 1 && |
| 311 | test_config_global trace2.normalTarget "$(pwd)/trace.normal" && |
| 312 | mv "$(pwd)/.gitconfig" "$(pwd)/real.gitconfig" && |
| 313 | test_config_global include.path "$(pwd)/real.gitconfig" && |
| 314 | test-tool trace2 001return 0 && |
| 315 | scrub_normal <trace.normal >actual && |
| 316 | cat >expect <<-EOF && |
| 317 | version $V |
| 318 | start _EXE_ trace2 001return 0 |
| 319 | cmd_name trace2 (trace2) |
| 320 | exit elapsed:_TIME_ code:0 |
| 321 | atexit elapsed:_TIME_ code:0 |
| 322 | EOF |
| 323 | test_cmp expect actual |
| 324 | ' |
| 325 | |
| 326 | test_expect_success 'unsafe URLs are redacted by default' ' |
| 327 | test_when_finished \ |
| 328 | "rm -r trace.normal unredacted.normal clone clone2" && |
| 329 | |
| 330 | test_config_global \ |
| 331 | "url.$(pwd).insteadOf" https://user:pwd@example.com/ && |
| 332 | test_config_global trace2.configParams "core.*,remote.*.url" && |
| 333 | |
| 334 | GIT_TRACE2="$(pwd)/trace.normal" \ |
| 335 | git clone https://user:pwd@example.com/ clone && |
| 336 | test_grep ! user:pwd trace.normal && |
| 337 | |
| 338 | GIT_TRACE2_REDACT=0 GIT_TRACE2="$(pwd)/unredacted.normal" \ |
| 339 | git clone https://user:pwd@example.com/ clone2 && |
| 340 | test_grep "start .* clone https://user:pwd@example.com" unredacted.normal && |
| 341 | test_grep "remote.origin.url=https://user:pwd@example.com" unredacted.normal |
| 342 | ' |
| 343 | |
| 344 | test_done |