Include severity in certain logs

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.

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.

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.

I guess you need to ask @DL6ER

Except for rewriting pihole-FTL you mean.

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

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

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.

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...

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.

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

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

Obsoleted by: 5424

RFC 5424 - The Syslog Protocol (ietf.org)

1 Like

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.

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.

Sure, writing directly into syslog is only meant for those who don't want a log file. This has neither been possible so far nor will it become the default. I perfectly agree any debugging isn't meant to happen in this place.

I'm not sure I understand what you are doing exactly. You don't want to log directly into syslog but into the log file. Then you import this file into syslog? You set the tag in this case, like:

so I don't see the need for a pihole-FTL string in the pihole-FTL.log file as you specify the tag here.

Also,

is something I don't really understand because you still know from which file you are reading.

I checked but didn't find any other products having specific log files themselves (I checked apt, cups, mosquitto, and lighttpd on my local Pi-hole) mentioning which process is logging here. Why should they? Better not to create double content where users are mislead into using this - instead of a proper selector like the file you are reading from.

OK, I can live with that, maybe unbound is overdoing it...

I don't import the file (message) in syslog. What I'm doing is:

  • use imfile to instruct syslog to watch a log (that log, for example unbound.log contains all messages).
  • if the message contains error or warning, I use a syslog action to write the message to a separate file, this new file will thus only contain error and warning messages.
  • I use fswatch to monitor that new file (fswatch monitors all files in the target directory), as soon as the file changes, a script is triggered by fswatch, that reads the new message(s) and sends (socat) the message to a syslog server, running on an android tablet.

Not as good as push notifications, but the syslog screen on the tablet is always on, so I'm immediately notified if an error or warning occurs. This already helped me resolve some issues I never noticed before, example, SURICATA rules reload triggered unbound to restart. It isn't always beneficial (gpgconf)...

Why don't you use (push) mail notification?

If something goes horribly wrong (I had this a few times), you get a few hundred mails. Tried it, not funny... The script I now use ensures this doesn't happen (consolidated mail if the syslog server isn't reachable - that's why I use socat, as opposed to nc, nc isn't always able to detect if the remote port is available).
Also tried omprog, this syslog feature doesn't always work (lots of omprog errors in the syslog).

This topic was automatically closed 180 days after the last reply. New replies are no longer allowed.