/// @file dpf/log.hpp /// @brief Leveled run log: one `key=value` line per record, written to /// stderr, syslog, or a file. /// @details Nothing is written until `log::configure` runs (normally through /// `app::start_logging`), so library code logs freely and a test or /// embedder that never configures the log stays quiet. /// /// A record is built in a local string and written with one /// `write(2)` per sink, so party threads, and party processes that /// append to one file, never interleave inside a line. Every line /// starts with `ts= lvl= inv= /// pid= tid=`, then `role=` when the /// thread has one (`role_scope`), then `ev=` and the event's /// fields. A value with a space, quote, `=`, backslash, or control /// character is double-quoted with backslash escapes. /// /// Seed bytes go through `record::seed`, which prints them as hex, as /// a SHA-256 fingerprint, or not at all, per `settings::seeds`. /// /// Levels, from quiet to loud: `silent`, `error`, `warning`, `info`, /// `debug`, `trace` (or `0`-`5`; `warn` and `absurd` are accepted as /// aliases). `DPF_LOG(level, "event").kv("key", value)` builds the /// record only when that level is enabled. #ifndef LIBDPF_INCLUDE_DPF_LOG_HPP__ #define LIBDPF_INCLUDE_DPF_LOG_HPP__ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #if defined(__linux__) #include #endif #if defined(__has_include) #if __has_include() #include #define DPF_LOG_HAS_SYSLOG 1 #endif #endif #ifndef DPF_LOG_HAS_SYSLOG #define DPF_LOG_HAS_SYSLOG 0 #endif namespace dpf { namespace log { enum class level : unsigned char { silent = 0, error = 1, warning = 2, info = 3, debug = 4, trace = 5 }; inline const char * level_name(level l) noexcept { switch (l) { case level::silent: return "silent"; case level::error: return "error"; case level::warning: return "warning"; case level::info: return "info"; case level::debug: return "debug"; case level::trace: return "trace"; } return "info"; } /// @brief Parse a level name or digit. Unknown names throw. inline level parse_level(const std::string & s) { if (s == "silent" || s == "none" || s == "off" || s == "0") return level::silent; if (s == "error" || s == "1") return level::error; if (s == "warning" || s == "warn" || s == "2") return level::warning; if (s == "info" || s == "3") return level::info; if (s == "debug" || s == "4") return level::debug; if (s == "trace" || s == "absurd" || s == "5") return level::trace; throw std::invalid_argument("unknown log level: " + s + " (silent|error|warning|info|debug|trace or 0-5)"); } /// @brief How seed bytes appear in records. enum class seed_policy : unsigned char { full, ///< the bytes as hex: the run can be replayed from the log hash, ///< a SHA-256 fingerprint: runs can be compared, not replayed off ///< neither; the field reads `withheld` }; inline const char * seed_policy_name(seed_policy p) noexcept { switch (p) { case seed_policy::full: return "full"; case seed_policy::hash: return "hash"; case seed_policy::off: return "off"; } return "full"; } inline seed_policy parse_seed_policy(const std::string & s) { if (s == "full" || s == "hex" || s == "1") return seed_policy::full; if (s == "hash" || s == "fingerprint" || s == "sha256") return seed_policy::hash; if (s == "off" || s == "none" || s == "0") return seed_policy::off; throw std::invalid_argument("unknown log_seeds: " + s + " (full|hash|off)"); } struct settings { level threshold = level::info; /// Comma-separated sinks: `stderr`, `syslog`, `file:PATH`, or `none`. /// One file at most; it is opened for append, so parties may share it. std::string sinks = "stderr"; seed_policy seeds = seed_policy::full; /// syslog identity (facility `LOG_USER`). std::string ident = "libdpf"; }; namespace detail { inline std::atomic threshold{0}; inline std::atomic seeds{0}; struct sinks_state { std::mutex mu; bool to_stderr = false; bool to_syslog = false; int fd = -1; std::string path; std::string ident; std::set said; sinks_state() = default; sinks_state(const sinks_state &) = delete; sinks_state & operator=(const sinks_state &) = delete; ~sinks_state() { threshold.store(0, std::memory_order_relaxed); if (fd >= 0) ::close(fd); #if DPF_LOG_HAS_SYSLOG if (to_syslog) ::closelog(); #endif } }; inline sinks_state & sinks() { static sinks_state s; return s; } inline thread_local std::string role_tls; inline long kernel_tid() noexcept { #if defined(__linux__) && defined(SYS_gettid) static thread_local const long tid = static_cast(::syscall(SYS_gettid)); return tid; #else return static_cast( std::hash{}(std::this_thread::get_id()) & 0x7fffffffu); #endif } /// @brief `YYYY-MM-DDTHH:MM:SS.uuuuuuZ` for `tp`. inline std::string utc_text(std::chrono::system_clock::time_point tp) { const auto us = std::chrono::duration_cast( tp.time_since_epoch()).count(); const std::time_t secs = static_cast(us / 1000000); const auto frac = static_cast((us % 1000000 + 1000000) % 1000000); std::tm tm{}; ::gmtime_r(&secs, &tm); char buf[96]; std::snprintf(buf, sizeof(buf), "%04d-%02d-%02dT%02d:%02d:%02d.%06uZ", tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, frac); return buf; } inline void append_value(std::string & out, const char * p, std::size_t n) { bool plain = n != 0; for (std::size_t i = 0; i < n && plain; ++i) { const auto c = static_cast(p[i]); plain = c > 0x20 && c < 0x7f && c != '"' && c != '=' && c != '\\'; } if (plain) { out.append(p, n); return; } out += '"'; for (std::size_t i = 0; i < n; ++i) { const auto c = static_cast(p[i]); switch (c) { case '"': out += "\\\""; break; case '\\': out += "\\\\"; break; case '\n': out += "\\n"; break; case '\r': out += "\\r"; break; case '\t': out += "\\t"; break; default: if (c < 0x20 || c == 0x7f) { char esc[5]; std::snprintf(esc, sizeof(esc), "\\x%02x", c); out += esc; } else out += static_cast(c); } } out += '"'; } inline void append_hex(std::string & out, const std::uint8_t * p, std::size_t n) { static const char digits[] = "0123456789abcdef"; for (std::size_t i = 0; i < n; ++i) { out += digits[p[i] >> 4]; out += digits[p[i] & 0x0f]; } } /// @brief SHA-256 of `label || data` (FIPS 180-4), for seed fingerprints. inline std::array sha256(const char * label, const std::uint8_t * data, std::size_t n) { static constexpr std::uint32_t k[64] = { 0x428a2f98u, 0x71374491u, 0xb5c0fbcfu, 0xe9b5dba5u, 0x3956c25bu, 0x59f111f1u, 0x923f82a4u, 0xab1c5ed5u, 0xd807aa98u, 0x12835b01u, 0x243185beu, 0x550c7dc3u, 0x72be5d74u, 0x80deb1feu, 0x9bdc06a7u, 0xc19bf174u, 0xe49b69c1u, 0xefbe4786u, 0x0fc19dc6u, 0x240ca1ccu, 0x2de92c6fu, 0x4a7484aau, 0x5cb0a9dcu, 0x76f988dau, 0x983e5152u, 0xa831c66du, 0xb00327c8u, 0xbf597fc7u, 0xc6e00bf3u, 0xd5a79147u, 0x06ca6351u, 0x14292967u, 0x27b70a85u, 0x2e1b2138u, 0x4d2c6dfcu, 0x53380d13u, 0x650a7354u, 0x766a0abbu, 0x81c2c92eu, 0x92722c85u, 0xa2bfe8a1u, 0xa81a664bu, 0xc24b8b70u, 0xc76c51a3u, 0xd192e819u, 0xd6990624u, 0xf40e3585u, 0x106aa070u, 0x19a4c116u, 0x1e376c08u, 0x2748774cu, 0x34b0bcb5u, 0x391c0cb3u, 0x4ed8aa4au, 0x5b9cca4fu, 0x682e6ff3u, 0x748f82eeu, 0x78a5636fu, 0x84c87814u, 0x8cc70208u, 0x90befffau, 0xa4506cebu, 0xbef9a3f7u, 0xc67178f2u}; std::uint32_t h[8] = {0x6a09e667u, 0xbb67ae85u, 0x3c6ef372u, 0xa54ff53au, 0x510e527fu, 0x9b05688cu, 0x1f83d9abu, 0x5be0cd19u}; std::string m(label == nullptr ? "" : label); m.append(reinterpret_cast(data), n); const std::uint64_t bits = static_cast(m.size()) * 8u; m += static_cast(0x80); while (m.size() % 64 != 56) m += '\0'; for (int i = 7; i >= 0; --i) m += static_cast((bits >> (8 * i)) & 0xffu); auto rotr = [](std::uint32_t x, int r) { return (x >> r) | (x << (32 - r)); }; for (std::size_t off = 0; off < m.size(); off += 64) { std::uint32_t w[64]; for (int i = 0; i < 16; ++i) { const auto * b = reinterpret_cast(m.data() + off + 4 * i); w[i] = (static_cast(b[0]) << 24) | (static_cast(b[1]) << 16) | (static_cast(b[2]) << 8) | static_cast(b[3]); } for (int i = 16; i < 64; ++i) { const std::uint32_t s0 = rotr(w[i - 15], 7) ^ rotr(w[i - 15], 18) ^ (w[i - 15] >> 3); const std::uint32_t s1 = rotr(w[i - 2], 17) ^ rotr(w[i - 2], 19) ^ (w[i - 2] >> 10); w[i] = w[i - 16] + s0 + w[i - 7] + s1; } std::uint32_t a = h[0], b = h[1], c = h[2], d = h[3]; std::uint32_t e = h[4], f = h[5], g = h[6], hh = h[7]; for (int i = 0; i < 64; ++i) { const std::uint32_t s1 = rotr(e, 6) ^ rotr(e, 11) ^ rotr(e, 25); const std::uint32_t ch = (e & f) ^ (~e & g); const std::uint32_t t1 = hh + s1 + ch + k[i] + w[i]; const std::uint32_t s0 = rotr(a, 2) ^ rotr(a, 13) ^ rotr(a, 22); const std::uint32_t mj = (a & b) ^ (a & c) ^ (b & c); const std::uint32_t t2 = s0 + mj; hh = g; g = f; f = e; e = d + t1; d = c; c = b; b = a; a = t1 + t2; } h[0] += a; h[1] += b; h[2] += c; h[3] += d; h[4] += e; h[5] += f; h[6] += g; h[7] += hh; } std::array out{}; for (int i = 0; i < 8; ++i) for (int j = 0; j < 4; ++j) out[static_cast(4 * i + j)] = static_cast((h[i] >> (24 - 8 * j)) & 0xffu); return out; } #if DPF_LOG_HAS_SYSLOG inline int syslog_priority(level l) noexcept { switch (l) { case level::error: return LOG_ERR; case level::warning: return LOG_WARNING; case level::info: return LOG_INFO; default: return LOG_DEBUG; } } #endif inline void write_all(int fd, const char * p, std::size_t n) noexcept { while (n > 0) { const ssize_t r = ::write(fd, p, n); if (r > 0) { p += r; n -= static_cast(r); continue; } if (r < 0 && errno == EINTR) continue; return; } } inline void emit(level l, std::string & line) noexcept { try { line += '\n'; auto & s = sinks(); std::lock_guard lock(s.mu); if (s.to_stderr) write_all(STDERR_FILENO, line.data(), line.size()); if (s.fd >= 0) write_all(s.fd, line.data(), line.size()); #if DPF_LOG_HAS_SYSLOG if (s.to_syslog) ::syslog(syslog_priority(l), "%.*s", static_cast(line.size() - 1), line.data()); #else (void)l; #endif } catch (...) { } } } // namespace detail /// @brief True when records at `l` are written somewhere. inline bool enabled(level l) noexcept { return l != level::silent && static_cast(l) <= detail::threshold.load(std::memory_order_relaxed); } inline seed_policy seeds() noexcept { return static_cast(detail::seeds.load(std::memory_order_relaxed)); } /// @brief Random per-process id stamped on every record (and on CSV rows that /// want to point back at the log). Drawn once from `std::random_device`, /// never from `dpf::uniform_fill`, so it does not perturb seed streams /// or random-byte counts. inline const std::string & invocation_id() { static const std::string id = [] { std::uint64_t v = 0; try { std::random_device rd; v = (static_cast(rd()) << 32) ^ rd(); } catch (...) { v = static_cast( std::chrono::system_clock::now().time_since_epoch().count()) ^ (static_cast(::getpid()) << 40); } std::string out; std::uint8_t b[8]; for (int i = 0; i < 8; ++i) b[i] = static_cast((v >> (56 - 8 * i)) & 0xffu); detail::append_hex(out, b, 8); return out; }(); return id; } /// @brief Apply `cfg`. A bad sink name or unopenable file throws and leaves the /// previous configuration in place. `none` (or no sinks) silences. inline void configure(const settings & cfg) { bool want_stderr = false; bool want_syslog = false; std::string path; std::size_t start = 0; while (start <= cfg.sinks.size()) { const auto comma = cfg.sinks.find(',', start); std::string tok = cfg.sinks.substr(start, comma == std::string::npos ? std::string::npos : comma - start); while (!tok.empty() && tok.front() == ' ') tok.erase(tok.begin()); while (!tok.empty() && tok.back() == ' ') tok.pop_back(); if (tok == "stderr") want_stderr = true; else if (tok == "syslog") want_syslog = true; else if (tok.rfind("file:", 0) == 0 && tok.size() > 5) path = tok.substr(5); else if (!tok.empty() && tok != "none") throw std::invalid_argument("unknown log sink '" + tok + "' (stderr|syslog|file:PATH|none)"); if (comma == std::string::npos) break; start = comma + 1; } #if !DPF_LOG_HAS_SYSLOG if (want_syslog) throw std::invalid_argument("log sink 'syslog' is not available here"); #endif (void)invocation_id(); auto & s = detail::sinks(); std::lock_guard lock(s.mu); int fd = -1; if (!path.empty()) { if (path == s.path && s.fd >= 0) fd = s.fd; else { fd = ::open(path.c_str(), O_WRONLY | O_CREAT | O_APPEND | O_CLOEXEC, 0640); if (fd < 0) throw std::runtime_error("log: cannot open '" + path + "': " + std::strerror(errno)); } } if (s.fd >= 0 && s.fd != fd) ::close(s.fd); s.fd = fd; s.path = path; #if DPF_LOG_HAS_SYSLOG if (s.to_syslog && (!want_syslog || s.ident != cfg.ident)) { ::closelog(); s.to_syslog = false; } if (want_syslog && !s.to_syslog) { s.ident = cfg.ident; ::openlog(s.ident.c_str(), LOG_PID | LOG_NDELAY, LOG_USER); } #endif s.to_syslog = want_syslog; s.to_stderr = want_stderr; detail::seeds.store(static_cast(cfg.seeds), std::memory_order_relaxed); const bool any = want_stderr || want_syslog || fd >= 0; detail::threshold.store(any ? static_cast(cfg.threshold) : 0u, std::memory_order_relaxed); } /// @brief True the first time `key` is seen in this process (for one-shot /// warnings from code that runs per trial or per cell). inline bool first_time(const std::string & key) { auto & s = detail::sinks(); std::lock_guard lock(s.mu); return s.said.insert(key).second; } /// @brief The party role stamped on this thread's records (`p0`, `p1`, `p2`). inline const std::string & role() noexcept { return detail::role_tls; } /// @brief Set this thread's role for the scope's lifetime. class role_scope { public: explicit role_scope(std::string role) : prev_(std::move(detail::role_tls)) { detail::role_tls = std::move(role); } ~role_scope() { detail::role_tls = std::move(prev_); } role_scope(const role_scope &) = delete; role_scope & operator=(const role_scope &) = delete; private: std::string prev_; }; /// @brief One log line. Written when it goes out of scope. class record { public: record(level l, const char * event) : level_(l) { line_.reserve(256); line_ += "ts="; line_ += detail::utc_text(std::chrono::system_clock::now()); line_ += " lvl="; line_ += level_name(l); line_ += " inv="; line_ += invocation_id(); line_ += " pid="; line_ += std::to_string(::getpid()); line_ += " tid="; line_ += std::to_string(detail::kernel_tid()); if (!detail::role_tls.empty()) { line_ += " role="; detail::append_value(line_, detail::role_tls.data(), detail::role_tls.size()); } line_ += " ev="; const char * ev = event == nullptr ? "event" : event; detail::append_value(line_, ev, std::strlen(ev)); } record(const record &) = delete; record & operator=(const record &) = delete; ~record() { detail::emit(level_, line_); } record & kv(const char * key, const std::string & v) { key_(key); detail::append_value(line_, v.data(), v.size()); return *this; } record & kv(const char * key, const char * v) { key_(key); const char * p = v == nullptr ? "" : v; detail::append_value(line_, p, std::strlen(p)); return *this; } record & kv(const char * key, bool v) { key_(key); line_ += v ? '1' : '0'; return *this; } template && !std::is_same_v, int> = 0> record & kv(const char * key, T v) { key_(key); line_ += std::to_string(v); return *this; } template , int> = 0> record & kv(const char * key, T v) { key_(key); char buf[32]; std::snprintf(buf, sizeof(buf), "%.6g", static_cast(v)); line_ += buf; return *this; } record & hex(const char * key, const void * bytes, std::size_t n) { key_(key); if (n == 0 || bytes == nullptr) line_ += "\"\""; else detail::append_hex(line_, static_cast(bytes), n); return *this; } /// @brief Seed bytes under the configured `seed_policy`. record & seed(const char * key, const void * bytes, std::size_t n) { switch (seeds()) { case seed_policy::full: return hex(key, bytes, n); case seed_policy::hash: { const auto d = detail::sha256("libdpf seed fingerprint", static_cast(bytes), bytes == nullptr ? 0 : n); key_(key); line_ += "sha256:"; detail::append_hex(line_, d.data(), 8); return *this; } case seed_policy::off: break; } key_(key); line_ += "withheld"; return *this; } private: void key_(const char * key) { line_ += ' '; line_ += key == nullptr ? "field" : key; line_ += '='; } level level_; std::string line_; }; } // namespace log } // namespace dpf /// @brief `DPF_LOG(info, "event").kv("key", value)`: the record and its /// arguments are only evaluated when `info` is enabled. The single-pass /// `for` has no `else` to pair with an enclosing unbraced `if`. #define DPF_LOG(LEVEL, EVENT) \ for (bool dpf_log_on_ = ::dpf::log::enabled(::dpf::log::level::LEVEL); \ dpf_log_on_; dpf_log_on_ = false) \ ::dpf::log::record(::dpf::log::level::LEVEL, EVENT) #endif // LIBDPF_INCLUDE_DPF_LOG_HPP__