Boost Logging displays linux thread ids as all 0s

Question

I am trying to send log strings to a file in the latest version of boost 1.57 and for some reason on linux, the thread IDs are always set to 0's. I have a feeling that it may have something to do with using native threads instead of boost threads - but that doesn't explain why it works in the windows environment. Any help would be appreciated.

Here is my initialization code in logger.cpp file.

EDIT: shown below I have also included my Logger.h which show the type of logger I use - effectively using the BOOST_LOG_CHANNEL_SEV macro to log to a

boost::log::sources::severity_channel_logger_mt< boost::log::trivial::severity_level >

#include <boost/log/core.hpp>
#include <boost/log/sinks/sync_frontend.hpp>
#include <boost/log/sinks/text_ostream_backend.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/attributes/scoped_attribute.hpp>
#include <boost/log/expressions/formatters/date_time.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/manipulators/add_value.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>

. . .

namespace fs = boost::filesystem;
namespace logging = boost::log;
namespace src = boost::log::sources;
namespace expr = boost::log::expressions;
namespace sinks = boost::log::sinks;
namespace attrs = boost::log::attributes;
namespace keywords = boost::log::keywords;
namespace trivial = boost::log::trivial;
void
Logger::init(
    const fs::path& rErrEvtPath,
    const fs::path& rStatusPath)
{
    // register common attributes - ThreadID, LineID, TimeStamp etc.
    logging::add_common_attributes();

    // Construct the sink for the "event_log" channel
    typedef sinks::synchronous_sink<
        sinks::text_ostream_backend> text_sink;
    auto sink = boost::make_shared<text_sink>();
    sink->locked_backend()->auto_flush(true);
    sink->locked_backend()->add_stream(
        boost::make_shared<std::ofstream>(rErrEvtPath.c_str()));
    sink->set_formatter(
        expr::format("%1% [%2%] tid[%3%] %4%")
        % expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f")
        % logging::trivial::severity
        % expr::attr<attrs::current_thread_id::value_type>("ThreadID")
        % expr::smessage);
    sink->set_filter(expr::attr<std::string>("Channel") == "event");
    logging::core::get()->add_sink(sink);

    // Construct the sink for the "status_log" channel
    sink = boost::make_shared<text_sink>();
    sink->locked_backend()->auto_flush(true);
    sink->locked_backend()->add_stream(
        boost::make_shared<std::ofstream>(rStatusPath.c_str()));
    sink->set_formatter(
        expr::format("%1% [%2%] tid[%3%] %4%")
        % expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f")
        % logging::trivial::severity
        % expr::attr<attrs::current_thread_id::value_type>("ThreadID")
        % expr::smessage);
    sink->set_filter(expr::attr<std::string>("Channel") == "status");
    logging::core::get()->add_sink(sink);
}

Logs on windows display just fine i.e.

15:42:35.205747 [info] tid[0x00000e14] module[NIC:192.168.1.1] SETCNTX IP_ADDR 192.168.1.1
15:42:35.207747 [info] tid[0x00000e14] module[NIC:192.168.1.1] SETCNTX RESP_ON
15:42:35.209747 [info] tid[0x00000e14] module[NIC:192.168.1.1] SETCNTX SET_FTP_TIMEOUT 10
15:42:35.212747 [info] tid[0x00000e14] module[NIC:192.168.1.1] FTPNOPROMPT [192.168.1.1] [timeout 10(s)]
15:42:35.552781 [info] tid[0x00000e14] module[NIC:192.168.1.1] SETCNTX RESP_OFF
15:42:35.553781 [info] tid[0x00000e14] module[NIC:192.168.1.1] FTPQUOTE "site attrib 0 DEOS"

however on linux (ppc) using the same version of boost 1.57.0 the logs are as follows:

13:43:45.092206 [info] tid[0000000000] module[N/A] MLFCommand - command group(5) - end
13:43:45.092568 [info] tid[0000000000] module[N/A] SETCNTX IP_ADDR 192.168.1.23
13:43:45.097037 [info] tid[0000000000] module[N/A] SETCNTX RESP_ON
13:43:45.098691 [info] tid[0000000000] module[N/A] SETCNTX SET_FTP_TIMEOUT 10
13:43:45.100474 [info] tid[0000000000] module[N/A] FTPNOPROMPT [192.168.1.23] [timeout 10(s)]
13:43:49.191856 [warning] tid[0000000000] module[N/A] [>TIMEOUT<]

EDIT: for completeness - I include logger.h

#ifndef _logger_h_
#define _logger_h_

// SYSTEM INCLUDES
#include <mutex>
#include <string>
#include <memory>
#include <boost/filesystem.hpp>
#if !defined(__GNUC__)
#pragma warning(push)
#pragma warning(disable: 4714 4100 4510 4503 4512 4610)
#endif
#include <boost/log/trivial.hpp>
#include <boost/log/sources/record_ostream.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#if !defined(__GNUC__)
#pragma warning(pop)
#endif

// APPLICATION INCLUDES
// DEFINES
#define LOG(logger, lvl) BOOST_LOG_CHANNEL_SEV(logger, "event", lvl)
#define LOG_TRACE(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::trace)
#define LOG_DEBUG(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::debug)
#define LOG_INFO(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::info)
#define LOG_WARNING(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::warning)
#define LOG_ERROR(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::error)
#define LOG_FATAL(logger) BOOST_LOG_CHANNEL_SEV(logger, "event", trivial::fatal)

// MACROS
// EXTERNAL FUNCTIONS
extern bool gVerboseMode;

// EXTERNAL VARIABLES
// CONSTANTS
// STRUCTS
// TYPEDEFS
// FORWARD DECLARATIONS

class Logger
{
public:
    using SEVChannelLoggerMT = boost::log::sources::severity_channel_logger_mt<
        boost::log::trivial::severity_level>;
    /**
     * singleton pattern implementation
     *
     * @return singleton instance
     */
    static Logger* getInstance();

    // destructor
    virtual ~Logger() = default;

    /** define a log filter associated with a channel attribute */
    enum class LogDest {
        EventLog, StatusLog
    };

    /**
     * log the message to a specified log<p>
     *
     * @param logDest  [in] filter used to route the log message to
     *                 the correct logging sink.
     * @param rMessage [in] message to log
     */
    void logMessage(
       const LogDest logDest,
       const boost::log::trivial::severity_level& severity,
       const std::string& rMessage);

    /**
     * Returns logger associated with the specified log destination.<p>
     *
     * @param logDest  [in] filter used to route the log message to
     *                 the correct logging sink.
     * @return logger of the appropriate type
     */
    SEVChannelLoggerMT& getLoggerRef(const LogDest logDest);

    /**
     * Custom reusable formatter which we can attach to all sinks
     * for a uniform formatting of log messages
     *
     * @param rec    [in] record contain the log details
     * @param strm   [in,out] logging stream
     */
    static void customFormatter(
        boost::log::record_view const& rec,
        boost::log::formatting_ostream& strm);

    /**
     * Initialize the logging framework.<p>
     * Initializes the Boost logging framework by setting up the
     * following log files<p>.
     * Under the covers the Boost Logging framework initializes two
     * distinct log files.
     * <ul>
     *     <li>Error/Event log - this contains everything</li>
     *     <li>rStatusPath - high level log file which is also
     *     displayed on the iPad</li>
     * </ul>
     *
     * @param rErrEvtPath
     *               [in] fully qualified path to
     *               DlfLogBuffer[num].txt log file.  This log
     *               file will be created as necessary or
     *               reinitialized to empty (truncated) if it
     *               already exists.
     * @param rStatusPath
     *               [in] fully qualified path to
     *               DlfStatusBuffer[num].txt log file.  This log
     *               file will be created as necessary or
     *               reinitialized to empty (truncated) if it
     *               already exists.
     */
    static void init(
        const boost::filesystem::path& rErrEvtPath,
        const boost::filesystem::path& rStatusPath);
private:
    // severity channel loggers - one for the error event log
    SEVChannelLoggerMT m_event_logger, m_status_logger;

    /**
     * Constructor - initialize each channel logger with a named
     * channel attribute which will be used by filtering to route
     * logging records to the appropriate sink.
     */
    Logger();
    // singleton and locking support
    static std::mutex gMutexGuard;
    static Logger* gpInstance;
};

#endif // _logger_h_

Answer 1

You may want to report this upstream (or debug it manually).

Update The issue has been reported to the Boost Log devs and they have fixed it (thanks @johnco3)

Here's the same on Debian:

Live On Coliru (Debian)

#define BOOST_LOG_DYN_LINK 1

#include <boost/filesystem.hpp>
#include <boost/log/attributes/scoped_attribute.hpp>
#include <boost/log/core.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/expressions/formatters/date_time.hpp>
#include <boost/log/sinks/sync_frontend.hpp>
#include <boost/log/sinks/text_ostream_backend.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#include <boost/log/sources/channel_logger.hpp>
#include <boost/log/sources/global_logger_storage.hpp>
#include <boost/log/keywords/channel.hpp>
#include <boost/log/keywords/severity.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/utility/manipulators/add_value.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <fstream>

#include <boost/log/sources/logger.hpp>
#include <boost/log/sources/record_ostream.hpp>
#include <boost/log/sources/global_logger_storage.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>

namespace fs       = boost::filesystem;
namespace logging  = boost::log;
namespace src      = boost::log::sources;
namespace expr     = boost::log::expressions;
namespace sinks    = boost::log::sinks;
namespace attrs    = boost::log::attributes;
namespace keywords = boost::log::keywords;
namespace trivial  = boost::log::trivial;

struct Logger {
    void init(const fs::path &rErrEvtPath, const fs::path &rStatusPath) {
        // register common attributes - ThreadID, LineID, TimeStamp etc.
        logging::add_common_attributes();

        // Construct the sink for the "event_log" channel
        typedef sinks::synchronous_sink<sinks::text_ostream_backend> text_sink;
        auto sink = boost::make_shared<text_sink>();
        sink->locked_backend()->auto_flush(true);
        sink->locked_backend()->add_stream(boost::make_shared<std::ofstream>(rErrEvtPath.c_str()));
        sink->set_formatter(expr::format("%1% [%2%] tid[%3%] %4%") %
                            expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f") %
                            logging::trivial::severity % expr::attr<attrs::current_thread_id::value_type>("ThreadID") %
                            expr::smessage);
        sink->set_filter(expr::attr<std::string>("Channel") == "event");
        logging::core::get()->add_sink(sink);

        // Construct the sink for the "status_log" channel
        sink = boost::make_shared<text_sink>();
        sink->locked_backend()->auto_flush(true);
        sink->locked_backend()->add_stream(boost::make_shared<std::ofstream>(rStatusPath.c_str()));
        sink->set_formatter(expr::format("%1% [%2%] tid[%3%] %4%") %
                            expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f") %
                            logging::trivial::severity % expr::attr<attrs::current_thread_id::value_type>("ThreadID") %
                            expr::smessage);
        sink->set_filter(expr::attr<std::string>("Channel") == "status");
        logging::core::get()->add_sink(sink);
    }
};

BOOST_LOG_INLINE_GLOBAL_LOGGER_CTOR_ARGS(statuc_lg,
        src::severity_channel_logger_mt< >, (keywords::severity = trivial::error)(keywords::channel = "status"))
BOOST_LOG_INLINE_GLOBAL_LOGGER_CTOR_ARGS(event_lg,
        src::severity_channel_logger_mt< >, (keywords::severity = trivial::error)(keywords::channel = "event"))

#include <boost/thread.hpp>

int main()
{
    Logger l;
    l.init("test.1", "test.2");

    boost::thread_group tg;
    tg.create_thread([]{
            BOOST_LOG(statuc_lg::get()) << "this is a status update";
            BOOST_LOG(event_lg::get()) << "this is an event"; });
    tg.create_thread([]{
            BOOST_LOG(statuc_lg::get()) << "this is a status update";
            BOOST_LOG(event_lg::get()) << "this is an event"; });

    tg.join_all();
}

Results:

==> test.1 <==
23:55:58.635779 [] tid[0x00007f26d9a65700] this is an event
23:55:58.635832 [] tid[0x00007f26d9264700] this is an event

==> test.2 <==
23:55:58.635367 [] tid[0x00007f26d9a65700] this is a status update
23:55:58.635540 [] tid[0x00007f26d9264700] this is a status update