Memory leak exposed by address sanitizer in insertable_collection example

[lifflander]

2021-03-09T20:34:54.1367935Z         Start   8: vt_example:insertable_collection_2
2021-03-09T20:34:54.2355824Z   8/322 Test   #8: vt_example:insertable_collection_2 .................................................***Failed    0.10 sec
2021-03-09T20:34:54.2357899Z �[32;1mvt�[00m: �[32mRuntime Initializing:�[00m �[32mmode: �[00m�[95msingle-thread per rank�[00m
2021-03-09T20:34:54.2359025Z �[00m�[32;1mvt�[00m: �[32mProgram: �[95minsertable_collection�[00m (�[95m./insertable_collection�[00m)
2021-03-09T20:34:54.2359875Z �[00m�[32;1mvt�[00m: �[32mRunning on: �[95m2 nodes�[00m
2021-03-09T20:34:54.2360799Z �[00m�[32;1mvt�[00m: �[32mMachine Hostname: �[95mf08f628cf7e7�[00m
2021-03-09T20:34:54.2361496Z �[00m�[32;1mvt�[00m: �[32mMPI Version: �[95m3�[00m.�[95m1�[00m
2021-03-09T20:34:54.2362151Z �[00m�[32;1mvt�[00m: �[32mMPI Max tag: �[95m268435455�[00m
2021-03-09T20:34:54.2362870Z �[00m�[32;1mvt�[00m: �[32mBuild SHA: �[95m6276e4bbf8206c7497451f2893bb2291bc36ea7f�[00m
2021-03-09T20:34:54.2363531Z �[00m�[32;1mvt�[00m: �[32mBuild Ref: �[95m�[00m
2021-03-09T20:34:54.2364307Z �[00m�[32;1mvt�[00m: �[32mDescription: �[95mremotes/origin/6276e4bbf8206c7497451f2893bb2291bc36ea7f-0-g6276e4bbf8�[00m 
2021-03-09T20:34:54.2365118Z �[00m�[32;1mvt�[00m: �[32mCompile-time Features Enabled:�[00m
2021-03-09T20:34:54.2366058Z �[00m�[32;1mvt�[00m: 	�[95mTracing Projections�[00m
2021-03-09T20:34:54.2366778Z �[32;1mvt�[00m: 	�[95mC++ Trait Detector�[00m
2021-03-09T20:34:54.2367416Z �[32;1mvt�[00m: 	�[95mLoad Balancing for Collections�[00m
2021-03-09T20:34:54.2368040Z �[32;1mvt�[00m: 	�[95mMessage priorities�[00m
2021-03-09T20:34:54.2368678Z �[32;1mvt�[00m: 	�[95mstd::thread Threading�[00m
2021-03-09T20:34:54.2369287Z �[32;1mvt�[00m: 	�[95mMPI access guards�[00m
2021-03-09T20:34:54.2369926Z �[32;1mvt�[00m: 	�[95mPerformance analysis diagnostics�[00m
2021-03-09T20:34:54.2370577Z �[32;1mvt�[00m: �[32mRuntime Configuration:�[00m
2021-03-09T20:34:54.2371776Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_sched_num_progress�[00m on: Running MPI progress 2 times each invocation�[00m
2021-03-09T20:34:54.2372906Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_sched_progress_han�[00m on: Running MPI progress function at least every 0 handler(s) executed�[00m
2021-03-09T20:34:54.2374054Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_print_no_progress�[00m on: Printing warnings when progress is stalls�[00m
2021-03-09T20:34:54.2375041Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Printing verbose epoch graphs when hang detected, use �[95m--vt_epoch_graph_terse�[00m to disable�[00m
2021-03-09T20:34:54.2376027Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_epoch_graph_on_hang�[00m on: Epoch graph output enabled if hang detected�[00m
2021-03-09T20:34:54.2377056Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Termination hang detection enabled by default, use �[95m--vt_no_detect_hang�[00m to disable�[00m
2021-03-09T20:34:54.2377947Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_hang_detect�[00m on: Printing stall warning every 1024 tree traversals �[00m
2021-03-09T20:34:54.2378832Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m SIGINT signal handling enabled by default, use �[95m--vt_no_SIGINT�[00m to disable�[00m
2021-03-09T20:34:54.2379683Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m SIGSEGV signal handling enabled by default, use �[95m--vt_no_SIGSEGV�[00m to disable�[00m
2021-03-09T20:34:54.2380580Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m std::terminate signal handling enabled by default, use �[95m--vt_no_terminate�[00m to disable�[00m
2021-03-09T20:34:54.2381400Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Color output enabled, use �[95m--vt_no_color�[00m to disable�[00m
2021-03-09T20:34:54.2382208Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Stack dumps enabled by default, use �[95m--vt_no_stack�[00m to disable�[00m
2021-03-09T20:34:54.2383193Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_memory_reporters�[00m on: Memory usage checker precedence: mstats,machinfo,selfstat,selfstatm,sbrk,mallinfo,getrusage,ps�[00m
2021-03-09T20:34:54.2384074Z �[00m�[32;1mvt�[00m: 	�[32mWorking memory reporters:�[00m �[95mselfstatm,getrusage�[00m
2021-03-09T20:34:54.2384908Z �[00m�[32;1mvt�[00m: 	�[32mInitial memory usage:�[00m �[32mselfstatm�[00m=�[95m35.3984�[00m �[32mgetrusage�[00m=�[95m35.4453�[00m (MiB)
2021-03-09T20:34:54.2385781Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Memory usage printing disabled, use �[95m--vt_print_memory_each_phase�[00m to enable�[00m
2021-03-09T20:34:54.2386636Z �[00m�[32;1mvt�[00m: 	�[32mDefault:�[00m Diagnostics are disabled by default, use �[95m--vt_diag_enable�[00m to enable�[00m
2021-03-09T20:34:54.2387668Z �[00m�[32;1mvt�[00m: 	�[32mOption:�[00m flag �[95m--vt_max_mpi_send_size�[00m on: Splitting messages greater than 1 GiB�[00m
2021-03-09T20:34:54.2388378Z �[00m�[32;1mvt�[00m: �[32mPass-through Arguments:�[00m
2021-03-09T20:34:54.2388951Z �[00m�[32;1mvt�[00m: 	None. All arguments handled.
2021-03-09T20:34:54.2389450Z �[00m�[00mcalling finished insert
2021-03-09T20:34:54.2389783Z 0: constructing: idx=0
2021-03-09T20:34:54.2390097Z 0: constructing: idx=2
2021-03-09T20:34:54.2390407Z 0: constructing: idx=4
2021-03-09T20:34:54.2390716Z 0: constructing: idx=6
2021-03-09T20:34:54.2391025Z 0: constructing: idx=8
2021-03-09T20:34:54.2391335Z 0: constructing: idx=10
2021-03-09T20:34:54.2391647Z 0: constructing: idx=12
2021-03-09T20:34:54.2392062Z 0: constructing: idx=14
2021-03-09T20:34:54.2392375Z 0: constructing: idx=16
2021-03-09T20:34:54.2392687Z 0: constructing: idx=18
2021-03-09T20:34:54.2392999Z 0: constructing: idx=20
2021-03-09T20:34:54.2393310Z 0: constructing: idx=22
2021-03-09T20:34:54.2393625Z 0: constructing: idx=24
2021-03-09T20:34:54.2393935Z 0: constructing: idx=26
2021-03-09T20:34:54.2394243Z 0: constructing: idx=28
2021-03-09T20:34:54.2394552Z 0: constructing: idx=30
2021-03-09T20:34:54.2394861Z 1: constructing: idx=1
2021-03-09T20:34:54.2395170Z 1: constructing: idx=3
2021-03-09T20:34:54.2395478Z 1: constructing: idx=5
2021-03-09T20:34:54.2395788Z 1: constructing: idx=11
2021-03-09T20:34:54.2396100Z 1: constructing: idx=15
2021-03-09T20:34:54.2396410Z 1: constructing: idx=17
2021-03-09T20:34:54.2396721Z 1: constructing: idx=27
2021-03-09T20:34:54.2397033Z 1: constructing: idx=29
2021-03-09T20:34:54.2397345Z 1: constructing: idx=25
2021-03-09T20:34:54.2397656Z 1: constructing: idx=7
2021-03-09T20:34:54.2397970Z 1: constructing: idx=9
2021-03-09T20:34:54.2398279Z 1: constructing: idx=21
2021-03-09T20:34:54.2398588Z 1: constructing: idx=19
2021-03-09T20:34:54.2398896Z 1: constructing: idx=13
2021-03-09T20:34:54.2399203Z 1: constructing: idx=31
2021-03-09T20:34:54.2399516Z 1: constructing: idx=23
2021-03-09T20:34:54.2399841Z insertions are finished (first phase)
2021-03-09T20:34:54.2400167Z 1: constructing: idx=33
2021-03-09T20:34:54.2400476Z 1: constructing: idx=35
2021-03-09T20:34:54.2400785Z 1: constructing: idx=37
2021-03-09T20:34:54.2401094Z 1: constructing: idx=43
2021-03-09T20:34:54.2401402Z 1: constructing: idx=45
2021-03-09T20:34:54.2401709Z 0: constructing: idx=32
2021-03-09T20:34:54.2402019Z 0: constructing: idx=40
2021-03-09T20:34:54.2402329Z 0: constructing: idx=42
2021-03-09T20:34:54.2402640Z 0: constructing: idx=46
2021-03-09T20:34:54.2402950Z 0: constructing: idx=48
2021-03-09T20:34:54.2403259Z 0: constructing: idx=34
2021-03-09T20:34:54.2403569Z 0: constructing: idx=38
2021-03-09T20:34:54.2403887Z 0: constructing: idx=50
2021-03-09T20:34:54.2404199Z 0: constructing: idx=52
2021-03-09T20:34:54.2404508Z 1: constructing: idx=59
2021-03-09T20:34:54.2404817Z 0: constructing: idx=54
2021-03-09T20:34:54.2405126Z 1: constructing: idx=61
2021-03-09T20:34:54.2405442Z 0: constructing: idx=56
2021-03-09T20:34:54.2405751Z 1: constructing: idx=63
2021-03-09T20:34:54.2406061Z 1: constructing: idx=57
2021-03-09T20:34:54.2406373Z 1: constructing: idx=55
2021-03-09T20:34:54.2406682Z 1: constructing: idx=53
2021-03-09T20:34:54.2406991Z 1: constructing: idx=51
2021-03-09T20:34:54.2407302Z 1: constructing: idx=49
2021-03-09T20:34:54.2407611Z 0: constructing: idx=62
2021-03-09T20:34:54.2407921Z 1: constructing: idx=47
2021-03-09T20:34:54.2408229Z 1: constructing: idx=41
2021-03-09T20:34:54.2408540Z 0: constructing: idx=60
2021-03-09T20:34:54.2408851Z 1: constructing: idx=39
2021-03-09T20:34:54.2409161Z 0: constructing: idx=44
2021-03-09T20:34:54.2409472Z 0: constructing: idx=36
2021-03-09T20:34:54.2409783Z 0: constructing: idx=58
2021-03-09T20:34:54.2410115Z insertions are finished (second phase)
2021-03-09T20:34:54.2410892Z �[32;1mvt�[00m: �[32mTotal collective epochs processed:�[00m �[95m0�[00m
2021-03-09T20:34:54.2411604Z �[32;1mvt�[00m: �[32mTotal work units processed:�[00m �[95m554�[00m
2021-03-09T20:34:54.2412365Z �[32;1mvt�[00m: �[32mRuntime Finalizing�[00m�[00m
2021-03-09T20:34:54.2412677Z 
2021-03-09T20:34:54.2454478Z =================================================================
2021-03-09T20:34:54.2454929Z ==1791==ERROR: LeakSanitizer: detected memory leaks
2021-03-09T20:34:54.2455134Z 
2021-03-09T20:34:54.2455480Z Direct leak of 64 byte(s) in 1 object(s) allocated from:
2021-03-09T20:34:54.2456301Z     #0 0x7f7494e06b40 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xdeb40)
2021-03-09T20:34:54.2456843Z     #1 0x7f749453a002 in MPIDI_CH3U_Receive_data_unexpected (/usr/local/lib/libmpi.so.12+0x122002)
2021-03-09T20:34:54.2457094Z 
2021-03-09T20:34:54.2457434Z SUMMARY: AddressSanitizer: 64 byte(s) leaked in 1 allocation(s).
2021-03-09T20:34:54.2457958Z 

[PhilMiller]

Should we add an exclusion for this? Track it down and report it upstream? Update MPI library version we're installing in that container?

[cz4rs]

I'm not hitting it consistently in local environment, but ctest -R insertable_collection_2 --repeat-until-fail 100 reproduces it sure enough.
It seems that it's not related to the last PR merged. I will try to see which change has introduced it.

Edit:
Test passes fine requires 6000+ repetitions to fail at 1c0e8bc, it seems like the issue was introduced made more apparent with 90206c6 (PR #1301). The commit looks innocent, so 👍 for exclusion at least to get our sanitize build working.

[cz4rs]

The decision after DARMA Weekly was that this should be blacklisted.

Silencing the error

• gcc does not support -fsanitize-blacklist
  • reference: AddressSanitizer#turning-off-instrumentation
• we cannot add no_sanitize_address attribute to MPIDI_CH3U_Receive_data_unexpected since it is mpich code

This means that we cannot silence this error in any reasonable way while using gcc-8 for asan build. We could move asan check to one of the clang builds and use -fsanitize-blacklist there - is that acceptable?

Origin of the leak

• similar error was mentioned at mpich mailing list (no follow-up unfortunately): https://lists.mpich.org/pipermail/discuss/2016-August/000399.html
• probable culprit in mpich code (notice FIXME comments):
  int MPIDI_CH3U_Post_data_receive_unexpected(MPIR_Request * rreq)

It seems that changes in PR #1301 have somehow triggered the leak.
To reproduce the bug (using ctest -R insertable_collection_2 --output-on-failure --repeat-until-fail 10000) it took me roughly:

• below 10 repetitions at 90206c6 (and later commits)
• 6000+ repetitions at 1c0e8bc

I was able to run the test 10000 times without a failure at 16362a0 (before #1301 was merged).

Open MPI
Enabling address sanitizer in openmpi build shows multiple leaks in multiple examples and tests - see openmpi-asan-build.log.

[PhilMiller]

I think there's an option to load a blacklist through an environment variable at runtime

[cz4rs]

I think there's an option to load a blacklist through an environment variable at runtime

LSAN_OPTIONS - I didn't notice this before. Checking the details right now. 👍

[PhilMiller]

https://github.com/google/sanitizers/wiki/AddressSanitizerFlags
ASAN_OPTIONS, look for suppression