curtin

Merge lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests into lp:~curtin-dev/curtin/trunk

  1. trunk.add-web-reporter-to-vmtests
  2. Merge into trunk
Proposed by Ryan Harper
Status: Merged
Approved by: Scott Moser
Approved revision: 405
Merged at revision: 465
Proposed branch: lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests
Merge into: lp:~curtin-dev/curtin/trunk
Diff against target: 978 lines (+543/-141)
15 files modified
curtin/commands/block_meta.py (+2/-1)
curtin/commands/curthooks.py (+21/-8)
curtin/commands/install.py (+18/-0)
curtin/reporter/events.py (+4/-9)
curtin/util.py (+12/-6)
tests/unittests/test_pack.py (+1/-0)
tests/unittests/test_reporter.py (+4/-8)
tests/vmtests/__init__.py (+74/-6)
tests/vmtests/helpers.py (+4/-1)
tests/vmtests/report_webhook_logger.py (+187/-0)
tools/curtin-log-print (+197/-0)
tools/report-webhook-logger (+0/-100)
tools/report_webhook_logger (+6/-0)
tools/run-pep8 (+6/-1)
tools/run-pyflakes (+7/-1)
To merge this branch: bzr merge lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests
Reviewer Review Type Date Requested Status
Scott Moser (community) Approve
Server Team CI bot continuous-integration Approve
Review via email: mp+298227@code.launchpad.net

Commit message

reporting: Add better descriptions and granularity of events

Add more human readable descriptions to the events and increase the number
of events we report to provide greater context in what's occurring during
a curtin install.

Add webhook reporting to all vmtests, including a unittest to catch if curtin
sends the install log to the webservice.

Refactor the in-tree webhook logger to be used as a module for use in vmtest

Add tools/curtin-log-print to pretty-print curtin install logs with custom
formatter and sorter.

Description of the change

reporting: Add better descriptions and granularity of events

Add more human readable descriptions to the events and increase the number
of events we report to provide greater context in what's occurring during
a curtin install.

Add webhook reporting to all vmtests, including a unittest to catch if curtin
sends the install log to the webservice.

Refactor the in-tree webhook logger to be used as a module for use in vmtest

Add tools/curtin-log-print to pretty-print curtin install logs with custom
formatter and sorter.

To post a comment you must log in.
Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:390
https://server-team-jenkins.canonical.com/job/curtin-ci/274/
Executed test runs:
    None: https://server-team-jenkins.canonical.com/job/generic-update-mp/271/console

Click here to trigger a rebuild:
https://server-team-jenkins.canonical.com/job/curtin-ci/274/rebuild

