add logging, use boost.log.

lichao

2021-05-06 0117d5f8ff386075b0c4cbec0cbe460fe3cfa680

add logging, use boost.log.

 .vscode/settings.json

@@ -77,7 +77,9 @@
    "cmake.configureOnOpen": false,
    "C_Cpp.default.includePath": [
        "build/proto",
        "log",
        "src",
        "box"
    ]
    ],
    "terminal.integrated.cwd": "utest"
}

 box/CMakeLists.txt

@@ -6,6 +6,7 @@
set(BinTarget ${Target}-bin)

include_directories(../src)
include_directories(../log)
add_library(${Target} ${lib_sources})
add_executable(${BinTarget} ${exe_sources})


 box/box.cc

@@ -76,13 +76,24 @@
}

const std::string kOrigName("bhshmqbox");

inline void PrintLn() { putchar('\n'); }

template <class... Params>
void PrintLn(const char *fmt, Params &&...t)
{
    printf(fmt, std::forward<decltype(t)>(t)...);
    PrintLn();
}

void Help()
{
    printf("%s : bhome shared memory message queue box application.\n", kOrigName.c_str());
    printf("usage:\n");
    printf("\t1) %s [function [options]...]\n", kOrigName.c_str());
    printf("\t2) rename or link %s to a function name then run it directly.\n", kOrigName.c_str());
    printf("\nsupported functions:\n");
    PrintLn("%s : bhome shared memory message queue box application.", kOrigName.c_str());
    PrintLn("usage:");
    PrintLn("\t1) %s [function [options]...]", kOrigName.c_str());
    PrintLn("\t2) rename or link %s to a function name then run it directly.", kOrigName.c_str());
    PrintLn();
    PrintLn("supported functions:");
    std::map<std::string, std::string> funcs;
    auto getInfo = [&](const std::string &name, const std::string &desc) {
        funcs[name] = desc;
@@ -92,9 +103,10 @@
    int max_len = std::max_element(funcs.begin(), funcs.end(), cmp_name_len)->first.size();
    for (auto &kv : funcs) {
        int npad = max_len - kv.first.size();
        printf("\n\t%s%s : %s\n", kv.first.c_str(), std::string(npad, ' ').c_str(), kv.second.c_str());
        PrintLn();
        PrintLn("\t%s%s : %s", kv.first.c_str(), std::string(npad, ' ').c_str(), kv.second.c_str());
    }
    printf("\n");
    PrintLn();
}

int BoxMain(int argc, const char *argv[])
@@ -106,7 +118,7 @@
    if (BoxFind(name, func)) {
        return func(argc, argv);
    } else {
        printf("%s : function not found!\n", name.c_str());
        PrintLn("%s : function not found!", name.c_str());
        // Help();
    }
    return 0;
@@ -119,7 +131,7 @@

    fs::path exe(argv[0]);
    auto name = exe.filename().string();
    // printf("name: %s\n", name.c_str());
    // PrintLn("name: %s", name.c_str());

    if (name == kOrigName) {
        if (argc > 1) {

 box/center.cpp

@@ -18,6 +18,7 @@
#include "center.h"
#include "bh_util.h"
#include "defs.h"
#include "log.h"
#include "shm.h"
#include <chrono>
#include <set>
@@ -60,9 +61,7 @@
        void UpdateState(const int64_t now, const int64_t offline_time, const int64_t kill_time)
        {
            auto diff = now - timestamp_;
#ifndef NDEBUG
            printf("state %p diff: %ld\n", this, diff);
#endif
            LOG_DEBUG() << "state " << this << " diff: " << diff;
            if (diff < offline_time) {
                flag_ = kStateNormal;
            } else if (diff < kill_time) {
@@ -117,7 +116,7 @@
        Node node(new NodeInfo);
        UpdateRegInfo(node);
        nodes_[ssn] = node;
        printf("new node ssn (%ld) init\n", ssn);
        LOG_INFO() << "new node ssn (" << ssn << ") init";
    }
    MsgCommonReply Register(const BHMsgHead &head, MsgRegister &msg)
    {
@@ -148,14 +147,14 @@
                UpdateRegInfo(node);
                nodes_[ssn] = node;
            }
            printf("node (%s) ssn (%ld)\n", head.proc_id().c_str(), ssn);
            LOG_DEBUG() << "node (" << head.proc_id() << ") ssn (" << ssn << ")";

            auto old = online_node_addr_map_.find(head.proc_id());
            if (old != online_node_addr_map_.end()) { // old session
                auto &old_ssn = old->second;
                if (old_ssn != ssn) {
                    nodes_[old_ssn]->state_.PutOffline(offline_time_);
                    printf("put node (%s) ssn (%ld) offline\n", nodes_[old_ssn]->proc_.proc_id().c_str(), old->second);
                    LOG_DEBUG() << "put node (" << nodes_[old_ssn]->proc_.proc_id() << ") ssn (" << old->second << ") offline";
                    old_ssn = ssn;
                }
            } else {
@@ -218,9 +217,9 @@
                for (auto &topic : topics) {
                    service_map_[topic].insert(dest);
                }
                printf("node %s ssn %ld serve %d topics:\n", node->proc_.proc_id().c_str(), *node->addrs_.begin(), topics.size());
                LOG_DEBUG() << "node " << node->proc_.proc_id() << " ssn " << *node->addrs_.begin() << " serve " << topics.size() << " topics:\n";
                for (auto &topic : topics) {
                    printf("\t %s\n", topic.c_str());
                    LOG_DEBUG() << "\t" << topic;
                }
                return MakeReply(eSuccess);
            });
@@ -572,7 +571,7 @@
    auto gc = [&](const MQId id) {
        auto r = ShmSocket::Remove(shm, id);
        if (r) {
            printf("remove mq %ld ok\n", id);
            LOG_DEBUG() << "remove mq " << id << " ok\n";
        }
    };


 box/center_main.cc

@@ -19,6 +19,7 @@
#include "box.h"
#include "center.h"
#include "defs.h"
#include "log.h"
#include "signalhandle.h"
#include <boost/interprocess/sync/named_mutex.hpp>
#include <chrono>
@@ -50,7 +51,7 @@
        if (mtx && time_stamp) {
            Guard lock(*mtx);
            auto now = NowSec();
            // printf("old: %ld, now: %ld\n", *time_stamp, now);
            LOG_DEBUG() << "old: " << *time_stamp << ", now: " << now;
            if (now > *time_stamp + 10) {
                *time_stamp = now;
                auto UpdateTime = [this, time_stamp]() {
@@ -91,12 +92,21 @@
        return 0;
    }

    ns_log::AddLog("/tmp/bhshmq_center.log", true, true);
    auto lvl = args.Get("log", "info");
    if (strcasecmp(lvl.c_str(), "trace") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::trace); }
    if (strcasecmp(lvl.c_str(), "debug") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::debug); }
    if (strcasecmp(lvl.c_str(), "info") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::info); }
    if (strcasecmp(lvl.c_str(), "warning") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::warning); }
    if (strcasecmp(lvl.c_str(), "error") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::error); }
    if (strcasecmp(lvl.c_str(), "fatal") == 0) { ns_log::ResetLogLevel(ns_log::LogLevel::fatal); }

    auto &shm = BHomeShm();
    GlobalInit(shm);

    InstanceFlag inst(shm, kCenterRunningFlag);
    if (!inst.TryStartAsFirstInstance()) {
        printf("another instance is running, exit.\n");
        LOG_INFO() << "another instance is running, exit.";
        return 0;
    }

