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
This commit is contained in:
Julia Kreger 2021-03-30 07:58:34 -07:00
parent 49d123dd6e
commit df418984f0
4 changed files with 44 additions and 2 deletions

View File

@ -46,7 +46,7 @@ def run():
logger = log.getLogger(__name__) logger = log.getLogger(__name__)
logger.debug("Configuration:") logger.debug("Configuration:")
CONF.log_opt_values(logger, log.DEBUG) CONF.log_opt_values(logger, log.DEBUG)
utils.log_early_log_to_logger()
agent.IronicPythonAgent(CONF.api_url, agent.IronicPythonAgent(CONF.api_url,
agent.Host(hostname=CONF.advertise_host, agent.Host(hostname=CONF.advertise_host,
port=CONF.advertise_port), port=CONF.advertise_port),

View File

@ -1195,3 +1195,26 @@ class TestCheckVirtualMedia(ironic_agent_base.IronicAgentTest):
mock_execute.assert_called_with('lsblk', '-n', '-s', '-P', '-b', mock_execute.assert_called_with('lsblk', '-n', '-s', '-P', '-b',
'-oKNAME,TRAN,TYPE,SIZE', '-oKNAME,TRAN,TYPE,SIZE',
'/dev/sdh') '/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)

View File

@ -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)', PARTED_TABLE_TYPE_REGEX = re.compile(r'^.*partition\s+table\s*:\s*(gpt|msdos)',
re.IGNORECASE) re.IGNORECASE)
_EARLY_LOG_BUFFER = []
def execute(*cmd, **kwargs): def execute(*cmd, **kwargs):
"""Convenience wrapper around ironic_lib's execute() method. """Convenience wrapper around ironic_lib's execute() method.
@ -187,7 +189,16 @@ def _get_vmedia_params():
def _early_log(msg, *args): def _early_log(msg, *args):
"""Log via printing (before oslo.log is configured).""" """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): def _copy_config_from(path):

View File

@ -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.