Valgrind reports memory leak in tracing_subscriber

[clubby789]

Bug Report

Version

> cargo tree | grep tracing
├── tracing v0.1.33
│   ├── tracing-attributes v0.1.20 (proc-macro)
│   └── tracing-core v0.1.24
└── tracing-subscriber v0.3.11
    ├── tracing-core v0.1.24 (*)
    └── tracing-log v0.1.2
        └── tracing-core v0.1.24 (*)

Platform

Linux clubby789 5.16.18-1-MANJARO #1 SMP PREEMPT Mon Mar 28 09:13:53 UTC 2022 x86_64 GNU/Linux

Crates

tracing_subscriber

Description

Running this program:

use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt::init();
    info!("Hello, world!");
}

under Valgrind (--leak-check=full --show-leak-kinds=all) reports

==28380== 
==28380== LEAK SUMMARY:
==28380==    definitely lost: 0 bytes in 0 blocks
==28380==    indirectly lost: 0 bytes in 0 blocks
==28380==      possibly lost: 0 bytes in 0 blocks
==28380==    still reachable: 34,136 bytes in 8 blocks
==28380==         suppressed: 0 bytes in 0 blocks

Removing the tracing_subscriber::fmt::init() call results in no leaks being reported

Full Valgrind output

==28380== Memcheck, a memory error detector
==28380== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==28380== Using Valgrind-3.18.1 and LibVEX; rerun with -h for copyright info
==28380== Command: ./target/debug/tracetest
==28380== 
2022-04-12T11:55:31.413744Z  INFO tracetest: Hello, world!
==28380== 
==28380== HEAP SUMMARY:
==28380==     in use at exit: 34,136 bytes in 8 blocks
==28380==   total heap usage: 28 allocs, 20 frees, 37,670 bytes allocated
==28380== 
==28380== 16 bytes in 1 blocks are still reachable in loss record 1 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1D5E3B: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x1D5EC6: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x1D6769: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x1D5D9C: alloc::alloc::exchange_malloc (alloc.rs:320)
==28380==    by 0x1DDA77: tracing_log::log_tracer::Builder::init (boxed.rs:195)
==28380==    by 0x198CCC: tracing_subscriber::util::SubscriberInitExt::try_init (util.rs:66)
==28380==    by 0x1B038B: tracing_subscriber::fmt::try_init (mod.rs:1179)
==28380==    by 0x1B0529: tracing_subscriber::fmt::init (mod.rs:1201)
==28380==    by 0x16517C: tracetest::main (main.rs:5)
==28380==    by 0x16589A: core::ops::function::FnOnce::call_once (function.rs:248)
==28380==    by 0x1658DD: std::sys_common::backtrace::__rust_begin_short_backtrace (backtrace.rs:122)
==28380== 
==28380== 32 bytes in 1 blocks are still reachable in loss record 2 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1C918B: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x1C9216: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x1C9A69: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x1CA5DD: alloc::raw_vec::finish_grow (raw_vec.rs:469)
==28380==    by 0x1CAA75: alloc::raw_vec::RawVec<T,A>::grow_amortized (raw_vec.rs:401)
==28380==    by 0x1CAC01: alloc::raw_vec::RawVec<T,A>::reserve_for_push (raw_vec.rs:299)
==28380==    by 0x1C8C19: alloc::vec::Vec<T,A>::push (mod.rs:1731)
==28380==    by 0x1CA14A: alloc::collections::binary_heap::BinaryHeap<T>::push (binary_heap.rs:493)
==28380==    by 0x1C6DEF: thread_local::thread_id::ThreadIdManager::free (thread_id.rs:42)
==28380==    by 0x1C7152: <thread_local::thread_id::ThreadHolder as core::ops::drop::Drop>::drop (thread_id.rs:85)
==28380==    by 0x1CCD4A: core::ptr::drop_in_place<thread_local::thread_id::ThreadHolder> (mod.rs:486)
==28380== 
==28380== 64 bytes in 1 blocks are still reachable in loss record 3 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1EA29B: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x1EA326: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x1EAB59: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x1E516D: alloc::raw_vec::finish_grow (raw_vec.rs:469)
==28380==    by 0x1E5715: alloc::raw_vec::RawVec<T,A>::grow_amortized (raw_vec.rs:401)
==28380==    by 0x1E5C01: alloc::raw_vec::RawVec<T,A>::reserve_for_push (raw_vec.rs:299)
==28380==    by 0x1E7669: alloc::vec::Vec<T,A>::push (mod.rs:1731)
==28380==    by 0x1EB1C1: tracing_core::callsite::register_dispatch (callsite.rs:144)
==28380==    by 0x17F19C: tracing_core::dispatcher::Dispatch::new (dispatcher.rs:417)
==28380==    by 0x182603: <tracing_core::dispatcher::Dispatch as core::convert::From<S>>::from (dispatcher.rs:656)
==28380==    by 0x195103: <T as core::convert::Into<U>>::into (mod.rs:550)
==28380== 
==28380== 64 bytes in 1 blocks are still reachable in loss record 4 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1EA29B: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x1EA326: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x1EAB59: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x1E516D: alloc::raw_vec::finish_grow (raw_vec.rs:469)
==28380==    by 0x1E59C5: alloc::raw_vec::RawVec<T,A>::grow_amortized (raw_vec.rs:401)
==28380==    by 0x1E5BD1: alloc::raw_vec::RawVec<T,A>::reserve_for_push (raw_vec.rs:299)
==28380==    by 0x1E77C3: alloc::vec::Vec<T,A>::push (mod.rs:1731)
==28380==    by 0x1EB0CF: tracing_core::callsite::register (callsite.rs:139)
==28380==    by 0x1E1094: tracing::__macro_support::MacroCallsite::register::{{closure}} (lib.rs:1029)
==28380==    by 0x1E133C: std::sync::once::Once::call_once::{{closure}} (once.rs:276)
==28380==    by 0x206B69: std::sync::once::Once::call_inner (once.rs:434)
==28380== 
==28380== 80 bytes in 2 blocks are still reachable in loss record 5 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1770AB: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x177136: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x178E99: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x1999AD: alloc::raw_vec::RawVec<T,A>::allocate_in (raw_vec.rs:186)
==28380==    by 0x19C08C: alloc::raw_vec::RawVec<T,A>::with_capacity_in (raw_vec.rs:132)
==28380==    by 0x16D953: alloc::vec::Vec<T,A>::with_capacity_in (mod.rs:613)
==28380==    by 0x16C6E6: alloc::vec::Vec<T>::with_capacity (mod.rs:470)
==28380==    by 0x165C7A: <alloc::vec::Vec<T> as alloc::vec::spec_from_iter_nested::SpecFromIterNested<T,I>>::from_iter (spec_from_iter_nested.rs:54)
==28380==    by 0x16F64A: <alloc::vec::Vec<T> as alloc::vec::spec_from_iter::SpecFromIter<T,I>>::from_iter (spec_from_iter.rs:33)
==28380==    by 0x16ED36: <alloc::vec::Vec<T> as core::iter::traits::collect::FromIterator<T>>::from_iter (mod.rs:2554)
==28380==    by 0x173CAA: core::iter::traits::iterator::Iterator::collect (iterator.rs:1784)
==28380== 
==28380== 1,112 bytes in 1 blocks are still reachable in loss record 6 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1770AB: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x177136: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x178E99: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x17700C: alloc::alloc::exchange_malloc (alloc.rs:320)
==28380==    by 0x1B120A: alloc::sync::Arc<T>::new (sync.rs:346)
==28380==    by 0x17F173: tracing_core::dispatcher::Dispatch::new (dispatcher.rs:415)
==28380==    by 0x182603: <tracing_core::dispatcher::Dispatch as core::convert::From<S>>::from (dispatcher.rs:656)
==28380==    by 0x195103: <T as core::convert::Into<U>>::into (mod.rs:550)
==28380==    by 0x198A31: tracing_subscriber::util::SubscriberInitExt::try_init (util.rs:59)
==28380==    by 0x1B038B: tracing_subscriber::fmt::try_init (mod.rs:1179)
==28380==    by 0x1B0529: tracing_subscriber::fmt::init (mod.rs:1201)
==28380== 
==28380== 32,768 bytes in 1 blocks are still reachable in loss record 7 of 7
==28380==    at 0x4845899: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28380==    by 0x1770AB: alloc::alloc::alloc (alloc.rs:89)
==28380==    by 0x177136: alloc::alloc::Global::alloc_impl (alloc.rs:171)
==28380==    by 0x178E99: <alloc::alloc::Global as core::alloc::Allocator>::allocate (alloc.rs:231)
==28380==    by 0x19938D: alloc::raw_vec::RawVec<T,A>::allocate_in (raw_vec.rs:186)
==28380==    by 0x19C0CC: alloc::raw_vec::RawVec<T,A>::with_capacity_in (raw_vec.rs:132)
==28380==    by 0x16D8F3: alloc::vec::Vec<T,A>::with_capacity_in (mod.rs:613)
==28380==    by 0x16C6B6: alloc::vec::Vec<T>::with_capacity (mod.rs:470)
==28380==    by 0x166060: sharded_slab::shard::Array<T,C>::new (shard.rs:273)
==28380==    by 0x19E2ED: sharded_slab::pool::Pool<T>::new_with_config (pool.rs:394)
==28380==    by 0x19E32D: sharded_slab::pool::Pool<T>::new (pool.rs:387)
==28380==    by 0x17929B: <tracing_subscriber::registry::sharded::Registry as core::default::Default>::default (sharded.rs:138)
==28380== 
==28380== LEAK SUMMARY:
==28380==    definitely lost: 0 bytes in 0 blocks
==28380==    indirectly lost: 0 bytes in 0 blocks
==28380==      possibly lost: 0 bytes in 0 blocks
==28380==    still reachable: 34,136 bytes in 8 blocks
==28380==         suppressed: 0 bytes in 0 blocks
==28380== 
==28380== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

[hawkw]

The default tracing subscriber is stored in a static. Creating a new fmt subscriber allocates some memory on the heap, and then stores the Subscriber in that static. In Rust, destructors are not run for static values, even when the program exits. Thus, Valgrind will report any held by a static as a "leak". However, the size of the heap allocation should be bounded rather than growing endlessly over the program's lifetime, so it shouldn't result in an issue in practice.

[clubby789]

I see, thank you for explaining