reporter.py@ 70570

Last change on this file since 70570 was 70570, checked in by vboxsync, 7 years ago
testdriver/reporter.py: Python 3 fix.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 59.8 KB

Line
1	# -- coding: utf-8 --
2	# $Id: reporter.py 70570 2018-01-13 00:02:51Z vboxsync $
3	# pylint: disable=C0302
4
5	"""
6	Testdriver reporter module.
7	"""
8
9	from __future__ import print_function;
10
11	__copyright__ = \
12	"""
13	Copyright (C) 2010-2017 Oracle Corporation
14
15	This file is part of VirtualBox Open Source Edition (OSE), as
16	available from http://www.215389.xyz. This file is free software;
17	you can redistribute it and/or modify it under the terms of the GNU
18	General Public License (GPL) as published by the Free Software
19	Foundation, in version 2 as it comes in the "COPYING" file of the
20	VirtualBox OSE distribution. VirtualBox OSE is distributed in the
21	hope that it will be useful, but WITHOUT ANY WARRANTY of any kind.
22
23	The contents of this file may alternatively be used under the terms
24	of the Common Development and Distribution License Version 1.0
25	(CDDL) only, as it comes in the "COPYING.CDDL" file of the
26	VirtualBox OSE distribution, in which case the provisions of the
27	CDDL are applicable instead of those of the GPL.
28
29	You may elect to license modified versions of this file under the
30	terms and conditions of either the GPL or the CDDL or both.
31	"""
32	__version__ = "$Revision: 70570 $"
33
34
35	# Standard Python imports.
36	import array
37	import datetime
38	import errno
39	import gc
40	import os
41	import os.path
42	import sys
43	import time
44	import threading
45	import traceback
46
47	# Validation Kit imports.
48	from common import utils;
49
50	## test reporter instance
51	g_oReporter = None; # type: ReporterBase
52	g_sReporterName = None;
53
54
55	class ReporterLock(object):
56	"""
57	Work around problem with garbage collection triggering __del__ method with
58	logging while inside the logger lock and causing a deadlock.
59	"""
60
61	def __init__(self, sName):
62	self.sName = sName;
63	self.oLock = threading.RLock();
64	self.oOwner = None;
65	self.cRecursion = 0;
66	self.fRestoreGC = False;
67
68	def acquire(self):
69	""" Acquire the lock. """
70	oSelf = threading.current_thread();
71
72	# Take the lock.
73	if not self.oLock.acquire():
74	return False;
75
76	self.oOwner = oSelf;
77	self.cRecursion += 1;
78
79	# Disable GC to avoid __del__ w/ log statement randomly reenter the logger.
80	if self.cRecursion == 1:
81	self.fRestoreGC = gc.isenabled();
82	if self.fRestoreGC:
83	gc.disable();
84
85	return True;
86
87	def release(self):
88	""" Release the lock. """
89	oSelf = threading.current_thread();
90
91	# Check the ownership.
92	if oSelf != self.oOwner:
93	raise threading.ThreadError();
94
95	# Drop one recursion.
96	self.cRecursion -= 1;
97	if self.cRecursion <= 0:
98
99	# Final recursion. Clear owner and re-enable GC.
100	self.oOwner = None;
101	if self.fRestoreGC:
102	self.fRestoreGC = False;
103	gc.enable();
104
105	self.oLock.release();
106
107	## Reporter lock.
108	g_oLock = ReporterLock('reporter');
109
110
111
112	class PythonLoggingStream(object):
113	"""
114	Python logging => testdriver/reporter.py stream.
115	"""
116
117	def write(self, sText):
118	"""Writes python log message to our stream."""
119	if g_oReporter != None:
120	sText = sText.rstrip("\r\n");
121	#g_oReporter.log(0, 'python: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
122	return True;
123
124	def flush(self):
125	"""Flushes the stream."""
126	return True;
127
128
129	class ReporterBase(object):
130	"""
131	Base class for the reporters.
132	"""
133
134	def __init__(self):
135	self.iVerbose = 1;
136	self.iDebug = 0;
137	self.cErrors = 0;
138	self.fTimedOut = False; # Once set, it trickles all the way up.
139	self.atTests = [];
140	self.sName = os.path.splitext(os.path.basename(sys.argv[0]))[0];
141
142	# Hook into the python logging.
143	import logging;
144	logging.basicConfig(stream = PythonLoggingStream(),
145	level = logging.DEBUG,
146	format = '%(name)-12s %(levelname)-8s %(message)s');
147	#
148	# Introspection and configuration.
149	#
150
151	def isLocal(self):
152	"""Is this a local reporter?"""
153	return False;
154
155	def incVerbosity(self):
156	"""Increases the verbosity level."""
157	self.iVerbose += 1;
158
159	def incDebug(self):
160	"""Increases the debug level."""
161	self.iDebug += 1;
162
163	def appendToProcessName(self, sAppend):
164	"""
165	Appends sAppend to the base process name.
166	Returns the new process name.
167	"""
168	self.sName = os.path.splitext(os.path.basename(sys.argv[0]))[0] + sAppend;
169	return self.sName;
170
171
172	#
173	# Generic logging.
174	#
175
176	def log(self, iLevel, sText, sCaller, sTsPrf):
177	"""
178	Writes the specfied text to the log if iLevel is less or requal
179	to iVerbose.
180	"""
181	_ = iLevel; _ = sText; _ = sCaller; _ = sTsPrf;
182	return 0;
183
184	#
185	# XML output from the reporter.
186	#
187
188	def _xmlEscAttr(self, sValue):
189	"""Escapes an XML attribute value."""
190	sValue = sValue.replace('&', '&');
191	sValue = sValue.replace('<', '<');
192	sValue = sValue.replace('>', '>');
193	#sValue = sValue.replace('\'', ''');
194	sValue = sValue.replace('"', '"');
195	sValue = sValue.replace('\n', '&#xA');
196	sValue = sValue.replace('\r', '&#xD');
197	return sValue;
198
199	def _xmlWrite(self, asText, fIndent = True):
200	"""XML output function for the reporter."""
201	_ = asText; _ = fIndent;
202	return None;
203
204	def xmlFlush(self, fRetry = False, fForce = False):
205	"""Flushes XML output if buffered."""
206	_ = fRetry; _ = fForce;
207	return None;
208
209	#
210	# XML output from child.
211	#
212
213	def subXmlStart(self, oFileWrapper):
214	"""Called by the file wrapper when the first bytes are written to the test pipe."""
215	_ = oFileWrapper;
216	return None;
217
218	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
219	"""Called by the file wrapper write method for test pipes."""
220	return self.log(0, 'raw xml%s: %s' % (oFileWrapper.sPrefix, sRawXml), sCaller, utils.getTimePrefix());
221
222	def subXmlEnd(self, oFileWrapper):
223	"""Called by the file wrapper __del__ method for test pipes."""
224	_ = oFileWrapper;
225	return None;
226
227	#
228	# File output.
229	#
230
231	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
232	"""
233	Adds the file to the report.
234	Returns True on success, False on failure.
235	"""
236	_ = oSrcFile; _ = sSrcFilename; _ = sAltName; _ = sDescription; _ = sKind; _ = sCaller; _ = sTsPrf;
237	return True;
238
239	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
240	"""
241	Adds the file to the report.
242	Returns True on success, False on failure.
243	"""
244	_ = sLog; _ = sLogName; _ = sDescription; _ = sKind; _ = sCaller; _ = sTsPrf;
245	return True;
246
247	#
248	# Test reporting
249	#
250
251	def _testGetFullName(self):
252	"""
253	Mangles the test names in atTest into a single name to make it easier
254	to spot where we are.
255	"""
256	sName = '';
257	for t in self.atTests:
258	if sName != '':
259	sName += ', ';
260	sName += t[0];
261	return sName;
262
263	def testIncErrors(self):
264	"""Increates the error count."""
265	self.cErrors += 1;
266	return self.cErrors;
267
268	def testSetTimedOut(self):
269	"""Sets time out indicator for the current test and increases the error counter."""
270	self.fTimedOut = True;
271	self.cErrors += 1;
272	return None;
273
274	def testStart(self, sName, sCaller):
275	""" Starts a new test, may be nested. """
276	(sTsPrf, sTsIso) = utils.getTimePrefixAndIsoTimestamp();
277	self._xmlWrite([ '<Test timestamp="%s" name="%s">' % (sTsIso, self._xmlEscAttr(sName),), ]);
278	self.atTests.append((sName, self.cErrors, self.fTimedOut));
279	self.fTimedOut = False;
280	return self.log(1, ' %-50s: TESTING' % (self._testGetFullName()), sCaller, sTsPrf);
281
282	def testValue(self, sName, sValue, sUnit, sCaller):
283	""" Reports a benchmark value or something simiarlly useful. """
284	(sTsPrf, sTsIso) = utils.getTimePrefixAndIsoTimestamp();
285	self._xmlWrite([ '<Value timestamp="%s" name="%s" unit="%s" value="%s"/>'
286	% (sTsIso, self._xmlEscAttr(sName), self._xmlEscAttr(sUnit), self._xmlEscAttr(sValue)), ]);
287	return self.log(0, '** %-48s: %12s %s' % (sName, sValue, sUnit), sCaller, sTsPrf);
288
289	def testFailure(self, sDetails, sCaller):
290	""" Reports a failure. """
291	(sTsPrf, sTsIso) = utils.getTimePrefixAndIsoTimestamp();
292	self.cErrors = self.cErrors + 1;
293	self._xmlWrite([ '<FailureDetails timestamp="%s" text="%s"/>' % (sTsIso, self._xmlEscAttr(sDetails),), ]);
294	return self.log(0, sDetails, sCaller, sTsPrf);
295
296	def testDone(self, fSkipped, sCaller):
297	"""
298	Marks the current test as DONE, pops it and maks the next test on the
299	stack current.
300	Returns (name, errors).
301	"""
302	(sTsPrf, sTsIso) = utils.getTimePrefixAndIsoTimestamp();
303	sFullName = self._testGetFullName();
304
305	# safe pop
306	if len(self.atTests) <= 0:
307	self.log(0, 'testDone on empty test stack!', sCaller, sTsPrf);
308	return ('internal error', 0);
309	fTimedOut = self.fTimedOut;
310	sName, cErrorsStart, self.fTimedOut = self.atTests.pop();
311
312	# log + xml.
313	cErrors = self.cErrors - cErrorsStart;
314	if cErrors == 0:
315	if fSkipped is not True:
316	self._xmlWrite([ ' <Passed timestamp="%s"/>' % (sTsIso,), '</Test>' ],);
317	self.log(1, '** %-50s: PASSED' % (sFullName,), sCaller, sTsPrf);
318	else:
319	self._xmlWrite([ ' <Skipped timestamp="%s"/>' % (sTsIso,), '</Test>' ]);
320	self.log(1, '** %-50s: SKIPPED' % (sFullName,), sCaller, sTsPrf);
321	elif fTimedOut:
322	self._xmlWrite([ ' <TimedOut timestamp="%s" errors="%d"/>' % (sTsIso, cErrors), '</Test>' ]);
323	self.log(0, '** %-50s: TIMED-OUT - %d errors' % (sFullName, cErrors), sCaller, sTsPrf);
324	else:
325	self._xmlWrite([ ' <Failed timestamp="%s" errors="%d"/>' % (sTsIso, cErrors), '</Test>' ]);
326	self.log(0, '** %-50s: FAILED - %d errors' % (sFullName, cErrors), sCaller, sTsPrf);
327
328	# Flush buffers when reaching the last test.
329	if not self.atTests:
330	self.xmlFlush(fRetry = True);
331
332	return (sName, cErrors);
333
334	def testErrorCount(self):
335	"""
336	Returns the number of errors accumulated by the current test.
337	"""
338	cTests = len(self.atTests);
339	if cTests <= 0:
340	return self.cErrors;
341	return self.cErrors - self.atTests[cTests - 1][1];
342
343	def testCleanup(self, sCaller):
344	"""
345	Closes all open test as failed.
346	Returns True if no open tests, False if there were open tests.
347	"""
348	if not self.atTests:
349	return True;
350	for _ in range(len(self.atTests)):
351	self.testFailure('Test not closed by test drver', sCaller)
352	self.testDone(False, sCaller);
353	return False;
354
355	#
356	# Misc.
357	#
358
359	def doPollWork(self, sDebug = None):
360	"""
361	Check if any pending stuff expired and needs doing.
362	"""
363	_ = sDebug;
364	return None;
365
366
367
368
369	class LocalReporter(ReporterBase):
370	"""
371	Local reporter instance.
372	"""
373
374	def __init__(self):
375	ReporterBase.__init__(self);
376	self.oLogFile = None;
377	self.oXmlFile = None;
378	self.fXmlOk = True;
379	self.iSubXml = 0;
380	self.iOtherFile = 0;
381	self.fnGetIsoTimestamp = utils.getIsoTimestamp; # Hack to get a timestamp in __del__.
382	self.oStdErr = sys.stderr; # Hack for __del__ output.
383
384	#
385	# Figure the main log directory.
386	#
387	try:
388	import user;
389	self.sDefLogDir = os.path.abspath(os.path.join(user.home, "VBoxTestLogs"));
390	except:
391	self.sDefLogDir = os.path.abspath("VBoxTestLogs");
392	try:
393	sLogDir = os.path.abspath(os.environ.get('TESTBOX_REPORTER_LOG_DIR', self.sDefLogDir));
394	if not os.path.isdir(sLogDir):
395	os.makedirs(sLogDir, 0o750);
396	except:
397	sLogDir = self.sDefLogDir;
398	if not os.path.isdir(sLogDir):
399	os.makedirs(sLogDir, 0o750);
400
401	#
402	# Make a subdirectory for this test run.
403	#
404	sTs = datetime.datetime.utcnow().strftime('%Y-%m-%dT%H-%M-%S.log');
405	self.sLogDir = sLogDir = os.path.join(sLogDir, '%s-%s' % (sTs, self.sName));
406	try:
407	os.makedirs(self.sLogDir, 0o750);
408	except:
409	self.sLogDir = '%s-%s' % (self.sLogDir, os.getpid());
410	os.makedirs(self.sLogDir, 0o750);
411
412	#
413	# Open the log file and write a header.
414	#
415	sLogName = os.path.join(self.sLogDir, 'testsuite.log');
416	sTsIso = utils.getIsoTimestamp();
417	if sys.version_info[0] >= 3: # Add 'b' to prevent write taking issue with encode('utf-8') not returning a string.
418	self.oLogFile = utils.openNoInherit(sLogName, "wb");
419	else:
420	self.oLogFile = utils.openNoInherit(sLogName, "w");
421	self.oLogFile.write(('Created log file at %s.\nRunning: %s' % (sTsIso, sys.argv)).encode('utf-8'));
422
423	#
424	# Open the xml log file and write the mandatory introduction.
425	#
426	# Note! This is done here and not in the base class because the remote
427	# logger doesn't really need this. It doesn't need the outer
428	# test wrapper either.
429	#
430	sXmlName = os.path.join(self.sLogDir, 'testsuite.xml');
431	if sys.version_info[0] >= 3: # Add 'b' to prevent write taking issue with encode('utf-8') not returning a string.
432	self.oXmlFile = utils.openNoInherit(sXmlName, "wb");
433	else:
434	self.oXmlFile = utils.openNoInherit(sXmlName, "w");
435	self._xmlWrite([ '<?xml version="1.0" encoding="UTF-8" ?>',
436	'<Test timestamp="%s" name="%s">' % (sTsIso, self._xmlEscAttr(self.sName),), ],
437	fIndent = False);
438
439	def __del__(self):
440	"""Ends and completes the log files."""
441	try: sTsIso = self.fnGetIsoTimestamp();
442	except Exception as oXcpt:
443	sTsIso = str(oXcpt);
444
445	if self.oLogFile is not None:
446	try:
447	self.oLogFile.write(('\nThe End %s\n' % (sTsIso,)).encode('utf-8'));
448	self.oLogFile.close();
449	except: pass;
450	self.oLogFile = None;
451
452	if self.oXmlFile is not None:
453	self._closeXml(sTsIso);
454	self.oXmlFile = None;
455
456	def _closeXml(self, sTsIso):
457	"""Closes the XML file."""
458	if self.oXmlFile is not None:
459	# pop the test stack
460	while self.atTests:
461	sName, cErrorsStart, self.fTimedOut = self.atTests.pop();
462	self._xmlWrite([ '<End timestamp="%s" errors="%d"/>' % (sTsIso, self.cErrors - cErrorsStart,),
463	'</%s>' % (sName,), ]);
464
465	# The outer one is not on the stack.
466	self._xmlWrite([ ' <End timestamp="%s"/>' % (sTsIso,),
467	'</Test>', ], fIndent = False);
468	try:
469	self.oXmlFile.close();
470	self.oXmlFile = None;
471	except:
472	pass;
473
474	def _xmlWrite(self, asText, fIndent = True):
475	"""Writes to the XML file."""
476	for sText in asText:
477	if fIndent:
478	sIndent = ''.ljust((len(self.atTests) + 1) * 2);
479	sText = sIndent + sText;
480	sText += '\n';
481
482	try:
483	self.oXmlFile.write(sText.encode('utf-8'));
484	except:
485	if self.fXmlOk:
486	traceback.print_exc();
487	self.fXmlOk = False;
488	return False;
489	return True;
490
491	#
492	# Overridden methods.
493	#
494
495	def isLocal(self):
496	"""Is this a local reporter?"""
497	return True;
498
499	def log(self, iLevel, sText, sCaller, sTsPrf):
500	if iLevel <= self.iVerbose:
501	# format it.
502	if self.iDebug > 0:
503	sLogText = '%s %30s: %s' % (sTsPrf, sCaller, sText);
504	else:
505	sLogText = '%s %s' % (sTsPrf, sText);
506
507	# output it.
508	sAscii = sLogText.encode('ascii', 'replace');
509	if self.iDebug == 0:
510	print('%s: %s' % (self.sName, sAscii), file = self.oStdErr);
511	else:
512	print('%s' % (sAscii), file = self.oStdErr);
513	sLogText += '\n';
514	try:
515	self.oLogFile.write(sLogText.encode('utf-8'));
516	except:
517	pass;
518	return 0;
519
520	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
521	# Figure the destination filename.
522	iOtherFile = self.iOtherFile;
523	self.iOtherFile += 1;
524	sDstFilename = os.path.join(self.sLogDir, 'other-%d-%s.log' \
525	% (iOtherFile, os.path.splitext(os.path.basename(sSrcFilename))[0]));
526	self.log(0, '** Other log file: %s - %s (%s)' % (sDstFilename, sDescription, sSrcFilename), sCaller, sTsPrf);
527
528	# Open the destination file and copy over the data.
529	fRc = True;
530	try:
531	oDstFile = utils.openNoInherit(sDstFilename, 'w');
532	except Exception as oXcpt:
533	self.log(0, 'error opening %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
534	else:
535	while True:
536	try:
537	abBuf = oSrcFile.read(65536);
538	except Exception as oXcpt:
539	fRc = False;
540	self.log(0, 'error reading %s: %s' % (sSrcFilename, oXcpt), sCaller, sTsPrf);
541	else:
542	try:
543	oDstFile.write(abBuf);
544	except Exception as oXcpt:
545	fRc = False;
546	self.log(0, 'error writing %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
547	else:
548	if abBuf:
549	continue;
550	break;
551	oDstFile.close();
552
553	# Leave a mark in the XML log.
554	self._xmlWrite(['<LogFile timestamp="%s" filename="%s" source="%s" kind="%s" ok="%s">%s</LogFile>\n'
555	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sDstFilename)), self._xmlEscAttr(sSrcFilename), \
556	self._xmlEscAttr(sKind), fRc, self._xmlEscAttr(sDescription))] );
557	_ = sAltName;
558	return fRc;
559
560	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
561	# Figure the destination filename.
562	iOtherFile = self.iOtherFile;
563	self.iOtherFile += 1;
564	sDstFilename = os.path.join(self.sLogDir, 'other-%d-%s.log' \
565	% (iOtherFile, os.path.splitext(os.path.basename(sLogName))[0]));
566	self.log(0, '** Other log file: %s - %s (%s)' % (sDstFilename, sDescription, sLogName), sCaller, sTsPrf);
567
568	# Open the destination file and copy over the data.
569	fRc = True;
570	try:
571	oDstFile = utils.openNoInherit(sDstFilename, 'w');
572	except Exception as oXcpt:
573	self.log(0, 'error opening %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
574	else:
575	try:
576	oDstFile.write(sLog);
577	except Exception as oXcpt:
578	fRc = False;
579	self.log(0, 'error writing %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
580
581	oDstFile.close();
582
583	# Leave a mark in the XML log.
584	self._xmlWrite(['<LogFile timestamp="%s" filename="%s" source="%s" kind="%s" ok="%s">%s</LogFile>\n'
585	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sDstFilename)), self._xmlEscAttr(sLogName), \
586	self._xmlEscAttr(sKind), fRc, self._xmlEscAttr(sDescription))] );
587	return fRc;
588
589	def subXmlStart(self, oFileWrapper):
590	# Open a new file and just include it from the main XML.
591	iSubXml = self.iSubXml;
592	self.iSubXml += 1;
593	sSubXmlName = os.path.join(self.sLogDir, 'sub-%d.xml' % (iSubXml,));
594	try:
595	oFileWrapper.oSubXmlFile = utils.openNoInherit(sSubXmlName, "w");
596	except:
597	errorXcpt('open(%s)' % oFileWrapper.oSubXmlName);
598	oFileWrapper.oSubXmlFile = None;
599	else:
600	self._xmlWrite(['<Include timestamp="%s" filename="%s"/>\n'
601	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sSubXmlName)))]);
602	return None;
603
604	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
605	if oFileWrapper.oSubXmlFile is not None:
606	try:
607	oFileWrapper.oSubXmlFile.write(sRawXml);
608	except:
609	pass;
610	if sCaller is None: pass; # pychecker - NOREF
611	return None;
612
613	def subXmlEnd(self, oFileWrapper):
614	if oFileWrapper.oSubXmlFile is not None:
615	try:
616	oFileWrapper.oSubXmlFile.close();
617	oFileWrapper.oSubXmlFile = None;
618	except:
619	pass;
620	return None;
621
622
623
624	class RemoteReporter(ReporterBase):
625	"""
626	Reporter that talks to the test manager server.
627	"""
628
629
630	## The XML sync min time (seconds).
631	kcSecXmlFlushMin = 30;
632	## The XML sync max time (seconds).
633	kcSecXmlFlushMax = 120;
634	## The XML sync idle time before flushing (seconds).
635	kcSecXmlFlushIdle = 5;
636	## The XML sync line count threshold.
637	kcLinesXmlFlush = 512;
638
639	## The retry timeout.
640	kcSecTestManagerRetryTimeout = 120;
641	## The request timeout.
642	kcSecTestManagerRequestTimeout = 30;
643
644
645	def __init__(self):
646	ReporterBase.__init__(self);
647	self.sTestManagerUrl = os.environ.get('TESTBOX_MANAGER_URL');
648	self.sTestBoxUuid = os.environ.get('TESTBOX_UUID');
649	self.idTestBox = int(os.environ.get('TESTBOX_ID'));
650	self.idTestSet = int(os.environ.get('TESTBOX_TEST_SET_ID'));
651	self._asXml = [];
652	self._secTsXmlFlush = utils.timestampSecond();
653	self._secTsXmlLast = self._secTsXmlFlush;
654	self._fXmlFlushing = False;
655	self.oOutput = sys.stdout; # Hack for __del__ output.
656	self.fFlushEachLine = True;
657	self.fDebugXml = 'TESTDRIVER_REPORTER_DEBUG_XML' in os.environ;
658
659	# Prepare the TM connecting.
660	from common import constants;
661	if sys.version_info[0] >= 3:
662	import urllib;
663	self._fnUrlEncode = urllib.parse.urlencode; # pylint: disable=no-member
664	self._fnUrlParseQs = urllib.parse.parse_qs; # pylint: disable=no-member
665	self._oParsedTmUrl = urllib.parse.urlparse(self.sTestManagerUrl); # pylint: disable=no-member
666	import http.client as httplib; # pylint: disable=no-name-in-module,import-error
667	else:
668	import urllib;
669	self._fnUrlEncode = urllib.urlencode; # pylint: disable=no-member
670	import urlparse; # pylint: disable=import-error
671	self._fnUrlParseQs = urlparse.parse_qs; # pylint: disable=no-member
672	self._oParsedTmUrl = urlparse.urlparse(self.sTestManagerUrl); # pylint: disable=no-member
673	import httplib; # pylint: disable=no-name-in-module,import-error
674
675	if sys.version_info[0] >= 3 \
676	or (sys.version_info[0] == 2 and sys.version_info[1] >= 6):
677	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=E1101
678	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname,
679	timeout = self.kcSecTestManagerRequestTimeout);
680	else:
681	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname,
682	timeout = self.kcSecTestManagerRequestTimeout);
683	else:
684	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=E1101
685	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname);
686	else:
687	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname);
688	self._dHttpHeader = \
689	{
690	'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8',
691	'User-Agent': 'TestDriverReporter/%s.0 (%s, %s)' % (__version__, utils.getHostOs(), utils.getHostArch(),),
692	'Accept': 'text/plain,application/x-www-form-urlencoded',
693	'Accept-Encoding': 'identity',
694	'Cache-Control': 'max-age=0',
695	#'Connection': 'keep-alive',
696	};
697
698	dParams = {
699	constants.tbreq.ALL_PARAM_TESTBOX_UUID: self.sTestBoxUuid,
700	constants.tbreq.ALL_PARAM_TESTBOX_ID: self.idTestBox,
701	constants.tbreq.RESULT_PARAM_TEST_SET_ID: self.idTestSet,
702	};
703	self._sTmServerPath = '/%s/testboxdisp.py?%s' \
704	% ( self._oParsedTmUrl.path.strip('/'), # pylint: disable=E1101
705	self._fnUrlEncode(dParams), );
706
707	def __del__(self):
708	"""Flush pending log messages?"""
709	if self._asXml:
710	self._xmlDoFlush(self._asXml, fRetry = True, fDtor = True);
711
712	def _writeOutput(self, sText):
713	""" Does the actual writing and flushing. """
714	print(sText.encode('ascii', 'replace'), file = self.oOutput);
715	if self.fFlushEachLine: self.oOutput.flush();
716	return None;
717
718	#
719	# Talking to TM.
720	#
721
722	def _processTmStatusResponse(self, oConn, sOperation, fClose = True):
723	"""
724	Processes HTTP reponse from the test manager.
725	Returns True, False or None. None should be retried, the others not.
726	May raise exception on HTTP issue (retry ok).
727	"""
728	if sys.version_info[0] >= 3: import http.client as httplib; # pylint: disable=no-name-in-module,import-error
729	else: import httplib; # pylint: disable=import-error
730	from common import constants;
731
732	# Read the response and (optionally) close the connection.
733	oResponse = oConn.getresponse();
734	try:
735	sRspBody = oResponse.read();
736	except httplib.IncompleteRead as oXcpt:
737	self._writeOutput('%s: %s: Warning: httplib.IncompleteRead: %s [expected %s, got %s]'
738	% (utils.getTimePrefix(), sOperation, oXcpt, oXcpt.expected, len(oXcpt.partial),));
739	sRspBody = oXcpt.partial;
740	if fClose is True:
741	try: oConn.close();
742	except: pass;
743
744	# Check the content type.
745	sContentType = oResponse.getheader('Content-Type');
746	if sContentType is not None and sContentType == 'application/x-www-form-urlencoded; charset=utf-8':
747
748	# Parse the body and check the RESULT parameter.
749	dResponse = self._fnUrlParseQs(sRspBody, strict_parsing = True);
750	sResult = dResponse.get(constants.tbresp.ALL_PARAM_RESULT, None);
751	if isinstance(sResult, list):
752	sResult = sResult[0] if len(sResult) == 1 else '%d results' % (len(sResult),);
753
754	if sResult is not None:
755	if sResult == constants.tbresp.STATUS_ACK:
756	return True;
757	if sResult == constants.tbresp.STATUS_NACK:
758	self._writeOutput('%s: %s: Failed (%s). (dResponse=%s)'
759	% (utils.getTimePrefix(), sOperation, sResult, dResponse,));
760	return False;
761
762	self._writeOutput('%s: %s: Failed - dResponse=%s' % (utils.getTimePrefix(), sOperation, dResponse,));
763	else:
764	self._writeOutput('%s: %s: Unexpected Content-Type: %s' % (utils.getTimePrefix(), sOperation, sContentType,));
765	self._writeOutput('%s: %s: Body: %s' % (utils.getTimePrefix(), sOperation, sRspBody,));
766	return None;
767
768	def _doUploadFile(self, oSrcFile, sSrcFilename, sDescription, sKind, sMime):
769	""" Uploads the given file to the test manager. """
770
771	# Prepare header and url.
772	dHeader = dict(self._dHttpHeader);
773	dHeader['Content-Type'] = 'application/octet-stream';
774	self._writeOutput('%s: _doUploadFile: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
775	oSrcFile.seek(0, 2);
776	self._writeOutput('%s: _doUploadFile: size=%d' % (utils.getTimePrefix(), oSrcFile.tell(),));
777	oSrcFile.seek(0);
778
779	from common import constants;
780	sUrl = self._sTmServerPath + '&' \
781	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcFilename),
782	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
783	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
784	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
785	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
786	});
787
788	# Retry loop.
789	secStart = utils.timestampSecond();
790	while True:
791	try:
792	oConn = self._fnTmConnect();
793	oConn.request('POST', sUrl, oSrcFile.read(), dHeader);
794	fRc = self._processTmStatusResponse(oConn, '_doUploadFile', fClose = True);
795	oConn.close();
796	if fRc is not None:
797	return fRc;
798	except:
799	logXcpt('warning: exception during UPLOAD request');
800
801	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
802	self._writeOutput('%s: _doUploadFile: Timed out.' % (utils.getTimePrefix(),));
803	break;
804	try: oSrcFile.seek(0);
805	except:
806	logXcpt();
807	break;
808	self._writeOutput('%s: _doUploadFile: Retrying...' % (utils.getTimePrefix(), ));
809	time.sleep(2);
810
811	return False;
812
813	def _doUploadString(self, sSrc, sSrcName, sDescription, sKind, sMime):
814	""" Uploads the given string as a separate file to the test manager. """
815
816	# Prepare header and url.
817	dHeader = dict(self._dHttpHeader);
818	dHeader['Content-Type'] = 'application/octet-stream';
819	self._writeOutput('%s: _doUploadString: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
820	self._writeOutput('%s: _doUploadString: size=%d' % (utils.getTimePrefix(), sys.getsizeof(sSrc),));
821
822	from common import constants;
823	sUrl = self._sTmServerPath + '&' \
824	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcName),
825	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
826	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
827	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
828	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
829	});
830
831	# Retry loop.
832	secStart = utils.timestampSecond();
833	while True:
834	try:
835	oConn = self._fnTmConnect();
836	oConn.request('POST', sUrl, sSrc, dHeader);
837	fRc = self._processTmStatusResponse(oConn, '_doUploadString', fClose = True);
838	oConn.close();
839	if fRc is not None:
840	return fRc;
841	except:
842	logXcpt('warning: exception during UPLOAD request');
843
844	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
845	self._writeOutput('%s: _doUploadString: Timed out.' % (utils.getTimePrefix(),));
846	break;
847	self._writeOutput('%s: _doUploadString: Retrying...' % (utils.getTimePrefix(), ));
848	time.sleep(2);
849
850	return False;
851
852	def _xmlDoFlush(self, asXml, fRetry = False, fDtor = False):
853	"""
854	The code that does the actual talking to the server.
855	Used by both xmlFlush and __del__.
856	"""
857	secStart = utils.timestampSecond();
858	while True:
859	fRc = None;
860	try:
861	# Post.
862	from common import constants;
863	sPostBody = self._fnUrlEncode({constants.tbreq.XML_RESULT_PARAM_BODY: '\n'.join(asXml),});
864	oConn = self._fnTmConnect();
865	oConn.request('POST',
866	self._sTmServerPath + ('&%s=%s' % (constants.tbreq.ALL_PARAM_ACTION, constants.tbreq.XML_RESULTS)),
867	sPostBody,
868	self._dHttpHeader);
869
870	fRc = self._processTmStatusResponse(oConn, '_xmlDoFlush', fClose = True);
871	if fRc is True:
872	if self.fDebugXml:
873	self._writeOutput('_xmlDoFlush:\n%s' % ('\n'.join(asXml),));
874	return (None, False);
875	if fRc is False:
876	self._writeOutput('_xmlDoFlush: Failed - we should abort the test, really.');
877	return (None, True);
878	except Exception as oXcpt:
879	if not fDtor:
880	logXcpt('warning: exception during XML_RESULTS request');
881	else:
882	self._writeOutput('warning: exception during XML_RESULTS request: %s' % (oXcpt,));
883
884	if fRetry is not True \
885	or utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
886	break;
887	time.sleep(2);
888
889	return (asXml, False);
890
891
892	#
893	# Overridden methods.
894	#
895
896	def isLocal(self):
897	return False;
898
899	def log(self, iLevel, sText, sCaller, sTsPrf):
900	if iLevel <= self.iVerbose:
901	if self.iDebug > 0:
902	sLogText = '%s %30s: %s' % (sTsPrf, sCaller, sText);
903	else:
904	sLogText = '%s %s: %s' % (sTsPrf, self.sName, sText);
905	self._writeOutput(sLogText);
906	return 0;
907
908	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
909	fRc = True;
910	if sKind in [ 'text', 'log', 'process'] \
911	or sKind.startswith('log/') \
912	or sKind.startswith('info/') \
913	or sKind.startswith('process/'):
914	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
915	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
916	self.xmlFlush();
917	g_oLock.release();
918	try:
919	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'text/plain');
920	finally:
921	g_oLock.acquire();
922	elif sKind.startswith('screenshot/'):
923	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
924	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
925	self.xmlFlush();
926	g_oLock.release();
927	try:
928	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'image/png');
929	finally:
930	g_oLock.acquire();
931	elif sKind.startswith('misc/'):
932	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
933	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
934	self.xmlFlush();
935	g_oLock.release();
936	try:
937	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'application/octet-stream');
938	finally:
939	g_oLock.acquire();
940	else:
941	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
942	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
943	return fRc;
944
945	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
946	fRc = True;
947	if sKind in [ 'text', 'log', 'process'] \
948	or sKind.startswith('log/') \
949	or sKind.startswith('info/') \
950	or sKind.startswith('process/'):
951	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
952	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
953	self.xmlFlush();
954	g_oLock.release();
955	try:
956	self._doUploadString(sLog, sLogName, sDescription, sKind, 'text/plain');
957	finally:
958	g_oLock.acquire();
959	else:
960	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
961	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
962	return fRc;
963
964	def xmlFlush(self, fRetry = False, fForce = False):
965	"""
966	Flushes the XML back log. Called with the lock held, may leave it
967	while communicating with the server.
968	"""
969	if not self._fXmlFlushing:
970	asXml = self._asXml;
971	self._asXml = [];
972	if asXml or fForce is True:
973	self._fXmlFlushing = True;
974
975	g_oLock.release();
976	try:
977	(asXml, fIncErrors) = self._xmlDoFlush(asXml, fRetry = fRetry);
978	finally:
979	g_oLock.acquire();
980
981	if fIncErrors:
982	self.testIncErrors();
983
984	self._fXmlFlushing = False;
985	if asXml is None:
986	self._secTsXmlFlush = utils.timestampSecond();
987	else:
988	self._asXml = asXml + self._asXml;
989	return True;
990
991	self._secTsXmlFlush = utils.timestampSecond();
992	return False;
993
994	def _xmlFlushIfNecessary(self, fPolling = False, sDebug = None):
995	"""Flushes the XML back log if necessary."""
996	tsNow = utils.timestampSecond();
997	cSecs = tsNow - self._secTsXmlFlush;
998	cSecsLast = tsNow - self._secTsXmlLast;
999	if fPolling is not True:
1000	self._secTsXmlLast = tsNow;
1001
1002	# Absolute flush thresholds.
1003	if cSecs >= self.kcSecXmlFlushMax:
1004	return self.xmlFlush();
1005	if len(self._asXml) >= self.kcLinesXmlFlush:
1006	return self.xmlFlush();
1007
1008	# Flush if idle long enough.
1009	if cSecs >= self.kcSecXmlFlushMin \
1010	and cSecsLast >= self.kcSecXmlFlushIdle:
1011	return self.xmlFlush();
1012
1013	_ = sDebug;
1014	return False;
1015
1016	def _xmlWrite(self, asText, fIndent = True):
1017	"""XML output function for the reporter."""
1018	self._asXml += asText;
1019	self._xmlFlushIfNecessary();
1020	_ = fIndent; # No pretty printing, thank you.
1021	return None;
1022
1023	def subXmlStart(self, oFileWrapper):
1024	oFileWrapper.sXmlBuffer = '';
1025	return None;
1026
1027	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
1028	oFileWrapper.sXmlBuffer += sRawXml;
1029	_ = sCaller;
1030	return None;
1031
1032	def subXmlEnd(self, oFileWrapper):
1033	sRawXml = oFileWrapper.sXmlBuffer;
1034	## @todo should validate the document here and maybe auto terminate things. Adding some hints to have the server do
1035	# this instead.
1036	g_oLock.acquire();
1037	try:
1038	self._asXml += [ '<PushHint testdepth="%d"/>' % (len(self.atTests),),
1039	sRawXml,
1040	'<PopHint testdepth="%d"/>' % (len(self.atTests),),];
1041	self._xmlFlushIfNecessary();
1042	finally:
1043	g_oLock.release();
1044	return None;
1045
1046	def doPollWork(self, sDebug = None):
1047	if self._asXml:
1048	g_oLock.acquire();
1049	try:
1050	self._xmlFlushIfNecessary(fPolling = True, sDebug = sDebug);
1051	finally:
1052	g_oLock.release();
1053	return None;
1054
1055
1056	#
1057	# Helpers
1058	#
1059
1060	def logXcptWorker(iLevel, fIncErrors, sPrefix="", sText=None, cFrames=1):
1061	"""
1062	Log an exception, optionally with a preceeding message and more than one
1063	call frame.
1064	"""
1065	g_oLock.acquire();
1066	try:
1067
1068	if fIncErrors:
1069	g_oReporter.testIncErrors();
1070
1071	## @todo skip all this if iLevel is too high!
1072
1073	# Try get exception info.
1074	sTsPrf = utils.getTimePrefix();
1075	try:
1076	oType, oValue, oTraceback = sys.exc_info();
1077	except:
1078	oType = oValue = oTraceback = None;
1079	if oType is not None:
1080
1081	# Try format the info
1082	try:
1083	rc = 0;
1084	sCaller = utils.getCallerName(oTraceback.tb_frame);
1085	if sText is not None:
1086	rc = g_oReporter.log(iLevel, "%s%s" % (sPrefix, sText), sCaller, sTsPrf);
1087	asInfo = [];
1088	try:
1089	asInfo = asInfo + traceback.format_exception_only(oType, oValue);
1090	if cFrames is not None and cFrames <= 1:
1091	asInfo = asInfo + traceback.format_tb(oTraceback, 1);
1092	else:
1093	asInfo.append('Traceback:')
1094	asInfo = asInfo + traceback.format_tb(oTraceback, cFrames);
1095	asInfo.append('Stack:')
1096	asInfo = asInfo + traceback.format_stack(oTraceback.tb_frame.f_back, cFrames);
1097	except:
1098	g_oReporter.log(0, '** internal-error: Hit exception #2! %s' % (traceback.format_exc()), sCaller, sTsPrf);
1099
1100	if asInfo:
1101	# Do the logging.
1102	for sItem in asInfo:
1103	asLines = sItem.splitlines();
1104	for sLine in asLines:
1105	rc = g_oReporter.log(iLevel, '%s%s' % (sPrefix, sLine), sCaller, sTsPrf);
1106
1107	else:
1108	g_oReporter.log(iLevel, 'No exception info...', sCaller, sTsPrf);
1109	rc = -3;
1110	except:
1111	g_oReporter.log(0, '** internal-error: Hit exception! %s' % (traceback.format_exc()), None, sTsPrf);
1112	rc = -2;
1113	else:
1114	g_oReporter.log(0, '** internal-error: No exception! %s'
1115	% (utils.getCallerName(iFrame=3)), utils.getCallerName(iFrame=3), sTsPrf);
1116	rc = -1;
1117
1118	finally:
1119	g_oLock.release();
1120	return rc;
1121
1122	#
1123	# The public Classes
1124	#
1125	class FileWrapper(object):
1126	""" File like class for TXS EXEC and similar. """
1127	def __init__(self, sPrefix):
1128	self.sPrefix = sPrefix;
1129
1130	def __del__(self):
1131	self.close();
1132
1133	def close(self):
1134	""" file.close """
1135	# Nothing to be done.
1136	return;
1137
1138	def read(self, cb):
1139	"""file.read"""
1140	_ = cb;
1141	return "";
1142
1143	def write(self, sText):
1144	"""file.write"""
1145	if isinstance(sText, array.array):
1146	try:
1147	sText = sText.tostring();
1148	except:
1149	pass;
1150	g_oLock.acquire();
1151	try:
1152	sTsPrf = utils.getTimePrefix();
1153	sCaller = utils.getCallerName();
1154	asLines = sText.splitlines();
1155	for sLine in asLines:
1156	g_oReporter.log(0, '%s: %s' % (self.sPrefix, sLine), sCaller, sTsPrf);
1157	except:
1158	traceback.print_exc();
1159	finally:
1160	g_oLock.release();
1161	return None;
1162
1163	class FileWrapperTestPipe(object):
1164	""" File like class for the test pipe (TXS EXEC and similar). """
1165	def __init__(self):
1166	self.sPrefix = '';
1167	self.fStarted = False;
1168	self.fClosed = False;
1169	self.sTagBuffer = None;
1170
1171	def __del__(self):
1172	self.close();
1173
1174	def close(self):
1175	""" file.close """
1176	if self.fStarted is True and self.fClosed is False:
1177	self.fClosed = True;
1178	try: g_oReporter.subXmlEnd(self);
1179	except:
1180	try: traceback.print_exc();
1181	except: pass;
1182	return True;
1183
1184	def read(self, cb = None):
1185	"""file.read"""
1186	_ = cb;
1187	return "";
1188
1189	def write(self, sText):
1190	"""file.write"""
1191	# lazy start.
1192	if self.fStarted is not True:
1193	try:
1194	g_oReporter.subXmlStart(self);
1195	except:
1196	traceback.print_exc();
1197	self.fStarted = True;
1198
1199	if isinstance(sText, array.array):
1200	try:
1201	sText = sText.tostring();
1202	except:
1203	pass;
1204	try:
1205	g_oReporter.subXmlWrite(self, sText, utils.getCallerName());
1206	# Parse the supplied text and look for <Failed.../> tags to keep track of the
1207	# error counter. This is only a very lazy aproach.
1208	sText.strip();
1209	idxText = 0;
1210	while sText:
1211	if self.sTagBuffer is None:
1212	# Look for the start of a tag.
1213	idxStart = sText[idxText:].find('<');
1214	if idxStart != -1:
1215	# Look for the end of the tag.
1216	idxEnd = sText[idxStart:].find('>');
1217
1218	# If the end was found inside the current buffer, parse the line,
1219	# else we have to save it for later.
1220	if idxEnd != -1:
1221	idxEnd += idxStart + 1;
1222	self._processXmlElement(sText[idxStart:idxEnd]);
1223	idxText = idxEnd;
1224	else:
1225	self.sTagBuffer = sText[idxStart:];
1226	idxText = len(sText);
1227	else:
1228	idxText = len(sText);
1229	else:
1230	# Search for the end of the tag and parse the whole tag.
1231	idxEnd = sText[idxText:].find('>');
1232	if idxEnd != -1:
1233	idxEnd += idxStart + 1;
1234	self._processXmlElement(self.sTagBuffer + sText[idxText:idxEnd]);
1235	self.sTagBuffer = None;
1236	idxText = idxEnd;
1237	else:
1238	self.sTagBuffer = self.sTagBuffer + sText[idxText:];
1239	idxText = len(sText);
1240
1241	sText = sText[idxText:];
1242	sText = sText.lstrip();
1243	except:
1244	traceback.print_exc();
1245	return None;
1246
1247	def _processXmlElement(self, sElement):
1248	"""
1249	Processes a complete XML tag (so far we only search for the Failed to tag
1250	to keep track of the error counter.
1251	"""
1252	# Make sure we don't parse any space between < and the element name.
1253	sElement = sElement.strip();
1254
1255	# Find the end of the name
1256	idxEndName = sElement.find(' ');
1257	if idxEndName == -1:
1258	idxEndName = sElement.find('/');
1259	if idxEndName == -1:
1260	idxEndName = sElement.find('>');
1261
1262	if idxEndName != -1:
1263	if sElement[1:idxEndName] == 'Failed':
1264	g_oLock.acquire();
1265	try:
1266	g_oReporter.testIncErrors();
1267	finally:
1268	g_oLock.release();
1269	else:
1270	error('_processXmlElement(%s)' % sElement);
1271
1272
1273	#
1274	# The public APIs.
1275	#
1276
1277	def log(sText):
1278	"""Writes the specfied text to the log."""
1279	g_oLock.acquire();
1280	try:
1281	rc = g_oReporter.log(1, sText, utils.getCallerName(), utils.getTimePrefix());
1282	except:
1283	rc = -1;
1284	finally:
1285	g_oLock.release();
1286	return rc;
1287
1288	def logXcpt(sText=None, cFrames=1):
1289	"""
1290	Log an exception, optionally with a preceeding message and more than one
1291	call frame.
1292	"""
1293	return logXcptWorker(1, False, "", sText, cFrames);
1294
1295	def log2(sText):
1296	"""Log level 2: Writes the specfied text to the log."""
1297	g_oLock.acquire();
1298	try:
1299	rc = g_oReporter.log(2, sText, utils.getCallerName(), utils.getTimePrefix());
1300	except:
1301	rc = -1;
1302	finally:
1303	g_oLock.release();
1304	return rc;
1305
1306	def log2Xcpt(sText=None, cFrames=1):
1307	"""
1308	Log level 2: Log an exception, optionally with a preceeding message and
1309	more than one call frame.
1310	"""
1311	return logXcptWorker(2, False, "", sText, cFrames);
1312
1313	def maybeErr(fIsError, sText):
1314	""" Maybe error or maybe normal log entry. """
1315	if fIsError is True:
1316	return error(sText);
1317	return log(sText);
1318
1319	def maybeErrXcpt(fIsError, sText=None, cFrames=1):
1320	""" Maybe error or maybe normal log exception entry. """
1321	if fIsError is True:
1322	return errorXcpt(sText, cFrames);
1323	return logXcpt(sText, cFrames);
1324
1325	def maybeLog(fIsNotError, sText):
1326	""" Maybe error or maybe normal log entry. """
1327	if fIsNotError is not True:
1328	return error(sText);
1329	return log(sText);
1330
1331	def maybeLogXcpt(fIsNotError, sText=None, cFrames=1):
1332	""" Maybe error or maybe normal log exception entry. """
1333	if fIsNotError is not True:
1334	return errorXcpt(sText, cFrames);
1335	return logXcpt(sText, cFrames);
1336
1337	def error(sText):
1338	"""
1339	Writes the specfied error message to the log.
1340
1341	This will add an error to the current test.
1342
1343	Always returns False for the convenience of methods returning boolean
1344	success indicators.
1345	"""
1346	g_oLock.acquire();
1347	try:
1348	g_oReporter.testIncErrors();
1349	g_oReporter.log(0, '** error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1350	except:
1351	pass;
1352	finally:
1353	g_oLock.release();
1354	return False;
1355
1356	def errorXcpt(sText=None, cFrames=1):
1357	"""
1358	Log an error caused by an exception. If sText is given, it will preceed
1359	the exception information. cFrames can be used to display more stack.
1360
1361	This will add an error to the current test.
1362
1363	Always returns False for the convenience of methods returning boolean
1364	success indicators.
1365	"""
1366	logXcptWorker(0, True, '** error: ', sText, cFrames);
1367	return False;
1368
1369	def errorTimeout(sText):
1370	"""
1371	Flags the current test as having timed out and writes the specified message to the log.
1372
1373	This will add an error to the current test.
1374
1375	Always returns False for the convenience of methods returning boolean
1376	success indicators.
1377	"""
1378	g_oLock.acquire();
1379	try:
1380	g_oReporter.testSetTimedOut();
1381	g_oReporter.log(0, '** timeout-error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1382	except:
1383	pass;
1384	finally:
1385	g_oLock.release();
1386	return False;
1387
1388	def fatal(sText):
1389	"""
1390	Writes a fatal error to the log.
1391
1392	This will add an error to the current test.
1393
1394	Always returns False for the convenience of methods returning boolean
1395	success indicators.
1396	"""
1397	g_oLock.acquire();
1398	try:
1399	g_oReporter.testIncErrors();
1400	g_oReporter.log(0, '** fatal error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1401	except:
1402	pass
1403	finally:
1404	g_oLock.release();
1405	return False;
1406
1407	def fatalXcpt(sText=None, cFrames=1):
1408	"""
1409	Log a fatal error caused by an exception. If sText is given, it will
1410	preceed the exception information. cFrames can be used to display more
1411	stack.
1412
1413	This will add an error to the current test.
1414
1415	Always returns False for the convenience of methods returning boolean
1416	success indicators.
1417	"""
1418	logXcptWorker(0, True, "** fatal error: ", sText, cFrames);
1419	return False;
1420
1421	def addLogFile(sFilename, sKind, sDescription = '', sAltName = None):
1422	"""
1423	Adds the specified log file to the report if the file exists.
1424
1425	The sDescription is a free form description of the log file.
1426
1427	The sKind parameter is for adding some machine parsable hint what kind of
1428	log file this really is.
1429
1430	Returns True on success, False on failure (no ENOENT errors are logged).
1431	"""
1432	sTsPrf = utils.getTimePrefix();
1433	sCaller = utils.getCallerName();
1434	fRc = False;
1435	if sAltName is None:
1436	sAltName = sFilename;
1437
1438	try:
1439	oSrcFile = utils.openNoInherit(sFilename, 'rb');
1440	except IOError as oXcpt:
1441	if oXcpt.errno != errno.ENOENT:
1442	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1443	else:
1444	logXcpt('addLogFile(%s,%s,%s) IOError' % (sFilename, sDescription, sKind));
1445	except:
1446	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1447	else:
1448	g_oLock.acquire();
1449	try:
1450	fRc = g_oReporter.addLogFile(oSrcFile, sFilename, sAltName, sDescription, sKind, sCaller, sTsPrf);
1451	finally:
1452	g_oLock.release();
1453	oSrcFile.close();
1454	return fRc;
1455
1456	def addLogString(sLog, sLogName, sKind, sDescription = ''):
1457	"""
1458	Adds the specified log string to the report.
1459
1460	The sLog parameter sets the name of the log file.
1461
1462	The sDescription is a free form description of the log file.
1463
1464	The sKind parameter is for adding some machine parsable hint what kind of
1465	log file this really is.
1466
1467	Returns True on success, False on failure (no ENOENT errors are logged).
1468	"""
1469	sTsPrf = utils.getTimePrefix();
1470	sCaller = utils.getCallerName();
1471	fRc = False;
1472
1473	g_oLock.acquire();
1474	try:
1475	fRc = g_oReporter.addLogString(sLog, sLogName, sDescription, sKind, sCaller, sTsPrf);
1476	finally:
1477	g_oLock.release();
1478	return fRc;
1479
1480	def isLocal():
1481	"""Is this a local reporter?"""
1482	return g_oReporter.isLocal()
1483
1484	def incVerbosity():
1485	"""Increases the verbosity level."""
1486	return g_oReporter.incVerbosity()
1487
1488	def incDebug():
1489	"""Increases the debug level."""
1490	return g_oReporter.incDebug()
1491
1492	def appendToProcessName(sAppend):
1493	"""
1494	Appends sAppend to the base process name.
1495	Returns the new process name.
1496	"""
1497	return g_oReporter.appendToProcessName(sAppend);
1498
1499	def getErrorCount():
1500	"""
1501	Get the current error count for the entire test run.
1502	"""
1503	g_oLock.acquire();
1504	try:
1505	cErrors = g_oReporter.cErrors;
1506	finally:
1507	g_oLock.release();
1508	return cErrors;
1509
1510	def doPollWork(sDebug = None):
1511	"""
1512	This can be called from wait loops and similar to make the reporter call
1513	home with pending XML and such.
1514	"""
1515	g_oReporter.doPollWork(sDebug);
1516	return None;
1517
1518
1519	#
1520	# Test reporting, a bit similar to RTTestI*.
1521	#
1522
1523	def testStart(sName):
1524	"""
1525	Starts a new test (pushes it).
1526	"""
1527	g_oLock.acquire();
1528	try:
1529	rc = g_oReporter.testStart(sName, utils.getCallerName());
1530	finally:
1531	g_oLock.release();
1532	return rc;
1533
1534	def testValue(sName, sValue, sUnit):
1535	"""
1536	Reports a benchmark value or something simiarlly useful.
1537	"""
1538	g_oLock.acquire();
1539	try:
1540	rc = g_oReporter.testValue(sName, str(sValue), sUnit, utils.getCallerName());
1541	finally:
1542	g_oLock.release();
1543	return rc;
1544
1545	def testFailure(sDetails):
1546	"""
1547	Reports a failure.
1548	We count these calls and testDone will use them to report PASSED or FAILED.
1549
1550	Returns False so that a return False line can be saved.
1551	"""
1552	g_oLock.acquire();
1553	try:
1554	g_oReporter.testFailure(sDetails, utils.getCallerName());
1555	finally:
1556	g_oLock.release();
1557	return False;
1558
1559	def testFailureXcpt(sDetails = ''):
1560	"""
1561	Reports a failure with exception.
1562	We count these calls and testDone will use them to report PASSED or FAILED.
1563
1564	Returns False so that a return False line can be saved.
1565	"""
1566	# Extract exception info.
1567	try:
1568	oType, oValue, oTraceback = sys.exc_info();
1569	except:
1570	oType = oValue, oTraceback = None;
1571	if oType is not None:
1572	sCaller = utils.getCallerName(oTraceback.tb_frame);
1573	sXcpt = ' '.join(traceback.format_exception_only(oType, oValue));
1574	else:
1575	sCaller = utils.getCallerName();
1576	sXcpt = 'No exception at %s' % (sCaller,);
1577
1578	# Use testFailure to do the work.
1579	g_oLock.acquire();
1580	try:
1581	if sDetails == '':
1582	g_oReporter.testFailure('Exception: %s' % (sXcpt,), sCaller);
1583	else:
1584	g_oReporter.testFailure('%s: %s' % (sDetails, sXcpt), sCaller);
1585	finally:
1586	g_oLock.release();
1587	return False;
1588
1589	def testDone(fSkipped = False):
1590	"""
1591	Completes the current test (pops it), logging PASSED / FAILURE.
1592
1593	Returns a tuple with the name of the test and its error count.
1594	"""
1595	g_oLock.acquire();
1596	try:
1597	rc = g_oReporter.testDone(fSkipped, utils.getCallerName());
1598	finally:
1599	g_oLock.release();
1600	return rc;
1601
1602	def testErrorCount():
1603	"""
1604	Gets the error count of the current test.
1605
1606	Returns the number of errors.
1607	"""
1608	g_oLock.acquire();
1609	try:
1610	cErrors = g_oReporter.testErrorCount();
1611	finally:
1612	g_oLock.release();
1613	return cErrors;
1614
1615	def testCleanup():
1616	"""
1617	Closes all open tests with a generic error condition.
1618
1619	Returns True if no open tests, False if something had to be closed with failure.
1620	"""
1621	g_oLock.acquire();
1622	try:
1623	fRc = g_oReporter.testCleanup(utils.getCallerName());
1624	g_oReporter.xmlFlush(fRetry = False, fForce = True);
1625	finally:
1626	g_oLock.release();
1627	return fRc;
1628
1629
1630	#
1631	# Sub XML stuff.
1632	#
1633
1634	def addSubXmlFile(sFilename):
1635	"""
1636	Adds a sub-xml result file to the party.
1637	"""
1638	fRc = False;
1639	try:
1640	oSrcFile = utils.openNoInherit(sFilename, 'r');
1641	except IOError as oXcpt:
1642	if oXcpt.errno != errno.ENOENT:
1643	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1644	except:
1645	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1646	else:
1647	try:
1648	oWrapper = FileWrapperTestPipe()
1649	oWrapper.write(oSrcFile.read());
1650	oWrapper.close();
1651	except:
1652	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1653	oSrcFile.close();
1654
1655	return fRc;
1656
1657
1658	#
1659	# Other useful debugging tools.
1660	#
1661
1662	def logAllStacks(cFrames = None):
1663	"""
1664	Logs the stacks of all python threads.
1665	"""
1666	sTsPrf = utils.getTimePrefix();
1667	sCaller = utils.getCallerName();
1668	g_oLock.acquire();
1669
1670	cThread = 0;
1671	for idThread, oStack in sys._current_frames().items(): # >=2.5, a bit ugly - pylint: disable=W0212
1672	try:
1673	if cThread > 0:
1674	g_oReporter.log(1, '', sCaller, sTsPrf);
1675	g_oReporter.log(1, 'Thread %s (%#x)' % (idThread, idThread), sCaller, sTsPrf);
1676	try:
1677	asInfo = traceback.format_stack(oStack, cFrames);
1678	except:
1679	g_oReporter.log(1, ' Stack formatting failed w/ exception', sCaller, sTsPrf);
1680	else:
1681	for sInfo in asInfo:
1682	asLines = sInfo.splitlines();
1683	for sLine in asLines:
1684	g_oReporter.log(1, sLine, sCaller, sTsPrf);
1685	except:
1686	pass;
1687	cThread += 1;
1688
1689	g_oLock.release();
1690	return None;
1691
1692	def checkTestManagerConnection():
1693	"""
1694	Checks the connection to the test manager.
1695
1696	Returns True if the connection is fine, False if not, None if not remote
1697	reporter.
1698
1699	Note! This as the sideeffect of flushing XML.
1700	"""
1701	g_oLock.acquire();
1702	try:
1703	fRc = g_oReporter.xmlFlush(fRetry = False, fForce = True);
1704	finally:
1705	g_oLock.release();
1706	return fRc;
1707
1708	def flushall(fSkipXml = False):
1709	"""
1710	Flushes all output streams, both standard and logger related.
1711	This may also push data to the remote test manager.
1712	"""
1713	try: sys.stdout.flush();
1714	except: pass;
1715	try: sys.stderr.flush();
1716	except: pass;
1717
1718	if fSkipXml is not True:
1719	g_oLock.acquire();
1720	try:
1721	g_oReporter.xmlFlush(fRetry = False);
1722	finally:
1723	g_oLock.release();
1724
1725	return True;
1726
1727
1728	#
1729	# Module initialization.
1730	#
1731
1732	def _InitReporterModule():
1733	"""
1734	Instantiate the test reporter.
1735	"""
1736	global g_oReporter, g_sReporterName
1737
1738	g_sReporterName = os.getenv("TESTBOX_REPORTER", "local");
1739	if g_sReporterName == "local":
1740	g_oReporter = LocalReporter();
1741	elif g_sReporterName == "remote":
1742	g_oReporter = RemoteReporter(); # Correct, but still plain stupid. pylint: disable=redefined-variable-type
1743	else:
1744	print(os.path.basename(__file__) + ": Unknown TESTBOX_REPORTER value: '" + g_sReporterName + "'", file = sys.stderr);
1745	raise Exception("Unknown TESTBOX_REPORTER value '" + g_sReporterName + "'");
1746
1747	if __name__ != "checker": # pychecker avoidance.
1748	_InitReporterModule();
1749

Note: See TracBrowser for help on using the repository browser.

source: vbox/trunk/src/VBox/ValidationKit/testdriver/reporter.py@ 70570

Download in other formats: