Add a log extension

The log extension is responsible for retrieving logs from the system,
if journalctl is present the logs will come from it, otherwise we
fallback to getting the logs from the /var/log directory + dmesg logs.

In the coreos ramdisk, we need to bind mount /run/log in the container
so the IPA service can have access to the journal.

For the tinyIPA ramdisk, the logs from IPA are now being redirected to
/var/logs/ironic-python-agent.log instead of only going to the default
stdout.

Inspector now shares the same method of collecting logs, extending its
capabilities for non-systemd systems.

Partial-Bug: #1587143
Change-Id: Ie507e2e5c58cffa255bbfb2fa5ffb95cb98ed8c4

10 files changed, 352 insertions, 53 deletions

diff --git a/imagebuild/coreos/oem/cloud-config.yml b/imagebuild/coreos/oem/cloud-config.yml
index f4f85f14..a50433cf 100644
--- a/imagebuild/coreos/oem/cloud-config.yml
+++ b/imagebuild/coreos/oem/cloud-config.yml
@@ -173,6 +173,22 @@ coreos:
         RemainAfterExit=yes
         ExecStart=/bin/ln -f /etc/resolv.conf /opt/ironic-python-agent/etc/resolv.conf
 
+    - name: opt-ironic\x2dpython\x2dagent-run-log.mount
+      command: start
+      content: |
+        [Unit]
+        DefaultDependencies=no
+        Conflicts=umount.target
+        Before=umount.target
+        After=ironic-python-agent-container-creation.service
+        Requires=ironic-python-agent-container-creation.service
+
+        [Mount]
+        What=/run/log
+        Where=/opt/ironic-python-agent/run/log
+        Type=none
+        Options=bind
+
     - name: ironic-python-agent.service
       command: start
       content: |
@@ -186,6 +202,7 @@ coreos:
         After=opt-ironic\x2dpython\x2dagent-run.mount
         After=opt-ironic\x2dpython\x2dagent-mnt.mount
         After=opt-ironic\x2dpython\x2dagent-etc-resolvconf.service
+        After=opt-ironic\x2dpython\x2dagent-run-log.mount
 
         Requires=ironic-python-agent-container-creation.service
         Requires=opt-ironic\x2dpython\x2dagent-proc.mount
@@ -195,6 +212,7 @@ coreos:
         Requires=opt-ironic\x2dpython\x2dagent-run.mount
         Requires=opt-ironic\x2dpython\x2dagent-mnt.mount
         Requires=opt-ironic\x2dpython\x2dagent-etc-resolvconf.service
+        Requires=opt-ironic\x2dpython\x2dagent-run-log.mount
 
         [Service]
         ExecStart=/usr/bin/chroot /opt/ironic-python-agent \
diff --git a/imagebuild/tinyipa/build_files/bootlocal.sh b/imagebuild/tinyipa/build_files/bootlocal.sh
index 280313fa..f93a538b 100755
--- a/imagebuild/tinyipa/build_files/bootlocal.sh
+++ b/imagebuild/tinyipa/build_files/bootlocal.sh
@@ -22,4 +22,4 @@ export PYTHONOPTIMIZE=1
 # Run IPA
 echo "Starting Ironic Python Agent:"
 date
-ironic-python-agent
+ironic-python-agent 2>&1 | tee /var/log/ironic-python-agent.log
diff --git a/ironic_python_agent/extensions/log.py b/ironic_python_agent/extensions/log.py
new file mode 100644
index 00000000..8889679e
--- /dev/null
+++ b/ironic_python_agent/extensions/log.py
@@ -0,0 +1,34 @@
+# Copyright 2016 Red Hat, Inc.
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+from ironic_python_agent.extensions import base
+from ironic_python_agent import utils
+
+
+class LogExtension(base.BaseAgentExtension):
+
+    @base.sync_command('collect_system_logs')
+    def collect_system_logs(self):
+        """Collect system logs.
+
+        Collect and package diagnostic and support data from the ramdisk.
+
+        :raises: CommandExecutionError if failed to collect the system logs.
+        :returns: A dictionary with the key `system_logs` and the value
+                  of a gzipped and base64 encoded string of the file with
+                  the logs.
+        """
+        logs = utils.collect_system_logs()
+        return {'system_logs': logs}
diff --git a/ironic_python_agent/inspector.py b/ironic_python_agent/inspector.py
index 3c59f9e3..766ce2ba 100644
--- a/ironic_python_agent/inspector.py
+++ b/ironic_python_agent/inspector.py
@@ -13,11 +13,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import base64
-import io
 import json
 import os
-import tarfile
 import time
 
 import netaddr
@@ -319,7 +316,7 @@ def collect_default(data, failures):
 
 
 def collect_logs(data, failures):
-    """Collect journald logs from the ramdisk.
+    """Collect system logs from the ramdisk.
 
     As inspection runs before any nodes details are known, it's handy to have
     logs returned with data. This collector sends logs to inspector in format
@@ -334,24 +331,11 @@ def collect_logs(data, failures):
     :param failures: AccumulatedFailures object
     """
     try:
-        out, _e = utils.execute('journalctl', '--full', '--no-pager', '-b',
-                                '-n', '10000', binary=True,
-                                log_stdout=False)
-    except (processutils.ProcessExecutionError, OSError):
+        data['logs'] = utils.collect_system_logs(journald_max_lines=10000)
+    except errors.CommandExecutionError:
         LOG.warning('failed to get system journal')
         return
 
-    journal = io.BytesIO(bytes(out))
-    with io.BytesIO() as fp:
-        with tarfile.open(fileobj=fp, mode='w:gz') as tar:
-            tarinfo = tarfile.TarInfo('journal')
-            tarinfo.size = len(out)
-            tarinfo.mtime = time.time()
-            tar.addfile(tarinfo, journal)
-
-        fp.seek(0)
-        data['logs'] = base64.b64encode(fp.getvalue())
-
 
 def collect_extra_hardware(data, failures):
     """Collect detailed inventory using 'hardware-detect' utility.
diff --git a/ironic_python_agent/tests/unit/extensions/test_log.py b/ironic_python_agent/tests/unit/extensions/test_log.py
new file mode 100644
index 00000000..ff90b914
--- /dev/null
+++ b/ironic_python_agent/tests/unit/extensions/test_log.py
@@ -0,0 +1,38 @@
+# Copyright 2016 Red Hat, Inc.
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+import mock
+
+from ironic_python_agent import utils
+from oslotest import base as test_base
+
+from ironic_python_agent.extensions import log
+
+
+class TestLogExtension(test_base.BaseTestCase):
+
+    def setUp(self):
+        super(TestLogExtension, self).setUp()
+        self.agent_extension = log.LogExtension()
+
+    @mock.patch.object(utils, 'collect_system_logs', autospec=True)
+    def test_collect_system_logs(self, mock_collect):
+        ret = 'Squidward Tentacles'
+        mock_collect.return_value = ret
+
+        cmd_result = self.agent_extension.collect_system_logs()
+        serialized_cmd_result = cmd_result.serialize()
+        expected_ret = {'system_logs': ret}
+        self.assertEqual(expected_ret, serialized_cmd_result['command_result'])
diff --git a/ironic_python_agent/tests/unit/test_inspector.py b/ironic_python_agent/tests/unit/test_inspector.py
index dfeb3a67..7f52ac9f 100644
--- a/ironic_python_agent/tests/unit/test_inspector.py
+++ b/ironic_python_agent/tests/unit/test_inspector.py
@@ -13,12 +13,9 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import base64
 import collections
 import copy
-import io
 import os
-import tarfile
 import time
 
 import mock
@@ -26,7 +23,6 @@ from oslo_concurrency import processutils
 from oslo_config import cfg
 from oslotest import base as test_base
 import requests
-import six
 import stevedore
 
 from ironic_python_agent import errors
@@ -379,41 +375,22 @@ class TestCollectDefault(BaseDiscoverTest):
         mock_wait_for_dhcp.assert_called_once_with()
 
 
-@mock.patch.object(utils, 'execute', autospec=True)
+@mock.patch.object(utils, 'collect_system_logs', autospec=True)
 class TestCollectLogs(test_base.BaseTestCase):
-    def test(self, mock_execute):
-        contents = 'journal contents \xd0\xbc\xd1\x8f\xd1\x83'
-        # That's how execute() works with binary=True
-        if six.PY3:
-            contents = b'journal contents \xd0\xbc\xd1\x8f\xd1\x83'
-        else:
-            contents = 'journal contents \xd0\xbc\xd1\x8f\xd1\x83'
-        expected_contents = u'journal contents \u043c\u044f\u0443'
-        mock_execute.return_value = (contents, '')
 
+    def test(self, mock_collect):
         data = {}
