Merge "Store ramdisk logs on all processing failures, not only reported by the ramdisk"

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.