Feature #1938
Filter messages broken into multiple syslog messages
| Status: | New | Start date: | 10/07/2011 | |
|---|---|---|---|---|
| Priority: | Normal | Due date: | ||
| Assignee: | - | % Done: | 0% |
|
| Category: | Logging | |||
| Target version: | - | |||
| Affected version: | Affected Architecture: |
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");
History
#1
Updated by Chris Buechler over 1 year 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
#2
Updated by Ermal Luçi over 1 year 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.
#3
Updated by Ted Lum over 1 year 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.
#4
Updated by Jim P over 1 year 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.
#5
Updated by Ted Lum over 1 year 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.
#6
Updated by Francis Turner over 1 year 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.
#7
Updated by Francis Turner over 1 year 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
#8
Updated by Jim P over 1 year ago
- Status changed from Feedback to New
- Affected version deleted (
2.0)
#9
Updated by Andre LaBranche 11 months 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.