boost log -- 使用心得和碰到的那些坑（一）

最近研究了一下boost::log这个库，记录一下心路历程
我的需求是log功能尽可能的不消耗程序时间，打印到stdout， log需要提供如下信息：时间，线程ID，进程名字，日志等级，文件及行号
我的测试环境 boost 1.67 gcc version 7.3.0 (Ubuntu 7.3.0-16ubuntu3)

定义

此处一些术语的定义，这些定义在此文档中会被广泛应用

日志记录 Log record

从用户的应用程序中收集的一个信息簇，是被输出到日志的候选信息。在简单的情况下，一个日志记录经过日志程序库处理之后表示为日志文件中的一行文本。

属性 attribute

一个属性是一条元数据，用于表示一个日志记录。在Boost.Log中，用一些有具体接口的函数对象来表示属性，在调用的时候返回真实的属性值。

属性值

属性值是从属性中获取的真实数据。这些数据依附于一条特定的日志记录，程序库会进行处理这些属性值。属性值有可能有不同的类型（整型，字符串类型或者更加复杂的类型，包括用户自定义类型）。一些属性值的示例包括：当前时间戳、文件名、行号、当前范围名称等等。属性值包装在一个包装器中，其真实类型在接口中是不可见的。值的真实类型有时被称作存储类型。

(属性)值访问

