Filtering logd in OpenWRT

So I’ve been running into an odd problem with log spam in my ring buffer log, and just kludged together a solution when I couldn’t find one elsewhere. I use nft-qos on my main OpenWRT router, and some days it spams my logs like crazy with lines that look like this:

Aug 22 04:15:11 hexenbiest nft-qos-monitor: ACTION=update, MACADDR=a8:86:dd:ac:73:ad, IPADDR=192.168.1.191, HOSTNAME=
Aug 22 04:15:12 hexenbiest nft-qos-dynamic: ACTION=update, MACADDR=a8:86:dd:ac:73:ad, IPADDR=192.168.1.191, HOSTNAME=
Aug 22 04:26:46 hexenbiest nft-qos-monitor: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:26:47 hexenbiest nft-qos-dynamic: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:26:50 hexenbiest nft-qos-monitor: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:26:50 hexenbiest nft-qos-dynamic: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:26:59 hexenbiest nft-qos-monitor: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:26:59 hexenbiest nft-qos-dynamic: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:27:15 hexenbiest nft-qos-monitor: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick
Aug 22 04:27:15 hexenbiest nft-qos-dynamic: ACTION=update, MACADDR=a4:08:01:3c:9e:bb, IPADDR=192.168.1.207, HOSTNAME=FireStick

That’s just a sampling – it’s not just the one device, more often it will spit out a list of every device on the network. Sometimes it does that multiple times per minute. Other times, it’ll go days and never do it once. I don’t have time to track down why nft-qos is logging this, or figure out how to turn it off, but I did have good luck with this kludge to filter it out.

Most people won’t need to filter this unless you’re using your logs for something else. I send my logs to an rsyslog server in my LAN and filter it there, so this isn’t an issue in my long term logs – only in the ring buffer copy that stays on the router itself. So why does it matter? I have a script that runs once a minute to count missed pings from mwan3 and update a conky dashboard on one of my monitoring servers, and it’s much more efficient if I have it parse the ring buffer, instead of asking the rsyslog server across the network once a minute for the whole day’s log!

In hunting around, I’ve seen a dozen or so people asking how to filter logs on OpenWRT, and the answer is universally to either implement rsyslog on the router, or send it to an external syslog server. My case is obviously a corner case, but it’s one that’s obviously come up enough that other people have asked, and I’ve never seen a solution that actually works with logd and logger on the box itself without an external server.

So I made one. And it turned out to be ridiculously simple. It’s also very easy for you to modify to filter out anything else you need to as well.

The Fix, without further ado

What you need to know: logger on OpenWRT isn’t a real program. Entering “type logger” in your shell will point to /usr/bin/logger, but that’s not a real file, just another link to /bin/busybox. When you type

logger -t testlog "Some test message"

into your terminal on OpenWRT, it just gets redirected into

/bin/busybox logger -t testlog "Some test message"

and busybox does the work. Filtering the log input is as simple as moving the link at /usr/bin/logger out of the way, and creating the following new ash script at /usr/bin/logger:

#!/bin/ash
# We are going to filter input to logger by intercepting it.

# Parse options if they're there, else use defaults.
STDERR=1
TAG=$USER
PRIO=0

while getopts st:p: flag ; do
        case "${flag}" in
                s) STDERR=0 ;;
                t) TAG=${OPTARG} ;;
                p) PRIO=${OPTARG} ;;
                *) exit 1 ;;
        esac
done

shift $((OPTIND -1))

# now filter the input string and exit early if we pick up a filtered string.

# Message filters (chain more if needed):
FILTERED=`echo "$*" | grep -v 'ACTION=update,'`

# Exit trigger lines (add more if needed):
[ -z "$FILTERED" ] && exit 0

# We have a good filtered string. Send it to the real logger.

if [ $STDERR -eq 1 ] ; then
        echo "$FILTERED" | /bin/busybox logger -t $TAG -p $PRIO
else
        echo "$FILTERED" | /bin/busybox logger -s -t $TAG -p $PRIO
fi

Now, here’s what that script does:

  • Parse any flags on the input using getopts. Busybox logger only accepts the three flags shown, so this is fairly simple. We’re setting defaults for all three, and then if a flag is actually given, replacing the defaults with what was given.
  • Shift the input over by the number of flags and flag parameters, leaving only the log message.
  • Using grep -v (think “grep inverse”) to filter according to the message content. This FILTERED line is either going to return exactly what you give it unchanged, or nothing at all if it matches your filter. It’s easy to add more filters here if needed, more info below.
  • Checking to see if the message has been filtered out (the code “[ -z “$FILTERED” ]” just returns success if the string you feed it is zero length) and exiting the script if so, basically discarding this log entry. This line is important to remember later if you want to filter on things like tags or priority, so remember it as an “exit trigger line.”
  • Finally, passing the message to the REAL logger facility, using either the default flag values or the values given in the input. The syslog flag is a true or false, and in doing this quickly I found it easiest to just split that using an if statement.

Modifying the script for your own purposes

Want to know how to modify this to make it your own, but not a bash scripting guru? It’s pretty simple, so I’ll give you the framework for the most common changes.

Changing it to filter based on different text is the easiest – just change what’s in the single quotes on the filter line. If you wanted to filter out messages where the content is “foobar” for example:

FILTERED=`echo "$*" | grep -v 'foobar'`

Changing it to filter multiple different things is also fairly easy. You just need to duplicate the filter line, and change any lines after the first to work with the output of the line before it instead of $*. You can chain together however many you want, at the end FILTERED is either going to contain your original input or just be a zero length “” string if a filter matched. If we wanted my original filter plus foo and bar:

FILTERED=`echo "$*" | grep -v 'ACTION=update,'`
FILTERED=`echo "$FILTERED" | grep -v 'foo'`
FILTERED=`echo "$FILTERED" | grep -v 'bar'`

You can change it to match anything in the message this way. One note, grep as it’s called there is also case sensitive, and all the other usual caveats around that kind of thing still apply – but overall, it’s easy to tweak these message filters any way you want.

What about filtering based on a whole tag? What if you want to filter out all log entries with the tag “testlog”? Now, instead of modifying the filter string, you need to modify the exit trigger line (if you only want to filter on the tag, not the message) or add additional exit trigger lines if you want to filter on both message and tags.

Example, filtering on one or more messages as well as tag “testlog”:

[ -z "$FILTERED" ] && exit 0
[ "$TAG" = "testlog" ] && exit 0

You can add as many exit triggers as you need – matching any one of them will cause the message to be discarded. What if you also want to filter by message priority, discarding any message with priority lower than (number higher than) 5? This is a functionality that’s been broken in OpenWRT since 2013, but it turns out it’s also trivial to fix by adding an exit trigger line:

[ -z "$FILTERED" ] && exit 0
[ "$TAG" = "testlog" ] && exit 0
[ "$TAG" = "foobar" ] && exit 0
[ "$PRIO" -gt 5 ] && exit 0

That one filters one one or more messages, plus two tags and priority. As you can see, you really can easily tweak this to do whatever you want.

In short, log filtering has been broken ever since the switch to logd, and it turns out it was always trivial to implement and no one has bothered. I’ve kludged it myself, but I don’t have the time to go implement a real replacement in the original source either – I wish I did! If you do, please feel free to take this framework and run with it. It would be almost as easy to add reading of filter settings from uci into this script so that we could actually make settings in /etc/config/system like conloglevel functional again. You could trivially include lots of message filter strings in /etc/config/system, and have the script loop through them instead of hard coding it like my examples above. Really, this is a trivial framework for fixing OpenWRT’s long-broken log filtering, and all it needs is someone with time and willingness to run with it.

But meanwhile, since you’re probably like me and just looking for a quick way to fix this – here you go, tweak as you see fit and enjoy your spam-free ring buffer logs!