From b65ab065ea41ab1ae3c0e7b4ccb16d2627bf9e22 Mon Sep 17 00:00:00 2001 From: Dmitry Tantsur Date: Thu, 31 Mar 2016 16:46:36 +0200 Subject: [PATCH] Store ramdisk logs on all processing failures, not only reported by the ramdisk Previously the ramdisk logs were only stored if the ramdisk reported an error. However, we are moving from ramdisk-side validation to server-side, so we need ramdisk logs to be available if processing fails too. This change moves storing ramdisk logs from a ramdisk_error plugin to core processing code. As before, it can be disabled by setting ramdisk_logs_dir to an empty value. Change-Id: Ib3742ee1c1d4f2f96d29466626e1121694610dc3 Closes-Bug: #1564448 --- ironic_inspector/plugins/standard.py | 35 -------- ironic_inspector/process.py | 53 +++++++++++- .../test/unit/test_plugins_standard.py | 75 ---------------- ironic_inspector/test/unit/test_process.py | 85 +++++++++++++++++++ ...logs-on-all-failures-24da41edf3a98400.yaml | 11 +++ 5 files changed, 146 insertions(+), 113 deletions(-) create mode 100644 releasenotes/notes/ramdisk-logs-on-all-failures-24da41edf3a98400.yaml 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.