1# This file is part of cloud-init. See LICENSE file for license information.
2
3from datetime import datetime
4from textwrap import dedent
5
6from cloudinit.analyze.dump import (
7    dump_events, parse_ci_logline, parse_timestamp)
8from cloudinit.util import write_file
9from cloudinit.subp import which
10from cloudinit.tests.helpers import CiTestCase, mock, skipIf
11
12
13class TestParseTimestamp(CiTestCase):
14
15    def test_parse_timestamp_handles_cloud_init_default_format(self):
16        """Logs with cloud-init detailed formats will be properly parsed."""
17        trusty_fmt = '%Y-%m-%d %H:%M:%S,%f'
18        trusty_stamp = '2016-09-12 14:39:20,839'
19        dt = datetime.strptime(trusty_stamp, trusty_fmt)
20        self.assertEqual(
21            float(dt.strftime('%s.%f')), parse_timestamp(trusty_stamp))
22
23    def test_parse_timestamp_handles_syslog_adding_year(self):
24        """Syslog timestamps lack a year. Add year and properly parse."""
25        syslog_fmt = '%b %d %H:%M:%S %Y'
26        syslog_stamp = 'Aug 08 15:12:51'
27
28        # convert stamp ourselves by adding the missing year value
29        year = datetime.now().year
30        dt = datetime.strptime(syslog_stamp + " " + str(year), syslog_fmt)
31        self.assertEqual(
32            float(dt.strftime('%s.%f')),
33            parse_timestamp(syslog_stamp))
34
35    def test_parse_timestamp_handles_journalctl_format_adding_year(self):
36        """Journalctl precise timestamps lack a year. Add year and parse."""
37        journal_fmt = '%b %d %H:%M:%S.%f %Y'
38        journal_stamp = 'Aug 08 17:15:50.606811'
39
40        # convert stamp ourselves by adding the missing year value
41        year = datetime.now().year
42        dt = datetime.strptime(journal_stamp + " " + str(year), journal_fmt)
43        self.assertEqual(
44            float(dt.strftime('%s.%f')), parse_timestamp(journal_stamp))
45
46    @skipIf(not which("date"), "'date' command not available.")
47    def test_parse_unexpected_timestamp_format_with_date_command(self):
48        """Dump sends unexpected timestamp formats to date for processing."""
49        new_fmt = '%H:%M %m/%d %Y'
50        new_stamp = '17:15 08/08'
51        # convert stamp ourselves by adding the missing year value
52        year = datetime.now().year
53        dt = datetime.strptime(new_stamp + " " + str(year), new_fmt)
54
55        # use date(1)
56        with self.allow_subp(["date"]):
57            self.assertEqual(
58                float(dt.strftime('%s.%f')), parse_timestamp(new_stamp))
59
60
61class TestParseCILogLine(CiTestCase):
62
63    def test_parse_logline_returns_none_without_separators(self):
64        """When no separators are found, parse_ci_logline returns None."""
65        expected_parse_ignores = [
66            '', '-', 'adsf-asdf', '2017-05-22 18:02:01,088', 'CLOUDINIT']
67        for parse_ignores in expected_parse_ignores:
68            self.assertIsNone(parse_ci_logline(parse_ignores))
69
70    def test_parse_logline_returns_event_for_cloud_init_logs(self):
71        """parse_ci_logline returns an event parse from cloud-init format."""
72        line = (
73            "2017-08-08 20:05:07,147 - util.py[DEBUG]: Cloud-init v. 0.7.9"
74            " running 'init-local' at Tue, 08 Aug 2017 20:05:07 +0000. Up"
75            " 6.26 seconds.")
76        dt = datetime.strptime(
77            '2017-08-08 20:05:07,147', '%Y-%m-%d %H:%M:%S,%f')
78        timestamp = float(dt.strftime('%s.%f'))
79        expected = {
80            'description': 'starting search for local datasources',
81            'event_type': 'start',
82            'name': 'init-local',
83            'origin': 'cloudinit',
84            'timestamp': timestamp}
85        self.assertEqual(expected, parse_ci_logline(line))
86
87    def test_parse_logline_returns_event_for_journalctl_logs(self):
88        """parse_ci_logline returns an event parse from journalctl format."""
89        line = ("Nov 03 06:51:06.074410 x2 cloud-init[106]: [CLOUDINIT]"
90                " util.py[DEBUG]: Cloud-init v. 0.7.8 running 'init-local' at"
91                "  Thu, 03 Nov 2016 06:51:06 +0000. Up 1.0 seconds.")
92        year = datetime.now().year
93        dt = datetime.strptime(
94            'Nov 03 06:51:06.074410 %d' % year, '%b %d %H:%M:%S.%f %Y')
95        timestamp = float(dt.strftime('%s.%f'))
96        expected = {
97            'description': 'starting search for local datasources',
98            'event_type': 'start',
99            'name': 'init-local',
100            'origin': 'cloudinit',
101            'timestamp': timestamp}
102        self.assertEqual(expected, parse_ci_logline(line))
103
104    @mock.patch("cloudinit.analyze.dump.parse_timestamp_from_date")
105    def test_parse_logline_returns_event_for_finish_events(self,
106                                                           m_parse_from_date):
107        """parse_ci_logline returns a finish event for a parsed log line."""
108        line = ('2016-08-30 21:53:25.972325+00:00 y1 [CLOUDINIT]'
109                ' handlers.py[DEBUG]: finish: modules-final: SUCCESS: running'
110                ' modules for final')
111        expected = {
112            'description': 'running modules for final',
113            'event_type': 'finish',
114            'name': 'modules-final',
115            'origin': 'cloudinit',
116            'result': 'SUCCESS',
117            'timestamp': 1472594005.972}
118        m_parse_from_date.return_value = "1472594005.972"
119        self.assertEqual(expected, parse_ci_logline(line))
120        m_parse_from_date.assert_has_calls(
121            [mock.call("2016-08-30 21:53:25.972325+00:00")])
122
123    def test_parse_logline_returns_event_for_amazon_linux_2_line(self):
124        line = (
125            "Apr 30 19:39:11 cloud-init[2673]: handlers.py[DEBUG]: start:"
126            " init-local/check-cache: attempting to read from cache [check]")
127        # Generate the expected value using `datetime`, so that TZ
128        # determination is consistent with the code under test.
129        timestamp_dt = datetime.strptime(
130            "Apr 30 19:39:11", "%b %d %H:%M:%S"
131        ).replace(year=datetime.now().year)
132        expected = {
133            'description': 'attempting to read from cache [check]',
134            'event_type': 'start',
135            'name': 'init-local/check-cache',
136            'origin': 'cloudinit',
137            'timestamp': timestamp_dt.timestamp()}
138        self.assertEqual(expected, parse_ci_logline(line))
139
140
141SAMPLE_LOGS = dedent("""\
142Nov 03 06:51:06.074410 x2 cloud-init[106]: [CLOUDINIT] util.py[DEBUG]:\
143 Cloud-init v. 0.7.8 running 'init-local' at Thu, 03 Nov 2016\
144 06:51:06 +0000. Up 1.0 seconds.
1452016-08-30 21:53:25.972325+00:00 y1 [CLOUDINIT] handlers.py[DEBUG]: finish:\
146 modules-final: SUCCESS: running modules for final
147""")
148
149
150class TestDumpEvents(CiTestCase):
151    maxDiff = None
152
153    @mock.patch("cloudinit.analyze.dump.parse_timestamp_from_date")
154    def test_dump_events_with_rawdata(self, m_parse_from_date):
155        """Rawdata is split and parsed into a tuple of events and data"""
156        m_parse_from_date.return_value = "1472594005.972"
157        events, data = dump_events(rawdata=SAMPLE_LOGS)
158        expected_data = SAMPLE_LOGS.splitlines()
159        self.assertEqual(
160            [mock.call("2016-08-30 21:53:25.972325+00:00")],
161            m_parse_from_date.call_args_list)
162        self.assertEqual(expected_data, data)
163        year = datetime.now().year
164        dt1 = datetime.strptime(
165            'Nov 03 06:51:06.074410 %d' % year, '%b %d %H:%M:%S.%f %Y')
166        timestamp1 = float(dt1.strftime('%s.%f'))
167        expected_events = [{
168            'description': 'starting search for local datasources',
169            'event_type': 'start',
170            'name': 'init-local',
171            'origin': 'cloudinit',
172            'timestamp': timestamp1}, {
173            'description': 'running modules for final',
174            'event_type': 'finish',
175            'name': 'modules-final',
176            'origin': 'cloudinit',
177            'result': 'SUCCESS',
178            'timestamp': 1472594005.972}]
179        self.assertEqual(expected_events, events)
180
181    @mock.patch("cloudinit.analyze.dump.parse_timestamp_from_date")
182    def test_dump_events_with_cisource(self, m_parse_from_date):
183        """Cisource file is read and parsed into a tuple of events and data."""
184        tmpfile = self.tmp_path('logfile')
185        write_file(tmpfile, SAMPLE_LOGS)
186        m_parse_from_date.return_value = 1472594005.972
187
188        events, data = dump_events(cisource=open(tmpfile))
189        year = datetime.now().year
190        dt1 = datetime.strptime(
191            'Nov 03 06:51:06.074410 %d' % year, '%b %d %H:%M:%S.%f %Y')
192        timestamp1 = float(dt1.strftime('%s.%f'))
193        expected_events = [{
194            'description': 'starting search for local datasources',
195            'event_type': 'start',
196            'name': 'init-local',
197            'origin': 'cloudinit',
198            'timestamp': timestamp1}, {
199            'description': 'running modules for final',
200            'event_type': 'finish',
201            'name': 'modules-final',
202            'origin': 'cloudinit',
203            'result': 'SUCCESS',
204            'timestamp': 1472594005.972}]
205        self.assertEqual(expected_events, events)
206        self.assertEqual(SAMPLE_LOGS.splitlines(), [d.strip() for d in data])
207        m_parse_from_date.assert_has_calls(
208            [mock.call("2016-08-30 21:53:25.972325+00:00")])
209