analyze return multiple bootRecords for single real boot

[ubuntu-server-builder]

This bug was originally filed in Launchpad as LP: #1930956

Launchpad details

affected_projects = []
assignee = None
assignee_name = None
date_closed = None
date_created = 2021-06-05T08:01:29.862826+00:00
date_fix_committed = None
date_fix_released = None
id = 1930956
importance = medium
is_complete = False
lp_url = https://bugs.launchpad.net/cloud-init/+bug/1930956
milestone = None
owner = haidaocht
owner_name = Haitao Chen
private = False
status = triaged
submitter = haidaocht
submitter_name = Haitao Chen
tags = ['analyze', 'azure']
duplicates = []

Launchpad user Haitao Chen(haidaocht) wrote on 2021-06-05T08:01:29.862826+00:00

cloud-init analyze show return me multiple boot records, while I just have 1.

• CloudProvider is Azure
• default (I didn't tune anything)
• attached

[ubuntu-server-builder]

Launchpad user Haitao Chen(haidaocht) wrote on 2021-06-05T08:01:29.862826+00:00

Launchpad attachments: cloud-init.log

[ubuntu-server-builder]

Launchpad user Haitao Chen(haidaocht) wrote on 2021-06-05T16:38:28.975527+00:00

/cloudinit/analyze/show.py

        if event_type(event) == 'start':
            if event.get('name') in stages_seen:

if a event name is repeated (start and finish multiple times).

and it's not finished right away(child event will break this condition), finish the event right away won't push the event to stages_seen.

then its considered as new boot record.

[ubuntu-server-builder]

Launchpad user Chad Smith(chad.smith) wrote on 2021-06-06T20:19:50.169359+00:00

Haitao Chen (haidaocht), thank you for the bug and contributing to cloud-init to make it better. Do you happen to have a system available to attach the sudo cloud-init analyze show output as well?

Much thanks.

[ubuntu-server-builder]

Launchpad user Chad Smith(chad.smith) wrote on 2021-06-06T20:37:10.495500+00:00

Nevermind, just grabbed it on a Xenial instance I had available: This does feel like a general bug that needs to be better handled by analyze show output for certain event types on Azure.

-- Boot Record 01 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: init-local
|->no cache found @00.00400s +00.00100s Starting stage: init-local/search-Azure Starting stage: azure-ds/_get_data |->found azure asset tag @00.03100s +00.00100s
|->get_boot_telemetry @00.03200s +00.01200s |->get_system_info @00.04500s +00.00000s
Starting stage: azure-ds/crawl_metadata
|->list_possible_azure_ds_devs @00.04500s +00.33100s |->load_azure_ds_dir @00.37700s +00.00000s
Starting stage: azure-ds/load_azure_ds_dir
Starting stage: azure-ds/read_azure_ovf
|->load_azure_ovf_pubkeys @00.38300s +00.00000s Starting stage: azure-ds/_get_preprovisioning_cfgs |->_get_preprovisionedvm_cfg_value @00.38300s +00.00100s
|`->_get_preprovisionedvmtype_cfg_value @00.38400s +00.00000s
Finished stage: (azure-ds/_get_preprovisioning_cfgs) 00.00100 seconds

Finished stage: (azure-ds/read_azure_ovf) 00.00600 seconds

Finished stage: (azure-ds/load_azure_ds_dir) 00.00700 seconds

Starting stage: azure-ds/get_imds_data_with_api_fallback
Starting stage: azure-ds/get_metadata_from_imds
|->obtain dhcp lease @00.39400s +00.08700s |->_get_metadata_from_imds @00.48200s +00.01400s
Finished stage: (azure-ds/get_metadata_from_imds) 00.12800 seconds

Finished stage: (azure-ds/get_imds_data_with_api_fallback) 00.12900 seconds

|`->_get_random_seed @00.52200s +00.00000s
Finished stage: (azure-ds/crawl_metadata) 00.47700 seconds

|`->write_files @00.52300s +00.00300s
Finished stage: (azure-ds/_get_data) 00.49500 seconds

|`->get_public_ssh_keys @00.52700s +00.00000s
Finished stage: (init-local/search-Azure) 00.50200 seconds

Starting stage: azure-ds/parse_network_config
|`->_generate_network_config_from_fallback_config @00.59400s +00.00600s
Finished stage: (azure-ds/parse_network_config) 00.00600 seconds

Finished stage: (init-local) 00.61900 seconds

Starting stage: init-network
|`->restored from cache with run check: DataSourceAzure [seed=/var/lib/waagent] @01.56200s +00.02200s
Total Time: 2.37000 seconds

-- Boot Record 02 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: azure-ds/parse_network_config
|`->_generate_network_config_from_fallback_config @00.00000s +00.00500s
Finished stage: (azure-ds/parse_network_config) 00.00500 seconds

Starting stage: init-network/setup-datasource
Starting stage: azure-ds/setup
Starting stage: azure-ds/_negotiate
Starting stage: azure-ds/bounce_network_with_azure_hostname
|`->temporary_hostname @00.01500s +00.00100s
Finished stage: (azure-ds/bounce_network_with_azure_hostname) 00.00300 seconds

Starting stage: azure-ds/get_metadata_from_fabric
Starting stage: azure-ds/register_with_azure_and_fetch_data
|->generate_certificate @00.01900s +01.48600s Starting stage: azure-ds/_fetch_goal_state_from_azure Starting stage: azure-ds/_get_raw_goal_state_xml_from_azure Starting stage: azure-ds/find_endpoint |->_networkd_get_value_from_leases @01.50500s +00.00100s
|->_load_dhclient_json @01.50600s +00.03100s |->_get_value_from_dhcpoptions @01.53700s +00.00000s
Finished stage: (azure-ds/find_endpoint) 00.03200 seconds

Starting stage: azure-ds/goalstate-retrieval
|`->http_with_retries @01.53800s +00.00800s
Finished stage: (azure-ds/goalstate-retrieval) 00.00800 seconds

Finished stage: (azure-ds/_get_raw_goal_state_xml_from_azure) 00.04100 seconds

Starting stage: azure-ds/_parse_raw_goal_state_xml
Starting stage: azure-ds/get-certificates-xml
|`->http_with_retries @01.54700s +00.01400s
Finished stage: (azure-ds/get-certificates-xml) 00.01400 seconds

Finished stage: (azure-ds/_parse_raw_goal_state_xml) 00.01500 seconds

Finished stage: (azure-ds/_fetch_goal_state_from_azure) 00.05700 seconds

Starting stage: azure-ds/_get_user_pubkeys
Starting stage: azure-ds/parse_certificates
|->_decrypt_certs_from_xml @01.56200s +00.02800s Starting stage: azure-ds/_get_ssh_key_from_cert |->_run_x509_action @01.59100s +00.02000s
Finished stage: (azure-ds/_get_ssh_key_from_cert) 00.04100 seconds

Starting stage: azure-ds/_get_fingerprint_from_cert
|`->_run_x509_action @01.63100s +00.02100s
Finished stage: (azure-ds/_get_fingerprint_from_cert) 00.02200 seconds

Finished stage: (azure-ds/parse_certificates) 00.09100 seconds

Finished stage: (azure-ds/_get_user_pubkeys) 00.09100 seconds

Starting stage: azure-ds/send_ready_signal
Starting stage: azure-ds/_post_health_report
Starting stage: azure-ds/push_log_to_kvp
|`->get_last_log_byte_pushed_to_kvp_index @01.65400s +00.00000s
Finished stage: (azure-ds/push_log_to_kvp) 00.01200 seconds

|`->http_with_retries @01.66700s +00.00700s
Finished stage: (azure-ds/_post_health_report) 00.02000 seconds

Finished stage: (azure-ds/send_ready_signal) 00.02100 seconds

Finished stage: (azure-ds/register_with_azure_and_fetch_data) 01.65500 seconds

Finished stage: (azure-ds/get_metadata_from_fabric) 01.65600 seconds

Finished stage: (azure-ds/_negotiate) 01.66000 seconds

Finished stage: (azure-ds/setup) 01.66100 seconds

Finished stage: (init-network/setup-datasource) 01.66100 seconds

|->reading and applying user-data @01.68400s +00.00300s |->reading and applying vendor-data @01.68700s +00.00100s
|->reading and applying vendor-data2 @01.68800s +00.00000s Starting stage: init-network/activate-datasource Starting stage: azure-ds/activate Starting stage: azure-ds/address_ephemeral_resize Starting stage: azure-ds/can_dev_be_reformatted |->_has_ntfs_filesystem @01.71900s +00.18200s
Finished stage: (azure-ds/can_dev_be_reformatted) 00.18300 seconds

Finished stage: (azure-ds/address_ephemeral_resize) 00.18300 seconds

Total Time: 9.13200 seconds

-- Boot Record 03 --
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

Starting stage: azure-ds/push_log_to_kvp
|`->get_last_log_byte_pushed_to_kvp_index @00.00000s +00.00100s
Finished stage: (azure-ds/push_log_to_kvp) 00.01200 seconds

Finished stage: (azure-ds/activate) 00.19500 seconds

Finished stage: (init-network/activate-datasource) 00.19900 seconds

|->config-migrator ran successfully @00.03300s +00.00100s |->config-seed_random ran successfully @00.03400s +00.00200s
|->config-bootcmd ran successfully @00.03600s +00.00100s |->config-write-files ran successfully @00.03700s +00.00100s
|->config-growpart ran successfully @00.03900s +00.03900s |->config-resizefs ran successfully @00.07900s +00.00500s
|->config-disk_setup ran successfully @00.08500s +00.08500s |->config-mounts ran successfully @00.17100s +00.09400s
|->config-set_hostname ran successfully @00.26600s +00.00200s |->config-update_hostname ran successfully @00.26900s +00.00200s
|->config-update_etc_hosts ran successfully @00.27200s +00.00000s |->config-ca-certs ran successfully @00.27200s +00.00200s
|->config-rsyslog ran successfully @00.27400s +00.00100s Starting stage: init-network/config-users-groups |->get_public_ssh_keys @00.27700s +00.00000s
Finished stage: (init-network/config-users-groups) 00.04700 seconds

Starting stage: init-network/config-ssh
|`->get_public_ssh_keys @01.00100s +00.00000s
Finished stage: (init-network/config-ssh) 00.68300 seconds

Finished stage: (init-network) 02.99900 seconds

Starting stage: modules-config
|->config-emit_upstart ran successfully @04.61400s +00.00000s |->config-snap ran successfully @04.61400s +00.00200s
|->config-ssh-import-id ran successfully @04.61600s +00.00200s |->config-locale ran successfully @04.61800s +00.00200s
|->config-set-passwords ran successfully @04.62000s +00.00200s |->config-grub-dpkg ran successfully @04.62200s +00.24200s
|->config-apt-pipelining ran successfully @04.86500s +00.00200s |->config-apt-configure ran successfully @04.86700s +00.10600s
|->config-ubuntu-advantage ran successfully @04.97400s +00.00100s |->config-ntp ran successfully @04.97500s +00.00100s
|->config-timezone ran successfully @04.97700s +00.00100s |->config-disable-ec2-metadata ran successfully @04.97800s +00.00100s
|->config-runcmd ran successfully @04.97900s +00.00100s |->config-byobu ran successfully @04.98000s +00.00200s
Finished stage: (modules-config) 00.38500 seconds

Starting stage: modules-final
|->config-package-update-upgrade-install ran successfully @05.47500s +00.00100s |->config-fan ran successfully @05.47700s +00.00100s
|->config-landscape ran successfully @05.47800s +00.00100s |->config-lxd ran successfully @05.48000s +00.00100s
|->config-ubuntu-drivers ran successfully @05.48100s +00.00200s |->config-puppet ran successfully @05.48300s +00.00100s
|->config-chef ran successfully @05.48400s +00.00000s |->config-mcollective ran successfully @05.48500s +00.00100s
|->config-salt-minion ran successfully @05.48700s +00.00100s |->config-reset_rmc ran successfully @05.48800s +00.00100s
|->config-refresh_rmc_and_interface ran successfully @05.48900s +00.00100s |->config-rightscale_userdata ran successfully @05.49000s +00.00100s
|->config-scripts-vendor ran successfully @05.49200s +00.00100s |->config-scripts-per-once ran successfully @05.49300s +00.00100s
|->config-scripts-per-boot ran successfully @05.49500s +00.00000s |->config-scripts-per-instance ran successfully @05.49500s +00.00200s
|->config-scripts-user ran successfully @05.49700s +00.00100s |->config-ssh-authkey-fingerprints ran successfully @05.49800s +00.07400s
|->config-keys-to-console ran successfully @05.57300s +00.14500s |->config-phone-home ran successfully @05.71900s +00.00200s
|->config-final-message ran successfully @05.72200s +00.00500s |->config-power-state-change ran successfully @05.72700s +00.00100s
Finished stage: (modules-final) 00.27300 seconds

Total Time: 4.79300 seconds

3 boot records analyzed