reporter.py@ 65857

Last change on this file since 65857 was 65857, checked in by vboxsync, 8 years ago
testdriver/reporter.py: Redid locking to account for garbage collection causing trouble when it calls del methods with log statements. Since those statements can be very useful, the reporter now disables GC while it's owning the lock, but allow recursion in case GC runs before we disables it or immediately after reenabling it.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 58.3 KB

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

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

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

Download in other formats: