cloud-init analyze output not formatted cleanly on Azure

[Ryan Harper]

Azure added additional reporting trace points, the result is that analyze/blame output doesn't look well formatted.

-- 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.00500s +00.00000s
Starting stage: init-local/search-Azure
Starting stage: azure-ds/_get_data
|`->found azure asset tag @00.05000s +00.01100s
Starting stage: azure-ds/crawl_metadata
|`->list_possible_azure_ds_devs @00.06200s +00.25000s
|`->load_azure_ds_dir @00.31300s +00.00000s
Starting stage: azure-ds/load_azure_ds_dir
Starting stage: azure-ds/read_azure_ovf
|`->load_azure_ovf_pubkeys @00.31700s +00.00000s
|`->_extract_preprovisioned_vm_setting @00.31700s +00.00100s
Finished stage: (azure-ds/read_azure_ovf) 00.00400 seconds

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

Starting stage: azure-ds/get_metadata_from_imds
|`->_get_metadata_from_imds @00.49100s +00.01000s
Finished stage: (azure-ds/get_metadata_from_imds) 00.19000 seconds

|`->_get_random_seed @00.52100s +00.00100s
Finished stage: (azure-ds/crawl_metadata) 00.47100 seconds

|`->maybe_remove_ubuntu_network_config_scripts @00.53200s +00.00100s
|`->write_files @00.53300s +00.00300s
Finished stage: (azure-ds/_get_data) 00.48600 seconds

Finished stage: (init-local/search-Azure) 00.48900 seconds

|`->network config from imds @00.59600s +00.00000s
Finished stage: (init-local) 00.73800 seconds

Starting stage: init-network
|`->restored from cache with run check: DataSourceAzure [seed=/var/lib/waagent] @03.12900s +00.03300s
|`->network config from imds @03.21700s +00.00100s
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 @03.23000s +00.00000s
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 @03.23500s +00.10500s
Starting stage: azure-ds/find_endpoint
|`->_networkd_get_value_from_leases @03.34000s +00.00200s
Finished stage: (azure-ds/find_endpoint) 00.00200 seconds

Starting stage: azure-ds/parse_certificates
|`->_decrypt_certs_from_xml @03.36100s +00.01000s
Starting stage: azure-ds/_get_ssh_key_from_cert
|`->_run_x509_action @03.37200s +00.00600s
Finished stage: (azure-ds/_get_ssh_key_from_cert) 00.04900 seconds

Starting stage: azure-ds/_get_fingerprint_from_cert
|`->_run_x509_action @03.42100s +00.00600s
Finished stage: (azure-ds/_get_fingerprint_from_cert) 00.00600 seconds

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

|`->_report_ready @03.42800s +00.00700s
Finished stage: (azure-ds/register_with_azure_and_fetch_data) 00.20200 seconds

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

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

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

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

|`->reading and applying user-data @03.44500s +00.00300s
|`->reading and applying vendor-data @03.44900s +00.00000s
Starting stage: init-network/activate-datasource
Starting stage: azure-ds/activate
Starting stage: azure-ds/address_ephemeral_resize
|`->wait for ephemeral disk @03.48600s +00.00100s
|`->can_dev_be_reformatted @03.48700s +00.00100s
Finished stage: (azure-ds/address_ephemeral_resize) 00.00200 seconds

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

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

|`->config-migrator ran successfully @03.54000s +00.00400s
|`->config-seed_random ran successfully @03.54600s +00.00200s
|`->config-bootcmd ran successfully @03.54900s +00.00000s
|`->config-write-files ran successfully @03.55000s +00.00000s
|`->config-growpart ran successfully @03.55100s +00.10400s
|`->config-resizefs ran successfully @03.65600s +00.04900s
|`->config-disk_setup ran successfully @03.70600s +03.42300s
|`->config-mounts ran successfully @07.13000s +00.22300s
|`->config-set_hostname ran successfully @07.35400s +00.00200s
|`->config-update_hostname ran successfully @07.35700s +00.00200s
|`->config-update_etc_hosts ran successfully @07.35900s +00.00100s
|`->config-ca-certs ran successfully @07.36000s +00.00100s
|`->config-rsyslog ran successfully @07.36200s +00.00100s
|`->config-users-groups ran successfully @07.36400s +00.32700s
|`->config-ssh ran successfully @07.69200s +00.26200s
Finished stage: (init-network) 04.83900 seconds

[Ryan Harper (raharper)]

I was hacking on this earlier and this is mostly what's needed for "sub-stage" events.

http://paste.ubuntu.com/p/2PWXDrBkSN/

Also, the DataSourceAzure/helper code really should get the current reporter from from stages cloud object which has a reporter. This isn't easily accessed from the datasource itself.

We may want to look at having stages update the the datasource with a reporter instance. In the mean time, it's probably accurate enought to have cloudinit/sources/helpers/azure:azure_ds_reporter to set it's reporter 'name' to:

name="init-local/search-Azure"

Which then can produce saner output like so:

$ cloud-init analyze show --infile /tmp/events.json2
-- 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.00500s +00.00100s
|`->_get_data @00.04100s +00.00000s
|`->found azure asset tag @00.04100s +00.00000s
|`->found azure asset tag @00.04100s +00.00900s
|`->list_possible_azure_ds_devs @00.05000s +00.00100s
|`->list_possible_azure_ds_devs @00.05100s +00.22300s
|`->load_azure_ds_dir @00.27400s +00.00000s
|`->read_azure_ovf @00.27400s +00.00100s
|`->load_azure_ovf_pubkeys @00.27500s +00.00200s
|`->load_azure_ovf_pubkeys @00.27700s +00.00000s
|`->_extract_preprovisioned_vm_setting @00.27800s +00.00000s
|`->_get_metadata_from_imds @00.29800s +00.11200s
|`->_get_metadata_from_imds @00.41000s +00.01000s
|`->_get_random_seed @00.44100s +00.00100s
|`->maybe_remove_ubuntu_network_config_scripts @00.45000s +00.00100s
|`->write_files @00.45100s +00.00200s
|`->network config from imds @00.50700s +00.00100s
Finished stage: (init-local) 00.64000 seconds

It's still not quite right as this adds the start of a nested event without a time-delta but it at least makes things look better.

[James Falcon (falcojr)]

Tracked in Github Issues as https://github.com/canonical/cloud-init/issues/3394