Include severity in certain logs

Feature Requests Partially-implemented
1

Would it be possible to format the FTL messages (pihole-FTL.log) more like syslog messages

for example,
unbound:

May 03 06:23:11 unbound[755:3] info: query response was ANSWER
May 03 06:23:11 unbound[755:3] error: read (in tcp s): Connection reset by peer for 2a00:13f0:0:3::aaaa port 53

all message starts with unbound and contain info, warning or error

dnsmasq (pihole log):

May  3 10:33:16 dnsmasq[30445]: 2790 127.0.0.1/45935 query[A] smtp.gmail.com from 127.0.0.1
May  3 10:33:16 dnsmasq[30445]: 2790 127.0.0.1/45935 forwarded smtp.gmail.com to fdaa:bbcc:ddee:2::5552
May  3 10:33:16 dnsmasq[30445]: 2791 127.0.0.1/45935 query[AAAA] smtp.gmail.com from 127.0.0.1
May  3 10:33:16 dnsmasq[30445]: 2791 127.0.0.1/45935 forwarded smtp.gmail.com to fdaa:bbcc:ddee:2::5552

all message starts with dnsmasq

unfortunately, the FTL log doesn't use that message format, making it difficult to write filters for rsyslog.

example for unbound, a filter I'm using in a custom rsyslog configuration, this to monitor the unbound log, sending mail and event to remote syslog server:

