VirtualBox

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

Last change on this file since 98589 was 98589, checked in by vboxsync, 2 years ago

vsheriff: General guest control failure reason if we couldn't find anything more specific.

  • Property svn:eol-style set to LF
  • Property svn:executable set to *
  • Property svn:keywords set to Author Date Id Revision
File size: 91.6 KB
Line 
1#!/usr/bin/env python
2# -*- coding: utf-8 -*-
3# $Id: virtual_test_sheriff.py 98589 2023-02-15 13:43:42Z vboxsync $
4# pylint: disable=line-too-long
5
6"""
7Virtual Test Sheriff.
8
9Duties:
10 - Try to a assign failure reasons to recently failed tests.
11 - Reboot or disable bad test boxes.
12
13"""
14
15from __future__ import print_function;
16
17__copyright__ = \
18"""
19Copyright (C) 2012-2023 Oracle and/or its affiliates.
20
21This file is part of VirtualBox base platform packages, as
22available from https://www.virtualbox.org.
23
24This program is free software; you can redistribute it and/or
25modify it under the terms of the GNU General Public License
26as published by the Free Software Foundation, in version 3 of the
27License.
28
29This program is distributed in the hope that it will be useful, but
30WITHOUT ANY WARRANTY; without even the implied warranty of
31MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
32General Public License for more details.
33
34You should have received a copy of the GNU General Public License
35along with this program; if not, see <https://www.gnu.org/licenses>.
36
37The contents of this file may alternatively be used under the terms
38of the Common Development and Distribution License Version 1.0
39(CDDL), a copy of it is provided in the "COPYING.CDDL" file included
40in the VirtualBox distribution, in which case the provisions of the
41CDDL are applicable instead of those of the GPL.
42
43You may elect to license modified versions of this file under the
44terms and conditions of either the GPL or the CDDL or both.
45
46SPDX-License-Identifier: GPL-3.0-only OR CDDL-1.0
47"""
48__version__ = "$Revision: 98589 $"
49
50
51# Standard python imports
52import hashlib;
53import os;
54import re;
55import smtplib;
56#import subprocess;
57import sys;
58from email.mime.multipart import MIMEMultipart;
59from email.mime.text import MIMEText;
60from email.utils import COMMASPACE;
61
62if sys.version_info[0] >= 3:
63 from io import BytesIO as BytesIO; # pylint: disable=import-error,no-name-in-module,useless-import-alias
64else:
65 from StringIO import StringIO as BytesIO; # pylint: disable=import-error,no-name-in-module,useless-import-alias
66from optparse import OptionParser; # pylint: disable=deprecated-module
67from PIL import Image; # pylint: disable=import-error
68
69# Add Test Manager's modules path
70g_ksTestManagerDir = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))));
71sys.path.append(g_ksTestManagerDir);
72
73# Test Manager imports
74from common import utils;
75from testmanager.core.db import TMDatabaseConnection;
76from testmanager.core.build import BuildDataEx;
77from testmanager.core.failurereason import FailureReasonLogic;
78from testmanager.core.testbox import TestBoxLogic, TestBoxData;
79from testmanager.core.testcase import TestCaseDataEx;
80from testmanager.core.testgroup import TestGroupData;
81from testmanager.core.testset import TestSetLogic, TestSetData;
82from testmanager.core.testresults import TestResultLogic, TestResultFileData;
83from testmanager.core.testresultfailures import TestResultFailureLogic, TestResultFailureData;
84from testmanager.core.useraccount import UserAccountLogic;
85from testmanager.config import g_ksSmtpHost, g_kcSmtpPort, g_ksAlertFrom, \
86 g_ksAlertSubject, g_asAlertList #, g_ksLomPassword;
87
88# Python 3 hacks:
89if sys.version_info[0] >= 3:
90 xrange = range; # pylint: disable=redefined-builtin,invalid-name
91
92
93class VirtualTestSheriffCaseFile(object):
94 """
95 A failure investigation case file.
96
97 """
98
99
100 ## Max log file we'll read into memory. (256 MB)
101 kcbMaxLogRead = 0x10000000;
102
103 def __init__(self, oSheriff, oTestSet, oTree, oBuild, oTestBox, oTestGroup, oTestCase):
104 self.oSheriff = oSheriff;
105 self.oTestSet = oTestSet; # TestSetData
106 self.oTree = oTree; # TestResultDataEx
107 self.oBuild = oBuild; # BuildDataEx
108 self.oTestBox = oTestBox; # TestBoxData
109 self.oTestGroup = oTestGroup; # TestGroupData
110 self.oTestCase = oTestCase; # TestCaseDataEx
111 self.sMainLog = ''; # The main log file. Empty string if not accessible.
112 self.sSvcLog = ''; # The VBoxSVC log file. Empty string if not accessible.
113
114 # Generate a case file name.
115 self.sName = '#%u: %s' % (self.oTestSet.idTestSet, self.oTestCase.sName,)
116 self.sLongName = '#%u: "%s" on "%s" running %s %s (%s), "%s" by %s, using %s %s %s r%u' \
117 % ( self.oTestSet.idTestSet,
118 self.oTestCase.sName,
119 self.oTestBox.sName,
120 self.oTestBox.sOs,
121 self.oTestBox.sOsVersion,
122 self.oTestBox.sCpuArch,
123 self.oTestBox.sCpuName,
124 self.oTestBox.sCpuVendor,
125 self.oBuild.oCat.sProduct,
126 self.oBuild.oCat.sBranch,
127 self.oBuild.oCat.sType,
128 self.oBuild.iRevision, );
129
130 # Investigation notes.
131 self.tReason = None; # None or one of the ktReason_XXX constants.
132 self.dReasonForResultId = {}; # Reason assignments indexed by idTestResult.
133 self.dCommentForResultId = {}; # Comment assignments indexed by idTestResult.
134
135 #
136 # Reason.
137 #
138
139 def noteReason(self, tReason):
140 """ Notes down a possible reason. """
141 self.oSheriff.dprint(u'noteReason: %s -> %s' % (self.tReason, tReason,));
142 self.tReason = tReason;
143 return True;
144
145 def noteReasonForId(self, tReason, idTestResult, sComment = None):
146 """ Notes down a possible reason for a specific test result. """
147 self.oSheriff.dprint(u'noteReasonForId: %u: %s -> %s%s'
148 % (idTestResult, self.dReasonForResultId.get(idTestResult, None), tReason,
149 (u' (%s)' % (sComment,)) if sComment is not None else ''));
150 self.dReasonForResultId[idTestResult] = tReason;
151 if sComment is not None:
152 self.dCommentForResultId[idTestResult] = sComment;
153 return True;
154
155
156 #
157 # Test classification.
158 #
159
160 def isVBoxTest(self):
161 """ Test classification: VirtualBox (using the build) """
162 return self.oBuild.oCat.sProduct.lower() in [ 'virtualbox', 'vbox' ];
163
164 def isVBoxUnitTest(self):
165 """ Test case classification: The unit test doing all our testcase/*.cpp stuff. """
166 return self.isVBoxTest() \
167 and (self.oTestCase.sName.lower() == 'unit tests' or self.oTestCase.sName.lower().startswith('misc: unit tests'));
168
169 def isVBoxInstallTest(self):
170 """ Test case classification: VirtualBox Guest installation test. """
171 return self.isVBoxTest() \
172 and self.oTestCase.sName.lower().startswith('install:');
173
174 def isVBoxUnattendedInstallTest(self):
175 """ Test case classification: VirtualBox Guest installation test. """
176 return self.isVBoxTest() \
177 and self.oTestCase.sName.lower().startswith('uinstall:');
178
179 def isVBoxUSBTest(self):
180 """ Test case classification: VirtualBox USB test. """
181 return self.isVBoxTest() \
182 and self.oTestCase.sName.lower().startswith('usb:');
183
184 def isVBoxStorageTest(self):
185 """ Test case classification: VirtualBox Storage test. """
186 return self.isVBoxTest() \
187 and self.oTestCase.sName.lower().startswith('storage:');
188
189 def isVBoxGAsTest(self):
190 """ Test case classification: VirtualBox Guest Additions test. """
191 return self.isVBoxTest() \
192 and ( self.oTestCase.sName.lower().startswith('guest additions')
193 or self.oTestCase.sName.lower().startswith('ga\'s tests'));
194
195 def isVBoxAPITest(self):
196 """ Test case classification: VirtualBox API test. """
197 return self.isVBoxTest() \
198 and self.oTestCase.sName.lower().startswith('api:');
199
200 def isVBoxBenchmarkTest(self):
201 """ Test case classification: VirtualBox Benchmark test. """
202 return self.isVBoxTest() \
203 and self.oTestCase.sName.lower().startswith('benchmark:');
204
205 def isVBoxSmokeTest(self):
206 """ Test case classification: Smoke test. """
207 return self.isVBoxTest() \
208 and self.oTestCase.sName.lower().startswith('smoketest');
209
210 def isVBoxSerialTest(self):
211 """ Test case classification: Smoke test. """
212 return self.isVBoxTest() \
213 and self.oTestCase.sName.lower().startswith('serial:');
214
215
216 #
217 # Utility methods.
218 #
219
220 def getMainLog(self):
221 """
222 Tries to read the main log file since this will be the first source of information.
223 """
224 if self.sMainLog:
225 return self.sMainLog;
226 (oFile, oSizeOrError, _) = self.oTestSet.openFile('main.log', 'rb');
227 if oFile is not None:
228 try:
229 self.sMainLog = oFile.read(min(self.kcbMaxLogRead, oSizeOrError)).decode('utf-8', 'replace');
230 except Exception as oXcpt:
231 self.oSheriff.vprint(u'Error reading main log file: %s' % (oXcpt,))
232 self.sMainLog = '';
233 else:
234 self.oSheriff.vprint(u'Error opening main log file: %s' % (oSizeOrError,));
235 return self.sMainLog;
236
237 def getLogFile(self, oFile):
238 """
239 Tries to read the given file as a utf-8 log file.
240 oFile is a TestFileDataEx instance.
241 Returns empty string if problems opening or reading the file.
242 """
243 sContent = '';
244 (oFile, oSizeOrError, _) = self.oTestSet.openFile(oFile.sFile, 'rb');
245 if oFile is not None:
246 try:
247 sContent = oFile.read(min(self.kcbMaxLogRead, oSizeOrError)).decode('utf-8', 'replace');
248 except Exception as oXcpt:
249 self.oSheriff.vprint(u'Error reading the "%s" log file: %s' % (oFile.sFile, oXcpt,))
250 else:
251 self.oSheriff.vprint(u'Error opening the "%s" log file: %s' % (oFile.sFile, oSizeOrError,));
252 return sContent;
253
254 def getSvcLog(self):
255 """
256 Tries to read the VBoxSVC log file as it typically not associated with a failing test result.
257 Note! Returns the first VBoxSVC log file we find.
258 """
259 if not self.sSvcLog:
260 aoSvcLogFiles = self.oTree.getListOfLogFilesByKind(TestResultFileData.ksKind_LogReleaseSvc);
261 if aoSvcLogFiles:
262 self.sSvcLog = self.getLogFile(aoSvcLogFiles[0]);
263 return self.sSvcLog;
264
265 def getScreenshotSha256(self, oFile):
266 """
267 Tries to read the given screenshot file, uncompress it, and do SHA-2
268 on the raw pixels.
269 Returns SHA-2 digest string on success, None on failure.
270 """
271 (oImgFile, _, _) = self.oTestSet.openFile(oFile.sFile, 'rb');
272 try:
273 abImageFile = oImgFile.read();
274 except Exception as oXcpt:
275 self.oSheriff.vprint(u'Error reading the "%s" image file: %s' % (oFile.sFile, oXcpt,))
276 else:
277 try:
278 oImage = Image.open(BytesIO(abImageFile));
279 except Exception as oXcpt:
280 self.oSheriff.vprint(u'Error opening the "%s" image bytes using PIL.Image.open: %s' % (oFile.sFile, oXcpt,))
281 else:
282 try:
283 oHash = hashlib.sha256();
284 if hasattr(oImage, 'tobytes'):
285 oHash.update(oImage.tobytes());
286 else:
287 oHash.update(oImage.tostring()); # pylint: disable=no-member
288 except Exception as oXcpt:
289 self.oSheriff.vprint(u'Error hashing the uncompressed image bytes for "%s": %s' % (oFile.sFile, oXcpt,))
290 else:
291 return oHash.hexdigest();
292 return None;
293
294
295
296 def isSingleTestFailure(self):
297 """
298 Figure out if this is a single test failing or if it's one of the
299 more complicated ones.
300 """
301 if self.oTree.cErrors == 1:
302 return True;
303 if self.oTree.deepCountErrorContributers() <= 1:
304 return True;
305 return False;
306
307
308
309class VirtualTestSheriff(object): # pylint: disable=too-few-public-methods
310 """
311 Add build info into Test Manager database.
312 """
313
314 ## The user account for the virtual sheriff.
315 ksLoginName = 'vsheriff';
316
317 def __init__(self):
318 """
319 Parse command line.
320 """
321 self.oDb = None;
322 self.tsNow = None;
323 self.oTestResultLogic = None;
324 self.oTestSetLogic = None;
325 self.oFailureReasonLogic = None; # FailureReasonLogic;
326 self.oTestResultFailureLogic = None; # TestResultFailureLogic
327 self.oLogin = None;
328 self.uidSelf = -1;
329 self.oLogFile = None;
330 self.asBsodReasons = [];
331 self.asUnitTestReasons = [];
332
333 oParser = OptionParser();
334 oParser.add_option('--start-hours-ago', dest = 'cStartHoursAgo', metavar = '<hours>', default = 0, type = 'int',
335 help = 'When to start specified as hours relative to current time. Defauls is right now.', );
336 oParser.add_option('--hours-period', dest = 'cHoursBack', metavar = '<period-in-hours>', default = 2, type = 'int',
337 help = 'Work period specified in hours. Defauls is 2 hours.');
338 oParser.add_option('--real-run-back', dest = 'fRealRun', action = 'store_true', default = False,
339 help = 'Whether to commit the findings to the database. Default is a dry run.');
340 oParser.add_option('--testset', dest = 'aidTestSets', metavar = '<id>', default = [], type = 'int', action = 'append',
341 help = 'Only investigate this one. Accumulates IDs when repeated.');
342 oParser.add_option('-q', '--quiet', dest = 'fQuiet', action = 'store_true', default = False,
343 help = 'Quiet execution');
344 oParser.add_option('-l', '--log', dest = 'sLogFile', metavar = '<logfile>', default = None,
345 help = 'Where to log messages.');
346 oParser.add_option('--debug', dest = 'fDebug', action = 'store_true', default = False,
347 help = 'Enables debug mode.');
348
349 (self.oConfig, _) = oParser.parse_args();
350
351 if self.oConfig.sLogFile:
352 self.oLogFile = open(self.oConfig.sLogFile, "a"); # pylint: disable=consider-using-with,unspecified-encoding
353 self.oLogFile.write('VirtualTestSheriff: $Revision: 98589 $ \n');
354
355
356 def eprint(self, sText):
357 """
358 Prints error messages.
359 Returns 1 (for exit code usage.)
360 """
361 print('error: %s' % (sText,));
362 if self.oLogFile is not None:
363 if sys.version_info[0] >= 3:
364 self.oLogFile.write(u'error: %s\n' % (sText,));
365 else:
366 self.oLogFile.write((u'error: %s\n' % (sText,)).encode('utf-8'));
367 return 1;
368
369 def dprint(self, sText):
370 """
371 Prints debug info.
372 """
373 if self.oConfig.fDebug:
374 if not self.oConfig.fQuiet:
375 print('debug: %s' % (sText, ));
376 if self.oLogFile is not None:
377 if sys.version_info[0] >= 3:
378 self.oLogFile.write(u'debug: %s\n' % (sText,));
379 else:
380 self.oLogFile.write((u'debug: %s\n' % (sText,)).encode('utf-8'));
381 return 0;
382
383 def vprint(self, sText):
384 """
385 Prints verbose info.
386 """
387 if not self.oConfig.fQuiet:
388 print('info: %s' % (sText,));
389 if self.oLogFile is not None:
390 if sys.version_info[0] >= 3:
391 self.oLogFile.write(u'info: %s\n' % (sText,));
392 else:
393 self.oLogFile.write((u'info: %s\n' % (sText,)).encode('utf-8'));
394 return 0;
395
396 def getFailureReason(self, tReason):
397 """ Gets the failure reason object for tReason. """
398 return self.oFailureReasonLogic.cachedLookupByNameAndCategory(tReason[1], tReason[0]);
399
400 def selfCheck(self):
401 """ Does some self checks, looking up things we expect to be in the database and such. """
402 rcExit = 0;
403 for sAttr in dir(self.__class__):
404 if sAttr.startswith('ktReason_'):
405 tReason = getattr(self.__class__, sAttr);
406 oFailureReason = self.getFailureReason(tReason);
407 if oFailureReason is None:
408 rcExit = self.eprint(u'Failed to find failure reason "%s" in category "%s" in the database!'
409 % (tReason[1], tReason[0],));
410
411 # Check the user account as well.
412 if self.oLogin is None:
413 oLogin = UserAccountLogic(self.oDb).tryFetchAccountByLoginName(VirtualTestSheriff.ksLoginName);
414 if oLogin is None:
415 rcExit = self.eprint(u'Cannot find my user account "%s"!' % (VirtualTestSheriff.ksLoginName,));
416 return rcExit;
417
418 def sendEmailAlert(self, uidAuthor, sBodyText):
419 """
420 Sends email alert.
421 """
422
423 # Get author email
424 self.oDb.execute('SELECT sEmail FROM Users WHERE uid=%s', (uidAuthor,));
425 sFrom = self.oDb.fetchOne();
426 if sFrom is not None:
427 sFrom = sFrom[0];
428 else:
429 sFrom = g_ksAlertFrom;
430
431 # Gather recipient list.
432 asEmailList = [];
433 for sUser in g_asAlertList:
434 self.oDb.execute('SELECT sEmail FROM Users WHERE sUsername=%s', (sUser,));
435 sEmail = self.oDb.fetchOne();
436 if sEmail:
437 asEmailList.append(sEmail[0]);
438 if not asEmailList:
439 return self.eprint('No email addresses to send alter to!');
440
441 # Compose the message.
442 oMsg = MIMEMultipart();
443 oMsg['From'] = sFrom;
444 oMsg['To'] = COMMASPACE.join(asEmailList);
445 oMsg['Subject'] = g_ksAlertSubject;
446 oMsg.attach(MIMEText(sBodyText, 'plain'))
447
448 # Try send it.
449 try:
450 oSMTP = smtplib.SMTP(g_ksSmtpHost, g_kcSmtpPort);
451 oSMTP.sendmail(sFrom, asEmailList, oMsg.as_string())
452 oSMTP.quit()
453 except smtplib.SMTPException as oXcpt:
454 return self.eprint('Failed to send mail: %s' % (oXcpt,));
455
456 return 0;
457
458 def badTestBoxManagement(self):
459 """
460 Looks for bad test boxes and first tries once to reboot them then disables them.
461 """
462 rcExit = 0;
463
464 #
465 # We skip this entirely if we're running in the past and not in harmless debug mode.
466 #
467 if self.oConfig.cStartHoursAgo != 0 \
468 and (not self.oConfig.fDebug or self.oConfig.fRealRun):
469 return rcExit;
470 tsNow = self.tsNow if self.oConfig.fDebug else None;
471 cHoursBack = self.oConfig.cHoursBack if self.oConfig.fDebug else 2;
472 oTestBoxLogic = TestBoxLogic(self.oDb);
473
474 #
475 # Generate a list of failures reasons we consider bad-testbox behavior.
476 #
477 aidFailureReasons = [
478 self.getFailureReason(self.ktReason_Host_DriverNotLoaded).idFailureReason,
479 self.getFailureReason(self.ktReason_Host_DriverNotUnloading).idFailureReason,
480 self.getFailureReason(self.ktReason_Host_DriverNotCompilable).idFailureReason,
481 self.getFailureReason(self.ktReason_Host_InstallationFailed).idFailureReason,
482 ];
483
484 #
485 # Get list of bad test boxes for given period and check them out individually.
486 #
487 aidBadTestBoxes = self.oTestSetLogic.fetchBadTestBoxIds(cHoursBack = cHoursBack, tsNow = tsNow,
488 aidFailureReasons = aidFailureReasons);
489 for idTestBox in aidBadTestBoxes:
490 # Skip if the testbox is already disabled or has a pending reboot command.
491 try:
492 oTestBox = TestBoxData().initFromDbWithId(self.oDb, idTestBox);
493 except Exception as oXcpt:
494 rcExit = self.eprint('Failed to get data for test box #%u in badTestBoxManagement: %s' % (idTestBox, oXcpt,));
495 continue;
496 if not oTestBox.fEnabled:
497 self.dprint(u'badTestBoxManagement: Skipping test box #%u (%s) as it has been disabled already.'
498 % ( idTestBox, oTestBox.sName, ));
499 continue;
500 if oTestBox.enmPendingCmd != TestBoxData.ksTestBoxCmd_None:
501 self.dprint(u'badTestBoxManagement: Skipping test box #%u (%s) as it has a command pending: %s'
502 % ( idTestBox, oTestBox.sName, oTestBox.enmPendingCmd));
503 continue;
504
505 # Get the most recent testsets for this box (descending on tsDone) and see how bad it is.
506 aoSets = self.oTestSetLogic.fetchSetsForTestBox(idTestBox, cHoursBack = cHoursBack, tsNow = tsNow);
507 cOkay = 0;
508 cBad = 0;
509 iFirstOkay = len(aoSets);
510 for iSet, oSet in enumerate(aoSets):
511 if oSet.enmStatus == TestSetData.ksTestStatus_BadTestBox:
512 cBad += 1;
513 else:
514 # Check for bad failure reasons.
515 oFailure = None;
516 if oSet.enmStatus in TestSetData.kasBadTestStatuses:
517 (oTree, _ ) = self.oTestResultLogic.fetchResultTree(oSet.idTestSet)
518 aoFailedResults = oTree.getListOfFailures();
519 for oFailedResult in aoFailedResults:
520 oFailure = self.oTestResultFailureLogic.getById(oFailedResult.idTestResult);
521 if oFailure is not None and oFailure.idFailureReason in aidFailureReasons:
522 break;
523 oFailure = None;
524 if oFailure is not None:
525 cBad += 1;
526 else:
527 # This is an okay test result then.
528 ## @todo maybe check the elapsed time here, it could still be a bad run?
529 cOkay += 1;
530 iFirstOkay = min(iFirstOkay, iSet);
531 if iSet > 10:
532 break;
533
534 # We react if there are two or more bad-testbox statuses at the head of the
535 # history and at least three in the last 10 results.
536 if iFirstOkay >= 2 and cBad > 2:
537 if oTestBoxLogic.hasTestBoxRecentlyBeenRebooted(idTestBox, cHoursBack = cHoursBack, tsNow = tsNow):
538 sComment = u'Disabling testbox #%u (%s) - iFirstOkay=%u cBad=%u cOkay=%u' \
539 % (idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay);
540 self.vprint(sComment);
541 self.sendEmailAlert(self.uidSelf, sComment);
542 if self.oConfig.fRealRun is True:
543 try:
544 oTestBoxLogic.disableTestBox(idTestBox, self.uidSelf, fCommit = True,
545 sComment = 'Automatically disabled (iFirstOkay=%u cBad=%u cOkay=%u)'
546 % (iFirstOkay, cBad, cOkay),);
547 except Exception as oXcpt:
548 rcExit = self.eprint(u'Error disabling testbox #%u (%u): %s\n' % (idTestBox, oTestBox.sName, oXcpt,));
549 else:
550 sComment = u'Rebooting testbox #%u (%s) - iFirstOkay=%u cBad=%u cOkay=%u' \
551 % (idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay);
552 self.vprint(sComment);
553 self.sendEmailAlert(self.uidSelf, sComment);
554 if self.oConfig.fRealRun is True:
555 try:
556 oTestBoxLogic.rebootTestBox(idTestBox, self.uidSelf, fCommit = True,
557 sComment = 'Automatically rebooted (iFirstOkay=%u cBad=%u cOkay=%u)'
558 % (iFirstOkay, cBad, cOkay),);
559 except Exception as oXcpt:
560 rcExit = self.eprint(u'Error rebooting testbox #%u (%s): %s\n' % (idTestBox, oTestBox.sName, oXcpt,));
561 else:
562 self.dprint(u'badTestBoxManagement: #%u (%s) looks ok: iFirstOkay=%u cBad=%u cOkay=%u'
563 % ( idTestBox, oTestBox.sName, iFirstOkay, cBad, cOkay));
564
565 ## @todo r=bird: review + rewrite;
566 ## - no selecting here, that belongs in the core/*.py files.
567 ## - preserve existing comments.
568 ## - doing way too much in the try/except block.
569 ## - No password quoting in the sshpass command that always fails (127).
570 ## - Timeout is way to low. testboxmem1 need more than 10 min to take a dump, ages to
571 ## get thru POST and another 5 just to time out in grub. Should be an hour or so.
572 ## Besides, it need to be constant elsewhere in the file, not a variable here.
573 ##
574 ##
575 ## Reset hanged testboxes
576 ##
577 #cStatusTimeoutMins = 10;
578 #
579 #self.oDb.execute('SELECT TestBoxStatuses.idTestBox\n'
580 # ' FROM TestBoxStatuses, TestBoxes\n'
581 # ' WHERE TestBoxStatuses.tsUpdated >= (CURRENT_TIMESTAMP - interval \'%s hours\')\n'
582 # ' AND TestBoxStatuses.tsUpdated < (CURRENT_TIMESTAMP - interval \'%s minutes\')\n'
583 # ' AND TestBoxStatuses.idTestBox = TestBoxes.idTestBox\n'
584 # ' AND Testboxes.tsExpire = \'infinity\'::timestamp', (cHoursBack,cStatusTimeoutMins));
585 #for idTestBox in self.oDb.fetchAll():
586 # idTestBox = idTestBox[0];
587 # try:
588 # oTestBox = TestBoxData().initFromDbWithId(self.oDb, idTestBox);
589 # except Exception as oXcpt:
590 # rcExit = self.eprint('Failed to get data for test box #%u in badTestBoxManagement: %s' % (idTestBox, oXcpt,));
591 # continue;
592 # # Skip if the testbox is already disabled, already reset or there's no iLOM
593 # if not oTestBox.fEnabled or oTestBox.ipLom is None or oTestBox.sComment is not None and oTestBox.sComment.find('Automatically reset') >= 0:
594 # self.dprint(u'badTestBoxManagement: Skipping test box #%u (%s) as it has been disabled already.'
595 # % ( idTestBox, oTestBox.sName, ));
596 # continue;
597 # ## @todo get iLOM credentials from a table?
598 # sCmd = 'sshpass -p%s ssh -oStrictHostKeyChecking=no root@%s show /SP && reset /SYS' % (g_ksLomPassword, oTestBox.ipLom,);
599 # try:
600 # oPs = subprocess.Popen(sCmd, stdout=subprocess.PIPE, shell=True);
601 # sStdout = oPs.communicate()[0];
602 # iRC = oPs.wait();
603 #
604 # oTestBox.sComment = 'Automatically reset (iRC=%u sStdout=%s)' % (iRC, sStdout,);
605 # oTestBoxLogic.editEntry(oTestBox, self.uidSelf, fCommit = True);
606 #
607 # sComment = u'Reset testbox #%u (%s) - iRC=%u sStduot=%s' % ( idTestBox, oTestBox.sName, iRC, sStdout);
608 # self.vprint(sComment);
609 # self.sendEmailAlert(self.uidSelf, sComment);
610 #
611 # except Exception as oXcpt:
612 # rcExit = self.eprint(u'Error resetting testbox #%u (%s): %s\n' % (idTestBox, oTestBox.sName, oXcpt,));
613 #
614 return rcExit;
615
616
617 ## @name Failure reasons we know.
618 ## @{
619
620 ktReason_Add_Installer_Win_Failed = ( 'Additions', 'Win GA install' );
621 ktReason_Add_ShFl_Automount = ( 'Additions', 'Automounting' );
622 ktReason_Add_ShFl_FsPerf = ( 'Additions', 'FsPerf' );
623 ktReason_Add_ShFl_FsPerf_Abend = ( 'Additions', 'FsPerf abend' );
624 ktReason_Add_GstCtl = ( 'Additions', 'GstCtl' );
625 ktReason_Add_GstCtl_Preparations = ( 'Additions', 'GstCtl preparations' );
626 ktReason_Add_GstCtl_SessionBasics = ( 'Additions', 'Session basics' );
627 ktReason_Add_GstCtl_SessionProcRefs = ( 'Additions', 'Session process' );
628 ktReason_Add_GstCtl_Session_Reboot = ( 'Additions', 'Session reboot' );
629 ktReason_Add_GstCtl_CopyFromGuest_Timeout = ( 'Additions', 'CopyFromGuest timeout' );
630 ktReason_Add_GstCtl_CopyToGuest_Timeout = ( 'Additions', 'CopyToGuest timeout' );
631 ktReason_Add_GstCtl_CopyToGuest_DstEmpty = ( 'Additions', 'CopyToGuest dst empty' );
632 ktReason_Add_GstCtl_CopyToGuest_DstExists = ( 'Additions', 'CopyToGuest dst exists' );
633 ktReason_Add_FlushViewOfFile = ( 'Additions', 'FlushViewOfFile' );
634 ktReason_Add_Mmap_Coherency = ( 'Additions', 'mmap coherency' );
635 ktReason_BSOD_Recovery = ( 'BSOD', 'Recovery' );
636 ktReason_BSOD_Automatic_Repair = ( 'BSOD', 'Automatic Repair' );
637 ktReason_BSOD_0000007F = ( 'BSOD', '0x0000007F' );
638 ktReason_BSOD_000000D1 = ( 'BSOD', '0x000000D1' );
639 ktReason_BSOD_C0000225 = ( 'BSOD', '0xC0000225 (boot)' );
640 ktReason_Guru_Generic = ( 'Guru Meditations', 'Generic Guru Meditation' );
641 ktReason_Guru_VERR_IEM_INSTR_NOT_IMPLEMENTED = ( 'Guru Meditations', 'VERR_IEM_INSTR_NOT_IMPLEMENTED' );
642 ktReason_Guru_VERR_IEM_ASPECT_NOT_IMPLEMENTED = ( 'Guru Meditations', 'VERR_IEM_ASPECT_NOT_IMPLEMENTED' );
643 ktReason_Guru_VERR_TRPM_DONT_PANIC = ( 'Guru Meditations', 'VERR_TRPM_DONT_PANIC' );
644 ktReason_Guru_VERR_PGM_PHYS_PAGE_RESERVED = ( 'Guru Meditations', 'VERR_PGM_PHYS_PAGE_RESERVED' );
645 ktReason_Guru_VERR_VMX_INVALID_GUEST_STATE = ( 'Guru Meditations', 'VERR_VMX_INVALID_GUEST_STATE' );
646 ktReason_Guru_VINF_EM_TRIPLE_FAULT = ( 'Guru Meditations', 'VINF_EM_TRIPLE_FAULT' );
647 ktReason_Host_HostMemoryLow = ( 'Host', 'HostMemoryLow' );
648 ktReason_Host_DriverNotLoaded = ( 'Host', 'Driver not loaded' );
649 ktReason_Host_DriverNotUnloading = ( 'Host', 'Driver not unloading' );
650 ktReason_Host_DriverNotCompilable = ( 'Host', 'Driver not compilable' );
651 ktReason_Host_InstallationFailed = ( 'Host', 'Installation failed' );
652 ktReason_Host_InstallationWantReboot = ( 'Host', 'Installation want reboot' );
653 ktReason_Host_InvalidPackage = ( 'Host', 'ERROR_INSTALL_PACKAGE_INVALID' );
654 ktReason_Host_InstallSourceAbsent = ( 'Host', 'ERROR_INSTALL_SOURCE_ABSENT' );
655 ktReason_Host_NotSignedWithBuildCert = ( 'Host', 'Not signed with build cert' );
656 ktReason_Host_DiskFull = ( 'Host', 'Host disk full' );
657 ktReason_Host_DoubleFreeHeap = ( 'Host', 'Double free or corruption' );
658 ktReason_Host_LeftoverService = ( 'Host', 'Leftover service' );
659 ktReason_Host_win32com_gen_py = ( 'Host', 'win32com.gen_py' );
660 ktReason_Host_Reboot_OSX_Watchdog_Timeout = ( 'Host Reboot', 'OSX Watchdog Timeout' );
661 ktReason_Host_Modprobe_Failed = ( 'Host', 'Modprobe failed' );
662 ktReason_Host_Install_Hang = ( 'Host', 'Install hang' );
663 ktReason_Host_NetworkMisconfiguration = ( 'Host', 'Network misconfiguration' );
664 ktReason_Host_TSTInfo_Accuracy_OOR = ( 'Host', 'TSTInfo accuracy out of range' );
665 ktReason_Networking_Nonexistent_host_nic = ( 'Networking', 'Nonexistent host networking interface' );
666 ktReason_Networking_VERR_INTNET_FLT_IF_NOT_FOUND = ( 'Networking', 'VERR_INTNET_FLT_IF_NOT_FOUND' );
667 ktReason_OSInstall_GRUB_hang = ( 'O/S Install', 'GRUB hang' );
668 ktReason_OSInstall_Udev_hang = ( 'O/S Install', 'udev hang' );
669 ktReason_OSInstall_Sata_no_BM = ( 'O/S Install', 'SATA busmaster bit not set' );
670 ktReason_Panic_BootManagerC000000F = ( 'Panic', 'Hardware Changed' );
671 ktReason_Panic_MP_BIOS_IO_APIC = ( 'Panic', 'MP-BIOS/IO-APIC' );
672 ktReason_Panic_HugeMemory = ( 'Panic', 'Huge memory assertion' );
673 ktReason_Panic_IOAPICDoesntWork = ( 'Panic', 'IO-APIC and timer does not work' );
674 ktReason_Panic_TxUnitHang = ( 'Panic', 'Tx Unit Hang' );
675 ktReason_API_std_bad_alloc = ( 'API / (XP)COM', 'std::bad_alloc' );
676 ktReason_API_Digest_Mismatch = ( 'API / (XP)COM', 'Digest mismatch' );
677 ktReason_API_MoveVM_SharingViolation = ( 'API / (XP)COM', 'MoveVM sharing violation' );
678 ktReason_API_MoveVM_InvalidParameter = ( 'API / (XP)COM', 'MoveVM invalid parameter' );
679 ktReason_API_Open_Session_Failed = ( 'API / (XP)COM', 'Open session failed' );
680 ktReason_XPCOM_Exit_Minus_11 = ( 'API / (XP)COM', 'exit -11' );
681 ktReason_XPCOM_VBoxSVC_Hang = ( 'API / (XP)COM', 'VBoxSVC hang' );
682 ktReason_XPCOM_VBoxSVC_Hang_Plus_Heap_Corruption = ( 'API / (XP)COM', 'VBoxSVC hang + heap corruption' );
683 ktReason_XPCOM_NS_ERROR_CALL_FAILED = ( 'API / (XP)COM', 'NS_ERROR_CALL_FAILED' );
684 ktReason_BootManager_Image_corrupt = ( 'Unknown', 'BOOTMGR Image corrupt' );
685 ktReason_Unknown_Heap_Corruption = ( 'Unknown', 'Heap corruption' );
686 ktReason_Unknown_Reboot_Loop = ( 'Unknown', 'Reboot loop' );
687 ktReason_Unknown_File_Not_Found = ( 'Unknown', 'File not found' );
688 ktReason_Unknown_HalReturnToFirmware = ( 'Unknown', 'HalReturnToFirmware' );
689 ktReason_Unknown_VM_Crash = ( 'Unknown', 'VM crash' );
690 ktReason_Unknown_VM_Terminated = ( 'Unknown', 'VM terminated' );
691 ktReason_Unknown_VM_Start_Error = ( 'Unknown', 'VM Start Error' );
692 ktReason_Unknown_VM_Runtime_Error = ( 'Unknown', 'VM Runtime Error' );
693 ktReason_VMM_Assert = ( 'VMM', 'Assert' );
694 ktReason_VMM_kvm_lock_spinning = ( 'VMM', 'kvm_lock_spinning' );
695 ktReason_Ignore_Buggy_Test_Driver = ( 'Ignore', 'Buggy test driver' );
696 ktReason_Ignore_Stale_Files = ( 'Ignore', 'Stale files' );
697 ktReason_Buggy_Build_Broken_Build = ( 'Broken Build', 'Buggy build' );
698 ktReason_GuestBug_CompizVBoxQt = ( 'Guest Bug', 'Compiz + VirtualBox Qt GUI crash' );
699 ## @}
700
701 ## BSOD category.
702 ksBsodCategory = 'BSOD';
703 ## Special reason indicating that the flesh and blood sheriff has work to do.
704 ksBsodAddNew = 'Add new BSOD';
705
706 ## Unit test category.
707 ksUnitTestCategory = 'Unit';
708 ## Special reason indicating that the flesh and blood sheriff has work to do.
709 ksUnitTestAddNew = 'Add new';
710
711 ## Used for indica that we shouldn't report anything for this test result ID and
712 ## consider promoting the previous error to test set level if it's the only one.
713 ktHarmless = ( 'Probably', 'Caused by previous error' );
714
715
716 def caseClosed(self, oCaseFile):
717 """
718 Reports the findings in the case and closes it.
719 """
720 #
721 # Log it and create a dReasonForReasultId we can use below.
722 #
723 dCommentForResultId = oCaseFile.dCommentForResultId;
724 if oCaseFile.dReasonForResultId:
725 # Must weed out ktHarmless.
726 dReasonForResultId = {};
727 for idKey, tReason in oCaseFile.dReasonForResultId.items():
728 if tReason is not self.ktHarmless:
729 dReasonForResultId[idKey] = tReason;
730 if not dReasonForResultId:
731 self.vprint(u'TODO: Closing %s without a real reason, only %s.'
732 % (oCaseFile.sName, oCaseFile.dReasonForResultId));
733 return False;
734
735 # Try promote to single reason.
736 atValues = dReasonForResultId.values();
737 fSingleReason = True;
738 if len(dReasonForResultId) == 1 and next(iter(dReasonForResultId.keys())) != oCaseFile.oTestSet.idTestResult:
739 self.dprint(u'Promoting single reason to whole set: %s' % (next(iter(atValues)),));
740 elif len(dReasonForResultId) > 1 and len(atValues) == list(atValues).count(next(iter(atValues))):
741 self.dprint(u'Merged %d reasons to a single one: %s' % (len(atValues), next(iter(atValues))));
742 else:
743 fSingleReason = False;
744 if fSingleReason:
745 dReasonForResultId = { oCaseFile.oTestSet.idTestResult: next(iter(atValues)), };
746 if dCommentForResultId:
747 dCommentForResultId = { oCaseFile.oTestSet.idTestResult: next(iter(dCommentForResultId.values())), };
748 elif oCaseFile.tReason is not None:
749 dReasonForResultId = { oCaseFile.oTestSet.idTestResult: oCaseFile.tReason, };
750 else:
751 self.vprint(u'Closing %s without a reason - this should not happen!' % (oCaseFile.sName,));
752 return False;
753
754 self.vprint(u'Closing %s with following reason%s: %s'
755 % ( oCaseFile.sName, 's' if len(dReasonForResultId) > 1 else '', dReasonForResultId, ));
756
757 #
758 # Add the test failure reason record(s).
759 #
760 for idTestResult, tReason in dReasonForResultId.items():
761 oFailureReason = self.getFailureReason(tReason);
762 if oFailureReason is not None:
763 sComment = 'Set by $Revision: 98589 $' # Handy for reverting later.
764 if idTestResult in dCommentForResultId:
765 sComment += ': ' + dCommentForResultId[idTestResult];
766
767 oAdd = TestResultFailureData();
768 oAdd.initFromValues(idTestResult = idTestResult,
769 idFailureReason = oFailureReason.idFailureReason,
770 uidAuthor = self.uidSelf,
771 idTestSet = oCaseFile.oTestSet.idTestSet,
772 sComment = sComment,);
773 if self.oConfig.fRealRun:
774 try:
775 self.oTestResultFailureLogic.addEntry(oAdd, self.uidSelf, fCommit = True);
776 except Exception as oXcpt:
777 self.eprint(u'caseClosed: Exception "%s" while adding reason %s for %s'
778 % (oXcpt, oAdd, oCaseFile.sLongName,));
779 else:
780 self.eprint(u'caseClosed: Cannot locate failure reason: %s / %s' % ( tReason[0], tReason[1],));
781 return True;
782
783 #
784 # Tools for assiting log parsing.
785 #
786
787 @staticmethod
788 def matchFollowedByLines(sStr, off, asFollowingLines):
789 """ Worker for isThisFollowedByTheseLines. """
790
791 # Advance off to the end of the line.
792 off = sStr.find('\n', off);
793 if off < 0:
794 return False;
795 off += 1;
796
797 # Match each string with the subsequent lines.
798 for iLine, sLine in enumerate(asFollowingLines):
799 offEnd = sStr.find('\n', off);
800 if offEnd < 0:
801 return iLine + 1 == len(asFollowingLines) and sStr.find(sLine, off) < 0;
802 if sLine and sStr.find(sLine, off, offEnd) < 0:
803 return False;
804
805 # next line.
806 off = offEnd + 1;
807
808 return True;
809
810 @staticmethod
811 def isThisFollowedByTheseLines(sStr, sFirst, asFollowingLines):
812 """
813 Looks for a line contining sFirst which is then followed by lines
814 with the strings in asFollowingLines. (No newline chars anywhere!)
815 Returns True / False.
816 """
817 off = sStr.find(sFirst, 0);
818 while off >= 0:
819 if VirtualTestSheriff.matchFollowedByLines(sStr, off, asFollowingLines):
820 return True;
821 off = sStr.find(sFirst, off + 1);
822 return False;
823
824 @staticmethod
825 def findAndReturnRestOfLine(sHaystack, sNeedle):
826 """
827 Looks for sNeedle in sHaystack.
828 Returns The text following the needle up to the end of the line.
829 Returns None if not found.
830 """
831 if sHaystack is None:
832 return None;
833 off = sHaystack.find(sNeedle);
834 if off < 0:
835 return None;
836 off += len(sNeedle)
837 offEol = sHaystack.find('\n', off);
838 if offEol < 0:
839 offEol = len(sHaystack);
840 return sHaystack[off:offEol]
841
842 @staticmethod
843 def findInAnyAndReturnRestOfLine(asHaystacks, sNeedle):
844 """
845 Looks for sNeedle in zeroe or more haystacks (asHaystack).
846 Returns The text following the first needed found up to the end of the line.
847 Returns None if not found.
848 """
849 for sHaystack in asHaystacks:
850 sRet = VirtualTestSheriff.findAndReturnRestOfLine(sHaystack, sNeedle);
851 if sRet is not None:
852 return sRet;
853 return None;
854
855
856 #
857 # The investigative units.
858 #
859
860 katSimpleInstallUninstallMainLogReasons = [
861 # ( Whether to stop on hit, reason tuple, needle text. )
862 ( False, ktReason_Host_LeftoverService,
863 'SERVICE_NAME: vbox' ),
864 ( False, ktReason_Host_LeftoverService,
865 'Seems installation was skipped. Old version lurking behind? Not the fault of this build/test run!'),
866 ];
867
868 kdatSimpleInstallUninstallMainLogReasonsPerOs = {
869 'darwin': [
870 # ( Whether to stop on hit, reason tuple, needle text. )
871 ( True, ktReason_Host_DriverNotUnloading,
872 'Can\'t remove kext org.virtualbox.kext.VBoxDrv; services failed to terminate - 0xe00002c7' ),
873 ],
874 'linux': [
875 # ( Whether to stop on hit, reason tuple, needle text. )
876 ( True, ktReason_Host_DriverNotCompilable,
877 'This system is not currently set up to build kernel modules' ),
878 ( True, ktReason_Host_DriverNotCompilable,
879 'This system is currently not set up to build kernel modules' ),
880 ( True, ktReason_Host_InstallationFailed,
881 'vboxdrv.sh: failed: Look at /var/log/vbox-install.log to find out what went wrong.' ),
882 ( True, ktReason_Host_DriverNotUnloading,
883 'Cannot unload module vboxdrv'),
884 ],
885 'solaris': [
886 # ( Whether to stop on hit, reason tuple, needle text. )
887 ( True, ktReason_Host_DriverNotUnloading, 'can\'t unload the module: Device busy' ),
888 ( True, ktReason_Host_DriverNotUnloading, 'Unloading: Host module ...FAILED!' ),
889 ( True, ktReason_Host_DriverNotUnloading, 'Unloading: NetFilter (Crossbow) module ...FAILED!' ),
890 ( True, ktReason_Host_InstallationFailed, 'svcadm: Couldn\'t bind to svc.configd.' ),
891 ( True, ktReason_Host_InstallationFailed, 'pkgadd: ERROR: postinstall script did not complete successfully' ),
892 ],
893 'win': [
894 # ( Whether to stop on hit, reason tuple, needle text. )
895 ( True, ktReason_Host_InstallationWantReboot, 'ERROR_SUCCESS_REBOOT_REQUIRED' ),
896 ( False, ktReason_Host_InstallationFailed, 'Installation error.' ),
897 ( True, ktReason_Host_InvalidPackage, 'Uninstaller failed, exit code: 1620' ),
898 ( True, ktReason_Host_InstallSourceAbsent, 'Uninstaller failed, exit code: 1612' ),
899 ],
900 };
901
902
903 def investigateInstallUninstallFailure(self, oCaseFile, oFailedResult, sResultLog, fInstall):
904 """
905 Investigates an install or uninstall failure.
906
907 We lump the two together since the installation typically also performs
908 an uninstall first and will be seeing similar issues to the uninstall.
909 """
910 self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
911
912 if fInstall and oFailedResult.enmStatus == TestSetData.ksTestStatus_TimedOut:
913 oCaseFile.noteReasonForId(self.ktReason_Host_Install_Hang, oFailedResult.idTestResult)
914 return True;
915
916 atSimple = self.katSimpleInstallUninstallMainLogReasons;
917 if oCaseFile.oTestBox.sOs in self.kdatSimpleInstallUninstallMainLogReasonsPerOs:
918 atSimple = self.kdatSimpleInstallUninstallMainLogReasonsPerOs[oCaseFile.oTestBox.sOs] + atSimple;
919
920 fFoundSomething = False;
921 for fStopOnHit, tReason, sNeedle in atSimple:
922 if sResultLog.find(sNeedle) > 0:
923 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
924 if fStopOnHit:
925 return True;
926 fFoundSomething = True;
927
928 return fFoundSomething if fFoundSomething else None;
929
930
931 def investigateBadTestBox(self, oCaseFile):
932 """
933 Checks out bad-testbox statuses.
934 """
935 _ = oCaseFile;
936 return False;
937
938
939 def investigateVBoxUnitTest(self, oCaseFile):
940 """
941 Checks out a VBox unittest problem.
942 """
943
944 # Determine if this is a host or guest run before we start.
945 fRunsInGuest = '(guest)' in oCaseFile.oTestCase.sName or 'selected VMs' in oCaseFile.oTestCase.sName;
946
947 #
948 # Process simple test case failures first, using their name as reason.
949 # We do the reason management just like for BSODs.
950 #
951 cRelevantOnes = 0;
952 sMainLog = oCaseFile.getMainLog();
953 aoFailedResults = oCaseFile.oTree.getListOfFailures();
954 for oFailedResult in aoFailedResults:
955 if oFailedResult is oCaseFile.oTree:
956 self.vprint('TODO: toplevel failure');
957 cRelevantOnes += 1
958
959 elif oFailedResult.sName == 'Installing VirtualBox':
960 sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
961 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = True)
962 cRelevantOnes += 1
963
964 elif oFailedResult.sName == 'Uninstalling VirtualBox':
965 sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
966 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = False)
967 cRelevantOnes += 1
968
969 elif oFailedResult.oParent is not None:
970 # Host: Get the 2nd level node because that's where we'll find the unit test name.
971 # Guest: Get the 6th level node.
972 aoParents = [];
973 oParent = oFailedResult.oParent;
974 while oParent is not None:
975 aoParents.insert(0, oParent);
976 oParent = oParent.oParent;
977 if not fRunsInGuest:
978 oFailedResult = aoParents[min(2, len(aoParents) - 1)];
979 else:
980 oFailedResult = aoParents[min(5, len(aoParents) - 1)];
981
982 # Only report a failure once.
983 if oFailedResult.idTestResult not in oCaseFile.dReasonForResultId:
984 sKey = oFailedResult.sName;
985 if sKey.startswith('testcase/'):
986 sKey = sKey[9:];
987 if sKey in self.asUnitTestReasons:
988 tReason = ( self.ksUnitTestCategory, sKey );
989 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
990 else:
991 self.dprint(u'Unit test failure "%s" not found in %s;' % (sKey, self.asUnitTestReasons));
992 sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated,
993 oFailedResult.tsElapsed);
994 if 'AudioMixer.cpp' in sResultLog: # Pipe drain assertion.
995 tReason = self.ktReason_VMM_Assert;
996 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = 'AudioMixer.cpp');
997 else:
998 tReason = ( self.ksUnitTestCategory, self.ksUnitTestAddNew );
999 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = sKey);
1000 cRelevantOnes += 1
1001 else:
1002 self.vprint(u'Internal error: expected oParent to NOT be None for %s' % (oFailedResult,));
1003
1004 #
1005 # If we've caught all the relevant ones by now, report the result.
1006 #
1007 if len(oCaseFile.dReasonForResultId) >= cRelevantOnes:
1008 return self.caseClosed(oCaseFile);
1009 return False;
1010
1011 def extractGuestCpuStack(self, sInfoText):
1012 """
1013 Extracts the guest CPU stacks from the input file.
1014
1015 Returns a dictionary keyed by the CPU number, value being a list of
1016 raw stack lines (no header).
1017 Returns empty dictionary if no stacks where found.
1018 """
1019 dRet = {};
1020 off = 0;
1021 while True:
1022 # Find the stack.
1023 offStart = sInfoText.find('=== start guest stack VCPU ', off);
1024 if offStart < 0:
1025 break;
1026 offEnd = sInfoText.find('=== end guest stack', offStart + 20);
1027 if offEnd >= 0:
1028 offEnd += 3;
1029 else:
1030 offEnd = sInfoText.find('=== start guest stack VCPU', offStart + 20);
1031 if offEnd < 0:
1032 offEnd = len(sInfoText);
1033
1034 sStack = sInfoText[offStart : offEnd];
1035 sStack = sStack.replace('\r',''); # paranoia
1036 asLines = sStack.split('\n');
1037
1038 # Figure the CPU.
1039 asWords = asLines[0].split();
1040 if len(asWords) < 6 or not asWords[5].isdigit():
1041 break;
1042 iCpu = int(asWords[5]);
1043
1044 # Add it and advance.
1045 dRet[iCpu] = [sLine.rstrip() for sLine in asLines[2:-1]]
1046 off = offEnd;
1047 return dRet;
1048
1049 def investigateInfoKvmLockSpinning(self, oCaseFile, sInfoText, dLogs):
1050 """ Investigates kvm_lock_spinning deadlocks """
1051 #
1052 # Extract the stacks. We need more than one CPU to create a deadlock.
1053 #
1054 dStacks = self.extractGuestCpuStack(sInfoText);
1055 self.dprint('kvm_lock_spinning: found %s stacks' % (len(dStacks),));
1056 if len(dStacks) >= 2:
1057 #
1058 # Examin each of the stacks. Each must have kvm_lock_spinning in
1059 # one of the first three entries.
1060 #
1061 cHits = 0;
1062 for asBacktrace in dStacks.values():
1063 for iFrame in xrange(min(3, len(asBacktrace))):
1064 if asBacktrace[iFrame].find('kvm_lock_spinning') >= 0:
1065 cHits += 1;
1066 break;
1067 self.dprint('kvm_lock_spinning: %s/%s hits' % (cHits, len(dStacks),));
1068 if cHits == len(dStacks):
1069 return (True, self.ktReason_VMM_kvm_lock_spinning);
1070
1071 _ = dLogs; _ = oCaseFile;
1072 return (False, None);
1073
1074 def investigateInfoHalReturnToFirmware(self, oCaseFile, sInfoText, dLogs):
1075 """ Investigates HalReturnToFirmware hangs """
1076 del oCaseFile
1077 del sInfoText
1078 del dLogs
1079 # hope that's sufficient
1080 return (True, self.ktReason_Unknown_HalReturnToFirmware);
1081
1082 ## Things we search a main or VM log for to figure out why something went bust.
1083 ## @note DO NOT ADD MORE STUFF HERE!
1084 ## Please use katSimpleMainLogReasons and katSimpleVmLogReasons instead!
1085 katSimpleMainAndVmLogReasonsDeprecated = [
1086 # ( Whether to stop on hit, reason tuple, needle text. )
1087 ( False, ktReason_Guru_Generic, 'GuruMeditation' ),
1088 ( False, ktReason_Guru_Generic, 'Guru Meditation' ),
1089 ( True, ktReason_Guru_VERR_IEM_INSTR_NOT_IMPLEMENTED, 'VERR_IEM_INSTR_NOT_IMPLEMENTED' ),
1090 ( True, ktReason_Guru_VERR_IEM_ASPECT_NOT_IMPLEMENTED, 'VERR_IEM_ASPECT_NOT_IMPLEMENTED' ),
1091 ( True, ktReason_Guru_VERR_TRPM_DONT_PANIC, 'VERR_TRPM_DONT_PANIC' ),
1092 ( True, ktReason_Guru_VERR_PGM_PHYS_PAGE_RESERVED, 'VERR_PGM_PHYS_PAGE_RESERVED' ),
1093 ( True, ktReason_Guru_VERR_VMX_INVALID_GUEST_STATE, 'VERR_VMX_INVALID_GUEST_STATE' ),
1094 ( True, ktReason_Guru_VINF_EM_TRIPLE_FAULT, 'VINF_EM_TRIPLE_FAULT' ),
1095 ( True, ktReason_Networking_Nonexistent_host_nic,
1096 'rc=E_FAIL text="Nonexistent host networking interface, name \'eth0\' (VERR_INTERNAL_ERROR)"' ),
1097 ( True, ktReason_Networking_VERR_INTNET_FLT_IF_NOT_FOUND,
1098 'Failed to attach the network LUN (VERR_INTNET_FLT_IF_NOT_FOUND)' ),
1099 ( True, ktReason_Host_Reboot_OSX_Watchdog_Timeout, ': "OSX Watchdog Timeout: ' ),
1100 ( False, ktReason_XPCOM_NS_ERROR_CALL_FAILED,
1101 'Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))' ),
1102 ( True, ktReason_API_std_bad_alloc, 'Unexpected exception: std::bad_alloc' ),
1103 ( True, ktReason_Host_HostMemoryLow, 'HostMemoryLow' ),
1104 ( True, ktReason_Host_HostMemoryLow, 'Failed to procure handy pages; rc=VERR_NO_MEMORY' ),
1105 ( True, ktReason_Unknown_File_Not_Found,
1106 'Error: failed to start machine. Error message: File not found. (VERR_FILE_NOT_FOUND)' ),
1107 ( True, ktReason_Unknown_File_Not_Found, # lump it in with file-not-found for now.
1108 'Error: failed to start machine. Error message: Not supported. (VERR_NOT_SUPPORTED)' ),
1109 ( False, ktReason_Unknown_VM_Crash, 'txsDoConnectViaTcp: Machine state: Aborted' ),
1110 ( True, ktReason_Host_Modprobe_Failed, 'Kernel driver not installed' ),
1111 ( True, ktReason_OSInstall_Sata_no_BM, 'PCHS=14128/14134/8224' ),
1112 ( True, ktReason_Host_DoubleFreeHeap, 'double free or corruption' ),
1113 #( False, ktReason_Unknown_VM_Start_Error, 'VMSetError: ' ), - false positives for stuff like:
1114 # "VMSetError: VD: Backend 'VBoxIsoMaker' does not support async I/O"
1115 ( False, ktReason_Unknown_VM_Start_Error, 'error: failed to open session for' ),
1116 ( False, ktReason_Unknown_VM_Runtime_Error, 'Console: VM runtime error: fatal=true' ),
1117 ];
1118
1119 ## This we search a main log for to figure out why something went bust.
1120 katSimpleMainLogReasons = [
1121 # ( Whether to stop on hit, reason tuple, needle text. )
1122 ( False, ktReason_Host_win32com_gen_py, 'ModuleNotFoundError: No module named \'win32com.gen_py' ),
1123
1124 ];
1125
1126 ## This we search a VM log for to figure out why something went bust.
1127 katSimpleVmLogReasons = [
1128 # ( Whether to stop on hit, reason tuple, needle text. )
1129 # Note: Works for ATA and VD drivers.
1130 ( False, ktReason_Host_DiskFull, '_DISKFULL' ),
1131 ];
1132
1133 ## Things we search a VBoxHardening.log file for to figure out why something went bust.
1134 katSimpleVBoxHardeningLogReasons = [
1135 # ( Whether to stop on hit, reason tuple, needle text. )
1136 ( True, ktReason_Host_DriverNotLoaded, 'Error opening VBoxDrvStub: STATUS_OBJECT_NAME_NOT_FOUND' ),
1137 ( True, ktReason_Host_NotSignedWithBuildCert, 'Not signed with the build certificate' ),
1138 ( True, ktReason_Host_TSTInfo_Accuracy_OOR, 'RTCRTSPTSTINFO::Accuracy::Millis: Out of range' ),
1139 ( False, ktReason_Unknown_VM_Crash, 'Quitting: ExitCode=0xc0000005 (rcNtWait=' ),
1140 ];
1141
1142 ## Things we search a kernel.log file for to figure out why something went bust.
1143 katSimpleKernelLogReasons = [
1144 # ( Whether to stop on hit, reason tuple, needle text. )
1145 ( True, ktReason_Panic_HugeMemory, 'mm/huge_memory.c:1988' ),
1146 ( True, ktReason_Panic_IOAPICDoesntWork, 'IO-APIC + timer doesn\'t work' ),
1147 ( True, ktReason_Panic_TxUnitHang, 'Detected Tx Unit Hang' ),
1148 ( True, ktReason_GuestBug_CompizVBoxQt, 'error 4 in libQt5CoreVBox' ),
1149 ( True, ktReason_GuestBug_CompizVBoxQt, 'error 4 in libgtk-3' ),
1150 ];
1151
1152 ## Things we search the _RIGHT_ _STRIPPED_ vgatext for.
1153 katSimpleVgaTextReasons = [
1154 # ( Whether to stop on hit, reason tuple, needle text. )
1155 ( True, ktReason_Panic_MP_BIOS_IO_APIC,
1156 "..MP-BIOS bug: 8254 timer not connected to IO-APIC\n\n" ),
1157 ( True, ktReason_Panic_MP_BIOS_IO_APIC,
1158 "..MP-BIOS bug: 8254 timer not connected to IO-APIC\n"
1159 "...trying to set up timer (IRQ0) through the 8259A ... failed.\n"
1160 "...trying to set up timer as Virtual Wire IRQ... failed.\n"
1161 "...trying to set up timer as ExtINT IRQ... failed :(.\n"
1162 "Kernel panic - not syncing: IO-APIC + timer doesn't work! Boot with apic=debug\n"
1163 "and send a report. Then try booting with the 'noapic' option\n"
1164 "\n" ),
1165 ( True, ktReason_OSInstall_GRUB_hang,
1166 "-----\nGRUB Loading stage2..\n\n\n\n" ),
1167 ( True, ktReason_OSInstall_GRUB_hang,
1168 "-----\nGRUB Loading stage2...\n\n\n\n" ), # the 3 dot hang appears to be less frequent
1169 ( True, ktReason_OSInstall_GRUB_hang,
1170 "-----\nGRUB Loading stage2....\n\n\n\n" ), # the 4 dot hang appears to be very infrequent
1171 ( True, ktReason_OSInstall_GRUB_hang,
1172 "-----\nGRUB Loading stage2.....\n\n\n\n" ), # the 5 dot hang appears to be more frequent again
1173 ( True, ktReason_OSInstall_Udev_hang,
1174 "\nStarting udev:\n\n\n\n" ),
1175 ( True, ktReason_OSInstall_Udev_hang,
1176 "\nStarting udev:\n------" ),
1177 ( True, ktReason_Panic_BootManagerC000000F,
1178 "Windows failed to start. A recent hardware or software change might be the" ),
1179 ( True, ktReason_BootManager_Image_corrupt,
1180 "BOOTMGR image is corrupt. The system cannot boot." ),
1181 ];
1182
1183 ## Things we search for in the info.txt file. Require handlers for now.
1184 katInfoTextHandlers = [
1185 # ( Trigger text, handler method )
1186 ( "kvm_lock_spinning", investigateInfoKvmLockSpinning ),
1187 ( "HalReturnToFirmware", investigateInfoHalReturnToFirmware ),
1188 ];
1189
1190 ## Mapping screenshot/failure SHA-256 hashes to failure reasons.
1191 katSimpleScreenshotHashReasons = [
1192 # ( Whether to stop on hit, reason tuple, lowercased sha-256 of PIL.Image.tostring output )
1193 ( True, ktReason_BSOD_Recovery, '576f8e38d62b311cac7e3dc3436a0d0b9bd8cfd7fa9c43aafa95631520a45eac' ),
1194 ( True, ktReason_BSOD_Automatic_Repair, 'c6a72076cc619937a7a39cfe9915b36d94cee0d4e3ce5ce061485792dcee2749' ),
1195 ( True, ktReason_BSOD_Automatic_Repair, '26c4d8a724ff2c5e1051f3d5b650dbda7b5fdee0aa3e3c6059797f7484a515df' ),
1196 ( True, ktReason_BSOD_0000007F, '57e1880619e13042a87100e7a38c8974b85ce3866501be621bea0cc696bb2c63' ),
1197 ( True, ktReason_BSOD_000000D1, '134621281f00a3f8aeeb7660064bffbf6187ed56d5852142328d0bcb18ef0ede' ),
1198 ( True, ktReason_BSOD_000000D1, '279f11258150c9d2fef041eca65501f3141da8df39256d8f6377e897e3b45a93' ),
1199 ( True, ktReason_BSOD_C0000225, 'bd13a144be9dcdfb16bc863ff4c8f02a86e263c174f2cd5ffd27ca5f3aa31789' ),
1200 ( True, ktReason_BSOD_C0000225, '8348b465e7ee9e59dd4e785880c57fd8677de05d11ac21e786bfde935307b42f' ),
1201 ( True, ktReason_BSOD_C0000225, '1316e1fc818a73348412788e6910b8c016f237d8b4e15b20caf4a866f7a7840e' ),
1202 ( True, ktReason_BSOD_C0000225, '54e0acbff365ce20a85abbe42bcd53647b8b9e80c68e45b2cd30e86bf177a0b5' ),
1203 ( True, ktReason_BSOD_C0000225, '50fec50b5199923fa48b3f3e782687cc381e1c8a788ebda14e6a355fbe3bb1b3' ),
1204 ];
1205
1206
1207 def scanLog(self, asLogs, atNeedles, oCaseFile, idTestResult):
1208 """
1209 Scans for atNeedles in sLog.
1210
1211 Returns True if a stop-on-hit neelde was found.
1212 Returns None if a no-stop reason was found.
1213 Returns False if no hit.
1214 """
1215 fRet = False;
1216 for fStopOnHit, tReason, oNeedle in atNeedles:
1217 fMatch = False;
1218 if utils.isString(oNeedle):
1219 for sLog in asLogs:
1220 if sLog:
1221 fMatch |= sLog.find(oNeedle) > 0;
1222 else:
1223 for sLog in asLogs:
1224 if sLog:
1225 fMatch |= oNeedle.search(sLog) is not None;
1226 if fMatch:
1227 oCaseFile.noteReasonForId(tReason, idTestResult);
1228 if fStopOnHit:
1229 return True;
1230 fRet = None;
1231 return fRet;
1232
1233
1234 def investigateGATest(self, oCaseFile, oFailedResult, sResultLog):
1235 """
1236 Investigates a failed VM run.
1237 """
1238 enmReason = None;
1239 sParentName = oFailedResult.oParent.sName if oFailedResult.oParent else '';
1240 if oFailedResult.sName == 'VBoxWindowsAdditions.exe' or sResultLog.find('VBoxWindowsAdditions.exe" failed with') > 0:
1241 enmReason = self.ktReason_Add_Installer_Win_Failed;
1242 # guest control:
1243 elif sParentName == 'Guest Control' and oFailedResult.sName == 'Preparations':
1244 enmReason = self.ktReason_Add_GstCtl_Preparations;
1245 elif oFailedResult.sName == 'Session Basics':
1246 enmReason = self.ktReason_Add_GstCtl_SessionBasics;
1247 elif oFailedResult.sName == 'Session Process References':
1248 enmReason = self.ktReason_Add_GstCtl_SessionProcRefs;
1249 elif oFailedResult.sName == 'Copy from guest':
1250 if sResultLog.find('*** abort action ***') >= 0:
1251 enmReason = self.ktReason_Add_GstCtl_CopyFromGuest_Timeout;
1252 elif oFailedResult.sName == 'Copy to guest':
1253 off = sResultLog.find('"Guest directory "');
1254 if off > 0 and sResultLog.find('" already exists"', off, off + 80):
1255 enmReason = self.ktReason_Add_GstCtl_CopyToGuest_DstExists;
1256 elif sResultLog.find('Guest destination must not be empty') >= 0:
1257 enmReason = self.ktReason_Add_GstCtl_CopyToGuest_DstEmpty;
1258 elif sResultLog.find('*** abort action ***') >= 0:
1259 enmReason = self.ktReason_Add_GstCtl_CopyToGuest_Timeout;
1260 elif oFailedResult.sName.find('Session w/ Guest Reboot') >= 0:
1261 enmReason = self.ktReason_Add_GstCtl_Session_Reboot;
1262 elif sParentName == 'Guest Control' or oFailedResult.sName == 'Guest Control':
1263 enmReason = self.ktReason_Add_GstCtl;
1264 # shared folders:
1265 elif sParentName == 'Shared Folders' and oFailedResult.sName == 'Automounting':
1266 enmReason = self.ktReason_Add_ShFl_Automount;
1267 elif oFailedResult.sName == 'mmap':
1268 if sResultLog.find('FsPerf: Flush issue at offset ') >= 0:
1269 enmReason = self.ktReason_Add_Mmap_Coherency;
1270 elif sResultLog.find('FlushViewOfFile') >= 0:
1271 enmReason = self.ktReason_Add_FlushViewOfFile;
1272 elif sParentName == 'Shared Folders' and oFailedResult.sName == 'Running FsPerf':
1273 enmReason = self.ktReason_Add_ShFl_FsPerf; ## Maybe it would be better to be more specific...
1274
1275 if enmReason is not None:
1276 return oCaseFile.noteReasonForId(enmReason, oFailedResult.idTestResult);
1277
1278 self.vprint(u'TODO: Cannot place GA failure idTestResult=%u - %s' % (oFailedResult.idTestResult, oFailedResult.sName,));
1279 self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
1280 return False;
1281
1282 def isResultFromGATest(self, oCaseFile, oFailedResult):
1283 """
1284 Checks if this result and corresponding log snippet looks like a GA test run.
1285 """
1286 while oFailedResult is not None:
1287 if oFailedResult.sName in [ 'Guest Control', 'Shared Folders', 'FsPerf', 'VBoxWindowsAdditions.exe' ]:
1288 return True;
1289 if oCaseFile.oTestCase.sName == 'Guest Additions' and oFailedResult.sName in [ 'Install', ]:
1290 return True;
1291 oFailedResult = oFailedResult.oParent;
1292 return False;
1293
1294
1295 def investigateVMResult(self, oCaseFile, oFailedResult, sResultLog):
1296 """
1297 Investigates a failed VM run.
1298 """
1299
1300 def investigateLogSet():
1301 """
1302 Investigates the current set of VM related logs.
1303 """
1304 self.dprint('investigateLogSet: log lengths: result %u, VM %u, kernel %u, vga text %u, info text %u, hard %u'
1305 % ( len(sResultLog if sResultLog else ''),
1306 len(sVMLog if sVMLog else ''),
1307 len(sKrnlLog if sKrnlLog else ''),
1308 len(sVgaText if sVgaText else ''),
1309 len(sInfoText if sInfoText else ''),
1310 len(sNtHardLog if sNtHardLog else ''),));
1311
1312 #self.dprint(u'main.log<<<\n%s\n<<<\n' % (sResultLog,));
1313 #self.dprint(u'vbox.log<<<\n%s\n<<<\n' % (sVMLog,));
1314 #self.dprint(u'krnl.log<<<\n%s\n<<<\n' % (sKrnlLog,));
1315 #self.dprint(u'vgatext.txt<<<\n%s\n<<<\n' % (sVgaText,));
1316 #self.dprint(u'info.txt<<<\n%s\n<<<\n' % (sInfoText,));
1317 #self.dprint(u'hard.txt<<<\n%s\n<<<\n' % (sNtHardLog,));
1318
1319 # TODO: more
1320
1321 #
1322 # Look for BSODs. Some stupid stupid inconsistencies in reason and log messages here, so don't try prettify this.
1323 #
1324 sDetails = self.findInAnyAndReturnRestOfLine([ sVMLog, sResultLog ],
1325 'GIM: HyperV: Guest indicates a fatal condition! P0=');
1326 if sDetails is not None:
1327 # P0=%#RX64 P1=%#RX64 P2=%#RX64 P3=%#RX64 P4=%#RX64 "
1328 sKey = sDetails.split(' ', 1)[0];
1329 try: sKey = '0x%08X' % (int(sKey, 16),);
1330 except: pass;
1331 if sKey in self.asBsodReasons:
1332 tReason = ( self.ksBsodCategory, sKey );
1333 elif sKey.lower() in self.asBsodReasons: # just in case.
1334 tReason = ( self.ksBsodCategory, sKey.lower() );
1335 else:
1336 self.dprint(u'BSOD "%s" not found in %s;' % (sKey, self.asBsodReasons));
1337 tReason = ( self.ksBsodCategory, self.ksBsodAddNew );
1338 return oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = sDetails.strip());
1339
1340 fFoundSomething = False;
1341
1342 #
1343 # Look for linux panic.
1344 #
1345 if sKrnlLog is not None:
1346 fRet = self.scanLog([sKrnlLog,], self.katSimpleKernelLogReasons, oCaseFile, oFailedResult.idTestResult);
1347 if fRet is True:
1348 return fRet;
1349 fFoundSomething |= fRet is None;
1350
1351 #
1352 # Loop thru the simple stuff.
1353 #
1354
1355 # Main log.
1356 fRet = self.scanLog([sResultLog,], self.katSimpleMainLogReasons, oCaseFile, oFailedResult.idTestResult);
1357 if fRet is True:
1358 return fRet;
1359 fFoundSomething |= fRet is None;
1360
1361 # VM log.
1362 fRet = self.scanLog([sVMLog,], self.katSimpleVmLogReasons, oCaseFile, oFailedResult.idTestResult);
1363 if fRet is True:
1364 return fRet;
1365 fFoundSomething |= fRet is None;
1366
1367 # Old main + vm log.
1368 fRet = self.scanLog([sResultLog, sVMLog], self.katSimpleMainAndVmLogReasonsDeprecated,
1369 oCaseFile, oFailedResult.idTestResult);
1370 if fRet is True:
1371 return fRet;
1372 fFoundSomething |= fRet is None;
1373
1374 # Continue with vga text.
1375 if sVgaText:
1376 fRet = self.scanLog([sVgaText,], self.katSimpleVgaTextReasons, oCaseFile, oFailedResult.idTestResult);
1377 if fRet is True:
1378 return fRet;
1379 fFoundSomething |= fRet is None;
1380
1381 # Continue with screen hashes.
1382 if sScreenHash is not None:
1383 for fStopOnHit, tReason, sHash in self.katSimpleScreenshotHashReasons:
1384 if sScreenHash == sHash:
1385 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
1386 if fStopOnHit:
1387 return True;
1388 fFoundSomething = True;
1389
1390 # Check VBoxHardening.log.
1391 if sNtHardLog is not None:
1392 fRet = self.scanLog([sNtHardLog,], self.katSimpleVBoxHardeningLogReasons, oCaseFile, oFailedResult.idTestResult);
1393 if fRet is True:
1394 return fRet;
1395 fFoundSomething |= fRet is None;
1396
1397 #
1398 # Complicated stuff.
1399 #
1400 dLogs = {
1401 'sVMLog': sVMLog,
1402 'sNtHardLog': sNtHardLog,
1403 'sScreenHash': sScreenHash,
1404 'sKrnlLog': sKrnlLog,
1405 'sVgaText': sVgaText,
1406 'sInfoText': sInfoText,
1407 };
1408
1409 # info.txt.
1410 if sInfoText:
1411 for sNeedle, fnHandler in self.katInfoTextHandlers:
1412 if sInfoText.find(sNeedle) > 0:
1413 (fStop, tReason) = fnHandler(self, oCaseFile, sInfoText, dLogs);
1414 if tReason is not None:
1415 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
1416 if fStop:
1417 return True;
1418 fFoundSomething = True;
1419
1420 #
1421 # Check for repeated reboots...
1422 #
1423 if sVMLog is not None:
1424 cResets = sVMLog.count('Changing the VM state from \'RUNNING\' to \'RESETTING\'');
1425 if cResets > 10:
1426 return oCaseFile.noteReasonForId(self.ktReason_Unknown_Reboot_Loop, oFailedResult.idTestResult,
1427 sComment = 'Counted %s reboots' % (cResets,));
1428
1429 return fFoundSomething;
1430
1431 #
1432 # Check if we got any VM or/and kernel logs. Treat them as sets in
1433 # case we run multiple VMs here (this is of course ASSUMING they
1434 # appear in the order that terminateVmBySession uploads them).
1435 #
1436 cTimes = 0;
1437 sVMLog = None;
1438 sNtHardLog = None;
1439 sScreenHash = None;
1440 sKrnlLog = None;
1441 sVgaText = None;
1442 sInfoText = None;
1443 for oFile in oFailedResult.aoFiles:
1444 if oFile.sKind == TestResultFileData.ksKind_LogReleaseVm:
1445 if 'VBoxHardening.log' not in oFile.sFile:
1446 if sVMLog is not None:
1447 if investigateLogSet() is True:
1448 return True;
1449 cTimes += 1;
1450 sInfoText = None;
1451 sVgaText = None;
1452 sKrnlLog = None;
1453 sScreenHash = None;
1454 sNtHardLog = None;
1455 sVMLog = oCaseFile.getLogFile(oFile);
1456 else:
1457 sNtHardLog = oCaseFile.getLogFile(oFile);
1458 elif oFile.sKind == TestResultFileData.ksKind_LogGuestKernel:
1459 sKrnlLog = oCaseFile.getLogFile(oFile);
1460 elif oFile.sKind == TestResultFileData.ksKind_InfoVgaText:
1461 sVgaText = '\n'.join([sLine.rstrip() for sLine in oCaseFile.getLogFile(oFile).split('\n')]);
1462 elif oFile.sKind == TestResultFileData.ksKind_InfoCollection:
1463 sInfoText = oCaseFile.getLogFile(oFile);
1464 elif oFile.sKind == TestResultFileData.ksKind_ScreenshotFailure:
1465 sScreenHash = oCaseFile.getScreenshotSha256(oFile);
1466 if sScreenHash is not None:
1467 sScreenHash = sScreenHash.lower();
1468 self.vprint(u'%s %s' % ( sScreenHash, oFile.sFile,));
1469
1470 if ( sVMLog is not None \
1471 or sNtHardLog is not None \
1472 or cTimes == 0) \
1473 and investigateLogSet() is True:
1474 return True;
1475
1476 return None;
1477
1478 def isResultFromVMRun(self, oFailedResult, sResultLog):
1479 """
1480 Checks if this result and corresponding log snippet looks like a VM run.
1481 """
1482
1483 # Look for startVmEx/ startVmAndConnectToTxsViaTcp and similar output in the log.
1484 if sResultLog.find(' startVm') > 0:
1485 return True;
1486
1487 # Any other indicators? No?
1488 _ = oFailedResult;
1489 return False;
1490
1491
1492 ## Things we search a VBoxSVC log for to figure out why something went bust.
1493 katSimpleSvcLogReasons = [
1494 # ( Whether to stop on hit, reason tuple, needle text. )
1495 ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* exited normally: -1073741819 \(0xc0000005\)') ),
1496 ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* was signalled: 11 \(0xb\)') ), # For VBox < 6.1.
1497 ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* was signalled: SIGABRT.*') ), # Since VBox 7.0.
1498 ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* was signalled: SIGSEGV.*') ),
1499 ( False, ktReason_Unknown_VM_Terminated, re.compile(r'Reaper.* was signalled: SIGTERM.*') ),
1500 ( False, ktReason_Unknown_VM_Terminated, re.compile(r'Reaper.* was signalled: SIGKILL.*') ),
1501 ];
1502
1503 def investigateSvcLogForVMRun(self, oCaseFile, sSvcLog):
1504 """
1505 Check the VBoxSVC log for a single VM run.
1506 """
1507 if sSvcLog:
1508 fRet = self.scanLog([sSvcLog,], self.katSimpleSvcLogReasons, oCaseFile, oCaseFile.oTree.idTestResult);
1509 if fRet is True or fRet is None:
1510 return True;
1511 return False;
1512
1513 def investigateNtHardLogForVMRun(self, oCaseFile):
1514 """
1515 Check if the hardening log for a single VM run contains VM crash indications.
1516 """
1517 aoLogFiles = oCaseFile.oTree.getListOfLogFilesByKind(TestResultFileData.ksKind_LogReleaseVm);
1518 for oLogFile in aoLogFiles:
1519 if oLogFile.sFile.find('VBoxHardening.log') >= 0:
1520 sLog = oCaseFile.getLogFile(oLogFile);
1521 if sLog.find('Quitting: ExitCode=0xc0000005') >= 0:
1522 return oCaseFile.noteReasonForId(self.ktReason_Unknown_VM_Crash, oCaseFile.oTree.idTestResult);
1523 return False;
1524
1525
1526 def investigateVBoxVMTest(self, oCaseFile, fSingleVM):
1527 """
1528 Checks out a VBox VM test.
1529
1530 This is generic investigation of a test running one or more VMs, like
1531 for example a smoke test or a guest installation test.
1532
1533 The fSingleVM parameter is a hint, which probably won't come in useful.
1534 """
1535 _ = fSingleVM;
1536
1537 #
1538 # Get a list of test result failures we should be looking into and the main log.
1539 #
1540 aoFailedResults = oCaseFile.oTree.getListOfFailures();
1541 sMainLog = oCaseFile.getMainLog();
1542
1543 #
1544 # There are a set of errors ending up on the top level result record.
1545 # Should deal with these first.
1546 #
1547 if len(aoFailedResults) == 1 and aoFailedResults[0] == oCaseFile.oTree:
1548 # Check if we've just got that XPCOM client smoke test shutdown issue. This will currently always
1549 # be reported on the top result because vboxinstall.py doesn't add an error for it. It is easy to
1550 # ignore other failures in the test if we're not a little bit careful here.
1551 if sMainLog.find('vboxinstaller: Exit code: -11 (') > 0:
1552 oCaseFile.noteReason(self.ktReason_XPCOM_Exit_Minus_11);
1553 return self.caseClosed(oCaseFile);
1554
1555 # Hang after starting VBoxSVC (e.g. idTestSet=136307258)
1556 if self.isThisFollowedByTheseLines(sMainLog, 'oVBoxMgr=<vboxapi.VirtualBoxManager object at',
1557 (' Timeout: ', ' Attempting to abort child...',) ):
1558 if sMainLog.find('*** glibc detected *** /') > 0:
1559 oCaseFile.noteReason(self.ktReason_XPCOM_VBoxSVC_Hang_Plus_Heap_Corruption);
1560 else:
1561 oCaseFile.noteReason(self.ktReason_XPCOM_VBoxSVC_Hang);
1562 return self.caseClosed(oCaseFile);
1563
1564 # Look for heap corruption without visible hang.
1565 if sMainLog.find('*** glibc detected *** /') > 0 \
1566 or sMainLog.find("-1073740940") > 0: # STATUS_HEAP_CORRUPTION / 0xc0000374
1567 oCaseFile.noteReason(self.ktReason_Unknown_Heap_Corruption);
1568 return self.caseClosed(oCaseFile);
1569
1570 # Out of memory w/ timeout.
1571 if sMainLog.find('sErrId=HostMemoryLow') > 0:
1572 oCaseFile.noteReason(self.ktReason_Host_HostMemoryLow);
1573 return self.caseClosed(oCaseFile);
1574
1575 # Stale files like vts_rm.exe (windows).
1576 offEnd = sMainLog.rfind('*** The test driver exits successfully. ***');
1577 if offEnd > 0 and sMainLog.find('[Error 145] The directory is not empty: ', offEnd) > 0:
1578 oCaseFile.noteReason(self.ktReason_Ignore_Stale_Files);
1579 return self.caseClosed(oCaseFile);
1580
1581 #
1582 # XPCOM screwup
1583 #
1584 if sMainLog.find('AttributeError: \'NoneType\' object has no attribute \'addObserver\'') > 0:
1585 oCaseFile.noteReason(self.ktReason_Buggy_Build_Broken_Build);
1586 return self.caseClosed(oCaseFile);
1587
1588 #
1589 # Go thru each failed result.
1590 #
1591 for oFailedResult in aoFailedResults:
1592 self.dprint(u'Looking at test result #%u - %s' % (oFailedResult.idTestResult, oFailedResult.getFullName(),));
1593 sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
1594 if oFailedResult.sName == 'Installing VirtualBox':
1595 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = True)
1596
1597 elif oFailedResult.sName == 'Uninstalling VirtualBox':
1598 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = False)
1599
1600 elif self.isResultFromVMRun(oFailedResult, sResultLog):
1601 self.investigateVMResult(oCaseFile, oFailedResult, sResultLog);
1602
1603 elif self.isResultFromGATest(oCaseFile, oFailedResult):
1604 self.investigateGATest(oCaseFile, oFailedResult, sResultLog);
1605
1606 elif sResultLog.find('most likely not unique') > 0:
1607 oCaseFile.noteReasonForId(self.ktReason_Host_NetworkMisconfiguration, oFailedResult.idTestResult)
1608 elif sResultLog.find('Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))') > 0:
1609 oCaseFile.noteReasonForId(self.ktReason_XPCOM_NS_ERROR_CALL_FAILED, oFailedResult.idTestResult);
1610
1611 elif sResultLog.find('The machine is not mutable (state is ') > 0:
1612 self.vprint('Ignoring "machine not mutable" error as it is probably due to an earlier problem');
1613 oCaseFile.noteReasonForId(self.ktHarmless, oFailedResult.idTestResult);
1614
1615 elif sResultLog.find('** error: no action was specified') > 0 \
1616 or sResultLog.find('(len(self._asXml, asText))') > 0:
1617 oCaseFile.noteReasonForId(self.ktReason_Ignore_Buggy_Test_Driver, oFailedResult.idTestResult);
1618
1619 else:
1620 self.vprint(u'TODO: Cannot place idTestResult=%u - %s' % (oFailedResult.idTestResult, oFailedResult.sName,));
1621 self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
1622
1623 #
1624 # Windows python/com screwup.
1625 #
1626 if sMainLog.find('ModuleNotFoundError: No module named \'win32com.gen_py') > 0:
1627 oCaseFile.noteReason(self.ktReason_Host_win32com_gen_py);
1628 return self.caseClosed(oCaseFile);
1629
1630 #
1631 # Check VBoxSVC.log and VBoxHardening.log for VM crashes if inconclusive on single VM runs.
1632 #
1633 if fSingleVM and len(oCaseFile.dReasonForResultId) < len(aoFailedResults):
1634 self.dprint(u'Got %u out of %u - checking VBoxSVC.log...'
1635 % (len(oCaseFile.dReasonForResultId), len(aoFailedResults)));
1636 if self.investigateSvcLogForVMRun(oCaseFile, oCaseFile.getSvcLog()):
1637 return self.caseClosed(oCaseFile);
1638 if self.investigateNtHardLogForVMRun(oCaseFile):
1639 return self.caseClosed(oCaseFile);
1640
1641 #
1642 # Report home and close the case if we got them all, otherwise log it.
1643 #
1644 if len(oCaseFile.dReasonForResultId) >= len(aoFailedResults):
1645 return self.caseClosed(oCaseFile);
1646
1647 if oCaseFile.dReasonForResultId:
1648 self.vprint(u'TODO: Got %u out of %u - close, but no cigar. :-/'
1649 % (len(oCaseFile.dReasonForResultId), len(aoFailedResults)));
1650 else:
1651 self.vprint(u'XXX: Could not figure out anything at all! :-(');
1652 return False;
1653
1654
1655 ## Things we search a main log for to figure out why something in the API test went bust.
1656 katSimpleApiMainLogReasons = [
1657 # ( Whether to stop on hit, reason tuple, needle text. )
1658 ( True, ktReason_Networking_Nonexistent_host_nic,
1659 'rc=E_FAIL text="Nonexistent host networking interface, name \'eth0\' (VERR_INTERNAL_ERROR)"' ),
1660 ( False, ktReason_XPCOM_NS_ERROR_CALL_FAILED,
1661 'Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))' ),
1662 ( True, ktReason_API_std_bad_alloc, 'Unexpected exception: std::bad_alloc' ),
1663 ( True, ktReason_API_Digest_Mismatch, 'Digest mismatch (VERR_NOT_EQUAL)' ),
1664 ( True, ktReason_API_MoveVM_SharingViolation, 'rc=VBOX_E_IPRT_ERROR text="Could not copy the log file ' ),
1665 ( True, ktReason_API_MoveVM_InvalidParameter,
1666 'rc=VBOX_E_IPRT_ERROR text="Could not copy the setting file ' ),
1667 ( True, ktReason_API_Open_Session_Failed, 'error: failed to open session for' ),
1668 ];
1669
1670 def investigateVBoxApiTest(self, oCaseFile):
1671 """
1672 Checks out a VBox API test.
1673 """
1674
1675 #
1676 # Get a list of test result failures we should be looking into and the main log.
1677 #
1678 aoFailedResults = oCaseFile.oTree.getListOfFailures();
1679 sMainLog = oCaseFile.getMainLog();
1680
1681 #
1682 # Go thru each failed result.
1683 #
1684 for oFailedResult in aoFailedResults:
1685 self.dprint(u'Looking at test result #%u - %s' % (oFailedResult.idTestResult, oFailedResult.getFullName(),));
1686 sResultLog = TestSetData.extractLogSectionElapsed(sMainLog, oFailedResult.tsCreated, oFailedResult.tsElapsed);
1687 if oFailedResult.sName == 'Installing VirtualBox':
1688 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = True)
1689
1690 elif oFailedResult.sName == 'Uninstalling VirtualBox':
1691 self.investigateInstallUninstallFailure(oCaseFile, oFailedResult, sResultLog, fInstall = False)
1692
1693 elif sResultLog.find('Exception: 0x800706be (Call to remote object failed (NS_ERROR_CALL_FAILED))') > 0:
1694 oCaseFile.noteReasonForId(self.ktReason_XPCOM_NS_ERROR_CALL_FAILED, oFailedResult.idTestResult);
1695
1696 else:
1697 fFoundSomething = False;
1698 for fStopOnHit, tReason, sNeedle in self.katSimpleApiMainLogReasons:
1699 if sResultLog.find(sNeedle) > 0:
1700 oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
1701 fFoundSomething = True;
1702 if fStopOnHit:
1703 break;
1704 if fFoundSomething:
1705 self.vprint(u'TODO: Cannot place idTestResult=%u - %s' % (oFailedResult.idTestResult, oFailedResult.sName,));
1706 self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
1707
1708 #
1709 # Report home and close the case if we got them all, otherwise log it.
1710 #
1711 if len(oCaseFile.dReasonForResultId) >= len(aoFailedResults):
1712 return self.caseClosed(oCaseFile);
1713
1714 if oCaseFile.dReasonForResultId:
1715 self.vprint(u'TODO: Got %u out of %u - close, but no cigar. :-/'
1716 % (len(oCaseFile.dReasonForResultId), len(aoFailedResults)));
1717 else:
1718 self.vprint(u'XXX: Could not figure out anything at all! :-(');
1719 return False;
1720
1721
1722 def reasoningFailures(self):
1723 """
1724 Guess the reason for failures.
1725 """
1726 #
1727 # Get a list of failed test sets without any assigned failure reason.
1728 #
1729 cGot = 0;
1730 if not self.oConfig.aidTestSets:
1731 aoTestSets = self.oTestSetLogic.fetchFailedSetsWithoutReason(cHoursBack = self.oConfig.cHoursBack,
1732 tsNow = self.tsNow);
1733 else:
1734 aoTestSets = [self.oTestSetLogic.getById(idTestSet) for idTestSet in self.oConfig.aidTestSets];
1735 for oTestSet in aoTestSets:
1736 self.dprint(u'----------------------------------- #%u, status %s -----------------------------------'
1737 % ( oTestSet.idTestSet, oTestSet.enmStatus,));
1738
1739 #
1740 # Open a case file and assign it to the right investigator.
1741 #
1742 (oTree, _ ) = self.oTestResultLogic.fetchResultTree(oTestSet.idTestSet);
1743 oBuild = BuildDataEx().initFromDbWithId( self.oDb, oTestSet.idBuild, oTestSet.tsCreated);
1744 oTestBox = TestBoxData().initFromDbWithGenId( self.oDb, oTestSet.idGenTestBox);
1745 oTestGroup = TestGroupData().initFromDbWithId( self.oDb, oTestSet.idTestGroup, oTestSet.tsCreated);
1746 oTestCase = TestCaseDataEx().initFromDbWithGenId( self.oDb, oTestSet.idGenTestCase, oTestSet.tsConfig);
1747
1748 oCaseFile = VirtualTestSheriffCaseFile(self, oTestSet, oTree, oBuild, oTestBox, oTestGroup, oTestCase);
1749
1750 if oTestSet.enmStatus == TestSetData.ksTestStatus_BadTestBox:
1751 self.dprint(u'investigateBadTestBox is taking over %s.' % (oCaseFile.sLongName,));
1752 fRc = self.investigateBadTestBox(oCaseFile);
1753
1754 elif oCaseFile.isVBoxUnitTest():
1755 self.dprint(u'investigateVBoxUnitTest is taking over %s.' % (oCaseFile.sLongName,));
1756 fRc = self.investigateVBoxUnitTest(oCaseFile);
1757
1758 elif oCaseFile.isVBoxInstallTest() or oCaseFile.isVBoxUnattendedInstallTest():
1759 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1760 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1761
1762 elif oCaseFile.isVBoxUSBTest():
1763 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1764 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1765
1766 elif oCaseFile.isVBoxStorageTest():
1767 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1768 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1769
1770 elif oCaseFile.isVBoxGAsTest():
1771 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1772 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = True);
1773
1774 elif oCaseFile.isVBoxAPITest():
1775 self.dprint(u'investigateVBoxApiTest is taking over %s.' % (oCaseFile.sLongName,));
1776 fRc = self.investigateVBoxApiTest(oCaseFile);
1777
1778 elif oCaseFile.isVBoxBenchmarkTest():
1779 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1780 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = False);
1781
1782 elif oCaseFile.isVBoxSmokeTest():
1783 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1784 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = False);
1785
1786 elif oCaseFile.isVBoxSerialTest():
1787 self.dprint(u'investigateVBoxVMTest is taking over %s.' % (oCaseFile.sLongName,));
1788 fRc = self.investigateVBoxVMTest(oCaseFile, fSingleVM = False);
1789
1790 else:
1791 self.vprint(u'reasoningFailures: Unable to classify test set: %s' % (oCaseFile.sLongName,));
1792 fRc = False;
1793 cGot += fRc is True;
1794
1795 self.vprint(u'reasoningFailures: Got %u out of %u' % (cGot, len(aoTestSets), ));
1796 return 0;
1797
1798
1799 def main(self):
1800 """
1801 The 'main' function.
1802 Return exit code (0, 1, etc).
1803 """
1804 # Database stuff.
1805 self.oDb = TMDatabaseConnection()
1806 self.oTestResultLogic = TestResultLogic(self.oDb);
1807 self.oTestSetLogic = TestSetLogic(self.oDb);
1808 self.oFailureReasonLogic = FailureReasonLogic(self.oDb);
1809 self.oTestResultFailureLogic = TestResultFailureLogic(self.oDb);
1810 self.asBsodReasons = self.oFailureReasonLogic.fetchForSheriffByNamedCategory(self.ksBsodCategory);
1811 self.asUnitTestReasons = self.oFailureReasonLogic.fetchForSheriffByNamedCategory(self.ksUnitTestCategory);
1812
1813 # Get a fix on our 'now' before we do anything..
1814 self.oDb.execute('SELECT CURRENT_TIMESTAMP - interval \'%s hours\'', (self.oConfig.cStartHoursAgo,));
1815 self.tsNow = self.oDb.fetchOne();
1816
1817 # If we're suppost to commit anything we need to get our user ID.
1818 rcExit = 0;
1819 if self.oConfig.fRealRun:
1820 self.oLogin = UserAccountLogic(self.oDb).tryFetchAccountByLoginName(VirtualTestSheriff.ksLoginName);
1821 if self.oLogin is None:
1822 rcExit = self.eprint('Cannot find my user account "%s"!' % (VirtualTestSheriff.ksLoginName,));
1823 else:
1824 self.uidSelf = self.oLogin.uid;
1825
1826 #
1827 # Do the stuff.
1828 #
1829 if rcExit == 0:
1830 rcExit = self.selfCheck();
1831 if rcExit == 0:
1832 rcExit = self.badTestBoxManagement();
1833 rcExit2 = self.reasoningFailures();
1834 if rcExit == 0:
1835 rcExit = rcExit2;
1836 # Redo the bad testbox management after failure reasons have been assigned (got timing issues).
1837 if rcExit == 0:
1838 rcExit = self.badTestBoxManagement();
1839
1840 # Cleanup.
1841 self.oFailureReasonLogic = None;
1842 self.oTestResultFailureLogic = None;
1843 self.oTestSetLogic = None;
1844 self.oTestResultLogic = None;
1845 self.oDb.close();
1846 self.oDb = None;
1847 if self.oLogFile is not None:
1848 self.oLogFile.close();
1849 self.oLogFile = None;
1850 return rcExit;
1851
1852if __name__ == '__main__':
1853 sys.exit(VirtualTestSheriff().main());
Note: See TracBrowser for help on using the repository browser.

© 2025 Oracle Support Privacy / Do Not Sell My Info Terms of Use Trademark Policy Automated Access Etiquette