From df418984f037856813b6bc5e495ef602a6737ee3 Mon Sep 17 00:00:00 2001
From: Julia Kreger <juliaashleykreger@gmail.com>
Date: Tue, 30 Mar 2021 07:58:34 -0700
Subject: [PATCH] Capture the early logging

_early_log prints to stdout, which is fine in some cases,
however in other cases it gets lost in the shuffle of process
launch by things like systemd.

Lets try to save everything, and re-log it so it is easy to
debug early issues.

Change-Id: I334a9073d17cccec4c669fae82edc3e388debc5c
---
 ironic_python_agent/cmd/agent.py              |  2 +-
 ironic_python_agent/tests/unit/test_utils.py  | 23 +++++++++++++++++++
 ironic_python_agent/utils.py                  | 13 ++++++++++-
 ...apture-early-logging-0f3fa58d75656117.yaml |  8 +++++++
 4 files changed, 44 insertions(+), 2 deletions(-)
 create mode 100644 releasenotes/notes/capture-early-logging-0f3fa58d75656117.yaml

diff --git a/ironic_python_agent/cmd/agent.py b/ironic_python_agent/cmd/agent.py
index 925303479..9ebe30065 100644
--- a/ironic_python_agent/cmd/agent.py
+++ b/ironic_python_agent/cmd/agent.py
@@ -46,7 +46,7 @@ def run():
     logger = log.getLogger(__name__)
     logger.debug("Configuration:")
     CONF.log_opt_values(logger, log.DEBUG)
-
+    utils.log_early_log_to_logger()
     agent.IronicPythonAgent(CONF.api_url,
                             agent.Host(hostname=CONF.advertise_host,
                                        port=CONF.advertise_port),
diff --git a/ironic_python_agent/tests/unit/test_utils.py b/ironic_python_agent/tests/unit/test_utils.py
index 02f2f95d4..640d50ca0 100644
--- a/ironic_python_agent/tests/unit/test_utils.py
+++ b/ironic_python_agent/tests/unit/test_utils.py
@@ -1195,3 +1195,26 @@ class TestCheckVirtualMedia(ironic_agent_base.IronicAgentTest):
         mock_execute.assert_called_with('lsblk', '-n', '-s', '-P', '-b',
                                         '-oKNAME,TRAN,TYPE,SIZE',
                                         '/dev/sdh')
+
+
+class TestCheckEarlyLogging(ironic_agent_base.IronicAgentTest):
+
+    @mock.patch.object(utils, 'LOG', autospec=True)
+    def test_early_logging_goes_to_logger(self, mock_log):
+        info = mock.Mock()
+        mock_log.info.side_effect = info
+        # Reset the buffer to be empty.
+        utils._EARLY_LOG_BUFFER = []
+        # Store some data via _early_log
+        utils._early_log('line 1.')
+        utils._early_log('line 2 %s', 'message')
+        expected_messages = ['line 1.',
+                             'line 2 message']
+        self.assertEqual(expected_messages, utils._EARLY_LOG_BUFFER)
+        # Test we've got data in the buffer.
+        info.assert_not_called()
+        # Test the other half of this.
+        utils.log_early_log_to_logger()
+        expected_calls = [mock.call('Early logging: %s', 'line 1.'),
+                          mock.call('Early logging: %s', 'line 2 message')]
+        info.assert_has_calls(expected_calls)
diff --git a/ironic_python_agent/utils.py b/ironic_python_agent/utils.py
index f045a4fe1..dd68a5267 100644
--- a/ironic_python_agent/utils.py
+++ b/ironic_python_agent/utils.py
@@ -78,6 +78,8 @@ DEVICE_EXTRACTOR = re.compile(r'^(?:(.*\d)p|(.*\D))(?:\d+)$')
 PARTED_TABLE_TYPE_REGEX = re.compile(r'^.*partition\s+table\s*:\s*(gpt|msdos)',
                                      re.IGNORECASE)
 
+_EARLY_LOG_BUFFER = []
+
 
 def execute(*cmd, **kwargs):
     """Convenience wrapper around ironic_lib's execute() method.
@@ -187,7 +189,16 @@ def _get_vmedia_params():
 
 def _early_log(msg, *args):
     """Log via printing (before oslo.log is configured)."""
-    print('ironic-python-agent:', msg % args, file=sys.stderr)
+    log_entry = msg % args
+    _EARLY_LOG_BUFFER.append(log_entry)
+    print('ironic-python-agent:', log_entry, file=sys.stderr)
+
+
+def log_early_log_to_logger():
+    """Logs early logging events to the configured logger."""
+
+    for entry in _EARLY_LOG_BUFFER:
+        LOG.info("Early logging: %s", entry)
 
 
 def _copy_config_from(path):
diff --git a/releasenotes/notes/capture-early-logging-0f3fa58d75656117.yaml b/releasenotes/notes/capture-early-logging-0f3fa58d75656117.yaml
new file mode 100644
index 000000000..b6e4a66d5
--- /dev/null
+++ b/releasenotes/notes/capture-early-logging-0f3fa58d75656117.yaml
@@ -0,0 +1,8 @@
+---
+fixes:
+  - |
+    Fixes initial logging before configuration is loaded to re-log anything
+    recorded for the purposes of troubleshooting. This is necessary as systemd
+    does not report stdout from a process launch as part of the process's
+    logging. Now messages will be re-logged once the configuration has been
+    loaded.