一种处理属性值的方式。这种方法调用一个应用于属性值的函数对象(访问者）。为了处理此属性值，这个访问者需要知道属性值的存储类型。

(属性)值提取

当调用者试图得到一个存储值的引用时，处理属性值的方式。为了提取属性值，调用者应当知道属性值的存储类型。

Log sink

将所有的用户应用程序收集到的日志记录输出到的目标。sink定义了这些日志记录被怎么处理以及被存储到哪儿。

日志源Log source

用户应用程序的日志记录的输入点。在一个简单的示例中，一个日志对象保持一套属性，用户根据需要将这些属性组成一个日志记录。当然，用户可以创建一个source，从其他的事件中获取信息，并产生日志记录。例如，通过截流和解析其他应用程序的显示器输出。

日志过滤器Log filter

用于判断一个日志记录是否应该通过或者被丢弃。日志过滤器通常需要根据日志的属性值类决策是否需要通过或丢弃。

日志格式化工具Log formatter

一个生成日志记录最终文本输出格式函数对象。一些sink，例如二进制日志sink也许不需要它。但是大部分基于文本的sink会需要一个格式化工具来组合它的输出。

日志核心Logging core

一个全局实体，保持了源和sink之间的连接，同时对记录提供过滤器。主要在日志程序库初始化的时候使用。

国际化 i18n

国际化，操纵宽字节的能力。

线程本地存储 TLS

线程本地存储，对于不同的线程访问一个变量时，其值是相互独立的。

实时类型信息RTTI

实时类型信息。这个是一个C++支持的数据结构。需要通过dynamic_cast和typeid来正常工作。

实现

！！！一定要仔细阅读官方文档！！！一定要搞清楚头文件

Boost.Log设计得非常模块化而且易于扩展。同时支持窄字节和宽字节日志。宽字节和窄字节日志提供相似的功能，因此在此文档大部分的情况下，仅仅介绍窄字节的接口。本程序库包括三个主要的层：

数据收集层
数据处理层
中央枢纽层，将上面两层连接起来。

整体设计如下图所示

箭头表示了日志信息流的方向。从用户的应用程序端，到最终的存储端。存储是可选的，因为有的时候日志处理结果可能包含一些动作并没有真正存储这些信息。例如，如果你的应用程序处于临界状态，它可能产生特殊的日志记录。这些日志通过处理，通过系统通知抖动以及声音来提醒用户。此程序库一个非常重要的特性是，收集、处理以及日志数据有哪些信息都是相互独立的。这样将允许使用此程序库不仅仅用于传统的日志。还包括指示重要的事件给应用程序用户，以及积累统计数据。

日志源

回到这张图。在左侧，应用程序输出日志记录。通过一些logger对象，提供流来格式化信息，这些信息最终被传输的日志中。本程序库提供了一些不同的logger类型，同时你也可以精心设计其他的logger类型，来扩展现有类型。logger被设计成一些不同特征的组合。你可以开发自己的特征，然后将其添加到池子中。你可以像使用函数式编程一样使用结构化的logger。通常这样比使用一个全局的logger更加方便。

总体来说，此程序库不需要logger来写日志。通用术语“日志源”指向一个实体，这个实体通过创建一个日志记录来启动日志过程。其他的日志源可能抓取子程序的屏幕输出或者从网络上获取的数据。然而logger是最通用的日志源。

属性和属性值

为了启动日志，一个日志源必须将所有与此日志记录有关的数据传输到日志核心logging core。这些数据，更准确来说，是这些数据的获取方式是通过一些属性来描述的。总的来说，每一个属性是一个函数，函数的结果是“属性值”，这些数据在未来阶段会被真正处理。举一个例子，返回当前时间就可以作为一个属性。其返回结果就是确切的当前时间。

有三种属性类型

全局属性
线程相关属性
源相关属性

你可以从这张图中看到，全局属性和线程相关属性，通过logging core来保持，因此不需要在初始化时通过日志源来传输。全局属性会依附于所有的日志记录。很显然，线程相关属性是线程产生的，依附在当前线程的日志记录上。源相关的属性，是在启动日志过程时，由源产生的，这些属性值依附于特定源产生的日志记录。

当一个源启动日志过程，从以上三个属性集合中获取属性值。然后，将这些属性值组成一个属性集合，在后续进行处理。你可以往属性集合中增加更多的属性值，新增的属性值只依附于特定的日志记录。并且于日志源和日志核心没有关联。在不同的属性结合中可能会出现同名的属性，这些冲突的优先级处理准则是：全局属性有最低的优先级，源相关的属性有最高的优先级。当出现冲突的时候，低优先级属性将被丢弃。

日志核心和过滤

当组合属性值集合之后，日志核心判断这条日志记录是否继续被sink处理。这就被称为过滤。其中包含两层过滤器：
全局过滤器 首先在日志核心中实施全局过滤器，允许快速擦去不需要的日志记录。

sink相关的过滤器 其次实施sink过滤器，sink过滤器允许日志记录到特定的sink。需要注意的是，日志记录是通过哪个源产生的并不重要，过滤器仅仅通过依附于日志记录上属性值集合来进行过滤。

需要提到的是，对于一个指定的日志记录，过滤仅仅实施一次。显然，只有在过滤之前产生的属性可以参与过滤。一些属性值，比如日志记录的message信息，一般在过滤之后才依附到日志记录中。这些属性值在过滤时是不会被用到的，你只能在sink和格式化是使用。
sink和格式化

如果一个日志记录通过了过滤，至少一个sink是可以处理此日志记录的。如果此sink支持结构化输出，在当前点会发生结构化的操作。结构化之后的信息以及属性值组合被传输到接收此日志记录的sink。需要注意的是结构化是发生在pre-sink阶段，因此每个sink可以将日志记录按照特定格式输出。

sink包含两部分，前端和后端。之所以如此区分，是为了提取sink的通用功能。比如过滤、格式化以及线程同步到独立的实体（前端）中。本程序库提供sink前端，用户基本上不用重新实现他们。后端，则相反，是程序库中最可能进行扩展的地方。sink后端是真正进行处理日志记录的地方。可能有一个sink将一条日志记录存储到文件中，有一个sink将日志记录通过网络发送到远端处理节点，也可能有sink，像之前提到的，将记录信息发送到桌面通知。大部分通用的sink在程序库中已经提供。

除了一些上述的基础设施，本程序库还提供各种各样的辅助工具，例如属性、格式化工具以及过滤器，表现为lambda表达式。甚至一些程序库初始化基本帮助。你会在详细特征描述小节学习到这些知识。不过对于初学者来说，推荐从教程小节开始学习。

【参考 http://www.wanguanglu.com/2016/07/28/boost-log-document/ 】

实现需求

减少对程序运行的影响

从之前的描述中可以知道 logging core 在获取日志并判断日志是否需要记录后会将日志信息传递给sink，sink 分为同步和异步两种。
官方网站对同步模式的描述：
The synchronous_sink class template above indicates that the sink is synchronous, that is, it allows for several threads to log simultaneously and will block in case of contention. This means that the backend text_ostream_backend doesn't have to worry about multithreading at all.
也就是说多个thread同时写log会有一定几率被阻塞， 但是好处是不用考虑多线程问题。

为了减少对程序运行的影响， 选择异步sink来实现log功能。
由于需要打印到stdout上，选择text_ostream_backend。

还有一个问题， async sink是将log 信息写到一个队列中，默认无限制，这里我们选择了bounded_fifo_queue，如果满了则丢弃drop_on_overflow。所以sink是这样的：
typedef sinks::asynchronous_sink<sinks::text_ostream_backend, sinks::bounded_fifo_queue<1000, sinks::drop_on_overflow>> sink_t;

增加日志信息

从官方网站中可知， 如果调用 add_common_attributes() 就会为日志添加一些默认的信息如time，thread id，process id等等，在实践中发现一些情况下，有一些选项仍然需要手动添加，既然可以手动添加，多一些设置没有什么坏处，这里全局添加thread id，process name：
core->add_global_attribute("ThreadID", attrs::current_thread_id());

core->add_global_attribute("Process", attrs::current_process_name());

添加格式信息：

  sink->set_formatter(
        expr::stream
        << "["
        << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%Y-%m-%d %H:%M:%S.%f") << "]["
        << expr::attr<attrs::current_thread_id::value_type>("ThreadID") << ":"
        << expr::attr<unsigned int>("LineID") << "]["
        << expr::attr<std::string>("Process")
        << "][" << expr::attr<severity_level>("Severity")
        << "] "
        << ":" << expr::smessage);

添加backend

为了实现线程安全的添加backend，应用到了sink提供的锁机制：

    {
        sink_t::locked_backend_ptr p = sink->locked_backend();
        p->add_stream(boost::shared_ptr<std::ostream>(&std::clog, boost::null_deleter()));
    }

stop sink

利用官网提供的例子：

    boost::shared_ptr<logging::core> core = logging::core::get();
    // Remove the sink from the core, so that no records are passed to it
    core->remove_sink(sink);
    // Break the feeding loop
    sink->stop();
    // Flush all log records that may have left buffered
    sink->flush();

    sink.reset();

logger

至此， 我们已经组装好log core， sink，现在就差一个logger了，boost提供了不同种类的logger，包括普通的，带日志等级的，带日志等级并且带通道信息的…
这里我们选择severity_channel_logger_mt 注意这里后缀有个mt代表是multithread版本。

现在万事俱备， 下面是具体代码：

#include <string>
#include <fstream>
#include <iostream>
#include <boost/smart_ptr/shared_ptr.hpp>
#include <boost/core/null_deleter.hpp>
#include <boost/log/core.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/sinks/async_frontend.hpp>
#include <boost/log/sinks/text_ostream_backend.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#include <boost/log/sources/record_ostream.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/attributes/current_thread_id.hpp>
#include <boost/log/attributes/current_process_name.hpp>
#include <boost/log/attributes/attribute.hpp>
#include <boost/log/attributes/attribute_cast.hpp>
#include <boost/log/attributes/attribute_value.hpp>
#include <boost/log/sinks/async_frontend.hpp>

// Related headers
#include <boost/log/sinks/unbounded_fifo_queue.hpp>
#include <boost/log/sinks/unbounded_ordering_queue.hpp>
#include <boost/log/sinks/bounded_fifo_queue.hpp>
#include <boost/log/sinks/bounded_ordering_queue.hpp>
#include <boost/log/sinks/drop_on_overflow.hpp>
#include <boost/log/sinks/block_on_overflow.hpp>

#include <thread>
#include <chrono>

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

enum severity_level
{
    normal,
    notification,
    warning,
    error,
    critical
};
std::ostream &operator<<(std::ostream &strm, severity_level level)
{
    static const char *strings[] =
        {
            "normal",
            "notification",
            "warning",
            "error",
            "critical"};

    if (static_cast<std::size_t>(level) < sizeof(strings) / sizeof(*strings))
        strm << strings[level];
    else
        strm << static_cast<int>(level);

    return strm;
}

typedef sinks::asynchronous_sink<sinks::text_ostream_backend, sinks::bounded_fifo_queue<1000, sinks::drop_on_overflow>> sink_t;

boost::shared_ptr<sink_t> init_logging()
{
    logging::add_common_attributes();
    boost::shared_ptr<logging::core> core = logging::core::get();
    boost::shared_ptr<sinks::text_ostream_backend> backend = boost::make_shared<sinks::text_ostream_backend>();
    boost::shared_ptr<sink_t> sink(new sink_t(backend));
    core->add_sink(sink);
    core->add_global_attribute("ThreadID", attrs::current_thread_id());
    core->add_global_attribute("Process", attrs::current_process_name());
    sink->set_filter(expr::attr<severity_level>("Severity") >= warning);
    sink->set_formatter(
        expr::stream
        << "["
        << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%Y-%m-%d %H:%M:%S.%f") << "]["
        << expr::attr<attrs::current_thread_id::value_type>("ThreadID") << ":"
        << expr::attr<unsigned int>("LineID") << "]["
        << expr::attr<std::string>("Process")
        << "][" << expr::attr<severity_level>("Severity")
        << "] "
        << ":" << expr::smessage);
    {
        sink_t::locked_backend_ptr p = sink->locked_backend();
        p->add_stream(boost::shared_ptr<std::ostream>(&std::clog, boost::null_deleter()));
    }
    return sink;
}

void stop_logging(boost::shared_ptr<sink_t> &sink)
{
    boost::shared_ptr<logging::core> core = logging::core::get();
    // Remove the sink from the core, so that no records are passed to it
    core->remove_sink(sink);
    // Break the feeding loop
    sink->stop();
    // Flush all log records that may have left buffered
    sink->flush();

    sink.reset();
}
int main(int, char *[])
{
    boost::shared_ptr<sink_t> sink = init_logging();

    src::severity_channel_logger_mt<severity_level> lg(keywords::channel = "net");
    std::thread th1([&]() {
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, error) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        std::this_thread::sleep_for(std::chrono::milliseconds(1));
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
        BOOST_LOG_SEV(lg, warning) << "Hello world!";
    });
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    std::this_thread::sleep_for(std::chrono::milliseconds(1));
    BOOST_LOG_SEV(lg, error) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    BOOST_LOG_SEV(lg, warning) << "Hello world!";
    std::this_thread::sleep_for(std::chrono::milliseconds(1));
    BOOST_LOG_SEV(lg, warning) << "Hello world!";

    th1.join();
    stop_logging(sink);

    return 0;
}

注意，这里编译选项让我找了半天，写在这里以防别人再走弯路
g++ -std=c++11 -DBOOST_LOG_DYN_LINK log.cpp -lboost_log -lpthread -lboost_log_setup -lboost_thread -lboost_system

后续

这篇文章只是实现了基本的log功能， 我会在下一篇文章实现一套API可以应用于工程上