reporter.py@ 65839

Last change on this file since 65839 was 65839, checked in by vboxsync, 8 years ago
testdriver/reporter.py: Enabled the lock debugging for linux and solaris too.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 62.7 KB

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

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

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

Download in other formats: