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