Project

General

Profile

Actions

Feature #1938

closed

Filter messages broken into multiple syslog messages

Added by Ted Lum about 13 years ago. Updated over 10 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
Logging
Target version:
Start date:
10/07/2011
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
Release Notes:

Description

The filter messages are being fragmented into multiple syslog message making filter log parsing difficult and unreliable.

BACKGROUND:
pf logs to a binary file. tcpdump is used to parse the binary into text log output. The tcpdump output is then sent to syslog. tcpdump likes to do some basic message formatting by adding new lines to its output. New lines in text sent to syslog causes syslog to fragment the message into multiple frames. Once fragmented, syslog messages do not necessarily arrive in order making reassembly of the multiple message fragments difficult and unreliable since there is no way to know what fragment goes with what message and in what order.

PROPOSED SOLUTION:
Strip new line characters from tcpdump output before presenting messages to syslog.

PATCH:

/etc/inc/filter.inc

Line 129, change

mwexec_bg("/usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0 | logger -t pf -p local0.info");
to
mwexec_bg("/usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0 | /usr/bin/sed -e 'N;s/\\n //;P;D;' | logger -t pf -p local0.info");
Actions #1

Updated by Chris Buechler about 13 years ago

  • Tracker changed from Bug to Feature
  • Status changed from New to Feedback

this is the default logging format and not sure it should be changed, leaving as feedback for thoughts from others. Maybe an option to change it

Actions #2

Updated by Ermal Luçi about 13 years ago

Probably some daemon should be done that reads this and does not complain much.
Does not seem hard to merge the tcpdump print code into pflogd and remove this issue and the performance problems you get from it.

Mostly 2-3 hours of work for someone wanting to put in place this.
It would help also with pfSense parsing since it can be customized to better fit into pfSense.

Actions #3

Updated by Ted Lum about 13 years ago

I don't know that I would call returning to the original functionality a "feature", this is a "bug" that broke the syslog feature. I don't know that I would call this the default logging format, when it comes to syslog there is an implicit one event = one message, and this change in v2 NOW violates that. I would call it tcpdump's NEW default output format screwing up syslog messages because the two are now incompatible. tcpdump NOW writes a single multi-line message and that's fine, but, syslog is incapable of handling it as a single mulit-line message and breaks all the line breaks into separate syslog messages. Maybe its more appropriate to escape the characters that syslog can't handle so that the tcpdump message at least has a placeholder, but the current implementation is broken. With this NEW behavior it is pointless to do syslog logging at all... the number of syslog messages are now more than double and its not possible to reassemble the out-of-sequence fragments. This is actually a breaking change from v1. More specifically the DShield firewall log parser was broken by this change in v2 and I don't see a way to fix it without first fixing the BUG in pfSense syslog output, which I've already done locally just to get the broken bits functioning again. Anyone that does syslog parsing and processing will have similar concerns with this BUG.

Actions #4

Updated by Jim Pingle about 13 years ago

A warning to those trying the proposed change, it doesn't quite work as written. It works if you run it from the command line but not when run from PHP. Sed needs the \n to be \n, but it's getting escaped somewhere along the way to \\n and breaks.

Actions #5

Updated by Ted Lum about 13 years ago

Wow, that's troubling. I escaped it because it looked like PHP was swallowing the backslash. But I'm looking now and see it made it through to the process:

PID  TT  STAT      TIME COMMAND
24058 v0- I 0:08.52 /usr/bin/sed -e N;s/\\n //;P;D;

and yet its been working fine here since I wrote this article. Wish I knew why we're getting different results. I need to look a little closer at it.

Actions #6

Updated by Francis Turner almost 13 years ago

I'm having this exact problem with Dshield log parsing and I'm also having Jim P's issue with getting the sed line to work.

Havis tried the original, I then tried changing quotes from " to ' and thus doing

mwexec_bg('/usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0 | /usr/bin/sed -e \'N;s/\n //;P;D;\' | logger -t pf -p local0.info')

but that too adds a \ before the \n so that ps ax gives
 /usr/bin/sed -e 'N;s/\\n //;P;D;'

This is very odd. The only thing I can think of is that something inside php is helpfully doing a search/replace for "\n"s

This is also a major irritation as it utterly borks log parsing/analysis without manually putting each line back together in the parse code. And that is not exactly simple.

Actions #7

Updated by Francis Turner almost 13 years ago

Correction. The ' version does seem to work even though ps ax shows the \\n. It seems that the other version did too but I was too fast to assume that it wasn't logging anything.

If you save the following code as a php script (e.g. chgfilter.php) and scp it to the pfsense home directory (/root/) you can create a new and a backup filter.inc in that directory.

$filter=file_get_contents ('/etc/inc/filter.inc');
$filternew =
    str_replace(
        "-ttt -i pflog0 | logger -t pf -p local0.info",
        "-ttt -i pflog0 | /usr/bin/sed -e 'N;s/\\\\n //;P;D;' | logger -t pf -p local0.info",
        $filter);
if (strcmp($filter, $filternew) !=0) {
    file_put_contents('filter.inc.new',$filternew);
    file_put_contents('filter.inc.org',$filter);
}


Run it with a
php chgfilter.php

You can then
mv filter.inc.new /etc/inc/filter.inc

to copy the updated version back over the real file. Unfortunately it looks like you need to reboot the device to get the new script to take - simply doing 'Status/Filter Reload' from the webConfigurator was not sufficient.

Note the script only makes a change if the replacement is successful so this will not hurt anything if run multiple times. Also if it goes wrong you can copy the original back by

mv filter.inc.org /etc/inc/filter.inc

Actions #8

Updated by Jim Pingle almost 13 years ago

  • Status changed from Feedback to New
  • Affected Version deleted (2.0)
Actions #9

Updated by Andre LaBranche over 12 years ago

sed should get the -l switch to make output line buffered. Otherwise the filter log will only get updates when several log lines are pending, instead of in real time.

Actions #10

Updated by Ted Lum almost 11 years ago

The workaround for this bug has changed in version 2.1. The affected section has been slightly rewritten so the position details above are no longer valid, and the php script no longer works.

You'd now change this
mwexec_bg("/usr/sbin/{$tcpdump_cmd} | logger -t pf -p local0.info");

to this
mwexec_bg("/usr/sbin/{$tcpdump_cmd} | /usr/bin/sed -e 'N;s/\\n //;P;D;' | logger -t pf -p local0.info");

Actions #11

Updated by Jim Pingle almost 11 years ago

There is a patch that will add a GUI option to enable this behavior:
http://files.pfsense.org/jimp/patches/pf-log-oneline-option.diff

It has not been merged because we are investigating a better backend fix in how the logs are produced, rather than changing the output after the fact.

Actions #12

Updated by Michael Jansson over 10 years ago

How do I import/patching with this file pf-log-oneline-option.diff ?

Iam new in to pfsense have not seen any patching funktion just an import funktion for backups.

Regards Kip3r

Actions #13

Updated by Jim Pingle over 10 years ago

If you need assistance, please use the forum or mailing list. This system is not for support.

Actions #14

Updated by Jim Pingle over 10 years ago

  • Status changed from New to Resolved
  • Target version set to 2.2

This has been implemented on 2.2 for a while now with the new log daemon/format and it is working well.

Actions

Also available in: Atom PDF