@@ -107,8 +117,10 @@
    BHCenter center(shm);
    center.Start();

    printf("center started ...\n");
    LOG_INFO() << "center started ...";
    WaitForSignals({SIGINT, SIGTERM});
    center.Stop();
    LOG_INFO() << "center stopped.";
    return 0;
}


 log/log.cpp

New file
@@ -0,0 +1,106 @@
#include "log.h"
#include <atomic>
#include <boost/log/core.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/sinks/text_file_backend.hpp>
#include <boost/log/sources/record_ostream.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <execinfo.h>

namespace ns_log
{

namespace logging = boost::log;
namespace src = boost::log::sources;
namespace sinks = boost::log::sinks;
namespace keywords = boost::log::keywords;

std::string TimeStamp()
{
    char buf[64] = {0};
    timeval tv = {0};
    gettimeofday(&tv, 0);
    tm r = {0};
    localtime_r(&tv.tv_sec, &r);
    int n = snprintf(buf, sizeof(buf) - 1, "%04d-%02d-%02d %02d:%02d:%02d.%06ld",
                     r.tm_year + 1900, r.tm_mon + 1, r.tm_mday,
                     r.tm_hour, r.tm_min, r.tm_sec,
                     tv.tv_usec);
    return std::string(buf, buf + n);
}

void GetTrace()
{
    const int ntrace = 256;
    void *buffer[ntrace];
    char **strings;
    int nptrs = backtrace(buffer, ntrace);
    strings = backtrace_symbols(buffer, nptrs);
    if (strings) {
        LOG_DEBUG() << "[[[ call trace begin:";
        MsgIndent(2);
        for (int i = 0; i < nptrs; ++i) {
            LOG_DEBUG() << strings[i];
        }
        free(strings);
        MsgIndent(-2);
        LOG_DEBUG() << "]]] call trace end.";
    }
}

std::string LogPrefix(logging::trivial::severity_level level)
{
    return "[" + TimeStamp() + "](" +
           //        logging::trivial::to_string(level) +
           std::to_string(level) +
           ") " + MsgPrefix();
}

void AddLogRaw(const std::string &file_ptn, bool flush, bool with_console)
{
    logging::add_file_log(
        keywords::file_name = file_ptn,
        keywords::open_mode = std::ios_base::app,
        keywords::rotation_size = 1024 * 1024 * 50,
        //            keywords::target = "/tmp/bhshmq_logs",
        //            keywords::format = "[%TimeStamp%] %Severity% %Message%",
        //            keywords::time_based_rotation = sinks::file::rotation_at_time_point(0, 0, 0)
        keywords::auto_flush = flush);
    if (with_console) {
        logging::add_console_log();
    }
    logging::add_common_attributes();
    logging::core::get()->set_filter(logging::trivial::severity >= GetLogLevel());
}
void AddLog(const std::string &file_ptn, bool flush, bool with_console)
{
    AddLogRaw(file_ptn, flush, with_console);
    std::string hint;
    for (int i = 0; i < 6; ++i) {
        hint += "(" + std::to_string(i) + ")=" + logging::trivial::to_string(logging::trivial::severity_level(i)) + ", ";
    }
    BOOST_LOG_TRIVIAL(fatal) << "[" + TimeStamp() + "]*info* log levels: " << hint;
}

std::atomic<LogLevel> &CurLogLevel()
{
    static std::atomic<LogLevel> cur(logging::trivial::info);
    return cur;
}

LogLevel GetLogLevel() { return LogLevel(CurLogLevel().load()); }

LogLevel ResetLogLevel(LogLevel level, bool log_this)
{
    if (log_this) {
        BOOST_LOG_TRIVIAL(fatal) << "[" + TimeStamp() + "]*info* log level reset to " << level;
    }
    logging::core::get()->set_filter(logging::trivial::severity >= level);
    return CurLogLevel().exchange(level);
}

} // namespace ns_log

 log/log.h

