From 92c529d706bd28abf75f96138c66063c12ceef8f Mon Sep 17 00:00:00 2001 From: Otto Moerbeek Date: Fri, 1 Mar 2024 10:56:05 +0100 Subject: [PATCH] rec: add structured logging backend that uses JSON representation --- .github/actions/spell-check/expect.txt | 1 + .../docs/appendices/structuredlogging.rst | 13 ++- pdns/recursordist/rec-main.cc | 85 +++++++++++++++---- pdns/recursordist/settings/table.py | 6 +- 4 files changed, 88 insertions(+), 17 deletions(-) diff --git a/.github/actions/spell-check/expect.txt b/.github/actions/spell-check/expect.txt index addd80d075..0b27c6a3cd 100644 --- a/.github/actions/spell-check/expect.txt +++ b/.github/actions/spell-check/expect.txt @@ -1319,6 +1319,7 @@ Storesund stou strcasestr stringmatch +structuredlogging stubquery stubresolver Stussy diff --git a/pdns/recursordist/docs/appendices/structuredlogging.rst b/pdns/recursordist/docs/appendices/structuredlogging.rst index d48366330b..020ecf6eca 100644 --- a/pdns/recursordist/docs/appendices/structuredlogging.rst +++ b/pdns/recursordist/docs/appendices/structuredlogging.rst @@ -2,10 +2,11 @@ Structured Logging Dictionary ============================= This page describes the common entries of the Structured Logging component. -Currently there are two possible values for :ref:`setting-structured-logging-backend`: +Currently :ref:`setting-structured-logging-backend` can have these values: - The ``default`` text based backend - The ``systemd-journal`` backend +- The ``json`` backend (added in version 5.1.0). The ``default`` backend ----------------------- @@ -100,3 +101,13 @@ To query the log, use a command similar to:: # journalctl -r -n 1 -o json-pretty -u pdns-recursor.service +The ``json`` backend +-------------------- +The ``json`` structured logging backend has been added in version 5.1.0 and uses the same keys and values as the default backend. +And example of a a log object:: + + {"level": "0", "limit": "10765", "msg": "Raised soft limit on number of filedescriptors to match max-mthreads and threads settings", "priority": "4", "subsystem": "config", "tid": "0", "ts": "1709285994.851"} + +All values are represented as strings. + +The JSON log objects are written to the standard error stream. diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc index e652ddb0cc..7b334f0101 100644 --- a/pdns/recursordist/rec-main.cc +++ b/pdns/recursordist/rec-main.cc @@ -40,6 +40,7 @@ #include "logging.hh" #include "dnsseckeeper.hh" #include "settings/cxxsettings.hh" +#include "json.hh" #ifdef NOD_ENABLED #include "nod.hh" @@ -1022,6 +1023,49 @@ static void loggerSDBackend(const Logging::Entry& entry) } #endif +static void loggerJSONBackend(const Logging::Entry& entry) +{ + // First map SL priority to syslog's Urgency + Logger::Urgency urg = entry.d_priority != 0 ? Logger::Urgency(entry.d_priority) : Logger::Info; + if (urg > s_logUrgency) { + // We do not log anything if the Urgency of the message is lower than the requested loglevel. + // Not that lower Urgency means higher number. + return; + } + + std::array timebuf{}; + json11::Json::object json = { + {"msg", entry.message}, + {"level", std::to_string(entry.level)}, + // Thread id filled in by backend, since the SL code does not know about RecursorThreads + // We use the Recursor thread, other threads get id 0. May need to revisit. + {"tid", std::to_string(RecThreadInfo::id())}, + {"ts", toTimestampStringMilli(entry.d_timestamp, timebuf)}, + }; + + if (entry.error) { + json.emplace("error", entry.error.get()); + } + + if (entry.name) { + json.emplace("subsystem", entry.name.get()); + } + + if (entry.d_priority != 0) { + json.emplace("priority", std::to_string(entry.d_priority)); + } + + for (auto const& value : entry.values) { + json.emplace(value.first, value.second); + } + + static thread_local std::string out; + out.clear(); + json11::Json doc(std::move(json)); + doc.dump(out); + cerr << out << endl; +} + static void loggerBackend(const Logging::Entry& entry) { static thread_local std::stringstream buf; @@ -2986,6 +3030,31 @@ static void handleRuntimeDefaults(Logr::log_t log) } } +static void setupLogging(const string& logname) +{ + if (logname == "systemd-journal") { +#ifdef HAVE_SYSTEMD + if (int fileDesc = sd_journal_stream_fd("pdns-recusor", LOG_DEBUG, 0); fileDesc >= 0) { + g_slog = Logging::Logger::create(loggerSDBackend); + close(fileDesc); + } +#endif + if (g_slog == nullptr) { + cerr << "Structured logging to systemd-journal requested but it is not available" << endl; + } + } + else if (logname == "json") { + g_slog = Logging::Logger::create(loggerJSONBackend); + if (g_slog == nullptr) { + cerr << "JSON logging to requested but it is not available" << endl; + } + } + + if (g_slog == nullptr) { + g_slog = Logging::Logger::create(loggerBackend); + } +} + int main(int argc, char** argv) { g_argc = argc; @@ -3056,21 +3125,7 @@ int main(int argc, char** argv) return 99; } - if (s_structured_logger_backend == "systemd-journal") { -#ifdef HAVE_SYSTEMD - if (int fd = sd_journal_stream_fd("pdns-recusor", LOG_DEBUG, 0); fd >= 0) { - g_slog = Logging::Logger::create(loggerSDBackend); - close(fd); - } -#endif - if (g_slog == nullptr) { - cerr << "Structured logging to systemd-journal requested but it is not available" << endl; - } - } - - if (g_slog == nullptr) { - g_slog = Logging::Logger::create(loggerBackend); - } + setupLogging(s_structured_logger_backend); // Missing: a mechanism to call setVerbosity(x) auto startupLog = g_slog->withName("config"); diff --git a/pdns/recursordist/settings/table.py b/pdns/recursordist/settings/table.py index 5028b4c5f4..8f92f630ad 100644 --- a/pdns/recursordist/settings/table.py +++ b/pdns/recursordist/settings/table.py @@ -2670,8 +2670,12 @@ Available backends are: - ``default``: use the traditional logging system to output structured logging information. - ``systemd-journal``: use systemd-journal. When using this backend, provide ``-o verbose`` or simular output option to ``journalctl`` to view the full information. +- ``json``: JSON objects are written to the standard error stream + +See :doc:`appendices/structuredlogging` for more details. ''', - 'versionadded': '4.8.0' + 'versionadded': '4.8.0', + 'versionchanged': ('5.1.0', 'The JSON backend was added') }, { 'name' : 'tcp_fast_open', -- 2.47.2