cloudinit.sources.DataSourceEc2:583 Calling 'None' failed

Similar issue with todays candidate on ubuntu-budgie

After 90 seconds the blank window changes to the installer and the installation continues successfully.

I've attached the install tarball log

I see this after 90 seconds when the installer properly appears and continues

flutter: INFO subiquity_server: ApplicationState.WAITING

No change with 2024-02-27 Candidate.

No change with 2024-02-29 candidate. Terminal output below:

--

$ ubuntu-desktop-bootstrap --try-or-install

(ubuntu_bootstrap:5321): Gdk-CRITICAL **: 19:33:25.999: gdk_window_get_state: assertion 'GDK_IS_WINDOW (window)' failed

(ubuntu_bootstrap:5321): Gtk-WARNING **: 19:33:26.012: /usr/lib/x86_64-linux-gnu/gtk-3.0/3.0.0/immodules/im-ibus.so: undefined symbol: ibus_input_context_set_post_process_key_event

(ubuntu_bootstrap:5321): Gtk-WARNING **: 19:33:26.012: Loading IM context type 'ibus' failed
flutter: INFO ubuntu_bootstrap: Logging to /var/log/installer/ubuntu_bootstrap.log
flutter: WARNING subiquity_server: Unable to find the subiquity_client package. Falling back to the current working dir: /home/edubuntu
flutter: INFO subiquity_server: Waiting server up to 90 seconds
flutter: INFO subiquity_server: ApplicationState.WAITING
flutter: DEBUG config: Loaded config file from /usr/share/desktop-provision/whitelabel.yaml
flutter: INFO flavor_provider: Using flavor from config: UbuntuFlavor.edubuntu
flutter: INFO subiquity_client: Opening socket to Endpoint(/run/subiquity/socket )
flutter: DEBUG desktop: Disabling automounting
flutter: DEBUG subiquity_client: POST http://localhost/meta/client_variant?variant=%22desktop%22
flutter: DEBUG subiquity_client: GET http://localhost/refresh?wait=true
flutter: DEBUG telemetry: Writing report to /var/log/installer/telemetry
flutter: DEBUG subiquity_client: ==> setVariant(Variant.DESKTOP) null
flutter: DEBUG subiquity_client: ==> checkRefresh() {"availability": "UNAVAILABLE", "current_snap_version": "0+git.f9c15278", "new_snap_version": ""}
flutter: DEBUG refresh: RefreshState.status(status: RefreshStatus(availability: RefreshCheckState.UNAVAILABLE, currentSnapVersion: 0+git.f9c15278, newSnapVersion: ))
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.4905, logSyslogId: subiquity_log.4905, eventSyslogId: subiquity_event.4905)
flutter: DEBUG subiquity_client: POST http://localhost/meta/mark_configured?endpoint_names=%5B%22mirror%22%2C%22proxy%22%2C%22ssh%22%2C%22snaplist%22%2C%22ubuntu_pro%22%5D
flutter: DEBUG subiquity_client: ==> markConfigured([mirror, proxy, ssh, snaplist, ubuntu_pro]) null
flutter: DEBUG desktop: Disabling screen blanking
flutter: DEBUG desktop: Disabling screensaver
flutter: DEBUG desktop: Inhibiting Gnome session
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.4905, logSyslogId: subiquity_log.4905, eventSyslogId: subiquity_event.4905)
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.4905, logSyslogId: subiquity_log.4905, eventSyslogId: subiquity_event.4905)
flutter: DEBUG subiquity_client: GET http://localhost/meta/interactive_sections
flutter: DEBUG subiquity_client: ==> getInteractiveSections() null
flutter: INFO locale: Loaded 75 languages
flutter: DEBUG subiquity_...

2024-02-26 19:29:49,617 WARNING cloudinit.sources.DataSourceEc2:583 Calling 'None' failed [119/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data/instance-id (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x74a6d282ad70>, 'Connection to 169.254.169.254 timed out. (connect timeout=18.0)'))]
2024-02-26 19:29:49,618 DEBUG cloudinit.url_helper:305 [0/1] open 'http://[fd00:ec2::254]/2009-04-04/meta-data/instance-id' with {'url': 'http://[fd00:ec2::254]/2009-04-04/meta-data/instance-id', 'stream': False, 'allow_redirects': True, 'method': 'GET', 'timeout': 0.0} configuration
2024-02-26 19:29:49,619 WARNING cloudinit.sources.DataSourceEc2:583 Calling 'None' failed [119/120s]: unexpected error [Attempted to set connect timeout to 0.0, but the timeout cannot be set to a value less than or equal to 0.]
2024-02-26 19:29:49,619 DEBUG cloudinit.url_helper:670 Please wait 1 seconds while we wait to try again

