dmesg(8) buffer contains messages from previous boots of the same system as well as most recent

Terri_Kennedy

Terri_Kennedy

I've been seeing a rather odd problem in 12.1-STABLE. I'm not sure if it was also in older releases. When I run the dmesg(8) command, I see records from several previous boots of the system. For example:
Code: 
(0:11) hostname:/sysprog/terry# dmesg | grep -E "BOOT|STABLE"
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r359769: Fri Apr 10 02:04:44 EDT 2020
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r360560: Fri May  1 21:53:51 EDT 2020
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r360668: Tue May  5 15:25:15 EDT 2020
These also appear in /var/run/dmesg.boot:
Code: 
(0:12) hostname:/sysprog/terry# grep -E "BOOT|STABLE" /var/run/dmesg.boot
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r359769: Fri Apr 10 02:04:44 EDT 2020
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r360560: Fri May  1 21:53:51 EDT 2020
---<<BOOT>>---
FreeBSD 12.1-STABLE #0 r360668: Tue May  5 15:25:15 EDT 2020
Other uses may not see this, as non-kernel messages will displace older messages from the buffer. Note that this is 3 different kernel builds, yet they share the same dmesg(8) buffer for some reason. There is no mention in the manpage about the message buffer being preserved across reboots. Other than doing a # dmesg -c to clear the buffer before a reboot, is there any way to prevent this from happening?

The reason that this is a problem is that I have some scripts that run at startup and shutdown that look for issues in the buffer, and if it finds an issue it emails a report to the system managers. But even if the issue is corrected, the managers are still notified because the messages from a previous boot are still present in the buffer.
 
Strange. The dmesg(8) program reads from a memory buffer. How can that buffer survive a reboot?

If you have nothing useful to do, and are willing to power-cycle a machine, try this: Power the computer down, wait a minute (for DRAM to be cleared), and power it back up. Compare the result with just rebooting. If the dmesg content is gone when power cycling, but with a simple reboot it survives, then this means the newly loaded kernel uses a memory buffer from the previous kernel invocation. Which is either genius (if deliberate), or a very odd bug.

Note that the word "dmesg" doesn't show up in either the 12.0 or 12.1 release notes. So if this was a deliberate change, it was not documented.
 
Pyret: That was sort of the theory behind my question too. But that begs the question: How does the kernel, when it starts, know whether it was rebooted or came up from powerup? I don't think that anything in the kernel knows that (other than platform-specific things like ACPI). So when it boots, it has to expect to find uninitialized memory where dmesg is supposed to be, so it can't trust any bytes found there. Which also means that it can't continue using the same (ring-) buffer, since it doesn't know where the insertion point in the buffer is.

Now, in theory it would be possible to leave markers in memory that indicate where the ring buffer insertion point is, and what part is valid. It could even make those markers complex enough (like using a CRC) that they could not be confused with random memory content. Possible, but implausible. I guess I should pull up the source code and read it.

By the way, the word "dmesg" does not show up in the index of the daemon book. So reading the source will be it.
 
If your kernel panicks, and reboots, you want the logs of the previous boot.

/etc/syslog.conf lists various locations for log info. So setting this in /etc/rc.conf might help:
Code: 
cleanvar_enable="YES"   # Clean the /var directory

I think you could also "cut" off the previous log messages by reducing the overall message buffer size in /boot/loader.conf
Code: 
kern.msgbufsize: 98304 # Set size of kernel message buffer
 
Elazar said:
I think you could also "cut" off the previous log messages by reducing the overall message buffer size in /boot/loader.conf
Code: 
kern.msgbufsize: 98304 # Set size of kernel message buffer
Click to expand...
sys/conf/NOTES in the source tree also lists it as a build-time option with a comment:
Code: 
# Size of the kernel message buffer.  Should be N * pagesize.
options        MSGBUF_SIZE=40960
For a system with a 4 KiB page size, that reduces the size to 10 pages from its default of 24 pages (98304, or 3 * 32768 as seen in the source code). Unless you have a lot of services starting at boot time, you might be fine with the 40960 unless you want to allow for messages about starting services you add later (and error messages that might occur in the future) and/or more than 2 full logs:
Code: 
sh# sysctl -n kern.msgbufsize
98304
sh# dmesg | grep -ce "$(sysctl -n kern.boot_tag | tee /dev/stderr)"
---<<BOOT>>---
3
sh# dmesg | wc -c
   50019
40960 would be plenty if I only wanted 2 logs available via dmesg. I don't mind having more, and you can use dmesg | split -d -p '---<<BOOT>>---' - dmesg to get dmesg00, dmesg01, dmesg02, etc., which allows you to work with them individually. You can then use something like echo '$-1p' | ed -s '!/bin/ls -1 dmesg??' | less to view the the log file in less(1) immediately before the last/current one (and $-2 would be the one before that, $-3 is the log before $-2, etc.)
 
