[21.04] autoinstall reports crashes

[Marian Gasparovic]

It may be nothing, maybe just better messages are needed.

Installing 21.04 with autoinstall on s390x. During the process I can see several times it created crash file. Install finishes fine, there is nothing in /var/crash

I can see those messages in installer-journal.txt

ubuntu@genrl03:/var/log/installer$ grep -B1 crash installer-journal.txt
...
--
Apr 15 14:09:31 ubuntu-server subiquity_log.1900[2290]: Running command ['lvremove', '--force', '--force', 'ubuntu-vg/mg-lv'] with allowed return codes [0] (capture=False)
Apr 15 14:09:34 ubuntu-server subiquity_event.1900[1900]: subiquity/ErrorReporter/1618495768.247747421.unknown/add_info: written to /var/crash/1618495768.247747421.unknown.crash
--
Apr 15 14:10:53 ubuntu-server subiquity_event.1900[1900]: subiquity/Meta/status_GET
Apr 15 14:10:57 ubuntu-server subiquity_event.1900[1900]: subiquity/ErrorReporter/1618495851.512825489.server_request_fail/add_info: written to /var/crash/1618495851.512825489.server_request_fail.crash
--
Apr 15 14:12:02 ubuntu-server subiquity.subiquity-server[1900]: start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
Apr 15 14:12:02 ubuntu-server subiquity.subiquity-server[1900]: finish: subiquity/ErrorReporter/1618495768.247747421.unknown/add_info: SUCCESS: written to /var/crash/1618495768.247747421.unknown.crash
--
Apr 15 14:12:02 ubuntu-server subiquity.subiquity-server[1900]: start: subiquity/Meta/status_GET:
Apr 15 14:12:02 ubuntu-server subiquity.subiquity-server[1900]: finish: subiquity/ErrorReporter/1618495851.512825489.server_request_fail/add_info: SUCCESS: written to /var/crash/1618495851.512825489.server_request_fail.crash
--
Apr 15 14:12:27 ubuntu-server curtin_event.1900[2290]: start: cmd-install/stage-hook/builtin: running 'curtin hook'
Apr 15 14:12:27 ubuntu-server subiquity_event.1900[1900]: subiquity/ErrorReporter/1618495942.050987005.server_request_fail/add_info: written to /var/crash/1618495942.050987005.server_request_fail.crash
--
Apr 15 14:12:40 ubuntu-server subiquity.subiquity-server[1900]: start: subiquity/Meta/status_GET:
Apr 15 14:12:40 ubuntu-server subiquity.subiquity-server[1900]: finish: subiquity/ErrorReporter/1618495942.050987005.server_request_fail/add_info: SUCCESS: written to /var/crash/1618495942.050987005.server_request_fail.crash
--
Apr 15 14:13:55 ubuntu-server subiquity_log.1900[9903]: update-initramfs: Generating /boot/initrd.img-5.11.0-14-generic
Apr 15 14:13:58 ubuntu-server subiquity_event.1900[1900]: subiquity/ErrorReporter/1618496032.512823582.server_request_fail/add_info: written to /var/crash/1618496032.512823582.server_request_fail.crash

[Michael Hudson-Doyle (mwhudson)]

That's strange! Can you attach the /var/log/installer/server-subiquity-debug.log.* files that should be copied to the installed system?

[Michael Hudson-Doyle (mwhudson)]

So I don't totally understand what's going on here but there seems to be a problem with how we're running subiquity on the serial line. We get these messages in the journal:

Apr 15 14:12:22 ubuntu-server systemd[1]: <email address hidden>: start-pre operation timed out. Terminating.

So it seems the subiquity client (on the serial line) gets killed every 90s. The cancelled errors in the server part are from the client going away, I guess they shouldn't trigger crash reports really. I don't understand why this doesn't seem too be a problem for regular users of subiquity on the serial line though!

Fortunately (?) the way we override systemd stuff to run on the serial console is excessively complicated and we can delete most of it.

(Not in time for hirsute release though)

[Frank Heimes (fheimes)]

The weirdness is here that the logs say that a crash happens, but there are no crash reports written.

The fact that the subiquity client is (re-)started (well and killed) every 90 secs is not new - this happens since quite a while (and was mentioned before).

The 'good' thing here is that from a user perspective it just looks like bad and misleading messages.
(As long as no VLAN config is used, see LP1924794) the autoinstall still completes successfully.