Thanks for filing this bug.

While we triage, it would be helpful if we can attach the results of `sudo cloud-init collect-logs` during the installation stage to this bug?
 - ideally we want to look at /run/cloud-init/ds-identify.log and the full /var/log/cloud-init.log which will give us more guidance on why Ec2 is even selected in the first place.

Reflecting this context to the bug instead of IRC messages.

There are a number of issues at play here:

1. edubuntu images do not provide /var/lib/cloud/seed/nocloud/user-data or meta-data files which allow cloud-init in Ubuntu Desktop images to detect cloud-init's NoCloud datasource.

2. /usr/lib/cloud-init/ds-identify is used to quickly limit any viable datasources on a system during systemd generator timeframe. inability to find any datasources will leave cloud-init with a disabled status.

3. subiquity (and live desktop images) make a call to cloud-init status to block on cloud-init completion: either disabled or enabled with user-data

4. subiquity calls cloud-init's stages.Init() function to query for any actionable `autoinstall` key in user-data presented in #cloud-config provided to the machine at boot.

The problem appears due to cloud-init being disabled/inert due to step #2.
Subiquity's subsequent waiting on cloud-init status doesn't consider `disabled` state of cloud-init in #3 and invokes stages.Init() directly in step #4 when there really isn't any possible way we'd have user-data.

The side-effect of cloud-init's stages.Init() call is: if no detected datasources are present, stages.Init() is trying to be helpful and try discovering datasources for you at runtime. Since ds-identify never found any datasource, it didn't limit the list of all potential datasources in /etc/cloud/cloud.cfg.d/90_dpkg.cfg. So, stages.Init() happily walks through all costly detection/discover logic for 31 datasource.

Short-term we could tidy up the edubuntu image flavor to ensure cloud-init can minimally detect an empty nocloud datasource by providing empty files at /var/lib/cloud/seed/nocloud/user-data and /var/lib/cloud/seed/nocloud/meta-data. That'll leave cloud-init in an enabled state that current subiquity code can invoke stages.Init() without side-effects.

long-term:
 - subiquity should probably double check cloud-init disabled status and avoid calling stages.Init() if cloud-init is "disabled"

If we want this kind of fix for subiquity to avoid edge cases where someone manually tries to disable cloud-init via kernel command-line params:
https://github.com/canonical/subiquity/pull/1923

Better logging from cloud-init to fix the 'None' warning https://github.com/canonical/cloud-init/pull/4994

AIUI the proposed change to livecd-rootfs has some issues wrt correctness on flavors, moving this back to 'in progress'

https://github.com/canonical/cloud-init/pull/4994 just merged for cloud-init to fix inconclusive logging of 'None'. Expect cloud-init logs in this regard to be fixed in 24.2 and/or next "bugfix release" of cloud-init into Noble.

This bug was fixed in the package cloud-init - 24.1.1-0ubuntu1

---------------
cloud-init (24.1.1-0ubuntu1) noble; urgency=medium

  * Upstream snapshot based on 24.1.1.
    List of changes from upstream can be found at
    https://raw.githubusercontent.com/canonical/cloud-init/24.1.1/ChangeLog
    - Bugs fixed in this snapshot: (LP: #2056439, #2056460, #2055077)
      (LP: #2056194)

 -- Brett Holman <email address hidden> Mon, 11 Mar 2024 21:09:37 -0600

No longer a problem after recent fixes to subiquity and cloud-init.

It's back:

$ ubuntu-desktop-bootstrap --try-or-install

(ubuntu_bootstrap:7450): Gtk-WARNING **: 04:13:54.764: /usr/lib/x86_64-linux-gnu/gtk-3.0/3.0.0/immodules/im-ibus.so: undefined symbol: ibus_input_context_set_post_process_key_event

(ubuntu_bootstrap:7450): Gtk-WARNING **: 04:13:54.764: Loading IM context type 'ibus' failed
flutter: INFO ubuntu_bootstrap: Logging to /var/log/installer/ubuntu_bootstrap.log
flutter: WARNING subiquity_server: Unable to find the subiquity_client package. Falling back to the current working dir: /home/edubuntu
flutter: INFO subiquity_server: Waiting server up to 90 seconds
flutter: INFO subiquity_server: ApplicationState.WAITING
flutter: DEBUG config: Loaded config file from /usr/share/desktop-provision/whitelabel.yaml
flutter: INFO flavor_provider: Using flavor from config: UbuntuFlavor.edubuntu
flutter: INFO subiquity_client: Opening socket to Endpoint(/run/subiquity/socket )
flutter: DEBUG desktop: Disabling automounting
flutter: DEBUG subiquity_client: POST http://localhost/meta/client_variant?variant=%22desktop%22
flutter: DEBUG subiquity_client: GET http://localhost/refresh?wait=true
flutter: DEBUG telemetry: Writing report to /var/log/installer/telemetry
flutter: DEBUG subiquity_client: ==> setVariant(Variant.DESKTOP) null
flutter: DEBUG subiquity_client: ==> checkRefresh() {"availability": "UNAVAILABLE", "current_snap_version": "0+git.a0db5e7c", "new_snap_version": ""}
flutter: DEBUG refresh: RefreshState.status(status: RefreshStatus(availability: RefreshCheckState.UNAVAILABLE, currentSnapVersion: 0+git.a0db5e7c, newSnapVersion: ))
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.5918, logSyslogId: subiquity_log.5918, eventSyslogId: subiquity_event.5918)
flutter: DEBUG subiquity_client: POST http://localhost/meta/mark_configured?endpoint_names=%5B%22mirror%22%2C%22proxy%22%2C%22ssh%22%2C%22snaplist%22%2C%22ubuntu_pro%22%5D
flutter: DEBUG subiquity_client: ==> markConfigured([mirror, proxy, ssh, snaplist, ubuntu_pro]) null
flutter: DEBUG desktop: Disabling screen blanking
flutter: DEBUG desktop: Disabling screensaver
flutter: DEBUG desktop: Inhibiting Gnome session
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.5918, logSyslogId: subiquity_log.5918, eventSyslogId: subiquity_event.5918)
flutter: INFO subiquity_status: null => ApplicationStatus(state: ApplicationState.WAITING, confirmingTty: , error: null, cloudInitOk: true, interactive: true, echoSyslogId: subiquity_echo.5918, logSyslogId: subiquity_log.5918, eventSyslogId: subiquity_event.5918)
flutter: DEBUG subiquity_client: GET http://localhost/meta/interactive_sections
flutter: DEBUG subiquity_client: ==> getInteractiveSections() null
flutter: INFO locale: Loaded 75 languages
flutter: DEBUG subiquity_client: GET http://localhost/locale
flutter: DEBUG subiquity_client: ==> locale() "C.UTF-8"
flutter: INFO locale: Selected en_US as UI language

Telltale sign is error appear...

Erich,

Please attach a full tarball of /var/log/installer.

The original way I wanted to address this issue is pending on livecd-rootfs. livecd-rootfs v24.04.49 is still in proposed, and when it migrates I will see to 24.04.50 being uploaded if it isn't already, which has my preferred version of the fix for this.

I am concerned that you are seeing a different issue, so that is why I'm asking for logs.

Hi Dan,

This should do it.

Erich - so what problems are you experiencing? The only data we have here is "It's back" but the logs you have provided reflect the Subiquity fixes being in place.

I am (slowly) downloading the latest edubuntu ISO so I'm happy to try to reproduce this, but I could use some details about what I'm looking for. Thanks.

Oh, I'm sorry Dan.

ubuntu-desktop-bootstrap loads but is not getting past the initial spinner with "Preparing Edubuntu...". I have been unable to duplicate the symptom using Ubuntu Studio or Ubuntu Desktop.

I have just completed my second install here with the 20240320 build of edubuntu. I'm not able to reproduce this problem. The first install was autoinstall based, the second one was completely manually.

Erich, the original bug was due to some problems trying to contact EC2 when that was plainly not going to work. Do you see evidence that the problem you're seeing has anything to do with cloud-init talking to EC2? All appears to be in order in my test installs (minus the backtrace I saw from ubuntu-desktop-bootstrap that mentioned slideshows, but I can't produce that again and it doesn't appear to be blocking)

Ok, good to know. I'll re-test soon. I thought cloud-init might be the problem again after Chad had released a fix there, but I'll re test when I'm in a better position.

So, false alarm. Everything appears to be fine. I 'm honestly not sure why it failed in my last test but testing just now, and everything seems to be fine.

+1 I confirmed yesterday as well. subiquity no longer calls cloud-init's stages.Init() when cloud-init is disabled. This was the source of the delay originally which performed all that rediscovery of every cloud-init datasource, including Ec2. Full install with cloud-init disabled on default installs works and we see subiquity correctly claiming cloud-init is disabled.

livecd-rootfs 24.04.50 merged and uploaded, now needs to clear proposed.

This bug was fixed in the package livecd-rootfs - 24.04.52

---------------
livecd-rootfs (24.04.52) noble; urgency=medium

  * Move from hwe-22.04 to hwe-24.04 throughout, hwe-22.04 is obsolete and
    to be dropped from the release pocket imminently.

 -- Steve Langasek <email address hidden> Wed, 27 Mar 2024 12:03:04 -0700