-        with mock.patch('time.time', return_value=42):
-            inspector.collect_logs(data, None)
-        res = io.BytesIO(base64.b64decode(data['logs']))
-
-        with tarfile.open(fileobj=res) as tar:
-            members = [(m.name, m.size, m.mtime) for m in tar]
-            self.assertEqual([('journal', len(contents), 42)], members)
-
-            member = tar.extractfile('journal')
-            self.assertEqual(expected_contents, member.read().decode('utf-8'))
+        ret = 'SpongeBob SquarePants'
+        mock_collect.return_value = ret
 
-        mock_execute.assert_called_once_with('journalctl', '--full',
-                                             '--no-pager', '-b',
-                                             '-n', '10000', binary=True,
-                                             log_stdout=False)
-
-    def test_no_journal(self, mock_execute):
-        mock_execute.side_effect = OSError()
+        inspector.collect_logs(data, None)
+        self.assertEqual({'logs': ret}, data)
 
+    def test_fail(self, mock_collect):
         data = {}
-        inspector.collect_logs(data, None)
-        self.assertFalse(data)
+        mock_collect.side_effect = errors.CommandExecutionError('boom')
+        self.assertIsNone(inspector.collect_logs(data, None))
+        self.assertNotIn('logs', data)
 
 
 @mock.patch.object(utils, 'execute', autospec=True)
diff --git a/ironic_python_agent/tests/unit/test_utils.py b/ironic_python_agent/tests/unit/test_utils.py
index be1626c7..aac438c9 100644
--- a/ironic_python_agent/tests/unit/test_utils.py
+++ b/ironic_python_agent/tests/unit/test_utils.py
@@ -13,10 +13,14 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import base64
 import errno
 import glob
+import io
 import os
 import shutil
+import subprocess
+import tarfile
 import tempfile
 import testtools
 
@@ -426,3 +430,115 @@ class TestFailures(testtools.TestCase):
         self.assertIsNone(f.raise_if_needed())
         f.add('foo')
         self.assertRaisesRegex(FakeException, 'foo', f.raise_if_needed)
