/// @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 #include #include #include #include #include #include #include #include #include #include #if defined(__linux__) #include #include #include #include #include #include #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 command_line() { std::vector 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(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(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( std::chrono::duration_cast( now.time_since_epoch()).count())) .kv("ppid", static_cast(::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(__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(::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(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(a->ifa_addr)->sin6_addr)) continue; char text[INET6_ADDRSTRLEN] = {}; const void * src = fam == AF_INET ? static_cast( &reinterpret_cast(a->ifa_addr)->sin_addr) : static_cast( &reinterpret_cast(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> 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 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__