reporter.py@ 79142

Last change on this file since 79142 was 79138, checked in by vboxsync, 6 years ago
ValKit: Hack to try make COM and XPCOM exceptions more readable.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 62.1 KB

Line
1	# -- coding: utf-8 --
2	# $Id: reporter.py 79138 2019-06-14 01:00:00Z vboxsync $
3	# pylint: disable=too-many-lines
4
5	"""
6	Testdriver reporter module.
7	"""
8
9	from __future__ import print_function;
10
11	__copyright__ = \
12	"""
13	Copyright (C) 2010-2019 Oracle Corporation
14
15	This file is part of VirtualBox Open Source Edition (OSE), as
16	available from http://www.virtualbox.org. 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: 79138 $"
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 is not 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 not self.atTests:
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	self.sDefLogDir = os.path.abspath(os.path.expanduser(os.path.join('~', 'VBoxTestLogs')));
389	except:
390	self.sDefLogDir = os.path.abspath("VBoxTestLogs");
391	try:
392	sLogDir = os.path.abspath(os.environ.get('TESTBOX_REPORTER_LOG_DIR', self.sDefLogDir));
393	if not os.path.isdir(sLogDir):
394	os.makedirs(sLogDir, 0o750);
395	except:
396	sLogDir = self.sDefLogDir;
397	if not os.path.isdir(sLogDir):
398	os.makedirs(sLogDir, 0o750);
399
400	#
401	# Make a subdirectory for this test run.
402	#
403	sTs = datetime.datetime.utcnow().strftime('%Y-%m-%dT%H-%M-%S.log');
404	self.sLogDir = sLogDir = os.path.join(sLogDir, '%s-%s' % (sTs, self.sName));
405	try:
406	os.makedirs(self.sLogDir, 0o750);
407	except:
408	self.sLogDir = '%s-%s' % (self.sLogDir, os.getpid());
409	os.makedirs(self.sLogDir, 0o750);
410
411	#
412	# Open the log file and write a header.
413	#
414	sLogName = os.path.join(self.sLogDir, 'testsuite.log');
415	sTsIso = utils.getIsoTimestamp();
416	if sys.version_info[0] >= 3: # Add 'b' to prevent write taking issue with encode('utf-8') not returning a string.
417	self.oLogFile = utils.openNoInherit(sLogName, "wb");
418	else:
419	self.oLogFile = utils.openNoInherit(sLogName, "w");
420	self.oLogFile.write(('Created log file at %s.\nRunning: %s' % (sTsIso, sys.argv)).encode('utf-8'));
421
422	#
423	# Open the xml log file and write the mandatory introduction.
424	#
425	# Note! This is done here and not in the base class because the remote
426	# logger doesn't really need this. It doesn't need the outer
427	# test wrapper either.
428	#
429	sXmlName = os.path.join(self.sLogDir, 'testsuite.xml');
430	if sys.version_info[0] >= 3: # Add 'b' to prevent write taking issue with encode('utf-8') not returning a string.
431	self.oXmlFile = utils.openNoInherit(sXmlName, "wb");
432	else:
433	self.oXmlFile = utils.openNoInherit(sXmlName, "w");
434	self._xmlWrite([ '<?xml version="1.0" encoding="UTF-8" ?>',
435	'<Test timestamp="%s" name="%s">' % (sTsIso, self._xmlEscAttr(self.sName),), ],
436	fIndent = False);
437
438	def __del__(self):
439	"""Ends and completes the log files."""
440	try: sTsIso = self.fnGetIsoTimestamp();
441	except Exception as oXcpt:
442	sTsIso = str(oXcpt);
443
444	if self.oLogFile is not None:
445	try:
446	self.oLogFile.write(('\nThe End %s\n' % (sTsIso,)).encode('utf-8'));
447	self.oLogFile.close();
448	except: pass;
449	self.oLogFile = None;
450
451	if self.oXmlFile is not None:
452	self._closeXml(sTsIso);
453	self.oXmlFile = None;
454
455	def _closeXml(self, sTsIso):
456	"""Closes the XML file."""
457	if self.oXmlFile is not None:
458	# pop the test stack
459	while self.atTests:
460	sName, cErrorsStart, self.fTimedOut = self.atTests.pop();
461	self._xmlWrite([ '<End timestamp="%s" errors="%d"/>' % (sTsIso, self.cErrors - cErrorsStart,),
462	'</%s>' % (sName,), ]);
463
464	# The outer one is not on the stack.
465	self._xmlWrite([ ' <End timestamp="%s"/>' % (sTsIso,),
466	'</Test>', ], fIndent = False);
467	try:
468	self.oXmlFile.close();
469	self.oXmlFile = None;
470	except:
471	pass;
472
473	def _xmlWrite(self, asText, fIndent = True):
474	"""Writes to the XML file."""
475	for sText in asText:
476	if fIndent:
477	sIndent = ''.ljust((len(self.atTests) + 1) * 2);
478	sText = sIndent + sText;
479	sText += '\n';
480
481	try:
482	self.oXmlFile.write(sText.encode('utf-8'));
483	except:
484	if self.fXmlOk:
485	traceback.print_exc();
486	self.fXmlOk = False;
487	return False;
488	return True;
489
490	#
491	# Overridden methods.
492	#
493
494	def isLocal(self):
495	"""Is this a local reporter?"""
496	return True;
497
498	def log(self, iLevel, sText, sCaller, sTsPrf):
499	if iLevel <= self.iVerbose:
500	# format it.
501	if self.iDebug > 0:
502	sLogText = '%s %30s: %s' % (sTsPrf, sCaller, sText);
503	else:
504	sLogText = '%s %s' % (sTsPrf, sText);
505
506	# output it.
507	if sys.version_info[0] >= 3:
508	sAscii = sLogText;
509	else:
510	sAscii = sLogText.encode('ascii', 'replace');
511	if self.iDebug == 0:
512	print('%s: %s' % (self.sName, sAscii), file = self.oStdErr);
513	else:
514	print('%s' % (sAscii), file = self.oStdErr);
515	sLogText += '\n';
516	try:
517	self.oLogFile.write(sLogText.encode('utf-8'));
518	except:
519	pass;
520	return 0;
521
522	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
523	# Figure the destination filename.
524	iOtherFile = self.iOtherFile;
525	self.iOtherFile += 1;
526	sDstFilename = os.path.join(self.sLogDir, 'other-%d-%s.log' \
527	% (iOtherFile, os.path.splitext(os.path.basename(sSrcFilename))[0]));
528	self.log(0, '** Other log file: %s - %s (%s)' % (sDstFilename, sDescription, sSrcFilename), sCaller, sTsPrf);
529
530	# Open the destination file and copy over the data.
531	fRc = True;
532	try:
533	oDstFile = utils.openNoInherit(sDstFilename, 'wb');
534	except Exception as oXcpt:
535	self.log(0, 'error opening %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
536	else:
537	while True:
538	try:
539	abBuf = oSrcFile.read(65536);
540	except Exception as oXcpt:
541	fRc = False;
542	self.log(0, 'error reading %s: %s' % (sSrcFilename, oXcpt), sCaller, sTsPrf);
543	else:
544	try:
545	oDstFile.write(abBuf);
546	except Exception as oXcpt:
547	fRc = False;
548	self.log(0, 'error writing %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
549	else:
550	if abBuf:
551	continue;
552	break;
553	oDstFile.close();
554
555	# Leave a mark in the XML log.
556	self._xmlWrite(['<LogFile timestamp="%s" filename="%s" source="%s" kind="%s" ok="%s">%s</LogFile>\n'
557	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sDstFilename)), self._xmlEscAttr(sSrcFilename), \
558	self._xmlEscAttr(sKind), fRc, self._xmlEscAttr(sDescription))] );
559	_ = sAltName;
560	return fRc;
561
562	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
563	# Figure the destination filename.
564	iOtherFile = self.iOtherFile;
565	self.iOtherFile += 1;
566	sDstFilename = os.path.join(self.sLogDir, 'other-%d-%s.log' \
567	% (iOtherFile, os.path.splitext(os.path.basename(sLogName))[0]));
568	self.log(0, '** Other log file: %s - %s (%s)' % (sDstFilename, sDescription, sLogName), sCaller, sTsPrf);
569
570	# Open the destination file and copy over the data.
571	fRc = True;
572	try:
573	oDstFile = utils.openNoInherit(sDstFilename, 'w');
574	except Exception as oXcpt:
575	self.log(0, 'error opening %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
576	else:
577	try:
578	oDstFile.write(sLog);
579	except Exception as oXcpt:
580	fRc = False;
581	self.log(0, 'error writing %s: %s' % (sDstFilename, oXcpt), sCaller, sTsPrf);
582
583	oDstFile.close();
584
585	# Leave a mark in the XML log.
586	self._xmlWrite(['<LogFile timestamp="%s" filename="%s" source="%s" kind="%s" ok="%s">%s</LogFile>\n'
587	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sDstFilename)), self._xmlEscAttr(sLogName), \
588	self._xmlEscAttr(sKind), fRc, self._xmlEscAttr(sDescription))] );
589	return fRc;
590
591	def subXmlStart(self, oFileWrapper):
592	# Open a new file and just include it from the main XML.
593	iSubXml = self.iSubXml;
594	self.iSubXml += 1;
595	sSubXmlName = os.path.join(self.sLogDir, 'sub-%d.xml' % (iSubXml,));
596	try:
597	oFileWrapper.oSubXmlFile = utils.openNoInherit(sSubXmlName, "w");
598	except:
599	errorXcpt('open(%s)' % oFileWrapper.oSubXmlName);
600	oFileWrapper.oSubXmlFile = None;
601	else:
602	self._xmlWrite(['<Include timestamp="%s" filename="%s"/>\n'
603	% (utils.getIsoTimestamp(), self._xmlEscAttr(os.path.basename(sSubXmlName)))]);
604	return None;
605
606	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
607	if oFileWrapper.oSubXmlFile is not None:
608	try:
609	oFileWrapper.oSubXmlFile.write(sRawXml);
610	except:
611	pass;
612	if sCaller is None: pass; # pychecker - NOREF
613	return None;
614
615	def subXmlEnd(self, oFileWrapper):
616	if oFileWrapper.oSubXmlFile is not None:
617	try:
618	oFileWrapper.oSubXmlFile.close();
619	oFileWrapper.oSubXmlFile = None;
620	except:
621	pass;
622	return None;
623
624
625
626	class RemoteReporter(ReporterBase):
627	"""
628	Reporter that talks to the test manager server.
629	"""
630
631
632	## The XML sync min time (seconds).
633	kcSecXmlFlushMin = 30;
634	## The XML sync max time (seconds).
635	kcSecXmlFlushMax = 120;
636	## The XML sync idle time before flushing (seconds).
637	kcSecXmlFlushIdle = 5;
638	## The XML sync line count threshold.
639	kcLinesXmlFlush = 512;
640
641	## The retry timeout.
642	kcSecTestManagerRetryTimeout = 120;
643	## The request timeout.
644	kcSecTestManagerRequestTimeout = 30;
645
646
647	def __init__(self):
648	ReporterBase.__init__(self);
649	self.sTestManagerUrl = os.environ.get('TESTBOX_MANAGER_URL');
650	self.sTestBoxUuid = os.environ.get('TESTBOX_UUID');
651	self.idTestBox = int(os.environ.get('TESTBOX_ID'));
652	self.idTestSet = int(os.environ.get('TESTBOX_TEST_SET_ID'));
653	self._asXml = [];
654	self._secTsXmlFlush = utils.timestampSecond();
655	self._secTsXmlLast = self._secTsXmlFlush;
656	self._fXmlFlushing = False;
657	self.oOutput = sys.stdout; # Hack for __del__ output.
658	self.fFlushEachLine = True;
659	self.fDebugXml = 'TESTDRIVER_REPORTER_DEBUG_XML' in os.environ;
660
661	# Prepare the TM connecting.
662	from common import constants;
663	if sys.version_info[0] >= 3:
664	import urllib;
665	self._fnUrlEncode = urllib.parse.urlencode; # pylint: disable=no-member
666	self._fnUrlParseQs = urllib.parse.parse_qs; # pylint: disable=no-member
667	self._oParsedTmUrl = urllib.parse.urlparse(self.sTestManagerUrl); # pylint: disable=no-member
668	import http.client as httplib; # pylint: disable=no-name-in-module,import-error
669	else:
670	import urllib;
671	self._fnUrlEncode = urllib.urlencode; # pylint: disable=no-member
672	import urlparse; # pylint: disable=import-error
673	self._fnUrlParseQs = urlparse.parse_qs; # pylint: disable=no-member
674	self._oParsedTmUrl = urlparse.urlparse(self.sTestManagerUrl); # pylint: disable=no-member
675	import httplib; # pylint: disable=no-name-in-module,import-error
676
677	if sys.version_info[0] >= 3 \
678	or (sys.version_info[0] == 2 and sys.version_info[1] >= 6):
679	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=no-member
680	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname,
681	timeout = self.kcSecTestManagerRequestTimeout);
682	else:
683	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname,
684	timeout = self.kcSecTestManagerRequestTimeout);
685	else:
686	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=no-member
687	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname);
688	else:
689	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname);
690	self._dHttpHeader = \
691	{
692	'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8',
693	'User-Agent': 'TestDriverReporter/%s.0 (%s, %s)' % (__version__, utils.getHostOs(), utils.getHostArch(),),
694	'Accept': 'text/plain,application/x-www-form-urlencoded',
695	'Accept-Encoding': 'identity',
696	'Cache-Control': 'max-age=0',
697	#'Connection': 'keep-alive',
698	};
699
700	dParams = {
701	constants.tbreq.ALL_PARAM_TESTBOX_UUID: self.sTestBoxUuid,
702	constants.tbreq.ALL_PARAM_TESTBOX_ID: self.idTestBox,
703	constants.tbreq.RESULT_PARAM_TEST_SET_ID: self.idTestSet,
704	};
705	self._sTmServerPath = '/%s/testboxdisp.py?%s' \
706	% ( self._oParsedTmUrl.path.strip('/'), # pylint: disable=no-member
707	self._fnUrlEncode(dParams), );
708
709	def __del__(self):
710	"""Flush pending log messages?"""
711	if self._asXml:
712	self._xmlDoFlush(self._asXml, fRetry = True, fDtor = True);
713
714	def _writeOutput(self, sText):
715	""" Does the actual writing and flushing. """
716	if sys.version_info[0] >= 3:
717	print(sText, file = self.oOutput);
718	else:
719	print(sText.encode('ascii', 'replace'), file = self.oOutput);
720	if self.fFlushEachLine: self.oOutput.flush();
721	return None;
722
723	#
724	# Talking to TM.
725	#
726
727	def _processTmStatusResponse(self, oConn, sOperation, fClose = True):
728	"""
729	Processes HTTP reponse from the test manager.
730	Returns True, False or None. None should be retried, the others not.
731	May raise exception on HTTP issue (retry ok).
732	"""
733	if sys.version_info[0] >= 3: import http.client as httplib; # pylint: disable=no-name-in-module,import-error
734	else: import httplib; # pylint: disable=import-error
735	from common import constants;
736
737	# Read the response and (optionally) close the connection.
738	oResponse = oConn.getresponse();
739	try:
740	sRspBody = oResponse.read();
741	except httplib.IncompleteRead as oXcpt:
742	self._writeOutput('%s: %s: Warning: httplib.IncompleteRead: %s [expected %s, got %s]'
743	% (utils.getTimePrefix(), sOperation, oXcpt, oXcpt.expected, len(oXcpt.partial),));
744	sRspBody = oXcpt.partial;
745	if fClose is True:
746	try: oConn.close();
747	except: pass;
748
749	# Make sure it's a string which encoding we grok.
750	if hasattr(sRspBody, 'decode'):
751	sRspBody = sRspBody.decode('utf-8', 'ignore');
752
753	# Check the content type.
754	sContentType = oResponse.getheader('Content-Type');
755	if sContentType is not None and sContentType == 'application/x-www-form-urlencoded; charset=utf-8':
756
757	# Parse the body and check the RESULT parameter.
758	dResponse = self._fnUrlParseQs(sRspBody, strict_parsing = True);
759	sResult = dResponse.get(constants.tbresp.ALL_PARAM_RESULT, None);
760	if isinstance(sResult, list):
761	sResult = sResult[0] if len(sResult) == 1 else '%d results' % (len(sResult),);
762
763	if sResult is not None:
764	if sResult == constants.tbresp.STATUS_ACK:
765	return True;
766	if sResult == constants.tbresp.STATUS_NACK:
767	self._writeOutput('%s: %s: Failed (%s). (dResponse=%s)'
768	% (utils.getTimePrefix(), sOperation, sResult, dResponse,));
769	return False;
770
771	self._writeOutput('%s: %s: Failed - dResponse=%s' % (utils.getTimePrefix(), sOperation, dResponse,));
772	else:
773	self._writeOutput('%s: %s: Unexpected Content-Type: %s' % (utils.getTimePrefix(), sOperation, sContentType,));
774	self._writeOutput('%s: %s: Body: %s' % (utils.getTimePrefix(), sOperation, sRspBody,));
775	return None;
776
777	def _doUploadFile(self, oSrcFile, sSrcFilename, sDescription, sKind, sMime):
778	""" Uploads the given file to the test manager. """
779
780	# Prepare header and url.
781	dHeader = dict(self._dHttpHeader);
782	dHeader['Content-Type'] = 'application/octet-stream';
783	self._writeOutput('%s: _doUploadFile: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
784	oSrcFile.seek(0, 2);
785	cbFileSize = oSrcFile.tell();
786	self._writeOutput('%s: _doUploadFile: size=%d' % (utils.getTimePrefix(), cbFileSize,));
787	oSrcFile.seek(0);
788
789	if cbFileSize <= 0: # The Test Manager will bitch if the file size is 0, so skip uploading.
790	self._writeOutput('%s: _doUploadFile: Empty file, skipping upload' % utils.getTimePrefix());
791	return False;
792
793	from common import constants;
794	sUrl = self._sTmServerPath + '&' \
795	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcFilename),
796	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
797	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
798	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
799	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
800	});
801
802	# Retry loop.
803	secStart = utils.timestampSecond();
804	while True:
805	try:
806	oConn = self._fnTmConnect();
807	oConn.request('POST', sUrl, oSrcFile.read(), dHeader);
808	fRc = self._processTmStatusResponse(oConn, '_doUploadFile', fClose = True);
809	oConn.close();
810	if fRc is not None:
811	return fRc;
812	except:
813	logXcpt('warning: exception during UPLOAD request');
814
815	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
816	self._writeOutput('%s: _doUploadFile: Timed out.' % (utils.getTimePrefix(),));
817	break;
818	try: oSrcFile.seek(0);
819	except:
820	logXcpt();
821	break;
822	self._writeOutput('%s: _doUploadFile: Retrying...' % (utils.getTimePrefix(), ));
823	time.sleep(2);
824
825	return False;
826
827	def _doUploadString(self, sSrc, sSrcName, sDescription, sKind, sMime):
828	""" Uploads the given string as a separate file to the test manager. """
829
830	# Prepare header and url.
831	dHeader = dict(self._dHttpHeader);
832	dHeader['Content-Type'] = 'application/octet-stream';
833	self._writeOutput('%s: _doUploadString: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
834	self._writeOutput('%s: _doUploadString: size=%d' % (utils.getTimePrefix(), sys.getsizeof(sSrc),));
835
836	from common import constants;
837	sUrl = self._sTmServerPath + '&' \
838	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcName),
839	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
840	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
841	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
842	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
843	});
844
845	# Retry loop.
846	secStart = utils.timestampSecond();
847	while True:
848	try:
849	oConn = self._fnTmConnect();
850	oConn.request('POST', sUrl, sSrc, dHeader);
851	fRc = self._processTmStatusResponse(oConn, '_doUploadString', fClose = True);
852	oConn.close();
853	if fRc is not None:
854	return fRc;
855	except:
856	logXcpt('warning: exception during UPLOAD request');
857
858	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
859	self._writeOutput('%s: _doUploadString: Timed out.' % (utils.getTimePrefix(),));
860	break;
861	self._writeOutput('%s: _doUploadString: Retrying...' % (utils.getTimePrefix(), ));
862	time.sleep(2);
863
864	return False;
865
866	def _xmlDoFlush(self, asXml, fRetry = False, fDtor = False):
867	"""
868	The code that does the actual talking to the server.
869	Used by both xmlFlush and __del__.
870	"""
871	secStart = utils.timestampSecond();
872	while True:
873	fRc = None;
874	try:
875	# Post.
876	from common import constants;
877	sPostBody = self._fnUrlEncode({constants.tbreq.XML_RESULT_PARAM_BODY: '\n'.join(asXml),});
878	oConn = self._fnTmConnect();
879	oConn.request('POST',
880	self._sTmServerPath + ('&%s=%s' % (constants.tbreq.ALL_PARAM_ACTION, constants.tbreq.XML_RESULTS)),
881	sPostBody,
882	self._dHttpHeader);
883
884	fRc = self._processTmStatusResponse(oConn, '_xmlDoFlush', fClose = True);
885	if fRc is True:
886	if self.fDebugXml:
887	self._writeOutput('_xmlDoFlush:\n%s' % ('\n'.join(asXml),));
888	return (None, False);
889	if fRc is False:
890	self._writeOutput('_xmlDoFlush: Failed - we should abort the test, really.');
891	return (None, True);
892	except Exception as oXcpt:
893	if not fDtor:
894	logXcpt('warning: exception during XML_RESULTS request');
895	else:
896	self._writeOutput('warning: exception during XML_RESULTS request: %s' % (oXcpt,));
897
898	if fRetry is not True \
899	or utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
900	break;
901	time.sleep(2);
902
903	return (asXml, False);
904
905
906	#
907	# Overridden methods.
908	#
909
910	def isLocal(self):
911	return False;
912
913	def log(self, iLevel, sText, sCaller, sTsPrf):
914	if iLevel <= self.iVerbose:
915	if self.iDebug > 0:
916	sLogText = '%s %30s: %s' % (sTsPrf, sCaller, sText);
917	else:
918	sLogText = '%s %s: %s' % (sTsPrf, self.sName, sText);
919	self._writeOutput(sLogText);
920	return 0;
921
922	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
923	fRc = True;
924	if sKind in [ 'text', 'log', 'process'] \
925	or sKind.startswith('log/') \
926	or sKind.startswith('info/') \
927	or sKind.startswith('process/'):
928	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
929	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
930	self.xmlFlush();
931	g_oLock.release();
932	try:
933	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'text/plain');
934	finally:
935	g_oLock.acquire();
936	elif sKind.startswith('screenshot/'):
937	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
938	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
939	self.xmlFlush();
940	g_oLock.release();
941	try:
942	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'image/png');
943	finally:
944	g_oLock.acquire();
945	elif sKind.startswith('misc/'):
946	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
947	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
948	self.xmlFlush();
949	g_oLock.release();
950	try:
951	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'application/octet-stream');
952	finally:
953	g_oLock.acquire();
954	else:
955	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
956	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
957	return fRc;
958
959	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
960	fRc = True;
961	if sKind in [ 'text', 'log', 'process'] \
962	or sKind.startswith('log/') \
963	or sKind.startswith('info/') \
964	or sKind.startswith('process/'):
965	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
966	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
967	self.xmlFlush();
968	g_oLock.release();
969	try:
970	self._doUploadString(sLog, sLogName, sDescription, sKind, 'text/plain');
971	finally:
972	g_oLock.acquire();
973	else:
974	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
975	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
976	return fRc;
977
978	def xmlFlush(self, fRetry = False, fForce = False):
979	"""
980	Flushes the XML back log. Called with the lock held, may leave it
981	while communicating with the server.
982	"""
983	if not self._fXmlFlushing:
984	asXml = self._asXml;
985	self._asXml = [];
986	if asXml or fForce is True:
987	self._fXmlFlushing = True;
988
989	g_oLock.release();
990	try:
991	(asXml, fIncErrors) = self._xmlDoFlush(asXml, fRetry = fRetry);
992	finally:
993	g_oLock.acquire();
994
995	if fIncErrors:
996	self.testIncErrors();
997
998	self._fXmlFlushing = False;
999	if asXml is None:
1000	self._secTsXmlFlush = utils.timestampSecond();
1001	else:
1002	self._asXml = asXml + self._asXml;
1003	return True;
1004
1005	self._secTsXmlFlush = utils.timestampSecond();
1006	return False;
1007
1008	def _xmlFlushIfNecessary(self, fPolling = False, sDebug = None):
1009	"""Flushes the XML back log if necessary."""
1010	tsNow = utils.timestampSecond();
1011	cSecs = tsNow - self._secTsXmlFlush;
1012	cSecsLast = tsNow - self._secTsXmlLast;
1013	if fPolling is not True:
1014	self._secTsXmlLast = tsNow;
1015
1016	# Absolute flush thresholds.
1017	if cSecs >= self.kcSecXmlFlushMax:
1018	return self.xmlFlush();
1019	if len(self._asXml) >= self.kcLinesXmlFlush:
1020	return self.xmlFlush();
1021
1022	# Flush if idle long enough.
1023	if cSecs >= self.kcSecXmlFlushMin \
1024	and cSecsLast >= self.kcSecXmlFlushIdle:
1025	return self.xmlFlush();
1026
1027	_ = sDebug;
1028	return False;
1029
1030	def _xmlWrite(self, asText, fIndent = True):
1031	"""XML output function for the reporter."""
1032	self._asXml += asText;
1033	self._xmlFlushIfNecessary();
1034	_ = fIndent; # No pretty printing, thank you.
1035	return None;
1036
1037	def subXmlStart(self, oFileWrapper):
1038	oFileWrapper.sXmlBuffer = '';
1039	return None;
1040
1041	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
1042	oFileWrapper.sXmlBuffer += sRawXml;
1043	_ = sCaller;
1044	return None;
1045
1046	def subXmlEnd(self, oFileWrapper):
1047	sRawXml = oFileWrapper.sXmlBuffer;
1048	## @todo should validate the document here and maybe auto terminate things. Adding some hints to have the server do
1049	# this instead.
1050	g_oLock.acquire();
1051	try:
1052	self._asXml += [ '<PushHint testdepth="%d"/>' % (len(self.atTests),),
1053	sRawXml,
1054	'<PopHint testdepth="%d"/>' % (len(self.atTests),),];
1055	self._xmlFlushIfNecessary();
1056	finally:
1057	g_oLock.release();
1058	return None;
1059
1060	def doPollWork(self, sDebug = None):
1061	if self._asXml:
1062	g_oLock.acquire();
1063	try:
1064	self._xmlFlushIfNecessary(fPolling = True, sDebug = sDebug);
1065	finally:
1066	g_oLock.release();
1067	return None;
1068
1069
1070	#
1071	# Helpers
1072	#
1073
1074	g_fnComXcptFormatter = None;
1075
1076	def setComXcptFormatter(fnCallback):
1077	"""
1078	Install callback for prettier COM exception formatting.
1079
1080	The callback replaces the work done by format_exception_only() and
1081	takes the same arguments. It returns None if not interested in the
1082	exception.
1083	"""
1084	global g_fnComXcptFormatter;
1085	g_fnComXcptFormatter = fnCallback;
1086	return True;
1087
1088	def formatExceptionOnly(oType, oXcpt, sCaller, sTsPrf):
1089	"""
1090	Wrapper around traceback.format_exception_only and __g_fnComXcptFormatter.
1091	"""
1092	#asRet = ['oType=%s type(oXcpt)=%s' % (oType, type(oXcpt),)];
1093	asRet = [];
1094
1095	# Try the callback first.
1096	fnCallback = g_fnComXcptFormatter;
1097	if fnCallback:
1098	try:
1099	asRetCb = fnCallback(oType, oXcpt);
1100	if asRetCb:
1101	return asRetCb;
1102	#asRet += asRetCb;
1103	except:
1104	g_oReporter.log(0, '** internal-error: Hit exception #2 in __g_fnComXcptFormatter! %s'
1105	% (traceback.format_exc()), sCaller, sTsPrf);
1106	asRet += ['internal error: exception in __g_fnComXcptFormatter'];
1107
1108	# Now try format_exception_only:
1109	try:
1110	asRet += traceback.format_exception_only(oType, oXcpt);
1111	except:
1112	g_oReporter.log(0, '** internal-error: Hit exception #2 in format_exception_only! %s'
1113	% (traceback.format_exc()), sCaller, sTsPrf);
1114	asRet += ['internal error: Exception in format_exception_only!'];
1115	return asRet;
1116
1117
1118	def logXcptWorker(iLevel, fIncErrors, sPrefix="", sText=None, cFrames=1):
1119	"""
1120	Log an exception, optionally with a preceeding message and more than one
1121	call frame.
1122	"""
1123	g_oLock.acquire();
1124	try:
1125
1126	if fIncErrors:
1127	g_oReporter.testIncErrors();
1128
1129	## @todo skip all this if iLevel is too high!
1130
1131	# Try get exception info.
1132	sTsPrf = utils.getTimePrefix();
1133	try:
1134	oType, oValue, oTraceback = sys.exc_info();
1135	except:
1136	oType = oValue = oTraceback = None;
1137	if oType is not None:
1138
1139	# Try format the info
1140	try:
1141	rc = 0;
1142	sCaller = utils.getCallerName(oTraceback.tb_frame);
1143	if sText is not None:
1144	rc = g_oReporter.log(iLevel, "%s%s" % (sPrefix, sText), sCaller, sTsPrf);
1145	asInfo = None;
1146	try:
1147	asInfo = formatExceptionOnly(oType, oValue, sCaller, sTsPrf);
1148	if cFrames is not None and cFrames <= 1:
1149	asInfo = asInfo + traceback.format_tb(oTraceback, 1);
1150	else:
1151	asInfo.append('Traceback:')
1152	asInfo = asInfo + traceback.format_tb(oTraceback, cFrames);
1153	asInfo.append('Stack:')
1154	asInfo = asInfo + traceback.format_stack(oTraceback.tb_frame.f_back, cFrames);
1155	except:
1156	g_oReporter.log(0, '** internal-error: Hit exception #2! %s' % (traceback.format_exc()), sCaller, sTsPrf);
1157
1158	if asInfo:
1159	# Do the logging.
1160	for sItem in asInfo:
1161	asLines = sItem.splitlines();
1162	for sLine in asLines:
1163	rc = g_oReporter.log(iLevel, '%s%s' % (sPrefix, sLine), sCaller, sTsPrf);
1164
1165	else:
1166	g_oReporter.log(iLevel, 'No exception info...', sCaller, sTsPrf);
1167	rc = -3;
1168	except:
1169	g_oReporter.log(0, '** internal-error: Hit exception! %s' % (traceback.format_exc()), None, sTsPrf);
1170	rc = -2;
1171	else:
1172	g_oReporter.log(0, '** internal-error: No exception! %s'
1173	% (utils.getCallerName(iFrame=3)), utils.getCallerName(iFrame=3), sTsPrf);
1174	rc = -1;
1175
1176	finally:
1177	g_oLock.release();
1178	return rc;
1179
1180
1181	#
1182	# The public Classes
1183	#
1184	class FileWrapper(object):
1185	""" File like class for TXS EXEC and similar. """
1186	def __init__(self, sPrefix):
1187	self.sPrefix = sPrefix;
1188
1189	def __del__(self):
1190	self.close();
1191
1192	def close(self):
1193	""" file.close """
1194	# Nothing to be done.
1195	return;
1196
1197	def read(self, cb):
1198	"""file.read"""
1199	_ = cb;
1200	return "";
1201
1202	def write(self, sText):
1203	"""file.write"""
1204	if isinstance(sText, array.array):
1205	try:
1206	sText = sText.tostring();
1207	except:
1208	pass;
1209	g_oLock.acquire();
1210	try:
1211	sTsPrf = utils.getTimePrefix();
1212	sCaller = utils.getCallerName();
1213	asLines = sText.splitlines();
1214	for sLine in asLines:
1215	g_oReporter.log(0, '%s: %s' % (self.sPrefix, sLine), sCaller, sTsPrf);
1216	except:
1217	traceback.print_exc();
1218	finally:
1219	g_oLock.release();
1220	return None;
1221
1222	class FileWrapperTestPipe(object):
1223	""" File like class for the test pipe (TXS EXEC and similar). """
1224	def __init__(self):
1225	self.sPrefix = '';
1226	self.fStarted = False;
1227	self.fClosed = False;
1228	self.sTagBuffer = None;
1229
1230	def __del__(self):
1231	self.close();
1232
1233	def close(self):
1234	""" file.close """
1235	if self.fStarted is True and self.fClosed is False:
1236	self.fClosed = True;
1237	try: g_oReporter.subXmlEnd(self);
1238	except:
1239	try: traceback.print_exc();
1240	except: pass;
1241	return True;
1242
1243	def read(self, cb = None):
1244	"""file.read"""
1245	_ = cb;
1246	return "";
1247
1248	def write(self, sText):
1249	"""file.write"""
1250	# lazy start.
1251	if self.fStarted is not True:
1252	try:
1253	g_oReporter.subXmlStart(self);
1254	except:
1255	traceback.print_exc();
1256	self.fStarted = True;
1257
1258	# Turn non-string stuff into strings.
1259	if not utils.isString(sText):
1260	if isinstance(sText, array.array):
1261	try: sText = sText.tostring();
1262	except: pass;
1263	if not utils.isString(sText) and hasattr(sText, 'decode'):
1264	try: sText = sText.decode('utf-8', 'ignore');
1265	except: pass;
1266
1267	try:
1268	g_oReporter.subXmlWrite(self, sText, utils.getCallerName());
1269	# Parse the supplied text and look for <Failed.../> tags to keep track of the
1270	# error counter. This is only a very lazy aproach.
1271	sText.strip();
1272	idxText = 0;
1273	while sText:
1274	if self.sTagBuffer is None:
1275	# Look for the start of a tag.
1276	idxStart = sText[idxText:].find('<');
1277	if idxStart != -1:
1278	# Look for the end of the tag.
1279	idxEnd = sText[idxStart:].find('>');
1280
1281	# If the end was found inside the current buffer, parse the line,
1282	# else we have to save it for later.
1283	if idxEnd != -1:
1284	idxEnd += idxStart + 1;
1285	self._processXmlElement(sText[idxStart:idxEnd]);
1286	idxText = idxEnd;
1287	else:
1288	self.sTagBuffer = sText[idxStart:];
1289	idxText = len(sText);
1290	else:
1291	idxText = len(sText);
1292	else:
1293	# Search for the end of the tag and parse the whole tag.
1294	idxEnd = sText[idxText:].find('>');
1295	if idxEnd != -1:
1296	idxEnd += idxStart + 1;
1297	self._processXmlElement(self.sTagBuffer + sText[idxText:idxEnd]);
1298	self.sTagBuffer = None;
1299	idxText = idxEnd;
1300	else:
1301	self.sTagBuffer = self.sTagBuffer + sText[idxText:];
1302	idxText = len(sText);
1303
1304	sText = sText[idxText:];
1305	sText = sText.lstrip();
1306	except:
1307	traceback.print_exc();
1308	return None;
1309
1310	def _processXmlElement(self, sElement):
1311	"""
1312	Processes a complete XML tag (so far we only search for the Failed to tag
1313	to keep track of the error counter.
1314	"""
1315	# Make sure we don't parse any space between < and the element name.
1316	sElement = sElement.strip();
1317
1318	# Find the end of the name
1319	idxEndName = sElement.find(' ');
1320	if idxEndName == -1:
1321	idxEndName = sElement.find('/');
1322	if idxEndName == -1:
1323	idxEndName = sElement.find('>');
1324
1325	if idxEndName != -1:
1326	if sElement[1:idxEndName] == 'Failed':
1327	g_oLock.acquire();
1328	try:
1329	g_oReporter.testIncErrors();
1330	finally:
1331	g_oLock.release();
1332	else:
1333	error('_processXmlElement(%s)' % sElement);
1334
1335
1336	#
1337	# The public APIs.
1338	#
1339
1340	def log(sText):
1341	"""Writes the specfied text to the log."""
1342	g_oLock.acquire();
1343	try:
1344	rc = g_oReporter.log(1, sText, utils.getCallerName(), utils.getTimePrefix());
1345	except:
1346	rc = -1;
1347	finally:
1348	g_oLock.release();
1349	return rc;
1350
1351	def logXcpt(sText=None, cFrames=1):
1352	"""
1353	Log an exception, optionally with a preceeding message and more than one
1354	call frame.
1355	"""
1356	return logXcptWorker(1, False, "", sText, cFrames);
1357
1358	def log2(sText):
1359	"""Log level 2: Writes the specfied text to the log."""
1360	g_oLock.acquire();
1361	try:
1362	rc = g_oReporter.log(2, sText, utils.getCallerName(), utils.getTimePrefix());
1363	except:
1364	rc = -1;
1365	finally:
1366	g_oLock.release();
1367	return rc;
1368
1369	def log2Xcpt(sText=None, cFrames=1):
1370	"""
1371	Log level 2: Log an exception, optionally with a preceeding message and
1372	more than one call frame.
1373	"""
1374	return logXcptWorker(2, False, "", sText, cFrames);
1375
1376	def maybeErr(fIsError, sText):
1377	""" Maybe error or maybe normal log entry. """
1378	if fIsError is True:
1379	return error(sText);
1380	return log(sText);
1381
1382	def maybeErrXcpt(fIsError, sText=None, cFrames=1):
1383	""" Maybe error or maybe normal log exception entry. """
1384	if fIsError is True:
1385	return errorXcpt(sText, cFrames);
1386	return logXcpt(sText, cFrames);
1387
1388	def maybeLog(fIsNotError, sText):
1389	""" Maybe error or maybe normal log entry. """
1390	if fIsNotError is not True:
1391	return error(sText);
1392	return log(sText);
1393
1394	def maybeLogXcpt(fIsNotError, sText=None, cFrames=1):
1395	""" Maybe error or maybe normal log exception entry. """
1396	if fIsNotError is not True:
1397	return errorXcpt(sText, cFrames);
1398	return logXcpt(sText, cFrames);
1399
1400	def error(sText):
1401	"""
1402	Writes the specfied error message to the log.
1403
1404	This will add an error to the current test.
1405
1406	Always returns False for the convenience of methods returning boolean
1407	success indicators.
1408	"""
1409	g_oLock.acquire();
1410	try:
1411	g_oReporter.testIncErrors();
1412	g_oReporter.log(0, '** error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1413	except:
1414	pass;
1415	finally:
1416	g_oLock.release();
1417	return False;
1418
1419	def errorXcpt(sText=None, cFrames=1):
1420	"""
1421	Log an error caused by an exception. If sText is given, it will preceed
1422	the exception information. cFrames can be used to display more stack.
1423
1424	This will add an error to the current test.
1425
1426	Always returns False for the convenience of methods returning boolean
1427	success indicators.
1428	"""
1429	logXcptWorker(0, True, '** error: ', sText, cFrames);
1430	return False;
1431
1432	def errorTimeout(sText):
1433	"""
1434	Flags the current test as having timed out and writes the specified message to the log.
1435
1436	This will add an error to the current test.
1437
1438	Always returns False for the convenience of methods returning boolean
1439	success indicators.
1440	"""
1441	g_oLock.acquire();
1442	try:
1443	g_oReporter.testSetTimedOut();
1444	g_oReporter.log(0, '** timeout-error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1445	except:
1446	pass;
1447	finally:
1448	g_oLock.release();
1449	return False;
1450
1451	def fatal(sText):
1452	"""
1453	Writes a fatal error to the log.
1454
1455	This will add an error to the current test.
1456
1457	Always returns False for the convenience of methods returning boolean
1458	success indicators.
1459	"""
1460	g_oLock.acquire();
1461	try:
1462	g_oReporter.testIncErrors();
1463	g_oReporter.log(0, '** fatal error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1464	except:
1465	pass
1466	finally:
1467	g_oLock.release();
1468	return False;
1469
1470	def fatalXcpt(sText=None, cFrames=1):
1471	"""
1472	Log a fatal error caused by an exception. If sText is given, it will
1473	preceed the exception information. cFrames can be used to display more
1474	stack.
1475
1476	This will add an error to the current test.
1477
1478	Always returns False for the convenience of methods returning boolean
1479	success indicators.
1480	"""
1481	logXcptWorker(0, True, "** fatal error: ", sText, cFrames);
1482	return False;
1483
1484	def addLogFile(sFilename, sKind, sDescription = '', sAltName = None):
1485	"""
1486	Adds the specified log file to the report if the file exists.
1487
1488	The sDescription is a free form description of the log file.
1489
1490	The sKind parameter is for adding some machine parsable hint what kind of
1491	log file this really is.
1492
1493	Returns True on success, False on failure (no ENOENT errors are logged).
1494	"""
1495	sTsPrf = utils.getTimePrefix();
1496	sCaller = utils.getCallerName();
1497	fRc = False;
1498	if sAltName is None:
1499	sAltName = sFilename;
1500
1501	try:
1502	oSrcFile = utils.openNoInherit(sFilename, 'rb');
1503	except IOError as oXcpt:
1504	if oXcpt.errno != errno.ENOENT:
1505	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1506	else:
1507	logXcpt('addLogFile(%s,%s,%s) IOError' % (sFilename, sDescription, sKind));
1508	except:
1509	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1510	else:
1511	g_oLock.acquire();
1512	try:
1513	fRc = g_oReporter.addLogFile(oSrcFile, sFilename, sAltName, sDescription, sKind, sCaller, sTsPrf);
1514	finally:
1515	g_oLock.release();
1516	oSrcFile.close();
1517	return fRc;
1518
1519	def addLogString(sLog, sLogName, sKind, sDescription = ''):
1520	"""
1521	Adds the specified log string to the report.
1522
1523	The sLog parameter sets the name of the log file.
1524
1525	The sDescription is a free form description of the log file.
1526
1527	The sKind parameter is for adding some machine parsable hint what kind of
1528	log file this really is.
1529
1530	Returns True on success, False on failure (no ENOENT errors are logged).
1531	"""
1532	sTsPrf = utils.getTimePrefix();
1533	sCaller = utils.getCallerName();
1534	fRc = False;
1535
1536	g_oLock.acquire();
1537	try:
1538	fRc = g_oReporter.addLogString(sLog, sLogName, sDescription, sKind, sCaller, sTsPrf);
1539	finally:
1540	g_oLock.release();
1541	return fRc;
1542
1543	def isLocal():
1544	"""Is this a local reporter?"""
1545	return g_oReporter.isLocal()
1546
1547	def incVerbosity():
1548	"""Increases the verbosity level."""
1549	return g_oReporter.incVerbosity()
1550
1551	def incDebug():
1552	"""Increases the debug level."""
1553	return g_oReporter.incDebug()
1554
1555	def appendToProcessName(sAppend):
1556	"""
1557	Appends sAppend to the base process name.
1558	Returns the new process name.
1559	"""
1560	return g_oReporter.appendToProcessName(sAppend);
1561
1562	def getErrorCount():
1563	"""
1564	Get the current error count for the entire test run.
1565	"""
1566	g_oLock.acquire();
1567	try:
1568	cErrors = g_oReporter.cErrors;
1569	finally:
1570	g_oLock.release();
1571	return cErrors;
1572
1573	def doPollWork(sDebug = None):
1574	"""
1575	This can be called from wait loops and similar to make the reporter call
1576	home with pending XML and such.
1577	"""
1578	g_oReporter.doPollWork(sDebug);
1579	return None;
1580
1581
1582	#
1583	# Test reporting, a bit similar to RTTestI*.
1584	#
1585
1586	def testStart(sName):
1587	"""
1588	Starts a new test (pushes it).
1589	"""
1590	g_oLock.acquire();
1591	try:
1592	rc = g_oReporter.testStart(sName, utils.getCallerName());
1593	finally:
1594	g_oLock.release();
1595	return rc;
1596
1597	def testValue(sName, sValue, sUnit):
1598	"""
1599	Reports a benchmark value or something simiarlly useful.
1600	"""
1601	g_oLock.acquire();
1602	try:
1603	rc = g_oReporter.testValue(sName, str(sValue), sUnit, utils.getCallerName());
1604	finally:
1605	g_oLock.release();
1606	return rc;
1607
1608	def testFailure(sDetails):
1609	"""
1610	Reports a failure.
1611	We count these calls and testDone will use them to report PASSED or FAILED.
1612
1613	Returns False so that a return False line can be saved.
1614	"""
1615	g_oLock.acquire();
1616	try:
1617	g_oReporter.testFailure(sDetails, utils.getCallerName());
1618	finally:
1619	g_oLock.release();
1620	return False;
1621
1622	def testFailureXcpt(sDetails = ''):
1623	"""
1624	Reports a failure with exception.
1625	We count these calls and testDone will use them to report PASSED or FAILED.
1626
1627	Returns False so that a return False line can be saved.
1628	"""
1629	# Extract exception info.
1630	try:
1631	oType, oValue, oTraceback = sys.exc_info();
1632	except:
1633	oType = oValue, oTraceback = None;
1634	if oType is not None:
1635	sCaller = utils.getCallerName(oTraceback.tb_frame);
1636	sXcpt = ' '.join(formatExceptionOnly(oType, oValue, sCaller, utils.getTimePrefix()));
1637	else:
1638	sCaller = utils.getCallerName();
1639	sXcpt = 'No exception at %s' % (sCaller,);
1640
1641	# Use testFailure to do the work.
1642	g_oLock.acquire();
1643	try:
1644	if sDetails == '':
1645	g_oReporter.testFailure('Exception: %s' % (sXcpt,), sCaller);
1646	else:
1647	g_oReporter.testFailure('%s: %s' % (sDetails, sXcpt), sCaller);
1648	finally:
1649	g_oLock.release();
1650	return False;
1651
1652	def testDone(fSkipped = False):
1653	"""
1654	Completes the current test (pops it), logging PASSED / FAILURE.
1655
1656	Returns a tuple with the name of the test and its error count.
1657	"""
1658	g_oLock.acquire();
1659	try:
1660	rc = g_oReporter.testDone(fSkipped, utils.getCallerName());
1661	finally:
1662	g_oLock.release();
1663	return rc;
1664
1665	def testErrorCount():
1666	"""
1667	Gets the error count of the current test.
1668
1669	Returns the number of errors.
1670	"""
1671	g_oLock.acquire();
1672	try:
1673	cErrors = g_oReporter.testErrorCount();
1674	finally:
1675	g_oLock.release();
1676	return cErrors;
1677
1678	def testCleanup():
1679	"""
1680	Closes all open tests with a generic error condition.
1681
1682	Returns True if no open tests, False if something had to be closed with failure.
1683	"""
1684	g_oLock.acquire();
1685	try:
1686	fRc = g_oReporter.testCleanup(utils.getCallerName());
1687	g_oReporter.xmlFlush(fRetry = False, fForce = True);
1688	finally:
1689	g_oLock.release();
1690	return fRc;
1691
1692
1693	#
1694	# Sub XML stuff.
1695	#
1696
1697	def addSubXmlFile(sFilename):
1698	"""
1699	Adds a sub-xml result file to the party.
1700	"""
1701	fRc = False;
1702	try:
1703	oSrcFile = utils.openNoInherit(sFilename, 'r');
1704	except IOError as oXcpt:
1705	if oXcpt.errno != errno.ENOENT:
1706	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1707	except:
1708	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1709	else:
1710	try:
1711	oWrapper = FileWrapperTestPipe()
1712	oWrapper.write(oSrcFile.read());
1713	oWrapper.close();
1714	except:
1715	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1716	oSrcFile.close();
1717
1718	return fRc;
1719
1720
1721	#
1722	# Other useful debugging tools.
1723	#
1724
1725	def logAllStacks(cFrames = None):
1726	"""
1727	Logs the stacks of all python threads.
1728	"""
1729	sTsPrf = utils.getTimePrefix();
1730	sCaller = utils.getCallerName();
1731	g_oLock.acquire();
1732
1733	cThread = 0;
1734	for idThread, oStack in sys._current_frames().items(): # >=2.5, a bit ugly - pylint: disable=protected-access
1735	try:
1736	if cThread > 0:
1737	g_oReporter.log(1, '', sCaller, sTsPrf);
1738	g_oReporter.log(1, 'Thread %s (%#x)' % (idThread, idThread), sCaller, sTsPrf);
1739	try:
1740	asInfo = traceback.format_stack(oStack, cFrames);
1741	except:
1742	g_oReporter.log(1, ' Stack formatting failed w/ exception', sCaller, sTsPrf);
1743	else:
1744	for sInfo in asInfo:
1745	asLines = sInfo.splitlines();
1746	for sLine in asLines:
1747	g_oReporter.log(1, sLine, sCaller, sTsPrf);
1748	except:
1749	pass;
1750	cThread += 1;
1751
1752	g_oLock.release();
1753	return None;
1754
1755	def checkTestManagerConnection():
1756	"""
1757	Checks the connection to the test manager.
1758
1759	Returns True if the connection is fine, False if not, None if not remote
1760	reporter.
1761
1762	Note! This as the sideeffect of flushing XML.
1763	"""
1764	g_oLock.acquire();
1765	try:
1766	fRc = g_oReporter.xmlFlush(fRetry = False, fForce = True);
1767	finally:
1768	g_oLock.release();
1769	return fRc;
1770
1771	def flushall(fSkipXml = False):
1772	"""
1773	Flushes all output streams, both standard and logger related.
1774	This may also push data to the remote test manager.
1775	"""
1776	try: sys.stdout.flush();
1777	except: pass;
1778	try: sys.stderr.flush();
1779	except: pass;
1780
1781	if fSkipXml is not True:
1782	g_oLock.acquire();
1783	try:
1784	g_oReporter.xmlFlush(fRetry = False);
1785	finally:
1786	g_oLock.release();
1787
1788	return True;
1789
1790
1791	#
1792	# Module initialization.
1793	#
1794
1795	def _InitReporterModule():
1796	"""
1797	Instantiate the test reporter.
1798	"""
1799	global g_oReporter, g_sReporterName
1800
1801	g_sReporterName = os.getenv("TESTBOX_REPORTER", "local");
1802	if g_sReporterName == "local":
1803	g_oReporter = LocalReporter();
1804	elif g_sReporterName == "remote":
1805	g_oReporter = RemoteReporter(); # Correct, but still plain stupid. pylint: disable=redefined-variable-type
1806	else:
1807	print(os.path.basename(__file__) + ": Unknown TESTBOX_REPORTER value: '" + g_sReporterName + "'", file = sys.stderr);
1808	raise Exception("Unknown TESTBOX_REPORTER value '" + g_sReporterName + "'");
1809
1810	if __name__ != "checker": # pychecker avoidance.
1811	_InitReporterModule();

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

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

Download in other formats: