Re: pflogd: Corrupted log file, move it away
Hi folks,
On 11/28/20 5:13 PM, Stuart Henderson wrote:
It is easy enough to add the filename, but adding that to the log
might suggest to users that things are setup to handle multiple pflogd
processes and that is not the case.
Various parts of the system would need changing in order to handle this.
Currently there is no way to distinguish between multiple "priv" processes
as the process title doesn't show the command-line flags. In order to
support multiple pflogd processes this would need adding, then the rc.d
scripts and default newsyslog.conf entry would need updating to use them.
I have to admit that this was my fault. There were 2 pflogd writing to
/var/log/pflog, AFAICS. The other 2 were not even started.
To support 4 pflog interfaces I had to create 4 symlinks in /sbin
ln -s pflogd /sbin/pflogd0
ln -s pflogd /sbin/pflogd1
ln -s pflogd /sbin/pflogd2
ln -s pflogd /sbin/pflogd3
and to create 4 rc scripts in /etc/rc.d, e.g /etc/rc.d/pflogd2:
#!/bin/ksh
daemon="/sbin/pflogd2"
. /etc/rc.d/rc.subr
pexp="pflogd2: \[priv\]"
rc_pre() {
if pfctl -si | grep -q Enabled; then
ifconfig pflog2 create
if ifconfig pflog2; then
ifconfig pflog2 up
else
return 1
fi
else
return 1
fi
}
rc_cmd $1
Each pflogd had to be configured accordingly using rcctl, e.g.
rcctl enable pflogd2
rcctl set pflogd2 flags "-i pflog2 -f /var/log/pflog2"
rcctl start pflogd2
(Be careful, if you disable and enable the service, then you have to
set the flags again.)
Finally I had to add the new log files to newsyslog.conf:
/var/log/pflog0 600 7 65536 24 ZB "pkill -HUP -u root -U
root -t - -x pflogd0"
/var/log/pflog1 600 7 65536 24 ZB "pkill -HUP -u root -U
root -t - -x pflogd1"
/var/log/pflog2 600 7 65536 24 ZB "pkill -HUP -u root -U
root -t - -x pflogd2"
/var/log/pflog3 600 7 65536 24 ZB "pkill -HUP -u root -U
root -t - -x pflogd3"
Hope this is helpful to anybody.
Regards
Harri
Re: pflogd: Corrupted log file, move it away
On 2020-11-28, Jan Stary wrote: > If I'm reading you right, the rotation sends a SIGHUP to each > of the pflogd processes; twice, in fact: after rotating each > of the two files. Is that the case? Yes, you have the same command for restarting pflogd on both newsyslog.conf lines so it will send signals to both daemons twice in short succession. I don't know if that will cause corruption (maybe pflogd doesn't care if it gets two signals in short succession) but it's clearly not ideal. > That would indeed be a problem; namely, it would break the nice > sequence of one rotated logfile per day. The rotation is done by newsyslog (once per file) so the sequence would still work. > If I read the newsyslog lines right, each of > > 13680 pflogd: [running] -s 1500 -i pflog0 -f /var/log/pflog > 84985 pflogd: [priv] > 10562 pflogd: [running] -s 1500 -i pflog1 -f /var/log/siplog > 94396 pflogd: [priv] > > is getting HUP'd, right? Only the priv processes are sent HUP. > Would it be enough to HUP the [running] child? no idea, but someone obviously went to the trouble to make it signal only the priv process so there's probably a reason for this. > |-+= 84985 root pflogd: [priv] (pflogd) > | \--- 13680 _pflogd pflogd: [running] -s 1500 -i pflog0 -f /var/log/pflog > (pflogd) > > |-+= 94396 root pflogd: [priv] (pflogd) > | \--- 10562 _pflogd pflogd: [running] -s 1500 -i pflog1 -f /var/log/siplog > (pflogd) > > Probably not, based on what you said about [priv]; but the [running] > processes can be distinguished in newsyslog.conf with "pkill -xf pflog0". yes those are easy to differentiate :)
Re: pflogd: Corrupted log file, move it away
On Nov 28 16:13:35, s...@spacehopper.org wrote:
> On 2020-11-27, Harald Dunkel wrote:
> > Hi folks,
> >
> > I got a bazillion of error messages in /var/log/daemon
> >
> >:
> > Nov 27 08:33:25 gate6a pflogd[26893]: Corrupted log file.
> > Nov 27 08:33:25 gate6a pflogd[26893]: Invalid/incompatible log file, move
> > it away
> > Nov 27 08:33:25 gate6a pflogd[26893]: Logging suspended: open error
> > Nov 27 08:33:32 gate6a pflogd[2985]: Corrupted log file.
> > Nov 27 08:33:32 gate6a pflogd[2985]: Invalid/incompatible log file, move it
> > away
> > Nov 27 08:33:32 gate6a pflogd[2985]: Logging suspended: open error
> >:
> >
> > Problem is, pflogd doesn't tell which one. I am logging to /var/log/\
> > pflog{0..3}. Nothing else but pflogd is writing these files. They are
> > rotated every hour, using the default
>
> It is easy enough to add the filename, but adding that to the log
> might suggest to users that things are setup to handle multiple pflogd
> processes and that is not the case.
>
> Various parts of the system would need changing in order to handle this.
> Currently there is no way to distinguish between multiple "priv" processes
> as the process title doesn't show the command-line flags. In order to
> support multiple pflogd processes this would need adding, then the rc.d
> scripts and default newsyslog.conf entry would need updating to use them.
>
> > I can't remember having seen this problem for 6.7.
>
> I think you got lucky.
Maybe I got lucky too - please help me understand.
I have two pflog interfaces: pflog0 (created by default)
and pflog1 (created with 'up' in /etc/hostname.pflog1).
pflgo0 logs the suspicious network traffic aimed at my machine:
block log all
# pass legit stuff
pflog1 logs all the SIP traffic to and from my SIP phone
(on an internal network):
match in log (all, to pflog1) on $int from $sip
match out log (all, to pflog1) on $int to $sip
There are two corresponding pflogd processes: one is started
with pflogd_flags="-s 1500" in /etc/rc.conf.local, and becomes
13680 pflogd: [running] -s 1500 -i pflog0 -f /var/log/pflog
84985 pflogd: [priv]
The other is started in /etc/rc.local as
/sbin/pflogd -s 1500 -i pflog1 -f /var/log/siplog
which runs
10562 pflogd: [running] -s 1500 -i pflog1 -f /var/log/siplog
94396 pflogd: [priv]
The two log files (/var/log/pflog, /var/log/siplog)
are rotated as follows:
/var/log/pflog 600 3650 * @T00 ZB "pkill -HUP -u root -U root -t - -x pflogd"
/var/log/siplog 600 3650 * @T00 ZB "pkill -HUP -u root -U root -t - -x pflogd"
I have had the same messages as the OP describes,
until I realized I missed the B iz 'ZB' for siplog,
which indeed rendered the file 'invalid' on rotation
because of the textual 'logfile turned over' message.
Since fixing that, I haven't had seen the message
(that would be a couple of weeks now).
If I'm reading you right, the rotation sends a SIGHUP to each
of the pflogd processes; twice, in fact: after rotating each
of the two files. Is that the case?
That would indeed be a problem; namely, it would break the nice
sequence of one rotated logfile per day.
However, looking at the timestamps of the few first and last entries
in pflog.1, pflog.0 and pflog (and, similarly, siplog{1,0,}), they
seem to follow one another as they should - one beginning just
where the previous one ends, none of them rotated empty.
If I read the newsyslog lines right, each of
13680 pflogd: [running] -s 1500 -i pflog0 -f /var/log/pflog
84985 pflogd: [priv]
10562 pflogd: [running] -s 1500 -i pflog1 -f /var/log/siplog
94396 pflogd: [priv]
is getting HUP'd, right? Would it be enough to HUP the [running] child?
|-+= 84985 root pflogd: [priv] (pflogd)
| \--- 13680 _pflogd pflogd: [running] -s 1500 -i pflog0 -f /var/log/pflog
(pflogd)
|-+= 94396 root pflogd: [priv] (pflogd)
| \--- 10562 _pflogd pflogd: [running] -s 1500 -i pflog1 -f /var/log/siplog
(pflogd)
Probably not, based on what you said about [priv]; but the [running]
processes can be distinguished in newsyslog.conf with "pkill -xf pflog0".
Jan
Re: pflogd: Corrupted log file, move it away
On 2020-11-27, Harald Dunkel wrote:
> Hi folks,
>
> I got a bazillion of error messages in /var/log/daemon
>
>:
> Nov 27 08:33:25 gate6a pflogd[26893]: Corrupted log file.
> Nov 27 08:33:25 gate6a pflogd[26893]: Invalid/incompatible log file, move it
> away
> Nov 27 08:33:25 gate6a pflogd[26893]: Logging suspended: open error
> Nov 27 08:33:32 gate6a pflogd[2985]: Corrupted log file.
> Nov 27 08:33:32 gate6a pflogd[2985]: Invalid/incompatible log file, move it
> away
> Nov 27 08:33:32 gate6a pflogd[2985]: Logging suspended: open error
>:
>
> Problem is, pflogd doesn't tell which one. I am logging to /var/log/\
> pflog{0..3}. Nothing else but pflogd is writing these files. They are
> rotated every hour, using the default
It is easy enough to add the filename, but adding that to the log
might suggest to users that things are setup to handle multiple pflogd
processes and that is not the case.
Various parts of the system would need changing in order to handle this.
Currently there is no way to distinguish between multiple "priv" processes
as the process title doesn't show the command-line flags. In order to
support multiple pflogd processes this would need adding, then the rc.d
scripts and default newsyslog.conf entry would need updating to use them.
> I can't remember having seen this problem for 6.7.
I think you got lucky.
> (Not to mention that syslog should try to avoid printing the same
> message again and again.)
Some kind of "last 3 messages repeated X times" might be nice indeed,
but every one of the messages you pasted are different (at least different
pid).
> I am legally bound to provide log files, so this is a huge problem.
> Every insightful comment is highly appreciated.
> Harri
>
>
I think it would be better to simplify the setup and use a single log
for pflogd. You can split in postprocessing with commands like this
tcpdump -r /var/log/pflog -w out-vlan2.pcap action block and on vlan2
using whatever BPF filter you like (ports, IP addresses, whatever).
Some people like to run tcpdump all the time to read on the pflog
interface and write in plaintext to syslog in realtime. That is another
possibility but I don't think this is a good idea because it will use
the dissectors in tcpdump to decode the packets, quality of these is not
always great. Better to write pcap files and handle any decoding later
so that if a dissector causes a crash it doesn't stop logging.
Re: pflogd: Corrupted log file, move it away
On Nov 27 09:02:04, harald.dun...@aixigo.com wrote:
> Hi folks,
>
> I got a bazillion of error messages in /var/log/daemon
>
> :
> Nov 27 08:33:25 gate6a pflogd[26893]: Corrupted log file.
> Nov 27 08:33:25 gate6a pflogd[26893]: Invalid/incompatible log file, move it
> away
Last time I had this, it was a missing B in the rotation flag,
slapping a "logfile turned over" text message into a binary log file.
> Nov 27 08:33:25 gate6a pflogd[26893]: Logging suspended: open error
> Nov 27 08:33:32 gate6a pflogd[2985]: Corrupted log file.
> Nov 27 08:33:32 gate6a pflogd[2985]: Invalid/incompatible log file, move it
> away
> Nov 27 08:33:32 gate6a pflogd[2985]: Logging suspended: open error
> :
>
> Problem is, pflogd doesn't tell which one. I am logging to /var/log/\
> pflog{0..3}. Nothing else but pflogd is writing these files. They are
> rotated every hour, using the default
>
> /var/log/pflog 600 3 250 * ZB "pkill -HUP -u root -U root -t - -x
> pflogd"
Does that mean you only keep the last 4 x 250 kilobytes of logs
(or whatever it accumulates to during the hour)?
Is that your intentiton?
> in /etc/newsyslog.conf. crontab entry:
>
> 0 * * * * /usr/bin/newsyslog
Re: pflogd: Corrupted log file, move it away
On Nov 27 09:02:04, harald.dun...@aixigo.com wrote:
> Hi folks,
>
> I got a bazillion of error messages in /var/log/daemon
>
> :
> Nov 27 08:33:25 gate6a pflogd[26893]: Corrupted log file.
> Nov 27 08:33:25 gate6a pflogd[26893]: Invalid/incompatible log file, move it
> away
> Nov 27 08:33:25 gate6a pflogd[26893]: Logging suspended: open error
> Nov 27 08:33:32 gate6a pflogd[2985]: Corrupted log file.
> Nov 27 08:33:32 gate6a pflogd[2985]: Invalid/incompatible log file, move it
> away
> Nov 27 08:33:32 gate6a pflogd[2985]: Logging suspended: open error
> :
>
> Problem is, pflogd doesn't tell which one. I am logging to /var/log/\
> pflog{0..3}.
To be sure, are these the names?
/var/log/pflog0
/var/log/pflog1
/var/log/pflog2
/var/log/pflog3
> Nothing else but pflogd is writing these files.
How, exactly? What are the pf.conf log rules?
What are the pflogd -i command lines?
> They are
> rotated every hour, using the default
>
> /var/log/pflog 600 3 250 * ZB "pkill -HUP -u root -U root -t - -x
> pflogd"
If the above names are correct, this does not rotate any of them.
Do you mean /var/log/pflog.0 etc, being the rotated copies
of a single /var/log/pflog ?
