libdpf/include/dpf/run_log.hpp

/// @file dpf/run_log.hpp
/// @brief Configure the run log from a `run_config` and write the provenance
///        banner: build, host, command line, environment, configuration, time.
/// @details `app::start_logging(cfg)` applies `cfg.log_level`, `cfg.log_sinks`,
///          and `cfg.log_seeds` (see `dpf/log.hpp`), then writes these records
///          once per process, at `info`:
///
///          - `ev=start`: program, executable, working directory, start time
///            (UTC and local with its offset), and the invocation id that
///            every later record and `runs.csv` row carries.
///          - `ev=build`: git revision (`LIBDPF_GIT_REV`, captured when the
///            build was configured; `unknown` for a bare compiler line),
///            compiler, language level, whether the build is optimized,
///            `NDEBUG`, the instruction-set extensions it targets, the entropy
///            source, and sanitizers.
///          - `ev=host`: hostname, kernel, machine, CPU model, online CPUs,
///            this process's CPU affinity, SMT, frequency governor, turbo,
///            memory, and load average. `ev=if` for each interface address
///            (link-local IPv6 skipped): name, address, MTU, and link speed.
///          - `ev=argv`: the command line, shell-quoted so it can be pasted.
///          - `ev=env`: each `DPF_*` and `LIBDPF_*` variable, and the few
///            others that change performance (`LD_PRELOAD`, `GLIBC_TUNABLES`,
///            allocator and sanitizer options). A name containing `SEED`,
///            `KEY`, `SECRET`, `TOKEN`, or `PASS` is printed under `log_seeds`.
///          - `ev=config`: every `run_config` setting.
///
///          A later call reapplies the sinks, and writes `ev=config` again only
///          when a setting changed. `ev=end` at exit gives the elapsed time.
#ifndef LIBDPF_INCLUDE_DPF_RUN_LOG_HPP__
#define LIBDPF_INCLUDE_DPF_RUN_LOG_HPP__

#include <chrono>
#include <cstdint>
#include <cstdlib>
#include <cstring>
#include <ctime>
#include <fstream>
#include <mutex>
#include <string>
#include <utility>
#include <vector>

#include <unistd.h>

#if defined(__linux__)
#include <arpa/inet.h>
#include <ifaddrs.h>
#include <net/if.h>
#include <netinet/in.h>
#include <sched.h>
#include <sys/utsname.h>
#endif

#include "dpf/log.hpp"
#include "dpf/run_config.hpp"

#ifndef LIBDPF_GIT_REV
#define LIBDPF_GIT_REV "unknown"
#endif

extern char ** environ;

namespace dpf
{
namespace app
{

inline log::settings log_settings(const run_config & cfg)
{
    log::settings s;
    s.threshold = cfg.log_level;
    s.sinks = cfg.log_sinks;
    s.seeds = cfg.log_seeds;
    return s;
}

namespace log_detail
{

inline std::string first_line(const std::string & path)
{
    std::ifstream in(path);
    std::string line;
    if (in)
        std::getline(in, line);
    return line;
}

inline std::string shell_quote(const std::string & s)
{
    if (s.empty())
        return "''";
    bool plain = true;
    for (char c : s)
    {
        const bool ok = (c >= 'a' && c <= 'z') || (c >= 'A' && c <= 'Z')
            || (c >= '0' && c <= '9') || std::strchr("_-./:=,+@%", c) != nullptr;
        plain = plain && ok;
    }
    if (plain)
        return s;
    std::string out = "'";
    for (char c : s)
    {
        if (c == '\'')
            out += "'\\''";
        else
            out += c;
    }
    out += '\'';
    return out;
}

/// @brief The command line from `/proc/self/cmdline` (no `argv` needed).
inline std::vector<std::string> command_line()
{
    std::vector<std::string> args;
#if defined(__linux__)
    std::ifstream in("/proc/self/cmdline", std::ios::binary);
    std::string arg;
    char c = 0;
    while (in.get(c))
    {
        if (c == '\0')
        {
            args.push_back(arg);
            arg.clear();
        }
        else
            arg += c;
    }
    if (!arg.empty())
        args.push_back(arg);
#endif
    return args;
}

inline std::string exe_path()
{
#if defined(__linux__)
    char buf[4096];
    const ssize_t n = ::readlink("/proc/self/exe", buf, sizeof(buf) - 1);
    if (n > 0)
        return std::string(buf, static_cast<std::size_t>(n));
#endif
    return "unknown";
}

inline std::string cwd()
{
    char buf[4096];
    return ::getcwd(buf, sizeof(buf)) != nullptr ? std::string(buf) : std::string("unknown");
}

inline std::string local_time(std::time_t t)
{
    std::tm tm{};
    ::localtime_r(&t, &tm);
    char buf[80];
    if (std::strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S %Z %z", &tm) == 0)
        return "unknown";
    return buf;
}

inline std::string isa()
{
    std::string out;
    auto add = [&out](const char * name) {
        if (!out.empty())
            out += ',';
        out += name;
    };
#if defined(__SSE4_2__)
    add("sse4.2");
#endif
#if defined(__AES__)
    add("aes");
#endif
#if defined(__PCLMUL__)
    add("pclmul");
#endif
#if defined(__AVX2__)
    add("avx2");
#endif
#if defined(__AVX512F__)
    add("avx512f");
#endif
#if defined(__VAES__)
    add("vaes");
#endif
#if defined(__VPCLMULQDQ__)
    add("vpclmulqdq");
#endif
#if defined(__BMI2__)
    add("bmi2");
#endif
#if defined(__ARM_NEON)
    add("neon");
#endif
#if defined(__ARM_FEATURE_CRYPTO) || defined(__ARM_FEATURE_AES)
    add("armv8-crypto");
#endif
    return out.empty() ? std::string("baseline") : out;
}

inline const char * entropy_source() noexcept
{
#if defined(LIBDPF_USE_ARC4RANDOM)
    return "arc4random";
#elif defined(LIBDPF_USE_DEV_RANDOM)
    return "/dev/random";
#else
    return "/dev/urandom";
#endif
}

inline std::string sanitizers()
{
    std::string out;
#if defined(__SANITIZE_ADDRESS__)
    out += "address";
#endif
#if defined(__SANITIZE_THREAD__)
    out += out.empty() ? "thread" : ",thread";
#endif
#if defined(__has_feature)
#if __has_feature(address_sanitizer) && !defined(__SANITIZE_ADDRESS__)
    out += out.empty() ? "address" : ",address";
#endif
#if __has_feature(thread_sanitizer) && !defined(__SANITIZE_THREAD__)
    out += out.empty() ? "thread" : ",thread";
#endif
#if __has_feature(undefined_behavior_sanitizer)
    out += out.empty() ? "undefined" : ",undefined";
#endif
#endif
    return out.empty() ? std::string("none") : out;
}

inline std::string cpu_model()
{
#if defined(__linux__)
    std::ifstream in("/proc/cpuinfo");
    std::string line;
    while (std::getline(in, line))
    {
        if (line.rfind("model name", 0) == 0 || line.rfind("Model", 0) == 0
            || line.rfind("Hardware", 0) == 0)
        {
            const auto colon = line.find(':');
            if (colon != std::string::npos)
            {
                auto v = line.substr(colon + 1);
                while (!v.empty() && v.front() == ' ')
                    v.erase(v.begin());
                return v;
            }
        }
    }
#endif
    return "unknown";
}

inline std::string affinity()
{
#if defined(__linux__)
    cpu_set_t set;
    CPU_ZERO(&set);
    if (::sched_getaffinity(0, sizeof(set), &set) != 0)
        return "unknown";
    std::string out;
    int run_start = -1;
    for (int c = 0; c <= CPU_SETSIZE; ++c)
    {
        const bool in = c < CPU_SETSIZE && CPU_ISSET(c, &set);
        if (in && run_start < 0)
            run_start = c;
        if (!in && run_start >= 0)
        {
            if (!out.empty())
                out += ',';
            out += std::to_string(run_start);
            if (c - 1 > run_start)
                out += "-" + std::to_string(c - 1);
            run_start = -1;
        }
    }
    return out;
#else
    return "unknown";
#endif
}

inline std::string turbo()
{
    const auto no_turbo = first_line("/sys/devices/system/cpu/intel_pstate/no_turbo");
    if (!no_turbo.empty())
        return no_turbo == "0" ? "on" : "off";
    const auto boost = first_line("/sys/devices/system/cpu/cpufreq/boost");
    if (!boost.empty())
        return boost == "1" ? "on" : "off";
    return "unknown";
}

inline std::string or_unknown(std::string s)
{
    return s.empty() ? std::string("unknown") : s;
}

inline bool secret_name(const std::string & name)
{
    for (const char * w : {"SEED", "KEY", "SECRET", "TOKEN", "PASS"})
        if (name.find(w) != std::string::npos)
            return true;
    return false;
}

inline bool relevant_env(const std::string & name)
{
    if (name.rfind("DPF_", 0) == 0 || name.rfind("LIBDPF_", 0) == 0)
        return true;
    for (const char * n : {"LD_PRELOAD", "LD_LIBRARY_PATH", "GLIBC_TUNABLES",
             "MALLOC_ARENA_MAX", "MALLOC_CONF", "ASAN_OPTIONS", "UBSAN_OPTIONS",
             "TSAN_OPTIONS", "OMP_NUM_THREADS", "TZ"})
        if (name == n)
            return true;
    return false;
}

struct banner_state
{
    std::mutex mu;
    bool written = false;
    std::string last_config;
    std::chrono::steady_clock::time_point started{};
};

inline banner_state & banner()
{
    static banner_state b;
    return b;
}

inline void log_config(const run_config & cfg)
{
    auto rec = log::record(log::level::info, "config");
    for (const auto & kv : cfg.describe())
        rec.kv(kv.first.c_str(), kv.second);
}

inline void at_exit()
{
    const auto elapsed = std::chrono::steady_clock::now() - banner().started;
    DPF_LOG(info, "end").kv("elapsed_ms",
        std::chrono::duration<double, std::milli>(elapsed).count());
}

inline void write_banner(const run_config & cfg)
{
    const auto now = std::chrono::system_clock::now();
    const auto args = command_line();
    DPF_LOG(info, "start")
        .kv("program", args.empty() ? std::string("unknown") : args.front())
        .kv("exe", exe_path()).kv("cwd", cwd())
        .kv("utc", log::detail::utc_text(now))
        .kv("local", local_time(std::chrono::system_clock::to_time_t(now)))
        .kv("epoch_ns", static_cast<long long>(
            std::chrono::duration_cast<std::chrono::nanoseconds>(
                now.time_since_epoch()).count()))
        .kv("ppid", static_cast<long long>(::getppid()));

#if defined(NDEBUG)
    const bool ndebug = true;
#else
    const bool ndebug = false;
#endif
#if defined(__OPTIMIZE__)
    const bool optimized = true;
#else
    const bool optimized = false;
#endif
#if defined(__clang__)
    const std::string compiler = std::string("clang ") + __clang_version__;
#elif defined(__GNUC__)
    const std::string compiler = std::string("gcc ") + __VERSION__;
#elif defined(__VERSION__)
    const std::string compiler = __VERSION__;
#else
    const std::string compiler = "unknown";
#endif
    DPF_LOG(info, "build").kv("rev", LIBDPF_GIT_REV).kv("compiler", compiler)
        .kv("cxx", static_cast<long>(__cplusplus)).kv("optimized", optimized)
        .kv("ndebug", ndebug).kv("isa", isa()).kv("entropy", entropy_source())
        .kv("sanitizers", sanitizers()).kv("compiled", __DATE__ " " __TIME__);

#if defined(__linux__)
    struct utsname u{};
    const bool have_uname = ::uname(&u) == 0;
    char host[256] = {};
    (void)::gethostname(host, sizeof(host) - 1);
    double load[3] = {0, 0, 0};
    const int nload = ::getloadavg(load, 3);
    const long pages = ::sysconf(_SC_PHYS_PAGES);
    const long page = ::sysconf(_SC_PAGESIZE);
    DPF_LOG(info, "host").kv("hostname", host)
        .kv("kernel", have_uname ? std::string(u.sysname) + " " + u.release
                                 : std::string("unknown"))
        .kv("machine", have_uname ? std::string(u.machine) : std::string("unknown"))
        .kv("cpu", cpu_model())
        .kv("cpus_online", static_cast<long>(::sysconf(_SC_NPROCESSORS_ONLN)))
        .kv("affinity", affinity())
        .kv("smt", or_unknown(first_line("/sys/devices/system/cpu/smt/active")))
        .kv("governor", or_unknown(first_line(
            "/sys/devices/system/cpu/cpu0/cpufreq/scaling_governor")))
        .kv("turbo", turbo())
        .kv("mem_mib", pages > 0 && page > 0
                ? static_cast<long long>(pages) * page / (1024 * 1024) : 0LL)
        .kv("load1", nload > 0 ? load[0] : -1.0);

    ifaddrs * ifs = nullptr;
    if (::getifaddrs(&ifs) == 0)
    {
        for (auto * a = ifs; a != nullptr; a = a->ifa_next)
        {
            if (a->ifa_addr == nullptr)
                continue;
            const int fam = a->ifa_addr->sa_family;
            if (fam != AF_INET && fam != AF_INET6)
                continue;
            if (fam == AF_INET6 && IN6_IS_ADDR_LINKLOCAL(
                    &reinterpret_cast<const sockaddr_in6 *>(a->ifa_addr)->sin6_addr))
                continue;
            char text[INET6_ADDRSTRLEN] = {};
            const void * src = fam == AF_INET
                ? static_cast<const void *>(
                    &reinterpret_cast<const sockaddr_in *>(a->ifa_addr)->sin_addr)
                : static_cast<const void *>(
                    &reinterpret_cast<const sockaddr_in6 *>(a->ifa_addr)->sin6_addr);
            if (::inet_ntop(fam, src, text, sizeof(text)) == nullptr)
                continue;
            const std::string name = a->ifa_name == nullptr ? "" : a->ifa_name;
            DPF_LOG(info, "if").kv("name", name).kv("addr", text)
                .kv("up", (a->ifa_flags & IFF_UP) != 0)
                .kv("loopback", (a->ifa_flags & IFF_LOOPBACK) != 0)
                .kv("mtu", or_unknown(first_line("/sys/class/net/" + name + "/mtu")))
                .kv("speed_mbps",
                    or_unknown(first_line("/sys/class/net/" + name + "/speed")));
        }
        ::freeifaddrs(ifs);
    }
#endif

    std::string joined;
    for (const auto & a : args)
    {
        if (!joined.empty())
            joined += ' ';
        joined += shell_quote(a);
    }
    DPF_LOG(info, "argv").kv("argc", args.size()).kv("cmdline", joined);

    std::vector<std::pair<std::string, std::string>> env;
    for (char ** e = environ; e != nullptr && *e != nullptr; ++e)
    {
        const std::string entry = *e;
        const auto eq = entry.find('=');
        if (eq == std::string::npos)
            continue;
        auto name = entry.substr(0, eq);
        if (relevant_env(name))
            env.emplace_back(std::move(name), entry.substr(eq + 1));
    }
    DPF_LOG(info, "env").kv("relevant", env.size());
    for (const auto & kv : env)
    {
        if (secret_name(kv.first))
            DPF_LOG(info, "env").kv("name", kv.first)
                .seed("value", kv.second.data(), kv.second.size());
        else
            DPF_LOG(info, "env").kv("name", kv.first).kv("value", kv.second);
    }
    DPF_LOG(info, "log").kv("level", log::level_name(cfg.log_level))
        .kv("sinks", cfg.log_sinks).kv("seeds", log::seed_policy_name(cfg.log_seeds));
}

}  // namespace log_detail

/// @brief Apply `cfg`'s log settings and write the provenance banner once.
inline void start_logging(const run_config & cfg)
{
    log::configure(log_settings(cfg));
    auto & b = log_detail::banner();
    std::lock_guard<std::mutex> lock(b.mu);
    const auto summary = cfg.summary();
    if (!b.written)
    {
        b.written = true;
        b.started = std::chrono::steady_clock::now();
        log_detail::write_banner(cfg);
        std::atexit(&log_detail::at_exit);
    }
    if (summary != b.last_config && log::enabled(log::level::info))
    {
        b.last_config = summary;
        log_detail::log_config(cfg);
    }
}

}  // namespace app
}  // namespace dpf

#endif  // LIBDPF_INCLUDE_DPF_RUN_LOG_HPP__