virtual_test_sheriff.py@ 74978

Last change on this file since 74978 was 73145, checked in by vboxsync, 7 years ago
ValidationKit/virtual_test_sheriff: more compiz crash symptoms
Property svn:eol-style set to `LF` Property svn:executable set to ``* Property svn:keywords set to `Author Date Id Revision`
File size: 66.2 KB

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

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

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

Download in other formats: