Spurious message in syslog after update to RC (13May)

pst

I get this critical message in the syslog. Hardly critical

======

There is one log of severity crit on pfsense. Go to Log Center to check the details.

The content of the log is as follows:

done.

From syslogserver

======

The origin of this message is unknown...

pst

@pst on version 23.05.r.20230513.0132

stephenw10

Hmm, when do you get that log? Immediately after the upgrade?

What did you upgrade from?

I'm not seeing that here on anything.

Steve

pst

@stephenw10 I upgraded through the GUI/System/Update as per the blog post. The message occurred after a reboot, all "done" are generated by the kernel:

May 14 09:21:19 	php-fpm 	385 	/rc.start_packages: Restarting/Starting all packages.
May 14 09:21:19 	kernel 		done.
May 14 09:21:19 	syslogd 		kernel boot file is /boot/kernel/kernel

Date	Time	Level	Host Name	Category	Program	Messages
2023-05-14	09:21:19	Critical	pfsense	kern	kernel	done.

I have checked all "done" in the log and the timestamps correspond to system startups.

stephenw10

Oh, I see to an external syslog server?

And this was only after upgrading from 23.01? Not on every reboot?

Not sure why that entry would be sent at a different level.

pst

@stephenw10 yes, I have an external syslog server which picked up this. I have only seen this message on 23.05-RC upgraded from 23.01. There are other kernel messages (dot, and dot dot for example) during bootup which are not critical, here is a longer extract

56 Matched General Log Entries. (Maximum 1000)
May 14 09:21:19 	php_pfb 	67243 	[pfBlockerNG] filterlog daemon started
May 14 09:21:19 	php-cgi 	8733 	notify_monitor.php: Message sent to someone@somewhere.tld OK
May 14 09:21:19 	tail_pfb 	66770 	[pfBlockerNG] Firewall Filter Service started
May 14 09:21:19 	php_pfb 	64808 	[pfBlockerNG] filterlog daemon stopped
May 14 09:21:19 	tail_pfb 	64805 	[pfBlockerNG] Firewall Filter Service stopped
May 14 09:21:19 	php-fpm 	385 	[pfBlockerNG] Starting firewall filter daemon
May 14 09:21:19 	lighttpd_pfb 	32891 	[pfBlockerNG] DNSBL Webserver started
May 14 09:21:19 	lighttpd_pfb 	31806 	[pfBlockerNG] DNSBL Webserver stopped
May 14 09:21:19 	php-fpm 	385 	/rc.start_packages: Restarting/Starting all packages.
May 14 09:21:19 	kernel 		done.
May 14 09:21:19 	syslogd 		kernel boot file is /boot/kernel/kernel
May 14 09:21:18 	syslogd 		exiting on signal 15
May 14 09:21:16 	root 	92662 	/etc/rc.d/hostid: WARNING: hostid: unable to figure out a UUID from DMI data, generating a new one
May 14 09:21:16 	kernel 		done.
May 14 09:21:16 	php-cgi 	454 	rc.bootup: Creating rrd update script
May 14 09:21:16 	php-cgi 	454 	rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/system-sensors.rrd N:U:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/system-sensors.rrd: found extra data on update argument: U'
May 14 09:21:15 	sshd 	5473 	Accepted keyboard-interactive/pam for admin from Z port 65392 ssh2
May 14 09:21:11 	kernel 		done.
May 14 09:21:11 	php-cgi 	454 	rc.bootup: The command '/usr/local/sbin/strongswanrc stop' returned exit code '1', the output was 'strongswan not running? (check /var/run/daemon-charon.pid).'
May 14 09:21:11 	kernel 		.
May 14 09:21:11 	kernel 		...
May 14 09:21:11 	kernel 		.
May 14 09:21:10 	kernel 		done.
May 14 09:21:10 	check_reload_status 	423 	Updating all dyndns
May 14 09:21:10 	kernel 		done.
May 14 09:21:09 	kernel 		done.
May 14 09:21:09 	php-cgi 	454 	rc.bootup: NTPD is starting up.
May 14 09:21:07 	php-fpm 	385 	/rc.linkup: Ignoring link event during boot sequence.
May 14 09:21:06 	kernel 		igb3: link state changed to UP
May 14 09:21:06 	check_reload_status 	423 	Linkup starting igb3
May 14 09:21:06 	php-fpm 	385 	/rc.linkup: Ignoring link event during boot sequence.
May 14 09:21:04 	kernel 		igb2: link state changed to UP
May 14 09:21:04 	check_reload_status 	423 	Linkup starting igb2
May 14 09:21:04 	php-fpm 	385 	/rc.linkup: Ignoring link event during boot sequence.
May 14 09:21:03 	syslogd 		sendto: Host is down
May 14 09:21:03 	kernel 		igb1: link state changed to UP
May 14 09:21:03 	syslogd 		sendto: Host is down
May 14 09:21:03 	check_reload_status 	423 	Linkup starting igb1
May 14 09:21:02 	kernel 		done.
May 14 09:21:02 	kernel 		done.
May 14 09:21:02 	syslogd 		sendto: Network is down
May 14 09:21:02 	php-cgi 	454 	rc.bootup: sync unbound done.
May 14 09:21:01 	kernel 		done.
May 14 09:21:01 	syslogd 		sendto: Network is down
May 14 09:21:01 	php-cgi 	454 	rc.bootup: Default gateway setting Interface WAN_DHCP Gateway as default.
May 14 09:21:00 	kernel 		done.
May 14 09:21:00 	kernel 		done.
May 14 09:21:00 	php-cgi 	454 	rc.bootup: Removing static route for monitor X and adding a new route through Y
May 14 09:21:00 	sshguard 	31214 	Now monitoring attacks.
May 14 09:21:00 	sshd 	30623 	Server listening on 0.0.0.0 port 222.
May 14 09:21:00 	sshd 	30623 	Server listening on :: port 222.
May 14 09:21:00 	kernel 		.
May 14 09:21:00 	syslogd 		sendto: Network is down
May 14 09:21:00 	php-fpm 	386 	/rc.newwanip: Removing static route for monitor X and adding a new route through Y
May 14 09:21:00 	php-fpm 	386 	/rc.newwanip: rc.newwanip: on (IP address: Y) (interface: WAN[wan]) (real interface: igb0).
May 14 09:21:00 	php-fpm 	386 	/rc.newwanip: rc.newwanip: Info: starting on igb0.

..

stephenw10

Hmm, OK and just to be clear this only happens on the first boot after upgrade or on every boot?

pst

@stephenw10 on every boot (I just rebooted to check)

pst

@stephenw10 but as it is only happens after a reboot, and hopefully not caused by data corruption, it is a minor issue,because we never need to reboot pfSense!