Avoid leak in Boost Log trivial usage

Question

I am getting valgrind leak reports from a server side application that use boostlog that is distributed with boost 1.56. the valgrind report is :

==8021== 37,088 bytes in 1,159 blocks are definitely lost in loss record 1,613 of 1,642

==8021== at 0x4A05588: memalign (vg_replace_malloc.c:727)

==8021== by 0x3FDA61118F: tls_get_addr_tail (in /lib64/ld-2.12.so)

==8021== by 0x3FDA61165F: __tls_get_addr (in /lib64/ld-2.12.so)

==8021== by 0x3FE6ABBDCB: __cxa_get_globals (in /usr/lib64/libstdc++.so.6.0.13)

==8021== by 0x730C528: boost::log::v2_mt_posix::aux::unhandled_exception_count() (in /opt/sesteksdk/lib/libboost_log.so.1.56.0)

==8021== by 0x5D54D1F: sestek::mrcp::audio::recognition::AsynchronousRecognizer::Notify(sestek::voice::recognition::IRecognizerNotification const*) (record_ostream.hpp:259)

this leak is coming from a line as simple as :
LOGGER(debug)<< _chanProp->GetId() << " got recognition ended notification from recognizer";

We get 5 of these leaks just from a single, short lived test run.

we use text file backend, with syncronous sink, auto flush is on. Basically:

void InitializeFileLog(const std::string & logDir)
    {   
        boost::shared_ptr< logging::core > loggingCore = logging::core::get();


        loggingCore->add_global_attribute("TimeStamp", attrs::local_clock());

        string logPath = logDir + "/gvzmrcpsr_%N.txt";

        boost::shared_ptr< sinks::text_file_backend > backend =
            boost::make_shared< sinks::text_file_backend >(
                // file name pattern
                keywords::file_name = logPath,
                // rotate the file upon reaching 5 MiB size...
                keywords::rotation_size = 5 * 1024 * 1024,
                // ...or at midnight, whichever comes first
                keywords::time_based_rotation = sinks::file::rotation_at_time_point(0, 0, 0)                    
            );

        backend->auto_flush(true);

        // Wrap it into the frontend and register in the core.
        // The backend requires synchronization in the frontend.
        typedef sinks::synchronous_sink< sinks::text_file_backend > sink_t;
        boost::shared_ptr< sink_t > sink = boost::make_shared< sink_t>(backend);

        loggingCore->add_sink(sink);


        sink->flush();
        sink->set_formatter
            (
            expr::stream
            << expr::attr< boost::posix_time::ptime >("TimeStamp")
            << " : [" << expr::attr< sestek::log::LogLevel >("Severity")
            << "] " << expr::smessage
            );

        backend->set_file_collector(sinks::file::make_collector(
            // rotated logs will be moved here
            keywords::target = logDir + "/old_mrcpsr_plugin_logs",
            // oldest log files will be removed if the total size reaches 100 MiB...
            keywords::max_size = 100 * 1024 * 1024,
            // ...or the free space in the target directory comes down to 50 MiB
            keywords::min_free_space = 50 * 1024 * 1024
        ));

        try
        {
            backend->scan_for_files(sinks::file::scan_all);
        }
        catch(std::exception & )
        {
            //LOGGER(sestek::log::fatal) << "exception during scanning : " << e.what();

        }

    }

The system is compiled and run on centos 6.6 using devtoolkit2.0. gcc version is 4.8.2.

So is there a problem in our usage of boost log? Or does boost log really have such problem(s). I think our usage can be considered as a trivial one, we just run the configuration code above during start-up.

Note: Even though a single leak size may be small enough, our software is run as a service on a server, so this kind of repetitive leak is problematic for us.

Answer 1

Boost Log - like many other logging libraries - uses tls internally. It is hard(and it seems sometimes impossible) for a logging system to clean up tls variables when a thread terminates. Boost faces the same difficulties.

For a long running application that contains logging code, detaching many threads and terminating them when their task is done is not a good use. A better approach in a heavily multitasking system is to use a thread-pool instead of kicking off new threads each and every time.

I converted the application to use a thread pool and the leaks in the question have disappeared. Tls variables are still there but since now threads are reused tls variables too are reused by their corresponding threads.

Answer 2

I don't really get the question. You show evidence of a leak, and ask "does it leak". Well yes. This is hardly surprising. The loggers use thread local "singletons". Depending on how you organized your threads, it will be possible/nigh impossible to properly tear those down.

Time to make a SSCCE and hit the documentation on proper shutdown sequences.

Note

Shutdown of loggers is notoriously hard. You need to deal with the off chance that something needs to log during shutdown (a design smell); Worse, different sinks could depend on each other and prevent shutdown in any particular order).

Quite a few frameworks just leave it to the OS to cleanup.

PS Nothing indicates a repetitive leak, as it looks like a leak per-thread.

Answer 3

The leaked object is an internal part of the C++ runtime, which is not explicitly created by Boost.Log. From what I can see, this object is created per-thread and as such should be destroyed when the thread terminates. Your usage of Boost.Log seems fine to me.