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

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

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

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

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

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.