Fix last reported event possibly not being sent

[TheRealFalcon]

Proposed Commit Message

Fix last reported event possibly not being sent

The run of every cloud-init mode is wrapped in a reporting
context manager. The final flush of events before the process exits was
happening within the context manager, however, one final event is sent
when the context manager exits. Since this event isn't subject to
waiting for event flush, cloud-init can exit before this event gets
sent.

This commit fixes this issue and also adds logging of POST data when
POSTING to a URL.

Additional Context

New log format actually includes useful information now:

2022-10-25 16:37:56,759 - url_helper.py[DEBUG]: [0/4] open 'http://10.20.30.1:55555/new_stuff' with {'url': 'http://10.20.30.1:55555/new_stuff', 'stream': False, 'allow_redirects': True, 'method': 'POST', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/22.3'}} configuration and POST data: {"name": "init-network/config-set_hostname", "description": "config-set_hostname ran successfully", "event_type": "finish", "origin": "cloudinit", "timestamp": 1666715876.7045417, "result": "SUCCESS"}

Test Steps

Checklist:

• My code follows the process laid out in the documentation
• I have updated or added any unit tests accordingly
• I have updated or added any documentation accordingly

[blackboxsw]

We may want to scrub this post data to redact secrets right this could be a security problem as we'd log all potential post data provided to this common function to /var/log/cloud-init.log which is world-readable.

Two known areas that may cause problems, or lead to sensitive data leaks:
Azure and GCP both send data in their requests.
cloudinit/sources/helpers/azure.py: http_with_retries
cloudinit/sources/DataSourceGCE.py:_write_host_key_to_guest_attributes maybe?

[TheRealFalcon]

I pushed an alternative for logging. Log the event data rather than the readurl data directly. Looks like this:

2022-10-27 21:17:24,062 - handlers.py[DEBUG]: Queuing POST to http://127.0.0.1:55555/, data: {'name': 'init-network/activate-datasource', 'description': 'activating datasource', 'event_type': 'start', 'origin': 'cloudinit', 'timestamp': 1666905444.0623877}

[blackboxsw]

Also something seems to be falling over as far as network being brought up as I run through this integration test on a lxd_vm platform. It is likely something unrelated that landed in tip of main, but I haven't been able to put my finger on it yet. So, a bit more testing is needed to tease out whether network not being brought up is related to this branch or something else in main.

I'd uploaded the failing bits (tip of main plus your branch for kinetic) to ppa:chad.smith/maas-testing
So, we should be able to peek at VM integration test failures:

CLOUD_INIT_KEEP_INSTANCE=1 CLOUD_INIT_PLATFORM=lxd_container CLOUD_INIT_OS_IMAGE=kinetic CLOUD_INIT_CLOUD_INIT_SOURCE=ppa:chad.smith/maas-testing tox -e integration-tests tests/integration_tests/reporting/test_webhook_reporting.py

[blackboxsw]

Can we assert there are paired start and finish events for each scope. I'm thinking we are occasionally seeing starts or finishes getting swallowed across bring up of a stage and teardown.
Minimally I want to assert each high level boot stage scope has bookend start/finish events:
As it is currently, it seems like we may be missing a matching start event for

  "name": "modules-final",
  "event_type": "finish",

[TheRealFalcon]

We can't assert this, because we still don't get every start event. Once that's fixed, we can make the change to this test.

[blackboxsw]

LGTM. I think we can iterate on the start event issues separately.
This commit message should probably also capture that it fixes:

LP: #1993836
in the footer of the message.

[blackboxsw]

We can address https://bugs.launchpad.net/cloud-init/+bug/1992711 separately for squelched "start" events.