Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On May 12, 2014, at 9:58 AM, Chris Murphy li...@colorremedies.com wrote: On May 12, 2014, at 7:06 AM, Kirill Elagin kirela...@gmail.com wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 80 # cat /proc/sys/kernel/random/boot_id 420fa190-e7dd-4cd7-b248-fd62417d7c02 # reboot ### # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 81 # cat /proc/sys/kernel/random/boot_id 1e0d5346-85cb-477b-9ae2-2cfb53097b97 So there are more boot ID's than there are list-boots, and list-boots doesn't increment while boot ID's do. And neither of these boot id's match any of the boot id's in --list-boots. Deleting the files in /var/log/journal/machineid/ fixes the problem on the Fedora 20 and Fedora Rawhide VMs experiencing this problem. If the files are restored, the problem returns. Yet --verify shows PASS for each log file. So it seems there's some kind of corruption or confusion with these log files. The btrfs filesystem is mounted with autodefrag option, for which there have been some problems with kernel 3.12 and older. But the Rawhide system has only been using 3.14 and 3.15 kernels so if there's still some problem I'm not sure how to isolate it since journalctl --verify seems to think the files are OK. Despite autodefrag enabled, the systemjournal has ~1450 fragments according to filefrag. If I boot from a rescue image so nothing is actively writing to these journal files, and recopy them such that they are each 1 extent only, then reboot the system, the list-boots changes. It actually goes down, from 45 boots to 31 boots, and stays stuck with additional reboots. Whereas BOOT_ID continues to increment as before. So just by copying the log files I get different --list-boot behavior. That's pretty strange. Yes, of course also btrfs check and scrub find no problems with either Fedora 20 or Fedora Rawhide Btrfs file systems this problem is happening on. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On Thu, 15.05.14 12:01, Chris Murphy (li...@colorremedies.com) wrote: On May 12, 2014, at 9:58 AM, Chris Murphy li...@colorremedies.com wrote: On May 12, 2014, at 7:06 AM, Kirill Elagin kirela...@gmail.com wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 80 # cat /proc/sys/kernel/random/boot_id 420fa190-e7dd-4cd7-b248-fd62417d7c02 # reboot ### # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 81 # cat /proc/sys/kernel/random/boot_id 1e0d5346-85cb-477b-9ae2-2cfb53097b97 So there are more boot ID's than there are list-boots, and list-boots doesn't increment while boot ID's do. And neither of these boot id's match any of the boot id's in --list-boots. Deleting the files in /var/log/journal/machineid/ fixes the problem on the Fedora 20 and Fedora Rawhide VMs experiencing this problem. If the files are restored, the problem returns. Yet --verify shows PASS for each log file. So it seems there's some kind of corruption or confusion with these log files. The btrfs filesystem is mounted with autodefrag option, for which there have been some problems with kernel 3.12 and older. But the Rawhide system has only been using 3.14 and 3.15 kernels so if there's still some problem I'm not sure how to isolate it since journalctl --verify seems to think the files are OK. Despite autodefrag enabled, the systemjournal has ~1450 fragments according to filefrag. If I boot from a rescue image so nothing is actively writing to these journal files, and recopy them such that they are each 1 extent only, then reboot the system, the list-boots changes. It actually goes down, from 45 boots to 31 boots, and stays stuck with additional reboots. Whereas BOOT_ID continues to increment as before. So just by copying the log files I get different --list-boot behavior. That's pretty strange. Yes, of course also btrfs check and scrub find no problems with either Fedora 20 or Fedora Rawhide Btrfs file systems this problem is happening on. This is certainly weird... Copying these files to ext4, does that change anything? I wonder if this might have to do something with time changes? Maybe the clock was not set correctly? Maybe it is a perms issue with some files not accessible to some users? Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On May 15, 2014, at 3:55 PM, Lennart Poettering lenn...@poettering.net wrote: On Thu, 15.05.14 12:01, Chris Murphy (li...@colorremedies.com) wrote: On May 12, 2014, at 9:58 AM, Chris Murphy li...@colorremedies.com wrote: On May 12, 2014, at 7:06 AM, Kirill Elagin kirela...@gmail.com wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 80 # cat /proc/sys/kernel/random/boot_id 420fa190-e7dd-4cd7-b248-fd62417d7c02 # reboot ### # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 81 # cat /proc/sys/kernel/random/boot_id 1e0d5346-85cb-477b-9ae2-2cfb53097b97 So there are more boot ID's than there are list-boots, and list-boots doesn't increment while boot ID's do. And neither of these boot id's match any of the boot id's in --list-boots. Deleting the files in /var/log/journal/machineid/ fixes the problem on the Fedora 20 and Fedora Rawhide VMs experiencing this problem. If the files are restored, the problem returns. Yet --verify shows PASS for each log file. So it seems there's some kind of corruption or confusion with these log files. The btrfs filesystem is mounted with autodefrag option, for which there have been some problems with kernel 3.12 and older. But the Rawhide system has only been using 3.14 and 3.15 kernels so if there's still some problem I'm not sure how to isolate it since journalctl --verify seems to think the files are OK. Despite autodefrag enabled, the systemjournal has ~1450 fragments according to filefrag. If I boot from a rescue image so nothing is actively writing to these journal files, and recopy them such that they are each 1 extent only, then reboot the system, the list-boots changes. It actually goes down, from 45 boots to 31 boots, and stays stuck with additional reboots. Whereas BOOT_ID continues to increment as before. So just by copying the log files I get different --list-boot behavior. That's pretty strange. Yes, of course also btrfs check and scrub find no problems with either Fedora 20 or Fedora Rawhide Btrfs file systems this problem is happening on. This is certainly weird... Copying these files to ext4, does that change anything? Each time I copy, no matter the file system, I get a different number of list-boots results each time. Yet each time the source and destination sha256sums for the journal files are the same. It makes no sense. Same sha256sums yet different --list-boot behavior. It's a non-deterministic hell it seems. Once the journals are affected by whatever is happening, they're permanently weird. I think the state is sufficiently bizarre, with a huge pile of Btrfs patches applied in the 3.14 time frame (both systems ran 3.14 and 3.15 rc kernels) that this is just not worth looking at further. I'll keep the journals elsewhere, but I'm going to clear out /var/log/journal and let it start new ones from scratch and see how it goes, if the problem reoccurs. I wonder if this might have to do something with time changes? Maybe the clock was not set correctly? It's a VM on a laptop host. Time is always correct. Maybe it is a perms issue with some files not accessible to some users? They are all throw away test systems and I'm lazy so I only use root. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On Thu, May 15, 2014 at 05:19:28PM -0600, Chris Murphy wrote: On May 15, 2014, at 3:55 PM, Lennart Poettering lenn...@poettering.net wrote: On Thu, 15.05.14 12:01, Chris Murphy (li...@colorremedies.com) wrote: On May 12, 2014, at 9:58 AM, Chris Murphy li...@colorremedies.com wrote: On May 12, 2014, at 7:06 AM, Kirill Elagin kirela...@gmail.com wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 80 # cat /proc/sys/kernel/random/boot_id 420fa190-e7dd-4cd7-b248-fd62417d7c02 # reboot ### # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 81 # cat /proc/sys/kernel/random/boot_id 1e0d5346-85cb-477b-9ae2-2cfb53097b97 So there are more boot ID's than there are list-boots, and list-boots doesn't increment while boot ID's do. And neither of these boot id's match any of the boot id's in --list-boots. Deleting the files in /var/log/journal/machineid/ fixes the problem on the Fedora 20 and Fedora Rawhide VMs experiencing this problem. If the files are restored, the problem returns. Yet --verify shows PASS for each log file. So it seems there's some kind of corruption or confusion with these log files. The btrfs filesystem is mounted with autodefrag option, for which there have been some problems with kernel 3.12 and older. But the Rawhide system has only been using 3.14 and 3.15 kernels so if there's still some problem I'm not sure how to isolate it since journalctl --verify seems to think the files are OK. Despite autodefrag enabled, the systemjournal has ~1450 fragments according to filefrag. If I boot from a rescue image so nothing is actively writing to these journal files, and recopy them such that they are each 1 extent only, then reboot the system, the list-boots changes. It actually goes down, from 45 boots to 31 boots, and stays stuck with additional reboots. Whereas BOOT_ID continues to increment as before. So just by copying the log files I get different --list-boot behavior. That's pretty strange. Yes, of course also btrfs check and scrub find no problems with either Fedora 20 or Fedora Rawhide Btrfs file systems this problem is happening on. This is certainly weird... Copying these files to ext4, does that change anything? Each time I copy, no matter the file system, I get a different number of list-boots results each time. Yet each time the source and destination sha256sums for the journal files are the same. It makes no sense. Same sha256sums yet different --list-boot behavior. It's a non-deterministic hell it seems. Once the journals are affected by whatever is happening, they're permanently weird. Probably the order of files in the directory (ls -U) changes randomly upon copying to a different fs. I think the state is sufficiently bizarre, with a huge pile of Btrfs patches applied in the 3.14 time frame (both systems ran 3.14 and 3.15 rc kernels) that this is just not worth looking at further. I'll keep the journals elsewhere, but I'm going to clear out /var/log/journal and let it start new ones from scratch and see how it goes, if the problem reoccurs. I wouldn't rule out an issue with the journal code... Zbyszek ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. You can also add ` -o verbose` to see all the fields of records. Since you say that the messages are actually stored in the journal, it might be interesting to check their _BOOT_ID fields. -- Кирилл Елагин On Mon, May 12, 2014 at 12:30 AM, Chris Murphy li...@colorremedies.comwrote: It looks like --list-boots is broken. I have have the same problem on Rawhide with systemd-212-4.fc21.x86_64, which is a completely different VM. Here are the last three items with --list-boots -2 95117f702e4d43619072f87b20b2f31b Sat 2014-05-03 20:38:22 MDT—Sat 2014-05-03 20:47:17 MDT -1 c9bf102876774c7a8748920f6135ddf6 Sat 2014-05-03 20:47:35 MDT—Sat 2014-05-03 20:51:55 MDT 0 f92e4dda29a54b89a3455a10bbb298b2 Sat 2014-05-03 21:01:17 MDT—Sat 2014-05-03 21:05:24 MDT OK installed Rawhide clean today to a third VM, with a Btrfs subvolume var mounted at /var, and the problem doesn't occur. Each boot gets a new entry with --list-boots. The prior Rawhide and Fedora 20 meanwhile, still always have the same --list-boot list after each boot, stuck on May 3rd for some reason. So it seems something broke --list-boot in a state persistent manner with the journal files themselves. The data is in the journal file however, I can extract the prior boots with --since and --lines, it's just that -b [x] is useless. -b -1 takes me back over a week rather than the boot 30 minutes ago. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On 12.05.2014 15:06, Kirill Elagin wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. You can also add ` -o verbose` to see all the fields of records. Since you say that the messages are actually stored in the journal, it might be interesting to check their _BOOT_ID fields. $ journalctl -F _BOOT_ID | wc -l 1159 $ journalctl --list-boots | wc -l 1159 poma ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
On May 12, 2014, at 7:06 AM, Kirill Elagin kirela...@gmail.com wrote: Could it be that all the boot ids are actually the same for some reason? I had this issue in a container when systemd was reading boot_id from `/proc/sys/kernel/random/boot_id` and since /proc was bind-mounted, boot_id always was host's boot_id. You can also run `journalctl -F _BOOT_ID` to see a set of all the boot ids recorded in the journal (this must agree with `journalctl --list-boots`. # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 80 # cat /proc/sys/kernel/random/boot_id 420fa190-e7dd-4cd7-b248-fd62417d7c02 # reboot ### # journalctl --list-boots | wc -l 36 [root@rawhide ~]# journalctl -F _BOOT_ID | wc -l 81 # cat /proc/sys/kernel/random/boot_id 1e0d5346-85cb-477b-9ae2-2cfb53097b97 So there are more boot ID's than there are list-boots, and list-boots doesn't increment while boot ID's do. And neither of these boot id's match any of the boot id's in --list-boots. You can also add ` -o verbose` to see all the fields of records. Since you say that the messages are actually stored in the journal, it might be interesting to check their _BOOT_ID fields. --since=2014-05-08 _BOOT_ID=e39d1329d216487f951334b229449d81 --since=2014-05-09 _BOOT_ID=550ece50b3ed4e21b9a0c446b95c2ebd --since=2014-05-04 _BOOT_ID=e428016363534ea595b1d9ba0440deeb They all appear to have unique boot IDs in the journal. Yet they aren't listed in --list-boots. For whatever reason, --list-boots is a subset of what I actually have. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
It looks like --list-boots is broken. I have have the same problem on Rawhide with systemd-212-4.fc21.x86_64, which is a completely different VM. Here are the last three items with --list-boots -2 95117f702e4d43619072f87b20b2f31b Sat 2014-05-03 20:38:22 MDT—Sat 2014-05-03 20:47:17 MDT -1 c9bf102876774c7a8748920f6135ddf6 Sat 2014-05-03 20:47:35 MDT—Sat 2014-05-03 20:51:55 MDT 0 f92e4dda29a54b89a3455a10bbb298b2 Sat 2014-05-03 21:01:17 MDT—Sat 2014-05-03 21:05:24 MDT OK installed Rawhide clean today to a third VM, with a Btrfs subvolume var mounted at /var, and the problem doesn't occur. Each boot gets a new entry with --list-boots. The prior Rawhide and Fedora 20 meanwhile, still always have the same --list-boot list after each boot, stuck on May 3rd for some reason. So it seems something broke --list-boot in a state persistent manner with the journal files themselves. The data is in the journal file however, I can extract the prior boots with --since and --lines, it's just that -b [x] is useless. -b -1 takes me back over a week rather than the boot 30 minutes ago. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] list-boots is incorrect, was: lost journal persistence
Fedora 20, systemd-208-16.fc20.x86_64 I no longer have persistent journals written to disk. I've done at least two dozen reboots today, yet journalctl --list-boots always reports the last three entries as: -2 43ba57a4decd4e2fb69bfd04493455c0 Mon 2014-04-14 14:43:38 MDT—Tue 2014-04-15 09:32:57 MDT -1 dd915a875c9b43168a4b43bd322a94ac Wed 2014-04-23 10:58:48 MDT—Wed 2014-04-23 11:32:20 MDT 0 eb5a4bb5c6364b84bf65020242c77347 Sat 2014-05-03 21:46:50 MDT—Sat 2014-05-03 22:22:54 MDT /var/log/journal/b7670… -rw-r-+ 1 root systemd-journal 8388608 May 10 17:46 system.journal So it seems to have written something to system.journal. # systemctl status systemd-journald.service systemd-journald.service - Journal Service Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static) Active: active (running) since Sat 2014-05-10 17:45:32 MDT; 1min 8s ago Docs: man:systemd-journald.service(8) man:journald.conf(5) Main PID: 288 (systemd-journal) Status: Processing requests... CGroup: /system.slice/systemd-journald.service └─288 /usr/lib/systemd/systemd-journald May 10 17:45:32 f20v.localdomain systemd-journal[288]: Runtime journal is using 8.0M (max allowed 125.2M, trying to leave 187.9M fr...5.2M). May 10 17:45:32 f20v.localdomain systemd-journal[288]: Runtime journal is using 8.0M (max allowed 125.2M, trying to leave 187.9M fr...5.2M). May 10 17:45:32 f20v.localdomain systemd-journal[288]: Journal started May 10 17:45:32 f20v.localdomain systemd-journal[288]: Permanent journal is using 104.0M (max allowed 4.0G, trying to leave 4.0G fr...4.0G). May 10 17:45:32 f20v.localdomain systemd-journal[288]: Time spent on flushing to /var is 26.812ms for 761 entries. I am mounting a Btrfs subvolume named var at /var, but it's always been this way and I have log entries going back to March. So I'm not sure when this started or what prompted it. The proximity to the journal start and flush to /var is the same time as mounting. May 10 17:45:32 f20v.localdomain systemd[1]: Mounting /var... May 10 17:45:32 f20v.localdomain systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway. May 10 17:45:32 f20v.localdomain systemd[1]: Mounted /var. So I thought maybe the flush is happening to /var before var subvolume is mounted there, but that's not the case; the reason why it's not empty is due to dhclient always creating one folder prior to var subvolume mounting at /var. /var/lib/dhclient There are no AVC messages, and the selinux context for /var and /var/log/journal is correct. In /var/log the Xorg.0.log has today's date so clearly it can be written to. lastlog and boot.log also have the current boot date/time stamp. journalctl --verify comes up with no problems, only pass. Very confusing. It looks like --list-boots is broken. I have have the same problem on Rawhide with systemd-212-4.fc21.x86_64, which is a completely different VM. Here are the last three items with --list-boots -2 95117f702e4d43619072f87b20b2f31b Sat 2014-05-03 20:38:22 MDT—Sat 2014-05-03 20:47:17 MDT -1 c9bf102876774c7a8748920f6135ddf6 Sat 2014-05-03 20:47:35 MDT—Sat 2014-05-03 20:51:55 MDT 0 f92e4dda29a54b89a3455a10bbb298b2 Sat 2014-05-03 21:01:17 MDT—Sat 2014-05-03 21:05:24 MDT So its last entries end the same date the Fedora 20 system ends, May 3. But I have a week of usage on both systems, and using -b doesn't work because they're not in the list. But if I do journalctl --since=today or --since=yesterday or --since=2014-05-04 They are all there. The journal is being written to disk. It's just that --list-boots isn't listing any boots since May 3, on two different VMs. So I don't know what broke it but it's broken in common with Fedora 20 and Rawhide. Chris Murphy ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