if $syslogfacility-text == 'local1' and $msg startswith 'unbound'  and ($msg contains_i 'error' or $msg contains_i 'warning') then {

because FTL doesn't use the syslog format (no name, only sometimes error), I'm currently forced to use an alternative method (facility local7) to capture events, not even sure it captures them all.
the FTL filter

if $syslogfacility-text == 'local7' and ($msg contains_i 'error' or $msg contains_i 'warning') then {

does capture an error like

2021-05-03 09:48:03.313 30445/T30449] REGEX WARNING: Invalid regex blacklist filter "(\.|^fathomdns\.com$": Missing ')'

however, other events may evade the filter, because the criteria aren't correct...

Thanks for your time and effort.

3

Possible? I guess... Likely? Not very. That would be basically rewriting the entire logging facility of dnsmasq. Better chance of getting Simon to do that really.

Though I'm not sure how redoing the logs has a bearing on this Feature Request?

4

That is surely NOT what I'm asking. I'm only asking for messages logged in pihole-FTL.log to start with FTL: [info|notice|warning|error]. If this is part of the message, the logging facilty doesn't need to be modified.
so

[2021-05-04 07:00:01.447 30445/T30449] Notice: Database size is 7.68 MB, deleted 46 rows
[2021-05-04 07:54:02.753 30445M] Received: Real-time signal 4 (38 -> 4)
[2021-05-04 07:54:05.826 30445M] Received: Real-time signal 3 (37 -> 3)

would be like

[2021-05-04 07:00:01.447 30445/T30449] FTL: Notice: Database size is 7.68 MB, deleted 46 rows
[2021-05-04 07:54:02.753 30445M] FTL: info: Received: Real-time signal 4 (38 -> 4)
[2021-05-04 07:54:05.826 30445M] FTL: info: Received: Real-time signal 3 (37 -> 3)

The prefix dnsmasq[30445] (example from pihole.log) doesn't appear to be coming from (embedded in) the logging facility, otherwise, it would also appear in all messages in the FTL log. I assume it's pointless to ask Simon to change something for features and messages, added to dnsmasq by the developpers...

I'm NOT a developer, thus assuming, I can only ask nice...

The request is about getting (push) notifications, this to avoid having to check the logs line by line in order to detect a possible problem. Using rsyslog does this, rsyslog is part of almost all distros, it's efficient and fast, and (important for the developers) doesn't require any modifications to the pihole code. It only requires the log entries to adhere to some kind of standard, this to write efficient syslog filters.

5

It would seem both unbound as well as dnsmasq would support RFC 5424 syslog messages only if logs aren't redirected to a custom file.

I've never checked this, but if it's syslog messages you are after, maybe you could give this a try.

6

Thank you for your reply and interest in this.

The primary goal of my setup is to get notifications for possible problems (FTL, unbound, OS) without changing anything to pihole.

I can't write any code here, so I'll try to explain what I've been doing.

I'm using rsyslog modules imfile and omprog, With the imfile module, I'm instructing rsyslog to watch the pihole-FTL.log and the unbound.log.
Once this is configured, I than use a filter ('error' or 'warning') to instruct rsyslog, using an 'action' to process and write only the messages, matching the criteria of the filter to a new (temporary) file, which ideally, doesn't contain any messages (everything healthy).
The second action, executed on filter match is an omprog action, simply executing a script that reads the line, entered as a result of the first action, and takes an appropriate action, e.g. send a mail and/or forward (uses nc) the message to a separate syslog server, running on an old android tablet. The android tablet only shows the syslog messages, that match the filter conditions (ideally none). This allows me to take action on important messages, but doesn't require me to go over all the logs (system, unbound, FTL).

It works, I accidently entered an incorrect regex (blacklist) and immediately got notified, despite the fact the pihole web interface indicated everything was ok.

Why am I requesting a change to the format of the log entries? The hard part of the setup is to construct a filter that matches everything I want, not ignoring important messages and not forwarding unnecessary messages. Most examples, see here, suggest to use both the syslogfacility value and the device name, e.g.

if $syslogfacility-text == 'local0' and $msg startswith 'DEVNAME' and ...

Unfortunately, the FTL log doesn't provide this (NAME and severity) in the message, hence the request for FTL: [info|notice|warning|error] as a message prefix.

1 Like
9

What did the pihole-FTL.log show when you tried to compile this regex?

11

The pihole-FTL log showed a regex warning. This is exactly the point of the setup (mail + syslog to android tablet) Nobody is looking at the pihole-FTL.log all of the time, some users might check it regularly, but certainly not after every change in the web interface, at least, I don't...

pihole:[2021-05-02 23:50:37.845 30445/T30449] REGEX WARNING: Invalid regex blacklist filter "(\.|^fathomdns\.com$": Missing ')'

This specific message contains the text 'WARNING', hence triggered the syslog filter and actions. I'm NOT convinced all important messages will contain the text, defined in my rsyslog trigger

Example from the log today, no alert

[2021-05-04 19:46:06.198 30445/T30451] SQLite3 message: database is locked in "SELECT name FROM network_addresses WHERE name IS NOT NULL AND ip = ?;" (5)

no alert for this, possibly important, log entry, I just happened to notice it, because I was looking at the log to write this post.

13

I believe the original Feature Request was for a simple way for the user to select a method of being alerted to conditions. My vision was something like a box on the web interface to enter the notification endpoint.

That simple process is going to take a lot of work and is not something that will happen any time soon.

This is now ballooned to rsyslog, smtp, scripts, cronjobs and writing filters. Suffice it to say that's got even less a priority than the original Feature Request.

Edit: And you don't need to use CAPS and bold text in your responses.

15

Again, not what I'm asking. What I'm asking, as specified in the first entry of this split of feature request is

examples of the requested format in other posts of this request.

Lots of users have some form of customizations for pihole, which are often discussed on reddit. Again, the goal of using rsyslog for this, is to add a method to the system, to notify the users, without changing a single line of pihole code.

16

I guess you need to ask @DL6ER

18

Except for rewriting pihole-FTL you mean.

19

I think if you write a script that parses the FTL log for warnings or errors, you will find them.

20

I tried to hint at the fact that RFC 5424 would already require a syslog message to contain a severity level as part of its priority/PRI field (the first field) (edit: i.e. when sending an RFC 5424 compliant message to syslog).

Since neither unbound's nor dnsmasq's log output seems to comply with that format, I was assuming that this would be attributable to log output being redirected to a custom file instead of being passed to syslog.

But also, you additionally may have to provide an appropriate rsyslog template to output the PRI field in the logs, see Recording the Priority of Syslog Messages.
If you're lucky, adding that template is enough already, and you wouldn't have to switch log facilities for unbound or dnsmasq to uniformly parse your logs.

But as I said, I've personally never checked this.

EDIT:
As a quick test, applying the template from the link and reverting to use dnsmasq's logging default will log lines like the following to/var/log/daemon.log:

daemon.info: May  4 23:47:13 pihole-5 systemd[1]: Started LSB: pihole-FTL daemon.
daemon.info: May  4 23:47:13 pihole-5 dnsmasq[8026]: read /etc/hosts - 5 addresses
daemon.err: May  4 23:47:13 pihole-5 dnsmasq[8026]: failed to load names from /etc/pihole/custom.list: No such file or directory
26

I see a few things that need to be considered here:

  1. Is this a breaking change ?

If any change is non-backwards compatible, this can only be done on a major version jump only. I'm happy to include this in v6.0 but it is not highest priority right now. Even more because @Bucking_Horn found a solution that should work in the use case of @jpgpi250.

  1. How exactly should the new log look like ?

Proposal:

2021-05-03 09:48:03.313 ${processName}[${id}] ${severity}: ${message}
  • ${processName} will typically be be pihole-FTL but may also be lua, dnsmasq, sqlite3 and other applications for which we provide drop-in support
  • ${id} will be the identification string stating the PID, possibly including a TID if the message came from a thread, or an FID if the message came from a fork
  • ${severity} will be one of {DEBUG, INFO, NOTICE, WARNING, ERROR, CRITICAL, ALERT, EMERGENCY}
  • ${message} is quite obvious. we'll have to rephrase a few texts if the severity is moved forward

I think we can go with this for the log file. Or is explicit (direct) syslog compatibility requested? I could also look into this when redesigning the code around here. If we send to syslog directly, we will loose ${id} and have to come up with an alternative to include it (likely add it to the beginning on ${message}).

  1. Is ${severity} always clear?

No. For instance, the SQLite3 database engine has no concept of severity. It can inform us about a locked database which may just be worth a warning, it can also inform us about a corrupted database, etc. I would not want to do string-inspection to decide ourselves what the correct severity is. We first have to come up with a clever solution for this part of the problem.

30

First of all, The request is to format the messages in pihole-FTL.log only, not pihole.log. The pihole.log is almost constantly updated, rsyslog triggers with actions on such a busy file don't work very well, rsyslog actions (omprog) have trouble to keep up with the rate the log entries are added.

When using rsyslogs imfile module, all messages, registered in the log that is monitored, are replicated to both syslog and messages, unless you have a proper filter to stop processing.

example, an unbound message, logged in a logfile (unbound.conf with the setting logfile: /log/unbound.log), thus not controlled by syslog, but rsyslog monitored using imfile looks like this:

May 05 19:13:57 unbound[4456:2] info: resolving a28-67.akam.net. AAAA IN
May 05 19:13:57 unbound[4456:2] info: response for adns1.akam.net. AAAA IN
May 05 05:32:11 unbound[6918:0] info: error sending query to auth server 2001:501:b1f9::30 port 53

unbound clearly tags all messages as info, thus in order to stop further processing, avoiding any actions, despite the word 'error' in the last message, the conf file starts with:

input(type="imfile" File="/etc/unbound/log/unbound.log"
reopenOnTruncate="on"
Tag="unbound:")

if $msg contains 'unbound[' and ($msg contains 'info:' or $msg contains 'notice:' ) then stop

Why like this? The unbound log, configured in unbound.conf (logfile: /log/unbound.log), still contains all messages, even the info messages. This is useful when trying to identify an unbound problem. The rsyslog imfile configuration for the unbound log than stops processing the message, if 'info' or 'notice' is detected, preventing the message to be entered in the syslog and messages logs. Since there is no further processing, action triggers are never executed.

I would suggest to use the unbound format, since a lot of pihole users also run unbound.
Be aware that not all versions of rsyslog (depending on the distro) have the case sensitive option, e.g. use contains_i, to ignore case doesn't always work. Unbound uses all lower case. This document also lists al the severities, you mentioned, in lower case.
The different process names are not a problem, the rsyslog conf file simply needs to provide stop filters for all the processes the user doesn't want to be notified (rsyslog action) about.

Your comments are correct, however:

  • currently the pihole-FTL log cannot be used efficiently (with rsyslog - imfile), because of the lack of any filter options, resulting in the fact that all log entries from pihole-FTL.log, are duplicated in both syslog.log and messages.log
  • looking at my pihole-FTL log today, after 19 hours (logrotation at midnight) the log contains only 122 lines.
  • 14 of these messages already contain Notice (should be notice - lower case).
  • 11 of these messages contain Resizing, this is clearly an info message.
  • 11 messages are the result of sudo service pihole-FTL stop, clearly info.
  • 68 messages are the result of sudo service pihole-FTL start, clearly info.
  • 10 messages containing Real-Time signal
  • 4 messages containing Imported alias-clients
    Very few messages left to write a filter for...

This doesn't mean the request is useless (very few messages under normal conditions). I want to catch the messages that will appear, when something is wrong, for example the incorrect regex warning (or other messages that wouldn't appear normally, for example)

This implies of course that all messages, generated as a result of activating a debug option in pihole-FTL.conf should get debug, this to be able to create an effective stop filter. If a debug option is enabled, the user will be looking at the pihole-FTL log, in search for a problem, probably instructed to do so by a developer.

under normal conditions, I never see any sqlite3 messages in the log. I thus wouldn't add a stop message for sqlite3 messages, because something might be wrong, worth analyzing.

I don't expect the code for dnsmasq and sqlite3 to be modified, I only request the messages you specifically added to pihole-FTL to be modified...

33

I'll check if we can address this during the v6.0 development.

This seems like a random source, do you have any particular reason to pick this (else than maybe "first on my search engine results")?

The relevant man syslog excerpt is:

   Values for level
       This determines the importance of the message.  The levels are, in  or‐
       der of decreasing importance:

       LOG_EMERG      system is unusable

       LOG_ALERT      action must be taken immediately

       LOG_CRIT       critical conditions

       LOG_ERR        error conditions

       LOG_WARNING    warning conditions

       LOG_NOTICE     normal, but significant, condition

       LOG_INFO       informational message

       LOG_DEBUG      debug-level message

       The function setlogmask(3) can be used to restrict logging to specified
       levels only.

My subjective feeling is that it is easier to skim through these texts when they are bold and, hence, have sufficient contrast from the message following it. The mere separating : is not really visible when skimming through lines. It could even be omitted, maybe. We're still discussing here.

35

I don't know what's best for the human eye (when you really have to look at the logs)

May 05 23:25:40 FTL[4456:2] LOG_WARNING: Invalid regex blacklist filter "(\.|^fathomdns\.com$": Missing ')'

(this is definitely unambiguous for an rsyslog filter)
or

May 05 23:25:40 FTL[4456:2] warning: Invalid regex blacklist filter "(\.|^fathomdns\.com$": Missing ')'

(this may cause invalid filtering, if the message contains a word that matches a severity)

I suggested lowercase because unbound uses this standard, and, if you look at the messages in syslog, most of them also use all lowercase If you want to follow the standard to the letter, RFC3164 is what I could find with a quick search

   These are described in the following table along with their numerical
   values.

        Numerical         Severity
          Code

           0       Emergency: system is unusable
           1       Alert: action must be taken immediately
           2       Critical: critical conditions
           3       Error: error conditions
           4       Warning: warning conditions
           5       Notice: normal but significant condition
           6       Informational: informational messages
           7       Debug: debug-level messages

           Table 2. syslog Message Severities

please don't do that, it's very useful to ensure an rsyslog filter makes a correct match.

if $msg contains 'unbound[' and ($msg contains 'info:' or $msg contains 'notice:' ) then stop
36

RFC 3164 - The BSD Syslog Protocol (ietf.org)

Obsoleted by: 5424

RFC 5424 - The Syslog Protocol (ietf.org)

1 Like
41

I made some progress in this direction in 8f40798c (FTL v6.0 development). You can even switch altogether from using the log file to syslog itself by specifying an empty LOGFILE= option in pihole-FTL.conf

For now, there are six new functions by which the existing generic logg() routine needs to be replaced with:

  • log_crit()
  • log_err()
  • log_warn()
  • log_notice()
  • log_info()
  • log_debug()

The output in /var/log/syslog looks like:

May 26 11:47:40 pi.hole pihole-FTL: Imported 227 queries from the long-term database

The same pihole-FTL.log output looks like:

2021-05-26 13:53:15.185 [3778765M] INFO: Imported 227 queries from the long-term database

Thinking again about ${process}: I found it pretty useless to include pihole-FTL everywhere in pihole-FTL.log. It should be clear which daemon is logging here and just wasted space (on screen and disk).

Right now, all log outputs are still of type INFO. I'll have to go over all of the log functions one after another and use the log routine with the correct priority everywhere:
Screenshot from 2021-05-26 13-05-24

This is still entirely open for discussions of any kind (even reversal, of course). But now we have something to play with.

47

On several occasions, You have asked me (and probably other users) to enable one or more of the FTL debug options, this to identify a possible problem / cause.

Glad to do this, but, unlike you, who probably eats several of these logs for breakfast, I find it very hard to get the specific entries that can contribute to a solution.

Therefore, I'm not a fan of logging the FTL entries into syslog, as the other entries (not FTL related) will make it even harder for me to find the entries needed.

When looking at the unbound log, the entries look like this (example):

May 25 23:56:46 unbound[750:1] info: response for grafana.com. AAAA IN

even when logging is setup to a dedicated file.

This makes it very easy to write syslog filters (imfile type) such as:

if $msg contains 'unbound[' and ($msg contains 'info:' or $msg contains 'notice:' ) then stop

The output you suggest, when logging to a dedicated file, does probably make a lot of sense to users, looking at the dedicated log, however the additional info (like in the syslog sample - 'pihole-FTL') makes it a lot easier when using a third party product to analyze / filter the log entries.

I'm happy with any improvement, assuming the severity will eventually be in the messages, but would be in favor of / eternally grateful, if the log entries resemble the entries from, for example unbound', and other products that generate log files.

It is, and stays, your choice, I'll find a workaround, if you choose to keep the current format.