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.