virtual_test_sheriff.py@ 67152

Last change on this file since 67152 was 67152, checked in by vboxsync, 8 years ago
vsheriff: teach about "driver not compilable" on Linux hosts
Property svn:eol-style set to `LF` Property svn:executable set to ``* Property svn:keywords set to `Author Date Id Revision`
File size: 62.5 KB

Line
1	#!/usr/bin/env python
2	# -- coding: utf-8 --
3	# $Id: virtual_test_sheriff.py 67152 2017-05-31 08:18:53Z vboxsync $
4	# pylint: disable=C0301
5
6	"""
7	Virtual Test Sheriff.
8
9	Duties:
10	- Try to a assign failure reasons to recently failed tests.
11	- Reboot or disable bad test boxes.
12
13	"""
14
15	__copyright__ = \
16	"""
17	Copyright (C) 2012-2016 Oracle Corporation
18
19	This file is part of VirtualBox Open Source Edition (OSE), as
20	available from http://www.virtualbox.org. This file is free software;
21	you can redistribute it and/or modify it under the terms of the GNU
22	General Public License (GPL) as published by the Free Software
23	Foundation, in version 2 as it comes in the "COPYING" file of the
24	VirtualBox OSE distribution. VirtualBox OSE is distributed in the
25	hope that it will be useful, but WITHOUT ANY WARRANTY of any kind.
26
27	The contents of this file may alternatively be used under the terms
28	of the Common Development and Distribution License Version 1.0
29	(CDDL) only, as it comes in the "COPYING.CDDL" file of the
30	VirtualBox OSE distribution, in which case the provisions of the
31	CDDL are applicable instead of those of the GPL.
32
33	You may elect to license modified versions of this file under the
34	terms and conditions of either the GPL or the CDDL or both.
35	"""
36	__version__ = "$Revision: 67152 $"
37
38
39	# Standard python imports
40	import sys;
41	import os;
42	import hashlib;
43	import StringIO;
44	from optparse import OptionParser;
45	from PIL import Image; # pylint: disable=import-error
46
47	# Add Test Manager's modules path
48	g_ksTestManagerDir = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))));
49	sys.path.append(g_ksTestManagerDir);
50
51	# Test Manager imports
52	from testmanager.core.db import TMDatabaseConnection;
53	from testmanager.core.build import BuildDataEx;
54	from testmanager.core.failurereason import FailureReasonLogic;
55	from testmanager.core.testbox import TestBoxLogic, TestBoxData;
56	from testmanager.core.testcase import TestCaseDataEx;
57	from testmanager.core.testgroup import TestGroupData;
58	from testmanager.core.testset import TestSetLogic, TestSetData;
59	from testmanager.core.testresults import TestResultLogic, TestResultFileData;
60	from testmanager.core.testresultfailures import TestResultFailureLogic, TestResultFailureData;
61	from testmanager.core.useraccount import UserAccountLogic;
62
63
64	class VirtualTestSheriffCaseFile(object):
65	"""
66	A failure investigation case file.
67
68	"""
69
70
71	## Max log file we'll read into memory. (256 MB)
72	kcbMaxLogRead = 0x10000000;
73
74	def __init__(self, oSheriff, oTestSet, oTree, oBuild, oTestBox, oTestGroup, oTestCase):
75	self.oSheriff = oSheriff;
76	self.oTestSet = oTestSet; # TestSetData
77	self.oTree = oTree; # TestResultDataEx
78	self.oBuild = oBuild; # BuildDataEx
79	self.oTestBox = oTestBox; # TestBoxData
80	self.oTestGroup = oTestGroup; # TestGroupData
81	self.oTestCase = oTestCase; # TestCaseDataEx
82	self.sMainLog = ''; # The main log file. Empty string if not accessible.
83
84	# Generate a case file name.
85	self.sName = '#%u: %s' % (self.oTestSet.idTestSet, self.oTestCase.sName,)
86	self.sLongName = '#%u: "%s" on "%s" running %s %s (%s), "%s" by %s, using %s %s %s r%u' \
87	% ( self.oTestSet.idTestSet,
88	self.oTestCase.sName,
89	self.oTestBox.sName,
90	self.oTestBox.sOs,
91	self.oTestBox.sOsVersion,
92	self.oTestBox.sCpuArch,
93	self.oTestBox.sCpuName,
94	self.oTestBox.sCpuVendor,
95	self.oBuild.oCat.sProduct,
96	self.oBuild.oCat.sBranch,
97	self.oBuild.oCat.sType,
98	self.oBuild.iRevision, );
99
100	# Investigation notes.
101	self.tReason = None; # None or one of the ktReason_XXX constants.
102	self.dReasonForResultId = {}; # Reason assignments indexed by idTestResult.
103	self.dCommentForResultId = {}; # Comment assignments indexed by idTestResult.
104
105	#
106	# Reason.
107	#
108
109	def noteReason(self, tReason):
110	""" Notes down a possible reason. """
111	self.oSheriff.dprint(u'noteReason: %s -> %s' % (self.tReason, tReason,));
112	self.tReason = tReason;
113	return True;
114
115	def noteReasonForId(self, tReason, idTestResult, sComment = None):
116	""" Notes down a possible reason for a specific test result. """
117	self.oSheriff.dprint(u'noteReasonForId: %u: %s -> %s%s'
118	% (idTestResult, self.dReasonForResultId.get(idTestResult, None), tReason,
119	(u' (%s)' % (sComment,)) if sComment is not None else ''));
120	self.dReasonForResultId[idTestResult] = tReason;
121	if sComment is not None:
122	self.dCommentForResultId[idTestResult] = sComment;
123	return True;
124
125
126	#
127	# Test classification.
128	#
129
130	def isVBoxTest(self):
131	""" Test classification: VirtualBox (using the build) """
132	return self.oBuild.oCat.sProduct.lower() in [ 'virtualbox', 'vbox' ];
133
134	def isVBoxUnitTest(self):
135	""" Test case classification: The unit test doing all our testcase/*.cpp stuff. """
136	return self.isVBoxTest() \
137	and self.oTestCase.sName.lower() == 'unit tests';
138
139	def isVBoxInstallTest(self):
140	""" Test case classification: VirtualBox Guest installation test. """
141	return self.isVBoxTest() \
142	and self.oTestCase.sName.lower().startswith('install:');
143
144	def isVBoxUSBTest(self):
145	""" Test case classification: VirtualBox USB test. """
146	return self.isVBoxTest() \
147	and self.oTestCase.sName.lower().startswith('usb:');
148
149	def isVBoxStorageTest(self):
150	""" Test case classification: VirtualBox Storage test. """
151	return self.isVBoxTest() \
152	and self.oTestCase.sName.lower().startswith('storage:');
153
154	def isVBoxGAsTest(self):
155	""" Test case classification: VirtualBox Guest Additions test. """
156	return self.isVBoxTest() \
157	and self.oTestCase.sName.lower().startswith('ga\'s tests');
158
159	def isVBoxAPITest(self):
160	""" Test case classification: VirtualBox API test. """
161	return self.isVBoxTest() \
162	and self.oTestCase.sName.lower().startswith('api:');
163
164	def isVBoxBenchmarkTest(self):
165	""" Test case classification: VirtualBox Benchmark test. """
166	return self.isVBoxTest() \
167	and self.oTestCase.sName.lower().startswith('benchmark:');
168
169	def isVBoxSmokeTest(self):
170	""" Test case classification: Smoke test. """
171	return self.isVBoxTest() \
172	and self.oTestCase.sName.lower().startswith('smoketest');
173
174
175	#
176	# Utility methods.
177	#
178
179	def getMainLog(self):
180	"""
181	Tries to reads the main log file since this will be the first source of information.
182	"""
183	if self.sMainLog:
184	return self.sMainLog;
185	(oFile, oSizeOrError, _) = self.oTestSet.openFile('main.log', 'rb');
186	if oFile is not None:
187	try:
188	self.sMainLog = oFile.read(min(self.kcbMaxLogRead, oSizeOrError)).decode('utf-8', 'replace');
189	except Exception as oXcpt:
190	self.oSheriff.vprint(u'Error reading main log file: %s' % (oXcpt,))
191	self.sMainLog = '';
192	else:
193	self.oSheriff.vprint(u'Error opening main log file: %s' % (oSizeOrError,));
194	return self.sMainLog;
195
196	def getLogFile(self, oFile):
197	"""
198	Tries to reads the given file as a utf-8 log file.
199	oFile is a TestFileDataEx instance.
200	Returns empty string if problems opening or reading the file.
201	"""
202	sContent = '';
203	(oFile, oSizeOrError, _) = self.oTestSet.openFile(oFile.sFile, 'rb');
204	if oFile is not None:
205	try:
206	sContent = oFile.read(min(self.kcbMaxLogRead, oSizeOrError)).decode('utf-8', 'replace');
207	except Exception as oXcpt:
208	self.oSheriff.vprint(u'Error reading the "%s" log file: %s' % (oFile.sFile, oXcpt,))
209	else:
210	self.oSheriff.vprint(u'Error opening the "%s" log file: %s' % (oFile.sFile, oSizeOrError,));
211	return sContent;
212
213	def getScreenshotSha256(self, oFile):
214	"""
215	Tries to read the given screenshot file, uncompress it, and do SHA-2
216	on the raw pixels.
217	Returns SHA-2 digest string on success, None on failure.
218	"""
219	(oFile, _, _) = self.oTestSet.openFile(oFile.sFile, 'rb');
220	try:
221	abImageFile = oFile.read();
222	except Exception as oXcpt:
223	self.oSheriff.vprint(u'Error reading the "%s" image file: %s' % (oFile.sFile, oXcpt,))
224	else:
225	try:
226	oImage = Image.open(StringIO.StringIO(abImageFile));
227	except Exception as oXcpt:
228	self.oSheriff.vprint(u'Error opening the "%s" image bytes using PIL.Image.open: %s' % (oFile.sFile, oXcpt,))
229	else:
230	try:
231	oHash = hashlib.sha256();
232	oHash.update(oImage.tostring());
233	except Exception as oXcpt:
234	self.oSheriff.vprint(u'Error hashing the uncompressed image bytes for "%s": %s' % (oFile.sFile, oXcpt,))
235	else:
236	return oHash.hexdigest();
237	return None;
238
239
240
241	def isSingleTestFailure(self):
242	"""
243	Figure out if this is a single test failing or if it's one of the
244	more complicated ones.
245	"""
246	if self.oTree.cErrors == 1:
247	return True;
248	if self.oTree.deepCountErrorContributers() <= 1:
249	return True;
250	return False;
251
252
253
254	class VirtualTestSheriff(object): # pylint: disable=R0903
255	"""
256	Add build info into Test Manager database.
257	"""
258
259	## The user account for the virtual sheriff.
260	ksLoginName = 'vsheriff';
261
262	def __init__(self):
263	"""
264	Parse command line.
265	"""
266	self.oDb = None;
267	self.tsNow = None;
268	self.oTestResultLogic = None;
269	self.oTestSetLogic = None;
270	self.oFailureReasonLogic = None; # FailureReasonLogic;
271	self.oTestResultFailureLogic = None; # TestResultFailureLogic
272	self.oLogin = None;
273	self.uidSelf = -1;
274	self.oLogFile = None;
275	self.asBsodReasons = [];
276	self.asUnitTestReasons = [];
277
278	oParser = OptionParser();
279	oParser.add_option('--start-hours-ago', dest = 'cStartHoursAgo', metavar = '<hours>', default = 0, type = 'int',
280	help = 'When to start specified as hours relative to current time. Defauls is right now.', );
281	oParser.add_option('--hours-period', dest = 'cHoursBack', metavar = '<period-in-hours>', default = 2, type = 'int',
282	help = 'Work period specified in hours. Defauls is 2 hours.');
283	oParser.add_option('--real-run-back', dest = 'fRealRun', action = 'store_true', default = False,
284	help = 'Whether to commit the findings to the database. Default is a dry run.');
285	oParser.add_option('-q', '--quiet', dest = 'fQuiet', action = 'store_true', default = False,
286	help = 'Quiet execution');
287	oParser.add_option('-l', '--log', dest = 'sLogFile', metavar = '<logfile>', default = None,
288	help = 'Where to log messages.');
289	oParser.add_option('--debug', dest = 'fDebug', action = 'store_true', default = False,
290	help = 'Enables debug mode.');
291
292	(self.oConfig, _) = oParser.parse_args();
293
294	if self.oConfig.sLogFile:
295	self.oLogFile = open(self.oConfig.sLogFile, "a");
296	self.oLogFile.write('VirtualTestSheriff: $Revision: 67152 $ \n');
297
298
299	def eprint(self, sText):
300	"""
301	Prints error messages.
302	Returns 1 (for exit code usage.)
303	"""
304	print 'error: %s' % (sText,);
305	if self.oLogFile is not None:
306	self.oLogFile.write((u'error: %s\n' % (sText,)).encode('utf-8'));
307	return 1;
308
309	def dprint(self, sText):
310	"""
311	Prints debug info.
312	"""
313	if self.oConfig.fDebug:
314	if not self.oConfig.fQuiet:
315	print 'debug: %s' % (sText, );
316	if self.oLogFile is not None:
317	self.oLogFile.write((u'debug: %s\n' % (sText,)).encode('utf-8'));
318	return 0;
319
320	def vprint(self, sText):
321	"""
322	Prints verbose info.
323	"""
324	if not self.oConfig.fQuiet:
325	print 'info: %s' % (sText,);
326	if self.oLogFile is not None:
327	self.oLogFile.write((u'info: %s\n' % (sText,)).encode('utf-8'));
328	return 0;
329
330	def getFailureReason(self, tReason):
331	""" Gets the failure reason object for tReason. """
332	return self.oFailureReasonLogic.cachedLookupByNameAndCategory(tReason[1], tReason[0]);
333
334	def selfCheck(self):
335	""" Does some self checks, looking up things we expect to be in the database and such. """
336	rcExit = 0;
337	for sAttr in dir(self.__class__):
338	if sAttr.startswith('ktReason_'):
339	tReason = getattr(self.__class__, sAttr);
340	oFailureReason = self.getFailureReason(tReason);
341	if oFailureReason is None:
342	rcExit = self.eprint(u'Failed to find failure reason "%s" in category "%s" in the database!'
343	% (tReason[1], tReason[0],));
344
345	# Check the user account as well.
346	if self.oLogin is None:
347	oLogin = UserAccountLogic(self.oDb).tryFetchAccountByLoginName(VirtualTestSheriff.ksLoginName);
348	if oLogin is None:
349	rcExit = self.eprint(u'Cannot find my user account "%s"!' % (VirtualTestSheriff.ksLoginName,));
350	return rcExit;
351
352
353
354	def badTestBoxManagement(self):
355	"""
356	Looks for bad test boxes and first tries once to reboot them then disables them.
357	"""
358	rcExit = 0;
359
360	#
361	# We skip this entirely if we're running in the past and not in harmless debug mode.
362	#
363	if self.oConfig.cStartHoursAgo != 0 \
364	and (not self.oConfig.fDebug or self.oConfig.fRealRun):
365	return rcExit;
366	tsNow = self.tsNow if self.oConfig.fDebug else None;
367	cHoursBack = self.oConfig.cHoursBack if self.oConfig.fDebug else 2;
368	oTestBoxLogic = TestBoxLogic(self.oDb);
369
370	#
371	# Generate a list of failures reasons we consider bad-testbox behavior.
372	#
373	aidFailureReasons = [
374	self.getFailureReason(self.ktReason_Host_DriverNotUnloading).idFailureReason,
375	self.getFailureReason(self.ktReason_Host_DriverNotCompilable).idFailureReason,
376	];
377
378	#
379	# Get list of bad test boxes for given period and check them out individually.
380	#
381	aidBadTestBoxes = self.oTestSetLogic.fetchBadTestBoxIds(cHoursBack = cHoursBack, tsNow = tsNow,
382	aidFailureReasons = aidFailureReasons);
383	for idTestBox in aidBadTestBoxes:
384	# Skip if the testbox is already disabled or has a pending reboot command.
385	try:
386	oTestBox = TestBoxData().initFromDbWithId(self.oDb, idTestBox);
387	except Exception as oXcpt:
388	rcExit = self.eprint('Failed to get data for test box #%u in badTestBoxManagement: %s' % (idTestBox, oXcpt,));
389	continue;
390	if not oTestBox.fEnabled:
391	self.dprint(u'badTestBoxManagement: Skipping test box #%u (%s) as it has been disabled already.'
392	% ( idTestBox, oTestBox.sName, ));
393	continue;
394	if oTestBox.enmPendingCmd != TestBoxData.ksTestBoxCmd_None:
395	self.dprint(u'badTestBoxManagement: Skipping test box #%u (%s) as it has a command pending: %s'
396	% ( idTestBox, oTestBox.sName, oTestBox.enmPendingCmd));
397	continue;
398
399	# Get the most recent testsets for this box (descending on tsDone) and see how bad it is.
400	aoSets = self.oTestSetLogic.fetchSetsForTestBox(idTestBox, cHoursBack = cHoursBack, tsNow = tsNow);
401	cOkay = 0;
402	cBad = 0;
403	iFirstOkay = len(aoSets);
404	for iSet, oSet in enumerate(aoSets):
405	if oSet.enmStatus == TestSetData.ksTestStatus_BadTestBox:
406	cBad += 1;
407	else:
408	# Check for bad failure reasons.
409	oFailure = None;
410	if oSet.enmStatus in TestSetData.kasBadTestStatuses:
411	oFailure = self.oTestResultFailureLogic.getById(oSet.idTestResult);
412	if oFailure is not None and oFailure.idFailureReason in aidFailureReasons:
413	cBad += 1;
414	else:
415	# This is an okay test result then.
416	## @todo maybe check the elapsed time here, it could still be a bad run?
417	cOkay += 1;
418	if iFirstOkay > iSet:
419	iFirstOkay = iSet;
420	if iSet > 10:
421	break;
422
423	# We react if there are two or more bad-testbox statuses at the head of the
424	# history and at least three in the last 10 results.
425	if iFirstOkay >= 2 and cBad > 2:
426	# Frank: For now don't reboot boxes automatically
427	if True or oTestBoxLogic.hasTestBoxRecentlyBeenRebooted(idTestBox, cHoursBack = cHoursBack, tsNow = tsNow):
428	self.vprint(u'Disabling testbox #%u (%s) - iFirstOkay=%u cBad=%u cOkay=%u'
429	% ( idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay));
430	if self.oConfig.fRealRun is True:
431	try:
432	oTestBoxLogic.disableTestBox(idTestBox, self.uidSelf, fCommit = True,
433	sComment = 'Automatically disabled (iFirstOkay=%u cBad=%u cOkay=%u)'
434	% (iFirstOkay, cBad, cOkay),);
435	except Exception as oXcpt:
436	rcExit = self.eprint(u'Error disabling testbox #%u (%u): %s\n' % (idTestBox, oTestBox.sName, oXcpt,));
437	else:
438	self.vprint(u'Rebooting testbox #%u (%s) - iFirstOkay=%u cBad=%u cOkay=%u'
439	% ( idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay));
440	if self.oConfig.fRealRun is True:
441	try:
442	oTestBoxLogic.rebootTestBox(idTestBox, self.uidSelf, fCommit = True,
443	sComment = 'Automatically rebooted (iFirstOkay=%u cBad=%u cOkay=%u)'
444	% (iFirstOkay, cBad, cOkay),);
445	except Exception as oXcpt:
446	rcExit = self.eprint(u'Error rebooting testbox #%u (%u): %s\n' % (idTestBox, oTestBox.sName, oXcpt,));
447	else:
448	self.dprint(u'badTestBoxManagement: #%u (%s) looks ok: iFirstOkay=%u cBad=%u cOkay=%u'
449	% ( idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay));
450	return rcExit;
451
452
453	## @name Failure reasons we know.
454	## @{
455	ktReason_BSOD_Recovery = ( 'BSOD', 'Recovery' );
456	ktReason_BSOD_Automatic_Repair = ( 'BSOD', 'Automatic Repair' );
457	ktReason_BSOD_000000D1 = ( 'BSOD', '0x000000D1' );
458	ktReason_BSOD_C0000225 = ( 'BSOD', '0xC0000225 (boot)' );
459	ktReason_Guru_Generic = ( 'Guru Meditations', 'Generic Guru Meditation' );
460	ktReason_Guru_VERR_IEM_INSTR_NOT_IMPLEMENTED = ( 'Guru Meditations', 'VERR_IEM_INSTR_NOT_IMPLEMENTED' );
461	ktReason_Guru_VERR_IEM_ASPECT_NOT_IMPLEMENTED = ( 'Guru Meditations', 'VERR_IEM_ASPECT_NOT_IMPLEMENTED' );
462	ktReason_Guru_VERR_TRPM_DONT_PANIC = ( 'Guru Meditations', 'VERR_TRPM_DONT_PANIC' );
463	ktReason_Guru_VERR_PGM_PHYS_PAGE_RESERVED = ( 'Guru Meditations', 'VERR_PGM_PHYS_PAGE_RESERVED' );
464	ktReason_Guru_VERR_VMX_INVALID_GUEST_STATE = ( 'Guru Meditations', 'VERR_VMX_INVALID_GUEST_STATE' );
465	ktReason_Guru_VINF_EM_TRIPLE_FAULT = ( 'Guru Meditations', 'VINF_EM_TRIPLE_FAULT' );
466	ktReason_Host_HostMemoryLow = ( 'Host', 'HostMemoryLow' );
467	ktReason_Host_DriverNotLoaded = ( 'Host', 'Driver not loaded' );
468	ktReason_Host_DriverNotUnloading = ( 'Host', 'Driver not unloading' );
469	ktReason_Host_DriverNotCompilable = ( 'Host', 'Driver not compilable' );
470	ktReason_Host_NotSignedWithBuildCert = ( 'Host', 'Not signed with build cert' );
471	ktReason_Host_LeftoverService = ( 'Host', 'Leftover service' );
472	ktReason_Host_Reboot_OSX_Watchdog_Timeout = ( 'Host Reboot', 'OSX Watchdog Timeout' );
473	ktReason_Host_Modprobe_Failed = ( 'Host', 'Modprobe failed' );
474	ktReason_Host_Install_Hang = ( 'Host', 'Install hang' );
475	ktReason_Networking_Nonexistent_host_nic = ( 'Networking', 'Nonexistent host networking interface' );
476	ktReason_OSInstall_GRUB_hang = ( 'O/S Install', 'GRUB hang' );
477	ktReason_Panic_BootManagerC000000F = ( 'Panic', 'Hardware Changed' );
478	ktReason_BootManager_Image_corrupt = ( 'Unknown', 'BOOTMGR Image corrupt' );
479	ktReason_Panic_MP_BIOS_IO_APIC = ( 'Panic', 'MP-BIOS/IO-APIC' );
480	ktReason_Panic_HugeMemory = ( 'Panic', 'Huge memory assertion' );
481	ktReason_Panic_IOAPICDoesntWork = ( 'Panic', 'IO-APIC and timer does not work' );
482	ktReason_Panic_TxUnitHang = ( 'Panic', 'Tx Unit Hang' );
483	ktReason_XPCOM_Exit_Minus_11 = ( 'API / (XP)COM', 'exit -11' );
484	ktReason_XPCOM_VBoxSVC_Hang = ( 'API / (XP)COM', 'VBoxSVC hang' );
485	ktReason_XPCOM_VBoxSVC_Hang_Plus_Heap_Corruption = ( 'API / (XP)COM', 'VBoxSVC hang + heap corruption' );
486	ktReason_XPCOM_NS_ERROR_CALL_FAILED = ( 'API / (XP)COM', 'NS_ERROR_CALL_FAILED' );
487	ktReason_Unknown_Heap_Corruption = ( 'Unknown', 'Heap corruption' );
488	ktReason_Unknown_Reboot_Loop = ( 'Unknown', 'Reboot loop' );
489	ktReason_Unknown_File_Not_Found = ( 'Unknown', 'File not found' );
490	ktReason_Unknown_VM_Crash = ( 'Unknown', 'VM crash' );
491	ktReason_VMM_kvm_lock_spinning = ( 'VMM', 'kvm_lock_spinning' );
492	ktReason_Ignore_Buggy_Test_Driver = ( 'Ignore', 'Buggy test driver' );
493	ktReason_Ignore_Stale_Files = ( 'Ignore', 'Stale files' );
494	ktReason_Buggy_Build_Broken_Build = ( 'Broken Build', 'Buggy build' );
495	## @}
496
497	## BSOD category.
498	ksBsodCategory = 'BSOD';
499	## Special reason indicating that the flesh and blood sheriff has work to do.
500	ksBsodAddNew = 'Add new BSOD';
501
502	## Unit test category.
503	ksUnitTestCategory = 'Unit';
504	## Special reason indicating that the flesh and blood sheriff has work to do.
505	ksUnitTestAddNew = 'Add new';
506
507	## Used for indica that we shouldn't report anything for this test result ID and
508	## consider promoting the previous error to test set level if it's the only one.
509	ktHarmless = ( 'Probably', 'Caused by previous error' );
510
511
512	def caseClosed(self, oCaseFile):
513	"""
514	Reports the findings in the case and closes it.
515	"""
516	#
517	# Log it and create a dReasonForReasultId we can use below.
518	#
519	dCommentForResultId = oCaseFile.dCommentForResultId;
520	if oCaseFile.dReasonForResultId:
521	# Must weed out ktHarmless.
522	dReasonForResultId = {};
523	for idKey, tReason in oCaseFile.dReasonForResultId.items():
524	if tReason is not self.ktHarmless:
525	dReasonForResultId[idKey] = tReason;
526	if not dReasonForResultId:
527	self.vprint(u'TODO: Closing %s without a real reason, only %s.'
528	% (oCaseFile.sName, oCaseFile.dReasonForResultId));
529	return False;
530
531	# Try promote to single reason.
532	atValues = dReasonForResultId.values();
533	fSingleReason = True;
534	if len(dReasonForResultId) == 1 and dReasonForResultId.keys()[0] != oCaseFile.oTestSet.idTestResult:
535	self.dprint(u'Promoting single reason to whole set: %s' % (atValues[0],));
536	elif len(dReasonForResultId) > 1 and len(atValues) == atValues.count(atValues[0]):
537	self.dprint(u'Merged %d reasons to a single one: %s' % (len(atValues), atValues[0]));
538	else:
539	fSingleReason = False;
540	if fSingleReason:
541	dReasonForResultId = { oCaseFile.oTestSet.idTestResult: atValues[0], };
542	if dCommentForResultId:
543	dCommentForResultId = { oCaseFile.oTestSet.idTestResult: dCommentForResultId.values()[0], };
544	elif oCaseFile.tReason is not None:
545	dReasonForResultId = { oCaseFile.oTestSet.idTestResult: oCaseFile.tReason, };
546	else:
547	self.vprint(u'Closing %s without a reason - this should not happen!' % (oCaseFile.sName,));
548	return False;
549
550	self.vprint(u'Closing %s with following reason%s: %s'
551	% ( oCaseFile.sName, 's' if dReasonForResultId > 0 else '', dReasonForResultId, ));
552
553	#
554	# Add the test failure reason record(s).
555	#
556	for idTestResult, tReason in dReasonForResultId.items():
557	oFailureReason = self.getFailureReason(tReason);
558	if oFailureReason is not None:
559	sComment = 'Set by $Revision: 67152 $' # Handy for reverting later.
560	if idTestResult in dCommentForResultId:
561	sComment += ': ' + dCommentForResultId[idTestResult];
562
563	oAdd = TestResultFailureData();
564	oAdd.initFromValues(idTestResult = idTestResult,
565	idFailureReason = oFailureReason.idFailureReason,
566	uidAuthor = self.uidSelf,
567	idTestSet = oCaseFile.oTestSet.idTestSet,
568	sComment = sComment,);
569	if self.oConfig.fRealRun:
570	try:
571	self.oTestResultFailureLogic.addEntry(oAdd, self.uidSelf, fCommit = True);
572	except Exception as oXcpt:
573	self.eprint(u'caseClosed: Exception "%s" while adding reason %s for %s'
574	% (oXcpt, oAdd, oCaseFile.sLongName,));
575	else:
576	self.eprint(u'caseClosed: Cannot locate failure reason: %s / %s' % ( tReason[0], tReason[1],));
577	return True;
578
579	#
580	# Tools for assiting log parsing.
581	#
582
583	@staticmethod
584	def matchFollowedByLines(sStr, off, asFollowingLines):
585	""" Worker for isThisFollowedByTheseLines. """
586
587	# Advance off to the end of the line.
588	off = sStr.find('\n', off);
589	if off < 0:
590	return False;
591	off += 1;
592
593	# Match each string with the subsequent lines.
594	for iLine, sLine in enumerate(asFollowingLines):
595	offEnd = sStr.find('\n', off);
596	if offEnd < 0:
597	return iLine + 1 == len(asFollowingLines) and sStr.find(sLine, off) < 0;
598	if sLine and sStr.find(sLine, off, offEnd) < 0:
599	return False;
600
601	# next line.
602	off = offEnd + 1;
603
604	return True;
605
606	@staticmethod
607	def isThisFollowedByTheseLines(sStr, sFirst, asFollowingLines):
608	"""
609	Looks for a line contining sFirst which is then followed by lines
610	with the strings in asFollowingLines. (No newline chars anywhere!)
611	Returns True / False.
612	"""
613	off = sStr.find(sFirst, 0);
614	while off >= 0:
615	if VirtualTestSheriff.matchFollowedByLines(sStr, off, asFollowingLines):
616	return True;
617	off = sStr.find(sFirst, off + 1);
618	return False;
619
620	@staticmethod
621	def findAndReturnRestOfLine(sHaystack, sNeedle):
622	"""
623	Looks for sNeedle in sHaystack.
624	Returns The text following the needle up to the end of the line.
625	Returns None if not found.
626	"""
627	if sHaystack is None:
628	return None;
629	off = sHaystack.find(sNeedle);
630	if off < 0:
631	return None;
632	off += len(sNeedle)
633	offEol = sHaystack.find('\n', off);
634	if offEol < 0:
635	offEol = len(sHaystack);
636	return sHaystack[off:offEol]
637
638	@staticmethod
639	def findInAnyAndReturnRestOfLine(asHaystacks, sNeedle):
640	"""
641	Looks for sNeedle in zeroe or more haystacks (asHaystack).
642	Returns The text following the first needed found up to the end of the line.
643	Returns None if not found.
644	"""
645	for sHaystack in asHaystacks:
646	sRet = VirtualTestSheriff.findAndReturnRestOfLine(sHaystack, sNeedle);
647	if sRet is not None:
648	return sRet;
649	return None;
650
651
652	#
653	# The investigative units.
654	#
655
656	katSimpleInstallUninstallMainLogReasons = [
657	# ( Whether to stop on hit, reason tuple, needle text. )
658	( False, ktReason_Host_LeftoverService,
659	'SERVICE_NAME: vbox' ),
660	];
661
662	kdatSimpleInstallUninstallMainLogReasonsPerOs = {
663	'darwin': [
664	# ( Whether to stop on hit, reason tuple, needle text. )
665	( True, ktReason_Host_DriverNotUnloading,
666	'Can\'t remove kext org.virtualbox.kext.VBoxDrv; services failed to terminate - 0xe00002c7' ),
667	],
668	'linux': [
669	# ( Whether to stop on hit, reason tuple, needle text. )
670	( True, ktReason_Host_DriverNotCompilable,
671	'This system is not currently set up to build kernel modules' ),
672	( True, ktReason_Host_DriverNotCompilable,
673	'This system is currently not set up to build kernel modules' ),
674	],
675	};
676
677
678	def investigateInstallUninstallFailure(self, oCaseFile, oFailedResult, sResultLog, fInstall):
679	"""
680	Investigates an install or uninstall failure.
681
682	We lump the two together since the installation typically also performs
683	an uninstall first and will be seeing similar issues to the uninstall.
684	"""
685
686	if fInstall and oFailedResult.enmStatus == TestSetData.ksTestStatus_TimedOut:
687	oCaseFile.noteReasonForId(self.ktReason_Host_Install_Hang, oFailedResult.idTestResult)
688	return True;
689
690	atSimple = self.katSimpleInstallUninstallMainLogReasons;
691	if oCaseFile.oTestBox.sOs in self.kdatSimpleInstallUninstallMainLogReasonsPerOs:
692	atSimple = self.kdatSimpleInstallUninstallMainLogReasonsPerOs[oCaseFile.oTestBox.sOs] + atSimple;
693
694	fFoundSomething = False;
695	for fStopOnHit, tReason, sNeedle in atSimple:
696	if sResultLog.find(sNeedle) > 0:
697	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
698	if fStopOnHit:
699	return True;
700	fFoundSomething = True;
701
702	return fFoundSomething if fFoundSomething else None;
703
704
705	def investigateBadTestBox(self, oCaseFile):
706	"""
707	Checks out bad-testbox statuses.
708	"""
709	_ = oCaseFile;
710	return False;
711
712
713	def investigateVBoxUnitTest(self, oCaseFile):
714	"""
715	Checks out a VBox unittest problem.
716	"""
717
718	#
719	# Process simple test case failures first, using their name as reason.
720	# We do the reason management just like for BSODs.
721	#
722	cRelevantOnes = 0;
723	sMainLog = oCaseFile.getMainLog();
724	aoFailedResults = oCaseFile.oTree.getListOfFailures();
725	for oFailedResult in aoFailedResults:
726	if oFailedResult is oCaseFile.oTree:
727	self.vprint('TODO: toplevel failure');
728	cRelevantOnes += 1
729
730	elif oFailedResult.sName == 'Installing VirtualBox':
731	sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
732	self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = True)
733	cRelevantOnes += 1
734
735	elif oFailedResult.sName == 'Uninstalling VirtualBox':
736	sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
737	self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = False)
738	cRelevantOnes += 1
739
740	elif oFailedResult.oParent is not None:
741	# Get the 2nd level node because that's where we'll find the unit test name.
742	while oFailedResult.oParent.oParent is not None:
743	oFailedResult = oFailedResult.oParent;
744
745	# Only report a failure once.
746	if oFailedResult.idTestResult not in oCaseFile.dReasonForResultId:
747	sKey = oFailedResult.sName;
748	if sKey.startswith('testcase/'):
749	sKey = sKey[9:];
750	if sKey in self.asUnitTestReasons:
751	tReason = ( self.ksUnitTestCategory, sKey );
752	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
753	else:
754	self.dprint(u'Unit test failure "%s" not found in %s;' % (sKey, self.asUnitTestReasons));
755	tReason = ( self.ksUnitTestCategory, self.ksUnitTestAddNew );
756	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = sKey);
757	cRelevantOnes += 1
758	else:
759	self.vprint(u'Internal error: expected oParent to NOT be None for %s' % (oFailedResult,));
760
761	#
762	# If we've caught all the relevant ones by now, report the result.
763	#
764	if len(oCaseFile.dReasonForResultId) >= cRelevantOnes:
765	return self.caseClosed(oCaseFile);
766	return False;
767
768	def extractGuestCpuStack(self, sInfoText):
769	"""
770	Extracts the guest CPU stacks from the input file.
771
772	Returns a dictionary keyed by the CPU number, value being a list of
773	raw stack lines (no header).
774	Returns empty dictionary if no stacks where found.
775	"""
776	dRet = {};
777	off = 0;
778	while True:
779	# Find the stack.
780	offStart = sInfoText.find('=== start guest stack VCPU ', off);
781	if offStart < 0:
782	break;
783	offEnd = sInfoText.find('=== end guest stack', offStart + 20);
784	if offEnd >= 0:
785	offEnd += 3;
786	else:
787	offEnd = sInfoText.find('=== start guest stack VCPU', offStart + 20);
788	if offEnd < 0:
789	offEnd = len(sInfoText);
790
791	sStack = sInfoText[offStart : offEnd];
792	sStack = sStack.replace('\r',''); # paranoia
793	asLines = sStack.split('\n');
794
795	# Figure the CPU.
796	asWords = asLines[0].split();
797	if len(asWords) < 6 or not asWords[5].isdigit():
798	break;
799	iCpu = int(asWords[5]);
800
801	# Add it and advance.
802	dRet[iCpu] = [sLine.rstrip() for sLine in asLines[2:-1]]
803	off = offEnd;
804	return dRet;
805
806	def investigateInfoKvmLockSpinning(self, oCaseFile, sInfoText, dLogs):
807	""" Investigates kvm_lock_spinning deadlocks """
808	#
809	# Extract the stacks. We need more than one CPU to create a deadlock.
810	#
811	dStacks = self.extractGuestCpuStack(sInfoText);
812	self.dprint('kvm_lock_spinning: found %s stacks' % (len(dStacks),));
813	if len(dStacks) >= 2:
814	#
815	# Examin each of the stacks. Each must have kvm_lock_spinning in
816	# one of the first three entries.
817	#
818	cHits = 0;
819	for iCpu in dStacks:
820	asBacktrace = dStacks[iCpu];
821	for iFrame in xrange(min(3, len(asBacktrace))):
822	if asBacktrace[iFrame].find('kvm_lock_spinning') >= 0:
823	cHits += 1;
824	break;
825	self.dprint('kvm_lock_spinning: %s/%s hits' % (cHits, len(dStacks),));
826	if cHits == len(dStacks):
827	return (True, self.ktReason_VMM_kvm_lock_spinning);
828
829	_ = dLogs; _ = oCaseFile;
830	return (False, None);
831
832	## Things we search a main or VM log for to figure out why something went bust.
833	katSimpleMainAndVmLogReasons = [
834	# ( Whether to stop on hit, reason tuple, needle text. )
835	( False, ktReason_Guru_Generic, 'GuruMeditation' ),
836	( False, ktReason_Guru_Generic, 'Guru Meditation' ),
837	( True, ktReason_Guru_VERR_IEM_INSTR_NOT_IMPLEMENTED, 'VERR_IEM_INSTR_NOT_IMPLEMENTED' ),
838	( True, ktReason_Guru_VERR_IEM_ASPECT_NOT_IMPLEMENTED, 'VERR_IEM_ASPECT_NOT_IMPLEMENTED' ),
839	( True, ktReason_Guru_VERR_TRPM_DONT_PANIC, 'VERR_TRPM_DONT_PANIC' ),
840	( True, ktReason_Guru_VERR_PGM_PHYS_PAGE_RESERVED, 'VERR_PGM_PHYS_PAGE_RESERVED' ),
841	( True, ktReason_Guru_VERR_VMX_INVALID_GUEST_STATE, 'VERR_VMX_INVALID_GUEST_STATE' ),
842	( True, ktReason_Guru_VINF_EM_TRIPLE_FAULT, 'VINF_EM_TRIPLE_FAULT' ),
843	( True, ktReason_Networking_Nonexistent_host_nic,
844	'rc=E_FAIL text="Nonexistent host networking interface, name \'eth0\' (VERR_INTERNAL_ERROR)"' ),
845	( True, ktReason_Host_Reboot_OSX_Watchdog_Timeout, ': "OSX Watchdog Timeout: ' ),
846	( False, ktReason_XPCOM_NS_ERROR_CALL_FAILED,
847	'Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))' ),
848	( True, ktReason_Host_HostMemoryLow, 'HostMemoryLow' ),
849	( True, ktReason_Host_HostMemoryLow, 'Failed to procure handy pages; rc=VERR_NO_MEMORY' ),
850	( True, ktReason_Unknown_File_Not_Found,
851	'Error: failed to start machine. Error message: File not found. (VERR_FILE_NOT_FOUND)' ),
852	( True, ktReason_Unknown_File_Not_Found, # lump it in with file-not-found for now.
853	'Error: failed to start machine. Error message: Not supported. (VERR_NOT_SUPPORTED)' ),
854	( False, ktReason_Unknown_VM_Crash, 'txsDoConnectViaTcp: Machine state: Aborted' ),
855	( True, ktReason_Host_Modprobe_Failed, 'Kernel driver not installed' )
856	];
857
858	## Things we search a VBoxHardening.log file for to figure out why something went bust.
859	katSimpleVBoxHardeningLogReasons = [
860	# ( Whether to stop on hit, reason tuple, needle text. )
861	( True, ktReason_Host_DriverNotLoaded, 'Error opening VBoxDrvStub: STATUS_OBJECT_NAME_NOT_FOUND' ),
862	( True, ktReason_Host_NotSignedWithBuildCert, 'Not signed with the build certificate' ),
863	];
864
865	## Things we search a kernel.log file for to figure out why something went bust.
866	katSimpleKernelLogReasons = [
867	# ( Whether to stop on hit, reason tuple, needle text. )
868	( True, ktReason_Panic_HugeMemory, 'mm/huge_memory.c:1988' ),
869	( True, ktReason_Panic_IOAPICDoesntWork, 'IO-APIC + timer doesn''t work' ),
870	( True, ktReason_Panic_TxUnitHang, 'Detected Tx Unit Hang' ),
871	];
872
873	## Things we search the _RIGHT_ _STRIPPED_ vgatext for.
874	katSimpleVgaTextReasons = [
875	# ( Whether to stop on hit, reason tuple, needle text. )
876	( True, ktReason_Panic_MP_BIOS_IO_APIC,
877	"..MP-BIOS bug: 8254 timer not connected to IO-APIC\n\n" ),
878	( True, ktReason_Panic_MP_BIOS_IO_APIC,
879	"..MP-BIOS bug: 8254 timer not connected to IO-APIC\n"
880	"...trying to set up timer (IRQ0) through the 8259A ... failed.\n"
881	"...trying to set up timer as Virtual Wire IRQ... failed.\n"
882	"...trying to set up timer as ExtINT IRQ... failed :(.\n"
883	"Kernel panic - not syncing: IO-APIC + timer doesn't work! Boot with apic=debug\n"
884	"and send a report. Then try booting with the 'noapic' option\n"
885	"\n" ),
886	( True, ktReason_OSInstall_GRUB_hang,
887	"-----\nGRUB Loading stage2..\n\n\n\n" ),
888	( True, ktReason_Panic_BootManagerC000000F,
889	"Windows failed to start. A recent hardware or software change might be the" ),
890	( True, ktReason_BootManager_Image_corrupt,
891	"BOOTMGR image is corrupt. The system cannot boot." ),
892	];
893
894	## Things we search for in the info.txt file. Require handlers for now.
895	katInfoTextHandlers = [
896	# ( Trigger text, handler method )
897	( "kvm_lock_spinning", investigateInfoKvmLockSpinning ),
898	];
899
900	## Mapping screenshot/failure SHA-256 hashes to failure reasons.
901	katSimpleScreenshotHashReasons = [
902	# ( Whether to stop on hit, reason tuple, lowercased sha-256 of PIL.Image.tostring output )
903	( True, ktReason_BSOD_Recovery, '576f8e38d62b311cac7e3dc3436a0d0b9bd8cfd7fa9c43aafa95631520a45eac' ),
904	( True, ktReason_BSOD_Automatic_Repair, 'c6a72076cc619937a7a39cfe9915b36d94cee0d4e3ce5ce061485792dcee2749' ),
905	( True, ktReason_BSOD_Automatic_Repair, '26c4d8a724ff2c5e1051f3d5b650dbda7b5fdee0aa3e3c6059797f7484a515df' ),
906	( True, ktReason_BSOD_000000D1, '134621281f00a3f8aeeb7660064bffbf6187ed56d5852142328d0bcb18ef0ede' ),
907	( True, ktReason_BSOD_000000D1, '279f11258150c9d2fef041eca65501f3141da8df39256d8f6377e897e3b45a93' ),
908	( True, ktReason_BSOD_C0000225, 'bd13a144be9dcdfb16bc863ff4c8f02a86e263c174f2cd5ffd27ca5f3aa31789' ),
909	( True, ktReason_BSOD_C0000225, '8348b465e7ee9e59dd4e785880c57fd8677de05d11ac21e786bfde935307b42f' ),
910	( True, ktReason_BSOD_C0000225, '1316e1fc818a73348412788e6910b8c016f237d8b4e15b20caf4a866f7a7840e' ),
911	( True, ktReason_BSOD_C0000225, '54e0acbff365ce20a85abbe42bcd53647b8b9e80c68e45b2cd30e86bf177a0b5' ),
912	( True, ktReason_BSOD_C0000225, '50fec50b5199923fa48b3f3e782687cc381e1c8a788ebda14e6a355fbe3bb1b3' ),
913	];
914
915	def investigateVMResult(self, oCaseFile, oFailedResult, sResultLog):
916	"""
917	Investigates a failed VM run.
918	"""
919
920	def investigateLogSet():
921	"""
922	Investigates the current set of VM related logs.
923	"""
924	self.dprint('investigateLogSet: lengths: result log %u, VM log %u, kernel log %u, vga text %u, info text %u'
925	% ( len(sResultLog if sResultLog else ''),
926	len(sVMLog if sVMLog else ''),
927	len(sKrnlLog if sKrnlLog else ''),
928	len(sVgaText if sVgaText else ''),
929	len(sInfoText if sInfoText else ''), ));
930
931	#self.dprint(u'main.log<<<\n%s\n<<<\n' % (sResultLog,));
932	#self.dprint(u'vbox.log<<<\n%s\n<<<\n' % (sVMLog,));
933	#self.dprint(u'krnl.log<<<\n%s\n<<<\n' % (sKrnlLog,));
934	#self.dprint(u'vgatext.txt<<<\n%s\n<<<\n' % (sVgaText,));
935	#self.dprint(u'info.txt<<<\n%s\n<<<\n' % (sInfoText,));
936
937	# TODO: more
938
939	#
940	# Look for BSODs. Some stupid stupid inconsistencies in reason and log messages here, so don't try prettify this.
941	#
942	sDetails = self.findInAnyAndReturnRestOfLine([ sVMLog, sResultLog ],
943	'GIM: HyperV: Guest indicates a fatal condition! P0=');
944	if sDetails is not None:
945	# P0=%#RX64 P1=%#RX64 P2=%#RX64 P3=%#RX64 P4=%#RX64 "
946	sKey = sDetails.split(' ', 1)[0];
947	try: sKey = '0x%08X' % (int(sKey, 16),);
948	except: pass;
949	if sKey in self.asBsodReasons:
950	tReason = ( self.ksBsodCategory, sKey );
951	elif sKey.lower() in self.asBsodReasons: # just in case.
952	tReason = ( self.ksBsodCategory, sKey.lower() );
953	else:
954	self.dprint(u'BSOD "%s" not found in %s;' % (sKey, self.asBsodReasons));
955	tReason = ( self.ksBsodCategory, self.ksBsodAddNew );
956	return oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = sDetails.strip());
957
958	#
959	# Look for linux panic.
960	#
961	if sKrnlLog is not None:
962	for fStopOnHit, tReason, sNeedle in self.katSimpleKernelLogReasons:
963	if sKrnlLog.find(sNeedle) > 0:
964	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
965	if fStopOnHit:
966	return True;
967	fFoundSomething = True;
968
969	#
970	# Loop thru the simple stuff.
971	#
972	fFoundSomething = False;
973	for fStopOnHit, tReason, sNeedle in self.katSimpleMainAndVmLogReasons:
974	if sResultLog.find(sNeedle) > 0 or (sVMLog is not None and sVMLog.find(sNeedle) > 0):
975	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
976	if fStopOnHit:
977	return True;
978	fFoundSomething = True;
979
980	# Continue with vga text.
981	if sVgaText:
982	for fStopOnHit, tReason, sNeedle in self.katSimpleVgaTextReasons:
983	if sVgaText.find(sNeedle) > 0:
984	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
985	if fStopOnHit:
986	return True;
987	fFoundSomething = True;
988	_ = sInfoText;
989
990	# Continue with screen hashes.
991	if sScreenHash is not None:
992	for fStopOnHit, tReason, sHash in self.katSimpleScreenshotHashReasons:
993	if sScreenHash == sHash:
994	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
995	if fStopOnHit:
996	return True;
997	fFoundSomething = True;
998
999	# Check VBoxHardening.log.
1000	if sNtHardLog is not None:
1001	for fStopOnHit, tReason, sNeedle in self.katSimpleVBoxHardeningLogReasons:
1002	if sNtHardLog.find(sNeedle) > 0:
1003	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
1004	if fStopOnHit:
1005	return True;
1006	fFoundSomething = True;
1007
1008	#
1009	# Complicated stuff.
1010	#
1011	dLogs = {
1012	'sVMLog': sVMLog,
1013	'sNtHardLog': sNtHardLog,
1014	'sScreenHash': sScreenHash,
1015	'sKrnlLog': sKrnlLog,
1016	'sVgaText': sVgaText,
1017	'sInfoText': sInfoText,
1018	};
1019
1020	# info.txt.
1021	if sInfoText:
1022	for sNeedle, fnHandler in self.katInfoTextHandlers:
1023	if sInfoText.find(sNeedle) > 0:
1024	(fStop, tReason) = fnHandler(self, oCaseFile, sInfoText, dLogs);
1025	if tReason is not None:
1026	oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
1027	if fStop:
1028	return True;
1029	fFoundSomething = True;
1030
1031	#
1032	# Check for repeated reboots...
1033	#
1034	if sVMLog is not None:
1035	cResets = sVMLog.count('Changing the VM state from \'RUNNING\' to \'RESETTING\'');
1036	if cResets > 10:
1037	return oCaseFile.noteReasonForId(self.ktReason_Unknown_Reboot_Loop, oFailedResult.idTestResult,
1038	sComment = 'Counted %s reboots' % (cResets,));
1039
1040	return fFoundSomething;
1041
1042	#
1043	# Check if we got any VM or/and kernel logs. Treat them as sets in
1044	# case we run multiple VMs here (this is of course ASSUMING they
1045	# appear in the order that terminateVmBySession uploads them).
1046	#
1047	cTimes = 0;
1048	sVMLog = None;
1049	sNtHardLog = None;
1050	sScreenHash = None;
1051	sKrnlLog = None;
1052	sVgaText = None;
1053	sInfoText = None;
1054	for oFile in oFailedResult.aoFiles:
1055	if oFile.sKind == TestResultFileData.ksKind_LogReleaseVm:
1056	if 'VBoxHardening.log' not in oFile.sFile:
1057	if sVMLog is not None:
1058	if investigateLogSet() is True:
1059	return True;
1060	cTimes += 1;
1061	sInfoText = None;
1062	sVgaText = None;
1063	sKrnlLog = None;
1064	sScreenHash = None;
1065	sNtHardLog = None;
1066	sVMLog = oCaseFile.getLogFile(oFile);
1067	else:
1068	sNtHardLog = oCaseFile.getLogFile(oFile);
1069	elif oFile.sKind == TestResultFileData.ksKind_LogGuestKernel:
1070	sKrnlLog = oCaseFile.getLogFile(oFile);
1071	elif oFile.sKind == TestResultFileData.ksKind_InfoVgaText:
1072	sVgaText = '\n'.join([sLine.rstrip() for sLine in oCaseFile.getLogFile(oFile).split('\n')]);
1073	elif oFile.sKind == TestResultFileData.ksKind_InfoCollection:
1074	sInfoText = oCaseFile.getLogFile(oFile);
1075	elif oFile.sKind == TestResultFileData.ksKind_ScreenshotFailure:
1076	sScreenHash = oCaseFile.getScreenshotSha256(oFile);
1077	if sScreenHash is not None:
1078	sScreenHash = sScreenHash.lower();
1079	self.vprint(u'%s %s' % ( sScreenHash, oFile.sFile,));
1080
1081	if ( sVMLog is not None \
1082	or sNtHardLog is not None \
1083	or cTimes == 0) \
1084	and investigateLogSet() is True:
1085	return True;
1086
1087	return None;
1088
1089
1090	def isResultFromVMRun(self, oFailedResult, sResultLog):
1091	"""
1092	Checks if this result and corresponding log snippet looks like a VM run.
1093	"""
1094
1095	# Look for startVmEx/ startVmAndConnectToTxsViaTcp and similar output in the log.
1096	if sResultLog.find(' startVm') > 0:
1097	return True;
1098
1099	# Any other indicators? No?
1100	_ = oFailedResult;
1101	return False;
1102
1103	def investigateVBoxVMTest(self, oCaseFile, fSingleVM):
1104	"""
1105	Checks out a VBox VM test.
1106
1107	This is generic investigation of a test running one or more VMs, like
1108	for example a smoke test or a guest installation test.
1109
1110	The fSingleVM parameter is a hint, which probably won't come in useful.
1111	"""
1112	_ = fSingleVM;
1113
1114	#
1115	# Get a list of test result failures we should be looking into and the main log.
1116	#
1117	aoFailedResults = oCaseFile.oTree.getListOfFailures();
1118	sMainLog = oCaseFile.getMainLog();
1119
1120	#
1121	# There are a set of errors ending up on the top level result record.
1122	# Should deal with these first.
1123	#
1124	if len(aoFailedResults) == 1 and aoFailedResults[0] == oCaseFile.oTree:
1125	# Check if we've just got that XPCOM client smoke test shutdown issue. This will currently always
1126	# be reported on the top result because vboxinstall.py doesn't add an error for it. It is easy to
1127	# ignore other failures in the test if we're not a little bit careful here.
1128	if sMainLog.find('vboxinstaller: Exit code: -11 (') > 0:
1129	oCaseFile.noteReason(self.ktReason_XPCOM_Exit_Minus_11);
1130	return self.caseClosed(oCaseFile);
1131
1132	# Hang after starting VBoxSVC (e.g. idTestSet=136307258)
1133	if self.isThisFollowedByTheseLines(sMainLog, 'oVBoxMgr=<vboxapi.VirtualBoxManager object at',
1134	(' Timeout: ', ' Attempting to abort child...',) ):
1135	if sMainLog.find('* glibc detected * /') > 0:
1136	oCaseFile.noteReason(self.ktReason_XPCOM_VBoxSVC_Hang_Plus_Heap_Corruption);
1137	else:
1138	oCaseFile.noteReason(self.ktReason_XPCOM_VBoxSVC_Hang);
1139	return self.caseClosed(oCaseFile);
1140
1141	# Look for heap corruption without visible hang.
1142	if sMainLog.find('* glibc detected * /') > 0 \
1143	or sMainLog.find("-1073740940") > 0: # STATUS_HEAP_CORRUPTION / 0xc0000374
1144	oCaseFile.noteReason(self.ktReason_Unknown_Heap_Corruption);
1145	return self.caseClosed(oCaseFile);
1146
1147	# Out of memory w/ timeout.
1148	if sMainLog.find('sErrId=HostMemoryLow') > 0:
1149	oCaseFile.noteReason(self.ktReason_Host_HostMemoryLow);
1150	return self.caseClosed(oCaseFile);
1151
1152	# Stale files like vts_rm.exe (windows).
1153	offEnd = sMainLog.rfind('* The test driver exits successfully. *');
1154	if offEnd > 0 and sMainLog.find('[Error 145] The directory is not empty: ', offEnd) > 0:
1155	oCaseFile.noteReason(self.ktReason_Ignore_Stale_Files);
1156	return self.caseClosed(oCaseFile);
1157
1158	#
1159	# XPCOM screwup
1160	#
1161	if sMainLog.find('AttributeError: \'NoneType\' object has no attribute \'addObserver\'') > 0:
1162	oCaseFile.noteReason(self.ktReason_Buggy_Build_Broken_Build);
1163	return self.caseClosed(oCaseFile);
1164
1165	#
1166	# Go thru each failed result.
1167	#
1168	for oFailedResult in aoFailedResults:
1169	self.dprint(u'Looking at test result #%u - %s' % (oFailedResult.idTestResult, oFailedResult.getFullName(),));
1170	sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
1171	if oFailedResult.sName == 'Installing VirtualBox':
1172	self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = True)
1173
1174	elif oFailedResult.sName == 'Uninstalling VirtualBox':
1175	self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = False)
1176
1177	elif self.isResultFromVMRun(oFailedResult, sResultLog):
1178	self.investigateVMResult(oCaseFile, oFailedResult, sResultLog);
1179
1180	elif sResultLog.find('Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))') > 0:
1181	oCaseFile.noteReasonForId(self.ktReason_XPCOM_NS_ERROR_CALL_FAILED, oFailedResult.idTestResult);
1182
1183	elif sResultLog.find('The machine is not mutable (state is ') > 0:
1184	self.vprint('Ignoring "machine not mutable" error as it is probably due to an earlier problem');
1185	oCaseFile.noteReasonForId(self.ktHarmless, oFailedResult.idTestResult);
1186
1187	elif sResultLog.find('** error: no action was specified') > 0 \
1188	or sResultLog.find('(len(self._asXml, asText))') > 0:
1189	oCaseFile.noteReasonForId(self.ktReason_Ignore_Buggy_Test_Driver, oFailedResult.idTestResult);
1190
1191	else:
1192	self.vprint(u'TODO: Cannot place idTestResult=%u - %s' % (oFailedResult.idTestResult, oFailedResult.sName,));
1193	self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
1194
1195	#
1196	# Report home and close the case if we got them all, otherwise log it.
1197	#
1198	if len(oCaseFile.dReasonForResultId) >= len(aoFailedResults):
1199	return self.caseClosed(oCaseFile);
1200
1201	if oCaseFile.dReasonForResultId:
1202	self.vprint(u'TODO: Got %u out of %u - close, but no cigar. :-/'
1203	% (len(oCaseFile.dReasonForResultId), len(aoFailedResults)));
1204	else:
1205	self.vprint(u'XXX: Could not figure out anything at all! :-(');
1206	return False;
1207
1208
1209	def reasoningFailures(self):
1210	"""
1211	Guess the reason for failures.
1212	"""
1213	#
1214	# Get a list of failed test sets without any assigned failure reason.
1215	#
1216	cGot = 0;
1217	aoTestSets = self.oTestSetLogic.fetchFailedSetsWithoutReason(cHoursBack = self.oConfig.cHoursBack, tsNow = self.tsNow);
1218	for oTestSet in aoTestSets:
1219	self.dprint(u'');
1220	self.dprint(u'reasoningFailures: Checking out test set #%u, status %s' % ( oTestSet.idTestSet, oTestSet.enmStatus,))
1221
1222	#
1223	# Open a case file and assign it to the right investigator.
1224	#
1225	(oTree, _ ) = self.oTestResultLogic.fetchResultTree(oTestSet.idTestSet);
1226	oBuild = BuildDataEx().initFromDbWithId( self.oDb, oTestSet.idBuild, oTestSet.tsCreated);
1227	oTestBox = TestBoxData().initFromDbWithGenId( self.oDb, oTestSet.idGenTestBox);
1228	oTestGroup = TestGroupData().initFromDbWithId( self.oDb, oTestSet.idTestGroup, oTestSet.tsCreated);
1229	oTestCase = TestCaseDataEx().initFromDbWithGenId( self.oDb, oTestSet.idGenTestCase, oTestSet.tsConfig);
1230
1231	oCaseFile = VirtualTestSheriffCaseFile(self, oTestSet, oTree, oBuild, oTestBox, oTestGroup, oTestCase);
1232
1233	if oTestSet.enmStatus == TestSetData.ksTestStatus_BadTestBox:
1234	self.dprint(u'investigateBadTestBox is taking over %s.' % (oCaseFile.sLongName,));
1235	fRc = self.investigateBadTestBox(oCaseFile);
1236
1237	elif oCaseFile.isVBoxUnitTest():
1238	self.dprint(u'investigateVBoxUnitTest is taking over %s.' % (oCaseFile.sLongName,));
1239	fRc = self.investigateVBoxUnitTest(oCaseFile);
1240
1241	elif oCaseFile.isVBoxInstallTest():
1242	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1243	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1244
1245	elif oCaseFile.isVBoxUSBTest():
1246	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1247	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1248
1249	elif oCaseFile.isVBoxStorageTest():
1250	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1251	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1252
1253	elif oCaseFile.isVBoxGAsTest():
1254	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1255	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1256
1257	elif oCaseFile.isVBoxAPITest():
1258	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1259	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1260
1261	elif oCaseFile.isVBoxBenchmarkTest():
1262	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1263	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = False);
1264
1265	elif oCaseFile.isVBoxSmokeTest():
1266	self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1267	fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = False);
1268
1269	else:
1270	self.vprint(u'reasoningFailures: Unable to classify test set: %s' % (oCaseFile.sLongName,));
1271	fRc = False;
1272	cGot += fRc is True;
1273
1274	self.vprint(u'reasoningFailures: Got %u out of %u' % (cGot, len(aoTestSets), ));
1275	return 0;
1276
1277
1278	def main(self):
1279	"""
1280	The 'main' function.
1281	Return exit code (0, 1, etc).
1282	"""
1283	# Database stuff.
1284	self.oDb = TMDatabaseConnection()
1285	self.oTestResultLogic = TestResultLogic(self.oDb);
1286	self.oTestSetLogic = TestSetLogic(self.oDb);
1287	self.oFailureReasonLogic = FailureReasonLogic(self.oDb);
1288	self.oTestResultFailureLogic = TestResultFailureLogic(self.oDb);
1289	self.asBsodReasons = self.oFailureReasonLogic.fetchForSheriffByNamedCategory(self.ksBsodCategory);
1290	self.asUnitTestReasons = self.oFailureReasonLogic.fetchForSheriffByNamedCategory(self.ksUnitTestCategory);
1291
1292	# Get a fix on our 'now' before we do anything..
1293	self.oDb.execute('SELECT CURRENT_TIMESTAMP - interval \'%s hours\'', (self.oConfig.cStartHoursAgo,));
1294	self.tsNow = self.oDb.fetchOne();
1295
1296	# If we're suppost to commit anything we need to get our user ID.
1297	rcExit = 0;
1298	if self.oConfig.fRealRun:
1299	self.oLogin = UserAccountLogic(self.oDb).tryFetchAccountByLoginName(VirtualTestSheriff.ksLoginName);
1300	if self.oLogin is None:
1301	rcExit = self.eprint('Cannot find my user account "%s"!' % (VirtualTestSheriff.ksLoginName,));
1302	else:
1303	self.uidSelf = self.oLogin.uid;
1304
1305	#
1306	# Do the stuff.
1307	#
1308	if rcExit == 0:
1309	rcExit = self.selfCheck();
1310	if rcExit == 0:
1311	rcExit = self.badTestBoxManagement();
1312	rcExit2 = self.reasoningFailures();
1313	if rcExit == 0:
1314	rcExit = rcExit2;
1315	# Redo the bad testbox management after failure reasons have been assigned (got timing issues).
1316	if rcExit == 0:
1317	rcExit = self.badTestBoxManagement();
1318
1319	# Cleanup.
1320	self.oFailureReasonLogic = None;
1321	self.oTestResultFailureLogic = None;
1322	self.oTestSetLogic = None;
1323	self.oTestResultLogic = None;
1324	self.oDb.close();
1325	self.oDb = None;
1326	if self.oLogFile is not None:
1327	self.oLogFile.close();
1328	self.oLogFile = None;
1329	return rcExit;
1330
1331	if __name__ == '__main__':
1332	sys.exit(VirtualTestSheriff().main());
1333

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

source: vbox/trunk/src/VBox/ValidationKit/testmanager/batch/virtual_test_sheriff.py@ 67152

Download in other formats: