subiquity crashes after manual update with snap refresh in installer shell

[Frank Heimes]

I started a 21.04 installation on s390x in a z/VM guest that which came up fine.
At the very beginning an second screen (after language selection) I navigated to the installer shell and did a snap refresh for being able to test a special installer build.
The snap refresh of subiquity just seem to complete fine and the prompt is coming back, but a second after this I get the following crash - and afterwards I'm no longer able to re-login:

root@ubuntu-server:/# sudo snap refresh subiquity --channel=edge/mwhudson-hack
subiquity (edge/mwhudson-hack) 0+git.de29ffe0 from Canonical* refreshed
root@ubuntu-server:/# generating crash report
report saved to /var/crash/1616658730.371623516.ui.crash
Traceback (most recent call last):
  File "/snap/subiquity/2278/usr/bin/subiquity", line 33, in <module>
    sys.exit(load_entry_point('subiquity==0.0.5', 'console_scripts', 'subiquity-tui')())
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/cmd/tui.py", line 142, in main
    subiquity_interface.run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/client/client.py", line 326, in run
    super().run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/tui.py", line 338, in run
    super().run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/core.py", line 136, in run
    raise exc
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/context.py", line 148, in decorated_async
    return await meth(self, **kw)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/client/controllers/progress.py", line 79, in _wait_status
    cur=self.app_state)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/api/client.py", line 49, in impl
    return serializer.deserialize(r_ann, await resp.json())
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 131, in deserialize
    return self._deserialize_attr(annotation, value, metadata, path)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 121, in _deserialize_attr
    field, value[field.name], path))
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 114, in _deserialize_field
    field.type, value, field.metadata, path)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 138, in deserialize
    return getattr(annotation, value)
  File "/snap/subiquity/2278/usr/lib/python3.6/enum.py", line 326, in __getattr__
    raise AttributeError(name) from None
AttributeError: CLOUD_INIT_WAIT
Connection to hwe0006 closed.
fheimes@T570:~$

The same happens if I'm using 20.04.2, but the difference that I can re-login there after the crash happened.

I've attached the entire complete console and shell output.

[Frank Heimes (fheimes)]

While running into this and trying some more times I came across a situation where the installer wasn't able to connect anymore, since I believe that this can be related to the above, I'm attaching two screenshots about this situation, too.

[Michael Hudson-Doyle (mwhudson)]

OK I think I've fixed the cause of the crash but I don't know why you wouldn't have been able to log in again :(

[Frank Heimes (fheimes)]

I retried after the recent changes using a 20.04.2 image and doing a manual update,
but still see the error/crash, but I'm now able to re-login afterwards.
And that allowed me to complete the installation and also to gather the logs and crash files:

...
Installer shell session activated.

This shell session is running inside the installer environment. You
will be returned to the installer when this shell is exited, for
example by typing Control-D or 'exit'.

Be aware that this is an ephemeral environment. Changes to this
environment will not survive a reboot. If the install has started, the
installed system will be mounted at /target.
root@ubuntu-server:/# snap list
Name Version Rev Tracking Publisher Notes
core18 20201210 1945 latest/stable canonical* base
lxd 4.0.5 19189 4.0/stable/… canonical* -
snapd 2.48.2 10704 latest/stable canonical* snapd
subiquity 21.01.2 2278 latest/stable/… canonical* classic
root@ubuntu-server:/#
root@ubuntu-server:/# snap refresh subiquity --channel=edge/mwhudson-hack
subiquity (edge/mwhudson-hack) 0+git.de29ffe0 from Canonical* refreshed
root@ubuntu-server:/# generating crash report
report saved to /var/crash/1617171065.612380743.ui.crash
Traceback (most recent call last):
  File "/snap/subiquity/2278/usr/bin/subiquity", line 33, in <module>
    sys.exit(load_entry_point('subiquity==0.0.5', 'console_scripts', 'subiquity-tui')())
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/cmd/tui.py", line 142, in main
    subiquity_interface.run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/client/client.py", line 326, in run
    super().run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/tui.py", line 338, in run
    super().run()
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/core.py", line 136, in run
    raise exc
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquitycore/context.py", line 148, in decorated_async
    return await meth(self, **kw)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/client/controllers/progress.py", line 79, in _wait_status
    cur=self.app_state)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/api/client.py", line 49, in impl
    return serializer.deserialize(r_ann, await resp.json())
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 131, in deserialize
    return self._deserialize_attr(annotation, value, metadata, path)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 121, in _deserialize_attr
    field, value[field.name], path))
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 114, in _deserialize_field
    field.type, value, field.metadata, path)
  File "/snap/subiquity/2278/lib/python3.6/site-packages/subiquity/common/serialize.py", line 138, in deserialize
    return getattr(annotation, value)
  File "/snap/subiquity/2278/usr/lib/python3.6/enum.py", line 326, in __getattr__
    raise AttributeError(name) from None
