diff --git a/ironic_inspector/plugins/standard.py b/ironic_inspector/plugins/standard.py index 5cf7d66ce..8c9befe24 100644 --- a/ironic_inspector/plugins/standard.py +++ b/ironic_inspector/plugins/standard.py @@ -13,9 +13,6 @@ """Standard set of plugins.""" -import base64 -import datetime -import os import sys import netaddr @@ -311,40 +308,8 @@ class ValidateInterfacesHook(base.ProcessingHook): class RamdiskErrorHook(base.ProcessingHook): """Hook to process error send from the ramdisk.""" - DATETIME_FORMAT = '%Y.%m.%d_%H.%M.%S_%f' - def before_processing(self, introspection_data, **kwargs): error = introspection_data.get('error') - logs = introspection_data.get('logs') - - if error or CONF.processing.always_store_ramdisk_logs: - if logs: - self._store_logs(logs, introspection_data) - else: - LOG.debug('No logs received from the ramdisk', - data=introspection_data) - if error: raise utils.Error(_('Ramdisk reported error: %s') % error, data=introspection_data) - - def _store_logs(self, logs, introspection_data): - if not CONF.processing.ramdisk_logs_dir: - LOG.warning( - _LW('Failed to store logs received from the ramdisk ' - 'because ramdisk_logs_dir configuration option ' - 'is not set'), - data=introspection_data) - return - - if not os.path.exists(CONF.processing.ramdisk_logs_dir): - os.makedirs(CONF.processing.ramdisk_logs_dir) - - time_fmt = datetime.datetime.utcnow().strftime(self.DATETIME_FORMAT) - bmc_address = introspection_data.get('ipmi_address', 'unknown') - file_name = 'bmc_%s_%s' % (bmc_address, time_fmt) - with open(os.path.join(CONF.processing.ramdisk_logs_dir, file_name), - 'wb') as fp: - fp.write(base64.b64decode(logs)) - LOG.info(_LI('Ramdisk logs stored in file %s'), file_name, - data=introspection_data) diff --git a/ironic_inspector/process.py b/ironic_inspector/process.py index 42b9e7301..e4ae86a9b 100644 --- a/ironic_inspector/process.py +++ b/ironic_inspector/process.py @@ -13,14 +13,19 @@ """Handling introspection data from the ramdisk.""" +import base64 import copy +import datetime +import os + import eventlet import json from ironicclient import exceptions from oslo_config import cfg +from oslo_utils import excutils -from ironic_inspector.common.i18n import _, _LE, _LI +from ironic_inspector.common.i18n import _, _LE, _LI, _LW from ironic_inspector.common import ironic as ir_utils from ironic_inspector.common import swift from ironic_inspector import firewall @@ -37,6 +42,40 @@ _CREDENTIALS_WAIT_RETRIES = 10 _CREDENTIALS_WAIT_PERIOD = 3 _STORAGE_EXCLUDED_KEYS = {'logs'} _UNPROCESSED_DATA_STORE_SUFFIX = 'UNPROCESSED' +_DATETIME_FORMAT = '%Y.%m.%d_%H.%M.%S_%f' + + +def _store_logs(introspection_data, node_info): + logs = introspection_data.get('logs') + if not logs: + LOG.warning(_LW('No logs were passed by the ramdisk'), + data=introspection_data, node_info=node_info) + return + + if not CONF.processing.ramdisk_logs_dir: + LOG.warning(_LW('Failed to store logs received from the ramdisk ' + 'because ramdisk_logs_dir configuration option ' + 'is not set'), + data=introspection_data, node_info=node_info) + return + + time_fmt = datetime.datetime.utcnow().strftime(_DATETIME_FORMAT) + bmc_address = (utils.get_ipmi_address_from_data(introspection_data) + or 'unknown') + file_name = 'bmc_%s_%s' % (bmc_address, time_fmt) + + try: + if not os.path.exists(CONF.processing.ramdisk_logs_dir): + os.makedirs(CONF.processing.ramdisk_logs_dir) + with open(os.path.join(CONF.processing.ramdisk_logs_dir, file_name), + 'wb') as fp: + fp.write(base64.b64decode(logs)) + except EnvironmentError: + LOG.exception(_LE('Could not store the ramdisk logs'), + data=introspection_data, node_info=node_info) + else: + LOG.info(_LI('Ramdisk logs were stored in file %s'), file_name, + data=introspection_data, node_info=node_info) def _find_node_info(introspection_data, failures): @@ -158,6 +197,7 @@ def process(introspection_data): 'pre-processing hooks:\n%s') % '\n'.join(failures) if node_info is not None: node_info.finished(error='\n'.join(failures)) + _store_logs(introspection_data, node_info) raise utils.Error(msg, node_info=node_info, data=introspection_data) LOG.info(_LI('Matching node is %s'), node_info.uuid, @@ -180,22 +220,29 @@ def process(introspection_data): except exceptions.NotFound: msg = _('Node was found in cache, but is not found in Ironic') node_info.finished(error=msg) + _store_logs(introspection_data, node_info) raise utils.Error(msg, code=404, node_info=node_info, data=introspection_data) try: - return _process_node(node, introspection_data, node_info) + result = _process_node(node, introspection_data, node_info) except utils.Error as exc: node_info.finished(error=str(exc)) - raise + with excutils.save_and_reraise_exception(): + _store_logs(introspection_data, node_info) except Exception as exc: LOG.exception(_LE('Unexpected exception during processing')) msg = _('Unexpected exception %(exc_class)s during processing: ' '%(error)s') % {'exc_class': exc.__class__.__name__, 'error': exc} node_info.finished(error=msg) + _store_logs(introspection_data, node_info) raise utils.Error(msg, node_info=node_info, data=introspection_data) + if CONF.processing.always_store_ramdisk_logs: + _store_logs(introspection_data, node_info) + return result + def _run_post_hooks(node_info, introspection_data): hooks = plugins_base.processing_hooks_manager() diff --git a/ironic_inspector/test/unit/test_plugins_standard.py b/ironic_inspector/test/unit/test_plugins_standard.py index 2434db854..2892a88f5 100644 --- a/ironic_inspector/test/unit/test_plugins_standard.py +++ b/ironic_inspector/test/unit/test_plugins_standard.py @@ -11,11 +11,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import base64 -import os -import shutil -import tempfile - import mock from oslo_config import cfg from oslo_utils import units @@ -404,77 +399,7 @@ class TestRamdiskError(test_base.BaseTest): 'ipmi_address': self.bmc_address, } - self.tempdir = tempfile.mkdtemp() - self.addCleanup(lambda: shutil.rmtree(self.tempdir)) - CONF.set_override('ramdisk_logs_dir', self.tempdir, 'processing') - def test_no_logs(self): self.assertRaisesRegexp(utils.Error, self.msg, process.process, self.data) - self.assertEqual([], os.listdir(self.tempdir)) - - def test_logs_disabled(self): - self.data['logs'] = 'some log' - CONF.set_override('ramdisk_logs_dir', None, 'processing') - - self.assertRaisesRegexp(utils.Error, - self.msg, - process.process, self.data) - self.assertEqual([], os.listdir(self.tempdir)) - - def test_logs(self): - log = b'log contents' - self.data['logs'] = base64.b64encode(log) - - self.assertRaisesRegexp(utils.Error, - self.msg, - process.process, self.data) - - files = os.listdir(self.tempdir) - self.assertEqual(1, len(files)) - filename = files[0] - self.assertTrue(filename.startswith('bmc_%s_' % self.bmc_address), - '%s does not start with bmc_%s' - % (filename, self.bmc_address)) - with open(os.path.join(self.tempdir, filename), 'rb') as fp: - self.assertEqual(log, fp.read()) - - def test_logs_create_dir(self): - shutil.rmtree(self.tempdir) - self.data['logs'] = base64.b64encode(b'log') - - self.assertRaisesRegexp(utils.Error, - self.msg, - process.process, self.data) - - files = os.listdir(self.tempdir) - self.assertEqual(1, len(files)) - - def test_logs_without_error(self): - log = b'log contents' - del self.data['error'] - self.data['logs'] = base64.b64encode(log) - - std_plugins.RamdiskErrorHook().before_processing(self.data) - - files = os.listdir(self.tempdir) - self.assertFalse(files) - - def test_always_store_logs(self): - CONF.set_override('always_store_ramdisk_logs', True, 'processing') - - log = b'log contents' - del self.data['error'] - self.data['logs'] = base64.b64encode(log) - - std_plugins.RamdiskErrorHook().before_processing(self.data) - - files = os.listdir(self.tempdir) - self.assertEqual(1, len(files)) - filename = files[0] - self.assertTrue(filename.startswith('bmc_%s_' % self.bmc_address), - '%s does not start with bmc_%s' - % (filename, self.bmc_address)) - with open(os.path.join(self.tempdir, filename), 'rb') as fp: - self.assertEqual(log, fp.read()) diff --git a/ironic_inspector/test/unit/test_process.py b/ironic_inspector/test/unit/test_process.py index 5f79ede85..79ef8c6d1 100644 --- a/ironic_inspector/test/unit/test_process.py +++ b/ironic_inspector/test/unit/test_process.py @@ -11,9 +11,13 @@ # See the License for the specific language governing permissions and # limitations under the License. +import base64 import copy import functools import json +import os +import shutil +import tempfile import time import eventlet @@ -257,6 +261,87 @@ class TestUnprocessedData(BaseProcessTest): swift_conn.create_object.assert_called_once_with(name, mock.ANY) +@mock.patch.object(example_plugin.ExampleProcessingHook, 'before_processing', + autospec=True) +class TestStoreLogs(BaseProcessTest): + def setUp(self): + super(TestStoreLogs, self).setUp() + CONF.set_override('processing_hooks', 'ramdisk_error,example', + 'processing') + + self.tempdir = tempfile.mkdtemp() + self.addCleanup(lambda: shutil.rmtree(self.tempdir)) + CONF.set_override('ramdisk_logs_dir', self.tempdir, 'processing') + + self.logs = b'test logs' + self.data['logs'] = base64.b64encode(self.logs) + + def _check_contents(self): + files = os.listdir(self.tempdir) + self.assertEqual(1, len(files)) + filename = files[0] + self.assertTrue(filename.startswith('bmc_%s_' % self.bmc_address), + '%s does not start with bmc_%s' + % (filename, self.bmc_address)) + with open(os.path.join(self.tempdir, filename), 'rb') as fp: + self.assertEqual(self.logs, fp.read()) + + def test_store_on_preprocess_failure(self, hook_mock): + hook_mock.side_effect = Exception('Hook Error') + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + def test_store_on_process_failure(self, hook_mock): + self.process_mock.side_effect = utils.Error('boom') + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + def test_store_on_unexpected_process_failure(self, hook_mock): + self.process_mock.side_effect = RuntimeError('boom') + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + def test_store_on_ramdisk_error(self, hook_mock): + self.data['error'] = 'boom' + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + def test_store_find_node_error(self, hook_mock): + self.cli.node.get.side_effect = exceptions.NotFound('boom') + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + def test_no_error_no_logs(self, hook_mock): + process.process(self.data) + self.assertEqual([], os.listdir(self.tempdir)) + + def test_logs_disabled(self, hook_mock): + CONF.set_override('ramdisk_logs_dir', None, 'processing') + hook_mock.side_effect = Exception('Hook Error') + self.assertRaises(utils.Error, process.process, self.data) + self.assertEqual([], os.listdir(self.tempdir)) + + def test_always_store_logs(self, hook_mock): + CONF.set_override('always_store_ramdisk_logs', True, 'processing') + process.process(self.data) + self._check_contents() + + @mock.patch.object(process.LOG, 'exception', autospec=True) + def test_failure_to_write(self, log_mock, hook_mock): + CONF.set_override('always_store_ramdisk_logs', True, 'processing') + CONF.set_override('ramdisk_logs_dir', '/I/cannot/write/here', + 'processing') + process.process(self.data) + self.assertEqual([], os.listdir(self.tempdir)) + self.assertTrue(log_mock.called) + + def test_directory_is_created(self, hook_mock): + shutil.rmtree(self.tempdir) + self.data['error'] = 'boom' + self.assertRaises(utils.Error, process.process, self.data) + self._check_contents() + + class TestProcessNode(BaseTest): def setUp(self): super(TestProcessNode, self).setUp() diff --git a/releasenotes/notes/ramdisk-logs-on-all-failures-24da41edf3a98400.yaml b/releasenotes/notes/ramdisk-logs-on-all-failures-24da41edf3a98400.yaml new file mode 100644 index 000000000..3e2a46166 --- /dev/null +++ b/releasenotes/notes/ramdisk-logs-on-all-failures-24da41edf3a98400.yaml @@ -0,0 +1,11 @@ +--- +fixes: + - The ramdisk logs are now stored on all preprocessing errors, not only + ones reported by the ramdisk itself. This required moving the ramdisk + logs handling from the "ramdisk_error" plugin to the generic processing + code. +upgrade: + - Handling ramdisk logs was moved out of the "ramdisk_error" plugin, so + disabling it will no longer disable handling ramdisk logs. As before, + you can set "ramdisk_logs_dir" option to an empty value (the default) + to disable storing ramdisk logs.