Fix last reported event possibly not being sent (#1796)

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.

LP: #1993836

5 files changed, 123 insertions, 3 deletions

diff --git a/cloudinit/cmd/main.py b/cloudinit/cmd/main.py
index 7e9f978f..f28fda15 100755
--- a/cloudinit/cmd/main.py
+++ b/cloudinit/cmd/main.py
@@ -1090,8 +1090,8 @@ def main(sysv_args=None):
             func=functor,
             args=(name, args),
         )
-        reporting.flush_events()
-        return retval
+    reporting.flush_events()
+    return retval
 
 
 if __name__ == "__main__":
diff --git a/cloudinit/reporting/handlers.py b/cloudinit/reporting/handlers.py
index d43b80b0..2c1f4998 100644
--- a/cloudinit/reporting/handlers.py
+++ b/cloudinit/reporting/handlers.py
@@ -128,6 +128,7 @@ class WebHookHandler(ReportingHandler):
                     timeout=args[2],
                     retries=args[3],
                     ssl_details=args[4],
+                    log_req_resp=False,
                 )
                 consecutive_failed = 0
             except Exception as e:
@@ -141,10 +142,16 @@ class WebHookHandler(ReportingHandler):
                 self.queue.task_done()
 
     def publish_event(self, event):
+        event_data = event.as_dict()
+        LOG.debug(
+            "Queuing POST to %s, data: %s",
+            self.endpoint,
+            event_data,
+        )
         self.queue.put(
             (
                 self.endpoint,
-                json.dumps(event.as_dict()),
+                json.dumps(event_data),
                 self.timeout,
                 self.retries,
                 self.ssl_details,
diff --git a/tests/integration_tests/assets/echo_server.py b/tests/integration_tests/assets/echo_server.py
new file mode 100644
index 00000000..5700082b
--- /dev/null
+++ b/tests/integration_tests/assets/echo_server.py
@@ -0,0 +1,37 @@
+#!/usr/bin/env python3
+"""
+Very simple HTTP daemon server in python for incoming POST data to stdout.
+Each line represents a request's POST data a dictionary.
+"""
+import contextlib
+import pathlib
+from http.server import BaseHTTPRequestHandler, HTTPServer
+
+OUTFILE = pathlib.Path("/var/tmp/echo_server_output")
+
+
+class Server(BaseHTTPRequestHandler):
+    def _set_response(self):
+        self.send_response(200)
+        self.send_header("Content-type", "text/html")
+        self.end_headers()
+
+    def do_GET(self):
+        self._set_response()
+
+    def do_POST(self):
+        content_length = int(self.headers["Content-Length"])
+        post_data = self.rfile.read(content_length).decode("utf-8")
+        with OUTFILE.open("a") as f:
+            f.write(f"{post_data}\n")
+        self._set_response()
+
+    def log_message(self, *args, **kwargs):
+        pass
+
+
+server_address = ("", 55555)
+httpd = HTTPServer(server_address, Server)
+with contextlib.suppress(KeyboardInterrupt):
+    httpd.serve_forever()
+httpd.server_close()
diff --git a/tests/integration_tests/assets/echo_server.service b/tests/integration_tests/assets/echo_server.service
new file mode 100644
index 00000000..8190b2c5
--- /dev/null
+++ b/tests/integration_tests/assets/echo_server.service
@@ -0,0 +1,10 @@
+[Unit]
+Description=echo_server
+Before=cloud-init-local.service
+DefaultDependencies=no
+
+[Service]
+ExecStart=/usr/bin/env python3 /var/tmp/echo_server.py
+
+[Install]
+WantedBy=multi-user.target
diff --git a/tests/integration_tests/reporting/test_webhook_reporting.py b/tests/integration_tests/reporting/test_webhook_reporting.py
new file mode 100644
index 00000000..9eb720c9
--- /dev/null
+++ b/tests/integration_tests/reporting/test_webhook_reporting.py
@@ -0,0 +1,66 @@
+# This file is part of cloud-init. See LICENSE file for license information.
+
+"""Tests for testing reporting and event handling."""
+
+import json
+
+import pytest
+
+from tests.integration_tests.instances import IntegrationInstance
+from tests.integration_tests.util import ASSETS_DIR, verify_clean_log
+
+URL = "http://127.0.0.1:55555"
+
+USER_DATA = f"""\
+#cloud-config
+reporting:
+  webserver:
+    type: webhook
+    endpoint: "{URL}"
+    timeout: 1
+    retries: 1
+
+"""
+
+
+@pytest.mark.user_data(USER_DATA)
+def test_webhook_reporting(client: IntegrationInstance):
+    """Test when using webhook reporting that we get expected events.
+
+    This test setups a simple echo server that prints out POST data out to
+    a file. Ensure that that file contains all of the expected events.
+    """
+    client.push_file(ASSETS_DIR / "echo_server.py", "/var/tmp/echo_server.py")
+    client.push_file(
+        ASSETS_DIR / "echo_server.service",
+        "/etc/systemd/system/echo_server.service",
+    )
+    client.execute("cloud-init clean --logs")
+    client.execute("systemctl start echo_server.service")
+    # Run through our standard process here. This remove any uncertainty
+    # around messages transmitting during pre-network boot.
+    client.execute(
+        "cloud-init init --local; "
+        "cloud-init init; "
+        "cloud-init modules --mode=config; "
+        "cloud-init modules --mode=final; "
+        "cloud-init status --wait"
+    )
+    verify_clean_log(client.read_from_file("/var/log/cloud-init.log"))
+
+    server_output = client.read_from_file(
+        "/var/tmp/echo_server_output"
+    ).splitlines()
+    events = [json.loads(line) for line in server_output]
+
+    # Only time this should be less is if we remove modules
+    assert len(events) > 58, events
+
+    # Assert our first and last expected messages exist
+    ds_events = [
+        e for e in events if e["name"] == "init-network/activate-datasource"
+    ]
+    assert len(ds_events) == 2  # 1 for start, 1 for stop
+
+    final_events = [e for e in events if e["name"] == "modules-final"]
+    assert final_events  # 1 for stop and ignore LP: #1992711 for now