Crash when running on console on arm64 qemu

[Alfonso Sanchez-Beato]

subiquity is crashing when running the arm64 installer on qemu, after the user creation screen:

Traceback (most recent call last):
  File "/snap/subiquity/2281/usr/bin/subiquity", line 33, in <module>
    sys.exit(load_entry_point('subiquity==0.0.5', 'console_scripts', 'subiquity-tui')())
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquity/cmd/tui.py", line 142, in main
    subiquity_interface.run()
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquity/client/client.py", line 326, in run
    super().run()
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/tui.py", line 338, in run
    super().run()
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/core.py", line 136, in run
    raise exc
  File "/snap/subiquity/2281/usr/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/raw_display.py", line 404, in <lambda>
    event_loop, callback, self.get_available_raw_input())
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/raw_display.py", line 502, in parse_input
    callback(processed, processed_codes)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/main_loop.py", line 411, in _update
    self.process_input(keys)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/main_loop.py", line 511, in process_input
    k = self._topmost_widget.keypress(self.screen_size, k)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/wimp.py", line 648, in keypress
    return self._current_widget.keypress(size, key)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquity/ui/frame.py", line 36, in keypress
    return super().keypress(size, key)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/ui/container.py", line 178, in keypress
    upkey = self.focus.keypress(tsize, downkey)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/view.py", line 107, in keypress
    key = super().keypress(size, key)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/ui/stretchy.py", line 159, in keypress
    return self.top_w.keypress(top_size, key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/decoration.py", line 840, in keypress
    return self._original_widget.keypress((maxcol,maxrow-top-bottom), key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/decoration.py", line 622, in keypress
    return self._original_widget.keypress(maxvals, key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/container.py", line 1590, in keypress
    key = self.focus.keypress(tsize, key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/container.py", line 2271, in keypress
    key = w.keypress((mc,) + size[1:], key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/decoration.py", line 840, in keypress
    return self._original_widget.keypress((maxcol,maxrow-top-bottom), key)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/decoration.py", line 622, in keypress
    return self._original_widget.keypress(maxvals, key)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/ui/container.py", line 178, in keypress
    upkey = self.focus.keypress(tsize, downkey)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/decoration.py", line 622, in keypress
    return self._original_widget.keypress(maxvals, key)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquitycore/ui/container.py", line 178, in keypress
    upkey = self.focus.keypress(tsize, downkey)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/wimp.py", line 540, in keypress
    self._emit('click')
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/widget.py", line 460, in _emit
    signals.emit_signal(self, name, self, *args)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/signals.py", line 265, in emit
    result |= self._call_callback(callback, user_arg, user_args, args)
  File "/snap/subiquity/2281/usr/lib/python3/dist-packages/urwid/signals.py", line 295, in _call_callback
    return bool(callback(*args_to_pass))
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquity/ui/views/installprogress.py", line 260, in ok
    self.app.remove_global_overlay(self)
  File "/snap/subiquity/2281/lib/python3.6/site-packages/subiquity/client/client.py", line 360, in remove_global_overlay
    self.global_overlays.remove(overlay)
ValueError: list.remove(x): x not in list

See also attached crash file.

[Michael Hudson-Doyle (mwhudson)]

Is this reproducible? I have seen it once in a blue moon in my testing, the best kind of bug :/

[Michael Hudson-Doyle (mwhudson)]

Ah so the crash report is for another bug that has been fixed now. Not sure about the traceback in the description.

[Michael Hudson-Doyle (mwhudson)]

Hmm I have an idea how this might have happened. Was it a partly-interactive install by any chance?

https://github.com/canonical/subiquity/pull/940 should help.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@Michael, I can reproduce easily with the latest 20.04 installer for arm64, and running it on qemu with:

fallocate -l 8G disk.img && sync
qemu-system-aarch64 -machine virt -cpu cortex-a57 -smp 2 -m 4096 \
                    -device virtio-gpu-pci \
                    -usb -device qemu-xhci,id=xhci -device usb-mouse -device usb-kbd \
                    -bios /usr/share/AAVMF/AAVMF_CODE.fd \
                    -netdev user,id=net0,hostfwd=tcp::8022-:22 \
                    -device virtio-net-pci,netdev=net0 \
                    -drive if=virtio,file=disk.img,format=raw \
                    -cdrom ubuntu-20.04.2-live-server-arm64.iso \
                    -serial mon:stdio -semihosting

Sometimes, the crash generator crashed itself, maybe that's the reason for the traceback not being the same as the file I attached.

Is the snap with the fix going to be available in some channel soon?

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Also, no it was not a partly-interactive install. Something interesting and maybe related I was seeing is that after a selection on a screen, before printing the new screen, an unrelated screen appears for a couple of seconds (maybe slow emulation makes this happen more easily).

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

This is the crash file that corresponds to the backtrace in the description.

[Dan Bungert (dbungert)]

Thanks for the detailed reproduction scenario Alfonso, I was able to see the same crash using the nightly iso and your steps.
Also retest with the latest code from main appears to resolve this.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Unfortunately, I am still seeing this with the snap in edge (version 21.04.2+git1.2719c57c, revision 2398).

Full crash report: https://paste.ubuntu.com/p/9yf3FY8kTx/

This is the backtrace:

Traceback:
 Traceback (most recent call last):
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquity/client/client.py", line 364, in run
     super().run()
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/tui.py", line 374, in run
     super().run()
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/core.py", line 128, in run
     raise exc
   File "/snap/subiquity/2398/usr/lib/python3.6/asyncio/events.py", line 145, in _run
     self._callback(*self._args)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/raw_display.py", line 404, in <lambda>
     event_loop, callback, self.get_available_raw_input())
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/raw_display.py", line 502, in parse_input
     callback(processed, processed_codes)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/main_loop.py", line 411, in _update
     self.process_input(keys)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/main_loop.py", line 511, in process_input
     k = self._topmost_widget.keypress(self.screen_size, k)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/wimp.py", line 648, in keypress
     return self._current_widget.keypress(size, key)
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquity/ui/frame.py", line 36, in keypress
     return super().keypress(size, key)
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/ui/container.py", line 178, in keypress
     upkey = self.focus.keypress(tsize, downkey)
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/view.py", line 107, in keypress
     key = super().keypress(size, key)
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/ui/stretchy.py", line 159, in keypress
     return self.top_w.keypress(top_size, key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/decoration.py", line 840, in keypress
     return self._original_widget.keypress((maxcol,maxrow-top-bottom), key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/decoration.py", line 622, in keypress
     return self._original_widget.keypress(maxvals, key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/container.py", line 1590, in keypress
     key = self.focus.keypress(tsize, key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/container.py", line 2271, in keypress
     key = w.keypress((mc,) + size[1:], key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/decoration.py", line 840, in keypress
     return self._original_widget.keypress((maxcol,maxrow-top-bottom), key)
   File "/snap/subiquity/2398/usr/lib/python3/dist-packages/urwid/decoration.py", line 622, in keypress
     return self._original_widget.keypress(maxvals, key)
   File "/snap/subiquity/2398/lib/python3.6/site-packages/subiquitycore/ui/container.py", line 178, in keypress
     upkey = self.focus.keyp...

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Note that I can reproduce the error on qemu, but also on our real target (an arm64 server).

[Alex Kaluzhny (alex-kaluzhny)]

@Dan,
Any word on when this issue can be resolved?
It is impacting delivery to the customer.

[Dan Bungert (dbungert)]

I have a workaround, but testing is slow (arm / not happening for me 100% of the time) and I wanted to do a better fix.
If a workaround is good enough for now I can get you that shortly.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

To clarify the situation, with a subiquity with the changes mentioned in comment #4, it is quite difficult to me to reproduce the bug. I have seen it again only when subiquity has crashed previously due to some other problem. So I do not think this is super-critical anymore.

@Dan, the workaround you mention is the one from comment #4 or it is something else?

[Dan Bungert (dbungert)]

@Alfonso - my change was a different item. Basically, we try to remove something from a list that isn't there and python doesn't like that. So I just not remove the thing from the list in that case. But this just masks an underlying problem in that we shouldn't even be trying to redundantly remove an item from the list.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@Dan is this already in the stable channel? If not, when is it planned to land?

[Dan Bungert (dbungert)]

@Alfonso - no, the last stable build was on April-20. I can discuss with mwhudson.

[Michael Hudson-Doyle (mwhudson)]

We discussed this and will aim to get a stable release out next week.