New file
@@ -0,0 +1,112 @@
#ifndef LOG_SPKA2JY7
#define LOG_SPKA2JY7

#include "macro.h"
#include <boost/log/trivial.hpp>
#include <string>

namespace ns_log
{

void GetTrace();
typedef boost::log::trivial::severity_level LogLevel;
inline std::string &MsgPrefix()
{
    thread_local std::string prefix;
    return prefix;
}
inline int MsgIndent(int offset)
{
    thread_local int indent = 0;
    indent += offset;
    if (indent > 0) {
        MsgPrefix() = std::string(indent, ' ');
    } else {
        MsgPrefix().clear();
    }
    return indent;
}
std::string TimeStamp();
std::string LogPrefix(LogLevel level);
void AddLogRaw(const std::string &file_ptn, bool flush = true, bool with_console = false);
void AddLog(const std::string &file_ptn, bool flush = true, bool with_console = false);
LogLevel ResetLogLevel(LogLevel level, bool log_this = true);
LogLevel GetLogLevel();

} // namespace ns_log

#define LOG_WITH_PREFIX(severity) BOOST_LOG_TRIVIAL(severity) << ns_log::LogPrefix(boost::log::trivial::severity)

#define LOG__TRACE() LOG_WITH_PREFIX(trace)
#define LOG__DEBUG() LOG_WITH_PREFIX(debug)
#define LOG__INFO() LOG_WITH_PREFIX(info)
#define LOG__WARNING() LOG_WITH_PREFIX(warning)
#define LOG__ERROR() LOG_WITH_PREFIX(error)
#define LOG__FATAL() LOG_WITH_PREFIX(fatal)

#ifndef LOG_TRACE
#define LOG_TRACE() LOG__TRACE()
#endif

#ifndef LOG_DEBUG
#define LOG_DEBUG() LOG__DEBUG()
#endif

#ifndef LOG_INFO
#define LOG_INFO() LOG__INFO()
#endif

#ifndef LOG_WARNING
#define LOG_WARNING() LOG__WARNING()
#endif

#ifndef LOG_ERROR
#define LOG_ERROR() LOG__ERROR()
#endif