I understand that it's difficult to get this resolved prior to hirsute release, but should be solved and cleaned-up at least afterwards.

[Frank Heimes (fheimes)]

https://code.launchpad.net/~mwhudson/livecd-rootfs/+git/livecd-rootfs/+merge/401501

[Frank Heimes (fheimes)]

While testing LP#1924794, that allows me to successfully do an autoinstall on a LPAR that is attached to a VLAN, I (post-install) still found some glitches in the logs:

subiquity-server-debug.log:2021-05-12 07:25:21,559 DEBUG subiquity.server.server:351 request to /meta/status?cur=%22POST_RUNNING%22 crashed
subiquity-server-debug.log:2021-05-12 07:25:21,560 DEBUG subiquitycore.common.errorreport:383 generating crash report
subiquity-server-debug.log:2021-05-12 07:25:21,560 INFO subiquitycore.common.errorreport:406 saving crash report 'request to /meta/status?cur=%22POST_RUNNING%22 crashed with CancelledError' to /var/crash/1620804321.560399294.server_request_fail.crash
subiquity-server-debug.log:2021-05-12 07:25:27,852 INFO root:39 finish: subiquity/ErrorReporter/1620804321.560399294.server_request_fail/add_info: SUCCESS: written to /var/crash/1620804321.560399294.server_request_fail.crash
subiquity-server-info.log:2021-05-12 07:25:21,560 INFO subiquitycore.common.errorreport:406 saving crash report 'request to /meta/status?cur=%22POST_RUNNING%22 crashed with CancelledError' to /var/crash/1620804321.560399294.server_request_fail.crash
subiquity-server-info.log:2021-05-12 07:25:27,852 INFO root:39 finish: subiquity/ErrorReporter/1620804321.560399294.server_request_fail/add_info: SUCCESS: written to /var/crash/1620804321.560399294.server_request_fail.crash

Obviously not super critical, since the install completed (and no real crash files found at the system), but maybe still worth to have a look at.

[Michael Hudson-Doyle (mwhudson)]

I think the fix for this bug migrated into the relevant places in time for the 20210512 but not the 20210511 image so could you try the 20210512 (or later) image if you have time?

[Frank Heimes (fheimes)]

Hi Michael,
I just retried with the image from May 14th (today) and it looks fine now, great.
I just get these (if grabbing wildly in /var/log/installer for crash):

installer-journal.txt:May 14 13:50:07 ubuntu-server systemd[1]: Condition check resulted in Unix socket for apport crash forwarding being skipped.
installer-journal.txt:May 14 13:50:07 ubuntu-server systemd[1]: Starting LSB: automatic crash report generation...
installer-journal.txt:May 14 13:50:07 ubuntu-server apport[1138]: * Starting automatic crash report generation: apport
installer-journal.txt:May 14 13:50:07 ubuntu-server systemd[1]: Started LSB: automatic crash report generation.

And these seem to be valid and okay.

The only thing that I've noticed is that message (which is unrelated to this bug):

  [ 20.258888] systemd[1]: serial-getty@sclp_line0.service: Service has more than
   one ExecStart= setting, which is only allowed for Type=oneshot services. Refusing.

Not sure if that can be simply ignored or not ...

Nevertheless, this bug seem to be fixed with the image from May 14th - thx !

[Michael Hudson-Doyle (mwhudson)]

This seems to be fixed in impish dailies.

[Michael Hudson-Doyle (mwhudson)]

Need to backport the fixes to 20.04 before the point release though.

[Frank Heimes (fheimes)]

I tested the updated livecd-rootfs that is part of the new live-server image that Łukasz created:
http://cdimage.ubuntu.com/ubuntu-server/focal/daily-live/20210805.1/
and did a couple of installations (mainly LPAR with the more complex FCP/multipath) and so far the autoinstall ran flawlessly, I didn't noticed any error or crashes (even after checking post-install), the autoinstall triggered a proper post-install reboot and I could login.
So I consider this now as successfully verified and think that we can close this ticket.

[Michael Hudson-Doyle (mwhudson)]

Oh oops I didn't reference this bug in the livecd-rootfs upload. Oh well. Glad to know the change helps :)

[Frank Heimes (fheimes)]

Since 20.04.3 got released today, where this is solved, I'm closing this ticket as Fix Released.