This is the fourth part of a series of blog posts we are publishing, mostly around recent developments with respect to PowerDNS Recursor. The first blog post was Refreshing Of Almost Expired Records: Keeping The Cache Hot, the second Probing DoT Support of Authoritative Servers: Just Try It and the third Sharing data between threads in PowerDNS Recursor.
Complex programs like PowerDNS Recursor need to log information about their operation. In itself this is a delicate balance: too much logging will slow the process down, too little will make it harder to diagnose issues. The question “what and how to log” is also important: up until now we have used free-format text logging. The messages itself can go to a logging daemon (e.g. systemd-journald or syslogd), a text file or the console.
The problem with free text logging is that is it very hard to keep it consistent and hard to process automatically in a reliable way. It is also not always clear (unless the creator of the message is very careful) what information is actually logged and quoting of special values is often problematic. A typical example of a free format log message looks like this (set quiet=no when running Recursor to see these detailed messages, this is not recommended in a production environment as it generates an awful lot of messages):
3 [1/1] question for 'www.powerdns.com|A' from 127.0.0.1:53408To illustrate, unless you are very familiar with the PowerDNS code base it is unclear what the 3 1/1 part means. These are: the Posix thread-id, the mthread-id (mthreads are the user level threads used by PowerDNS Recursor) and the number of queries being resolved concurrently. Observe that automated log analysis will probably fail if the name queried contains characters like a quote or vertical bar.
Structured Logging
A structured log message consists of a set of key-value pairs. The pairs can be exported in various formats, one of them being text lines. In the text representation, a message like the one above would look like:
msg="Question" subsystem="syncres" level="0" prio="Info" tid="3" ts="1664192640.282" ecs="" mtid="1" proto="udp" qname="www.powerdns.com" qtype="A" remote="127.0.0.1:63684"Note that each value is labelled. That is a good start to make sure we know what each part means.
There are several keys that are common to each structured log entry. These are:
msga short text message indicating the subject of the message instance. This part is fixed to allow for easily selection by log analysis tools.subsystemthe component which generated the messagelevelthe detail levelpriothe prioritytidthe Posix thread-idtsa timestampmtidthe mthread-id
The message instance specific parts are ecs, proto, qname, qtype and remote.
The timestamp is produced by Recursor itself, which means that it is not dependent in the system used to export the log messages The structured message also adds extra information left out in the original (e.g. proto), and leaves out one item, as it was deemed to be non-relevant (the number of concurrent queries being processed).
The level value indicates the amount of detail. Higher levels indicated very detailed information, only relevant when developing or when doing very deep analysis of logs. Priority indicates if action by the administrator is required and is the same as the priority value used by e.g. syslog.
From an implementation point of view, the code that implements structured logging has a big advantage that information associated with several related log lines only has to be set up once, each generated log line will share the common information. The existing logging code would need to repeat that information with each generated log line. The structured logging code also has methods to log specific value types, like internet addresses, making sure they are always logged in the same manner.
Text format and key-value format
By default, PowerDNS Recursor sends its structured information as a formatted text string containing key-value pairs with proper quoting and escaping of quotes. On Linux system using systemd, it can also send information to systemd-journald as structured log entries. In this case systemd-journald stores the entry as a sequence of key-value pairs in a log database.
To use this logging backend, add the --structured-logging-backend=systemd-journal to the command line in the systemd unit file. Note that adding it to the recursor configuration file does not work as expected, as this file is processed after the logging has been set up.
To query the log, use a command similar to
# journalctl -r -n 1 -o json-pretty -u pdns-recursor.service {
"_SYSTEMD_INVOCATION_ID" : "568cd5479a5f4ea29e3c793939cd31f6",
"REMOTE" : "127.0.0.1:40908",
"PRIORITY" : "6",
"_UID" : "107",
"ECS" : "",
"_SYSTEMD_UNIT" : "pdns-recursor.service",
"__CURSOR" : "s=3e46e7865e524e19bada5d3e56e08b69;i=100129;b=8a57b91cdb5346559d48
2f5fae75bd92;m=b09c7370;t=5e99425342dfd;x=d050d34430fdca60",
"QNAME" : "www.powerdns.com",
"__MONOTONIC_TIMESTAMP" : "2963043184",
"_CAP_EFFECTIVE" : "0",
"_HOSTNAME" : "pepper",
"_COMM" : "pdns_recursor",
"_GID" : "114",
"_MACHINE_ID" : "8b32d617439149049d62119e02e2fa10",
"_SYSTEMD_CGROUP" : "/system.slice/pdns-recursor.service",
"MTID" : "1",
"_BOOT_ID" : "8a57b91cdb5346559d482f5fae75bd92",
"SUBSYSTEM" : "syncres",
"TID" : "2",
"_EXE" : "/usr/sbin/pdns_recursor",
"_PID" : "23684",
"QTYPE" : "A",
"MESSAGE" : "Question",
"LEVEL" : "0",
"_SOURCE_REALTIME_TIMESTAMP" : "1664197372161506",
"__REALTIME_TIMESTAMP" : "1664197372161533",
"_CMDLINE" : "/usr/sbin/pdns_recursor --daemon=no --write-pid=no --disable-syslo
g --log-timestamp=no --structured-logging-backend=systemd-journal",
"TIMESTAMP" : "1664197372.161",
"PROTO" : "udp",
"_SYSTEMD_SLICE" : "system.slice",
"_TRANSPORT" : "journal",
"_SELINUX_CONTEXT" : "unconfined\n",
"SYSLOG_IDENTIFIER" : "pdns_recursor"
}As can be seen, systemd-journald adds quite a bit of extra key-value pairs and capitalises the keys. A drawback is that the information in this form is hard to parse for humans, but programs that are used for log analysis process JSON easily.
The future
In the future we will add more logging backends, to make it easy to send the structured logging information to a program used to process logs.
Note that trace information (the very detailed information on each step of the resolving process collected when debugging specific query processing using rec_control trace-regex) is not converted to structured format yet. This will be done in the near future, together with functionality to send trace logs to a specific destination for further analysis. Until then trace logs will end up in the general log, as they do now.
Reverting to old-style logging
If you already have log analysis in place, the changing of the logging information might disrupt your log processing. Switch back to tradition logging by setting structured-logging to no. New functionality requiring logging will implement structured logging only. When structured-logging is set to no, these new subsystems will output a textual representation of the key-value pairs.
Status and Conclusion
The structured logging system has been used by a few subsystems already in recent releases. The full conversion will appear in version 4.8.0, to be released in the near future. Pre-releases already allow you to see structured logging in action. With structured logging, log analysis of PowerDNS Recursor will become more easy, as the information is structured in a uniform way.