Installer is just a blank window for 60 seconds (unless connected to network)

[Daniel van Vugt]

What happened?
Installer is just a blank window for around 60 seconds. If connected to the Internet then the blank white window only lasts about 10 seconds, which is also a bug but less severe.

What was expected?
Installer window has contents.

Steps to reproduce
1. Find a machine not connected to the Internet.
2. Boot the Ubuntu iso.

Additional context
This seems to have been happening for a few weeks at least. Confirmed again today in Noble 20240229.

Originally reported at https://github.com/canonical/ubuntu-desktop-installer/issues/2418 but I'm told that project is now deprecated(?)

[Daniel van Vugt (vanvugt)]

Confirmed still happening in 20240320.1

[Daniel van Vugt (vanvugt)]

And in 20240325.

[Dan Bungert (dbungert)]

Let's break this into parts:

1. What is ubuntu-desktop-provision waiting on during this time? /meta/status to return state==DONE ?
2. If some sort of wait is unavoidable, please consider showing something other than the white screen.

[Ubuntu QA Website (ubuntuqa)]

This bug has been reported on the Ubuntu ISO testing tracker.

A list of all reports related to this bug can be found here:
http://iso.qa.ubuntu.com/qatracker/reports/bugs/2056160

[Dennis Loose (dloose)]

The UI is waiting until subiquity reports a state other than STARTING_UP, CLOUD_INIT_WAIT, or EARLY_COMMANDS. Apparently this was added as a fix for this: https://bugs.launchpad.net/subiquity/+bug/1988042 .

This is done before the Flutter app is drawn onto the screen, which is why only the empty GTK window is visible at this point. We'll need to refactor ubuntu-desktop-provision's initialization routine to be able to show a loading screen.

[Daniel van Vugt (vanvugt)]

That fix was two years ago and looks like it was released in 22.10, so it might not fully explain why this bug is new in 24.04.

[Dennis Loose (dloose)]

I can reproduce this with today's (2024-04-05) iso in a vm without a network connection. Logs are attached.
It looks like in the first ~30 seconds the front end is still waiting for subiquity's socket to become available. For the other ~30 seconds subiquity is reporting CLOUD_INIT_WAIT.

[Dennis Loose (dloose)]

I've moved some things around in the front-end's startup routine so that the loading screen is now shown while we're waiting for subiquity to be ready.
https://github.com/canonical/ubuntu-desktop-provision/pull/589

[Olivier Gayot (ogayot)]

From my observations, there are two separate aspects to this.

First, subiquity waits for cloud-init (it takes ~30 seconds to complete in my runs). I'm not sure if there is any way to reduce this delay.

Perhaps more importantly tough, after Subiquity reports {"state": "WAITING"}, it still takes 30 more seconds until the loading animation is shown.

It looks like the UI is blocking (without a visible animation) until Subiquity sends a response to /refresh ; which times out after 30 seconds when the network is down:

24-04-05 12:24:15,379 DEBUG root:30 start: subiquity/Refresh/check_for_update:
2024-04-05 12:24:15,380 DEBUG subiquitycore.utils:119 arun_command called: ['/usr/sbin/realm', 'discover']
2024-04-05 12:24:15,396 DEBUG root:30 start: subiquity/OEM/load_metapackages_list:
2024-04-05 12:24:15,396 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_confirmation:
2024-04-05 12:24:15,396 DEBUG root:30 start: subiquity/Install/install:
2024-04-05 12:24:15,397 DEBUG root:30 start: subiquity/Filesystem/_probe:
2024-04-05 12:24:15,397 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2024-04-05 12:24:15,398 DEBUG asyncio:54 Using selector: EpollSelector
2024-04-05 12:24:15,400 INFO root:30 start: subiquity/Meta/status_GET:
2024-04-05 12:24:15,401 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "nonreportable_erro...
2024-04-05 12:24:15,425 INFO root:30 start: subiquity/Meta/client_variant_POST:
2024-04-05 12:24:15,426 INFO root:30 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2024-04-05 12:24:15,426 DEBUG root:30 start: subiquity/Refresh/GET:
2024-04-05 12:24:15,445 DEBUG urllib3.connectionpool:453 http://localhost:None "GET /v2/snaps/ubuntu-desktop-bootstrap HTTP/1.1" 200 1348
2024-04-05 12:24:15,461 DEBUG root:30 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '0+git.046d4c30'
2024-04-05 12:24:15,462 DEBUG subiquity.server.controllers.refresh:139 snap tracking , not resetting based on .disk/info
2024-04-05 12:24:15,462 DEBUG root:30 finish: subiquity/Refresh/configure_snapd: SUCCESS:
[...]

2024-04-05 12:24:48,179 DEBUG urllib3.connectionpool:453 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 234
2024-04-05 12:24:48,182 ERROR subiquity.server.controllers.refresh:197 checking for snap update failed
Traceback (most recent call last):
  File "/snap/ubuntu-desktop-bootstrap/75/bin/subiquity/subiquity/server/controllers/refresh.py", line 195, in check_for_update
    result = await self.app.snapdapi.v2.find.GET(select="refresh")
  File "/snap/ubuntu-desktop-bootstrap/75/bin/subiquity/subiquity/common/api/client.py", line 47, in impl
    async with make_request(
  File "/snap/ubuntu-desktop-bootstrap/75/usr/lib/python3.10/contextlib.py", line 199, in __aenter__
    return await anext(self.gen)
  File "/snap/ubuntu-desktop-bootstrap/75/bin/subiquity/subiquity/server/snapdapi.py", line 298, in make_request
    content = await async_snapd.get(path[1:], **params)
  File "/snap/ubuntu-desktop-bootstrap/75/bin/subiquity/subiquitycore/snapd.py", line 226, in g...

[Dennis Loose (dloose)]

In addition to showing the loading screen as early as possible, we've also removed the unneeded early call to /refresh here: https://github.com/canonical/ubuntu-desktop-provision/pull/592

I think that's all we can do on the front end side to minimize the loading time.

[Daniel van Vugt (vanvugt)]

Thanks, I saw the improvement when testing 20240408 last night, but think we'll need a new bug report. Because the loading animation now runs for 50 seconds, which is kind of crazy when the user's just sitting there waiting.

[Daniel van Vugt (vanvugt)]

Moved to bug 2060616.