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

阿新 • • 發佈：2018-12-16

最近研究了一下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設計得非常模組化而且易於擴充套件。同時支援窄位元組和寬位元組日誌。寬位元組和窄位元組日誌提供相似的功能，因此在此文件大部分的情況下，僅僅介紹窄位元組的介面。本程式庫包括三個主要的層：

資料收集層
資料處理層
中央樞紐層，將上面兩層連線起來。

整體設計如下圖所示

arc

箭頭表示了日誌資訊流的方向。從使用者的應用程式端，到最終的儲存端。儲存是可選的，因為有的時候日誌處理結果可能包含一些動作並沒有真正儲存這些資訊。例如，如果你的應用程式處於臨界狀態，它可能產生特殊的日誌記錄。這些日誌通過處理，通過系統通知抖動以及聲音來提醒使用者。此程式庫一個非常重要的特性是，收集、處理以及日誌資料有哪些資訊都是相互獨立的。這樣將允許使用此程式庫不僅僅用於傳統的日誌。還包括指示重要的事件給應用程式使用者，以及積累統計資料。

日誌源

回到這張圖。在左側，應用程式輸出日誌記錄。通過一些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表示式。甚至一些程式庫初始化基本幫助。你會在詳細特徵描述小節學習到這些知識。不過對於初學者來說，推薦從教程小節開始學習。

實現需求

減少對程式執行的影響

從之前的描述中可以知道 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可以應用於工程上