blob: 76840239065695c35e734f9c332f67d043c0438e [file] [log] [blame]
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001#!/usr/bin/python -u
Hung-Te Linf2f78f72012-02-08 19:27:11 +08002# -*- coding: utf-8 -*-
3#
Jon Salz37eccbd2012-05-25 16:06:52 +08004# Copyright (c) 2012 The Chromium OS Authors. All rights reserved.
Hung-Te Linf2f78f72012-02-08 19:27:11 +08005# Use of this source code is governed by a BSD-style license that can be
6# found in the LICENSE file.
7
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08008"""The main factory flow that runs the factory test and finalizes a device."""
Hung-Te Linf2f78f72012-02-08 19:27:11 +08009
Jon Salze12c2b32013-06-25 16:24:34 +080010import glob
Jon Salz0405ab52012-03-16 15:26:52 +080011import logging
12import os
Jon Salz73e0fd02012-04-04 11:46:38 +080013import Queue
Jon Salze12c2b32013-06-25 16:24:34 +080014import shutil
Jon Salz77c151e2012-08-28 07:20:37 +080015import signal
Jon Salz0405ab52012-03-16 15:26:52 +080016import sys
Jon Salzeff94182013-06-19 15:06:28 +080017import syslog
Jon Salz0405ab52012-03-16 15:26:52 +080018import threading
19import time
20import traceback
Jon Salz258a40c2012-04-19 12:34:01 +080021import uuid
Jon Salzb10cf512012-08-09 17:29:21 +080022from xmlrpclib import Binary
Hung-Te Linf2f78f72012-02-08 19:27:11 +080023from collections import deque
24from optparse import OptionParser
Hung-Te Linf2f78f72012-02-08 19:27:11 +080025
Jon Salz0697cbf2012-07-04 15:14:04 +080026import factory_common # pylint: disable=W0611
jcliangcd688182012-08-20 21:01:26 +080027from cros.factory import event_log
28from cros.factory import system
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +080029from cros.factory.event_log import EventLog, FloatDigit
Tom Wai-Hong Tamd33723e2013-04-10 21:14:37 +080030from cros.factory.event_log_watcher import EventLogWatcher
jcliangcd688182012-08-20 21:01:26 +080031from cros.factory.goofy import test_environment
32from cros.factory.goofy import time_sanitizer
Jon Salz83591782012-06-26 11:09:58 +080033from cros.factory.goofy import updater
jcliangcd688182012-08-20 21:01:26 +080034from cros.factory.goofy.goofy_rpc import GoofyRPC
Jon Salz885dcac2013-07-23 16:39:50 +080035from cros.factory.goofy.invocation import TestArgEnv
jcliangcd688182012-08-20 21:01:26 +080036from cros.factory.goofy.invocation import TestInvocation
37from cros.factory.goofy.prespawner import Prespawner
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +080038from cros.factory.goofy.system_log_manager import SystemLogManager
jcliangcd688182012-08-20 21:01:26 +080039from cros.factory.goofy.web_socket_manager import WebSocketManager
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +080040from cros.factory.system.board import Board, BoardException
jcliangcd688182012-08-20 21:01:26 +080041from cros.factory.system.charge_manager import ChargeManager
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +080042from cros.factory.system.core_dump_manager import CoreDumpManager
Jon Salzce6a7f82013-06-10 18:22:54 +080043from cros.factory.system.cpufreq_manager import CpufreqManager
Jon Salzb92c5112012-09-21 15:40:11 +080044from cros.factory.system import disk_space
jcliangcd688182012-08-20 21:01:26 +080045from cros.factory.test import factory
Jon Salz670ce062014-05-16 15:53:50 +080046from cros.factory.test import phase
jcliangcd688182012-08-20 21:01:26 +080047from cros.factory.test import state
Jon Salz51528e12012-07-02 18:54:45 +080048from cros.factory.test import shopfloor
Jon Salz83591782012-06-26 11:09:58 +080049from cros.factory.test import utils
Jon Salz128b0932013-07-03 16:55:26 +080050from cros.factory.test.test_lists import test_lists
Ricky Liang6fe218c2013-12-27 15:17:17 +080051from cros.factory.test.e2e_test.common import (
52 AutomationMode, AutomationModePrompt, ParseAutomationMode)
Jon Salz83591782012-06-26 11:09:58 +080053from cros.factory.test.event import Event
54from cros.factory.test.event import EventClient
55from cros.factory.test.event import EventServer
jcliangcd688182012-08-20 21:01:26 +080056from cros.factory.test.factory import TestState
Jon Salzd7550792013-07-12 05:49:27 +080057from cros.factory.test.utils import Enum
Dean Liao592e4d52013-01-10 20:06:39 +080058from cros.factory.tools.key_filter import KeyFilter
Jon Salz2af235d2013-06-24 14:47:21 +080059from cros.factory.utils import file_utils
Jon Salz78c32392012-07-25 14:18:29 +080060from cros.factory.utils.process_utils import Spawn
Hung-Te Linf2f78f72012-02-08 19:27:11 +080061
62
Hung-Te Linf2f78f72012-02-08 19:27:11 +080063HWID_CFG_PATH = '/usr/local/share/chromeos-hwid/cfg'
Chun-ta Lin279e7e92013-02-19 17:40:39 +080064CACHES_DIR = os.path.join(factory.get_state_root(), "caches")
Hung-Te Linf2f78f72012-02-08 19:27:11 +080065
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +080066CLEANUP_LOGS_PAUSED = '/var/lib/cleanup_logs_paused'
67
Jon Salz5c344f62012-07-13 14:31:16 +080068# Value for tests_after_shutdown that forces auto-run (e.g., after
69# a factory update, when the available set of tests might change).
70FORCE_AUTO_RUN = 'force_auto_run'
71
cychiang21886742012-07-05 15:16:32 +080072RUN_QUEUE_TIMEOUT_SECS = 10
73
Justin Chuang83813982013-05-13 01:26:32 +080074# Sync disks when battery level is higher than this value.
75# Otherwise, power loss during disk sync operation may incur even worse outcome.
76MIN_BATTERY_LEVEL_FOR_DISK_SYNC = 1.0
77
Jon Salze12c2b32013-06-25 16:24:34 +080078MAX_CRASH_FILE_SIZE = 64*1024
79
Jon Salz758e6cc2012-04-03 15:47:07 +080080GOOFY_IN_CHROOT_WARNING = '\n' + ('*' * 70) + '''
81You are running Goofy inside the chroot. Autotests are not supported.
82
83To use Goofy in the chroot, first install an Xvnc server:
84
Jon Salz0697cbf2012-07-04 15:14:04 +080085 sudo apt-get install tightvncserver
Jon Salz758e6cc2012-04-03 15:47:07 +080086
87...and then start a VNC X server outside the chroot:
88
Jon Salz0697cbf2012-07-04 15:14:04 +080089 vncserver :10 &
90 vncviewer :10
Jon Salz758e6cc2012-04-03 15:47:07 +080091
92...and run Goofy as follows:
93
Jon Salz0697cbf2012-07-04 15:14:04 +080094 env --unset=XAUTHORITY DISPLAY=localhost:10 python goofy.py
Jon Salz758e6cc2012-04-03 15:47:07 +080095''' + ('*' * 70)
Jon Salz73e0fd02012-04-04 11:46:38 +080096suppress_chroot_warning = False
Hung-Te Linf2f78f72012-02-08 19:27:11 +080097
Jon Salzd7550792013-07-12 05:49:27 +080098Status = Enum(['UNINITIALIZED', 'INITIALIZING', 'RUNNING',
99 'TERMINATING', 'TERMINATED'])
100
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800101def get_hwid_cfg():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800102 """Returns the HWID config tag, or an empty string if none can be found."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800103 if 'CROS_HWID' in os.environ:
104 return os.environ['CROS_HWID']
105 if os.path.exists(HWID_CFG_PATH):
106 with open(HWID_CFG_PATH, 'rt') as hwid_cfg_handle:
107 return hwid_cfg_handle.read().strip()
108 return ''
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800109
110
Jon Salz73e0fd02012-04-04 11:46:38 +0800111_inited_logging = False
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800112
113class Goofy(object):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800114 """The main factory flow.
Jon Salz0697cbf2012-07-04 15:14:04 +0800115
116 Note that all methods in this class must be invoked from the main
117 (event) thread. Other threads, such as callbacks and TestInvocation
118 methods, should instead post events on the run queue.
119
120 TODO: Unit tests. (chrome-os-partner:7409)
121
122 Properties:
123 uuid: A unique UUID for this invocation of Goofy.
124 state_instance: An instance of FactoryState.
125 state_server: The FactoryState XML/RPC server.
126 state_server_thread: A thread running state_server.
127 event_server: The EventServer socket server.
128 event_server_thread: A thread running event_server.
129 event_client: A client to the event server.
130 connection_manager: The connection_manager object.
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800131 system_log_manager: The SystemLogManager object.
132 core_dump_manager: The CoreDumpManager object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800133 ui_process: The factory ui process object.
134 run_queue: A queue of callbacks to invoke from the main thread.
135 invocations: A map from FactoryTest objects to the corresponding
136 TestInvocations objects representing active tests.
137 tests_to_run: A deque of tests that should be run when the current
138 test(s) complete.
139 options: Command-line options.
140 args: Command-line args.
141 test_list: The test list.
Jon Salz128b0932013-07-03 16:55:26 +0800142 test_lists: All new-style test lists.
Ricky Liang4bff3e32014-02-20 18:46:11 +0800143 run_id: The identifier for latest test run.
144 scheduled_run_tests: The list of tests scheduled for latest test run.
Jon Salz0697cbf2012-07-04 15:14:04 +0800145 event_handlers: Map of Event.Type to the method used to handle that
146 event. If the method has an 'event' argument, the event is passed
147 to the handler.
148 exceptions: Exceptions encountered in invocation threads.
Jon Salz3c493bb2013-02-07 17:24:58 +0800149 last_log_disk_space_message: The last message we logged about disk space
150 (to avoid duplication).
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800151 last_kick_sync_time: The last time to kick system_log_manager to sync
152 because of core dump files (to avoid kicking too soon then abort the
153 sync.)
Jon Salz416f9cc2013-05-10 18:32:50 +0800154 hooks: A Hooks object containing hooks for various Goofy actions.
Jon Salzd7550792013-07-12 05:49:27 +0800155 status: The current Goofy status (a member of the Status enum).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800156 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800157 def __init__(self):
158 self.uuid = str(uuid.uuid4())
159 self.state_instance = None
160 self.state_server = None
161 self.state_server_thread = None
Jon Salz16d10542012-07-23 12:18:45 +0800162 self.goofy_rpc = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800163 self.event_server = None
164 self.event_server_thread = None
165 self.event_client = None
166 self.connection_manager = None
Vic Yang4953fc12012-07-26 16:19:53 +0800167 self.charge_manager = None
Jon Salz8fa8e832012-07-13 19:04:09 +0800168 self.time_sanitizer = None
169 self.time_synced = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800170 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800171 self.system_log_manager = None
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800172 self.core_dump_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800173 self.event_log = None
174 self.prespawner = None
175 self.ui_process = None
Jon Salzc79a9982012-08-30 04:42:01 +0800176 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800177 self.run_queue = Queue.Queue()
178 self.invocations = {}
179 self.tests_to_run = deque()
180 self.visible_test = None
181 self.chrome = None
Jon Salz416f9cc2013-05-10 18:32:50 +0800182 self.hooks = None
Vic Yangd8990da2013-06-27 16:57:43 +0800183 self.cpu_usage_watcher = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800184
185 self.options = None
186 self.args = None
187 self.test_list = None
Jon Salz128b0932013-07-03 16:55:26 +0800188 self.test_lists = None
Ricky Liang4bff3e32014-02-20 18:46:11 +0800189 self.run_id = None
190 self.scheduled_run_tests = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800191 self.on_ui_startup = []
192 self.env = None
Jon Salzb22d1172012-08-06 10:38:57 +0800193 self.last_idle = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800194 self.last_shutdown_time = None
cychiang21886742012-07-05 15:16:32 +0800195 self.last_update_check = None
Jon Salz8fa8e832012-07-13 19:04:09 +0800196 self.last_sync_time = None
Jon Salzb92c5112012-09-21 15:40:11 +0800197 self.last_log_disk_space_time = None
Jon Salz3c493bb2013-02-07 17:24:58 +0800198 self.last_log_disk_space_message = None
Justin Chuang83813982013-05-13 01:26:32 +0800199 self.last_check_battery_time = None
200 self.last_check_battery_message = None
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800201 self.last_kick_sync_time = None
Vic Yang311ddb82012-09-26 12:08:28 +0800202 self.exclusive_items = set()
Jon Salz0f996602012-10-03 15:26:48 +0800203 self.event_log = None
Dean Liao592e4d52013-01-10 20:06:39 +0800204 self.key_filter = None
Jon Salzce6a7f82013-06-10 18:22:54 +0800205 self.cpufreq_manager = None
Jon Salzd7550792013-07-12 05:49:27 +0800206 self.status = Status.UNINITIALIZED
Jon Salz0697cbf2012-07-04 15:14:04 +0800207
Jon Salz85a39882012-07-05 16:45:04 +0800208 def test_or_root(event, parent_or_group=True):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800209 """Returns the test affected by a particular event.
Jon Salz85a39882012-07-05 16:45:04 +0800210
211 Args:
212 event: The event containing an optional 'path' attribute.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800213 parent_or_group: If True, returns the top-level parent for a test (the
Jon Salz85a39882012-07-05 16:45:04 +0800214 root node of the tests that need to be run together if the given test
215 path is to be run).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800216 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800217 try:
218 path = event.path
219 except AttributeError:
220 path = None
221
222 if path:
Jon Salz85a39882012-07-05 16:45:04 +0800223 test = self.test_list.lookup_path(path)
224 if parent_or_group:
225 test = test.get_top_level_parent_or_group()
226 return test
Jon Salz0697cbf2012-07-04 15:14:04 +0800227 else:
228 return self.test_list
229
230 self.event_handlers = {
231 Event.Type.SWITCH_TEST: self.handle_switch_test,
232 Event.Type.SHOW_NEXT_ACTIVE_TEST:
233 lambda event: self.show_next_active_test(),
234 Event.Type.RESTART_TESTS:
235 lambda event: self.restart_tests(root=test_or_root(event)),
236 Event.Type.AUTO_RUN:
237 lambda event: self.auto_run(root=test_or_root(event)),
238 Event.Type.RE_RUN_FAILED:
239 lambda event: self.re_run_failed(root=test_or_root(event)),
240 Event.Type.RUN_TESTS_WITH_STATUS:
241 lambda event: self.run_tests_with_status(
242 event.status,
243 root=test_or_root(event)),
244 Event.Type.REVIEW:
245 lambda event: self.show_review_information(),
246 Event.Type.UPDATE_SYSTEM_INFO:
247 lambda event: self.update_system_info(),
Jon Salz0697cbf2012-07-04 15:14:04 +0800248 Event.Type.STOP:
Jon Salz85a39882012-07-05 16:45:04 +0800249 lambda event: self.stop(root=test_or_root(event, False),
Jon Salz6dc031d2013-06-19 13:06:23 +0800250 fail=getattr(event, 'fail', False),
251 reason=getattr(event, 'reason', None)),
Jon Salz36fbbb52012-07-05 13:45:06 +0800252 Event.Type.SET_VISIBLE_TEST:
253 lambda event: self.set_visible_test(
254 self.test_list.lookup_path(event.path)),
Jon Salz4712ac72013-02-07 17:12:05 +0800255 Event.Type.CLEAR_STATE:
256 lambda event: self.clear_state(self.test_list.lookup_path(event.path)),
Jon Salz0697cbf2012-07-04 15:14:04 +0800257 }
258
259 self.exceptions = []
260 self.web_socket_manager = None
261
262 def destroy(self):
Jon Salzd7550792013-07-12 05:49:27 +0800263 self.status = Status.TERMINATING
Jon Salz0697cbf2012-07-04 15:14:04 +0800264 if self.chrome:
265 self.chrome.kill()
266 self.chrome = None
Jon Salzc79a9982012-08-30 04:42:01 +0800267 if self.dummy_shopfloor:
268 self.dummy_shopfloor.kill()
269 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800270 if self.ui_process:
271 utils.kill_process_tree(self.ui_process, 'ui')
272 self.ui_process = None
273 if self.web_socket_manager:
274 logging.info('Stopping web sockets')
275 self.web_socket_manager.close()
276 self.web_socket_manager = None
277 if self.state_server_thread:
278 logging.info('Stopping state server')
279 self.state_server.shutdown()
280 self.state_server_thread.join()
281 self.state_server.server_close()
282 self.state_server_thread = None
283 if self.state_instance:
284 self.state_instance.close()
285 if self.event_server_thread:
286 logging.info('Stopping event server')
287 self.event_server.shutdown() # pylint: disable=E1101
288 self.event_server_thread.join()
289 self.event_server.server_close()
290 self.event_server_thread = None
291 if self.log_watcher:
292 if self.log_watcher.IsThreadStarted():
293 self.log_watcher.StopWatchThread()
294 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800295 if self.system_log_manager:
296 if self.system_log_manager.IsThreadRunning():
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +0800297 self.system_log_manager.Stop()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800298 self.system_log_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800299 if self.prespawner:
300 logging.info('Stopping prespawner')
301 self.prespawner.stop()
302 self.prespawner = None
303 if self.event_client:
304 logging.info('Closing event client')
305 self.event_client.close()
306 self.event_client = None
Jon Salzddf0d052013-06-18 12:52:44 +0800307 if self.cpufreq_manager:
308 self.cpufreq_manager.Stop()
Jon Salz0697cbf2012-07-04 15:14:04 +0800309 if self.event_log:
310 self.event_log.Close()
311 self.event_log = None
Dean Liao592e4d52013-01-10 20:06:39 +0800312 if self.key_filter:
313 self.key_filter.Stop()
Vic Yangd8990da2013-06-27 16:57:43 +0800314 if self.cpu_usage_watcher:
315 self.cpu_usage_watcher.terminate()
Dean Liao592e4d52013-01-10 20:06:39 +0800316
Jon Salz0697cbf2012-07-04 15:14:04 +0800317 self.check_exceptions()
318 logging.info('Done destroying Goofy')
Jon Salzd7550792013-07-12 05:49:27 +0800319 self.status = Status.TERMINATED
Jon Salz0697cbf2012-07-04 15:14:04 +0800320
321 def start_state_server(self):
Jon Salz2af235d2013-06-24 14:47:21 +0800322 # Before starting state server, remount stateful partitions with
323 # no commit flag. The default commit time (commit=600) makes corruption
324 # too likely.
325 file_utils.ResetCommitTime()
326
Jon Salz0697cbf2012-07-04 15:14:04 +0800327 self.state_instance, self.state_server = (
328 state.create_server(bind_address='0.0.0.0'))
Jon Salz16d10542012-07-23 12:18:45 +0800329 self.goofy_rpc = GoofyRPC(self)
330 self.goofy_rpc.RegisterMethods(self.state_instance)
Jon Salz0697cbf2012-07-04 15:14:04 +0800331 logging.info('Starting state server')
332 self.state_server_thread = threading.Thread(
333 target=self.state_server.serve_forever,
334 name='StateServer')
335 self.state_server_thread.start()
336
337 def start_event_server(self):
338 self.event_server = EventServer()
339 logging.info('Starting factory event server')
340 self.event_server_thread = threading.Thread(
341 target=self.event_server.serve_forever,
342 name='EventServer') # pylint: disable=E1101
343 self.event_server_thread.start()
344
345 self.event_client = EventClient(
346 callback=self.handle_event, event_loop=self.run_queue)
347
348 self.web_socket_manager = WebSocketManager(self.uuid)
349 self.state_server.add_handler("/event",
350 self.web_socket_manager.handle_web_socket)
351
352 def start_ui(self):
353 ui_proc_args = [
354 os.path.join(factory.FACTORY_PACKAGE_PATH, 'test', 'ui.py'),
355 self.options.test_list]
356 if self.options.verbose:
357 ui_proc_args.append('-v')
358 logging.info('Starting ui %s', ui_proc_args)
Jon Salz78c32392012-07-25 14:18:29 +0800359 self.ui_process = Spawn(ui_proc_args)
Jon Salz0697cbf2012-07-04 15:14:04 +0800360 logging.info('Waiting for UI to come up...')
361 self.event_client.wait(
362 lambda event: event.type == Event.Type.UI_READY)
363 logging.info('UI has started')
364
365 def set_visible_test(self, test):
366 if self.visible_test == test:
367 return
Jon Salz2f2d42c2012-07-30 12:30:34 +0800368 if test and not test.has_ui:
369 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800370
371 if test:
372 test.update_state(visible=True)
373 if self.visible_test:
374 self.visible_test.update_state(visible=False)
375 self.visible_test = test
376
Ricky Liang48e47f92014-02-26 19:31:51 +0800377 def log_startup_messages(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800378 """Logs the tail of var/log/messages and mosys and EC console logs."""
Jon Salzd4306c82012-11-30 15:16:36 +0800379 # TODO(jsalz): This is mostly a copy-and-paste of code in init_states,
380 # for factory-3004.B only. Consolidate and merge back to ToT.
381 if utils.in_chroot():
382 return
383
384 try:
385 var_log_messages = (
386 utils.var_log_messages_before_reboot())
387 logging.info(
388 'Tail of /var/log/messages before last reboot:\n'
389 '%s', ('\n'.join(
390 ' ' + x for x in var_log_messages)))
391 except: # pylint: disable=W0702
392 logging.exception('Unable to grok /var/log/messages')
393
394 try:
Ricky Liang117484a2014-04-14 11:14:41 +0800395 mosys_log = Spawn(
Jon Salzd4306c82012-11-30 15:16:36 +0800396 ['mosys', 'eventlog', 'list'],
397 read_stdout=True, log_stderr_on_error=True).stdout_data
398 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
399 except: # pylint: disable=W0702
400 logging.exception('Unable to read mosys eventlog')
401
402 try:
Vic Yang8341dde2013-01-29 16:48:52 +0800403 board = system.GetBoard()
404 ec_console_log = board.GetECConsoleLog()
Jon Salzd4306c82012-11-30 15:16:36 +0800405 logging.info('EC console log after reboot:\n%s\n', ec_console_log)
406 except: # pylint: disable=W0702
407 logging.exception('Error retrieving EC console log')
408
Vic Yang079f9872013-07-01 11:32:00 +0800409 try:
410 board = system.GetBoard()
411 ec_panic_info = board.GetECPanicInfo()
412 logging.info('EC panic info after reboot:\n%s\n', ec_panic_info)
413 except: # pylint: disable=W0702
414 logging.exception('Error retrieving EC panic info')
415
Ricky Liang48e47f92014-02-26 19:31:51 +0800416 def shutdown(self, operation):
417 """Starts shutdown procedure.
418
419 Args:
Vic (Chun-Ju) Yang05b0d952014-04-28 17:39:09 +0800420 operation: The shutdown operation (reboot, full_reboot, or halt).
Ricky Liang48e47f92014-02-26 19:31:51 +0800421 """
422 active_tests = []
423 for test in self.test_list.walk():
424 if not test.is_leaf():
425 continue
426
427 test_state = test.get_state()
428 if test_state.status == TestState.ACTIVE:
429 active_tests.append(test)
430
431
432 if not (len(active_tests) == 1 and
433 isinstance(active_tests[0], factory.ShutdownStep)):
434 logging.error(
435 'Calling Goofy shutdown outside of the shutdown factory test')
436 return
437
438 logging.info('Start Goofy shutdown (%s)', operation)
439 # Save pending test list in the state server
440 self.state_instance.set_shared_data(
441 'tests_after_shutdown',
442 [t.path for t in self.tests_to_run])
443 # Save shutdown time
444 self.state_instance.set_shared_data('shutdown_time', time.time())
445
446 with self.env.lock:
447 self.event_log.Log('shutdown', operation=operation)
448 shutdown_result = self.env.shutdown(operation)
449 if shutdown_result:
450 # That's all, folks!
451 self.run_queue.put(None)
452 else:
453 # Just pass (e.g., in the chroot).
454 self.state_instance.set_shared_data('tests_after_shutdown', None)
455 # Send event with no fields to indicate that there is no
456 # longer a pending shutdown.
457 self.event_client.post_event(Event(Event.Type.PENDING_SHUTDOWN))
458
459 def handle_shutdown_complete(self, test):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800460 """Handles the case where a shutdown was detected during a shutdown step.
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800461
Ricky Liang6fe218c2013-12-27 15:17:17 +0800462 Args:
463 test: The ShutdownStep.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800464 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800465 test_state = test.update_state(increment_shutdown_count=1)
466 logging.info('Detected shutdown (%d of %d)',
Ricky Liang48e47f92014-02-26 19:31:51 +0800467 test_state.shutdown_count, test.iterations)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800468
Ricky Liang48e47f92014-02-26 19:31:51 +0800469 # Insert current shutdown test at the front of the list of tests to run
470 # after shutdown. This is to continue on post-shutdown verification in the
471 # shutdown step.
472 tests_after_shutdown = self.state_instance.get_shared_data(
473 'tests_after_shutdown', optional=True)
474 if not tests_after_shutdown:
475 self.state_instance.set_shared_data('tests_after_shutdown', [test.path])
476 elif isinstance(tests_after_shutdown, list):
477 self.state_instance.set_shared_data(
478 'tests_after_shutdown', [test.path] + tests_after_shutdown)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800479
Ricky Liang48e47f92014-02-26 19:31:51 +0800480 # Set 'post_shutdown' to inform shutdown test that a shutdown just occurred.
481 self.state_instance.set_shared_data('post_shutdown', True)
Jon Salz258a40c2012-04-19 12:34:01 +0800482
Jon Salz0697cbf2012-07-04 15:14:04 +0800483 def init_states(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800484 """Initializes all states on startup."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800485 for test in self.test_list.get_all_tests():
486 # Make sure the state server knows about all the tests,
487 # defaulting to an untested state.
488 test.update_state(update_parent=False, visible=False)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800489
Jon Salz0697cbf2012-07-04 15:14:04 +0800490 var_log_messages = None
Vic Yanga9c32212012-08-16 20:07:54 +0800491 mosys_log = None
Vic Yange4c275d2012-08-28 01:50:20 +0800492 ec_console_log = None
Vic Yang079f9872013-07-01 11:32:00 +0800493 ec_panic_info = None
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800494
Jon Salz0697cbf2012-07-04 15:14:04 +0800495 # Any 'active' tests should be marked as failed now.
496 for test in self.test_list.walk():
Jon Salza6711d72012-07-18 14:33:03 +0800497 if not test.is_leaf():
498 # Don't bother with parents; they will be updated when their
499 # children are updated.
500 continue
501
Jon Salz0697cbf2012-07-04 15:14:04 +0800502 test_state = test.get_state()
503 if test_state.status != TestState.ACTIVE:
504 continue
505 if isinstance(test, factory.ShutdownStep):
506 # Shutdown while the test was active - that's good.
Ricky Liang48e47f92014-02-26 19:31:51 +0800507 self.handle_shutdown_complete(test)
Jon Salz0697cbf2012-07-04 15:14:04 +0800508 else:
509 # Unexpected shutdown. Grab /var/log/messages for context.
510 if var_log_messages is None:
511 try:
512 var_log_messages = (
513 utils.var_log_messages_before_reboot())
514 # Write it to the log, to make it easier to
515 # correlate with /var/log/messages.
516 logging.info(
517 'Unexpected shutdown. '
518 'Tail of /var/log/messages before last reboot:\n'
519 '%s', ('\n'.join(
520 ' ' + x for x in var_log_messages)))
521 except: # pylint: disable=W0702
522 logging.exception('Unable to grok /var/log/messages')
523 var_log_messages = []
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800524
Jon Salz008f4ea2012-08-28 05:39:45 +0800525 if mosys_log is None and not utils.in_chroot():
526 try:
Ricky Liang117484a2014-04-14 11:14:41 +0800527 mosys_log = Spawn(
Jon Salz008f4ea2012-08-28 05:39:45 +0800528 ['mosys', 'eventlog', 'list'],
529 read_stdout=True, log_stderr_on_error=True).stdout_data
530 # Write it to the log also.
531 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
532 except: # pylint: disable=W0702
533 logging.exception('Unable to read mosys eventlog')
Vic Yanga9c32212012-08-16 20:07:54 +0800534
Vic Yange4c275d2012-08-28 01:50:20 +0800535 if ec_console_log is None:
536 try:
Vic Yang8341dde2013-01-29 16:48:52 +0800537 board = system.GetBoard()
538 ec_console_log = board.GetECConsoleLog()
Vic Yange4c275d2012-08-28 01:50:20 +0800539 logging.info('EC console log after reboot:\n%s\n', ec_console_log)
Jon Salzfe1f6652012-09-07 05:40:14 +0800540 except: # pylint: disable=W0702
Vic Yange4c275d2012-08-28 01:50:20 +0800541 logging.exception('Error retrieving EC console log')
542
Vic Yang079f9872013-07-01 11:32:00 +0800543 if ec_panic_info is None:
544 try:
545 board = system.GetBoard()
546 ec_panic_info = board.GetECPanicInfo()
547 logging.info('EC panic info after reboot:\n%s\n', ec_panic_info)
548 except: # pylint: disable=W0702
549 logging.exception('Error retrieving EC panic info')
550
Jon Salz0697cbf2012-07-04 15:14:04 +0800551 error_msg = 'Unexpected shutdown while test was running'
552 self.event_log.Log('end_test',
553 path=test.path,
554 status=TestState.FAILED,
555 invocation=test.get_state().invocation,
556 error_msg=error_msg,
Vic Yanga9c32212012-08-16 20:07:54 +0800557 var_log_messages='\n'.join(var_log_messages),
558 mosys_log=mosys_log)
Jon Salz0697cbf2012-07-04 15:14:04 +0800559 test.update_state(
560 status=TestState.FAILED,
561 error_msg=error_msg)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800562
Jon Salz50efe942012-07-26 11:54:10 +0800563 if not test.never_fails:
564 # For "never_fails" tests (such as "Start"), don't cancel
565 # pending tests, since reboot is expected.
566 factory.console.info('Unexpected shutdown while test %s '
567 'running; cancelling any pending tests',
568 test.path)
569 self.state_instance.set_shared_data('tests_after_shutdown', [])
Jon Salz69806bb2012-07-20 18:05:02 +0800570
Jon Salz008f4ea2012-08-28 05:39:45 +0800571 self.update_skipped_tests()
572
573 def update_skipped_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800574 """Updates skipped states based on run_if."""
Jon Salz885dcac2013-07-23 16:39:50 +0800575 env = TestArgEnv()
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800576 def _evaluate_skip_from_run_if(test):
577 """Returns the run_if evaluation of the test.
578
579 Args:
580 test: A FactoryTest object.
581
582 Returns:
583 The run_if evaluation result. Returns False if the test has no
584 run_if argument.
585 """
586 value = None
587 if test.run_if_expr:
588 try:
589 value = test.run_if_expr(env)
590 except: # pylint: disable=W0702
591 logging.exception('Unable to evaluate run_if expression for %s',
592 test.path)
593 # But keep going; we have no choice. This will end up
594 # always activating the test.
595 elif test.run_if_table_name:
596 try:
597 aux = shopfloor.get_selected_aux_data(test.run_if_table_name)
598 value = aux.get(test.run_if_col)
599 except ValueError:
600 # Not available; assume it shouldn't be skipped
601 pass
602
603 if value is None:
604 skip = False
605 else:
606 skip = (not value) ^ t.run_if_not
607 return skip
608
609 # Gets all run_if evaluation, and stores results in skip_map.
610 skip_map = dict()
Jon Salz008f4ea2012-08-28 05:39:45 +0800611 for t in self.test_list.walk():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800612 skip_map[t.path] = _evaluate_skip_from_run_if(t)
Jon Salz885dcac2013-07-23 16:39:50 +0800613
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800614 # Propagates the skip value from root of tree and updates skip_map.
615 def _update_skip_map_from_node(test, skip_from_parent):
616 """Updates skip_map from a given node.
Jon Salz885dcac2013-07-23 16:39:50 +0800617
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800618 Given a FactoryTest node and the skip value from parent, updates the
619 skip value of current node in the skip_map if skip value from parent is
620 True. If this node has children, recursively propagate this value to all
621 its children, that is, all its subtests.
622 Note that this function only updates value in skip_map, not the actual
623 test_list tree.
Jon Salz008f4ea2012-08-28 05:39:45 +0800624
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800625 Args:
626 test: The given FactoryTest object. It is a node in the test_list tree.
627 skip_from_parent: The skip value which propagates from the parent of
628 input node.
629 """
630 skip_this_tree = skip_from_parent or skip_map[test.path]
631 if skip_this_tree:
632 logging.info('Skip from node %r', test.path)
633 skip_map[test.path] = True
634 if test.is_leaf():
635 return
636 # Propagates skip value to its subtests
637 for subtest in test.subtests:
638 _update_skip_map_from_node(subtest, skip_this_tree)
639
640 _update_skip_map_from_node(self.test_list, False)
641
642 # Updates the skip value from skip_map to test_list tree. Also, updates test
643 # status if needed.
644 for t in self.test_list.walk():
645 skip = skip_map[t.path]
646 test_state = t.get_state()
647 if ((not skip) and
648 (test_state.status == TestState.PASSED) and
649 (test_state.error_msg == TestState.SKIPPED_MSG)):
650 # It was marked as skipped before, but now we need to run it.
651 # Mark as untested.
652 t.update_state(skip=skip, status=TestState.UNTESTED, error_msg='')
653 else:
654 t.update_state(skip=skip)
Jon Salz008f4ea2012-08-28 05:39:45 +0800655
Jon Salz0697cbf2012-07-04 15:14:04 +0800656 def show_next_active_test(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800657 """Rotates to the next visible active test."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800658 self.reap_completed_tests()
659 active_tests = [
660 t for t in self.test_list.walk()
661 if t.is_leaf() and t.get_state().status == TestState.ACTIVE]
662 if not active_tests:
663 return
Jon Salz4f6c7172012-06-11 20:45:36 +0800664
Jon Salz0697cbf2012-07-04 15:14:04 +0800665 try:
666 next_test = active_tests[
667 (active_tests.index(self.visible_test) + 1) % len(active_tests)]
668 except ValueError: # visible_test not present in active_tests
669 next_test = active_tests[0]
Jon Salz4f6c7172012-06-11 20:45:36 +0800670
Jon Salz0697cbf2012-07-04 15:14:04 +0800671 self.set_visible_test(next_test)
Jon Salz4f6c7172012-06-11 20:45:36 +0800672
Jon Salz0697cbf2012-07-04 15:14:04 +0800673 def handle_event(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800674 """Handles an event from the event server."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800675 handler = self.event_handlers.get(event.type)
676 if handler:
677 handler(event)
678 else:
679 # We don't register handlers for all event types - just ignore
680 # this event.
681 logging.debug('Unbound event type %s', event.type)
Jon Salz4f6c7172012-06-11 20:45:36 +0800682
Vic Yangaabf9fd2013-04-09 18:56:13 +0800683 def check_critical_factory_note(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800684 """Returns True if the last factory note is critical."""
Vic Yangaabf9fd2013-04-09 18:56:13 +0800685 notes = self.state_instance.get_shared_data('factory_note', True)
686 return notes and notes[-1]['level'] == 'CRITICAL'
687
Jon Salz0697cbf2012-07-04 15:14:04 +0800688 def run_next_test(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800689 """Runs the next eligible test (or tests) in self.tests_to_run."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800690 self.reap_completed_tests()
Vic Yangaabf9fd2013-04-09 18:56:13 +0800691 if self.tests_to_run and self.check_critical_factory_note():
692 self.tests_to_run.clear()
693 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800694 while self.tests_to_run:
Ricky Liang6fe218c2013-12-27 15:17:17 +0800695 logging.debug('Tests to run: %s', [x.path for x in self.tests_to_run])
Jon Salz94eb56f2012-06-12 18:01:12 +0800696
Jon Salz0697cbf2012-07-04 15:14:04 +0800697 test = self.tests_to_run[0]
Jon Salz94eb56f2012-06-12 18:01:12 +0800698
Jon Salz0697cbf2012-07-04 15:14:04 +0800699 if test in self.invocations:
700 logging.info('Next test %s is already running', test.path)
701 self.tests_to_run.popleft()
702 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800703
Jon Salza1412922012-07-23 16:04:17 +0800704 for requirement in test.require_run:
705 for i in requirement.test.walk():
706 if i.get_state().status == TestState.ACTIVE:
Jon Salz304a75d2012-07-06 11:14:15 +0800707 logging.info('Waiting for active test %s to complete '
Jon Salza1412922012-07-23 16:04:17 +0800708 'before running %s', i.path, test.path)
Jon Salz304a75d2012-07-06 11:14:15 +0800709 return
710
Jon Salz0697cbf2012-07-04 15:14:04 +0800711 if self.invocations and not (test.backgroundable and all(
712 [x.backgroundable for x in self.invocations])):
713 logging.debug('Waiting for non-backgroundable tests to '
Ricky Liang6fe218c2013-12-27 15:17:17 +0800714 'complete before running %s', test.path)
Jon Salz0697cbf2012-07-04 15:14:04 +0800715 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800716
Jon Salz3e6f5202012-10-15 15:08:29 +0800717 if test.get_state().skip:
718 factory.console.info('Skipping test %s', test.path)
719 test.update_state(status=TestState.PASSED,
720 error_msg=TestState.SKIPPED_MSG)
721 self.tests_to_run.popleft()
722 continue
723
Jon Salz0697cbf2012-07-04 15:14:04 +0800724 self.tests_to_run.popleft()
Jon Salz94eb56f2012-06-12 18:01:12 +0800725
Jon Salz304a75d2012-07-06 11:14:15 +0800726 untested = set()
Jon Salza1412922012-07-23 16:04:17 +0800727 for requirement in test.require_run:
728 for i in requirement.test.walk():
729 if i == test:
Jon Salz304a75d2012-07-06 11:14:15 +0800730 # We've hit this test itself; stop checking
731 break
Jon Salza1412922012-07-23 16:04:17 +0800732 if ((i.get_state().status == TestState.UNTESTED) or
733 (requirement.passed and i.get_state().status !=
734 TestState.PASSED)):
Jon Salz304a75d2012-07-06 11:14:15 +0800735 # Found an untested test; move on to the next
736 # element in require_run.
Jon Salza1412922012-07-23 16:04:17 +0800737 untested.add(i)
Jon Salz304a75d2012-07-06 11:14:15 +0800738 break
739
740 if untested:
741 untested_paths = ', '.join(sorted([x.path for x in untested]))
742 if self.state_instance.get_shared_data('engineering_mode',
743 optional=True):
744 # In engineering mode, we'll let it go.
745 factory.console.warn('In engineering mode; running '
746 '%s even though required tests '
747 '[%s] have not completed',
748 test.path, untested_paths)
749 else:
750 # Not in engineering mode; mark it failed.
751 error_msg = ('Required tests [%s] have not been run yet'
752 % untested_paths)
753 factory.console.error('Not running %s: %s',
754 test.path, error_msg)
755 test.update_state(status=TestState.FAILED,
756 error_msg=error_msg)
757 continue
758
Ricky Liang48e47f92014-02-26 19:31:51 +0800759 if (isinstance(test, factory.ShutdownStep) and
760 self.state_instance.get_shared_data('post_shutdown', optional=True)):
761 # Invoking post shutdown method of shutdown test. We should retain the
762 # iterations_left and retries_left of the original test state.
763 test_state = self.state_instance.get_test_state(test.path)
764 self._run_test(test, test_state.iterations_left,
765 test_state.retries_left)
766 else:
767 # Starts a new test run; reset iterations and retries.
768 self._run_test(test, test.iterations, test.retries)
Jon Salz1acc8742012-07-17 17:45:55 +0800769
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800770 def _run_test(self, test, iterations_left=None, retries_left=None):
Jon Salz1acc8742012-07-17 17:45:55 +0800771 invoc = TestInvocation(self, test, on_completion=self.run_next_test)
772 new_state = test.update_state(
Ricky Liang48e47f92014-02-26 19:31:51 +0800773 status=TestState.ACTIVE, increment_count=1, error_msg='',
774 invocation=invoc.uuid, iterations_left=iterations_left,
775 retries_left=retries_left,
776 visible=(self.visible_test == test))
Jon Salz1acc8742012-07-17 17:45:55 +0800777 invoc.count = new_state.count
778
779 self.invocations[test] = invoc
780 if self.visible_test is None and test.has_ui:
781 self.set_visible_test(test)
Vic Yang311ddb82012-09-26 12:08:28 +0800782 self.check_exclusive()
Jon Salz1acc8742012-07-17 17:45:55 +0800783 invoc.start()
Jon Salz5f2a0672012-05-22 17:14:06 +0800784
Vic Yang311ddb82012-09-26 12:08:28 +0800785 def check_exclusive(self):
Jon Salzce6a7f82013-06-10 18:22:54 +0800786 # alias since this is really long
787 EXCL_OPT = factory.FactoryTest.EXCLUSIVE_OPTIONS
788
Vic Yang311ddb82012-09-26 12:08:28 +0800789 current_exclusive_items = set([
Jon Salzce6a7f82013-06-10 18:22:54 +0800790 item for item in EXCL_OPT
Vic Yang311ddb82012-09-26 12:08:28 +0800791 if any([test.is_exclusive(item) for test in self.invocations])])
792
793 new_exclusive_items = current_exclusive_items - self.exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800794 if EXCL_OPT.NETWORKING in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800795 logging.info('Disabling network')
796 self.connection_manager.DisableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800797 if EXCL_OPT.CHARGER in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800798 logging.info('Stop controlling charger')
799
800 new_non_exclusive_items = self.exclusive_items - current_exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800801 if EXCL_OPT.NETWORKING in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800802 logging.info('Re-enabling network')
803 self.connection_manager.EnableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800804 if EXCL_OPT.CHARGER in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800805 logging.info('Start controlling charger')
806
Jon Salzce6a7f82013-06-10 18:22:54 +0800807 if self.cpufreq_manager:
808 enabled = EXCL_OPT.CPUFREQ not in current_exclusive_items
809 try:
810 self.cpufreq_manager.SetEnabled(enabled)
811 except: # pylint: disable=W0702
812 logging.exception('Unable to %s cpufreq services',
813 'enable' if enabled else 'disable')
814
Vic Yang311ddb82012-09-26 12:08:28 +0800815 # Only adjust charge state if not excluded
Jon Salzce6a7f82013-06-10 18:22:54 +0800816 if (EXCL_OPT.CHARGER not in current_exclusive_items and
817 not utils.in_chroot()):
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +0800818 if self.charge_manager:
819 self.charge_manager.AdjustChargeState()
820 else:
821 try:
822 system.GetBoard().SetChargeState(Board.ChargeState.CHARGE)
823 except BoardException:
824 logging.exception('Unable to set charge state on this board')
Vic Yang311ddb82012-09-26 12:08:28 +0800825
826 self.exclusive_items = current_exclusive_items
Jon Salz5da61e62012-05-31 13:06:22 +0800827
cychiang21886742012-07-05 15:16:32 +0800828 def check_for_updates(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800829 """Schedules an asynchronous check for updates if necessary."""
cychiang21886742012-07-05 15:16:32 +0800830 if not self.test_list.options.update_period_secs:
831 # Not enabled.
832 return
833
834 now = time.time()
835 if self.last_update_check and (
836 now - self.last_update_check <
837 self.test_list.options.update_period_secs):
838 # Not yet time for another check.
839 return
840
841 self.last_update_check = now
842
843 def handle_check_for_update(reached_shopfloor, md5sum, needs_update):
844 if reached_shopfloor:
845 new_update_md5sum = md5sum if needs_update else None
846 if system.SystemInfo.update_md5sum != new_update_md5sum:
847 logging.info('Received new update MD5SUM: %s', new_update_md5sum)
848 system.SystemInfo.update_md5sum = new_update_md5sum
849 self.run_queue.put(self.update_system_info)
850
851 updater.CheckForUpdateAsync(
852 handle_check_for_update,
853 self.test_list.options.shopfloor_timeout_secs)
854
Jon Salza6711d72012-07-18 14:33:03 +0800855 def cancel_pending_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800856 """Cancels any tests in the run queue."""
Jon Salza6711d72012-07-18 14:33:03 +0800857 self.run_tests([])
858
Ricky Liang4bff3e32014-02-20 18:46:11 +0800859 def restore_active_run_state(self):
860 """Restores active run id and the list of scheduled tests."""
861 self.run_id = self.state_instance.get_shared_data('run_id', optional=True)
862 self.scheduled_run_tests = self.state_instance.get_shared_data(
863 'scheduled_run_tests', optional=True)
864
865 def set_active_run_state(self):
866 """Sets active run id and the list of scheduled tests."""
867 self.run_id = str(uuid.uuid4())
868 self.scheduled_run_tests = [test.path for test in self.tests_to_run]
869 self.state_instance.set_shared_data('run_id', self.run_id)
870 self.state_instance.set_shared_data('scheduled_run_tests',
871 self.scheduled_run_tests)
872
Jon Salz0697cbf2012-07-04 15:14:04 +0800873 def run_tests(self, subtrees, untested_only=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800874 """Runs tests under subtree.
Jon Salz258a40c2012-04-19 12:34:01 +0800875
Jon Salz0697cbf2012-07-04 15:14:04 +0800876 The tests are run in order unless one fails (then stops).
877 Backgroundable tests are run simultaneously; when a foreground test is
878 encountered, we wait for all active tests to finish before continuing.
Jon Salzb1b39092012-05-03 02:05:09 +0800879
Ricky Liang6fe218c2013-12-27 15:17:17 +0800880 Args:
881 subtrees: Node or nodes containing tests to run (may either be
882 a single test or a list). Duplicates will be ignored.
883 untested_only: True to run untested tests only.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800884 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800885 if type(subtrees) != list:
886 subtrees = [subtrees]
Jon Salz258a40c2012-04-19 12:34:01 +0800887
Jon Salz0697cbf2012-07-04 15:14:04 +0800888 # Nodes we've seen so far, to avoid duplicates.
889 seen = set()
Jon Salz94eb56f2012-06-12 18:01:12 +0800890
Jon Salz0697cbf2012-07-04 15:14:04 +0800891 self.tests_to_run = deque()
892 for subtree in subtrees:
893 for test in subtree.walk():
894 if test in seen:
895 continue
896 seen.add(test)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800897
Jon Salz0697cbf2012-07-04 15:14:04 +0800898 if not test.is_leaf():
899 continue
Ricky Liang4bff3e32014-02-20 18:46:11 +0800900 if (untested_only and test.get_state().status != TestState.UNTESTED):
Jon Salz0697cbf2012-07-04 15:14:04 +0800901 continue
902 self.tests_to_run.append(test)
Ricky Liang4bff3e32014-02-20 18:46:11 +0800903 if subtrees:
904 self.set_active_run_state()
Jon Salz0697cbf2012-07-04 15:14:04 +0800905 self.run_next_test()
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800906
Jon Salz0697cbf2012-07-04 15:14:04 +0800907 def reap_completed_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800908 """Removes completed tests from the set of active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +0800909
910 Also updates the visible test if it was reaped.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800911 """
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800912 test_completed = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800913 for t, v in dict(self.invocations).iteritems():
914 if v.is_completed():
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800915 test_completed = True
Jon Salz1acc8742012-07-17 17:45:55 +0800916 new_state = t.update_state(**v.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +0800917 del self.invocations[t]
918
Chun-Ta Lin54e17e42012-09-06 22:05:13 +0800919 # Stop on failure if flag is true.
920 if (self.test_list.options.stop_on_failure and
921 new_state.status == TestState.FAILED):
922 # Clean all the tests to cause goofy to stop.
923 self.tests_to_run = []
924 factory.console.info("Stop on failure triggered. Empty the queue.")
925
Jon Salz1acc8742012-07-17 17:45:55 +0800926 if new_state.iterations_left and new_state.status == TestState.PASSED:
927 # Play it again, Sam!
928 self._run_test(t)
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800929 # new_state.retries_left is obtained after update.
930 # For retries_left == 0, test can still be run for the last time.
931 elif (new_state.retries_left >= 0 and
932 new_state.status == TestState.FAILED):
933 # Still have to retry, Sam!
934 self._run_test(t)
Jon Salz1acc8742012-07-17 17:45:55 +0800935
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800936 if test_completed:
Vic Yangf01c59f2013-04-19 17:37:56 +0800937 self.log_watcher.KickWatchThread()
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800938
Jon Salz0697cbf2012-07-04 15:14:04 +0800939 if (self.visible_test is None or
Jon Salz85a39882012-07-05 16:45:04 +0800940 self.visible_test not in self.invocations):
Jon Salz0697cbf2012-07-04 15:14:04 +0800941 self.set_visible_test(None)
942 # Make the first running test, if any, the visible test
943 for t in self.test_list.walk():
944 if t in self.invocations:
945 self.set_visible_test(t)
946 break
947
Jon Salz6dc031d2013-06-19 13:06:23 +0800948 def kill_active_tests(self, abort, root=None, reason=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800949 """Kills and waits for all active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +0800950
Jon Salz85a39882012-07-05 16:45:04 +0800951 Args:
952 abort: True to change state of killed tests to FAILED, False for
Jon Salz0697cbf2012-07-04 15:14:04 +0800953 UNTESTED.
Jon Salz85a39882012-07-05 16:45:04 +0800954 root: If set, only kills tests with root as an ancestor.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800955 reason: If set, the abort reason.
956 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800957 self.reap_completed_tests()
958 for test, invoc in self.invocations.items():
Jon Salz85a39882012-07-05 16:45:04 +0800959 if root and not test.has_ancestor(root):
960 continue
961
Jon Salz0697cbf2012-07-04 15:14:04 +0800962 factory.console.info('Killing active test %s...' % test.path)
Jon Salz6dc031d2013-06-19 13:06:23 +0800963 invoc.abort_and_join(reason)
Jon Salz0697cbf2012-07-04 15:14:04 +0800964 factory.console.info('Killed %s' % test.path)
Jon Salz1acc8742012-07-17 17:45:55 +0800965 test.update_state(**invoc.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +0800966 del self.invocations[test]
Jon Salz1acc8742012-07-17 17:45:55 +0800967
Jon Salz0697cbf2012-07-04 15:14:04 +0800968 if not abort:
969 test.update_state(status=TestState.UNTESTED)
970 self.reap_completed_tests()
971
Jon Salz6dc031d2013-06-19 13:06:23 +0800972 def stop(self, root=None, fail=False, reason=None):
973 self.kill_active_tests(fail, root, reason)
Jon Salz85a39882012-07-05 16:45:04 +0800974 # Remove any tests in the run queue under the root.
975 self.tests_to_run = deque([x for x in self.tests_to_run
976 if root and not x.has_ancestor(root)])
977 self.run_next_test()
Jon Salz0697cbf2012-07-04 15:14:04 +0800978
Jon Salz4712ac72013-02-07 17:12:05 +0800979 def clear_state(self, root=None):
Jon Salzd7550792013-07-12 05:49:27 +0800980 if root is None:
981 root = self.test_list
Jon Salz6dc031d2013-06-19 13:06:23 +0800982 self.stop(root, reason='Clearing test state')
Jon Salz4712ac72013-02-07 17:12:05 +0800983 for f in root.walk():
984 if f.is_leaf():
985 f.update_state(status=TestState.UNTESTED)
986
Jon Salz6dc031d2013-06-19 13:06:23 +0800987 def abort_active_tests(self, reason=None):
988 self.kill_active_tests(True, reason=reason)
Jon Salz0697cbf2012-07-04 15:14:04 +0800989
990 def main(self):
Jon Salzeff94182013-06-19 15:06:28 +0800991 syslog.openlog('goofy')
992
Jon Salz0697cbf2012-07-04 15:14:04 +0800993 try:
Jon Salzd7550792013-07-12 05:49:27 +0800994 self.status = Status.INITIALIZING
Jon Salz0697cbf2012-07-04 15:14:04 +0800995 self.init()
996 self.event_log.Log('goofy_init',
997 success=True)
998 except:
999 if self.event_log:
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001000 try:
Jon Salz0697cbf2012-07-04 15:14:04 +08001001 self.event_log.Log('goofy_init',
1002 success=False,
1003 trace=traceback.format_exc())
1004 except: # pylint: disable=W0702
1005 pass
1006 raise
1007
Jon Salzd7550792013-07-12 05:49:27 +08001008 self.status = Status.RUNNING
Jon Salzeff94182013-06-19 15:06:28 +08001009 syslog.syslog('Goofy (factory test harness) starting')
Jon Salz0697cbf2012-07-04 15:14:04 +08001010 self.run()
1011
1012 def update_system_info(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001013 """Updates system info."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001014 system_info = system.SystemInfo()
1015 self.state_instance.set_shared_data('system_info', system_info.__dict__)
1016 self.event_client.post_event(Event(Event.Type.SYSTEM_INFO,
1017 system_info=system_info.__dict__))
1018 logging.info('System info: %r', system_info.__dict__)
1019
Jon Salzeb42f0d2012-07-27 19:14:04 +08001020 def update_factory(self, auto_run_on_restart=False, post_update_hook=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001021 """Commences updating factory software.
Jon Salzeb42f0d2012-07-27 19:14:04 +08001022
1023 Args:
1024 auto_run_on_restart: Auto-run when the machine comes back up.
1025 post_update_hook: Code to call after update but immediately before
1026 restart.
1027
1028 Returns:
1029 Never if the update was successful (we just reboot).
1030 False if the update was unnecessary (no update available).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001031 """
Jon Salz6dc031d2013-06-19 13:06:23 +08001032 self.kill_active_tests(False, reason='Factory software update')
Jon Salza6711d72012-07-18 14:33:03 +08001033 self.cancel_pending_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001034
Jon Salz5c344f62012-07-13 14:31:16 +08001035 def pre_update_hook():
1036 if auto_run_on_restart:
1037 self.state_instance.set_shared_data('tests_after_shutdown',
1038 FORCE_AUTO_RUN)
1039 self.state_instance.close()
1040
Jon Salzeb42f0d2012-07-27 19:14:04 +08001041 if updater.TryUpdate(pre_update_hook=pre_update_hook):
1042 if post_update_hook:
1043 post_update_hook()
1044 self.env.shutdown('reboot')
Jon Salz0697cbf2012-07-04 15:14:04 +08001045
Jon Salzcef132a2012-08-30 04:58:08 +08001046 def handle_sigint(self, dummy_signum, dummy_frame):
Jon Salz77c151e2012-08-28 07:20:37 +08001047 logging.error('Received SIGINT')
1048 self.run_queue.put(None)
1049 raise KeyboardInterrupt()
1050
Jon Salze12c2b32013-06-25 16:24:34 +08001051 def find_kcrashes(self):
1052 """Finds kcrash files, logs them, and marks them as seen."""
1053 seen_crashes = set(
1054 self.state_instance.get_shared_data('seen_crashes', optional=True)
1055 or [])
1056
1057 for path in glob.glob('/var/spool/crash/*'):
1058 if not os.path.isfile(path):
1059 continue
1060 if path in seen_crashes:
1061 continue
1062 try:
1063 stat = os.stat(path)
1064 mtime = utils.TimeString(stat.st_mtime)
1065 logging.info(
1066 'Found new crash file %s (%d bytes at %s)',
1067 path, stat.st_size, mtime)
1068 extra_log_args = {}
1069
1070 try:
1071 _, ext = os.path.splitext(path)
1072 if ext in ['.kcrash', '.meta']:
1073 ext = ext.replace('.', '')
1074 with open(path) as f:
1075 data = f.read(MAX_CRASH_FILE_SIZE)
1076 tell = f.tell()
1077 logging.info(
1078 'Contents of %s%s:%s',
1079 path,
1080 ('' if tell == stat.st_size
1081 else '(truncated to %d bytes)' % MAX_CRASH_FILE_SIZE),
1082 ('\n' + data).replace('\n', '\n ' + ext + '> '))
1083 extra_log_args['data'] = data
1084
1085 # Copy to /var/factory/kcrash for posterity
1086 kcrash_dir = factory.get_factory_root('kcrash')
1087 utils.TryMakeDirs(kcrash_dir)
1088 shutil.copy(path, kcrash_dir)
1089 logging.info('Copied to %s',
1090 os.path.join(kcrash_dir, os.path.basename(path)))
1091 finally:
1092 # Even if something goes wrong with the above, still try to
1093 # log to event log
1094 self.event_log.Log('crash_file',
1095 path=path, size=stat.st_size, mtime=mtime,
1096 **extra_log_args)
1097 except: # pylint: disable=W0702
1098 logging.exception('Unable to handle crash files %s', path)
1099 seen_crashes.add(path)
1100
1101 self.state_instance.set_shared_data('seen_crashes', list(seen_crashes))
1102
Jon Salz128b0932013-07-03 16:55:26 +08001103 def GetTestList(self, test_list_id):
1104 """Returns the test list with the given ID.
1105
1106 Raises:
1107 TestListError: The test list ID is not valid.
1108 """
1109 try:
1110 return self.test_lists[test_list_id]
1111 except KeyError:
1112 raise test_lists.TestListError(
1113 '%r is not a valid test list ID (available IDs are [%s])' % (
1114 test_list_id, ', '.join(sorted(self.test_lists.keys()))))
1115
1116 def InitTestLists(self):
1117 """Reads in all test lists and sets the active test list."""
Ricky Liang27051552014-05-04 14:22:26 +08001118 self.test_lists = test_lists.BuildAllTestLists(
1119 force_generic=(self.options.automation_mode is not None))
Jon Salzd7550792013-07-12 05:49:27 +08001120 logging.info('Loaded test lists: [%s]',
1121 test_lists.DescribeTestLists(self.test_lists))
Jon Salz128b0932013-07-03 16:55:26 +08001122
1123 if not self.options.test_list:
1124 self.options.test_list = test_lists.GetActiveTestListId()
1125
1126 if os.sep in self.options.test_list:
1127 # It's a path pointing to an old-style test list; use it.
1128 self.test_list = factory.read_test_list(self.options.test_list)
1129 else:
1130 self.test_list = self.GetTestList(self.options.test_list)
1131
1132 logging.info('Active test list: %s', self.test_list.test_list_id)
1133
1134 if isinstance(self.test_list, test_lists.OldStyleTestList):
1135 # Actually load it in. (See OldStyleTestList for an explanation
1136 # of why this is necessary.)
1137 self.test_list = self.test_list.Load()
1138
1139 self.test_list.state_instance = self.state_instance
1140
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001141 def init_hooks(self):
1142 """Initializes hooks.
1143
1144 Must run after self.test_list ready.
1145 """
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001146 module, cls = self.test_list.options.hooks_class.rsplit('.', 1)
1147 self.hooks = getattr(__import__(module, fromlist=[cls]), cls)()
1148 assert isinstance(self.hooks, factory.Hooks), (
1149 "hooks should be of type Hooks but is %r" % type(self.hooks))
1150 self.hooks.test_list = self.test_list
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001151 self.hooks.OnCreatedTestList()
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001152
Jon Salz0697cbf2012-07-04 15:14:04 +08001153 def init(self, args=None, env=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001154 """Initializes Goofy.
Jon Salz0697cbf2012-07-04 15:14:04 +08001155
1156 Args:
1157 args: A list of command-line arguments. Uses sys.argv if
1158 args is None.
1159 env: An Environment instance to use (or None to choose
1160 FakeChrootEnvironment or DUTEnvironment as appropriate).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001161 """
Jon Salz77c151e2012-08-28 07:20:37 +08001162 signal.signal(signal.SIGINT, self.handle_sigint)
1163
Jon Salz0697cbf2012-07-04 15:14:04 +08001164 parser = OptionParser()
1165 parser.add_option('-v', '--verbose', dest='verbose',
Jon Salz8fa8e832012-07-13 19:04:09 +08001166 action='store_true',
1167 help='Enable debug logging')
Jon Salz0697cbf2012-07-04 15:14:04 +08001168 parser.add_option('--print_test_list', dest='print_test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001169 metavar='FILE',
1170 help='Read and print test list FILE, and exit')
Jon Salz0697cbf2012-07-04 15:14:04 +08001171 parser.add_option('--restart', dest='restart',
Jon Salz8fa8e832012-07-13 19:04:09 +08001172 action='store_true',
1173 help='Clear all test state')
Jon Salz0697cbf2012-07-04 15:14:04 +08001174 parser.add_option('--ui', dest='ui', type='choice',
Jon Salz8fa8e832012-07-13 19:04:09 +08001175 choices=['none', 'gtk', 'chrome'],
Jon Salz2f881df2013-02-01 17:00:35 +08001176 default='chrome',
Jon Salz8fa8e832012-07-13 19:04:09 +08001177 help='UI to use')
Jon Salz0697cbf2012-07-04 15:14:04 +08001178 parser.add_option('--ui_scale_factor', dest='ui_scale_factor',
Jon Salz8fa8e832012-07-13 19:04:09 +08001179 type='int', default=1,
1180 help=('Factor by which to scale UI '
1181 '(Chrome UI only)'))
Jon Salz0697cbf2012-07-04 15:14:04 +08001182 parser.add_option('--test_list', dest='test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001183 metavar='FILE',
1184 help='Use FILE as test list')
Jon Salzc79a9982012-08-30 04:42:01 +08001185 parser.add_option('--dummy_shopfloor', action='store_true',
1186 help='Use a dummy shopfloor server')
Ricky Liang6fe218c2013-12-27 15:17:17 +08001187 parser.add_option('--automation-mode',
1188 choices=[m.lower() for m in AutomationMode],
1189 default='none', help="Factory test automation mode.")
Ricky Liang117484a2014-04-14 11:14:41 +08001190 parser.add_option('--no-auto-run-on-start', dest='auto_run_on_start',
1191 action='store_false', default=True,
1192 help=('do not automatically run the test list on goofy '
1193 'start; this is only valid when factory test '
1194 'automation is enabled'))
Ricky Liang8c2c6c32013-11-02 23:02:44 +08001195 parser.add_option('--guest_login', dest='guest_login', default=False,
Ricky Liangb2432362013-10-02 13:12:41 +08001196 action='store_true',
Ricky Liang8c2c6c32013-11-02 23:02:44 +08001197 help='Log in as guest. This will not own the TPM.')
Jon Salz0697cbf2012-07-04 15:14:04 +08001198 (self.options, self.args) = parser.parse_args(args)
1199
Jon Salz46b89562012-07-05 11:49:22 +08001200 # Make sure factory directories exist.
1201 factory.get_log_root()
1202 factory.get_state_root()
1203 factory.get_test_data_root()
1204
Jon Salz0697cbf2012-07-04 15:14:04 +08001205 global _inited_logging # pylint: disable=W0603
1206 if not _inited_logging:
1207 factory.init_logging('goofy', verbose=self.options.verbose)
1208 _inited_logging = True
Jon Salz8fa8e832012-07-13 19:04:09 +08001209
Jon Salz0f996602012-10-03 15:26:48 +08001210 if self.options.print_test_list:
1211 print factory.read_test_list(
1212 self.options.print_test_list).__repr__(recursive=True)
1213 sys.exit(0)
1214
Jon Salzee85d522012-07-17 14:34:46 +08001215 event_log.IncrementBootSequence()
Jon Salzd15bbcf2013-05-21 17:33:57 +08001216 # Don't defer logging the initial event, so we can make sure
1217 # that device_id, reimage_id, etc. are all set up.
1218 self.event_log = EventLog('goofy', defer=False)
Jon Salz0697cbf2012-07-04 15:14:04 +08001219
1220 if (not suppress_chroot_warning and
1221 factory.in_chroot() and
1222 self.options.ui == 'gtk' and
1223 os.environ.get('DISPLAY') in [None, '', ':0', ':0.0']):
1224 # That's not going to work! Tell the user how to run
1225 # this way.
1226 logging.warn(GOOFY_IN_CHROOT_WARNING)
1227 time.sleep(1)
1228
1229 if env:
1230 self.env = env
1231 elif factory.in_chroot():
1232 self.env = test_environment.FakeChrootEnvironment()
1233 logging.warn(
1234 'Using chroot environment: will not actually run autotests')
1235 else:
Ricky Liang8c2c6c32013-11-02 23:02:44 +08001236 if self.options.guest_login:
1237 os.mknod(test_environment.DUTEnvironment.GUEST_MODE_TAG_FILE)
1238 self.env = test_environment.DUTEnvironment()
Jon Salz0697cbf2012-07-04 15:14:04 +08001239 self.env.goofy = self
1240
1241 if self.options.restart:
1242 state.clear_state()
1243
Jon Salz0697cbf2012-07-04 15:14:04 +08001244 if self.options.ui_scale_factor != 1 and utils.in_qemu():
1245 logging.warn(
1246 'In QEMU; ignoring ui_scale_factor argument')
1247 self.options.ui_scale_factor = 1
1248
1249 logging.info('Started')
1250
1251 self.start_state_server()
1252 self.state_instance.set_shared_data('hwid_cfg', get_hwid_cfg())
1253 self.state_instance.set_shared_data('ui_scale_factor',
Ricky Liang09216dc2013-02-22 17:26:45 +08001254 self.options.ui_scale_factor)
Jon Salz0697cbf2012-07-04 15:14:04 +08001255 self.last_shutdown_time = (
1256 self.state_instance.get_shared_data('shutdown_time', optional=True))
1257 self.state_instance.del_shared_data('shutdown_time', optional=True)
Jon Salzb19ea072013-02-07 16:35:00 +08001258 self.state_instance.del_shared_data('startup_error', optional=True)
Jon Salz0697cbf2012-07-04 15:14:04 +08001259
Ricky Liang6fe218c2013-12-27 15:17:17 +08001260 self.options.automation_mode = ParseAutomationMode(
1261 self.options.automation_mode)
1262 self.state_instance.set_shared_data('automation_mode',
1263 self.options.automation_mode)
1264 self.state_instance.set_shared_data(
1265 'automation_mode_prompt',
1266 AutomationModePrompt[self.options.automation_mode])
1267
Jon Salz128b0932013-07-03 16:55:26 +08001268 try:
1269 self.InitTestLists()
1270 except: # pylint: disable=W0702
1271 logging.exception('Unable to initialize test lists')
1272 self.state_instance.set_shared_data(
1273 'startup_error',
1274 'Unable to initialize test lists\n%s' % (
1275 traceback.format_exc()))
Jon Salzb19ea072013-02-07 16:35:00 +08001276 if self.options.ui == 'chrome':
1277 # Create an empty test list with default options so that the rest of
1278 # startup can proceed.
1279 self.test_list = factory.FactoryTestList(
1280 [], self.state_instance, factory.Options())
1281 else:
1282 # Bail with an error; no point in starting up.
1283 sys.exit('No valid test list; exiting.')
1284
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001285 self.init_hooks()
1286
Jon Salz822838b2013-03-25 17:32:33 +08001287 if self.test_list.options.clear_state_on_start:
1288 self.state_instance.clear_test_state()
1289
Jon Salz670ce062014-05-16 15:53:50 +08001290 # If the phase is invalid, this will raise a ValueError.
1291 phase.SetPersistentPhase(self.test_list.options.phase)
1292
Vic Yang3e1cf5d2013-06-05 18:50:24 +08001293 if system.SystemInfo().firmware_version is None and not utils.in_chroot():
Vic Yang9bd4f772013-06-04 17:34:00 +08001294 self.state_instance.set_shared_data('startup_error',
1295 'Netboot firmware detected\n'
1296 'Connect Ethernet and reboot to re-image.\n'
1297 u'侦测到网路开机固件\n'
1298 u'请连接乙太网并重启')
1299
Jon Salz0697cbf2012-07-04 15:14:04 +08001300 if not self.state_instance.has_shared_data('ui_lang'):
1301 self.state_instance.set_shared_data('ui_lang',
1302 self.test_list.options.ui_lang)
1303 self.state_instance.set_shared_data(
1304 'test_list_options',
1305 self.test_list.options.__dict__)
1306 self.state_instance.test_list = self.test_list
1307
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001308 self.check_log_rotation()
Jon Salz83ef34b2012-11-01 19:46:35 +08001309
Jon Salz23926422012-09-01 03:38:13 +08001310 if self.options.dummy_shopfloor:
1311 os.environ[shopfloor.SHOPFLOOR_SERVER_ENV_VAR_NAME] = (
1312 'http://localhost:%d/' % shopfloor.DEFAULT_SERVER_PORT)
1313 self.dummy_shopfloor = Spawn(
1314 [os.path.join(factory.FACTORY_PATH, 'bin', 'shopfloor_server'),
1315 '--dummy'])
1316 elif self.test_list.options.shopfloor_server_url:
1317 shopfloor.set_server_url(self.test_list.options.shopfloor_server_url)
Jon Salz2bf2f6b2013-03-28 18:49:26 +08001318 shopfloor.set_enabled(True)
Jon Salz23926422012-09-01 03:38:13 +08001319
Jon Salz0f996602012-10-03 15:26:48 +08001320 if self.test_list.options.time_sanitizer and not utils.in_chroot():
Jon Salz8fa8e832012-07-13 19:04:09 +08001321 self.time_sanitizer = time_sanitizer.TimeSanitizer(
1322 base_time=time_sanitizer.GetBaseTimeFromFile(
1323 # lsb-factory is written by the factory install shim during
1324 # installation, so it should have a good time obtained from
Jon Salz54882d02012-08-31 01:57:54 +08001325 # the mini-Omaha server. If it's not available, we'll use
1326 # /etc/lsb-factory (which will be much older, but reasonably
1327 # sane) and rely on a shopfloor sync to set a more accurate
1328 # time.
1329 '/usr/local/etc/lsb-factory',
1330 '/etc/lsb-release'))
Jon Salz8fa8e832012-07-13 19:04:09 +08001331 self.time_sanitizer.RunOnce()
1332
Vic Yangd8990da2013-06-27 16:57:43 +08001333 if self.test_list.options.check_cpu_usage_period_secs:
1334 self.cpu_usage_watcher = Spawn(['py/tools/cpu_usage_monitor.py',
1335 '-p', str(self.test_list.options.check_cpu_usage_period_secs)],
1336 cwd=factory.FACTORY_PATH)
1337
Jon Salz0697cbf2012-07-04 15:14:04 +08001338 self.init_states()
1339 self.start_event_server()
1340 self.connection_manager = self.env.create_connection_manager(
Tai-Hsu Lin371351a2012-08-27 14:17:14 +08001341 self.test_list.options.wlans,
1342 self.test_list.options.scan_wifi_period_secs)
Jon Salz0697cbf2012-07-04 15:14:04 +08001343 # Note that we create a log watcher even if
1344 # sync_event_log_period_secs isn't set (no background
1345 # syncing), since we may use it to flush event logs as well.
1346 self.log_watcher = EventLogWatcher(
1347 self.test_list.options.sync_event_log_period_secs,
Jon Salzd15bbcf2013-05-21 17:33:57 +08001348 event_log_db_file=None,
Jon Salz16d10542012-07-23 12:18:45 +08001349 handle_event_logs_callback=self.handle_event_logs)
Jon Salz0697cbf2012-07-04 15:14:04 +08001350 if self.test_list.options.sync_event_log_period_secs:
1351 self.log_watcher.StartWatchThread()
1352
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001353 # Creates a system log manager to scan logs periocially.
1354 # A scan includes clearing logs and optionally syncing logs if
1355 # enable_syng_log is True. We kick it to sync logs.
1356 self.system_log_manager = SystemLogManager(
1357 sync_log_paths=self.test_list.options.sync_log_paths,
1358 sync_log_period_secs=self.test_list.options.sync_log_period_secs,
1359 scan_log_period_secs=self.test_list.options.scan_log_period_secs,
Cheng-Yi Chiangb8a491c2014-01-20 14:37:57 +08001360 clear_log_paths=self.test_list.options.clear_log_paths,
1361 clear_log_excluded_paths=self.test_list.options.clear_log_excluded_paths)
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001362 self.system_log_manager.Start()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +08001363
Jon Salz0697cbf2012-07-04 15:14:04 +08001364 self.update_system_info()
1365
Vic Yang4953fc12012-07-26 16:19:53 +08001366 assert ((self.test_list.options.min_charge_pct is None) ==
1367 (self.test_list.options.max_charge_pct is None))
Vic Yange83d9a12013-04-19 20:00:20 +08001368 if utils.in_chroot():
1369 logging.info('In chroot, ignoring charge manager and charge state')
1370 elif self.test_list.options.min_charge_pct is not None:
Vic Yang4953fc12012-07-26 16:19:53 +08001371 self.charge_manager = ChargeManager(self.test_list.options.min_charge_pct,
1372 self.test_list.options.max_charge_pct)
Jon Salzad7353b2012-10-15 16:22:46 +08001373 system.SystemStatus.charge_manager = self.charge_manager
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +08001374 else:
1375 # Goofy should set charger state to charge if charge_manager is disabled.
1376 try:
1377 system.GetBoard().SetChargeState(Board.ChargeState.CHARGE)
1378 except BoardException:
1379 logging.exception('Unable to set charge state on this board')
Vic Yang4953fc12012-07-26 16:19:53 +08001380
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001381 self.core_dump_manager = CoreDumpManager(
1382 self.test_list.options.core_dump_watchlist)
1383
Jon Salz0697cbf2012-07-04 15:14:04 +08001384 os.environ['CROS_FACTORY'] = '1'
1385 os.environ['CROS_DISABLE_SITE_SYSINFO'] = '1'
1386
1387 # Set CROS_UI since some behaviors in ui.py depend on the
1388 # particular UI in use. TODO(jsalz): Remove this (and all
1389 # places it is used) when the GTK UI is removed.
1390 os.environ['CROS_UI'] = self.options.ui
1391
Shuo-Peng Liao1ff502e2013-06-30 18:37:02 +08001392 if not utils.in_chroot() and self.test_list.options.use_cpufreq_manager:
Jon Salzddf0d052013-06-18 12:52:44 +08001393 self.cpufreq_manager = CpufreqManager(event_log=self.event_log)
Jon Salzce6a7f82013-06-10 18:22:54 +08001394
Justin Chuang31b02432013-06-27 15:16:51 +08001395 # Startup hooks may want to skip some tests.
1396 self.update_skipped_tests()
Jon Salz416f9cc2013-05-10 18:32:50 +08001397
Jon Salze12c2b32013-06-25 16:24:34 +08001398 self.find_kcrashes()
1399
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001400 # Should not move earlier.
1401 self.hooks.OnStartup()
1402
Jon Salz0697cbf2012-07-04 15:14:04 +08001403 if self.options.ui == 'chrome':
1404 self.env.launch_chrome()
1405 logging.info('Waiting for a web socket connection')
Cheng-Yi Chiangfd8ed392013-03-08 21:37:31 +08001406 self.web_socket_manager.wait()
Jon Salz0697cbf2012-07-04 15:14:04 +08001407
1408 # Wait for the test widget size to be set; this is done in
1409 # an asynchronous RPC so there is a small chance that the
1410 # web socket might be opened first.
1411 for _ in range(100): # 10 s
1412 try:
1413 if self.state_instance.get_shared_data('test_widget_size'):
1414 break
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001415 except KeyError:
Jon Salz0697cbf2012-07-04 15:14:04 +08001416 pass # Retry
1417 time.sleep(0.1) # 100 ms
1418 else:
1419 logging.warn('Never received test_widget_size from UI')
Jon Salz45297282013-05-18 14:31:47 +08001420
1421 # Send Chrome a Tab to get focus to the factory UI
1422 # (http://crosbug.com/p/19444). TODO(jsalz): remove this hack
1423 # and figure out the right way to get the focus to Chrome.
1424 if not utils.in_chroot():
Ricky Liangb97f3652013-08-20 17:30:28 +08001425 utils.SendKey('Tab')
Jon Salz0697cbf2012-07-04 15:14:04 +08001426 elif self.options.ui == 'gtk':
1427 self.start_ui()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001428
Ricky Liang650f6bf2012-09-28 13:22:54 +08001429 # Create download path for autotest beforehand or autotests run at
1430 # the same time might fail due to race condition.
1431 if not factory.in_chroot():
1432 utils.TryMakeDirs(os.path.join('/usr/local/autotest', 'tests',
1433 'download'))
1434
Jon Salz0697cbf2012-07-04 15:14:04 +08001435 def state_change_callback(test, test_state):
1436 self.event_client.post_event(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001437 Event(Event.Type.STATE_CHANGE, path=test.path, state=test_state))
Jon Salz0697cbf2012-07-04 15:14:04 +08001438 self.test_list.state_change_callback = state_change_callback
Jon Salz73e0fd02012-04-04 11:46:38 +08001439
Jon Salza6711d72012-07-18 14:33:03 +08001440 for handler in self.on_ui_startup:
1441 handler()
1442
1443 self.prespawner = Prespawner()
1444 self.prespawner.start()
1445
Ricky Liang48e47f92014-02-26 19:31:51 +08001446 tests_after_shutdown = self.state_instance.get_shared_data(
1447 'tests_after_shutdown', optional=True)
Jon Salz57717ca2012-04-04 16:47:25 +08001448
Jon Salz5c344f62012-07-13 14:31:16 +08001449 force_auto_run = (tests_after_shutdown == FORCE_AUTO_RUN)
1450 if not force_auto_run and tests_after_shutdown is not None:
Ricky Liang48e47f92014-02-26 19:31:51 +08001451 logging.info('Resuming tests after shutdown: %s', tests_after_shutdown)
Jon Salz0697cbf2012-07-04 15:14:04 +08001452 self.tests_to_run.extend(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001453 self.test_list.lookup_path(t) for t in tests_after_shutdown)
Jon Salz0697cbf2012-07-04 15:14:04 +08001454 self.run_queue.put(self.run_next_test)
1455 else:
Jon Salz5c344f62012-07-13 14:31:16 +08001456 if force_auto_run or self.test_list.options.auto_run_on_start:
Ricky Liang117484a2014-04-14 11:14:41 +08001457 # If automation mode is enabled, allow suppress auto_run_on_start.
1458 if (self.options.automation_mode == 'NONE' or
1459 self.options.auto_run_on_start):
1460 self.run_queue.put(
1461 lambda: self.run_tests(self.test_list, untested_only=True))
Jon Salz5c344f62012-07-13 14:31:16 +08001462 self.state_instance.set_shared_data('tests_after_shutdown', None)
Ricky Liang4bff3e32014-02-20 18:46:11 +08001463 self.restore_active_run_state()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001464
Dean Liao592e4d52013-01-10 20:06:39 +08001465 self.may_disable_cros_shortcut_keys()
1466
1467 def may_disable_cros_shortcut_keys(self):
1468 test_options = self.test_list.options
1469 if test_options.disable_cros_shortcut_keys:
1470 logging.info('Filter ChromeOS shortcut keys.')
1471 self.key_filter = KeyFilter(
1472 unmap_caps_lock=test_options.disable_caps_lock,
1473 caps_lock_keycode=test_options.caps_lock_keycode)
1474 self.key_filter.Start()
1475
Jon Salz0697cbf2012-07-04 15:14:04 +08001476 def run(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001477 """Runs Goofy."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001478 # Process events forever.
1479 while self.run_once(True):
1480 pass
Jon Salz73e0fd02012-04-04 11:46:38 +08001481
Jon Salz0697cbf2012-07-04 15:14:04 +08001482 def run_once(self, block=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001483 """Runs all items pending in the event loop.
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001484
Jon Salz0697cbf2012-07-04 15:14:04 +08001485 Args:
1486 block: If true, block until at least one event is processed.
Jon Salz7c15e8b2012-06-19 17:10:37 +08001487
Jon Salz0697cbf2012-07-04 15:14:04 +08001488 Returns:
1489 True to keep going or False to shut down.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001490 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001491 events = utils.DrainQueue(self.run_queue)
cychiang21886742012-07-05 15:16:32 +08001492 while not events:
Jon Salz0697cbf2012-07-04 15:14:04 +08001493 # Nothing on the run queue.
1494 self._run_queue_idle()
1495 if block:
1496 # Block for at least one event...
cychiang21886742012-07-05 15:16:32 +08001497 try:
1498 events.append(self.run_queue.get(timeout=RUN_QUEUE_TIMEOUT_SECS))
1499 except Queue.Empty:
1500 # Keep going (calling _run_queue_idle() again at the top of
1501 # the loop)
1502 continue
Jon Salz0697cbf2012-07-04 15:14:04 +08001503 # ...and grab anything else that showed up at the same
1504 # time.
1505 events.extend(utils.DrainQueue(self.run_queue))
cychiang21886742012-07-05 15:16:32 +08001506 else:
1507 break
Jon Salz51528e12012-07-02 18:54:45 +08001508
Jon Salz0697cbf2012-07-04 15:14:04 +08001509 for event in events:
1510 if not event:
1511 # Shutdown request.
1512 self.run_queue.task_done()
1513 return False
Jon Salz51528e12012-07-02 18:54:45 +08001514
Jon Salz0697cbf2012-07-04 15:14:04 +08001515 try:
1516 event()
Jon Salz85a39882012-07-05 16:45:04 +08001517 except: # pylint: disable=W0702
1518 logging.exception('Error in event loop')
Jon Salz0697cbf2012-07-04 15:14:04 +08001519 self.record_exception(traceback.format_exception_only(
1520 *sys.exc_info()[:2]))
1521 # But keep going
1522 finally:
1523 self.run_queue.task_done()
1524 return True
Jon Salz0405ab52012-03-16 15:26:52 +08001525
Jon Salz0e6532d2012-10-25 16:30:11 +08001526 def _should_sync_time(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001527 """Returns True if we should attempt syncing time with shopfloor.
Jon Salz0e6532d2012-10-25 16:30:11 +08001528
1529 Args:
1530 foreground: If True, synchronizes even if background syncing
1531 is disabled (e.g., in explicit sync requests from the
1532 SyncShopfloor test).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001533 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001534 return ((foreground or
1535 self.test_list.options.sync_time_period_secs) and
Jon Salz54882d02012-08-31 01:57:54 +08001536 self.time_sanitizer and
1537 (not self.time_synced) and
1538 (not factory.in_chroot()))
1539
Jon Salz0e6532d2012-10-25 16:30:11 +08001540 def sync_time_with_shopfloor_server(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001541 """Syncs time with shopfloor server, if not yet synced.
Jon Salz54882d02012-08-31 01:57:54 +08001542
Jon Salz0e6532d2012-10-25 16:30:11 +08001543 Args:
1544 foreground: If True, synchronizes even if background syncing
1545 is disabled (e.g., in explicit sync requests from the
1546 SyncShopfloor test).
1547
Jon Salz54882d02012-08-31 01:57:54 +08001548 Returns:
1549 False if no time sanitizer is available, or True if this sync (or a
1550 previous sync) succeeded.
1551
1552 Raises:
1553 Exception if unable to contact the shopfloor server.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001554 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001555 if self._should_sync_time(foreground):
Jon Salz54882d02012-08-31 01:57:54 +08001556 self.time_sanitizer.SyncWithShopfloor()
1557 self.time_synced = True
1558 return self.time_synced
1559
Jon Salzb92c5112012-09-21 15:40:11 +08001560 def log_disk_space_stats(self):
Jon Salz18e0e022013-06-11 17:13:39 +08001561 if (utils.in_chroot() or
1562 not self.test_list.options.log_disk_space_period_secs):
Jon Salzb92c5112012-09-21 15:40:11 +08001563 return
1564
1565 now = time.time()
1566 if (self.last_log_disk_space_time and
1567 now - self.last_log_disk_space_time <
1568 self.test_list.options.log_disk_space_period_secs):
1569 return
1570 self.last_log_disk_space_time = now
1571
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001572 # Upload event if stateful partition usage is above threshold.
1573 # Stateful partition is mounted on /usr/local, while
1574 # encrypted stateful partition is mounted on /var.
1575 # If there are too much logs in the factory process,
1576 # these two partitions might get full.
Jon Salzb92c5112012-09-21 15:40:11 +08001577 try:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001578 vfs_infos = disk_space.GetAllVFSInfo()
1579 stateful_info, encrypted_info = None, None
1580 for vfs_info in vfs_infos.values():
1581 if '/usr/local' in vfs_info.mount_points:
1582 stateful_info = vfs_info
1583 if '/var' in vfs_info.mount_points:
1584 encrypted_info = vfs_info
1585
1586 stateful = disk_space.GetPartitionUsage(stateful_info)
1587 encrypted = disk_space.GetPartitionUsage(encrypted_info)
1588
1589 above_threshold = (
1590 self.test_list.options.stateful_usage_threshold and
1591 max(stateful.bytes_used_pct,
1592 stateful.inodes_used_pct,
1593 encrypted.bytes_used_pct,
1594 encrypted.inodes_used_pct) >
1595 self.test_list.options.stateful_usage_threshold)
1596
1597 if above_threshold:
1598 self.event_log.Log('stateful_partition_usage',
1599 partitions={
1600 'stateful': {
1601 'bytes_used_pct': FloatDigit(stateful.bytes_used_pct, 2),
1602 'inodes_used_pct': FloatDigit(stateful.inodes_used_pct, 2)},
1603 'encrypted_stateful': {
1604 'bytes_used_pct': FloatDigit(encrypted.bytes_used_pct, 2),
1605 'inodes_used_pct': FloatDigit(encrypted.inodes_used_pct, 2)}
1606 })
1607 self.log_watcher.ScanEventLogs()
Cheng-Yi Chiang00798e72013-06-20 18:16:39 +08001608 if (not utils.in_chroot() and
1609 self.test_list.options.stateful_usage_above_threshold_action):
1610 Spawn(self.test_list.options.stateful_usage_above_threshold_action,
1611 call=True)
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001612
1613 message = disk_space.FormatSpaceUsedAll(vfs_infos)
Jon Salz3c493bb2013-02-07 17:24:58 +08001614 if message != self.last_log_disk_space_message:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001615 if above_threshold:
1616 logging.warning(message)
1617 else:
1618 logging.info(message)
Jon Salz3c493bb2013-02-07 17:24:58 +08001619 self.last_log_disk_space_message = message
Jon Salzb92c5112012-09-21 15:40:11 +08001620 except: # pylint: disable=W0702
1621 logging.exception('Unable to get disk space used')
1622
Justin Chuang83813982013-05-13 01:26:32 +08001623 def check_battery(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001624 """Checks the current battery status.
Justin Chuang83813982013-05-13 01:26:32 +08001625
1626 Logs current battery charging level and status to log. If the battery level
1627 is lower below warning_low_battery_pct, send warning event to shopfloor.
1628 If the battery level is lower below critical_low_battery_pct, flush disks.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001629 """
Justin Chuang83813982013-05-13 01:26:32 +08001630 if not self.test_list.options.check_battery_period_secs:
1631 return
1632
1633 now = time.time()
1634 if (self.last_check_battery_time and
1635 now - self.last_check_battery_time <
1636 self.test_list.options.check_battery_period_secs):
1637 return
1638 self.last_check_battery_time = now
1639
1640 message = ''
1641 log_level = logging.INFO
1642 try:
1643 power = system.GetBoard().power
1644 if not power.CheckBatteryPresent():
1645 message = 'Battery is not present'
1646 else:
1647 ac_present = power.CheckACPresent()
1648 charge_pct = power.GetChargePct(get_float=True)
1649 message = ('Current battery level %.1f%%, AC charger is %s' %
1650 (charge_pct, 'connected' if ac_present else 'disconnected'))
1651
1652 if charge_pct > self.test_list.options.critical_low_battery_pct:
1653 critical_low_battery = False
1654 else:
1655 critical_low_battery = True
1656 # Only sync disks when battery level is still above minimum
1657 # value. This can be used for offline analysis when shopfloor cannot
1658 # be connected.
1659 if charge_pct > MIN_BATTERY_LEVEL_FOR_DISK_SYNC:
1660 logging.warning('disk syncing for critical low battery situation')
1661 os.system('sync; sync; sync')
1662 else:
1663 logging.warning('disk syncing is cancelled '
1664 'because battery level is lower than %.1f',
1665 MIN_BATTERY_LEVEL_FOR_DISK_SYNC)
1666
1667 # Notify shopfloor server
1668 if (critical_low_battery or
1669 (not ac_present and
1670 charge_pct <= self.test_list.options.warning_low_battery_pct)):
1671 log_level = logging.WARNING
1672
1673 self.event_log.Log('low_battery',
1674 battery_level=charge_pct,
1675 charger_connected=ac_present,
1676 critical=critical_low_battery)
1677 self.log_watcher.KickWatchThread()
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001678 if self.test_list.options.enable_sync_log:
1679 self.system_log_manager.KickToSync()
Justin Chuang83813982013-05-13 01:26:32 +08001680 except: # pylint: disable=W0702
1681 logging.exception('Unable to check battery or notify shopfloor')
1682 finally:
1683 if message != self.last_check_battery_message:
1684 logging.log(log_level, message)
1685 self.last_check_battery_message = message
1686
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001687 def check_core_dump(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001688 """Checks if there is any core dumped file.
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001689
1690 Removes unwanted core dump files immediately.
1691 Syncs those files matching watch list to server with a delay between
1692 each sync. After the files have been synced to server, deletes the files.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001693 """
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001694 core_dump_files = self.core_dump_manager.ScanFiles()
1695 if core_dump_files:
1696 now = time.time()
1697 if (self.last_kick_sync_time and now - self.last_kick_sync_time <
1698 self.test_list.options.kick_sync_min_interval_secs):
1699 return
1700 self.last_kick_sync_time = now
1701
1702 # Sends event to server
1703 self.event_log.Log('core_dumped', files=core_dump_files)
1704 self.log_watcher.KickWatchThread()
1705
1706 # Syncs files to server
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001707 if self.test_list.options.enable_sync_log:
1708 self.system_log_manager.KickToSync(
Cheng-Yi Chiangd3516a32013-07-17 15:30:47 +08001709 core_dump_files, self.core_dump_manager.ClearFiles)
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001710
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001711 def check_log_rotation(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001712 """Checks log rotation file presence/absence according to test_list option.
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001713
1714 Touch /var/lib/cleanup_logs_paused if test_list.options.disable_log_rotation
1715 is True, delete it otherwise. This must be done in idle loop because
1716 autotest client will touch /var/lib/cleanup_logs_paused each time it runs
1717 an autotest.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001718 """
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001719 if utils.in_chroot():
1720 return
1721 try:
1722 if self.test_list.options.disable_log_rotation:
1723 open(CLEANUP_LOGS_PAUSED, 'w').close()
1724 else:
1725 file_utils.TryUnlink(CLEANUP_LOGS_PAUSED)
1726 except: # pylint: disable=W0702
1727 # Oh well. Logs an error (but no trace)
1728 logging.info(
1729 'Unable to %s %s: %s',
1730 'touch' if self.test_list.options.disable_log_rotation else 'delete',
1731 CLEANUP_LOGS_PAUSED, utils.FormatExceptionOnly())
1732
Jon Salz8fa8e832012-07-13 19:04:09 +08001733 def sync_time_in_background(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001734 """Writes out current time and tries to sync with shopfloor server."""
Jon Salzb22d1172012-08-06 10:38:57 +08001735 if not self.time_sanitizer:
1736 return
1737
1738 # Write out the current time.
1739 self.time_sanitizer.SaveTime()
1740
Jon Salz54882d02012-08-31 01:57:54 +08001741 if not self._should_sync_time():
Jon Salz8fa8e832012-07-13 19:04:09 +08001742 return
1743
1744 now = time.time()
1745 if self.last_sync_time and (
1746 now - self.last_sync_time <
1747 self.test_list.options.sync_time_period_secs):
1748 # Not yet time for another check.
1749 return
1750 self.last_sync_time = now
1751
1752 def target():
1753 try:
Jon Salz54882d02012-08-31 01:57:54 +08001754 self.sync_time_with_shopfloor_server()
Jon Salz8fa8e832012-07-13 19:04:09 +08001755 except: # pylint: disable=W0702
1756 # Oh well. Log an error (but no trace)
1757 logging.info(
1758 'Unable to get time from shopfloor server: %s',
1759 utils.FormatExceptionOnly())
1760
1761 thread = threading.Thread(target=target)
1762 thread.daemon = True
1763 thread.start()
1764
Jon Salz0697cbf2012-07-04 15:14:04 +08001765 def _run_queue_idle(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001766 """Invoked when the run queue has no events.
Vic Yang4953fc12012-07-26 16:19:53 +08001767
1768 This method must not raise exception.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001769 """
Jon Salzb22d1172012-08-06 10:38:57 +08001770 now = time.time()
1771 if (self.last_idle and
1772 now < (self.last_idle + RUN_QUEUE_TIMEOUT_SECS - 1)):
1773 # Don't run more often than once every (RUN_QUEUE_TIMEOUT_SECS -
1774 # 1) seconds.
1775 return
1776
1777 self.last_idle = now
1778
Vic Yang311ddb82012-09-26 12:08:28 +08001779 self.check_exclusive()
cychiang21886742012-07-05 15:16:32 +08001780 self.check_for_updates()
Jon Salz8fa8e832012-07-13 19:04:09 +08001781 self.sync_time_in_background()
Jon Salzb92c5112012-09-21 15:40:11 +08001782 self.log_disk_space_stats()
Justin Chuang83813982013-05-13 01:26:32 +08001783 self.check_battery()
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001784 self.check_core_dump()
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001785 self.check_log_rotation()
Jon Salz57717ca2012-04-04 16:47:25 +08001786
Jon Salzd15bbcf2013-05-21 17:33:57 +08001787 def handle_event_logs(self, chunks):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001788 """Callback for event watcher.
Jon Salz258a40c2012-04-19 12:34:01 +08001789
Jon Salz0697cbf2012-07-04 15:14:04 +08001790 Attempts to upload the event logs to the shopfloor server.
Vic Yang93027612013-05-06 02:42:49 +08001791
1792 Args:
Jon Salzd15bbcf2013-05-21 17:33:57 +08001793 chunks: A list of Chunk objects.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001794 """
Vic Yang93027612013-05-06 02:42:49 +08001795 first_exception = None
1796 exception_count = 0
1797
Jon Salzd15bbcf2013-05-21 17:33:57 +08001798 for chunk in chunks:
Vic Yang93027612013-05-06 02:42:49 +08001799 try:
Jon Salzcddb6402013-05-23 12:56:42 +08001800 description = 'event logs (%s)' % str(chunk)
Vic Yang93027612013-05-06 02:42:49 +08001801 start_time = time.time()
1802 shopfloor_client = shopfloor.get_instance(
1803 detect=True,
1804 timeout=self.test_list.options.shopfloor_timeout_secs)
Jon Salzd15bbcf2013-05-21 17:33:57 +08001805 shopfloor_client.UploadEvent(chunk.log_name + "." +
1806 event_log.GetReimageId(),
1807 Binary(chunk.chunk))
Vic Yang93027612013-05-06 02:42:49 +08001808 logging.info(
1809 'Successfully synced %s in %.03f s',
1810 description, time.time() - start_time)
1811 except: # pylint: disable=W0702
Jon Salzd15bbcf2013-05-21 17:33:57 +08001812 first_exception = (first_exception or (chunk.log_name + ': ' +
Vic Yang93027612013-05-06 02:42:49 +08001813 utils.FormatExceptionOnly()))
1814 exception_count += 1
1815
1816 if exception_count:
1817 if exception_count == 1:
1818 msg = 'Log upload failed: %s' % first_exception
1819 else:
1820 msg = '%d log upload failed; first is: %s' % (
1821 exception_count, first_exception)
1822 raise Exception(msg)
1823
Jon Salz57717ca2012-04-04 16:47:25 +08001824
Jon Salz0697cbf2012-07-04 15:14:04 +08001825 def run_tests_with_status(self, statuses_to_run, starting_at=None,
1826 root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001827 """Runs all top-level tests with a particular status.
Jon Salz0405ab52012-03-16 15:26:52 +08001828
Jon Salz0697cbf2012-07-04 15:14:04 +08001829 All active tests, plus any tests to re-run, are reset.
Jon Salz57717ca2012-04-04 16:47:25 +08001830
Jon Salz0697cbf2012-07-04 15:14:04 +08001831 Args:
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001832 statuses_to_run: The particular status that caller wants to run.
Jon Salz0697cbf2012-07-04 15:14:04 +08001833 starting_at: If provided, only auto-runs tests beginning with
1834 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001835 root: The root of tests to run. If not provided, it will be
1836 the root of all tests.
1837 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001838 root = root or self.test_list
Jon Salz57717ca2012-04-04 16:47:25 +08001839
Jon Salz0697cbf2012-07-04 15:14:04 +08001840 if starting_at:
1841 # Make sure they passed a test, not a string.
1842 assert isinstance(starting_at, factory.FactoryTest)
Jon Salz0405ab52012-03-16 15:26:52 +08001843
Jon Salz0697cbf2012-07-04 15:14:04 +08001844 tests_to_reset = []
1845 tests_to_run = []
Jon Salz0405ab52012-03-16 15:26:52 +08001846
Jon Salz0697cbf2012-07-04 15:14:04 +08001847 found_starting_at = False
Jon Salz0405ab52012-03-16 15:26:52 +08001848
Jon Salz0697cbf2012-07-04 15:14:04 +08001849 for test in root.get_top_level_tests():
1850 if starting_at:
1851 if test == starting_at:
1852 # We've found starting_at; do auto-run on all
1853 # subsequent tests.
1854 found_starting_at = True
1855 if not found_starting_at:
1856 # Don't start this guy yet
1857 continue
Jon Salz0405ab52012-03-16 15:26:52 +08001858
Jon Salz0697cbf2012-07-04 15:14:04 +08001859 status = test.get_state().status
1860 if status == TestState.ACTIVE or status in statuses_to_run:
1861 # Reset the test (later; we will need to abort
1862 # all active tests first).
1863 tests_to_reset.append(test)
1864 if status in statuses_to_run:
1865 tests_to_run.append(test)
Jon Salz0405ab52012-03-16 15:26:52 +08001866
Jon Salz6dc031d2013-06-19 13:06:23 +08001867 self.abort_active_tests('Operator requested run/re-run of certain tests')
Jon Salz258a40c2012-04-19 12:34:01 +08001868
Jon Salz0697cbf2012-07-04 15:14:04 +08001869 # Reset all statuses of the tests to run (in case any tests were active;
1870 # we want them to be run again).
1871 for test_to_reset in tests_to_reset:
1872 for test in test_to_reset.walk():
1873 test.update_state(status=TestState.UNTESTED)
Jon Salz57717ca2012-04-04 16:47:25 +08001874
Jon Salz0697cbf2012-07-04 15:14:04 +08001875 self.run_tests(tests_to_run, untested_only=True)
Jon Salz0405ab52012-03-16 15:26:52 +08001876
Jon Salz0697cbf2012-07-04 15:14:04 +08001877 def restart_tests(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001878 """Restarts all tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001879 root = root or self.test_list
Jon Salz0405ab52012-03-16 15:26:52 +08001880
Jon Salz6dc031d2013-06-19 13:06:23 +08001881 self.abort_active_tests('Operator requested restart of certain tests')
Jon Salz0697cbf2012-07-04 15:14:04 +08001882 for test in root.walk():
Ricky Liang48e47f92014-02-26 19:31:51 +08001883 test.update_state(status=TestState.UNTESTED, shutdown_count=0)
Jon Salz0697cbf2012-07-04 15:14:04 +08001884 self.run_tests(root)
Hung-Te Lin96632362012-03-20 21:14:18 +08001885
Jon Salz0697cbf2012-07-04 15:14:04 +08001886 def auto_run(self, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001887 """"Auto-runs" tests that have not been run yet.
Hung-Te Lin96632362012-03-20 21:14:18 +08001888
Jon Salz0697cbf2012-07-04 15:14:04 +08001889 Args:
1890 starting_at: If provide, only auto-runs tests beginning with
1891 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001892 root: If provided, the root of tests to run. If not provided, the root
1893 will be test_list (root of all tests).
1894 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001895 root = root or self.test_list
1896 self.run_tests_with_status([TestState.UNTESTED, TestState.ACTIVE],
1897 starting_at=starting_at,
1898 root=root)
Jon Salz968e90b2012-03-18 16:12:43 +08001899
Jon Salz0697cbf2012-07-04 15:14:04 +08001900 def re_run_failed(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001901 """Re-runs failed tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001902 root = root or self.test_list
1903 self.run_tests_with_status([TestState.FAILED], root=root)
Jon Salz57717ca2012-04-04 16:47:25 +08001904
Jon Salz0697cbf2012-07-04 15:14:04 +08001905 def show_review_information(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001906 """Event handler for showing review information screen.
Jon Salz57717ca2012-04-04 16:47:25 +08001907
Jon Salz0697cbf2012-07-04 15:14:04 +08001908 The information screene is rendered by main UI program (ui.py), so in
1909 goofy we only need to kill all active tests, set them as untested, and
1910 clear remaining tests.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001911 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001912 self.kill_active_tests(False)
Jon Salza6711d72012-07-18 14:33:03 +08001913 self.cancel_pending_tests()
Jon Salz57717ca2012-04-04 16:47:25 +08001914
Jon Salz0697cbf2012-07-04 15:14:04 +08001915 def handle_switch_test(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001916 """Switches to a particular test.
Jon Salz0405ab52012-03-16 15:26:52 +08001917
Ricky Liang6fe218c2013-12-27 15:17:17 +08001918 Args:
1919 event: The SWITCH_TEST event.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001920 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001921 test = self.test_list.lookup_path(event.path)
1922 if not test:
1923 logging.error('Unknown test %r', event.key)
1924 return
Jon Salz73e0fd02012-04-04 11:46:38 +08001925
Jon Salz0697cbf2012-07-04 15:14:04 +08001926 invoc = self.invocations.get(test)
1927 if invoc and test.backgroundable:
1928 # Already running: just bring to the front if it
1929 # has a UI.
1930 logging.info('Setting visible test to %s', test.path)
Jon Salz36fbbb52012-07-05 13:45:06 +08001931 self.set_visible_test(test)
Jon Salz0697cbf2012-07-04 15:14:04 +08001932 return
Jon Salz73e0fd02012-04-04 11:46:38 +08001933
Jon Salz6dc031d2013-06-19 13:06:23 +08001934 self.abort_active_tests('Operator requested abort (switch_test)')
Jon Salz0697cbf2012-07-04 15:14:04 +08001935 for t in test.walk():
1936 t.update_state(status=TestState.UNTESTED)
Jon Salz73e0fd02012-04-04 11:46:38 +08001937
Jon Salz0697cbf2012-07-04 15:14:04 +08001938 if self.test_list.options.auto_run_on_keypress:
1939 self.auto_run(starting_at=test)
1940 else:
1941 self.run_tests(test)
Jon Salz73e0fd02012-04-04 11:46:38 +08001942
Jon Salz0697cbf2012-07-04 15:14:04 +08001943 def wait(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001944 """Waits for all pending invocations.
Jon Salz0697cbf2012-07-04 15:14:04 +08001945
1946 Useful for testing.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001947 """
Jon Salz1acc8742012-07-17 17:45:55 +08001948 while self.invocations:
1949 for k, v in self.invocations.iteritems():
1950 logging.info('Waiting for %s to complete...', k)
1951 v.thread.join()
1952 self.reap_completed_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001953
1954 def check_exceptions(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001955 """Raises an error if any exceptions have occurred in
1956 invocation threads.
1957 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001958 if self.exceptions:
1959 raise RuntimeError('Exception in invocation thread: %r' %
1960 self.exceptions)
1961
1962 def record_exception(self, msg):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001963 """Records an exception in an invocation thread.
Jon Salz0697cbf2012-07-04 15:14:04 +08001964
1965 An exception with the given message will be rethrown when
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001966 Goofy is destroyed.
1967 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001968 self.exceptions.append(msg)
Jon Salz73e0fd02012-04-04 11:46:38 +08001969
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001970
1971if __name__ == '__main__':
Jon Salz77c151e2012-08-28 07:20:37 +08001972 goofy = Goofy()
1973 try:
1974 goofy.main()
Jon Salz0f996602012-10-03 15:26:48 +08001975 except SystemExit:
1976 # Propagate SystemExit without logging.
1977 raise
Jon Salz31373eb2012-09-21 16:19:49 +08001978 except:
Jon Salz0f996602012-10-03 15:26:48 +08001979 # Log the error before trying to shut down (unless it's a graceful
1980 # exit).
Jon Salz31373eb2012-09-21 16:19:49 +08001981 logging.exception('Error in main loop')
1982 raise
Jon Salz77c151e2012-08-28 07:20:37 +08001983 finally:
1984 goofy.destroy()