After update from 219 to 221 journalctl throws "Error was encountered while opening journal files: Invalid argument"

[p4yne]

The bug was originally discovered by users from the archlinux bug tracker.

The following is just a short summary for detailed error logs please take a look at the linked bug report.

This is the affected version:

$ sudo journalctl --version
systemd 221
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD +IDN

After upgrading from systemd 219 to 221, journalctl is not able to open some journal files. Which of the journal files is not deterministic (system.journal or user-1000.journal).

With version 221 the verify command fails in this case for system.journal and succeeds for user-1000.journal:

$ sudo journalctl --verify --file /var/log/journal/*/system.journal
Failed to open /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal: Invalid argument
Failed to open files: Invalid argument
$ sudo journalctl --verify --file /var/log/journal/*/user-1000.journal
PASS: /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000.journal 

When downgrading to 219 both commands succeed and every thing is fine.

A debug log on the same machine when 221 is used:

$ SYSTEMD_LOG_LEVEL=debug journalctl
Root directory /run/log/journal added.
Considering /run/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /run/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /run/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal added.
Root directory /var/log/journal added.
Considering /var/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /var/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000133fd7-000513823c5f5c8a.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-0000000000000001-00050e8fe588ee02.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001357a8-000513826dfca51e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000000001-00050a50f2d222db.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001343cb-00051382448173e4.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135ba7-00051382766685fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136397-0005138286ec73b9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134fb7-000513825d7033d3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013776a-00051382b06d1ef1.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135f95-000513827e8884fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000138cbd-00051382e93af095.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137f6e-00051382c3c2d203.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000c1aa0-00050fa957605fc0.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000000069d-00050dd20e6b8ee3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137b7c-00051382b8dbf680.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137371-00051382a7fcde5e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000008ca67-00050f1ac844d6f3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@f73d577bcd5e42c4ae9d2aee7c940bd8-0000000000000001-00050c18685b675f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136f8d-000513829fe4a5ff.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001347cf-000513824ceaa2e8.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134bd5-00051382555da4cc.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013836d-00051382d2eb369c.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000012eff3-00051363533be320.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000056cbf-00050a83e98645d9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000000001-000512ee0380b441.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@2b559fa0ac5a4d91b48b618fcd8b0bfe-0000000000000001-00050dd20a82ee11.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001353c7-0005138265e2b347.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-000000000008c54a-00050f19dcc3a37f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136b87-0005138297768761.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-00000000000e5de4-00051292723891ca.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-120.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@6856d051d3a74eb388cac7f4e4a28857-0000000000056a8e-00050a83e2dc4a31.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-0000000000034693-00050e71eeb13577.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@3748a0d9714947e895474cde2dfa1509-0000000000000759-00050c186cc16a78.journal added.
Failed to add file /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal: Invalid argument
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000e5a10-0005129270971d89.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001367a3-000513828f5329d2.journal added.
Error was encountered while opening journal files: Invalid argument
Root directory /run/log/journal removed.
Directory /run/log/journal/22207cfa7a3d42cbb48e15413f10137b removed.
Root directory /var/log/journal removed.
Directory /var/log/journal/22207cfa7a3d42cbb48e15413f10137b removed.
mmap cache statistics: 76 hit, 39 miss

This comment contains the same logs as above but also a strace dump is attached for further bug hunting.

To make matters worse it was just discovered that after using the system for 2 days on the new version 221 the journalctl --verify --file /var/log/journal/*/system.journal also fails if the old systemd 219 version is used so data was written to the journal but it is now also corrupted for the old version.

But interestingly enough when using journalctl -b or journalctl -f the journal can be accessed with the old 219 version.

SYSTEMD_LOG_LEVEL=debug journalctl -f
Root directory /run/log/journal added.
Considering /run/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /run/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /run/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal added.
Root directory /var/log/journal added.
Considering /var/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /var/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000133fd7-000513823c5f5c8a.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-0000000000000001-00050e8fe588ee02.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001357a8-000513826dfca51e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000000001-00050a50f2d222db.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001343cb-00051382448173e4.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135ba7-00051382766685fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136397-0005138286ec73b9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134fb7-000513825d7033d3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013776a-00051382b06d1ef1.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135f95-000513827e8884fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000138cbd-00051382e93af095.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137f6e-00051382c3c2d203.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000c1aa0-00050fa957605fc0.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000000069d-00050dd20e6b8ee3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137b7c-00051382b8dbf680.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137371-00051382a7fcde5e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000008ca67-00050f1ac844d6f3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@f73d577bcd5e42c4ae9d2aee7c940bd8-0000000000000001-00050c18685b675f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136f8d-000513829fe4a5ff.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001347cf-000513824ceaa2e8.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134bd5-00051382555da4cc.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013836d-00051382d2eb369c.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000012eff3-00051363533be320.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000056cbf-00050a83e98645d9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000000001-000512ee0380b441.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@2b559fa0ac5a4d91b48b618fcd8b0bfe-0000000000000001-00050dd20a82ee11.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001353c7-0005138265e2b347.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-000000000008c54a-00050f19dcc3a37f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136b87-0005138297768761.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-00000000000e5de4-00051292723891ca.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-120.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@6856d051d3a74eb388cac7f4e4a28857-0000000000056a8e-00050a83e2dc4a31.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-0000000000034693-00050e71eeb13577.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@3748a0d9714947e895474cde2dfa1509-0000000000000759-00050c186cc16a78.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000e5a10-0005129270971d89.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001367a3-000513828f5329d2.journal added.
Journal filter: none
Considering /run/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Considering /var/log/journal/22207cfa7a3d42cbb48e15413f10137b.

When using the new version 221 with both commands the error persists:

SYSTEMD_LOG_LEVEL=debug journalctl -f
Root directory /run/log/journal added.
Considering /run/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /run/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /run/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal added.
Root directory /var/log/journal added.
Considering /var/log/journal/22207cfa7a3d42cbb48e15413f10137b.
Directory /var/log/journal/22207cfa7a3d42cbb48e15413f10137b added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000133fd7-000513823c5f5c8a.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-0000000000000001-00050e8fe588ee02.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001357a8-000513826dfca51e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000000001-00050a50f2d222db.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001343cb-00051382448173e4.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135ba7-00051382766685fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136397-0005138286ec73b9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134fb7-000513825d7033d3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013776a-00051382b06d1ef1.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000135f95-000513827e8884fe.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000138cbd-00051382e93af095.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137f6e-00051382c3c2d203.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000c1aa0-00050fa957605fc0.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000000069d-00050dd20e6b8ee3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137b7c-00051382b8dbf680.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000137371-00051382a7fcde5e.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-000000000008ca67-00050f1ac844d6f3.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@f73d577bcd5e42c4ae9d2aee7c940bd8-0000000000000001-00050c18685b675f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136f8d-000513829fe4a5ff.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001347cf-000513824ceaa2e8.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000134bd5-00051382555da4cc.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000013836d-00051382d2eb369c.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-000000000012eff3-00051363533be320.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@162234b90c79446b81847eef6a378c27-0000000000056cbf-00050a83e98645d9.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000000001-000512ee0380b441.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@2b559fa0ac5a4d91b48b618fcd8b0bfe-0000000000000001-00050dd20a82ee11.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001353c7-0005138265e2b347.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-000000000008c54a-00050f19dcc3a37f.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-0000000000136b87-0005138297768761.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-00000000000e5de4-00051292723891ca.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-120.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@6856d051d3a74eb388cac7f4e4a28857-0000000000056a8e-00050a83e2dc4a31.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@ad58fd4ada754ed7a8e4f34f48f7d404-0000000000034693-00050e71eeb13577.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000@3748a0d9714947e895474cde2dfa1509-0000000000000759-00050c186cc16a78.journal added.
Failed to add file /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal: Invalid argument
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@907a0b46df624ae6a0a26e6c05dfae0f-00000000000e5a10-0005129270971d89.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/user-1000.journal added.
File /var/log/journal/22207cfa7a3d42cbb48e15413f10137b/system@75438d26bd664af5bf188f5de40f0668-00000000001367a3-000513828f5329d2.journal added.
Error was encountered while opening journal files: Invalid argument
Directory /run/log/journal/22207cfa7a3d42cbb48e15413f10137b removed.
Directory /var/log/journal/22207cfa7a3d42cbb48e15413f10137b removed.
Root directory /var/log/journal removed.
Root directory /run/log/journal removed.
mmap cache statistics: 76 hit, 39 miss

[Nobulus]

I have a similar problem with journalctl 221, also on Archlinux and like the other accounts I read, also following an unclean shutdown, in my case, pressing reset after waiting for an ever increasing timeout on

A stop job is running for /var/lib/libvirt/images/Intel_Install

This from dmesg on start-up:

[    8.715392] systemd-journald[407]: File /var/log/journal/673d7c22fbfa46339627
4fbbeae9c374/system.journal corrupted or uncleanly shut down, renaming and replacing.
[    8.962537] systemd[1]: Started Journal Service.
[    8.978089] systemd-journald[407]: Received request to flush runtime journal from PID 1

journalctl said this

[root@archlinux ~]# journalctl  
Error was encountered while opening journal files: No data available

With debug, one journal file isn't added

Root directory /var/log/journal added.
Considering /var/log/journal/673d7c22fbfa463396274fbbeae9c374.
Directory /var/log/journal/673d7c22fbfa463396274fbbeae9c374 added.
File /var/log/journal/673d7c22fbfa463396274fbbeae9c374/system.journal added.
File /var/log/journal/673d7c22fbfa463396274fbbeae9c374/system@ae9b4b5ab33c4f1aa3db736584e9d185-00000000000469db-00050ca9698bdc59.journal added.
...
File /var/log/journal/673d7c22fbfa463396274fbbeae9c374/system@00051a2964473733-f15d6bdd8141ed81.journal~ added.
Failed to add file /var/log/journal/673d7c22fbfa463396274fbbeae9c374/system@0004f30946b8295b-e379cea217248a02.journal~: No data available
Error was encountered while opening journal files: No data available
Directory /var/log/journal/673d7c22fbfa463396274fbbeae9c374 removed.
Root directory /var/log/journal removed.
mmap cache statistics: 82 hit, 42 miss
[root@archlinux ~]#

After removing the file, journalctl behaves apparently as normal. Put it back and journalctl fails again.

[p4yne]

Hello me again, after I graduated from git bisect noob to git bisect compile pro, I discovered that there may be two distinct errors hidden in this bug.

• First: After this commit:

$ git bisect good
7b300be75e6d5755778dd7da63e7147866f21351 is the first bad commit
commit 7b300be75e6d5755778dd7da63e7147866f21351
Author: Zbigniew Jędrzejewski-Szmek <zbyszek@in.waw.pl>
Date:   Sun Mar 8 11:11:50 2015 -0400

    sd-journal: return error when we cannot open a file

    Lack of this caused journalctl not to display a hint about missing groups
    properly when the user lacks permissions.

:040000 040000 fe9e5c0fa6a8b177036d7993548e0b5b416c1b56 bbdf181b4eaf6e20d170d48bbfc91d8221d0d808 M  src

journalctl --verify does verify the journals but there is always an error thrown right at the beginning but the system.journal file passes:

 $ journalctl --verify
Error was encountered while opening journal files: Invalid argument
PASS: /run/log/journal/22207cfa7a3d42cbb48e15413f10137b/system.journal

• Second: After this commit:

$ git bisect bad
e346512c684e9efae84c6442f7e6a5781564ecde is the first bad commit
commit e346512c684e9efae84c6442f7e6a5781564ecde
Author: Lennart Poettering <lennart@poettering.net>
Date:   Wed Apr 22 22:54:23 2015 +0200

    journalctl: rework code that checks whether we have access to /var/log/journal

    - fix some memory leaks on error conditions

    - handle all error cases properly, and log about failures

    - move HAVE_ACL and no-HAVE_ACL code closer to each other

:040000 040000 ebbf5b4bb03c0b09c0ad299da4a706f141200cb5 63df76a2ea2c233a467da7b963b98e4d01fc574c M  src

Verify fails completely with the same error message as before but no verification is done any more:

$ journalctl --verify
Error was encountered while opening journal files: Invalid argument

But in contrast to @Nobulus I was not experiencing any unclean shutdowns, these errors appeared out of nowhere just after simply upgrading from sytemd-219 to systemd-221.

[poettering]

Are these some weird builds without ACLs?

Any idea what precisely is triggering the EINVAL you see? for that please gdb journalctl and set a breakpoint to set_put_error() and let it run, and provide the backtrace here when the breakpoint hits, as well as the precise numeric argument "r" of that function.

[falconindy]

These are being reported by Arch users using the distro-provided package -- we build with ACLs. I can't reproduce this error myself, so I can't provide a backtrace.

[p4yne]

There you go, this is the fresh version with the all current commits by the time of writing:

(gdb) break src/journal/sd-journal.c:68
Breakpoint 1 at 0x38550: file src/journal/sd-journal.c, line 68.
(gdb) run --verify
Starting program: /home/p4yne/Desktop/journalctl/systemd/journalctl --verify
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".

Breakpoint 1, set_put_error.lto_priv.247 (j=0x5555555c9f10, r=-22)
    at src/journal/sd-journal.c:71
71          if (r >= 0)
(gdb) bt
#0  set_put_error.lto_priv.247 (j=0x5555555c9f10, r=-22)
    at src/journal/sd-journal.c:71
#1  0x0000555555594213 in add_directory.lto_priv.245 (j=0x5555555c9f10, 
    prefix=<optimized out>, dirname=<optimized out>)
    at src/journal/sd-journal.c:1384
#2  0x0000555555594837 in add_root_directory.lto_priv.250 (j=0x5555555c9f10, 
    p=<optimized out>) at src/journal/sd-journal.c:1481
#3  0x000055555559d810 in add_search_paths.lto_priv.213 (j=0x5555555c9f10)
    at src/journal/sd-journal.c:1528
#4  0x0000555555562f97 in sd_journal_open (flags=<optimized out>, 
    ret=0x7fffffffd670) at src/journal/sd-journal.c:1629
#5  main (argc=<optimized out>, argv=0x7fffffffe148)
    at src/journal/journalctl.c:1857
(gdb)

Which fails completely again with:

(gdb) continue
Continuing.
Error was encountered while opening journal files: Invalid argument
[Inferior 1 (process 9344) exited with code 01]
(gdb) 

[so0k]

This bug still exists in journalctl v222

$ journalctl --version
systemd 222
-PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN

log tail comes out fine using sudo systemctl status <service>

[poettering]

Any chance you can redo this with all optimizations off and LTO disabled?

[p4yne]

As requested:

1. git pull origin master
2. ./autogen.sh
3. ./configure CFLAGS='-g -O0 -ftrapv' --libexecdir=/usr/lib --localstatedir=/var --sysconfdir=/etc --enable-lz4 --enable-compat-libs --enable-gnuefi --disable-audit --disable-ima --disable-kdbus --with-sysvinit-path= --with-sysvrcnd-path= --with-ntp-servers="0.arch.pool.ntp.org"
4. make
5. gdb journalctl

Reading symbols from journalctl...done.
(gdb) break src/journal/sd-journal.c:68
Breakpoint 1 at 0x96982: file src/journal/sd-journal.c, line 68.
(gdb) run --verify
Starting program: /home/p4yne/Desktop/journalctl/systemd/journalctl --verify
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".

Breakpoint 1, set_put_error (j=0x555555644f10, r=-22)
    at src/journal/sd-journal.c:71
71          if (r >= 0)
(gdb) bt
#0  set_put_error (j=0x555555644f10, r=-22) at src/journal/sd-journal.c:71
#1  0x00005555555ef54f in add_directory (j=0x555555644f10, 
    prefix=0x5555556571e0 "/var/log/journal", 
    dirname=0x55555564f1a3 "22207cfa7a3d42cbb48e15413f10137b")
    at src/journal/sd-journal.c:1384
#2  0x00005555555efc83 in add_root_directory (j=0x555555644f10, 
    p=0x7fffffffde41 "/var/log/journal") at src/journal/sd-journal.c:1481
#3  0x00005555555effb8 in add_search_paths (j=0x555555644f10)
    at src/journal/sd-journal.c:1528
#4  0x00005555555f0435 in sd_journal_open (ret=0x7fffffffdf88, flags=1)
    at src/journal/sd-journal.c:1629
#5  0x0000555555567025 in main (argc=2, argv=0x7fffffffe148)
    at src/journal/journalctl.c:1857
(gdb) continue
Continuing.
Error was encountered while opening journal files: Invalid argument
[Inferior 1 (process 14926) exited with code 01]
(gdb)

[devurandom]

I ran into this with systemd-220 (previous version being 219). It also happens to root. I do not have SELinux or anything else enabled in the system.

$ journalctl --version
systemd 222
+PAM +AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN

$ gdb journalctl 
[...]
(gdb) break set_put_error
Breakpoint 2 at 0x5555555974b0: file /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c, line 68.
(gdb) run
Starting program: /usr/bin/journalctl 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".

Breakpoint 2, set_put_error (j=0x5555555d4fe0, r=-22) at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:68
68      /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c: No such file or directory.
(gdb) bt full
#0  set_put_error (j=0x5555555d4fe0, r=-22) at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:68
        k = <optimized out>
#1  0x0000555555597a3a in add_directory (j=j@entry=0x5555555d4fe0, prefix=<optimized out>, dirname=dirname@entry=0x5555555d71e3 "da20799125212121ea1810b900000015") at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:1384
        de = 0x5555555e0ef0
        path = 0x0
        r = -22
        d = 0x5555555df230
        id = {bytes = "\332 y\221%!!!\352\030\020\271\000\000\000\025", qwords = {2387225722721214682, 1513209477901326570}}
        mid = {bytes = "\332 y\221%!!!\352\030\020\271\000\000\000\025", qwords = {2387225722721214682, 1513209477901326570}}
        m = 0x5555555e7270
        __PRETTY_FUNCTION__ = "add_directory"
        __func__ = "add_directory"
#2  0x000055555559802f in add_root_directory (j=j@entry=0x5555555d4fe0, p=<optimized out>, p@entry=0x7fffffffca31 "/var/log/journal") at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:1481
        de = 0x5555555d71d0
        id = {bytes = "\332 y\221%!!!\352\030\020\271\000\000\000\025", qwords = {2387225722721214682, 1513209477901326570}}
        d = 0x5555555d7170
        m = 0x5555555df1b0
        r = <optimized out>
        __PRETTY_FUNCTION__ = "add_root_directory"
        __func__ = "add_root_directory"
#3  0x00005555555982c0 in add_search_paths (j=0x5555555d4fe0) at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:1528
        r = <optimized out>
        search_paths = "/run/log/journal\000/var/log/journal\000"
        p = 0x7fffffffca31 "/var/log/journal"
#4  0x000055555559a33a in sd_journal_open (ret=0x7fffffffcae8, flags=<optimized out>) at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/sd-journal.c:1629
        j = 0x5555555d4fe0
        r = <optimized out>
        __PRETTY_FUNCTION__ = "sd_journal_open"
#5  0x000055555555d8f1 in main (argc=1, argv=0x7fffffffcd98) at /var/tmp/portage/sys-apps/systemd-222/work/systemd-222/src/journal/journalctl.c:1857
        r = 1
        j = 0x0
        need_seek = false
        previous_boot_id = <optimized out>
        previous_boot_id_valid = false
        first_line = true
        n_shown = 0
        ellipsized = false
        __func__ = "main"

# emerge --info systemd
Portage 2.2.20 (python 3.4.3-final-0, default/linux/amd64/13.0/desktop/plasma/systemd, gcc-4.9.3, glibc-2.20-r2, 4.1.2-gentoo x86_64)
=================================================================
                         System Settings
=================================================================
System uname: Linux-4.1.2-gentoo-x86_64-AMD_A10-7800_Radeon_R7,_12_Compute_Cores_4C+8G-with-gentoo-2.2
KiB Mem:    15315584 total,  10302264 free
KiB Swap:          0 total,         0 free
Timestamp of repository gentoo: Sun, 12 Jul 2015 05:45:01 +0000
sh bash 4.3_p39
ld GNU ld (Gentoo 2.25 p1.2) 2.25
ccache version 3.2.2 [disabled]
app-shells/bash:          4.3_p39::gentoo
dev-java/java-config:     2.2.0::gentoo
dev-lang/perl:            5.20.2-r1::gentoo
dev-lang/python:          2.7.10::gentoo, 3.3.5-r1::gentoo, 3.4.3::gentoo
dev-util/ccache:          3.2.2::gentoo
dev-util/cmake:           3.2.3::gentoo
dev-util/pkgconfig:       0.28-r3::gentoo
sys-apps/baselayout:      2.2::gentoo
sys-apps/sandbox:         2.6-r1::gentoo
sys-devel/autoconf:       2.13::gentoo, 2.69-r1::gentoo
sys-devel/automake:       1.11.6-r1::gentoo, 1.12.6::gentoo, 1.13.4::gentoo, 1.14.1::gentoo, 1.15::gentoo
sys-devel/binutils:       2.25-r1::gentoo
sys-devel/gcc:            4.9.3::gentoo
sys-devel/gcc-config:     1.8-r1::gentoo
sys-devel/libtool:        2.4.6-r1::gentoo
sys-devel/make:           4.1-r1::gentoo
sys-kernel/linux-headers: 4.1::gentoo (virtual/os-headers)
sys-libs/glibc:           2.20-r2::gentoo
Repositories:

gentoo
    location: /var/cache/portage/gentoo
    sync-type: rsync
    sync-uri: rsync://rsync.de.gentoo.org/gentoo-portage
    priority: -1000

kde
    location: /var/lib/layman/kde
    sync-type: laymansync
    sync-uri: git://anongit.gentoo.org/proj/kde.git
    masters: gentoo
    priority: 50

sage-on-gentoo
    location: /var/lib/layman/sage-on-gentoo
    sync-type: laymansync
    sync-uri: git://github.com/cschwan/sage-on-gentoo.git
    masters: gentoo
    priority: 50

local
    location: /var/cache/portage/local
    masters: gentoo
    priority: 100

ACCEPT_KEYWORDS="amd64 ~amd64"
ACCEPT_LICENSE="* -@EULA"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-pipe -O2 -march=bdver3"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/lib64/libreoffice/program/sofficerc /usr/share/config /usr/share/gnupg/qualified.txt /usr/share/themes/oxygen-gtk/gtk-2.0 /usr/share/themes/oxygen-gtk/gtk-3.0"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php5.6/ext-active/ /etc/php/cgi-php5.6/ext-active/ /etc/php/cli-php5.6/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c"
CXXFLAGS="-pipe -O2 -march=bdver3"
DISTDIR="/var/cache/portage/distfiles"
EMERGE_DEFAULT_OPTS="--keep-going --nospinner"
FCFLAGS="-O2 -pipe"
FEATURES="assume-digests binpkg-logs buildsyspkg compressdebug config-protect-if-modified distlocks ebuild-locks fixlafiles merge-sync news parallel-fetch parallel-install preserve-libs protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://ftp.spline.inf.fu-berlin.de/mirrors/gentoo/ http://ftp-stud.hs-esslingen.de/pub/Mirrors/gentoo/ http://distfiles.gentoo.org"
LANG="en_GB.UTF-8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed -Wl,--hash-style=gnu"
MAKEOPTS="-j6"
PKGDIR="/var/cache/portage/packages"
PORTAGE_COMPRESS="xz"
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages"
PORTAGE_TMPDIR="/var/tmp"
USE="X a52 aac aacplus aacs acl acpi alsa amd64 audit avahi bash-completion bdplus berkdb bluetooth bluray branding bzip2 cairo caps cdda cddb cdio cdr celt cjk cli cracklib crypt cups cxx dbus declarative dirac dri dts dvb dvd dvdr egl emboss encode exif fam fax ffmpeg firefox flac fontconfig fortran gdbm gif glamor gles gles2 gmp gpm gstreamer gtk ibus iconv ipv6 jpeg jpeg2k kde kipi ladspa latex lcms ldap libnotify libsecret lua_target_lua5-2 lv2 lz4 lzma lzo mad mmx mmxext mng modemmanager modplug modules mp3 mp4 mpeg mplayer mtp multilib multitarget mysql ncurses networkmanager nls nptl ogg openal opencl openexr opengl openmax openmp opus pam pango pch pcre pdf phonon plasma png policykit ppds pulseaudio qml qt3support qt4 qt5 readline rtmp samba scanner schroedinger sctp sdl semantic-desktop session speex spell sse sse2 ssl startup-notification subversion svg systemd tcpd theora threads tiff truetype udev udisks unicode upnp upower usb v4l vaapi vdpau vorbis vpx wavpack wayland webp widgets x264 x265 xattr xcb xcomposite xinerama xml xscreensaver xv xvid xz zeroconf zlib" ABI_X86="64" ALSA_CARDS="hda-intel" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="stage words flow sheets" CAMERAS="ptp2" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="3dnow 3dnowext mmx mmxext sse sse2 sse3" DRACUT_MODULES="btrfs caps systemd" ELIBC="glibc" ENLIGHTENMENT_MODULES="*" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ublox ubx" GRUB_PLATFORMS="coreboot efi-64 pc" INPUT_DEVICES="evdev joystick" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LINGUAS="de en en_GB ar fa" LIRC_DEVICES="devinput" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php5-5" PYTHON_SINGLE_TARGET="python2_7" PYTHON_TARGETS="python2_7 python3_3 python3_4" RUBY_TARGETS="ruby22" USERLAND="GNU" VIDEO_CARDS="radeon radeonsi r600" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account"
USE_PYTHON="2.7 3.3 3.4"
Unset:  CPPFLAGS, CTARGET, INSTALL_MASK, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS

=================================================================
                        Package Settings
=================================================================

sys-apps/systemd-222::gentoo was built with the following:
USE="acl audit elfutils gnuefi kdbus kmod lz4 lzma pam (policykit) seccomp ssl sysv-utils -apparmor -cryptsetup -curl -gcrypt -http -idn -importd -nat -qrcode (-selinux) -terminal -test -vanilla -xkb" ABI_X86="32 64 -x32"
CFLAGS="-pipe -O2 -march=bdver3 -g"
CXXFLAGS="-pipe -O2 -march=bdver3 -g"

[Lekensteyn]

Also affected by the "Bad message" error in systemd 221-2 (Arch Linux ARM).

Moving the bad file mentioned in the message below avoids the issue. Why does journalctl exit on reading errors?

$ SYSTEMD_LOG_LEVEL=debug journalctl --verify
Root directory /var/log/journal added.
Considering /var/log/journal/5c49cb5bf08724338eb09a6900092bb0.
Directory /var/log/journal/5c49cb5bf08724338eb09a6900092bb0 added.
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/system@00000000010ef127-acc6f8188769af17.journal~ added.
...
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/user-1003.journal added.
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/user-1003@17ae98a383394f95a9b2887090738288-0000000000047b28-000510f1a4fcd0c4.journal added.
Failed to add file /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/system@00000000018c8e59-da92eacc9875a421.journal~: Bad message
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/system@53cc43332f5b4a32b2577b5746ea30d5-0000000000000001-0000000000f62544.journal added.
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/system@53cc43332f5b4a32b2577b5746ea30d5-0000000000000194-000516092f280087.journal added.
...
File /var/log/journal/5c49cb5bf08724338eb09a6900092bb0/user-1002.journal added.
Error was encountered while opening journal files: Bad message
Root directory /var/log/journal removed.
Directory /var/log/journal/5c49cb5bf08724338eb09a6900092bb0 removed.
mmap cache statistics: 116 hit, 59 miss

[poettering]

Hmm, so, one of the journal files seems to trigger this behaviour, it would be really nice if one of you could isolate out which journal file that is (use journalctl --file= on each file in turn, until you find it), and append it here, so that i can reproduce this locally. Thanks!

[jleclanche]

@poettering I can reproduce it on a remote server of mine and my /var/log/journal is emptyish:

 # tree /var/log/journal                                                                ⇄
/var/log/journal
├── 323f82a03c2e4a08961b5749acbb411b
│   └── system.journal
└── remote

2 directories, 1 file

[poettering]

@jleclanche any chance you can pass me that journal file? if you don#t want to attach it here, please send it as private mail. would be very helpful to track his down.