#ifndef LOG_FATAL
#define LOG_FATAL() LOG__FATAL()
#endif

#define LOG_POS() LOG__DEBUG() << __FILE__ << " +" << __LINE__ << ": "

// usage:
// LOG__WARNING() << "warning msg ...";
// LOG__ERROR() << "error msg ...";

namespace ns_log
{
namespace impl
{
using namespace boost::log::trivial;
class FuncLog
{
    const char *name_;

public:
    FuncLog(const char *name) :
        name_(name)
    {
        LOG__DEBUG() << ">>> " << name_;
        if (GetLogLevel() <= debug) {
            MsgIndent(2);
        }
    }
    ~FuncLog()
    {
        if (GetLogLevel() <= debug) {
            MsgIndent(-2);
        }
        LOG__DEBUG() << "<// " << name_;
    }
};
} // namespace impl
} // namespace ns_log

#if defined(__GNUG__)
#define LOG_FUNCTION ns_log::impl::FuncLog JOIN(log_func_, JOIN(__LINE__, _))(__PRETTY_FUNCTION__)
#else
#define LOG_FUNCTION ns_log::impl::FuncLog JOIN(log_func_, JOIN(__LINE__, _))(__FUNCTION__)
#endif

#endif // end of include guard: LOG_SPKA2JY7

 log/macro.h

New file
@@ -0,0 +1,15 @@
#ifndef MACRO_LMMKBZRX
#define MACRO_LMMKBZRX

#define EXPAND(x) x
#define CALL(M, ...) EXPAND(M(__VA_ARGS__))

// macro helper
#define JOIN_IMPL(a, b) a##b
#define JOIN(a, b) JOIN_IMPL(a, b)

// defer function or lambda.
#define DEFERF(func) ExitCall JOIN(defer_, __LINE__)(func)
// defer simple expression
#define DEFER1(expr) DEFERF([&]() { expr; })
#endif // end of include guard: MACRO_LMMKBZRX

 src/CMakeLists.txt

@@ -1,11 +1,14 @@

file(GLOB sources "./*.cpp")
file(GLOB sources "./*.cpp" "../log/*.cpp")

set(Target bhome_shmq)
set(TargetStatic bhome_shmq_static)

include_directories(../log)
add_library(${Target} SHARED ${sources})
add_library(${TargetStatic} STATIC ${sources})

target_link_libraries(${Target} bhome_msg pthread rt)
target_link_libraries(${TargetStatic} bhome_msg_static pthread rt)
set(LogLibs "boost_log;boost_log_setup;boost_thread;boost_filesystem")

target_link_libraries(${Target} bhome_msg ${LogLibs} pthread rt)
target_link_libraries(${TargetStatic} bhome_msg_static ${LogLibs} pthread rt)

 src/bh_api.cpp

@@ -1,6 +1,7 @@
#include "bh_api.h"
#include "defs.h"
#include "topic_node.h"
#include <cstdio>
#include <memory>

using namespace bhome_shm;
@@ -8,9 +9,36 @@

namespace
{
std::string GetProcExe()
{
    auto f = fopen("/proc/self/stat", "rb");
    if (f) {
        DEFER1(fclose(f));
        char buf[100] = {0};
        int n = fread(buf, 1, sizeof(buf), f);
        if (n > 0) {
            std::string s(buf, n);
            auto start = s.find('(');
            if (start != std::string::npos) {
                ++start;
                auto end = s.find(')', start);
                return s.substr(start, end - start);
            }
        }
    }
    return std::to_string(getpid());
}
std::unique_ptr<TopicNode> &ProcNodePtr()
{
    static bool init = GlobalInit(BHomeShm());
    auto InitLog = []() {
        auto id = GetProcExe();
        char path[200] = {0};
        sprintf(path, "/tmp/bhshmq_node_%s.log", id.c_str());
        ns_log::AddLog(path);
        return true;
    };
    static bool init_log = InitLog();
    static std::unique_ptr<TopicNode> ptr(new TopicNode(BHomeShm()));
    return ptr;
}

 src/bh_util.h

@@ -18,6 +18,7 @@
#ifndef BH_UTIL_SOXWOK67
#define BH_UTIL_SOXWOK67

#include "macro.h"
#include <functional>
#include <mutex>
#include <stdint.h>
@@ -167,13 +168,5 @@
        return ptr() ? false : Bind();
    }
};

// macro helper
#define JOIN_IMPL(a, b) a##b
#define JOIN(a, b) JOIN_IMPL(a, b)
// defer function / lambda.
#define DEFERF(func) ExitCall JOIN(defer_, __LINE__)(func)
// defer simple expression
#define DEFER1(expr) DEFERF([&]() { expr; })

#endif /* end of include guard: BH_UTIL_SOXWOK67 */

 src/robust.h

@@ -19,6 +19,7 @@
#ifndef ROBUST_Q31RCWYU
#define ROBUST_Q31RCWYU

#include "log.h"
#include <atomic>
#include <chrono>
#include <memory>
@@ -171,7 +172,7 @@
        } else if (!is_alive(Locker(old))) {
            r = static_cast<int>(MetaCas(old, Meta(1, this_locker()))) << 1;
            if (r) {
                printf("captured locker %ld -> %ld, locker = %d\n", int64_t(Locker(old)), int64_t(this_locker()), r);
                LOG_DEBUG() << "captured locker " << int64_t(Locker(old)) << " -> " << int64_t(this_locker()) << ", locker = " << r;
            }
        }
        return r;

 src/shm.h

@@ -68,7 +68,7 @@
            if (Killed(old)) {
                r = PidCas(old, pid());
                if (r) {
                    printf("PidCheck captured pid %d -> %d\n", old, pid());
                    LOG_DEBUG() << "PidCheck captured pid " << old << " -> " << pid();
                }
            }
        }

 src/socket.h

@@ -114,7 +114,7 @@
            std::unique_lock<std::mutex> lk(st->mutex);
            bool sendok = Send(remote, head, body, std::move(OnRecv));
            if (!sendok) {
                printf("send timeout\n");
                LOG_DEBUG() << "send timeout";
            }
            if (sendok && st->cv.wait_until(lk, endtime) == std::cv_status::no_timeout) {
                return true;

 src/topic_node.cpp

@@ -44,7 +44,7 @@

TopicNode::~TopicNode()
{
    printf("~TopicNode()\n");
    LOG_DEBUG() << "~TopicNode()";
    Stop();
}

@@ -59,7 +59,7 @@
    if (ssn_id_ == 0) {
        ssn_id_ = ShmMsgQueue::NewId();
    }
    printf("Node Init, id %ld \n", ssn_id_);
    LOG_DEBUG() << "Node Init, id " << ssn_id_;
    MsgI msg;
    msg.OffsetRef() = ssn_id_;
    if (ShmMsgQueue::TrySend(shm(), BHInitAddress(), msg)) {
@@ -95,9 +95,9 @@
}
void TopicNode::Stop()
{
    printf("Node Stopping\n");
    LOG_DEBUG() << "Node Stopping";
    for (auto &p : sockets_) { p->Stop(); }
    printf("Node Stopped\n");
    LOG_INFO() << "Node Stopped";
}

bool TopicNode::Register(ProcInfo &proc, MsgCommonReply &reply_body, const int timeout_ms)
@@ -423,7 +423,7 @@

        BHAddress addr;
        if (ClientQueryRPCTopic(request.topic(), addr, timeout_ms)) {
            // printf("node: %ld, topic dest: %ld\n", SockNode().id(), addr.mq_id());
            LOG_TRACE() << "node: " << SockNode().id() << ", topic dest: " << addr.mq_id();
            BHMsgHead head(InitMsgHead(GetType(request), proc_id(), ssn()));
            AddRoute(head, sock.id());
            head.set_topic(request.topic());

 utest/CMakeLists.txt

@@ -1,6 +1,7 @@

FILE(GLOB sources "./*.cpp")

include_directories(../log)
include_directories(../src)
add_executable(utest ${sources})


 utest/api_test.cpp

@@ -284,7 +284,7 @@
    threads.Launch(hb, &run);
    threads.Launch(showStatus, &run);
    int ncli = 10;
    const uint64_t nreq = 1000 * 100;
    const int64_t nreq = 1000 * 100;
    for (int i = 0; i < ncli; ++i) {
        threads.Launch(asyncRequest, nreq);
    }

 utest/utest.cpp

@@ -1,5 +1,6 @@
#include "center.h"
#include "defs.h"
#include "log.h"
#include "util.h"
#include <atomic>
#include <condition_variable>
@@ -8,6 +9,17 @@
#include <thread>
#include <vector>

namespace
{
bool InitLog()
{
    ns_log::AddLog("/tmp/bhshmq_test.log", true, true);
    ns_log::ResetLogLevel(ns_log::LogLevel::debug);
    return true;
}
static bool g_test_init_log = InitLog();
} // namespace

using namespace bhome_shm;
using namespace bhome_msg;