Alain De Vos said:
To survive the buffer, doesn't the CPU not need to stay in 64bit mode ?. Does a warm reboot do this ?
Click to expand...
Not only that, but needs to have the exact same address layout - as you can see from my boot messages, these are 3 different kernel revisions (that was the reason for the reboots). My systems normally stay up long enough for the previous boot messages to be pushed out of the buffer, either due to other messages from the kernel or syslog / console messages that get put into that buffer.
 
Elazar said:
If your kernel panicks, and reboots, you want the logs of the previous boot.
Click to expand...
Of course. That is why the logs are saved in (normally) /var/log/messages and dmesg(8) can read the message buffer from a kernel core dump file (the -M option). Neither of those requires saving past history in the buffer used by the currently-running kernel.

/etc/syslog.conf lists various locations for log info. So setting this in /etc/rc.conf might help:
Code: 
cleanvar_enable="YES"   # Clean the /var directory
Click to expand...
No, that only affects the on-disk contents. I'm specifically talking about the kernel memory buffer read by dmesg(8). The only time that it reads from something other than the kernel memory buffer is when you use the -M options to read from an on-disk kernel core dump.
I think you could also "cut" off the previous log messages by reducing the overall message buffer size in /boot/loader.conf
Code: 
kern.msgbufsize: 98304 # Set size of kernel message buffer
Click to expand...
That has side effects that I don't want: 1) reducing the amount of buffered log messages and 2) not being effective - /var/run/dmesg.boot is 70270 bytes on the system in question, so reducing to a value near that runs the risk of not populating that file with the full contents of the boot messages,

It seems like this was either an undocumented change or an unexpected side effect of a change. There has been a lot of recent work in the boot / loader / UEFI area which might be affecting this. If nobody has any ideas within the next few days about why it has started happening, I'll file a PR on it.
 
For those who do see the same thing (multiple boots in the buffer), can you let me know if your systems are booting with BIOS or UEFI, and optionally the FreeBSD version and hardware platform?
For those who don't see it, can you also let me know the same thing?

In my case, the system (Dell PowerEdge R730) boots 12.1-STABLE with UEFI. I'm wondering is this is UEFI related. The code to retain the old message buffer is in msgbuf_reinit() in /usr/src/sys/kern/subr_msgbuf.c with a comment of:
Code: 
/*
 * Reinitialize a message buffer, retaining its previous contents if
 * the size and checksum are correct. If the old contents cannot be
 * recovered, the message buffer is cleared.
 */
That code has been in there since at least r116660, nearly 17 years ago (the oldest version of that file in SVN).

The <BOOT> tag was added in to HEAD in /usr/src/sys/kern/subr_prf.c r337518 in August 2018 with some subsequent bikeshedding, and was propagated to 12 when it was branched from head. Since there would be no need to have such a <BOOT> tag if the buffer wasn't intended to be re-used between boots, this seems to be intentional behavior which just hasn't shown up (or been noticed) by most users previously.

I think the best path forward is to request an "always clear message buffer" boot tunable, with the default being the current behavior. I might be able to partially simulate this with a # dmesg -c at shutdown time, but that will still leave the various "Waiting" messages in the buffer as those are added after all user processes have exited.
 
Terry_Kennedy said:
I think the best path forward is to request an "always clear message buffer" boot tunable
Click to expand...
dmesg -c certainly works, but there's also a sysctl OID kern.msgbuf_clear that can be set in userspace to clear the buffer. In 9.3-RELEASE, dmesg lacked the -c switch, so maybe they were implemented at the same time, or perhaps the OID was available before the -c switch. Anyway, kern.msgbuf_clear currently has no effect in loader.conf, so maybe that functionality just needs to be added to clear the buffer on boot.
 
ralphbsz said:
Strange. The dmesg(8) program reads from a memory buffer. How can that buffer survive a reboot?
Click to expand...

I don't know why, but I can confirm that it sometimes happens.

If you have nothing useful to do, and are willing to power-cycle a machine, try this: Power the computer down, wait a minute (for DRAM to be cleared), and power it back up. Compare the result with just rebooting. If the dmesg content is gone when power cycling, but with a simple reboot it survives, then this means the newly loaded kernel uses a memory buffer from the previous kernel invocation. Which is either genius (if deliberate), or a very odd bug.

Note that the word "dmesg" doesn't show up in either the 12.0 or 12.1 release notes. So if this was a deliberate change, it was not documented.
Click to expand...

Nope. Here is 11.3, and this is there for a long time already.
Here it doesn't happen always. Most often the dmesg starts cleanly with the current uptime. But sometimes it happens and I see some stuff from earlier uptime. As there are lots of things going into the kernel messages, I never see an earlier boot message - also my buffer is increased to 252k size, so I thought it might be related to that. I never thought it being a bug, and only slightly annoying, so I had no reason to not ignore it.
 
You must log in or register to reply here.
Back
Top