+
+
+class TestUtils(testtools.TestCase):
+
+    def _get_journalctl_output(self, mock_execute, lines=None, units=None):
+        contents = b'Krusty Krab'
+        mock_execute.return_value = (contents, '')
+        data = utils.get_journalctl_output(lines=lines, units=units)
+
+        cmd = ['journalctl', '--full', '--no-pager', '-b']
+        if lines is not None:
+            cmd.extend(['-n', str(lines)])
+        if units is not None:
+            [cmd.extend(['-u', u]) for u in units]
+
+        mock_execute.assert_called_once_with(*cmd, binary=True,
+                                             log_stdout=False)
+        self.assertEqual(contents, data.read())
+
+    @mock.patch.object(utils, 'execute', autospec=True)
+    def test_get_journalctl_output(self, mock_execute):
+        self._get_journalctl_output(mock_execute)
+
+    @mock.patch.object(utils, 'execute', autospec=True)
+    def test_get_journalctl_output_with_lines(self, mock_execute):
+        self._get_journalctl_output(mock_execute, lines=123)
+
+    @mock.patch.object(utils, 'execute', autospec=True)
+    def test_get_journalctl_output_with_units(self, mock_execute):
+        self._get_journalctl_output(mock_execute, units=['fake-unit1',
+                                                         'fake-unit2'])
+
+    @mock.patch.object(utils, 'execute', autospec=True)
+    def test_get_journalctl_output_fail(self, mock_execute):
+        mock_execute.side_effect = processutils.ProcessExecutionError()
+        self.assertRaises(errors.CommandExecutionError,
+                          self._get_journalctl_output, mock_execute)
+
+    def test_gzip_and_b64encode(self):
+        contents = b'Squidward Tentacles'
+        io_dict = {'fake-name': io.BytesIO(bytes(contents))}
+        data = utils.gzip_and_b64encode(io_dict=io_dict)
+
+        res = io.BytesIO(base64.b64decode(data))
+        with tarfile.open(fileobj=res) as tar:
+            members = [(m.name, m.size) for m in tar]
+            self.assertEqual([('fake-name', len(contents))], members)
+
+            member = tar.extractfile('fake-name')
+            self.assertEqual(contents, member.read())
+
+    @mock.patch.object(utils, 'execute', autospec=True)
+    def test_get_command_output(self, mock_execute):
+        contents = b'Sandra Sandy Cheeks'
+        mock_execute.return_value = (contents, '')
+        data = utils.get_command_output(['foo'])
+
+        mock_execute.assert_called_once_with(
+            'foo', binary=True, log_stdout=False)
+        self.assertEqual(contents, data.read())
+
+    @mock.patch.object(subprocess, 'check_call')
+    def test_is_journalctl_present(self, mock_call):
+        self.assertTrue(utils.is_journalctl_present())
+
+    @mock.patch.object(subprocess, 'check_call')
+    def test_is_journalctl_present_false(self, mock_call):
+        os_error = OSError()
+        os_error.errno = errno.ENOENT
+        mock_call.side_effect = os_error
+        self.assertFalse(utils.is_journalctl_present())
+
+    @mock.patch.object(utils, 'gzip_and_b64encode')
+    @mock.patch.object(utils, 'is_journalctl_present')
+    @mock.patch.object(utils, 'get_command_output')
+    @mock.patch.object(utils, 'get_journalctl_output')
+    def test_collect_system_logs_journald(
+            self, mock_logs, mock_outputs, mock_journalctl, mock_gzip_b64):
+        mock_journalctl.return_value = True
+        ret = 'Patrick Star'
+        mock_gzip_b64.return_value = ret
+
+        logs_string = utils.collect_system_logs()
+        self.assertEqual(ret, logs_string)
+        mock_logs.assert_called_once_with(lines=None)
+        calls = [mock.call(['ps', '-ax']), mock.call(['df', '-a']),
+                 mock.call(['iptables', '-L']), mock.call(['ip', 'addr'])]
+        mock_outputs.assert_has_calls(calls, any_order=True)
+        mock_gzip_b64.assert_called_once_with(
+            file_list=[],
+            io_dict={'journal': mock.ANY, 'ip_addr': mock.ANY, 'ps': mock.ANY,
+                     'df': mock.ANY, 'iptables': mock.ANY})
+
+    @mock.patch.object(utils, 'gzip_and_b64encode')
+    @mock.patch.object(utils, 'is_journalctl_present')
+    @mock.patch.object(utils, 'get_command_output')
+    def test_collect_system_logs_non_journald(
+            self, mock_outputs, mock_journalctl, mock_gzip_b64):
+        mock_journalctl.return_value = False
+        ret = 'SpongeBob SquarePants'
+        mock_gzip_b64.return_value = ret
+
+        logs_string = utils.collect_system_logs()
+        self.assertEqual(ret, logs_string)
+        calls = [mock.call(['dmesg']), mock.call(['ps', '-ax']),
+                 mock.call(['df', '-a']), mock.call(['iptables', '-L']),
+                 mock.call(['ip', 'addr'])]
+        mock_outputs.assert_has_calls(calls, any_order=True)
+        mock_gzip_b64.assert_called_once_with(
+            file_list=['/var/log'],
+            io_dict={'iptables': mock.ANY, 'ip_addr': mock.ANY, 'ps': mock.ANY,
+                     'dmesg': mock.ANY, 'df': mock.ANY})
diff --git a/ironic_python_agent/utils.py b/ironic_python_agent/utils.py
index a5d0798b..023747dc 100644
--- a/ironic_python_agent/utils.py
+++ b/ironic_python_agent/utils.py
@@ -12,11 +12,17 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import base64
 import copy
+import errno
 import glob
+import io
 import os
 import shutil
+import subprocess
+import tarfile
 import tempfile
+import time
 
 from oslo_concurrency import processutils
 from oslo_log import log as logging
@@ -44,6 +50,14 @@ LOG = logging.getLogger(__name__)
 AGENT_PARAMS_CACHED = dict()
 
 
+COLLECT_LOGS_COMMANDS = {
+    'ps': ['ps', '-ax'],
+    'df': ['df', '-a'],
+    'iptables': ['iptables', '-L'],
+    'ip_addr': ['ip', 'addr'],
+}
+
+
 def execute(*cmd, **kwargs):
     """Convenience wrapper around oslo's execute() method.
 
@@ -305,3 +319,114 @@ def guess_root_disk(block_devices, min_size_required=4 * units.Gi):
     for device in block_devices:
         if device.size >= min_size_required:
             return device
+
+
+def is_journalctl_present():
+    """Check if the journalctl command is present.
+
+    :returns: True if journalctl is present, False if not.
+    """
+    try:
+        devnull = open(os.devnull)
+        subprocess.check_call(['journalctl', '--version'], stdout=devnull,
+                              stderr=devnull)
+    except OSError as e:
+        if e.errno == errno.ENOENT:
+            return False
+    return True
+
+
+def get_command_output(command):
+    """Return the output of a given command.
+
+    :param command: The command to be executed.
+    :raises: CommandExecutionError if the execution of the command fails.
+    :returns: A BytesIO string with the output.
+    """
+    try:
+        out, _ = execute(*command, binary=True, log_stdout=False)
+    except (processutils.ProcessExecutionError, OSError) as e:
+        error_msg = ('Failed to get the output of the command "%(command)s". '
+                     'Error: %(error)s' % {'command': command, 'error': e})
+        LOG.error(error_msg)
+        raise errors.CommandExecutionError(error_msg)
+    return io.BytesIO(out)
+
+
+def get_journalctl_output(lines=None, units=None):
+    """Query the contents of the systemd journal.
+
+    :param lines: Maximum number of lines to retrieve from the
+                  logs. If None, return everything.
+    :param units: A list with the names of the units we should
+                  retrieve the logs from. If None retrieve the logs
+                  for everything.
+    :returns: A log string.
+    """
+    cmd = ['journalctl', '--full', '--no-pager', '-b']
+    if lines is not None:
+        cmd.extend(['-n', str(lines)])
+    if units is not None:
+        [cmd.extend(['-u', u]) for u in units]
+
+    return get_command_output(cmd)
+
+
+def gzip_and_b64encode(io_dict=None, file_list=None):
+    """Gzip and base64 encode files and BytesIO buffers.
+
+    :param io_dict: A dictionary containg whose the keys are the file
+        names and the value a BytesIO object.
+    :param file_list: A list of file path.
+    :returns: A gzipped and base64 encoded string.
+    """
+    io_dict = io_dict or {}
+    file_list = file_list or []
+
+    with io.BytesIO() as fp:
+        with tarfile.open(fileobj=fp, mode='w:gz') as tar:
+            for fname in io_dict:
+                ioobj = io_dict[fname]
+                tarinfo = tarfile.TarInfo(name=fname)
+                tarinfo.size = ioobj.seek(0, 2)
+                tarinfo.mtime = time.time()
+                ioobj.seek(0)
+                tar.addfile(tarinfo, ioobj)
+
+            for f in file_list:
+                tar.add(f)
+
+        fp.seek(0)
+        return base64.b64encode(fp.getvalue())
+
+
+def collect_system_logs(journald_max_lines=None):
+    """Collect system logs.
+
+    Collect system logs, for distributions using systemd the logs will
+    come from journald. On other distributions the logs will come from
+    the /var/log directory and dmesg output.
+
+    :param journald_max_lines: Maximum number of lines to retrieve from
+                               the journald. if None, return everything.
+    :returns: A tar, gzip base64 encoded string with the logs.
+    """
+
+    def try_get_command_output(io_dict, file_name, command):
+        try:
+            io_dict[file_name] = get_command_output(command)
+        except errors.CommandExecutionError:
+            pass
+
+    io_dict = {}
+    file_list = []
+    if is_journalctl_present():
+        io_dict['journal'] = get_journalctl_output(lines=journald_max_lines)
+    else:
+        try_get_command_output(io_dict, 'dmesg', ['dmesg'])
+        file_list.append('/var/log')
+
+    for name, cmd in COLLECT_LOGS_COMMANDS.items():
+        try_get_command_output(io_dict, name, cmd)
+
+    return gzip_and_b64encode(io_dict=io_dict, file_list=file_list)
diff --git a/releasenotes/notes/add-log-extension-35ca22cc0709af4c.yaml b/releasenotes/notes/add-log-extension-35ca22cc0709af4c.yaml
new file mode 100644
index 00000000..00fbcb99
--- /dev/null
+++ b/releasenotes/notes/add-log-extension-35ca22cc0709af4c.yaml
@@ -0,0 +1,6 @@
+---
+features:
+  - A new "log" extension has been added and can be used to retrieve
+    the system logs via the IPA API.
+fixes:
+  - The "logs" inspection collector now works with the TinyIPA image.
diff --git a/setup.cfg b/setup.cfg
index 14a893e6..caab61c3 100644
--- a/setup.cfg
+++ b/setup.cfg
@@ -25,6 +25,7 @@ ironic_python_agent.extensions =
     flow = ironic_python_agent.extensions.flow:FlowExtension
     iscsi = ironic_python_agent.extensions.iscsi:ISCSIExtension
     image = ironic_python_agent.extensions.image:ImageExtension
+    log = ironic_python_agent.extensions.log:LogExtension
 
 ironic_python_agent.hardware_managers =
     generic = ironic_python_agent.hardware:GenericHardwareManager