Bug 1804993

Proposed as a Blocker for 32-final by Fedora user chrismurphy using the blocker tracking app because:

 Final: All system services present after installation with one of the release-blocking package sets must start properly, unless they require hardware which is not present.

Created attachment 1664246 [details]
journal

Discussed during the 2020-02-24 blocker review meeting: [1]

The decision to classify this bug as an AcceptedBlocker was made:

"All system services present after installation with one of the release-blocking package sets must start properly, unless they require hardware which is not present."

[1] https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2020-02-24/f32-blocker-review.2020-02-24-17.00.log.txt

I’ll take a look.

I am unable to reproduce the issue on Fedora-Workstation-Live-x86_64-32-20200224.n.0.

And the service is running after installation without me touching anything. I’m going to close this unless you can give me a clear reproducer.

(In reply to Chris Murphy from comment #2)
> Created attachment 1664246 [details]
> journal

This is full of noise.

Please take a look at https://bugzilla.redhat.com/show_bug.cgi?id=1433652#c13. Could be an issue with your storage configuraiton.

I’ll add a better error message to suggest verifying the state of the journal, but this cannot be blocked on without information from you.

I can't reproduce with Fedora-Workstation-Live-x86_64-32-20200226.n.0.iso on baremetal. I did get two reproducers in VMs over a week ago. Clean install, reboot, and the unit fails.

re: bug 1433652#c13, I don't have a corrupt journal in this case, but if there were a corrupt journal I think abrt-xorg.service needs to be able to handle it gracefully, rather than the service unit failing. Journal corrupt is less common these days but it's still an ordinary event. Systemd devs have said it's not a big deal, the file can still be read, just the corrupt records are skipped over, and the journal is rotated out anyway.

If I find a more consistent reproducer, I'll reopen.

I can suggest adding -v, -vv or -vvv to the service unit and seeing what kind of error libsystemd is returning (genius idea to print the error at a higher log level, so it doesn’t normally appear), because it seems to be happening on that side exclusively. We only try to get some data from it and, if it returns an error, then it returns an error and we can only bail out. If we can narrow down the error, maybe we can add some fail-safes and not explode, but I do not have a reliable reproducer.

Merely having a system and/or user journal corrupt, doesn't trigger this...


$ sudo journalctl --verify
[sudo] password for chris: 
Sorry, try again.
[sudo] password for chris: 
PASS: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/system~                             
4baf58: Invalid entry item (7/32 offset: 000000                                                                                       
4baf58: Invalid object contents: Bad message                                                                                          
File corruption detected at /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/user-1000~:4baf58 (of 8388608 bytes, 59%).
FAIL: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/user-1000~ (Bad message)
2f76f00: Invalid entry item (12/27 offset: 000000                                                                                     
2f76f00: Invalid object contents: Bad message                                                                                         
File corruption detected at /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/system~:2f76f00 (of 50331648 bytes, 98%).
FAIL: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/system~ (Bad message)
PASS: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/system.journal                                                                
PASS: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/user-1000~                          
PASS: /var/log/journal/26336922e1044e80ae4bd42e1d6b9099/user-1000.journal                                                             
$ systemctl status abrt-xorg.service
● abrt-xorg.service - ABRT Xorg log watcher
     Loaded: loaded (/usr/lib/systemd/system/abrt-xorg.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2020-03-05 12:08:52 MST; 1min 20s ago
   Main PID: 764 (abrt-dump-journ)
      Tasks: 1 (limit: 3459)
     Memory: 19.5M
        CPU: 36ms
     CGroup: /system.slice/abrt-xorg.service
             └─764 /usr/bin/abrt-dump-journal-xorg -fxtD

Mar 05 12:08:52 localhost.localdomain systemd[1]: Started ABRT Xorg log watcher.
$ 


It's fairly trivial to corrupt a systemd journal, just by forcing power off on a VM. Such sabotage probably makes any discovered bug not a blocker, but still a valid way of checking for proper error handling. Yet I still can't trigger it.

Okay, so I’ll just go through the code path and bump the log level for error messages, so we can get more information the next time this happens.