review: Approve (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
391. By Ryan Harper

merge from trunk

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:391
https://server-team-jenkins.canonical.com/job/curtin-ci/196/
Executed test runs:
    SUCCESS: https://server-team-jenkins.canonical.com/job/curtin-ci/nodes=amd64/196
    SUCCESS: https://server-team-jenkins.canonical.com/job/curtin-ci/nodes=ppc64el/196

Click here to trigger a rebuild:
https://server-team-jenkins.canonical.com/job/curtin-ci/196/rebuild

review: Approve (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
392. By Ryan Harper

merge wesley's updates to reporter

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:392
https://server-team-jenkins.canonical.com/job/curtin-ci/198/
Executed test runs:
    SUCCESS: https://server-team-jenkins.canonical.com/job/curtin-ci/nodes=amd64/198
    SUCCESS: https://server-team-jenkins.canonical.com/job/curtin-ci/nodes=ppc64el/198

Click here to trigger a rebuild:
https://server-team-jenkins.canonical.com/job/curtin-ci/198/rebuild

review: Approve (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
393. By Ryan Harper

merge from trunk

394. By Ryan Harper

curtin-log-print: write out event files instead of just printing them, save to cwd.

395. By Ryan Harper

merge from trunk

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

FAILED: Continuous integration, rev:395
https://jenkins.ubuntu.com/server/job/curtin-ci/326/
Executed test runs:
    FAILURE: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/326/console
    FAILURE: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/326/console
    FAILURE: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/326/console
    FAILURE: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/326/console
    FAILURE: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/326/console

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/326/rebuild

review: Needs Fixing (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
396. By Ryan Harper

Use ip_a_to_dict when finding host ip

397. By Ryan Harper <email address hidden>

fix getting host gateway ip for vmtest reporting

398. By Ryan Harper

merge from trunk

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:398
https://jenkins.ubuntu.com/server/job/curtin-ci/330/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/330
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/330
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/330
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/330
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/330

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/330/rebuild

review: Approve (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
399. By Ryan Harper

merge from trunk

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:399
https://jenkins.ubuntu.com/server/job/curtin-ci/348/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/348
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/348
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/348
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/348
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/348

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/348/rebuild

review: Approve (continuous-integration)
Revision history for this message
Ryan Harper (raharper) wrote :

vmtests ran on diglett:

Ran 1552 tests in 10582.920s

OK (SKIP=1)

lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
400. By Ryan Harper

merge from trunk

401. By Ryan Harper

Make collect output dir usable by non-root

vmtests now copy /root from within the VM to examine the curtin install log
Some OSes we run have more restrictive root permissions which prevent
non-root users on the host from removing the collect dir. Resolve this by
fixing permissions recursively after untarring.

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:401
https://jenkins.ubuntu.com/server/job/curtin-ci/354/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/354
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/354
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/354
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/354
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/354

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/354/rebuild

review: Approve (continuous-integration)
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
402. By Ryan Harper

merge from diglett, fix curtin-log-print time calculations

Revision history for this message
Ryan Harper (raharper) wrote :

Look at the "pretty" output:

% ./tools/curtin-log-print output/YakketyTestBridging/logs/webhooks-events.json
The total time elapsed since completing an event is printed after the "@" character.
The time the event takes is printed after the "+" character.

[00.00000] curtin command install
|`->preparing for installation @00.03245s +00.00432s
| `->curtin command block-meta @00.74075s +00.31162s
| `->running 'curtin block-meta simple' @00.77128s +00.73040s
|`->configuring storage @00.77885s +00.74375s
| `->curtin command net-meta @01.20295s +00.01775s
| `->running 'curtin net-meta auto' @01.26119s +00.47551s
|`->configuring network @01.26803s +00.48581s
| `->acquiring and extracting image from http://<foo>:38878//vmtest.root-tgz @12.21989s +10.59816s
| `->curtin command extract @12.22587s +10.60414s
| `->running 'curtin extract' @12.25528s +10.97986s
|`->writing install sources to disk @12.26237s +10.99108s
| `->writing config files and configuring apt @12.80547s +00.08445s
| `->Installing packages on target system: ['bridge-utils'] @17.74691s +04.91033s
| `->installing kernel @75.94985s +58.19748s
| `->setting up swap @75.98323s +00.02837s
| `->apply networking config @76.02617s +00.03834s
| `->writing etc/fstab @76.03918s +00.00603s
| `->configuring multipath @76.23384s +00.18823s
| `->installing missing packages @76.26244s +00.02305s
| `->updating packages on target system @76.27560s +00.00684s
| `->curtin command curthooks @77.33753s +64.50094s
| `->running 'curtin curthooks' @77.36807s +65.09799s
|`->configuring installed system @77.37604s +65.10981s
| `->curtin command hook @77.79744s +00.00865s
| `->running 'curtin hook' @77.82802s +00.44200s
|`->finalizing installation @77.83520s +00.45403s
|`->executing late commands @77.84598s +00.00588s
|`->curtin command install @77.99770s +77.99770s
  ---
77.99770 seconds total time

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:402
https://jenkins.ubuntu.com/server/job/curtin-ci/355/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/355
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/355
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/355
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/355
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/355

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/355/rebuild

review: Approve (continuous-integration)
Revision history for this message
Scott Moser (smoser) wrote :

over all looks great.
thank you.

lets avoid importing from tools.<thing>.
rather lets move that to vmtest and we can have a tools/ that just imports it there.

review: Approve
lp:~raharper/curtin/trunk.add-web-reporter-to-vmtests updated
403. By Ryan Harper

report_webhook cleanup

- Move .py from tools and put in tests/vmtests
- Adjust vmtests import of report_webhook_logger
- Add tools/report_webhook_logger wrapper
- Switch to socket.AF_INET6 which supports v6 and v4

404. By Ryan Harper

Remove .py from report_webhook_logger in tools

405. By Ryan Harper

Update httpd.server_address return signature

Revision history for this message
Server Team CI bot (server-team-bot) wrote :

PASSED: Continuous integration, rev:405
https://jenkins.ubuntu.com/server/job/curtin-ci/358/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/358
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/358
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-s390x/358
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-amd64/358
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/358

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/358/rebuild

review: Approve (continuous-integration)
Revision history for this message
Scott Moser (smoser) wrote :

lets get this in.

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'curtin/commands/block_meta.py'
2--- curtin/commands/block_meta.py 2017-02-08 05:56:12 +0000
3+++ curtin/commands/block_meta.py 2017-02-10 17:07:49 +0000
4@@ -602,7 +602,8 @@
5 # Figure out what point should be
6 while len(path) > 0 and path[0] == "/":
7 path = path[1:]
8- mount_point = os.path.join(state['target'], path)
9+ mount_point = os.path.sep.join([state['target'], path])
10+ mount_point = os.path.normpath(mount_point)
11
12 # Create mount point if does not exist
13 util.ensure_dir(mount_point)
14
15=== modified file 'curtin/commands/curthooks.py'
16--- curtin/commands/curthooks.py 2017-02-09 19:59:11 +0000
17+++ curtin/commands/curthooks.py 2017-02-10 17:07:49 +0000
18@@ -684,7 +684,8 @@
19 stack_prefix = state.get('report_stack_prefix', '')
20
21 with events.ReportEventStack(
22- name=stack_prefix, reporting_enabled=True, level="INFO",
23+ name=stack_prefix + '/writing-config',
24+ reporting_enabled=True, level="INFO",
25 description="writing config files and configuring apt"):
26 write_files(cfg, target)
27 do_apt_config(cfg, target)
28@@ -705,7 +706,8 @@
29 data=None, target=target)
30
31 with events.ReportEventStack(
32- name=stack_prefix, reporting_enabled=True, level="INFO",
33+ name=stack_prefix + '/installing-kernel',
34+ reporting_enabled=True, level="INFO",
35 description="installing kernel"):
36 setup_zipl(cfg, target)
37 install_kernel(cfg, target)
38@@ -714,27 +716,38 @@
39 restore_dist_interfaces(cfg, target)
40
41 with events.ReportEventStack(
42- name=stack_prefix, reporting_enabled=True, level="INFO",
43+ name=stack_prefix + '/setting-up-swap',
44+ reporting_enabled=True, level="INFO",
45 description="setting up swap"):
46 add_swap(cfg, target, state.get('fstab'))
47
48 with events.ReportEventStack(
49- name=stack_prefix, reporting_enabled=True, level="INFO",
50- description="apply networking"):
51+ name=stack_prefix + '/apply-networking-config',
52+ reporting_enabled=True, level="INFO",
53+ description="apply networking config"):
54 apply_networking(target, state)
55
56 with events.ReportEventStack(
57- name=stack_prefix, reporting_enabled=True, level="INFO",
58+ name=stack_prefix + '/writing-etc-fstab',
59+ reporting_enabled=True, level="INFO",
60 description="writing etc/fstab"):
61 copy_fstab(state.get('fstab'), target)
62
63 with events.ReportEventStack(
64- name=stack_prefix, reporting_enabled=True, level="INFO",
65+ name=stack_prefix + '/configuring-multipath',
66+ reporting_enabled=True, level="INFO",
67 description="configuring multipath"):
68 detect_and_handle_multipath(cfg, target)
69
70 with events.ReportEventStack(
71- name=stack_prefix, reporting_enabled=True, level="INFO",
72+ name=stack_prefix + '/installing-missing-packages',
73+ reporting_enabled=True, level="INFO",
74+ description="installing missing packages"):
75+ install_missing_packages(cfg, target)
76+
77+ with events.ReportEventStack(
78+ name=stack_prefix + '/system-upgrade',
79+ reporting_enabled=True, level="INFO",
80 description="updating packages on target system"):
81 system_upgrade(cfg, target)
82
83
84=== modified file 'curtin/commands/install.py'
85--- curtin/commands/install.py 2017-02-09 19:59:11 +0000
86+++ curtin/commands/install.py 2017-02-10 17:07:49 +0000
87@@ -76,6 +76,20 @@
88 pass
89
90
91+def copy_install_log(logfile, target, log_target_path):
92+ """Copy curtin install log file to target system"""
93+ if not logfile:
94+ LOG.warn('Cannot copy curtin install log to target, no log exists')
95+ return
96+
97+ LOG.debug('Copying curtin install log to target')
98+ target = os.path.sep.join([target, log_target_path])
99+ if os.path.exists(target):
100+ shutil.copy(logfile, os.path.normpath(target))
101+ else:
102+ LOG.debug('install log file not at path: %s', target)
103+
104+
105 def writeline_and_stdout(logfile, message):
106 writeline(logfile, message)
107 out = sys.stdout
108@@ -432,6 +446,10 @@
109 legacy_reporter.report_failure(exp_msg)
110 raise e
111 finally:
112+ log_target_path = instcfg.get('save_install_log',
113+ '/root/curtin-install.log')
114+ if log_target_path:
115+ copy_install_log(logfile, workingd.target, log_target_path)
116 for d in ('sys', 'dev', 'proc'):
117 util.do_umount(os.path.join(workingd.target, d))
118 mounted = block.get_mountpoints()
119
120=== modified file 'curtin/reporter/events.py'
121--- curtin/reporter/events.py 2016-05-06 17:21:33 +0000
122+++ curtin/reporter/events.py 2017-02-10 17:07:49 +0000
123@@ -84,6 +84,10 @@
124 self.post_files = post_files
125 if result not in status:
126 raise ValueError("Invalid result: %s" % result)
127+ if self.result == status.WARN:
128+ self.level = "WARN"
129+ elif self.result == status.FAIL:
130+ self.level = "ERROR"
131
132 def as_string(self):
133 return '{0}: {1}: {2}: {3}'.format(
134@@ -95,10 +99,6 @@
135 data['result'] = self.result
136 if self.post_files:
137 data['files'] = _collect_file_info(self.post_files)
138- if self.result == status.WARN:
139- data['level'] = "WARN"
140- elif self.result == status.FAIL:
141- data['level'] = "ERROR"
142 return data
143
144
145@@ -122,10 +122,6 @@
146
147 See :py:func:`.report_event` for parameter details.
148 """
149- if result == status.SUCCESS:
150- event_description = "finished: " + event_description
151- else:
152- event_description = "failed: " + event_description
153 event = FinishReportingEvent(event_name, event_description, result,
154 post_files=post_files, level=level)
155 return report_event(event)
156@@ -141,7 +137,6 @@
157 :param event_description:
158 A human-readable description of the event that has occurred.
159 """
160- event_description = "started: " + event_description
161 event = ReportingEvent(START_EVENT_TYPE, event_name, event_description,
162 level=level)
163 return report_event(event)
164
165=== modified file 'curtin/util.py'
166--- curtin/util.py 2017-02-09 19:59:11 +0000
167+++ curtin/util.py 2017-02-10 17:07:49 +0000
168@@ -213,8 +213,9 @@
169 'Command: %(cmd)s\n'
170 'Exit code: %(exit_code)s\n'
171 'Reason: %(reason)s\n'
172- 'Stdout: %(stdout)r\n'
173- 'Stderr: %(stderr)r')
174+ 'Stdout: %(stdout)s\n'
175+ 'Stderr: %(stderr)s')
176+ stdout_indent_level = 8
177
178 def __init__(self, stdout=None, stderr=None,
179 exit_code=None, cmd=None,
180@@ -235,14 +236,14 @@
181 self.exit_code = exit_code
182
183 if not stderr:
184- self.stderr = ''
185+ self.stderr = "''"
186 else:
187- self.stderr = stderr
188+ self.stderr = self._indent_text(stderr)
189
190 if not stdout:
191- self.stdout = ''
192+ self.stdout = "''"
193 else:
194- self.stdout = stdout
195+ self.stdout = self._indent_text(stdout)
196
197 if reason:
198 self.reason = reason
199@@ -259,6 +260,11 @@
200 }
201 IOError.__init__(self, message)
202
203+ def _indent_text(self, text):
204+ if type(text) == bytes:
205+ text = text.decode()
206+ return text.replace('\n', '\n' + ' ' * self.stdout_indent_level)
207+
208
209 class LogTimer(object):
210 def __init__(self, logfunc, msg):
211
212=== modified file 'tests/unittests/test_pack.py'
213--- tests/unittests/test_pack.py 2017-02-07 19:20:27 +0000
214+++ tests/unittests/test_pack.py 2017-02-10 17:07:49 +0000
215@@ -68,6 +68,7 @@
216 mcfg['install'] = {'log_file': log_file}
217 mcfg['sources'] = {'testsrc': src_url}
218 util.write_file(cfg_file, json.dumps(mcfg))
219+ print(json.dumps(mcfg))
220 try:
221 out, err = self.run_main(['install', '--config=' + cfg_file])
222 rc = 0
223
224=== modified file 'tests/unittests/test_reporter.py'
225--- tests/unittests/test_reporter.py 2016-06-14 13:54:46 +0000
226+++ tests/unittests/test_reporter.py 2017-02-10 17:07:49 +0000
227@@ -147,8 +147,7 @@
228 event_dict = self._get_reported_event(mock_report_event).as_dict()
229 self.assertEqual(event_dict.get('name'), self.ev_name)
230 self.assertEqual(event_dict.get('level'), 'INFO')
231- self.assertEqual(event_dict.get('description'),
232- 'started: ' + self.ev_desc)
233+ self.assertEqual(event_dict.get('description'), self.ev_desc)
234 self.assertEqual(event_dict.get('event_type'), events.START_EVENT_TYPE)
235
236 @patch('curtin.reporter.events.report_event')
237@@ -157,8 +156,7 @@
238 event = self._get_reported_event(mock_report_event)
239 self.assertIsInstance(event, events.FinishReportingEvent)
240 event_dict = event.as_dict()
241- self.assertEqual(event_dict.get('description'),
242- 'finished: ' + self.ev_desc)
243+ self.assertEqual(event_dict.get('description'), self.ev_desc)
244
245 @patch('curtin.reporter.events.report_event')
246 def test_report_finished_event_levelset(self, mock_report_event):
247@@ -166,15 +164,13 @@
248 result=events.status.FAIL)
249 event_dict = self._get_reported_event(mock_report_event).as_dict()
250 self.assertEqual(event_dict.get('level'), 'ERROR')
251- self.assertEqual(event_dict.get('description'),
252- 'failed: ' + self.ev_desc)
253+ self.assertEqual(event_dict.get('description'), self.ev_desc)
254
255 events.report_finish_event(self.ev_name, self.ev_desc,
256 result=events.status.WARN)
257 event_dict = self._get_reported_event(mock_report_event).as_dict()
258 self.assertEqual(event_dict.get('level'), 'WARN')
259- self.assertEqual(event_dict.get('description'),
260- 'failed: ' + self.ev_desc)
261+ self.assertEqual(event_dict.get('description'), self.ev_desc)
262
263 @patch('curtin.reporter.events.report_event')
264 def test_report_finished_post_files(self, mock_report_event):
265
266=== modified file 'tests/vmtests/__init__.py'
267--- tests/vmtests/__init__.py 2017-02-08 20:50:59 +0000
268+++ tests/vmtests/__init__.py 2017-02-10 17:07:49 +0000
269@@ -14,12 +14,13 @@
270 import curtin.net as curtin_net
271 import curtin.util as util
272
273+from .report_webhook_logger import CaptureReporting
274 from curtin.commands.install import INSTALL_PASS_MSG
275
276 from .image_sync import query as imagesync_query
277 from .image_sync import mirror as imagesync_mirror
278 from .image_sync import (IMAGE_SRC_URL, IMAGE_DIR, ITEM_NAME_FILTERS)
279-from .helpers import check_call, TimeoutExpired
280+from .helpers import check_call, TimeoutExpired, ip_a_to_dict
281 from unittest import TestCase, SkipTest
282
283 try:
284@@ -316,6 +317,9 @@
285 subprocess.check_call(['tar', '-C', self.collect, '-xf',
286 self.output_disk],
287 stdout=DEVNULL, stderr=subprocess.STDOUT)
288+ # make sure collect output dir is usable by non-root
289+ subprocess.check_call(['chmod', '-R', 'u+rwX', self.collect],
290+ stdout=DEVNULL, stderr=subprocess.STDOUT)
291
292
293 class VMBaseClass(TestCase):
294@@ -517,6 +521,30 @@
295 if cls.multipath:
296 disks = disks * cls.multipath_num_paths
297
298+ # set reporting logger
299+ cls.reporting_log = os.path.join(cls.td.logs, 'webhooks-events.json')
300+ reporting_logger = CaptureReporting(cls.reporting_log)
301+
302+ # write reporting config
303+ reporting_config = os.path.join(cls.td.install, 'reporting.cfg')
304+ localhost_url = ('http://' + get_lan_ip() +
305+ ':{:d}/'.format(reporting_logger.port))
306+ with open(reporting_config, 'w') as fp:
307+ fp.write(json.dumps({
308+ 'install': {
309+ 'log_file': '/tmp/install.log',
310+ 'post_files': ['/tmp/install.log'],
311+ },
312+ 'reporting': {
313+ 'maas': {
314+ 'level': 'DEBUG',
315+ 'type': 'webhook',
316+ 'endpoint': localhost_url,
317+ },
318+ },
319+ }))
320+ configs.append(reporting_config)
321+
322 cmd.extend(uefi_flags + netdevs + disks +
323 [ftypes['vmtest.root-image'], "--kernel=%s" %
324 ftypes['boot-kernel'], "--initrd=%s" %
325@@ -529,9 +557,10 @@
326 logger.info('Running curtin installer: {}'.format(cls.install_log))
327 try:
328 with open(lout_path, "wb") as fpout:
329- cls.boot_system(cmd, timeout=cls.install_timeout,
330- console_log=cls.install_log, proc_out=fpout,
331- purpose="install")
332+ with reporting_logger:
333+ cls.boot_system(cmd, timeout=cls.install_timeout,
334+ console_log=cls.install_log,
335+ proc_out=fpout, purpose="install")
336 except TimeoutExpired:
337 logger.error('Curtin installer failed with timeout')
338 cls.tearDownClass()
339@@ -825,6 +854,25 @@
340 self.assertIn(link, contents)
341 self.assertIn(diskname, contents)
342
343+ def test_reporting_data(self):
344+ with open(self.reporting_log, 'r') as fp:
345+ data = json.load(fp)
346+ self.assertTrue(len(data) > 0)
347+ first_event = data[0]
348+ self.assertEqual(first_event['event_type'], 'start')
349+ next_event = data[1]
350+ # make sure we don't have that timestamp bug
351+ self.assertNotEqual(first_event['timestamp'], next_event['timestamp'])
352+ final_event = data[-1]
353+ self.assertEqual(final_event['event_type'], 'finish')
354+ self.assertEqual(final_event['name'], 'cmd-install')
355+ # check for install log
356+ [events_with_files] = [ev for ev in data if 'files' in ev]
357+ self.assertIn('files', events_with_files)
358+ [files] = events_with_files.get('files', [])
359+ self.assertIn('path', files)
360+ self.assertEqual('/tmp/install.log', files.get('path', ''))
361+
362 def test_interfacesd_eth0_removed(self):
363 """ Check that curtin has removed /etc/network/interfaces.d/eth0.cfg
364 by examining the output of a find /etc/network > find_interfaces.d
365@@ -938,6 +986,9 @@
366 def test_interfacesd_eth0_removed(self):
367 pass
368
369+ def test_reporting_data(self):
370+ pass
371+
372 def _maybe_raise(self, exc):
373 if self.allow_test_fails:
374 raise exc
375@@ -1044,6 +1095,9 @@
376 collect_post = textwrap.dedent(
377 'tar -C "%s" -cf "%s" .' % (output_dir, output_device))
378
379+ # copy /root for curtin config and install.log
380+ copy_rootdir = textwrap.dedent("cp -a /root " + output_dir)
381+
382 # failsafe poweroff runs on precise and centos only, where power_state does
383 # not exist.
384 failsafe_poweroff = textwrap.dedent("""#!/bin/sh -x
385@@ -1054,8 +1108,8 @@
386 exit 0;
387 """)
388
389- scripts = ([collect_prep] + collect_scripts + [collect_post] +
390- [failsafe_poweroff])
391+ scripts = ([collect_prep] + [copy_rootdir] + collect_scripts +
392+ [collect_post] + [failsafe_poweroff])
393
394 for part in scripts:
395 if not part.startswith("#!"):
396@@ -1129,5 +1183,19 @@
397 return ret
398
399
400+def get_lan_ip():
401+ (out, _) = util.subp(['ip', 'a'], capture=True)
402+ info = ip_a_to_dict(out)
403+ (routes, _) = util.subp(['route', '-n'], capture=True)
404+ gwdevs = [route.split()[-1] for route in routes.splitlines()
405+ if route.startswith('0.0.0.0') and 'UG' in route]
406+ if len(gwdevs) > 0:
407+ dev = gwdevs.pop()
408+ addr = info[dev].get('inet4')[0].get('address')
409+ else:
410+ raise OSError('could not get local ip address')
411+ return addr
412+
413+
414 apply_keep_settings()
415 logger = _initialize_logging()
416
417=== modified file 'tests/vmtests/helpers.py'
418--- tests/vmtests/helpers.py 2017-01-23 16:47:07 +0000
419+++ tests/vmtests/helpers.py 2017-02-10 17:07:49 +0000
420@@ -227,7 +227,10 @@
421 cur_data[cur_tok] = next_tok
422 elif cur_tok.startswith("inet"):
423 cidr = toks[1]
424- address, prefixlen = cidr.split("/")
425+ address = cidr
426+ prefixlen = None
427+ if '/' in cidr:
428+ address, prefixlen = cidr.split("/")
429 cur_ip = {
430 'address': address,
431 'prefixlen': prefixlen,
432
433=== added file 'tests/vmtests/report_webhook_logger.py'
434--- tests/vmtests/report_webhook_logger.py 1970-01-01 00:00:00 +0000
435+++ tests/vmtests/report_webhook_logger.py 2017-02-10 17:07:49 +0000
436@@ -0,0 +1,187 @@
437+#!/usr/bin/python3
438+import socket
439+try:
440+ # python2
441+ import SimpleHTTPServer as http_server
442+ import SocketServer as socketserver
443+except ImportError:
444+ import http.server as http_server
445+ import socketserver
446+
447+import json
448+import os
449+import sys
450+import threading
451+
452+EXAMPLE_CONFIG = """\
453+# example config
454+reporting:
455+ mypost:
456+ type: webhook
457+ endpoint: %(endpoint)s
458+install:
459+ log_file: /tmp/foo
460+ post_files: [/tmp/foo]
461+
462+# example python:
463+from curtin.reporter import events, update_configuration
464+cfg = {'mypost': {'type': 'webhook', 'endpoint': '%(endpoint)s'}}
465+update_configuration(cfg)
466+with events.ReportEventStack(name="myname", description="mydesc",
467+ reporting_enabled=True):
468+ print("do something")
469+"""
470+
471+CURTIN_EVENTS = []
472+DEFAULT_PORT = 8000
473+addr = ""
474+
475+
476+def render_event_string(event_str):
477+ return json.dumps(json.loads(event_str), indent=1)
478+
479+
480+def write_event_string(target, event_str):
481+ try:
482+ with open(target, 'r') as fp:
483+ data = json.load(fp)
484+ except:
485+ data = []
486+ data.append(json.loads(event_str))
487+ with open(target, 'w') as fp:
488+ json.dump(data, fp)
489+
490+
491+class HTTPServerV6(socketserver.TCPServer):
492+ address_family = socket.AF_INET6
493+
494+
495+class ServerHandler(http_server.SimpleHTTPRequestHandler):
496+ address_family = socket.AF_INET6
497+ result_log_file = None
498+
499+ def log_request(self, code, size=None):
500+ if self.result_log_file:
501+ return
502+ lines = [
503+ "== %s %s ==" % (self.command, self.path),
504+ str(self.headers).replace('\r', '')]
505+ if self._message:
506+ lines.append(self._message)
507+ sys.stdout.write('\n'.join(lines) + '\n')
508+ sys.stdout.flush()
509+
510+ def do_GET(self):
511+ self._message = None
512+ self.send_response(200)
513+ self.end_headers()
514+ self.wfile.write("content of %s\n" % self.path)
515+
516+ def do_POST(self):
517+ length = int(self.headers['Content-Length'])
518+ post_data = self.rfile.read(length).decode('utf-8')
519+ try:
520+ if self.result_log_file:
521+ write_event_string(self.result_log_file, post_data)
522+ self._message = render_event_string(post_data)
523+ except Exception as e:
524+ self._message = '\n'.join(
525+ ["failed printing event: %s" % e, post_data])
526+
527+ msg = "received post to %s" % self.path
528+ self.send_response(200)
529+ self.send_header("Content-type", "text/plain")
530+ self.end_headers()
531+ self.wfile.write(msg.encode('utf-8'))
532+
533+
534+def GenServerHandlerWithResultFile(file_path):
535+ class ExtendedServerHandler(ServerHandler):
536+ result_log_file = file_path
537+ return ExtendedServerHandler
538+
539+
540+def get_httpd(port=None, result_file=None):
541+ # avoid 'Address already in use' after ctrl-c
542+ socketserver.TCPServer.allow_reuse_address = True
543+
544+ # get first available port if none specified
545+ if port is None:
546+ port = 0
547+
548+ if result_file:
549+ Handler = GenServerHandlerWithResultFile(result_file)
550+ else:
551+ Handler = ServerHandler
552+ httpd = HTTPServerV6(("::", port), Handler)
553+ httpd.allow_reuse_address = True
554+
555+ return httpd
556+
557+
558+def run_server(port=DEFAULT_PORT, log_data=True):
559+ """Run the server and capture output, redirecting output to /dev/null if
560+ log_data = False"""
561+ httpd = get_httpd(port=port)
562+
563+ _stdout = sys.stdout
564+ with open(os.devnull, 'w') as fp:
565+ try:
566+ if not log_data:
567+ sys.stdout = fp
568+ httpd.serve_forever()
569+ except KeyboardInterrupt:
570+ sys.stdout.flush()
571+ pass
572+ finally:
573+ sys.stdout = _stdout
574+ httpd.server_close()
575+
576+ return CURTIN_EVENTS
577+
578+
579+class CaptureReporting:
580+
581+ def __init__(self, result_file):
582+ self.result_file = result_file
583+ self.httpd = get_httpd(result_file=self.result_file,
584+ port=None)
585+ self.httpd.server_activate()
586+ # socket.AF_INET6 returns
587+ # (host, port, flowinfo, scopeid)
588+ (self.bind_addr, self.port, _, _) = self.httpd.server_address
589+
590+ def __enter__(self):
591+ if os.path.exists(self.result_file):
592+ os.remove(self.result_file)
593+ self.worker = threading.Thread(target=self.httpd.serve_forever)
594+ self.worker.start()
595+ return self
596+
597+ def __exit__(self, etype, value, trace):
598+ self.httpd.shutdown()
599+
600+
601+def mainloop():
602+ addr = port = None
603+ if len(sys.argv) > 2:
604+ port = int(sys.argv[2])
605+ addr = sys.argv[1]
606+ elif len(sys.argv) > 1:
607+ port = int(sys.argv[1])
608+ addr = ""
609+ else:
610+ port = DEFAULT_PORT
611+ info = {
612+ 'interface': addr or "::",
613+ 'port': port,
614+ 'endpoint': "http://" + (addr or "[::1]") + ":%s" % port
615+ }
616+ print("Serving at: %(endpoint)s" % info)
617+ print("Post to this with:\n%s\n" % (EXAMPLE_CONFIG % info))
618+ run_server(port=port, log_data=True)
619+ sys.exit(0)
620+
621+
622+if __name__ == "__main__":
623+ mainloop()
624
625=== added file 'tools/__init__.py'
626=== added file 'tools/curtin-log-print'
627--- tools/curtin-log-print 1970-01-01 00:00:00 +0000
628+++ tools/curtin-log-print 2017-02-10 17:07:49 +0000
629@@ -0,0 +1,197 @@
630+#!/usr/bin/env python3
631+# Copyright (C) 2016 Canonical Ltd.
632+#
633+# Author: Ryan Harper <ryan.harper@canonical.com>
634+#
635+# Curtin is free software: you can redistribute it and/or modify it under
636+# the terms of the GNU Affero General Public License as published by the
637+# Free Software Foundation, either version 3 of the License, or (at your
638+# option) any later version.
639+#
640+# Curtin is distributed in the hope that it will be useful, but WITHOUT ANY
641+# WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
642+# FOR A PARTICULAR PURPOSE. See the GNU Affero General Public License for
643+# more details.
644+#
645+# You should have received a copy of the GNU Affero General Public License
646+# along with Curtin. If not, see <http://www.gnu.org/licenses/>.
647+from collections import OrderedDict
648+import argparse
649+import base64
650+import datetime
651+import json
652+import os
653+import sys
654+
655+# An event:
656+'''
657+{
658+ "description": "executing late commands",
659+ "event_type": "start",
660+ "level": "INFO",
661+ "name": "cmd-install/stage-late"
662+ "origin": "curtin",
663+ "timestamp": 1461164249.1590767,
664+},
665+
666+ {
667+ "description": "executing late commands",
668+ "event_type": "finish",
669+ "level": "INFO",
670+ "name": "cmd-install/stage-late",
671+ "origin": "curtin",
672+ "result": "SUCCESS",
673+ "timestamp": 1461164249.1590767
674+ }
675+
676+'''
677+format_key = {
678+ '%d': 'delta',
679+ '%D': 'description',
680+ '%E': 'elapsed',
681+ '%e': 'event_type',
682+ '%I': 'indent',
683+ '%l': 'level',
684+ '%n': 'name',
685+ '%o': 'origin',
686+ '%r': 'result',
687+ '%t': 'timestamp',
688+ '%T': 'total_time',
689+}
690+
691+formatting_help = " ".join(["{}: {}".format(k.replace('%', '%%'), v)
692+ for k, v in format_key.items()])
693+
694+
695+def format_record(msg, event):
696+ for i, j in format_key.items():
697+ if i in msg:
698+ msg = msg.replace(i, "{%s}" % j)
699+ return msg.format(**event)
700+
701+
702+def dump_event_files(event):
703+ content = {k: v for k, v in event.items() if k not in ['content']}
704+ files = content['files']
705+ saved = []
706+ for f in files:
707+ fname = f['path']
708+ fn_local = os.path.basename(fname)
709+ fcontent = base64.b64decode(f['content']).decode('ascii')
710+ with open(fn_local, 'w') as fh:
711+ fh.write(fcontent)
712+ saved.append(fn_local)
713+
714+ return saved
715+
716+
717+def generate_records(j, blame_sort=False, print_format="%d seconds in %I%D",
718+ dump_files=False, log_datafiles=False):
719+
720+ dumped_files = []
721+ records = []
722+ start_time = None
723+ timestamps = OrderedDict()
724+ total_time = 0.0
725+ for event in j:
726+ name = event.get('name')
727+ event['indent'] = '|' + ' ' * (name.count('/') - 1) + '`->'
728+ if 'files' in event:
729+ if dump_files:
730+ dumped_files += dump_event_files(event)
731+
732+ if event['event_type'] == 'start':
733+ timestamps[name] = {'start': event['timestamp']}
734+ start = datetime.datetime.utcfromtimestamp(
735+ timestamps[name]['start'])
736+ event['delta'] = "{:08.5f}".format(total_time)
737+ # Initial start event has different record format
738+ if '/' not in event['name']:
739+ start_time = datetime.datetime.utcfromtimestamp(
740+ event['timestamp'])
741+ elapsed = start - start_time
742+ event['elapsed'] = "{:08.5f}".format(elapsed.total_seconds())
743+ records.append(format_record('[%d] %D', event))
744+ else:
745+ elapsed = start - start_time
746+ event['elapsed'] = "{:08.5f}".format(elapsed.total_seconds())
747+ if '%e' in print_format:
748+ records.append(format_record(print_format, event))
749+ else:
750+ timestamps[name].update({'finish': event['timestamp']})
751+ start = datetime.datetime.utcfromtimestamp(
752+ timestamps[name]['start'])
753+ end = datetime.datetime.utcfromtimestamp(
754+ timestamps[name]['finish'])
755+ delta = end - start
756+ elapsed = start - start_time + delta
757+ event['elapsed'] = "{:08.5f}".format(elapsed.total_seconds())
758+ # don't the main event's time to total time, it's already counted
759+ if '/' not in event['name']:
760+ total_time += delta.total_seconds()
761+ event['delta'] = "{:008.5f}".format(delta.total_seconds())
762+ timestamps[name].update({
763+ 'delta': event['delta'],
764+ 'elapsed': event['elapsed']})
765+ records.append(format_record(print_format, event))
766+
767+ records.append(' ---\n%3.5f seconds total time' % total_time)
768+ if log_datafiles:
769+ with open('timestamps.json', 'w') as fh:
770+ fh.write(json.dumps(timestamps, indent=4))
771+
772+ with open('records.json', 'w') as fh:
773+ fh.write(json.dumps(records, indent=4))
774+
775+ if dumped_files:
776+ records.append('\nSaved event file(s):')
777+ for f in dumped_files:
778+ records.append(' %s' % f)
779+
780+ return records
781+
782+
783+def main():
784+ parser = argparse.ArgumentParser(
785+ description='curtin-print-log - pretty print and sort curtin logs',
786+ prog='curtin-print-log')
787+ parser.add_argument('--dumpfiles', action='store_true',
788+ default=False,
789+ dest='dump_files',
790+ help='dump content of any posted files')
791+ parser.add_argument('--save-processing-data', action='store_true',
792+ default=False,
793+ dest='log_datafiles',
794+ help='save the processing data')
795+ parser.add_argument('--format', action='store',
796+ dest='print_format',
797+ default='%I%D @%Es +%ds',
798+ help='specify formatting of output. ' +
799+ formatting_help)
800+ parser.add_argument('infile', nargs='?', type=argparse.FileType('r'),
801+ help='Path to log to parse. Use - for stdin')
802+
803+ opts = parser.parse_args(sys.argv[1:])
804+ if not opts.infile:
805+ parser.print_help()
806+ sys.exit(1)
807+
808+ try:
809+ j = json.load(opts.infile)
810+ except json.JSONDecodeError:
811+ print("Input must be valid JSON")
812+ sys.exit(1)
813+
814+ sj = sorted(j, key=lambda x: x['timestamp'])
815+ records = generate_records(sj, print_format=opts.print_format,
816+ dump_files=opts.dump_files,
817+ log_datafiles=opts.log_datafiles)
818+ print('The total time elapsed since completing an event is printed'
819+ ' after the "@" character.')
820+ print('The time the event takes is printed after the "+" character.')
821+ print()
822+ print("\n".join(records))
823+
824+
825+if __name__ == '__main__':
826+ main()
827
828=== removed file 'tools/report-webhook-logger'
829--- tools/report-webhook-logger 2015-10-09 14:47:09 +0000
830+++ tools/report-webhook-logger 1970-01-01 00:00:00 +0000
831@@ -1,100 +0,0 @@
832-#!/usr/bin/python3
833-try:
834- # python2
835- import SimpleHTTPServer as http_server
836- import SocketServer as socketserver
837-except ImportError:
838- import http.server as http_server
839- import socketserver
840-
841-import json
842-import sys
843-
844-EXAMPLE_CONFIG = """\
845-# example config
846-reporting:
847- mypost:
848- type: webhook
849- endpoint: %(endpoint)s
850-install:
851- log_file: /tmp/foo
852- post_files: [/tmp/foo]
853-
854-# example python:
855-from curtin.reporter import events, update_configuration
856-cfg = {'mypost': {'type': 'webhook', 'endpoint': '%(endpoint)s'}}
857-update_configuration(cfg)
858-with events.ReportEventStack(name="myname", description="mydesc",
859- reporting_enabled=True):
860- print("do something")
861-"""
862-
863-if len(sys.argv) > 2:
864- PORT = int(sys.argv[2])
865- addr = sys.argv[1]
866-elif len(sys.argv) > 1:
867- PORT = int(sys.argv[1])
868- addr = ""
869-else:
870- PORT = 8000
871- addr = ""
872-
873-
874-def render_event_string(event_str):
875- return json.dumps(json.loads(event_str), indent=1)
876-
877-
878-class ServerHandler(http_server.SimpleHTTPRequestHandler):
879-
880- def log_request(self, code, size=None):
881- lines = [
882- "== %s %s ==" % (self.command, self.path),
883- str(self.headers).replace('\r', '')]
884- if self._message:
885- lines.append(self._message)
886- sys.stdout.write('\n'.join(lines) + '\n')
887- sys.stdout.flush()
888-
889- def do_GET(self):
890- self._message = None
891- self.send_response(200)
892- self.end_headers()
893- self.wfile.write("content of %s\n" % self.path)
894-
895- def do_POST(self):
896- length = int(self.headers['Content-Length'])
897- post_data = self.rfile.read(length).decode('utf-8')
898- try:
899- self._message = render_event_string(post_data)
900- except Exception as e:
901- self._message = '\n'.join(
902- ["failed printing event: %s" % e, post_data])
903-
904- msg = "received post to %s" % self.path
905- self.send_response(200)
906- self.send_header("Content-type", "text/plain")
907- self.end_headers()
908- self.wfile.write(msg.encode('utf-8'))
909-
910-# avoid 'Address already in use' after ctrl-c
911-socketserver.TCPServer.allow_reuse_address = True
912-
913-Handler = ServerHandler
914-httpd = socketserver.TCPServer(("", PORT), Handler)
915-httpd.allow_reuse_address = True
916-
917-info = {
918- 'interface': addr or "localhost",
919- 'port': PORT,
920- 'endpoint': "http://" + (addr or "localhost") + ":%s" % PORT
921-}
922-print("Serving at: %(endpoint)s" % info)
923-print("Post to this with:\n%s\n" % (EXAMPLE_CONFIG % info))
924-
925-try:
926- httpd.serve_forever()
927-except KeyboardInterrupt:
928- sys.stdout.flush()
929- pass
930-httpd.server_close()
931-sys.exit(0)
932
933=== added file 'tools/report_webhook_logger'
934--- tools/report_webhook_logger 1970-01-01 00:00:00 +0000
935+++ tools/report_webhook_logger 2017-02-10 17:07:49 +0000
936@@ -0,0 +1,6 @@
937+#!/usr/bin/python3
938+
939+from tests.vmtests.report_webhook_logger import mainloop
940+
941+if __name__ == "__main__":
942+ mainloop()
943
944=== modified file 'tools/run-pep8'
945--- tools/run-pep8 2015-03-09 16:32:36 +0000
946+++ tools/run-pep8 2017-02-10 17:07:49 +0000
947@@ -1,6 +1,11 @@
948 #!/bin/bash
949
950-pycheck_dirs=( "curtin/" "tests/" )
951+pycheck_dirs=(
952+ "curtin/"
953+ "tests/"
954+ "tools/curtin-log-print"
955+ "tools/report_webhook_logger"
956+)
957 bin_files=( )
958 CR="
959 "
960
961=== modified file 'tools/run-pyflakes'
962--- tools/run-pyflakes 2016-02-12 16:43:18 +0000
963+++ tools/run-pyflakes 2017-02-10 17:07:49 +0000
964@@ -7,7 +7,13 @@
965 if [ "$PYTHON_VERSION" = "3" ]; then
966 vmtests="tests/vmtests/"
967 fi
968-pycheck_dirs=( "curtin/" "tests/unittests/" $vmtests )
969+pycheck_dirs=(
970+ "curtin/"
971+ "tests/unittests/"
972+ $vmtests
973+ "tools/curtin-log-print"
974+ "tools/report_webhook_logger"
975+)
976
977 set -f
978 if [ $# -eq 0 ]; then

Subscribers

People subscribed via source and target branches