AttributeError: CLOUD_IN...

[Frank Heimes (fheimes)]

Now retrying again with edge (and not edge/mwhudson-hack), the situation is a bit different.

A different crash happens and I can see the subiquity UI for a second after manual refresh, but get a different crash then:

Installer shell session activated.

This shell session is running inside the installer environment. You
will be returned to the installer when this shell is exited, for
example by typing Control-D or 'exit'.

Be aware that this is an ephemeral environment. Changes to this
environment will not survive a reboot. If the install has started, the
installed system will be mounted at /target.
root@ubuntu-server:/# snap list
Name Version Rev Tracking Publisher Notes
core18 20201210 1945 latest/stable canonical* base
lxd 4.0.5 19189 4.0/stable/… canonical* -
snapd 2.48.2 10704 latest/stable canonical* snapd
subiquity 21.01.2 2278 latest/stable/… canonical* classic
root@ubuntu-server:/#
# snap refresh subiquity --channel=edge
...
### I can see here the graphical UI popping up for a second ...

### shell output:
...
    tcsetattr(fd, when, mode)
termios.error: (5, 'Input/output error')

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/snap/subiquity/2349/usr/bin/subiquity", line 33, in <module>
    sys.exit(load_entry_point('subiquity==0.0.5', 'console_scripts', 'subiquity-tui')())
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/cmd/tui.py", line 142, in main
    subiquity_interface.run()
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/client/client.py", line 350, in run
    super().run()
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquitycore/tui.py", line 344, in run
    self.urwid_loop.stop()
  File "/snap/subiquity/2349/usr/lib/python3/dist-packages/urwid/main_loop.py", line 362, in stop
    self.event_loop.remove_enter_idle(self.idle_handle)
AttributeError: 'MainLoop' object has no attribute 'idle_handle'
Connection to 10.245.236.26 closed.
fheimes@T570:~$

### and I can see this crash looping in the (3270) console

Traceback (most recent call last):
  File "/snap/subiquity/2349/usr/bin/subiquity", line 33, in <module>
    sys.exit(load_entry_point('subiquity==0.0.5', 'console_scripts', 'subiquity-
tui')())
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/cmd/tui.py",
line 142, in main
    subiquity_interface.run()
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/client/client
.py", line 350, in run
    super().run()
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquitycore/tui.py",
line 341, in run
    super().run()
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquitycore/core.py",
 line 136, in run
    raise exc
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/client/client
.py", line 290, in start
    texts = ssh_help_texts(ssh_info)
  File "/snap/subiquity/2349/lib/python3.6/site-packages/subiquity/ui/views/help
.py", line 151, in ssh_help_texts
    if len(ssh_info.ips) > 0:
AttributeError: 'coroutine' object has no attribute 'ips'
connecting... -
generating cr...

[Frank Heimes (fheimes)]

and btw. after reconnecting I was able to complete the install ...

[Michael Hudson-Doyle (mwhudson)]

OK that was about a million types harder than I expected but I think these two PRs together:

https://github.com/canonical/subiquity/pull/927
https://github.com/canonical/subiquity/pull/928

fix this once and for all.

[Frank Heimes (fheimes)]

Since I just updated the install server with the latest 21.04 daily (for testing a different topic), I thought about retrying the update situation again.

It looks now a bit different, I don't see a crash, and I'm again at the UI again after having done a manual refresh, but then I'm suddenly falling back to the shall.
Exiting from there (and hitting Enter once again) brings me back to a working installer.
Since it's a bit difficult to explain, I've attached a one minute screen recording ...

[Michael Hudson-Doyle (mwhudson)]

So the bug I'm fixing is in the version of subiquity you're upgrading *from*, so until there is an image with bug fix in, you can't really test it. That behaviour there is confusing but sort of makes sense -- the shell you are interacting with is not being killed when subiquity restarts, and part of the fix for this issue means that the new subiquity doesn't crash (to my slight surprise!). The other part of the fix kills any foreground subprocess (i.e. the shell proccess) before restarting the client. I'll let you know when there is media to test :)