testboxtasks.py@ 86996

Last change on this file since 86996 was 82968, checked in by vboxsync, 5 years ago
Copyright year updates by scm.
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 34.6 KB

Line
1	# -- coding: utf-8 --
2	# $Id: testboxtasks.py 82968 2020-02-04 10:35:17Z vboxsync $
3
4	"""
5	TestBox Script - Async Tasks.
6	"""
7
8	__copyright__ = \
9	"""
10	Copyright (C) 2012-2020 Oracle Corporation
11
12	This file is part of VirtualBox Open Source Edition (OSE), as
13	available from http://www.virtualbox.org. This file is free software;
14	you can redistribute it and/or modify it under the terms of the GNU
15	General Public License (GPL) as published by the Free Software
16	Foundation, in version 2 as it comes in the "COPYING" file of the
17	VirtualBox OSE distribution. VirtualBox OSE is distributed in the
18	hope that it will be useful, but WITHOUT ANY WARRANTY of any kind.
19
20	The contents of this file may alternatively be used under the terms
21	of the Common Development and Distribution License Version 1.0
22	(CDDL) only, as it comes in the "COPYING.CDDL" file of the
23	VirtualBox OSE distribution, in which case the provisions of the
24	CDDL are applicable instead of those of the GPL.
25
26	You may elect to license modified versions of this file under the
27	terms and conditions of either the GPL or the CDDL or both.
28	"""
29	__version__ = "$Revision: 82968 $"
30
31
32	# Standard python imports.
33	from datetime import datetime
34	import os
35	import re
36	import signal;
37	import sys
38	import subprocess
39	import threading
40	import time
41
42	# Validation Kit imports.
43	from common import constants
44	from common import utils;
45	from common import webutils;
46	import testboxcommons
47
48	# Figure where we are.
49	try: __file__
50	except: __file__ = sys.argv[0];
51	g_ksTestScriptDir = os.path.dirname(os.path.abspath(__file__));
52
53
54
55	class TestBoxBaseTask(object):
56	"""
57	Asynchronous task employing a thread to do the actual work.
58	"""
59
60	## Time to wait for a task to terminate.
61	kcSecTerminateTimeout = 60
62
63	def __init__(self, oTestBoxScript, cSecTimeout, fnThreadProc):
64	self._oTestBoxScript = oTestBoxScript;
65	self._cSecTimeout = cSecTimeout;
66	self._tsSecStarted = utils.timestampSecond();
67	self.__oRLock = threading.RLock();
68	self._oCv = threading.Condition(self.__oRLock);
69	self._fRunning = True; # Protected by lock.
70	self._fShouldTerminate = False; # Protected by lock.
71
72	# Spawn the worker thread.
73	self._oThread = threading.Thread(target=fnThreadProc);
74	self._oThread.daemon = True;
75	self._oThread.start();
76
77	def _lock(self):
78	""" Take the CV lock. """
79	self._oCv.acquire();
80
81	def _unlock(self):
82	""" Release the CV lock. """
83	self._oCv.release();
84
85	def _complete(self):
86	"""
87	Indicate that the task is complete, waking up the main thread.
88	Usually called at the end of the thread procedure.
89	"""
90	self._lock();
91	self._fRunning = False;
92	self._oCv.notifyAll();
93	self._unlock();
94
95	def isRunning(self):
96	""" Check if the task is still running. """
97	self._lock();
98	fRunning = self._fRunning;
99	self._unlock();
100	return fRunning;
101
102	def wait(self, cSecTimeout):
103	""" Wait for the task to complete. """
104	self._lock();
105	fRunning = self._fRunning;
106	if fRunning is True and cSecTimeout > 0:
107	self._oCv.wait(cSecTimeout)
108	self._unlock();
109	return fRunning;
110
111	def terminate(self, cSecTimeout = kcSecTerminateTimeout):
112	""" Terminate the task. """
113	self._lock();
114	self._fShouldTerminate = True;
115	self._unlock();
116
117	return self.wait(cSecTimeout);
118
119	def _shouldTerminate(self):
120	"""
121	Returns True if we should terminate, False if not.
122	"""
123	self._lock();
124	fShouldTerminate = self._fShouldTerminate is True;
125	self._unlock();
126	return fShouldTerminate;
127
128
129	class TestBoxTestDriverTask(TestBoxBaseTask):
130	"""
131	Base class for tasks involving test drivers.
132	"""
133
134	## When to flush the backlog of log messages.
135	kcchMaxBackLog = 32768;
136
137	## The backlog sync time (seconds).
138	kcSecBackLogFlush = 30;
139
140	## The timeout for the cleanup job (5 mins).
141	kcSecCleanupTimeout = 300;
142	## The timeout to wait for the abort command before killing it.
143	kcSecAbortTimeout = 300;
144
145	## The timeout to wait for the final output to be processed.
146	kcSecFinalOutputTimeout = 180;
147	## The timeout to wait for the abort command output to be processed.
148	kcSecAbortCmdOutputTimeout = 30;
149	## The timeout to wait for the terminate output to be processed.
150	kcSecTerminateOutputTimeout = 30;
151	## The timeout to wait for the kill output to be processed.
152	kcSecKillOutputTimeout = 30;
153
154	## The timeout for talking to the test manager.
155	ksecTestManagerTimeout = 60;
156
157
158	def __init__(self, oTestBoxScript, fnThreadProc, cSecTimeout, idResult, sScriptCmdLine):
159	"""
160	Class instance init
161	"""
162	# Init our instance data.
163	self._idResult = idResult;
164	self._sScriptCmdLine = sScriptCmdLine;
165	self._oChild = None;
166	self._oBackLogLock = threading.RLock();
167	self._oBackLogFlushLock = threading.RLock();
168	self._asBackLog = [];
169	self._cchBackLog = 0;
170	self._secTsBackLogFlush = utils.timestampSecond();
171
172	# Init super.
173	TestBoxBaseTask.__init__(self, oTestBoxScript, cSecTimeout, fnThreadProc);
174
175	def terminate(self, cSecTimeout = kcSecCleanupTimeout):
176	""" Reimplement with higher default timeout. """
177	return TestBoxBaseTask.terminate(self, cSecTimeout);
178
179	def _logFlush(self, oGivenConnection = None):
180	"""
181	Flushes the log to the test manager.
182
183	No exceptions.
184	"""
185	fRc = True;
186	self._oBackLogFlushLock.acquire();
187
188	# Grab the current back log.
189	self._oBackLogLock.acquire();
190	asBackLog = self._asBackLog;
191	self._asBackLog = [];
192	self._cchBackLog = 0;
193	self._secTsBackLogFlush = utils.timestampSecond();
194	self._oBackLogLock.release();
195
196	# If there is anything to flush, flush it.
197	if asBackLog:
198	sBody = '';
199	for sLine in asBackLog:
200	sBody += sLine + '\n';
201
202	oConnection = None;
203	try:
204	if oGivenConnection is None:
205	oConnection = self._oTestBoxScript.openTestManagerConnection();
206	oConnection.postRequest(constants.tbreq.LOG_MAIN, {constants.tbreq.LOG_PARAM_BODY: sBody});
207	oConnection.close();
208	else:
209	oGivenConnection.postRequest(constants.tbreq.LOG_MAIN, {constants.tbreq.LOG_PARAM_BODY: sBody});
210	except Exception as oXcpt:
211	testboxcommons.log('_logFlush error: %s' % (oXcpt,));
212	if len(sBody) < self.kcchMaxBackLog * 4:
213	self._oBackLogLock.acquire();
214	asBackLog.extend(self._asBackLog);
215	self._asBackLog = asBackLog;
216	# Don't restore _cchBackLog as there is no point in retrying immediately.
217	self._oBackLogLock.release();
218	if oConnection is not None: # Be kind to apache.
219	try: oConnection.close();
220	except: pass;
221	fRc = False;
222
223	self._oBackLogFlushLock.release();
224	return fRc;
225
226	def flushLogOnConnection(self, oConnection):
227	"""
228	Attempts to flush the logon the given connection.
229
230	No exceptions.
231	"""
232	return self._logFlush(oConnection);
233
234	def _logInternal(self, sMessage, fPrefix = True, fFlushCheck = False):
235	"""
236	Internal logging.
237	Won't flush the backlog, returns a flush indicator so the caller can
238	do it instead.
239	"""
240	if fPrefix:
241	try:
242	oNow = datetime.utcnow();
243	sTs = '%02u:%02u:%02u.%06u ' % (oNow.hour, oNow.minute, oNow.second, oNow.microsecond);
244	except Exception as oXcpt:
245	sTs = 'oXcpt=%s ' % (oXcpt);
246	sFullMsg = sTs + sMessage;
247	else:
248	sFullMsg = sMessage;
249
250	self._oBackLogLock.acquire();
251	self._asBackLog.append(sFullMsg);
252	cchBackLog = self._cchBackLog + len(sFullMsg) + 1;
253	self._cchBackLog = cchBackLog;
254	secTsBackLogFlush = self._secTsBackLogFlush;
255	self._oBackLogLock.release();
256
257	testboxcommons.log(sFullMsg);
258	return fFlushCheck \
259	and ( cchBackLog >= self.kcchMaxBackLog \
260	or utils.timestampSecond() - secTsBackLogFlush >= self.kcSecBackLogFlush);
261
262	def _log(self, sMessage):
263	"""
264	General logging function, will flush.
265	"""
266	if self._logInternal(sMessage, fFlushCheck = True):
267	self._logFlush();
268	return True;
269
270	def _reportDone(self, sResult):
271	"""
272	Report EXEC job done to the test manager.
273
274	sResult is a value from constants.result.
275	"""
276	## @todo optimize this to use one server connection.
277
278	#
279	# Log it.
280	#
281	assert sResult in constants.result.g_kasValidResults;
282	self._log('Done %s' % (sResult,));
283
284	#
285	# Report it.
286	#
287	fRc = True;
288	secStart = utils.timestampSecond();
289	while True:
290	self._logFlush(); ## @todo Combine this with EXEC_COMPLETED.
291	oConnection = None;
292	try:
293	oConnection = self._oTestBoxScript.openTestManagerConnection();
294	oConnection.postRequest(constants.tbreq.EXEC_COMPLETED, {constants.tbreq.EXEC_COMPLETED_PARAM_RESULT: sResult});
295	oConnection.close();
296	except Exception as oXcpt:
297	if utils.timestampSecond() - secStart < self.ksecTestManagerTimeout:
298	self._log('_reportDone exception (%s) - retrying...' % (oXcpt,));
299	time.sleep(2);
300	continue;
301	self._log('_reportDone error: %s' % (oXcpt,));
302	if oConnection is not None: # Be kind to apache.
303	try: oConnection.close();
304	except: pass;
305	fRc = False;
306	break;
307
308	#
309	# Mark the task as completed.
310	#
311	self._complete();
312	return fRc;
313
314	def _assembleArguments(self, sAction, fWithInterpreter = True):
315	"""
316	Creates an argument array for subprocess.Popen, splitting the
317	sScriptCmdLine like bourne shell would.
318	fWithInterpreter is used (False) when checking that the script exists.
319
320	Returns None on bad input.
321	"""
322
323	#
324	# This is a good place to export the test set id to the environment.
325	#
326	os.environ['TESTBOX_TEST_SET_ID'] = str(self._idResult);
327	cTimeoutLeft = utils.timestampSecond() - self._tsSecStarted;
328	cTimeoutLeft = 0 if cTimeoutLeft >= self._cSecTimeout else self._cSecTimeout - cTimeoutLeft;
329	os.environ['TESTBOX_TIMEOUT'] = str(cTimeoutLeft);
330	os.environ['TESTBOX_TIMEOUT_ABS'] = str(self._tsSecStarted + self._cSecTimeout);
331
332	#
333	# Do replacements and split the command line into arguments.
334	#
335	if self._sScriptCmdLine.find('@ACTION@') >= 0:
336	sCmdLine = self._sScriptCmdLine.replace('@ACTION@', sAction);
337	else:
338	sCmdLine = self._sScriptCmdLine + ' ' + sAction;
339	for sVar in [ 'TESTBOX_PATH_BUILDS', 'TESTBOX_PATH_RESOURCES', 'TESTBOX_PATH_SCRATCH', 'TESTBOX_PATH_SCRIPTS',
340	'TESTBOX_PATH_UPLOAD', 'TESTBOX_UUID', 'TESTBOX_REPORTER', 'TESTBOX_ID', 'TESTBOX_TEST_SET_ID',
341	'TESTBOX_TIMEOUT', 'TESTBOX_TIMEOUT_ABS' ]:
342	if sCmdLine.find('${' + sVar + '}') >= 0:
343	sCmdLine = sCmdLine.replace('${' + sVar + '}', os.environ[sVar]);
344
345	asArgs = utils.argsSplit(sCmdLine);
346
347	#
348	# Massage argv[0]:
349	# - Convert portable slashes ('/') to the flavor preferred by the
350	# OS we're currently running on.
351	# - Run python script thru the current python interpreter (important
352	# on systems that doesn't sport native hash-bang script execution).
353	#
354	asArgs[0] = asArgs[0].replace('/', os.path.sep);
355	if not os.path.isabs(asArgs[0]):
356	asArgs[0] = os.path.join(self._oTestBoxScript.getPathScripts(), asArgs[0]);
357
358	if asArgs[0].endswith('.py') and fWithInterpreter:
359	if sys.executable:
360	asArgs.insert(0, sys.executable);
361	else:
362	asArgs.insert(0, 'python');
363
364	return asArgs;
365
366	def _outputThreadProc(self, oChild, oStdOut, sAction):
367	"""
368	Thread procedure for the thread that reads the output of the child
369	process. We use a dedicated thread for this purpose since non-blocking
370	I/O may be hard to keep portable according to hints around the web...
371	"""
372	oThread = oChild.oOutputThread;
373	while not oThread.fPleaseQuit:
374	# Get a line.
375	try:
376	sLine = oStdOut.readline();
377	except Exception as oXcpt:
378	self._log('child (%s) pipe I/O error: %s' % (sAction, oXcpt,));
379	break;
380
381	# EOF?
382	if not sLine:
383	break;
384
385	# Strip trailing new line (DOS and UNIX).
386	if sLine.endswith("\r\n"):
387	sLine = sLine[0:-2];
388	elif sLine.endswith("\n"):
389	sLine = sLine[0:-1];
390
391	# Log it.
392	if self._logInternal(sLine, fPrefix = False, fFlushCheck = True):
393	self._logFlush();
394
395	# Close the stdout pipe in case we were told to get lost.
396	try:
397	oStdOut.close();
398	except Exception as oXcpt:
399	self._log('warning: Exception closing stdout pipe of "%s" child: %s' % (sAction, oXcpt,));
400
401	# This is a bit hacky, but try reap the child so it won't hang as
402	# defunkt during abort/timeout.
403	if oChild.poll() is None:
404	for _ in range(15):
405	time.sleep(0.2);
406	if oChild.poll() is not None:
407	break;
408
409	oChild = None;
410	return None;
411
412	def _spawnChild(self, sAction):
413	"""
414	Spawns the child process, returning success indicator + child object.
415	"""
416
417	# Argument list.
418	asArgs = self._assembleArguments(sAction)
419	if asArgs is None:
420	self._log('Malformed command line: "%s"' % (self._sScriptCmdLine,));
421	return (False, None);
422
423	# Spawn child.
424	try:
425	oChild = utils.processPopenSafe(asArgs,
426	shell = False,
427	bufsize = -1,
428	stdout = subprocess.PIPE,
429	stderr = subprocess.STDOUT,
430	cwd = self._oTestBoxScript.getPathSpill(),
431	universal_newlines = True,
432	close_fds = utils.getHostOs() != 'win',
433	preexec_fn = (None if utils.getHostOs() in ['win', 'os2']
434	else os.setsid)); # pylint: disable=no-member
435	except Exception as oXcpt:
436	self._log('Error creating child process %s: %s' % (asArgs, oXcpt));
437	return (False, None);
438
439	oChild.sTestBoxScriptAction = sAction;
440
441	# Start output thread, extending the child object to keep track of it.
442	oChild.oOutputThread = threading.Thread(target=self._outputThreadProc, args=(oChild, oChild.stdout, sAction))
443	oChild.oOutputThread.daemon = True;
444	oChild.oOutputThread.fPleaseQuit = False; # Our extension.
445	oChild.oOutputThread.start();
446
447	return (True, oChild);
448
449	def _monitorChild(self, cSecTimeout, fTryKillCommand = True, oChild = None):
450	"""
451	Monitors the child process. If the child executes longer that
452	cSecTimeout allows, we'll terminate it.
453	Returns Success indicator and constants.result value.
454	"""
455
456	if oChild is None:
457	oChild = self._oChild;
458
459	iProcGroup = oChild.pid;
460	if utils.getHostOs() in ['win', 'os2'] or iProcGroup <= 0:
461	iProcGroup = -2;
462
463	#
464	# Do timeout processing and check the health of the child.
465	#
466	sResult = constants.result.PASSED;
467	seStarted = utils.timestampSecond();
468	while True:
469	# Check status.
470	iRc = oChild.poll();
471	if iRc is not None:
472	self._log('Child doing "%s" completed with exit code %d' % (oChild.sTestBoxScriptAction, iRc));
473	oChild.oOutputThread.join(self.kcSecFinalOutputTimeout);
474
475	if oChild is self._oChild:
476	self._oChild = None;
477
478	if iRc == constants.rtexitcode.SUCCESS:
479	return (True, constants.result.PASSED);
480	if iRc == constants.rtexitcode.SKIPPED:
481	return (True, constants.result.SKIPPED);
482	if iRc == constants.rtexitcode.BAD_TESTBOX:
483	return (False, constants.result.BAD_TESTBOX);
484	return (False, constants.result.FAILED);
485
486	# Check for abort first, since that has less of a stigma.
487	if self._shouldTerminate() is True:
488	sResult = constants.result.ABORTED;
489	break;
490
491	# Check timeout.
492	cSecElapsed = utils.timestampSecond() - seStarted;
493	if cSecElapsed > cSecTimeout:
494	self._log('Timeout: %u secs (limit %u secs)' % (cSecElapsed, cSecTimeout));
495	sResult = constants.result.TIMED_OUT;
496	break;
497
498	# Wait.
499	cSecLeft = cSecTimeout - cSecElapsed;
500	oChild.oOutputThread.join(15 if cSecLeft > 15 else (cSecLeft + 1));
501
502	#
503	# If the child is still alive, try use the abort command to stop it
504	# very gently. This let's the testdriver clean up daemon processes
505	# and such that our code below won't catch.
506	#
507	if fTryKillCommand and oChild.poll() is None:
508	self._log('Attempting to abort child...');
509	(fRc2, oAbortChild) = self._spawnChild('abort');
510	if oAbortChild is not None and fRc2 is True:
511	self._monitorChild(self.kcSecAbortTimeout, False, oAbortChild);
512	oAbortChild = None;
513
514	#
515	# If the child is still alive, try the polite way.
516	#
517	if oChild.poll() is None:
518	self._log('Attempting to terminate child doing "%s"...' % (oChild.sTestBoxScriptAction,));
519
520	if iProcGroup > 0:
521	try:
522	os.killpg(iProcGroup, signal.SIGTERM); # pylint: disable=no-member
523	except Exception as oXcpt:
524	self._log('killpg() failed: %s' % (oXcpt,));
525
526	try:
527	self._oChild.terminate();
528	oChild.oOutputThread.join(self.kcSecTerminateOutputTimeout);
529	except Exception as oXcpt:
530	self._log('terminate() failed: %s' % (oXcpt,));
531
532	#
533	# If the child doesn't respond to polite, kill it. Always do a killpg
534	# should there be any processes left in the group.
535	#
536	if iProcGroup > 0:
537	try:
538	os.killpg(iProcGroup, signal.SIGKILL); # pylint: disable=no-member
539	except Exception as oXcpt:
540	self._log('killpg() failed: %s' % (oXcpt,));
541
542	if oChild.poll() is None:
543	self._log('Attemting to kill child doing "%s"...' % (oChild.sTestBoxScriptAction,));
544	try:
545	self._oChild.kill();
546	oChild.oOutputThread.join(self.kcSecKillOutputTimeout);
547	except Exception as oXcpt:
548	self._log('kill() failed: %s' % (oXcpt,));
549
550	#
551	# Give the whole mess a couple of more seconds to respond in case the
552	# output thread exitted prematurely for some weird reason.
553	#
554	if oChild.poll() is None:
555	time.sleep(2);
556	time.sleep(2);
557	time.sleep(2);
558
559	iRc = oChild.poll();
560	if iRc is not None:
561	self._log('Child doing "%s" aborted with exit code %d' % (oChild.sTestBoxScriptAction, iRc));
562	else:
563	self._log('Child doing "%s" is still running, giving up...' % (oChild.sTestBoxScriptAction,));
564	## @todo in this case we should probably try reboot the testbox...
565	oChild.oOutputThread.fPleaseQuit = True;
566
567	if oChild is self._oChild:
568	self._oChild = None;
569	return (False, sResult);
570
571	def _terminateChild(self):
572	"""
573	Terminates the child forcefully.
574	"""
575	if self._oChild is not None:
576	pass;
577
578	def _cleanupAfter(self):
579	"""
580	Cleans up after a test failure. (On success, cleanup is implicit.)
581	"""
582	assert self._oChild is None;
583
584	#
585	# Tell the script to clean up.
586	#
587	if self._sScriptCmdLine: # can be empty if cleanup crashed.
588	(fRc, self._oChild) = self._spawnChild('cleanup-after');
589	if fRc is True:
590	(fRc, _) = self._monitorChild(self.kcSecCleanupTimeout, False);
591	self._terminateChild();
592	else:
593	fRc = False;
594
595	#
596	# Wipe the stuff clean.
597	#
598	fRc2 = self._oTestBoxScript.reinitScratch(fnLog = self._log, cRetries = 6);
599
600	return fRc and fRc2;
601
602
603
604	class TestBoxCleanupTask(TestBoxTestDriverTask):
605	"""
606	Special asynchronous task for cleaning up a stale test when starting the
607	testbox script. It's assumed that the reason for the stale test lies in
608	it causing a panic, reboot, or similar, so we'll also try collect some
609	info about recent system crashes and reboots.
610	"""
611
612	def __init__(self, oTestBoxScript):
613	# Read the old state, throwing a fit if it's invalid.
614	sScriptState = oTestBoxScript.getPathState();
615	sScriptCmdLine = self._readStateFile(os.path.join(sScriptState, 'script-cmdline.txt'));
616	sResultId = self._readStateFile(os.path.join(sScriptState, 'result-id.txt'));
617	try:
618	idResult = int(sResultId);
619	if idResult <= 0 or idResult >= 0x7fffffff:
620	raise Exception('');
621	except:
622	raise Exception('Invalid id value "%s" found in %s' % (sResultId, os.path.join(sScriptState, 'result-id.txt')));
623
624	sTestBoxId = self._readStateFile(os.path.join(sScriptState, 'testbox-id.txt'));
625	try:
626	self.idTestBox = int(sTestBoxId);
627	if self.idTestBox <= 0 or self.idTestBox >= 0x7fffffff:
628	raise Exception('');
629	except:
630	raise Exception('Invalid id value "%s" found in %s' % (sTestBoxId, os.path.join(sScriptState, 'testbox-id.txt')));
631	self.sTestBoxName = self._readStateFile(os.path.join(sScriptState, 'testbox-name.txt'));
632
633	# Init super.
634	TestBoxTestDriverTask.__init__(self, oTestBoxScript, self._threadProc, self.kcSecCleanupTimeout,
635	idResult, sScriptCmdLine);
636
637	@staticmethod
638	def _readStateFile(sPath):
639	"""
640	Reads a state file, returning a string on success and otherwise raising
641	an exception.
642	"""
643	try:
644	oFile = open(sPath, "rb");
645	sStr = oFile.read();
646	sStr = sStr.decode('utf-8');
647	oFile.close();
648	return sStr.strip();
649	except Exception as oXcpt:
650	raise Exception('Failed to read "%s": %s' % (sPath, oXcpt));
651
652	def _threadProc(self):
653	"""
654	Perform the actual clean up on script startup.
655	"""
656
657	#
658	# First make sure we won't repeat this exercise should it turn out to
659	# trigger another reboot/panic/whatever.
660	#
661	sScriptCmdLine = os.path.join(self._oTestBoxScript.getPathState(), 'script-cmdline.txt');
662	try:
663	os.remove(sScriptCmdLine);
664	oFile = open(sScriptCmdLine, 'wb');
665	oFile.close();
666	except Exception as oXcpt:
667	self._log('Error truncating "%s": %s' % (sScriptCmdLine, oXcpt));
668
669	#
670	# Report the incident.
671	#
672	self._log('Seems we rebooted!');
673	self._log('script-cmdline="%s"' % (self._sScriptCmdLine));
674	self._log('result-id=%d' % (self._idResult));
675	self._log('testbox-id=%d' % (self.idTestBox));
676	self._log('testbox-name=%s' % (self.sTestBoxName));
677	self._logFlush();
678
679	# System specific info.
680	sOs = utils.getHostOs();
681	if sOs == 'darwin':
682	self._log('NVRAM Panic Info:\n%s\n' % (self.darwinGetPanicInfo(),));
683
684	self._logFlush();
685	## @todo Add some special command for reporting this situation so we get something
686	# useful in the event log.
687
688	#
689	# Do the cleaning up.
690	#
691	self._cleanupAfter();
692
693	self._reportDone(constants.result.REBOOTED);
694	return False;
695
696	def darwinGetPanicInfo(self):
697	"""
698	Returns a string with the aapl,panic-info content.
699	"""
700	# Retriev the info.
701	try:
702	sRawInfo = utils.processOutputChecked(['nvram', 'aapl,panic-info']);
703	except Exception as oXcpt:
704	return 'exception running nvram: %s' % (oXcpt,);
705
706	# Decode (%xx) and decompact it (7-bit -> 8-bit).
707	ahDigits = \
708	{
709	'0': 0, '1': 1, '2': 2, '3': 3, '4': 4, '5': 5, '6': 6, '7': 7,
710	'8': 8, '9': 9, 'a': 10, 'b': 11, 'c': 12, 'd': 13, 'e': 14, 'f': 15,
711	};
712	sInfo = '';
713	off = len('aapl,panic-info') + 1;
714	iBit = 0;
715	bLow = 0;
716
717	while off < len(sRawInfo):
718	# isprint is used to determine whether to %xx or %c it, so we have to
719	# be a little careful before assuming % sequences are hex bytes.
720	if sRawInfo[off] == '%' \
721	and off + 3 <= len(sRawInfo) \
722	and sRawInfo[off + 1] in ahDigits \
723	and sRawInfo[off + 2] in ahDigits:
724	bCur = ahDigits[sRawInfo[off + 1]] * 0x10 + ahDigits[sRawInfo[off + 2]];
725	off += 3;
726	else:
727	bCur = ord(sRawInfo[off]);
728	off += 1;
729
730	sInfo += chr(((bCur & (0x7f >> iBit)) << iBit) \| bLow);
731	bLow = bCur >> (7 - iBit);
732
733	if iBit < 6:
734	iBit += 1;
735	else:
736	# Final bit in sequence.
737	sInfo += chr(bLow);
738	bLow = 0;
739	iBit = 0;
740
741	# Expand shorthand.
742	sInfo = sInfo.replace('@', 'com.apple.');
743	sInfo = sInfo.replace('>', 'com.apple.driver.');
744	sInfo = sInfo.replace('\|', 'com.apple.iokit.');
745	sInfo = sInfo.replace('$', 'com.apple.security.');
746	sInfo = sInfo.replace('!A', 'Apple');
747	sInfo = sInfo.replace('!a', 'Action');
748	sInfo = sInfo.replace('!B', 'Bluetooth');
749	sInfo = sInfo.replace('!C', 'Controller');
750	sInfo = sInfo.replace('!F', 'Family');
751	sInfo = sInfo.replace('!I', 'Intel');
752	sInfo = sInfo.replace('!U', 'AppleUSB');
753	sInfo = sInfo.replace('!P', 'Profile');
754
755	# Done.
756	return sInfo
757
758
759	class TestBoxExecTask(TestBoxTestDriverTask):
760	"""
761	Implementation of a asynchronous EXEC task.
762
763	This uses a thread for doing the actual work, i.e. starting and monitoring
764	the child process, processing its output, and more.
765	"""
766
767	def __init__(self, oTestBoxScript, idResult, sScriptZips, sScriptCmdLine, cSecTimeout):
768	"""
769	Class instance init
770	"""
771	# Init our instance data.
772	self._sScriptZips = sScriptZips;
773
774	# Init super.
775	TestBoxTestDriverTask.__init__(self, oTestBoxScript, self._threadProc, cSecTimeout, idResult, sScriptCmdLine);
776
777	@staticmethod
778	def _writeStateFile(sPath, sContent):
779	"""
780	Writes a state file, raising an exception on failure.
781	"""
782	try:
783	oFile = open(sPath, "wb");
784	oFile.write(sContent.encode('utf-8'));
785	oFile.flush();
786	try: os.fsync(oFile.fileno());
787	except: pass;
788	oFile.close();
789	except Exception as oXcpt:
790	raise Exception('Failed to write "%s": %s' % (sPath, oXcpt));
791	return True;
792
793	@staticmethod
794	def _environTxtContent():
795	"""
796	Collects environment variables and values for the environ.txt stat file
797	(for external monitoring tool).
798	"""
799	sText = '';
800	for sVar in [ 'TESTBOX_PATH_BUILDS', 'TESTBOX_PATH_RESOURCES', 'TESTBOX_PATH_SCRATCH', 'TESTBOX_PATH_SCRIPTS',
801	'TESTBOX_PATH_UPLOAD', 'TESTBOX_HAS_HW_VIRT', 'TESTBOX_HAS_NESTED_PAGING', 'TESTBOX_HAS_IOMMU',
802	'TESTBOX_SCRIPT_REV', 'TESTBOX_CPU_COUNT', 'TESTBOX_MEM_SIZE', 'TESTBOX_SCRATCH_SIZE',
803	'TESTBOX_WITH_RAW_MODE', 'TESTBOX_WITH_RAW_MODE', 'TESTBOX_MANAGER_URL', 'TESTBOX_UUID',
804	'TESTBOX_REPORTER', 'TESTBOX_NAME', 'TESTBOX_ID', 'TESTBOX_TEST_SET_ID',
805	'TESTBOX_TIMEOUT', 'TESTBOX_TIMEOUT_ABS', ]:
806	sValue = os.environ.get(sVar);
807	if sValue:
808	sText += sVar + '=' + sValue + '\n';
809	return sText;
810
811	def _saveState(self):
812	"""
813	Saves the task state on disk so we can launch a TestBoxCleanupTask job
814	if the test should cause system panic or similar.
815
816	Note! May later be extended to support tests that reboots the host.
817	"""
818	sScriptState = self._oTestBoxScript.getPathState();
819	try:
820	self._writeStateFile(os.path.join(sScriptState, 'script-cmdline.txt'), self._sScriptCmdLine);
821	self._writeStateFile(os.path.join(sScriptState, 'result-id.txt'), str(self._idResult));
822	self._writeStateFile(os.path.join(sScriptState, 'testbox-id.txt'), str(self._oTestBoxScript.getTestBoxId()));
823	self._writeStateFile(os.path.join(sScriptState, 'testbox-name.txt'), self._oTestBoxScript.getTestBoxName());
824	self._writeStateFile(os.path.join(sScriptState, 'environ.txt'), self._environTxtContent());
825	except Exception as oXcpt:
826	self._log('Failed to write state: %s' % (oXcpt,));
827	return False;
828	return True;
829
830	def _downloadAndUnpackScriptZips(self):
831	"""
832	Downloads/copies the script ZIPs into TESTBOX_SCRIPT and unzips them to
833	the same directory.
834
835	Raises no exceptions, returns log + success indicator instead.
836	"""
837	sPathScript = self._oTestBoxScript.getPathScripts();
838	asArchives = self._sScriptZips.split(',');
839	for sArchive in asArchives:
840	sArchive = sArchive.strip();
841	if not sArchive:
842	continue;
843
844	# Figure the destination name (in scripts).
845	sDstFile = webutils.getFilename(sArchive);
846	if not sDstFile \
847	or re.search('[^a-zA-Z0-9 !#$%&\'()@^_`{}~.-]', sDstFile) is not None: # FAT charset sans 128-255 + '.'.
848	self._log('Malformed script zip filename: %s' % (sArchive,));
849	return False;
850	sDstFile = os.path.join(sPathScript, sDstFile);
851
852	# Do the work.
853	if webutils.downloadFile(sArchive, sDstFile, self._oTestBoxScript.getPathBuilds(), self._log, self._log) is not True:
854	return False;
855	asFiles = utils.unpackFile(sDstFile, sPathScript, self._log, self._log);
856	if asFiles is None:
857	return False;
858
859	# Since zip files doesn't always include mode masks, set the X bit
860	# of all of them so we can execute binaries and hash-bang scripts.
861	for sFile in asFiles:
862	utils.chmodPlusX(sFile);
863
864	return True;
865
866	def _threadProc(self):
867	"""
868	Do the work of an EXEC command.
869	"""
870
871	sResult = constants.result.PASSED;
872
873	#
874	# Start by preparing the scratch directories.
875	#
876	# Note! Failures at this stage are not treated as real errors since
877	# they may be caused by the previous test and other circumstances
878	# so we don't want to go fail a build because of this.
879	#
880	fRc = self._oTestBoxScript.reinitScratch(self._logInternal);
881	fNeedCleanUp = fRc;
882	if fRc is True:
883	fRc = self._downloadAndUnpackScriptZips();
884	testboxcommons.log2('_threadProc: _downloadAndUnpackScriptZips -> %s' % (fRc,));
885	if fRc is not True:
886	sResult = constants.result.BAD_TESTBOX;
887
888	#
889	# Make sure the script exists.
890	#
891	if fRc is True:
892	sScript = self._assembleArguments('none', fWithInterpreter = False)[0];
893	if not os.path.exists(sScript):
894	self._log('The test driver script "%s" cannot be found.' % (sScript,));
895	sDir = sScript;
896	while len(sDir) > 3:
897	sDir = os.path.dirname(sDir);
898	if os.path.exists(sDir):
899	self._log('First existing parent directory is "%s".' % (sDir,));
900	break;
901	fRc = False;
902
903	if fRc is True:
904	#
905	# Start testdriver script.
906	#
907	fRc = self._saveState();
908	if fRc:
909	(fRc, self._oChild) = self._spawnChild('all');
910	testboxcommons.log2('_threadProc: _spawnChild -> %s, %s' % (fRc, self._oChild));
911	if fRc:
912	(fRc, sResult) = self._monitorChild(self._cSecTimeout);
913	testboxcommons.log2('_threadProc: _monitorChild -> %s' % (fRc,));
914
915	# If the run failed, do explicit cleanup unless its a BAD_TESTBOX, since BAD_TESTBOX is
916	# intended for pre-cleanup problems caused by previous test failures. Do a cleanup on
917	# a BAD_TESTBOX could easily trigger an uninstallation error and change status to FAILED.
918	if fRc is not True:
919	if sResult != constants.result.BAD_TESTBOX:
920	testboxcommons.log2('_threadProc: explicit cleanups...');
921	self._terminateChild();
922	self._cleanupAfter();
923	fNeedCleanUp = False;
924	assert self._oChild is None;
925
926	#
927	# Clean up scratch.
928	#
929	if fNeedCleanUp:
930	if self._oTestBoxScript.reinitScratch(self._logInternal, cRetries = 6) is not True:
931	self._log('post run reinitScratch failed.');
932	fRc = False;
933
934	#
935	# Report status and everything back to the test manager.
936	#
937	if fRc is False and sResult == constants.result.PASSED:
938	sResult = constants.result.FAILED;
939	self._reportDone(sResult);
940	return fRc;
941

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

source: vbox/trunk/src/VBox/ValidationKit/testboxscript/testboxtasks.py@ 86996

Download in other formats: