{"thread":{"id":"62186","subject":"[PATCH 0/3] LSan quality of life improvements","startedAt":"2024-09-24T21:34:05Z","lastAt":"2024-09-27T03:58:33Z","messageCount":9,"participants":["Jeff King","Patrick Steinhardt"],"isPatch":true,"patchVersion":1,"patchTotal":3},"messages":[{"id":"503399","messageId":"20240924213404.GA1142219@coredump.intra.peff.net","threadId":"62186","inReplyTo":null,"subject":"[PATCH 0/3] LSan quality of life improvements","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-24T21:34:04Z","receivedAt":"2024-09-24T21:34:05Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"I was fixing some leaks the other day and came up with a few changes\nthat made the process a bit less painful, especially when the leaks are\nhidden in sub-processes (which is most of them when you are digging into\nhttp push/fetch, as I was).\n\nI hope we're not too far off from a world where leaks are something that\npop up in your newly written code, and you're not slogging through\nexisting test scripts. But until then, I hope these might help others.\n\nIf you want to see the before/after, try:\n\n  cd t\n  ./t5550-http-fetch-dumb.sh -i\n\nbefore and after this series. Before you get no leaks reported to stdout\nwith \"-i\", and way too many without it. After, you get the leaks for the\nfirst test that generates them.\n\n  [1/3]: test-lib: stop showing old leak logs\n  [2/3]: test-lib: show leak-sanitizer logs on --immediate failure\n  [3/3]: test-lib: check for leak logs after every test\n\n t/test-lib-functions.sh |  3 ++-\n t/test-lib.sh           | 41 ++++++-----------------------------------\n 2 files changed, 8 insertions(+), 36 deletions(-)\n\n-Peff\n"},{"id":"503401","messageId":"20240924213540.GA1142403@coredump.intra.peff.net","threadId":"62186","inReplyTo":"20240924213404.GA1142219@coredump.intra.peff.net","subject":"[PATCH 1/3] test-lib: stop showing old leak logs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-24T21:35:40Z","receivedAt":"2024-09-24T21:35:42Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"We ask LSan to record the logs of all leaks in test-results/, which is\nuseful for finding leaks that didn't trigger a test failure.\n\nWe don't clean out the leak/ directory for each test before running it,\nthough. Instead, we count the number of files it has, and complain only\nif we ended up with more when the script finishes. So we shouldn't\ntrigger any output if you've made a script leak free. But if you simply\n_reduced_ the number of leaks, then there is an annoying outcome: we do\nnot record which logs were from this run and which were from previous\nones. So when we dump them to stdout, you get a mess of\npossibly-outdated leaks. This is very confusing when you are in an\nedit-compile-test cycle trying to fix leaks.\n\nThe instructions do note that you should \"rm -rf test-results/\" if you\nwant to avoid this. But I'm having trouble seeing how this cumulative\ncount could ever be useful. It is not even counting the number of leaks,\nbut rather the number of processes with at least one leak!\n\nSo let's just blow away the per-test leak/ directory before running. We\nalready overwrite the \".out\" file in test-results/ in the same way, so\nthis is following that pattern.\n\nRunning \"make test\" isn't affected by this, since it blows away all of\ntest-results/ already. This only comes up when you are iterating on a\nsingle script that you're running manually.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/test-lib.sh | 35 ++---------------------------------\n 1 file changed, 2 insertions(+), 33 deletions(-)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex e718efe4c6..7d4471fbc5 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -322,7 +322,6 @@ TEST_RESULTS_SAN_FILE_PFX=trace\n TEST_RESULTS_SAN_DIR_SFX=leak\n TEST_RESULTS_SAN_FILE=\n TEST_RESULTS_SAN_DIR=\"$TEST_RESULTS_DIR/$TEST_NAME.$TEST_RESULTS_SAN_DIR_SFX\"\n-TEST_RESULTS_SAN_DIR_NR_LEAKS_STARTUP=\n TRASH_DIRECTORY=\"trash directory.$TEST_NAME$TEST_STRESS_JOB_SFX\"\n test -n \"$root\" && TRASH_DIRECTORY=\"$root/$TRASH_DIRECTORY\"\n case \"$TRASH_DIRECTORY\" in\n@@ -1215,42 +1214,15 @@ test_atexit_handler () {\n \tteardown_malloc_check\n }\n \n-sanitize_leak_log_message_ () {\n-\tlocal new=\"$1\" &&\n-\tlocal old=\"$2\" &&\n-\tlocal file=\"$3\" &&\n-\n-\tprintf \"With SANITIZE=leak at exit we have %d leak logs, but started with %d\n-\n-This means that we have a blindspot where git is leaking but we're\n-losing the exit code somewhere, or not propagating it appropriately\n-upwards!\n-\n-See the logs at \\\"%s.*\\\";\n-those logs are reproduced below.\" \\\n-\t       \"$new\" \"$old\" \"$file\"\n-}\n-\n check_test_results_san_file_ () {\n \tif test -z \"$TEST_RESULTS_SAN_FILE\"\n \tthen\n \t\treturn\n \tfi &&\n-\tlocal old=\"$TEST_RESULTS_SAN_DIR_NR_LEAKS_STARTUP\" &&\n-\tlocal new=\"$(nr_san_dir_leaks_)\" &&\n-\n-\tif test $new -le $old\n+\tif test \"$(nr_san_dir_leaks_)\" = 0\n \tthen\n \t\treturn\n \tfi &&\n-\tlocal out=\"$(sanitize_leak_log_message_ \"$new\" \"$old\" \"$TEST_RESULTS_SAN_FILE\")\" &&\n-\tsay_color error \"$out\" &&\n-\tif test \"$old\" != 0\n-\tthen\n-\t\techo &&\n-\t\tsay_color error \"The logs include output from past runs to avoid\" &&\n-\t\tsay_color error \"that remove 'test-results' between runs.\"\n-\tfi &&\n \tsay_color error \"$(cat \"$TEST_RESULTS_SAN_FILE\".*)\" &&\n \n \tif test -n \"$passes_sanitize_leak\" && test \"$test_failure\" = 0\n@@ -1586,16 +1558,13 @@ then\n \t\ttest_done\n \tfi\n \n+\trm -rf \"$TEST_RESULTS_SAN_DIR\"\n \tif ! mkdir -p \"$TEST_RESULTS_SAN_DIR\"\n \tthen\n \t\tBAIL_OUT \"cannot create $TEST_RESULTS_SAN_DIR\"\n \tfi &&\n \tTEST_RESULTS_SAN_FILE=\"$TEST_RESULTS_SAN_DIR/$TEST_RESULTS_SAN_FILE_PFX\"\n \n-\t# In case \"test-results\" is left over from a previous\n-\t# run: Only report if new leaks show up.\n-\tTEST_RESULTS_SAN_DIR_NR_LEAKS_STARTUP=$(nr_san_dir_leaks_)\n-\n \t# Don't litter *.leak dirs if there was nothing to report\n \ttest_atexit \"rmdir \\\"$TEST_RESULTS_SAN_DIR\\\" 2>/dev/null || :\"\n \n-- \n2.46.2.1011.gf1f9323e02\n\n"},{"id":"503402","messageId":"20240924213636.GB1142403@coredump.intra.peff.net","threadId":"62186","inReplyTo":"20240924213404.GA1142219@coredump.intra.peff.net","subject":"[PATCH 2/3] test-lib: show leak-sanitizer logs on --immediate failure","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-24T21:36:36Z","receivedAt":"2024-09-24T21:36:37Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"When we've compiled with SANITIZE=leak, at the end of the test script\nwe'll dump any collected logs to stdout. These logs have two uses:\n\n  1. Leaks don't always cause a test snippet to fail (e.g., if they\n     happen in a sub-process that we expect to return non-zero).\n     Checking the logs catches these cases that we'd otherwise miss\n     entirely.\n\n  2. LSan will dump the leak info to stderr, but that is sometimes\n     hidden (e.g., because it's redirected by the test, or because it's\n     in a sub-process whose stderr goes elsewhere). Dumping the logs is\n     the easiest way for the developer to see them.\n\nOne downside is that the set of logs for an entire script may be very\nlong, especially when you're trying to fix existing test scripts. You\ncan run with --immediate to stop at the first failing test, which means\nwe'll have accrued fewer logs. But we don't show the logs in that case!\n\nLet's start doing so. This can only help case (2), of course (since it\ndepends on test failure). And it's somewhat weakened by the fact that\nany cases of (1) will pollute the logs. But we can improve things\nfurther in the next patch.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/test-lib.sh | 1 +\n 1 file changed, 1 insertion(+)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 7d4471fbc5..d624ee186c 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -847,6 +847,7 @@ test_failure_ () {\n \t\t\tGIT_EXIT_OK=t\n \t\t\texit 0\n \t\tfi\n+\t\tcheck_test_results_san_file_ \"$test_failure\"\n \t\t_error_exit\n \tfi\n \tfinalize_test_case_output failure \"$failure_label\" \"$@\"\n-- \n2.46.2.1011.gf1f9323e02\n\n"},{"id":"503403","messageId":"20240924213836.GC1142403@coredump.intra.peff.net","threadId":"62186","inReplyTo":"20240924213404.GA1142219@coredump.intra.peff.net","subject":"[PATCH 3/3] test-lib: check for leak logs after every test","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-24T21:38:36Z","receivedAt":"2024-09-24T21:38:37Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"If you are trying to find and fix leaks in a large test script, it can\nbe overwhelming to see the leak logs for every test at once. The\nprevious commit let you use \"--immediate\" to see the logs after the\nfirst failing test, but this isn't always the first leak. As discussed\nthere, we may see leaks from previous tests that didn't happen to fail.\n\nTo catch those, let's check for any logs that appeared after each test\nsnippet is run, meaning that in a SANITIZE=leak build, any leak is an\nimmediate failure of the test snippet.\n\nThis check is mostly free in non-leak builds (just a \"test -z\"), and\nonly a few extra processes in a leak build, so I don't think the\noverhead should matter (if it does, we could probably optimize for the\ncommon \"no logs\" case without even spending a process).\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/test-lib-functions.sh |  3 ++-\n t/test-lib.sh           | 11 ++++++-----\n 2 files changed, 8 insertions(+), 6 deletions(-)\n\ndiff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh\nindex fde9bf54fc..78e054ab50 100644\n--- a/t/test-lib-functions.sh\n+++ b/t/test-lib-functions.sh\n@@ -926,7 +926,8 @@ test_expect_success () {\n \t\ttest_body_or_stdin test_body \"$2\"\n \t\ttest -n \"$test_skip_test_preamble\" ||\n \t\tsay >&3 \"expecting success of $TEST_NUMBER.$test_count '$1': $test_body\"\n-\t\tif test_run_ \"$test_body\"\n+\t\tif test_run_ \"$test_body\" &&\n+\t\t   check_test_results_san_file_empty_\n \t\tthen\n \t\t\ttest_ok_ \"$1\"\n \t\telse\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex d624ee186c..b1a8ee5c00 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -1215,12 +1215,13 @@ test_atexit_handler () {\n \tteardown_malloc_check\n }\n \n+check_test_results_san_file_empty_ () {\n+\ttest -z \"$TEST_RESULTS_SAN_FILE\" ||\n+\ttest \"$(nr_san_dir_leaks_)\" = 0\n+}\n+\n check_test_results_san_file_ () {\n-\tif test -z \"$TEST_RESULTS_SAN_FILE\"\n-\tthen\n-\t\treturn\n-\tfi &&\n-\tif test \"$(nr_san_dir_leaks_)\" = 0\n+\tif check_test_results_san_file_empty_\n \tthen\n \t\treturn\n \tfi &&\n-- \n2.46.2.1011.gf1f9323e02\n"},{"id":"503557","messageId":"ZvVtZDrUwkdeRbje@pks.im","threadId":"62186","inReplyTo":"20240924213540.GA1142403@coredump.intra.peff.net","subject":"Re: [PATCH 1/3] test-lib: stop showing old leak logs","fromName":"Patrick Steinhardt","fromEmail":"ps@pks.im","sentAt":"2024-09-26T14:19:16Z","receivedAt":"2024-09-26T14:19:25Z","isPatch":true,"sender":{"key":"ps@pks.im","avatar":"https://avatars.githubusercontent.com/u/4056630?v=4"},"body":"On Tue, Sep 24, 2024 at 05:35:40PM -0400, Jeff King wrote:\n> We ask LSan to record the logs of all leaks in test-results/, which is\n> useful for finding leaks that didn't trigger a test failure.\n> \n> We don't clean out the leak/ directory for each test before running it,\n> though. Instead, we count the number of files it has, and complain only\n> if we ended up with more when the script finishes. So we shouldn't\n> trigger any output if you've made a script leak free. But if you simply\n> _reduced_ the number of leaks, then there is an annoying outcome: we do\n> not record which logs were from this run and which were from previous\n> ones. So when we dump them to stdout, you get a mess of\n> possibly-outdated leaks. This is very confusing when you are in an\n> edit-compile-test cycle trying to fix leaks.\n> \n> The instructions do note that you should \"rm -rf test-results/\" if you\n> want to avoid this. But I'm having trouble seeing how this cumulative\n> count could ever be useful. It is not even counting the number of leaks,\n> but rather the number of processes with at least one leak!\n> \n> So let's just blow away the per-test leak/ directory before running. We\n> already overwrite the \".out\" file in test-results/ in the same way, so\n> this is following that pattern.\n> \n> Running \"make test\" isn't affected by this, since it blows away all of\n> test-results/ already. This only comes up when you are iterating on a\n> single script that you're running manually.\n\nI'm very much in favor of this change. I frequently re-ran tests with\nleak checking enabled only to realize that, oops, I forgot to \"rm -rf\"\nthe leak directory first. So eventually I ended up with the following\ncommand:\n\n    $ rm -rf /tmp/git-tests/ && make -C .. -j20 SANITIZE=leak && ./t5310-pack-bitmaps.sh -ix\n\nEvery time I didn't use it I soon came to regret it.\n\nPatrick\n"},{"id":"503558","messageId":"ZvVtafQfwnh6NLmQ@pks.im","threadId":"62186","inReplyTo":"20240924213636.GB1142403@coredump.intra.peff.net","subject":"Re: [PATCH 2/3] test-lib: show leak-sanitizer logs on --immediate failure","fromName":"Patrick Steinhardt","fromEmail":"ps@pks.im","sentAt":"2024-09-26T14:19:21Z","receivedAt":"2024-09-26T14:19:26Z","isPatch":true,"sender":{"key":"ps@pks.im","avatar":"https://avatars.githubusercontent.com/u/4056630?v=4"},"body":"On Tue, Sep 24, 2024 at 05:36:36PM -0400, Jeff King wrote:\n> When we've compiled with SANITIZE=leak, at the end of the test script\n> we'll dump any collected logs to stdout. These logs have two uses:\n> \n>   1. Leaks don't always cause a test snippet to fail (e.g., if they\n>      happen in a sub-process that we expect to return non-zero).\n>      Checking the logs catches these cases that we'd otherwise miss\n>      entirely.\n> \n>   2. LSan will dump the leak info to stderr, but that is sometimes\n>      hidden (e.g., because it's redirected by the test, or because it's\n>      in a sub-process whose stderr goes elsewhere). Dumping the logs is\n>      the easiest way for the developer to see them.\n> \n> One downside is that the set of logs for an entire script may be very\n> long, especially when you're trying to fix existing test scripts. You\n> can run with --immediate to stop at the first failing test, which means\n> we'll have accrued fewer logs. But we don't show the logs in that case!\n> \n> Let's start doing so. This can only help case (2), of course (since it\n> depends on test failure). And it's somewhat weakened by the fact that\n> any cases of (1) will pollute the logs. But we can improve things\n> further in the next patch.\n\nYes, please!\n\nPatrick\n"},{"id":"503559","messageId":"ZvVtbPw5VjTSfwzH@pks.im","threadId":"62186","inReplyTo":"20240924213836.GC1142403@coredump.intra.peff.net","subject":"Re: [PATCH 3/3] test-lib: check for leak logs after every test","fromName":"Patrick Steinhardt","fromEmail":"ps@pks.im","sentAt":"2024-09-26T14:19:24Z","receivedAt":"2024-09-26T14:19:29Z","isPatch":true,"sender":{"key":"ps@pks.im","avatar":"https://avatars.githubusercontent.com/u/4056630?v=4"},"body":"On Tue, Sep 24, 2024 at 05:38:36PM -0400, Jeff King wrote:\n> If you are trying to find and fix leaks in a large test script, it can\n> be overwhelming to see the leak logs for every test at once. The\n> previous commit let you use \"--immediate\" to see the logs after the\n> first failing test, but this isn't always the first leak. As discussed\n> there, we may see leaks from previous tests that didn't happen to fail.\n> \n> To catch those, let's check for any logs that appeared after each test\n> snippet is run, meaning that in a SANITIZE=leak build, any leak is an\n> immediate failure of the test snippet.\n> \n> This check is mostly free in non-leak builds (just a \"test -z\"), and\n> only a few extra processes in a leak build, so I don't think the\n> overhead should matter (if it does, we could probably optimize for the\n> common \"no logs\" case without even spending a process).\n\nSo previously, `--immediate` didn't detect tests that should have failed\nbecause they were leaks, and now it does? Sounds like a sensible change\nto me, too.\n\nPatrick\n"},{"id":"503560","messageId":"ZvVtcJOsbbrnWukB@pks.im","threadId":"62186","inReplyTo":"20240924213404.GA1142219@coredump.intra.peff.net","subject":"Re: [PATCH 0/3] LSan quality of life improvements","fromName":"Patrick Steinhardt","fromEmail":"ps@pks.im","sentAt":"2024-09-26T14:19:28Z","receivedAt":"2024-09-26T14:19:33Z","isPatch":true,"sender":{"key":"ps@pks.im","avatar":"https://avatars.githubusercontent.com/u/4056630?v=4"},"body":"On Tue, Sep 24, 2024 at 05:34:04PM -0400, Jeff King wrote:\n> I was fixing some leaks the other day and came up with a few changes\n> that made the process a bit less painful, especially when the leaks are\n> hidden in sub-processes (which is most of them when you are digging into\n> http push/fetch, as I was).\n> \n> I hope we're not too far off from a world where leaks are something that\n> pop up in your newly written code, and you're not slogging through\n> existing test scripts. But until then, I hope these might help others.\n> \n> If you want to see the before/after, try:\n> \n>   cd t\n>   ./t5550-http-fetch-dumb.sh -i\n> \n> before and after this series. Before you get no leaks reported to stdout\n> with \"-i\", and way too many without it. After, you get the leaks for the\n> first test that generates them.\n> \n>   [1/3]: test-lib: stop showing old leak logs\n>   [2/3]: test-lib: show leak-sanitizer logs on --immediate failure\n>   [3/3]: test-lib: check for leak logs after every test\n\nThanks, all of these look like strict improvements to me! Now I wish\nthat I had all of these changes earlier, as that would have made my\nleak-fixing sessions way more enjoyable.\n\nPatrick\n"},{"id":"503600","messageId":"20240927035832.GI567395@coredump.intra.peff.net","threadId":"62186","inReplyTo":"ZvVtbPw5VjTSfwzH@pks.im","subject":"Re: [PATCH 3/3] test-lib: check for leak logs after every test","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-27T03:58:32Z","receivedAt":"2024-09-27T03:58:33Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Sep 26, 2024 at 04:19:24PM +0200, Patrick Steinhardt wrote:\n\n> On Tue, Sep 24, 2024 at 05:38:36PM -0400, Jeff King wrote:\n> > If you are trying to find and fix leaks in a large test script, it can\n> > be overwhelming to see the leak logs for every test at once. The\n> > previous commit let you use \"--immediate\" to see the logs after the\n> > first failing test, but this isn't always the first leak. As discussed\n> > there, we may see leaks from previous tests that didn't happen to fail.\n> > \n> > To catch those, let's check for any logs that appeared after each test\n> > snippet is run, meaning that in a SANITIZE=leak build, any leak is an\n> > immediate failure of the test snippet.\n> > \n> > This check is mostly free in non-leak builds (just a \"test -z\"), and\n> > only a few extra processes in a leak build, so I don't think the\n> > overhead should matter (if it does, we could probably optimize for the\n> > common \"no logs\" case without even spending a process).\n> \n> So previously, `--immediate` didn't detect tests that should have failed\n> because they were leaks, and now it does? Sounds like a sensible change\n> to me, too.\n\nYes, though just to be pedantic, they are marked as failures even\nwithout --immediate. It is just that doing so is a lot more useful with\n--immediate, since otherwise we'd find the leaks at the end (but even\nthat it may still be useful to point to a particular test).\n\nSo it really is \"if you are in a SANITIZE=leak build, generating a leak\nlog fails the test even if it would otherwise pass\".\n\n-Peff\n"}]}