reporter.py@ 70517

Last change on this file since 70517 was 70517, checked in by vboxsync, 7 years ago
testdriver: More python 3 adjustments.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 58.8 KB

Line
1	# -- coding: utf-8 --
2	# $Id: reporter.py 70517 2018-01-10 14:14:45Z 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: 70517 $"
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, 0x1e8); # 0750 = 0x1e8
396	except:
397	sLogDir = self.sDefLogDir;
398	if not os.path.isdir(sLogDir):
399	os.makedirs(sLogDir, 0x1e8); # 0750 = 0x1e8
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, 0x1e8); # 0750 = 0x1e8
408	except:
409	self.sLogDir = '%s-%s' % (self.sLogDir, os.getpid());
410	os.makedirs(self.sLogDir, 0x1e8); # 0750 = 0x1e8
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	import urlparse;
661	import httplib;
662	import urllib;
663	from common import constants;
664
665	self._fnUrlEncode = urllib.urlencode;
666	self._fnUrlParseQs = urlparse.parse_qs;
667	self._oParsedTmUrl = urlparse.urlparse(self.sTestManagerUrl);
668
669	if sys.version_info[0] >= 3 \
670	or (sys.version_info[0] == 2 and sys.version_info[1] >= 6):
671	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=E1101
672	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname,
673	timeout = self.kcSecTestManagerRequestTimeout);
674	else:
675	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname,
676	timeout = self.kcSecTestManagerRequestTimeout);
677	else:
678	if self._oParsedTmUrl.scheme == 'https': # pylint: disable=E1101
679	self._fnTmConnect = lambda: httplib.HTTPSConnection(self._oParsedTmUrl.hostname);
680	else:
681	self._fnTmConnect = lambda: httplib.HTTPConnection( self._oParsedTmUrl.hostname);
682	self._dHttpHeader = \
683	{
684	'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8',
685	'User-Agent': 'TestDriverReporter/%s.0 (%s, %s)' % (__version__, utils.getHostOs(), utils.getHostArch(),),
686	'Accept': 'text/plain,application/x-www-form-urlencoded',
687	'Accept-Encoding': 'identity',
688	'Cache-Control': 'max-age=0',
689	#'Connection': 'keep-alive',
690	};
691
692	dParams = {
693	constants.tbreq.ALL_PARAM_TESTBOX_UUID: self.sTestBoxUuid,
694	constants.tbreq.ALL_PARAM_TESTBOX_ID: self.idTestBox,
695	constants.tbreq.RESULT_PARAM_TEST_SET_ID: self.idTestSet,
696	};
697	self._sTmServerPath = '/%s/testboxdisp.py?%s' \
698	% ( self._oParsedTmUrl.path.strip('/'), # pylint: disable=E1101
699	urllib.urlencode(dParams), );
700
701	def __del__(self):
702	"""Flush pending log messages?"""
703	if self._asXml:
704	self._xmlDoFlush(self._asXml, fRetry = True, fDtor = True);
705
706	def _writeOutput(self, sText):
707	""" Does the actual writing and flushing. """
708	print(sText.encode('ascii', 'replace'), file = self.oOutput);
709	if self.fFlushEachLine: self.oOutput.flush();
710	return None;
711
712	#
713	# Talking to TM.
714	#
715
716	def _processTmStatusResponse(self, oConn, sOperation, fClose = True):
717	"""
718	Processes HTTP reponse from the test manager.
719	Returns True, False or None. None should be retried, the others not.
720	May raise exception on HTTP issue (retry ok).
721	"""
722	import httplib;
723	from common import constants;
724
725	# Read the response and (optionally) close the connection.
726	oResponse = oConn.getresponse();
727	try:
728	sRspBody = oResponse.read();
729	except httplib.IncompleteRead as oXcpt:
730	self._writeOutput('%s: %s: Warning: httplib.IncompleteRead: %s [expected %s, got %s]'
731	% (utils.getTimePrefix(), sOperation, oXcpt, oXcpt.expected, len(oXcpt.partial),));
732	sRspBody = oXcpt.partial;
733	if fClose is True:
734	try: oConn.close();
735	except: pass;
736
737	# Check the content type.
738	sContentType = oResponse.getheader('Content-Type');
739	if sContentType is not None and sContentType == 'application/x-www-form-urlencoded; charset=utf-8':
740
741	# Parse the body and check the RESULT parameter.
742	dResponse = self._fnUrlParseQs(sRspBody, strict_parsing = True);
743	sResult = dResponse.get(constants.tbresp.ALL_PARAM_RESULT, None);
744	if isinstance(sResult, list):
745	sResult = sResult[0] if len(sResult) == 1 else '%d results' % (len(sResult),);
746
747	if sResult is not None:
748	if sResult == constants.tbresp.STATUS_ACK:
749	return True;
750	if sResult == constants.tbresp.STATUS_NACK:
751	self._writeOutput('%s: %s: Failed (%s). (dResponse=%s)'
752	% (utils.getTimePrefix(), sOperation, sResult, dResponse,));
753	return False;
754
755	self._writeOutput('%s: %s: Failed - dResponse=%s' % (utils.getTimePrefix(), sOperation, dResponse,));
756	else:
757	self._writeOutput('%s: %s: Unexpected Content-Type: %s' % (utils.getTimePrefix(), sOperation, sContentType,));
758	self._writeOutput('%s: %s: Body: %s' % (utils.getTimePrefix(), sOperation, sRspBody,));
759	return None;
760
761	def _doUploadFile(self, oSrcFile, sSrcFilename, sDescription, sKind, sMime):
762	""" Uploads the given file to the test manager. """
763
764	# Prepare header and url.
765	dHeader = dict(self._dHttpHeader);
766	dHeader['Content-Type'] = 'application/octet-stream';
767	self._writeOutput('%s: _doUploadFile: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
768	oSrcFile.seek(0, 2);
769	self._writeOutput('%s: _doUploadFile: size=%d' % (utils.getTimePrefix(), oSrcFile.tell(),));
770	oSrcFile.seek(0);
771
772	from common import constants;
773	sUrl = self._sTmServerPath + '&' \
774	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcFilename),
775	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
776	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
777	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
778	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
779	});
780
781	# Retry loop.
782	secStart = utils.timestampSecond();
783	while True:
784	try:
785	oConn = self._fnTmConnect();
786	oConn.request('POST', sUrl, oSrcFile.read(), dHeader);
787	fRc = self._processTmStatusResponse(oConn, '_doUploadFile', fClose = True);
788	oConn.close();
789	if fRc is not None:
790	return fRc;
791	except:
792	logXcpt('warning: exception during UPLOAD request');
793
794	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
795	self._writeOutput('%s: _doUploadFile: Timed out.' % (utils.getTimePrefix(),));
796	break;
797	try: oSrcFile.seek(0);
798	except:
799	logXcpt();
800	break;
801	self._writeOutput('%s: _doUploadFile: Retrying...' % (utils.getTimePrefix(), ));
802	time.sleep(2);
803
804	return False;
805
806	def _doUploadString(self, sSrc, sSrcName, sDescription, sKind, sMime):
807	""" Uploads the given string as a separate file to the test manager. """
808
809	# Prepare header and url.
810	dHeader = dict(self._dHttpHeader);
811	dHeader['Content-Type'] = 'application/octet-stream';
812	self._writeOutput('%s: _doUploadString: sHeader=%s' % (utils.getTimePrefix(), dHeader,));
813	self._writeOutput('%s: _doUploadString: size=%d' % (utils.getTimePrefix(), sys.getsizeof(sSrc),));
814
815	from common import constants;
816	sUrl = self._sTmServerPath + '&' \
817	+ self._fnUrlEncode({ constants.tbreq.UPLOAD_PARAM_NAME: os.path.basename(sSrcName),
818	constants.tbreq.UPLOAD_PARAM_DESC: sDescription,
819	constants.tbreq.UPLOAD_PARAM_KIND: sKind,
820	constants.tbreq.UPLOAD_PARAM_MIME: sMime,
821	constants.tbreq.ALL_PARAM_ACTION: constants.tbreq.UPLOAD,
822	});
823
824	# Retry loop.
825	secStart = utils.timestampSecond();
826	while True:
827	try:
828	oConn = self._fnTmConnect();
829	oConn.request('POST', sUrl, sSrc, dHeader);
830	fRc = self._processTmStatusResponse(oConn, '_doUploadString', fClose = True);
831	oConn.close();
832	if fRc is not None:
833	return fRc;
834	except:
835	logXcpt('warning: exception during UPLOAD request');
836
837	if utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
838	self._writeOutput('%s: _doUploadString: Timed out.' % (utils.getTimePrefix(),));
839	break;
840	self._writeOutput('%s: _doUploadString: Retrying...' % (utils.getTimePrefix(), ));
841	time.sleep(2);
842
843	return False;
844
845	def _xmlDoFlush(self, asXml, fRetry = False, fDtor = False):
846	"""
847	The code that does the actual talking to the server.
848	Used by both xmlFlush and __del__.
849	"""
850	secStart = utils.timestampSecond();
851	while True:
852	fRc = None;
853	try:
854	# Post.
855	from common import constants;
856	sPostBody = self._fnUrlEncode({constants.tbreq.XML_RESULT_PARAM_BODY: '\n'.join(asXml),});
857	oConn = self._fnTmConnect();
858	oConn.request('POST',
859	self._sTmServerPath + ('&%s=%s' % (constants.tbreq.ALL_PARAM_ACTION, constants.tbreq.XML_RESULTS)),
860	sPostBody,
861	self._dHttpHeader);
862
863	fRc = self._processTmStatusResponse(oConn, '_xmlDoFlush', fClose = True);
864	if fRc is True:
865	if self.fDebugXml:
866	self._writeOutput('_xmlDoFlush:\n%s' % ('\n'.join(asXml),));
867	return (None, False);
868	if fRc is False:
869	self._writeOutput('_xmlDoFlush: Failed - we should abort the test, really.');
870	return (None, True);
871	except Exception as oXcpt:
872	if not fDtor:
873	logXcpt('warning: exception during XML_RESULTS request');
874	else:
875	self._writeOutput('warning: exception during XML_RESULTS request: %s' % (oXcpt,));
876
877	if fRetry is not True \
878	or utils.timestampSecond() - secStart >= self.kcSecTestManagerRetryTimeout:
879	break;
880	time.sleep(2);
881
882	return (asXml, False);
883
884
885	#
886	# Overridden methods.
887	#
888
889	def isLocal(self):
890	return False;
891
892	def log(self, iLevel, sText, sCaller, sTsPrf):
893	if iLevel <= self.iVerbose:
894	if self.iDebug > 0:
895	sLogText = '%s %30s: %s' % (sTsPrf, sCaller, sText);
896	else:
897	sLogText = '%s %s: %s' % (sTsPrf, self.sName, sText);
898	self._writeOutput(sLogText);
899	return 0;
900
901	def addLogFile(self, oSrcFile, sSrcFilename, sAltName, sDescription, sKind, sCaller, sTsPrf):
902	fRc = True;
903	if sKind in [ 'text', 'log', 'process'] \
904	or sKind.startswith('log/') \
905	or sKind.startswith('info/') \
906	or sKind.startswith('process/'):
907	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
908	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
909	self.xmlFlush();
910	g_oLock.release();
911	try:
912	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'text/plain');
913	finally:
914	g_oLock.acquire();
915	elif sKind.startswith('screenshot/'):
916	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
917	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
918	self.xmlFlush();
919	g_oLock.release();
920	try:
921	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'image/png');
922	finally:
923	g_oLock.acquire();
924	elif sKind.startswith('misc/'):
925	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
926	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
927	self.xmlFlush();
928	g_oLock.release();
929	try:
930	self._doUploadFile(oSrcFile, sAltName, sDescription, sKind, 'application/octet-stream');
931	finally:
932	g_oLock.acquire();
933	else:
934	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
935	% (sSrcFilename, sKind, sDescription), sCaller, sTsPrf);
936	return fRc;
937
938	def addLogString(self, sLog, sLogName, sDescription, sKind, sCaller, sTsPrf):
939	fRc = True;
940	if sKind in [ 'text', 'log', 'process'] \
941	or sKind.startswith('log/') \
942	or sKind.startswith('info/') \
943	or sKind.startswith('process/'):
944	self.log(0, '* Uploading "%s" - KIND: "%s" - DESC: "%s" *'
945	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
946	self.xmlFlush();
947	g_oLock.release();
948	try:
949	self._doUploadString(sLog, sLogName, sDescription, sKind, 'text/plain');
950	finally:
951	g_oLock.acquire();
952	else:
953	self.log(0, '* UNKNOWN FILE "%s" - KIND "%s" - DESC "%s" *'
954	% (sLogName, sKind, sDescription), sCaller, sTsPrf);
955	return fRc;
956
957	def xmlFlush(self, fRetry = False, fForce = False):
958	"""
959	Flushes the XML back log. Called with the lock held, may leave it
960	while communicating with the server.
961	"""
962	if not self._fXmlFlushing:
963	asXml = self._asXml;
964	self._asXml = [];
965	if asXml or fForce is True:
966	self._fXmlFlushing = True;
967
968	g_oLock.release();
969	try:
970	(asXml, fIncErrors) = self._xmlDoFlush(asXml, fRetry = fRetry);
971	finally:
972	g_oLock.acquire();
973
974	if fIncErrors:
975	self.testIncErrors();
976
977	self._fXmlFlushing = False;
978	if asXml is None:
979	self._secTsXmlFlush = utils.timestampSecond();
980	else:
981	self._asXml = asXml + self._asXml;
982	return True;
983
984	self._secTsXmlFlush = utils.timestampSecond();
985	return False;
986
987	def _xmlFlushIfNecessary(self, fPolling = False, sDebug = None):
988	"""Flushes the XML back log if necessary."""
989	tsNow = utils.timestampSecond();
990	cSecs = tsNow - self._secTsXmlFlush;
991	cSecsLast = tsNow - self._secTsXmlLast;
992	if fPolling is not True:
993	self._secTsXmlLast = tsNow;
994
995	# Absolute flush thresholds.
996	if cSecs >= self.kcSecXmlFlushMax:
997	return self.xmlFlush();
998	if len(self._asXml) >= self.kcLinesXmlFlush:
999	return self.xmlFlush();
1000
1001	# Flush if idle long enough.
1002	if cSecs >= self.kcSecXmlFlushMin \
1003	and cSecsLast >= self.kcSecXmlFlushIdle:
1004	return self.xmlFlush();
1005
1006	_ = sDebug;
1007	return False;
1008
1009	def _xmlWrite(self, asText, fIndent = True):
1010	"""XML output function for the reporter."""
1011	self._asXml += asText;
1012	self._xmlFlushIfNecessary();
1013	_ = fIndent; # No pretty printing, thank you.
1014	return None;
1015
1016	def subXmlStart(self, oFileWrapper):
1017	oFileWrapper.sXmlBuffer = '';
1018	return None;
1019
1020	def subXmlWrite(self, oFileWrapper, sRawXml, sCaller):
1021	oFileWrapper.sXmlBuffer += sRawXml;
1022	_ = sCaller;
1023	return None;
1024
1025	def subXmlEnd(self, oFileWrapper):
1026	sRawXml = oFileWrapper.sXmlBuffer;
1027	## @todo should validate the document here and maybe auto terminate things. Adding some hints to have the server do
1028	# this instead.
1029	g_oLock.acquire();
1030	try:
1031	self._asXml += [ '<PushHint testdepth="%d"/>' % (len(self.atTests),),
1032	sRawXml,
1033	'<PopHint testdepth="%d"/>' % (len(self.atTests),),];
1034	self._xmlFlushIfNecessary();
1035	finally:
1036	g_oLock.release();
1037	return None;
1038
1039	def doPollWork(self, sDebug = None):
1040	if self._asXml:
1041	g_oLock.acquire();
1042	try:
1043	self._xmlFlushIfNecessary(fPolling = True, sDebug = sDebug);
1044	finally:
1045	g_oLock.release();
1046	return None;
1047
1048
1049	#
1050	# Helpers
1051	#
1052
1053	def logXcptWorker(iLevel, fIncErrors, sPrefix="", sText=None, cFrames=1):
1054	"""
1055	Log an exception, optionally with a preceeding message and more than one
1056	call frame.
1057	"""
1058	g_oLock.acquire();
1059	try:
1060
1061	if fIncErrors:
1062	g_oReporter.testIncErrors();
1063
1064	## @todo skip all this if iLevel is too high!
1065
1066	# Try get exception info.
1067	sTsPrf = utils.getTimePrefix();
1068	try:
1069	oType, oValue, oTraceback = sys.exc_info();
1070	except:
1071	oType = oValue = oTraceback = None;
1072	if oType is not None:
1073
1074	# Try format the info
1075	try:
1076	rc = 0;
1077	sCaller = utils.getCallerName(oTraceback.tb_frame);
1078	if sText is not None:
1079	rc = g_oReporter.log(iLevel, "%s%s" % (sPrefix, sText), sCaller, sTsPrf);
1080	asInfo = [];
1081	try:
1082	asInfo = asInfo + traceback.format_exception_only(oType, oValue);
1083	if cFrames is not None and cFrames <= 1:
1084	asInfo = asInfo + traceback.format_tb(oTraceback, 1);
1085	else:
1086	asInfo.append('Traceback:')
1087	asInfo = asInfo + traceback.format_tb(oTraceback, cFrames);
1088	asInfo.append('Stack:')
1089	asInfo = asInfo + traceback.format_stack(oTraceback.tb_frame.f_back, cFrames);
1090	except:
1091	g_oReporter.log(0, '** internal-error: Hit exception #2! %s' % (traceback.format_exc()), sCaller, sTsPrf);
1092
1093	if asInfo:
1094	# Do the logging.
1095	for sItem in asInfo:
1096	asLines = sItem.splitlines();
1097	for sLine in asLines:
1098	rc = g_oReporter.log(iLevel, '%s%s' % (sPrefix, sLine), sCaller, sTsPrf);
1099
1100	else:
1101	g_oReporter.log(iLevel, 'No exception info...', sCaller, sTsPrf);
1102	rc = -3;
1103	except:
1104	g_oReporter.log(0, '** internal-error: Hit exception! %s' % (traceback.format_exc()), None, sTsPrf);
1105	rc = -2;
1106	else:
1107	g_oReporter.log(0, '** internal-error: No exception! %s'
1108	% (utils.getCallerName(iFrame=3)), utils.getCallerName(iFrame=3), sTsPrf);
1109	rc = -1;
1110
1111	finally:
1112	g_oLock.release();
1113	return rc;
1114
1115	#
1116	# The public Classes
1117	#
1118	class FileWrapper(object):
1119	""" File like class for TXS EXEC and similar. """
1120	def __init__(self, sPrefix):
1121	self.sPrefix = sPrefix;
1122
1123	def __del__(self):
1124	self.close();
1125
1126	def close(self):
1127	""" file.close """
1128	# Nothing to be done.
1129	return;
1130
1131	def read(self, cb):
1132	"""file.read"""
1133	_ = cb;
1134	return "";
1135
1136	def write(self, sText):
1137	"""file.write"""
1138	if isinstance(sText, array.array):
1139	try:
1140	sText = sText.tostring();
1141	except:
1142	pass;
1143	g_oLock.acquire();
1144	try:
1145	sTsPrf = utils.getTimePrefix();
1146	sCaller = utils.getCallerName();
1147	asLines = sText.splitlines();
1148	for sLine in asLines:
1149	g_oReporter.log(0, '%s: %s' % (self.sPrefix, sLine), sCaller, sTsPrf);
1150	except:
1151	traceback.print_exc();
1152	finally:
1153	g_oLock.release();
1154	return None;
1155
1156	class FileWrapperTestPipe(object):
1157	""" File like class for the test pipe (TXS EXEC and similar). """
1158	def __init__(self):
1159	self.sPrefix = '';
1160	self.fStarted = False;
1161	self.fClosed = False;
1162	self.sTagBuffer = None;
1163
1164	def __del__(self):
1165	self.close();
1166
1167	def close(self):
1168	""" file.close """
1169	if self.fStarted is True and self.fClosed is False:
1170	self.fClosed = True;
1171	try: g_oReporter.subXmlEnd(self);
1172	except:
1173	try: traceback.print_exc();
1174	except: pass;
1175	return True;
1176
1177	def read(self, cb = None):
1178	"""file.read"""
1179	_ = cb;
1180	return "";
1181
1182	def write(self, sText):
1183	"""file.write"""
1184	# lazy start.
1185	if self.fStarted is not True:
1186	try:
1187	g_oReporter.subXmlStart(self);
1188	except:
1189	traceback.print_exc();
1190	self.fStarted = True;
1191
1192	if isinstance(sText, array.array):
1193	try:
1194	sText = sText.tostring();
1195	except:
1196	pass;
1197	try:
1198	g_oReporter.subXmlWrite(self, sText, utils.getCallerName());
1199	# Parse the supplied text and look for <Failed.../> tags to keep track of the
1200	# error counter. This is only a very lazy aproach.
1201	sText.strip();
1202	idxText = 0;
1203	while sText:
1204	if self.sTagBuffer is None:
1205	# Look for the start of a tag.
1206	idxStart = sText[idxText:].find('<');
1207	if idxStart != -1:
1208	# Look for the end of the tag.
1209	idxEnd = sText[idxStart:].find('>');
1210
1211	# If the end was found inside the current buffer, parse the line,
1212	# else we have to save it for later.
1213	if idxEnd != -1:
1214	idxEnd += idxStart + 1;
1215	self._processXmlElement(sText[idxStart:idxEnd]);
1216	idxText = idxEnd;
1217	else:
1218	self.sTagBuffer = sText[idxStart:];
1219	idxText = len(sText);
1220	else:
1221	idxText = len(sText);
1222	else:
1223	# Search for the end of the tag and parse the whole tag.
1224	idxEnd = sText[idxText:].find('>');
1225	if idxEnd != -1:
1226	idxEnd += idxStart + 1;
1227	self._processXmlElement(self.sTagBuffer + sText[idxText:idxEnd]);
1228	self.sTagBuffer = None;
1229	idxText = idxEnd;
1230	else:
1231	self.sTagBuffer = self.sTagBuffer + sText[idxText:];
1232	idxText = len(sText);
1233
1234	sText = sText[idxText:];
1235	sText = sText.lstrip();
1236	except:
1237	traceback.print_exc();
1238	return None;
1239
1240	def _processXmlElement(self, sElement):
1241	"""
1242	Processes a complete XML tag (so far we only search for the Failed to tag
1243	to keep track of the error counter.
1244	"""
1245	# Make sure we don't parse any space between < and the element name.
1246	sElement = sElement.strip();
1247
1248	# Find the end of the name
1249	idxEndName = sElement.find(' ');
1250	if idxEndName == -1:
1251	idxEndName = sElement.find('/');
1252	if idxEndName == -1:
1253	idxEndName = sElement.find('>');
1254
1255	if idxEndName != -1:
1256	if sElement[1:idxEndName] == 'Failed':
1257	g_oLock.acquire();
1258	try:
1259	g_oReporter.testIncErrors();
1260	finally:
1261	g_oLock.release();
1262	else:
1263	error('_processXmlElement(%s)' % sElement);
1264
1265
1266	#
1267	# The public APIs.
1268	#
1269
1270	def log(sText):
1271	"""Writes the specfied text to the log."""
1272	g_oLock.acquire();
1273	try:
1274	rc = g_oReporter.log(1, sText, utils.getCallerName(), utils.getTimePrefix());
1275	except:
1276	rc = -1;
1277	finally:
1278	g_oLock.release();
1279	return rc;
1280
1281	def logXcpt(sText=None, cFrames=1):
1282	"""
1283	Log an exception, optionally with a preceeding message and more than one
1284	call frame.
1285	"""
1286	return logXcptWorker(1, False, "", sText, cFrames);
1287
1288	def log2(sText):
1289	"""Log level 2: Writes the specfied text to the log."""
1290	g_oLock.acquire();
1291	try:
1292	rc = g_oReporter.log(2, sText, utils.getCallerName(), utils.getTimePrefix());
1293	except:
1294	rc = -1;
1295	finally:
1296	g_oLock.release();
1297	return rc;
1298
1299	def log2Xcpt(sText=None, cFrames=1):
1300	"""
1301	Log level 2: Log an exception, optionally with a preceeding message and
1302	more than one call frame.
1303	"""
1304	return logXcptWorker(2, False, "", sText, cFrames);
1305
1306	def maybeErr(fIsError, sText):
1307	""" Maybe error or maybe normal log entry. """
1308	if fIsError is True:
1309	return error(sText);
1310	return log(sText);
1311
1312	def maybeErrXcpt(fIsError, sText=None, cFrames=1):
1313	""" Maybe error or maybe normal log exception entry. """
1314	if fIsError is True:
1315	return errorXcpt(sText, cFrames);
1316	return logXcpt(sText, cFrames);
1317
1318	def maybeLog(fIsNotError, sText):
1319	""" Maybe error or maybe normal log entry. """
1320	if fIsNotError is not True:
1321	return error(sText);
1322	return log(sText);
1323
1324	def maybeLogXcpt(fIsNotError, sText=None, cFrames=1):
1325	""" Maybe error or maybe normal log exception entry. """
1326	if fIsNotError is not True:
1327	return errorXcpt(sText, cFrames);
1328	return logXcpt(sText, cFrames);
1329
1330	def error(sText):
1331	"""
1332	Writes the specfied error message to the log.
1333
1334	This will add an error to the current test.
1335
1336	Always returns False for the convenience of methods returning boolean
1337	success indicators.
1338	"""
1339	g_oLock.acquire();
1340	try:
1341	g_oReporter.testIncErrors();
1342	g_oReporter.log(0, '** error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1343	except:
1344	pass;
1345	finally:
1346	g_oLock.release();
1347	return False;
1348
1349	def errorXcpt(sText=None, cFrames=1):
1350	"""
1351	Log an error caused by an exception. If sText is given, it will preceed
1352	the exception information. cFrames can be used to display more stack.
1353
1354	This will add an error to the current test.
1355
1356	Always returns False for the convenience of methods returning boolean
1357	success indicators.
1358	"""
1359	logXcptWorker(0, True, '** error: ', sText, cFrames);
1360	return False;
1361
1362	def errorTimeout(sText):
1363	"""
1364	Flags the current test as having timed out and writes the specified message to the log.
1365
1366	This will add an error to the current test.
1367
1368	Always returns False for the convenience of methods returning boolean
1369	success indicators.
1370	"""
1371	g_oLock.acquire();
1372	try:
1373	g_oReporter.testSetTimedOut();
1374	g_oReporter.log(0, '** timeout-error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1375	except:
1376	pass;
1377	finally:
1378	g_oLock.release();
1379	return False;
1380
1381	def fatal(sText):
1382	"""
1383	Writes a fatal error to the log.
1384
1385	This will add an error to the current test.
1386
1387	Always returns False for the convenience of methods returning boolean
1388	success indicators.
1389	"""
1390	g_oLock.acquire();
1391	try:
1392	g_oReporter.testIncErrors();
1393	g_oReporter.log(0, '** fatal error: %s' % (sText), utils.getCallerName(), utils.getTimePrefix());
1394	except:
1395	pass
1396	finally:
1397	g_oLock.release();
1398	return False;
1399
1400	def fatalXcpt(sText=None, cFrames=1):
1401	"""
1402	Log a fatal error caused by an exception. If sText is given, it will
1403	preceed the exception information. cFrames can be used to display more
1404	stack.
1405
1406	This will add an error to the current test.
1407
1408	Always returns False for the convenience of methods returning boolean
1409	success indicators.
1410	"""
1411	logXcptWorker(0, True, "** fatal error: ", sText, cFrames);
1412	return False;
1413
1414	def addLogFile(sFilename, sKind, sDescription = '', sAltName = None):
1415	"""
1416	Adds the specified log file to the report if the file exists.
1417
1418	The sDescription is a free form description of the log file.
1419
1420	The sKind parameter is for adding some machine parsable hint what kind of
1421	log file this really is.
1422
1423	Returns True on success, False on failure (no ENOENT errors are logged).
1424	"""
1425	sTsPrf = utils.getTimePrefix();
1426	sCaller = utils.getCallerName();
1427	fRc = False;
1428	if sAltName is None:
1429	sAltName = sFilename;
1430
1431	try:
1432	oSrcFile = utils.openNoInherit(sFilename, 'rb');
1433	except IOError as oXcpt:
1434	if oXcpt.errno != errno.ENOENT:
1435	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1436	else:
1437	logXcpt('addLogFile(%s,%s,%s) IOError' % (sFilename, sDescription, sKind));
1438	except:
1439	logXcpt('addLogFile(%s,%s,%s)' % (sFilename, sDescription, sKind));
1440	else:
1441	g_oLock.acquire();
1442	try:
1443	fRc = g_oReporter.addLogFile(oSrcFile, sFilename, sAltName, sDescription, sKind, sCaller, sTsPrf);
1444	finally:
1445	g_oLock.release();
1446	oSrcFile.close();
1447	return fRc;
1448
1449	def addLogString(sLog, sLogName, sKind, sDescription = ''):
1450	"""
1451	Adds the specified log string to the report.
1452
1453	The sLog parameter sets the name of the log file.
1454
1455	The sDescription is a free form description of the log file.
1456
1457	The sKind parameter is for adding some machine parsable hint what kind of
1458	log file this really is.
1459
1460	Returns True on success, False on failure (no ENOENT errors are logged).
1461	"""
1462	sTsPrf = utils.getTimePrefix();
1463	sCaller = utils.getCallerName();
1464	fRc = False;
1465
1466	g_oLock.acquire();
1467	try:
1468	fRc = g_oReporter.addLogString(sLog, sLogName, sDescription, sKind, sCaller, sTsPrf);
1469	finally:
1470	g_oLock.release();
1471	return fRc;
1472
1473	def isLocal():
1474	"""Is this a local reporter?"""
1475	return g_oReporter.isLocal()
1476
1477	def incVerbosity():
1478	"""Increases the verbosity level."""
1479	return g_oReporter.incVerbosity()
1480
1481	def incDebug():
1482	"""Increases the debug level."""
1483	return g_oReporter.incDebug()
1484
1485	def appendToProcessName(sAppend):
1486	"""
1487	Appends sAppend to the base process name.
1488	Returns the new process name.
1489	"""
1490	return g_oReporter.appendToProcessName(sAppend);
1491
1492	def getErrorCount():
1493	"""
1494	Get the current error count for the entire test run.
1495	"""
1496	g_oLock.acquire();
1497	try:
1498	cErrors = g_oReporter.cErrors;
1499	finally:
1500	g_oLock.release();
1501	return cErrors;
1502
1503	def doPollWork(sDebug = None):
1504	"""
1505	This can be called from wait loops and similar to make the reporter call
1506	home with pending XML and such.
1507	"""
1508	g_oReporter.doPollWork(sDebug);
1509	return None;
1510
1511
1512	#
1513	# Test reporting, a bit similar to RTTestI*.
1514	#
1515
1516	def testStart(sName):
1517	"""
1518	Starts a new test (pushes it).
1519	"""
1520	g_oLock.acquire();
1521	try:
1522	rc = g_oReporter.testStart(sName, utils.getCallerName());
1523	finally:
1524	g_oLock.release();
1525	return rc;
1526
1527	def testValue(sName, sValue, sUnit):
1528	"""
1529	Reports a benchmark value or something simiarlly useful.
1530	"""
1531	g_oLock.acquire();
1532	try:
1533	rc = g_oReporter.testValue(sName, str(sValue), sUnit, utils.getCallerName());
1534	finally:
1535	g_oLock.release();
1536	return rc;
1537
1538	def testFailure(sDetails):
1539	"""
1540	Reports a failure.
1541	We count these calls and testDone will use them to report PASSED or FAILED.
1542
1543	Returns False so that a return False line can be saved.
1544	"""
1545	g_oLock.acquire();
1546	try:
1547	g_oReporter.testFailure(sDetails, utils.getCallerName());
1548	finally:
1549	g_oLock.release();
1550	return False;
1551
1552	def testFailureXcpt(sDetails = ''):
1553	"""
1554	Reports a failure with exception.
1555	We count these calls and testDone will use them to report PASSED or FAILED.
1556
1557	Returns False so that a return False line can be saved.
1558	"""
1559	# Extract exception info.
1560	try:
1561	oType, oValue, oTraceback = sys.exc_info();
1562	except:
1563	oType = oValue, oTraceback = None;
1564	if oType is not None:
1565	sCaller = utils.getCallerName(oTraceback.tb_frame);
1566	sXcpt = ' '.join(traceback.format_exception_only(oType, oValue));
1567	else:
1568	sCaller = utils.getCallerName();
1569	sXcpt = 'No exception at %s' % (sCaller,);
1570
1571	# Use testFailure to do the work.
1572	g_oLock.acquire();
1573	try:
1574	if sDetails == '':
1575	g_oReporter.testFailure('Exception: %s' % (sXcpt,), sCaller);
1576	else:
1577	g_oReporter.testFailure('%s: %s' % (sDetails, sXcpt), sCaller);
1578	finally:
1579	g_oLock.release();
1580	return False;
1581
1582	def testDone(fSkipped = False):
1583	"""
1584	Completes the current test (pops it), logging PASSED / FAILURE.
1585
1586	Returns a tuple with the name of the test and its error count.
1587	"""
1588	g_oLock.acquire();
1589	try:
1590	rc = g_oReporter.testDone(fSkipped, utils.getCallerName());
1591	finally:
1592	g_oLock.release();
1593	return rc;
1594
1595	def testErrorCount():
1596	"""
1597	Gets the error count of the current test.
1598
1599	Returns the number of errors.
1600	"""
1601	g_oLock.acquire();
1602	try:
1603	cErrors = g_oReporter.testErrorCount();
1604	finally:
1605	g_oLock.release();
1606	return cErrors;
1607
1608	def testCleanup():
1609	"""
1610	Closes all open tests with a generic error condition.
1611
1612	Returns True if no open tests, False if something had to be closed with failure.
1613	"""
1614	g_oLock.acquire();
1615	try:
1616	fRc = g_oReporter.testCleanup(utils.getCallerName());
1617	g_oReporter.xmlFlush(fRetry = False, fForce = True);
1618	finally:
1619	g_oLock.release();
1620	return fRc;
1621
1622
1623	#
1624	# Sub XML stuff.
1625	#
1626
1627	def addSubXmlFile(sFilename):
1628	"""
1629	Adds a sub-xml result file to the party.
1630	"""
1631	fRc = False;
1632	try:
1633	oSrcFile = utils.openNoInherit(sFilename, 'r');
1634	except IOError as oXcpt:
1635	if oXcpt.errno != errno.ENOENT:
1636	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1637	except:
1638	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1639	else:
1640	try:
1641	oWrapper = FileWrapperTestPipe()
1642	oWrapper.write(oSrcFile.read());
1643	oWrapper.close();
1644	except:
1645	logXcpt('addSubXmlFile(%s)' % (sFilename,));
1646	oSrcFile.close();
1647
1648	return fRc;
1649
1650
1651	#
1652	# Other useful debugging tools.
1653	#
1654
1655	def logAllStacks(cFrames = None):
1656	"""
1657	Logs the stacks of all python threads.
1658	"""
1659	sTsPrf = utils.getTimePrefix();
1660	sCaller = utils.getCallerName();
1661	g_oLock.acquire();
1662
1663	cThread = 0;
1664	for idThread, oStack in sys._current_frames().items(): # >=2.5, a bit ugly - pylint: disable=W0212
1665	try:
1666	if cThread > 0:
1667	g_oReporter.log(1, '', sCaller, sTsPrf);
1668	g_oReporter.log(1, 'Thread %s (%#x)' % (idThread, idThread), sCaller, sTsPrf);
1669	try:
1670	asInfo = traceback.format_stack(oStack, cFrames);
1671	except:
1672	g_oReporter.log(1, ' Stack formatting failed w/ exception', sCaller, sTsPrf);
1673	else:
1674	for sInfo in asInfo:
1675	asLines = sInfo.splitlines();
1676	for sLine in asLines:
1677	g_oReporter.log(1, sLine, sCaller, sTsPrf);
1678	except:
1679	pass;
1680	cThread += 1;
1681
1682	g_oLock.release();
1683	return None;
1684
1685	def checkTestManagerConnection():
1686	"""
1687	Checks the connection to the test manager.
1688
1689	Returns True if the connection is fine, False if not, None if not remote
1690	reporter.
1691
1692	Note! This as the sideeffect of flushing XML.
1693	"""
1694	g_oLock.acquire();
1695	try:
1696	fRc = g_oReporter.xmlFlush(fRetry = False, fForce = True);
1697	finally:
1698	g_oLock.release();
1699	return fRc;
1700
1701	def flushall(fSkipXml = False):
1702	"""
1703	Flushes all output streams, both standard and logger related.
1704	This may also push data to the remote test manager.
1705	"""
1706	try: sys.stdout.flush();
1707	except: pass;
1708	try: sys.stderr.flush();
1709	except: pass;
1710
1711	if fSkipXml is not True:
1712	g_oLock.acquire();
1713	try:
1714	g_oReporter.xmlFlush(fRetry = False);
1715	finally:
1716	g_oLock.release();
1717
1718	return True;
1719
1720
1721	#
1722	# Module initialization.
1723	#
1724
1725	def _InitReporterModule():
1726	"""
1727	Instantiate the test reporter.
1728	"""
1729	global g_oReporter, g_sReporterName
1730
1731	g_sReporterName = os.getenv("TESTBOX_REPORTER", "local");
1732	if g_sReporterName == "local":
1733	g_oReporter = LocalReporter();
1734	elif g_sReporterName == "remote":
1735	g_oReporter = RemoteReporter(); # Correct, but still plain stupid. pylint: disable=redefined-variable-type
1736	else:
1737	print(os.path.basename(__file__) + ": Unknown TESTBOX_REPORTER value: '" + g_sReporterName + "'", file = sys.stderr);
1738	raise Exception("Unknown TESTBOX_REPORTER value '" + g_sReporterName + "'");
1739
1740	if __name__ != "checker": # pychecker avoidance.
1741	_InitReporterModule();
1742

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

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

Download in other formats: