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