Merge "Capture the early logging"

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),

ironic_python_agent/tests/unit/test_utils.py

@@ -1197,3 +1197,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)

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):

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.