testboxtasks.py@ 97405

Last change on this file since 97405 was 96407, checked in by vboxsync, 2 years ago
scm copyright and license note update
Property svn:eol-style set to `native` Property svn:keywords set to `Author Date Id Revision`
File size: 34.9 KB

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

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

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

Download in other formats: