blob: 4cfc0ff8f16bc2b84dff201d0a44a523b4752a58 [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
Joel Kitchingb85ed7f2014-10-08 18:24:39 +080010from __future__ import print_function
11
Jon Salze12c2b32013-06-25 16:24:34 +080012import glob
Jon Salz0405ab52012-03-16 15:26:52 +080013import logging
14import os
Jon Salze12c2b32013-06-25 16:24:34 +080015import shutil
Jon Salz77c151e2012-08-28 07:20:37 +080016import signal
Jon Salz0405ab52012-03-16 15:26:52 +080017import sys
Jon Salzeff94182013-06-19 15:06:28 +080018import syslog
Jon Salz0405ab52012-03-16 15:26:52 +080019import threading
20import time
21import traceback
Jon Salz258a40c2012-04-19 12:34:01 +080022import uuid
Jon Salzb10cf512012-08-09 17:29:21 +080023from xmlrpclib import Binary
Hung-Te Linf2f78f72012-02-08 19:27:11 +080024from collections import deque
25from optparse import OptionParser
Hung-Te Linf2f78f72012-02-08 19:27:11 +080026
Jon Salz0697cbf2012-07-04 15:14:04 +080027import factory_common # pylint: disable=W0611
jcliangcd688182012-08-20 21:01:26 +080028from cros.factory import event_log
29from cros.factory import system
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +080030from cros.factory.event_log import EventLog, FloatDigit
Tom Wai-Hong Tamd33723e2013-04-10 21:14:37 +080031from cros.factory.event_log_watcher import EventLogWatcher
Hung-Te Lincc41d2a2014-10-29 13:35:20 +080032from cros.factory.goofy import connection_manager
Vic Yangd80ea752014-09-24 16:07:14 +080033from cros.factory.goofy import test_environment
34from cros.factory.goofy import time_sanitizer
35from cros.factory.goofy import updater
36from cros.factory.goofy.goofy_base import GoofyBase
37from cros.factory.goofy.goofy_rpc import GoofyRPC
38from cros.factory.goofy.invocation import TestArgEnv
39from cros.factory.goofy.invocation import TestInvocation
40from cros.factory.goofy.link_manager import PresenterLinkManager
Vic Yange2c76a82014-10-30 12:48:19 -070041from cros.factory.goofy import prespawner
Vic Yangd80ea752014-09-24 16:07:14 +080042from cros.factory.goofy.system_log_manager import SystemLogManager
43from cros.factory.goofy.web_socket_manager import WebSocketManager
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +080044from cros.factory.system.board import Board, BoardException
jcliangcd688182012-08-20 21:01:26 +080045from cros.factory.system.charge_manager import ChargeManager
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +080046from cros.factory.system.core_dump_manager import CoreDumpManager
Jon Salzce6a7f82013-06-10 18:22:54 +080047from cros.factory.system.cpufreq_manager import CpufreqManager
Jon Salzb92c5112012-09-21 15:40:11 +080048from cros.factory.system import disk_space
jcliangcd688182012-08-20 21:01:26 +080049from cros.factory.test import factory
Jon Salz670ce062014-05-16 15:53:50 +080050from cros.factory.test import phase
jcliangcd688182012-08-20 21:01:26 +080051from cros.factory.test import state
Jon Salz51528e12012-07-02 18:54:45 +080052from cros.factory.test import shopfloor
Jon Salz83591782012-06-26 11:09:58 +080053from cros.factory.test import utils
Jon Salz128b0932013-07-03 16:55:26 +080054from cros.factory.test.test_lists import test_lists
Ricky Liang6fe218c2013-12-27 15:17:17 +080055from cros.factory.test.e2e_test.common import (
56 AutomationMode, AutomationModePrompt, ParseAutomationMode)
Jon Salz83591782012-06-26 11:09:58 +080057from cros.factory.test.event import Event
58from cros.factory.test.event import EventClient
59from cros.factory.test.event import EventServer
jcliangcd688182012-08-20 21:01:26 +080060from cros.factory.test.factory import TestState
Jon Salzd7550792013-07-12 05:49:27 +080061from cros.factory.test.utils import Enum
Dean Liao592e4d52013-01-10 20:06:39 +080062from cros.factory.tools.key_filter import KeyFilter
Jon Salz2af235d2013-06-24 14:47:21 +080063from cros.factory.utils import file_utils
Joel Kitchingb85ed7f2014-10-08 18:24:39 +080064from cros.factory.utils import net_utils
Jon Salz78c32392012-07-25 14:18:29 +080065from cros.factory.utils.process_utils import Spawn
Hung-Te Linf2f78f72012-02-08 19:27:11 +080066
67
Hung-Te Linf2f78f72012-02-08 19:27:11 +080068HWID_CFG_PATH = '/usr/local/share/chromeos-hwid/cfg'
Chun-ta Lin279e7e92013-02-19 17:40:39 +080069CACHES_DIR = os.path.join(factory.get_state_root(), "caches")
Hung-Te Linf2f78f72012-02-08 19:27:11 +080070
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +080071CLEANUP_LOGS_PAUSED = '/var/lib/cleanup_logs_paused'
72
Jon Salz5c344f62012-07-13 14:31:16 +080073# Value for tests_after_shutdown that forces auto-run (e.g., after
74# a factory update, when the available set of tests might change).
75FORCE_AUTO_RUN = 'force_auto_run'
76
Justin Chuang83813982013-05-13 01:26:32 +080077# Sync disks when battery level is higher than this value.
78# Otherwise, power loss during disk sync operation may incur even worse outcome.
79MIN_BATTERY_LEVEL_FOR_DISK_SYNC = 1.0
80
Jon Salze12c2b32013-06-25 16:24:34 +080081MAX_CRASH_FILE_SIZE = 64*1024
82
Jon Salzd7550792013-07-12 05:49:27 +080083Status = Enum(['UNINITIALIZED', 'INITIALIZING', 'RUNNING',
84 'TERMINATING', 'TERMINATED'])
85
Hung-Te Linf2f78f72012-02-08 19:27:11 +080086def get_hwid_cfg():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +080087 """Returns the HWID config tag, or an empty string if none can be found."""
Jon Salz0697cbf2012-07-04 15:14:04 +080088 if 'CROS_HWID' in os.environ:
89 return os.environ['CROS_HWID']
90 if os.path.exists(HWID_CFG_PATH):
91 with open(HWID_CFG_PATH, 'rt') as hwid_cfg_handle:
92 return hwid_cfg_handle.read().strip()
93 return ''
Hung-Te Linf2f78f72012-02-08 19:27:11 +080094
95
Jon Salz73e0fd02012-04-04 11:46:38 +080096_inited_logging = False
Hung-Te Linf2f78f72012-02-08 19:27:11 +080097
Peter Ammon1e1ec572014-06-26 17:56:32 -070098class Goofy(GoofyBase):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +080099 """The main factory flow.
Jon Salz0697cbf2012-07-04 15:14:04 +0800100
101 Note that all methods in this class must be invoked from the main
102 (event) thread. Other threads, such as callbacks and TestInvocation
103 methods, should instead post events on the run queue.
104
105 TODO: Unit tests. (chrome-os-partner:7409)
106
107 Properties:
108 uuid: A unique UUID for this invocation of Goofy.
109 state_instance: An instance of FactoryState.
110 state_server: The FactoryState XML/RPC server.
111 state_server_thread: A thread running state_server.
112 event_server: The EventServer socket server.
113 event_server_thread: A thread running event_server.
114 event_client: A client to the event server.
115 connection_manager: The connection_manager object.
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800116 system_log_manager: The SystemLogManager object.
117 core_dump_manager: The CoreDumpManager object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800118 ui_process: The factory ui process object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800119 invocations: A map from FactoryTest objects to the corresponding
120 TestInvocations objects representing active tests.
121 tests_to_run: A deque of tests that should be run when the current
122 test(s) complete.
123 options: Command-line options.
124 args: Command-line args.
125 test_list: The test list.
Jon Salz128b0932013-07-03 16:55:26 +0800126 test_lists: All new-style test lists.
Ricky Liang4bff3e32014-02-20 18:46:11 +0800127 run_id: The identifier for latest test run.
128 scheduled_run_tests: The list of tests scheduled for latest test run.
Jon Salz0697cbf2012-07-04 15:14:04 +0800129 event_handlers: Map of Event.Type to the method used to handle that
130 event. If the method has an 'event' argument, the event is passed
131 to the handler.
Jon Salz3c493bb2013-02-07 17:24:58 +0800132 last_log_disk_space_message: The last message we logged about disk space
133 (to avoid duplication).
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800134 last_kick_sync_time: The last time to kick system_log_manager to sync
135 because of core dump files (to avoid kicking too soon then abort the
136 sync.)
Jon Salz416f9cc2013-05-10 18:32:50 +0800137 hooks: A Hooks object containing hooks for various Goofy actions.
Jon Salzd7550792013-07-12 05:49:27 +0800138 status: The current Goofy status (a member of the Status enum).
Peter Ammon948b7172014-07-15 12:43:06 -0700139 link_manager: Instance of PresenterLinkManager for communicating
140 with GoofyPresenter
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800141 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800142 def __init__(self):
Peter Ammon1e1ec572014-06-26 17:56:32 -0700143 super(Goofy, self).__init__()
Jon Salz0697cbf2012-07-04 15:14:04 +0800144 self.uuid = str(uuid.uuid4())
145 self.state_instance = None
146 self.state_server = None
147 self.state_server_thread = None
Jon Salz16d10542012-07-23 12:18:45 +0800148 self.goofy_rpc = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800149 self.event_server = None
150 self.event_server_thread = None
151 self.event_client = None
152 self.connection_manager = None
Vic Yang4953fc12012-07-26 16:19:53 +0800153 self.charge_manager = None
Dean Liao88b93192014-10-23 19:37:41 +0800154 self._can_charge = True
Jon Salz8fa8e832012-07-13 19:04:09 +0800155 self.time_sanitizer = None
156 self.time_synced = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800157 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800158 self.system_log_manager = None
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800159 self.core_dump_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800160 self.event_log = None
Vic Yange2c76a82014-10-30 12:48:19 -0700161 self.autotest_prespawner = None
162 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800163 self.ui_process = None
Vic Yanga3cecf82014-12-26 00:44:21 -0800164 self._ui_initialized = False
Jon Salzc79a9982012-08-30 04:42:01 +0800165 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800166 self.invocations = {}
167 self.tests_to_run = deque()
168 self.visible_test = None
169 self.chrome = None
Jon Salz416f9cc2013-05-10 18:32:50 +0800170 self.hooks = None
Vic Yangd8990da2013-06-27 16:57:43 +0800171 self.cpu_usage_watcher = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800172
173 self.options = None
174 self.args = None
175 self.test_list = None
Jon Salz128b0932013-07-03 16:55:26 +0800176 self.test_lists = None
Ricky Liang4bff3e32014-02-20 18:46:11 +0800177 self.run_id = None
178 self.scheduled_run_tests = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800179 self.env = None
Jon Salzb22d1172012-08-06 10:38:57 +0800180 self.last_idle = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800181 self.last_shutdown_time = None
cychiang21886742012-07-05 15:16:32 +0800182 self.last_update_check = None
Jon Salz8fa8e832012-07-13 19:04:09 +0800183 self.last_sync_time = None
Jon Salzb92c5112012-09-21 15:40:11 +0800184 self.last_log_disk_space_time = None
Jon Salz3c493bb2013-02-07 17:24:58 +0800185 self.last_log_disk_space_message = None
Justin Chuang83813982013-05-13 01:26:32 +0800186 self.last_check_battery_time = None
187 self.last_check_battery_message = None
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800188 self.last_kick_sync_time = None
Vic Yang311ddb82012-09-26 12:08:28 +0800189 self.exclusive_items = set()
Jon Salz0f996602012-10-03 15:26:48 +0800190 self.event_log = None
Dean Liao592e4d52013-01-10 20:06:39 +0800191 self.key_filter = None
Jon Salzce6a7f82013-06-10 18:22:54 +0800192 self.cpufreq_manager = None
Jon Salzd7550792013-07-12 05:49:27 +0800193 self.status = Status.UNINITIALIZED
Ricky Liang36512a32014-07-25 11:47:04 +0800194 self.ready_for_ui_connection = False
Peter Ammon1e1ec572014-06-26 17:56:32 -0700195 self.link_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800196
Jon Salz85a39882012-07-05 16:45:04 +0800197 def test_or_root(event, parent_or_group=True):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800198 """Returns the test affected by a particular event.
Jon Salz85a39882012-07-05 16:45:04 +0800199
200 Args:
201 event: The event containing an optional 'path' attribute.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800202 parent_or_group: If True, returns the top-level parent for a test (the
Jon Salz85a39882012-07-05 16:45:04 +0800203 root node of the tests that need to be run together if the given test
204 path is to be run).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800205 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800206 try:
207 path = event.path
208 except AttributeError:
209 path = None
210
211 if path:
Jon Salz85a39882012-07-05 16:45:04 +0800212 test = self.test_list.lookup_path(path)
213 if parent_or_group:
214 test = test.get_top_level_parent_or_group()
215 return test
Jon Salz0697cbf2012-07-04 15:14:04 +0800216 else:
217 return self.test_list
218
219 self.event_handlers = {
220 Event.Type.SWITCH_TEST: self.handle_switch_test,
221 Event.Type.SHOW_NEXT_ACTIVE_TEST:
222 lambda event: self.show_next_active_test(),
223 Event.Type.RESTART_TESTS:
224 lambda event: self.restart_tests(root=test_or_root(event)),
225 Event.Type.AUTO_RUN:
226 lambda event: self.auto_run(root=test_or_root(event)),
227 Event.Type.RE_RUN_FAILED:
228 lambda event: self.re_run_failed(root=test_or_root(event)),
229 Event.Type.RUN_TESTS_WITH_STATUS:
230 lambda event: self.run_tests_with_status(
231 event.status,
232 root=test_or_root(event)),
233 Event.Type.REVIEW:
234 lambda event: self.show_review_information(),
235 Event.Type.UPDATE_SYSTEM_INFO:
236 lambda event: self.update_system_info(),
Jon Salz0697cbf2012-07-04 15:14:04 +0800237 Event.Type.STOP:
Jon Salz85a39882012-07-05 16:45:04 +0800238 lambda event: self.stop(root=test_or_root(event, False),
Jon Salz6dc031d2013-06-19 13:06:23 +0800239 fail=getattr(event, 'fail', False),
240 reason=getattr(event, 'reason', None)),
Jon Salz36fbbb52012-07-05 13:45:06 +0800241 Event.Type.SET_VISIBLE_TEST:
242 lambda event: self.set_visible_test(
243 self.test_list.lookup_path(event.path)),
Jon Salz4712ac72013-02-07 17:12:05 +0800244 Event.Type.CLEAR_STATE:
245 lambda event: self.clear_state(self.test_list.lookup_path(event.path)),
Jon Salz0697cbf2012-07-04 15:14:04 +0800246 }
247
Jon Salz0697cbf2012-07-04 15:14:04 +0800248 self.web_socket_manager = None
249
250 def destroy(self):
Ricky Liang74237a02014-09-18 15:11:23 +0800251 """Performs any shutdown tasks. Overrides base class method."""
Jon Salzd7550792013-07-12 05:49:27 +0800252 self.status = Status.TERMINATING
Jon Salz0697cbf2012-07-04 15:14:04 +0800253 if self.chrome:
254 self.chrome.kill()
255 self.chrome = None
Jon Salzc79a9982012-08-30 04:42:01 +0800256 if self.dummy_shopfloor:
257 self.dummy_shopfloor.kill()
258 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800259 if self.ui_process:
260 utils.kill_process_tree(self.ui_process, 'ui')
261 self.ui_process = None
262 if self.web_socket_manager:
263 logging.info('Stopping web sockets')
264 self.web_socket_manager.close()
265 self.web_socket_manager = None
266 if self.state_server_thread:
267 logging.info('Stopping state server')
268 self.state_server.shutdown()
269 self.state_server_thread.join()
270 self.state_server.server_close()
271 self.state_server_thread = None
272 if self.state_instance:
273 self.state_instance.close()
274 if self.event_server_thread:
275 logging.info('Stopping event server')
276 self.event_server.shutdown() # pylint: disable=E1101
277 self.event_server_thread.join()
278 self.event_server.server_close()
279 self.event_server_thread = None
280 if self.log_watcher:
281 if self.log_watcher.IsThreadStarted():
282 self.log_watcher.StopWatchThread()
283 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800284 if self.system_log_manager:
285 if self.system_log_manager.IsThreadRunning():
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +0800286 self.system_log_manager.Stop()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800287 self.system_log_manager = None
Vic Yange2c76a82014-10-30 12:48:19 -0700288 if self.autotest_prespawner:
289 logging.info('Stopping autotest prespawner')
290 self.autotest_prespawner.stop()
291 self.autotest_prespawner = None
292 if self.pytest_prespawner:
293 logging.info('Stopping pytest prespawner')
294 self.pytest_prespawner.stop()
295 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800296 if self.event_client:
297 logging.info('Closing event client')
298 self.event_client.close()
299 self.event_client = None
Jon Salzddf0d052013-06-18 12:52:44 +0800300 if self.cpufreq_manager:
301 self.cpufreq_manager.Stop()
Jon Salz0697cbf2012-07-04 15:14:04 +0800302 if self.event_log:
303 self.event_log.Close()
304 self.event_log = None
Dean Liao592e4d52013-01-10 20:06:39 +0800305 if self.key_filter:
306 self.key_filter.Stop()
Vic Yangd8990da2013-06-27 16:57:43 +0800307 if self.cpu_usage_watcher:
308 self.cpu_usage_watcher.terminate()
Peter Ammon1e1ec572014-06-26 17:56:32 -0700309 if self.link_manager:
310 self.link_manager.Stop()
311 self.link_manager = None
Dean Liao592e4d52013-01-10 20:06:39 +0800312
Peter Ammon1e1ec572014-06-26 17:56:32 -0700313 super(Goofy, self).destroy()
Jon Salz0697cbf2012-07-04 15:14:04 +0800314 logging.info('Done destroying Goofy')
Jon Salzd7550792013-07-12 05:49:27 +0800315 self.status = Status.TERMINATED
Jon Salz0697cbf2012-07-04 15:14:04 +0800316
317 def start_state_server(self):
Jon Salz2af235d2013-06-24 14:47:21 +0800318 # Before starting state server, remount stateful partitions with
319 # no commit flag. The default commit time (commit=600) makes corruption
320 # too likely.
Hung-Te Lind59dbfa2014-08-27 12:27:53 +0800321 utils.ResetCommitTime()
Jon Salz2af235d2013-06-24 14:47:21 +0800322
Jon Salz0697cbf2012-07-04 15:14:04 +0800323 self.state_instance, self.state_server = (
324 state.create_server(bind_address='0.0.0.0'))
Jon Salz16d10542012-07-23 12:18:45 +0800325 self.goofy_rpc = GoofyRPC(self)
326 self.goofy_rpc.RegisterMethods(self.state_instance)
Jon Salz0697cbf2012-07-04 15:14:04 +0800327 logging.info('Starting state server')
328 self.state_server_thread = threading.Thread(
329 target=self.state_server.serve_forever,
330 name='StateServer')
331 self.state_server_thread.start()
332
333 def start_event_server(self):
334 self.event_server = EventServer()
335 logging.info('Starting factory event server')
336 self.event_server_thread = threading.Thread(
337 target=self.event_server.serve_forever,
338 name='EventServer') # pylint: disable=E1101
339 self.event_server_thread.start()
340
341 self.event_client = EventClient(
342 callback=self.handle_event, event_loop=self.run_queue)
343
344 self.web_socket_manager = WebSocketManager(self.uuid)
345 self.state_server.add_handler("/event",
346 self.web_socket_manager.handle_web_socket)
347
348 def start_ui(self):
349 ui_proc_args = [
350 os.path.join(factory.FACTORY_PACKAGE_PATH, 'test', 'ui.py'),
351 self.options.test_list]
352 if self.options.verbose:
353 ui_proc_args.append('-v')
354 logging.info('Starting ui %s', ui_proc_args)
Jon Salz78c32392012-07-25 14:18:29 +0800355 self.ui_process = Spawn(ui_proc_args)
Jon Salz0697cbf2012-07-04 15:14:04 +0800356 logging.info('Waiting for UI to come up...')
357 self.event_client.wait(
358 lambda event: event.type == Event.Type.UI_READY)
359 logging.info('UI has started')
360
361 def set_visible_test(self, test):
362 if self.visible_test == test:
363 return
Jon Salz2f2d42c2012-07-30 12:30:34 +0800364 if test and not test.has_ui:
365 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800366
367 if test:
368 test.update_state(visible=True)
369 if self.visible_test:
370 self.visible_test.update_state(visible=False)
371 self.visible_test = test
372
Ricky Liang48e47f92014-02-26 19:31:51 +0800373 def log_startup_messages(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800374 """Logs the tail of var/log/messages and mosys and EC console logs."""
Jon Salzd4306c82012-11-30 15:16:36 +0800375 # TODO(jsalz): This is mostly a copy-and-paste of code in init_states,
376 # for factory-3004.B only. Consolidate and merge back to ToT.
377 if utils.in_chroot():
378 return
379
380 try:
381 var_log_messages = (
382 utils.var_log_messages_before_reboot())
383 logging.info(
384 'Tail of /var/log/messages before last reboot:\n'
385 '%s', ('\n'.join(
386 ' ' + x for x in var_log_messages)))
387 except: # pylint: disable=W0702
388 logging.exception('Unable to grok /var/log/messages')
389
390 try:
Ricky Liang117484a2014-04-14 11:14:41 +0800391 mosys_log = Spawn(
Jon Salzd4306c82012-11-30 15:16:36 +0800392 ['mosys', 'eventlog', 'list'],
393 read_stdout=True, log_stderr_on_error=True).stdout_data
394 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
395 except: # pylint: disable=W0702
396 logging.exception('Unable to read mosys eventlog')
397
Dean Liao88b93192014-10-23 19:37:41 +0800398 self.log_ec_console()
399 self.log_ec_panic_info()
400
401 @staticmethod
402 def log_ec_console():
403 """Logs EC console log into logging.info.
404
405 It logs an error message in logging.exception if an exception is raised
406 when getting EC console log.
407 For unsupported device, it logs unsupport message in logging.info
408
409 Returns:
410 EC console log string.
411 """
Jon Salzd4306c82012-11-30 15:16:36 +0800412 try:
Vic Yang8341dde2013-01-29 16:48:52 +0800413 board = system.GetBoard()
414 ec_console_log = board.GetECConsoleLog()
Jon Salzd4306c82012-11-30 15:16:36 +0800415 logging.info('EC console log after reboot:\n%s\n', ec_console_log)
Dean Liao88b93192014-10-23 19:37:41 +0800416 return ec_console_log
417 except NotImplementedError:
418 logging.info('EC console log not supported')
Jon Salzd4306c82012-11-30 15:16:36 +0800419 except: # pylint: disable=W0702
420 logging.exception('Error retrieving EC console log')
421
Dean Liao88b93192014-10-23 19:37:41 +0800422 @staticmethod
423 def log_ec_panic_info():
424 """Logs EC panic info into logging.info.
425
426 It logs an error message in logging.exception if an exception is raised
427 when getting EC panic info.
428 For unsupported device, it logs unsupport message in logging.info
429
430 Returns:
431 EC panic info string.
432 """
Vic Yang079f9872013-07-01 11:32:00 +0800433 try:
434 board = system.GetBoard()
435 ec_panic_info = board.GetECPanicInfo()
436 logging.info('EC panic info after reboot:\n%s\n', ec_panic_info)
Dean Liao88b93192014-10-23 19:37:41 +0800437 return ec_panic_info
438 except NotImplementedError:
439 logging.info('EC panic info is not supported')
Vic Yang079f9872013-07-01 11:32:00 +0800440 except: # pylint: disable=W0702
441 logging.exception('Error retrieving EC panic info')
442
Ricky Liang48e47f92014-02-26 19:31:51 +0800443 def shutdown(self, operation):
444 """Starts shutdown procedure.
445
446 Args:
Vic (Chun-Ju) Yang05b0d952014-04-28 17:39:09 +0800447 operation: The shutdown operation (reboot, full_reboot, or halt).
Ricky Liang48e47f92014-02-26 19:31:51 +0800448 """
449 active_tests = []
450 for test in self.test_list.walk():
451 if not test.is_leaf():
452 continue
453
454 test_state = test.get_state()
455 if test_state.status == TestState.ACTIVE:
456 active_tests.append(test)
457
458
459 if not (len(active_tests) == 1 and
460 isinstance(active_tests[0], factory.ShutdownStep)):
461 logging.error(
462 'Calling Goofy shutdown outside of the shutdown factory test')
463 return
464
465 logging.info('Start Goofy shutdown (%s)', operation)
466 # Save pending test list in the state server
467 self.state_instance.set_shared_data(
468 'tests_after_shutdown',
469 [t.path for t in self.tests_to_run])
470 # Save shutdown time
471 self.state_instance.set_shared_data('shutdown_time', time.time())
472
473 with self.env.lock:
474 self.event_log.Log('shutdown', operation=operation)
475 shutdown_result = self.env.shutdown(operation)
476 if shutdown_result:
477 # That's all, folks!
Peter Ammon1e1ec572014-06-26 17:56:32 -0700478 self.run_enqueue(None)
Ricky Liang48e47f92014-02-26 19:31:51 +0800479 else:
480 # Just pass (e.g., in the chroot).
481 self.state_instance.set_shared_data('tests_after_shutdown', None)
482 # Send event with no fields to indicate that there is no
483 # longer a pending shutdown.
484 self.event_client.post_event(Event(Event.Type.PENDING_SHUTDOWN))
485
486 def handle_shutdown_complete(self, test):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800487 """Handles the case where a shutdown was detected during a shutdown step.
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800488
Ricky Liang6fe218c2013-12-27 15:17:17 +0800489 Args:
490 test: The ShutdownStep.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800491 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800492 test_state = test.update_state(increment_shutdown_count=1)
493 logging.info('Detected shutdown (%d of %d)',
Ricky Liang48e47f92014-02-26 19:31:51 +0800494 test_state.shutdown_count, test.iterations)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800495
Ricky Liang48e47f92014-02-26 19:31:51 +0800496 # Insert current shutdown test at the front of the list of tests to run
497 # after shutdown. This is to continue on post-shutdown verification in the
498 # shutdown step.
499 tests_after_shutdown = self.state_instance.get_shared_data(
500 'tests_after_shutdown', optional=True)
501 if not tests_after_shutdown:
502 self.state_instance.set_shared_data('tests_after_shutdown', [test.path])
503 elif isinstance(tests_after_shutdown, list):
504 self.state_instance.set_shared_data(
505 'tests_after_shutdown', [test.path] + tests_after_shutdown)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800506
Ricky Liang48e47f92014-02-26 19:31:51 +0800507 # Set 'post_shutdown' to inform shutdown test that a shutdown just occurred.
Ricky Liangb7eb8772014-09-15 18:05:22 +0800508 self.state_instance.set_shared_data(
509 state.POST_SHUTDOWN_TAG % test.path,
510 self.state_instance.get_test_state(test.path).invocation)
Jon Salz258a40c2012-04-19 12:34:01 +0800511
Jon Salz0697cbf2012-07-04 15:14:04 +0800512 def init_states(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800513 """Initializes all states on startup."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800514 for test in self.test_list.get_all_tests():
515 # Make sure the state server knows about all the tests,
516 # defaulting to an untested state.
517 test.update_state(update_parent=False, visible=False)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800518
Jon Salz0697cbf2012-07-04 15:14:04 +0800519 var_log_messages = None
Vic Yanga9c32212012-08-16 20:07:54 +0800520 mosys_log = None
Vic Yange4c275d2012-08-28 01:50:20 +0800521 ec_console_log = None
Vic Yang079f9872013-07-01 11:32:00 +0800522 ec_panic_info = None
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800523
Jon Salz0697cbf2012-07-04 15:14:04 +0800524 # Any 'active' tests should be marked as failed now.
525 for test in self.test_list.walk():
Jon Salza6711d72012-07-18 14:33:03 +0800526 if not test.is_leaf():
527 # Don't bother with parents; they will be updated when their
528 # children are updated.
529 continue
530
Jon Salz0697cbf2012-07-04 15:14:04 +0800531 test_state = test.get_state()
532 if test_state.status != TestState.ACTIVE:
533 continue
534 if isinstance(test, factory.ShutdownStep):
535 # Shutdown while the test was active - that's good.
Ricky Liang48e47f92014-02-26 19:31:51 +0800536 self.handle_shutdown_complete(test)
Jon Salz0697cbf2012-07-04 15:14:04 +0800537 else:
538 # Unexpected shutdown. Grab /var/log/messages for context.
539 if var_log_messages is None:
540 try:
541 var_log_messages = (
542 utils.var_log_messages_before_reboot())
543 # Write it to the log, to make it easier to
544 # correlate with /var/log/messages.
545 logging.info(
546 'Unexpected shutdown. '
547 'Tail of /var/log/messages before last reboot:\n'
548 '%s', ('\n'.join(
549 ' ' + x for x in var_log_messages)))
550 except: # pylint: disable=W0702
551 logging.exception('Unable to grok /var/log/messages')
552 var_log_messages = []
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800553
Jon Salz008f4ea2012-08-28 05:39:45 +0800554 if mosys_log is None and not utils.in_chroot():
555 try:
Ricky Liang117484a2014-04-14 11:14:41 +0800556 mosys_log = Spawn(
Jon Salz008f4ea2012-08-28 05:39:45 +0800557 ['mosys', 'eventlog', 'list'],
558 read_stdout=True, log_stderr_on_error=True).stdout_data
559 # Write it to the log also.
560 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
561 except: # pylint: disable=W0702
562 logging.exception('Unable to read mosys eventlog')
Vic Yanga9c32212012-08-16 20:07:54 +0800563
Vic Yange4c275d2012-08-28 01:50:20 +0800564 if ec_console_log is None:
Dean Liao88b93192014-10-23 19:37:41 +0800565 ec_console_log = self.log_ec_console()
Vic Yange4c275d2012-08-28 01:50:20 +0800566
Vic Yang079f9872013-07-01 11:32:00 +0800567 if ec_panic_info is None:
Dean Liao88b93192014-10-23 19:37:41 +0800568 ec_panic_info = self.log_ec_panic_info()
Vic Yang079f9872013-07-01 11:32:00 +0800569
Jon Salz0697cbf2012-07-04 15:14:04 +0800570 error_msg = 'Unexpected shutdown while test was running'
571 self.event_log.Log('end_test',
572 path=test.path,
573 status=TestState.FAILED,
574 invocation=test.get_state().invocation,
575 error_msg=error_msg,
Vic Yanga9c32212012-08-16 20:07:54 +0800576 var_log_messages='\n'.join(var_log_messages),
577 mosys_log=mosys_log)
Jon Salz0697cbf2012-07-04 15:14:04 +0800578 test.update_state(
579 status=TestState.FAILED,
580 error_msg=error_msg)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800581
Jon Salz50efe942012-07-26 11:54:10 +0800582 if not test.never_fails:
583 # For "never_fails" tests (such as "Start"), don't cancel
584 # pending tests, since reboot is expected.
585 factory.console.info('Unexpected shutdown while test %s '
586 'running; cancelling any pending tests',
587 test.path)
588 self.state_instance.set_shared_data('tests_after_shutdown', [])
Jon Salz69806bb2012-07-20 18:05:02 +0800589
Jon Salz008f4ea2012-08-28 05:39:45 +0800590 self.update_skipped_tests()
591
592 def update_skipped_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800593 """Updates skipped states based on run_if."""
Jon Salz885dcac2013-07-23 16:39:50 +0800594 env = TestArgEnv()
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800595 def _evaluate_skip_from_run_if(test):
596 """Returns the run_if evaluation of the test.
597
598 Args:
599 test: A FactoryTest object.
600
601 Returns:
602 The run_if evaluation result. Returns False if the test has no
603 run_if argument.
604 """
605 value = None
606 if test.run_if_expr:
607 try:
608 value = test.run_if_expr(env)
609 except: # pylint: disable=W0702
610 logging.exception('Unable to evaluate run_if expression for %s',
611 test.path)
612 # But keep going; we have no choice. This will end up
613 # always activating the test.
614 elif test.run_if_table_name:
615 try:
616 aux = shopfloor.get_selected_aux_data(test.run_if_table_name)
617 value = aux.get(test.run_if_col)
618 except ValueError:
619 # Not available; assume it shouldn't be skipped
620 pass
621
622 if value is None:
623 skip = False
624 else:
625 skip = (not value) ^ t.run_if_not
626 return skip
627
628 # Gets all run_if evaluation, and stores results in skip_map.
629 skip_map = dict()
Jon Salz008f4ea2012-08-28 05:39:45 +0800630 for t in self.test_list.walk():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800631 skip_map[t.path] = _evaluate_skip_from_run_if(t)
Jon Salz885dcac2013-07-23 16:39:50 +0800632
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800633 # Propagates the skip value from root of tree and updates skip_map.
634 def _update_skip_map_from_node(test, skip_from_parent):
635 """Updates skip_map from a given node.
Jon Salz885dcac2013-07-23 16:39:50 +0800636
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800637 Given a FactoryTest node and the skip value from parent, updates the
638 skip value of current node in the skip_map if skip value from parent is
639 True. If this node has children, recursively propagate this value to all
640 its children, that is, all its subtests.
641 Note that this function only updates value in skip_map, not the actual
642 test_list tree.
Jon Salz008f4ea2012-08-28 05:39:45 +0800643
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800644 Args:
645 test: The given FactoryTest object. It is a node in the test_list tree.
646 skip_from_parent: The skip value which propagates from the parent of
647 input node.
648 """
649 skip_this_tree = skip_from_parent or skip_map[test.path]
650 if skip_this_tree:
651 logging.info('Skip from node %r', test.path)
652 skip_map[test.path] = True
653 if test.is_leaf():
654 return
655 # Propagates skip value to its subtests
656 for subtest in test.subtests:
657 _update_skip_map_from_node(subtest, skip_this_tree)
658
659 _update_skip_map_from_node(self.test_list, False)
660
661 # Updates the skip value from skip_map to test_list tree. Also, updates test
662 # status if needed.
663 for t in self.test_list.walk():
664 skip = skip_map[t.path]
665 test_state = t.get_state()
666 if ((not skip) and
667 (test_state.status == TestState.PASSED) and
668 (test_state.error_msg == TestState.SKIPPED_MSG)):
669 # It was marked as skipped before, but now we need to run it.
670 # Mark as untested.
671 t.update_state(skip=skip, status=TestState.UNTESTED, error_msg='')
672 else:
673 t.update_state(skip=skip)
Jon Salz008f4ea2012-08-28 05:39:45 +0800674
Jon Salz0697cbf2012-07-04 15:14:04 +0800675 def show_next_active_test(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800676 """Rotates to the next visible active test."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800677 self.reap_completed_tests()
678 active_tests = [
679 t for t in self.test_list.walk()
680 if t.is_leaf() and t.get_state().status == TestState.ACTIVE]
681 if not active_tests:
682 return
Jon Salz4f6c7172012-06-11 20:45:36 +0800683
Jon Salz0697cbf2012-07-04 15:14:04 +0800684 try:
685 next_test = active_tests[
686 (active_tests.index(self.visible_test) + 1) % len(active_tests)]
687 except ValueError: # visible_test not present in active_tests
688 next_test = active_tests[0]
Jon Salz4f6c7172012-06-11 20:45:36 +0800689
Jon Salz0697cbf2012-07-04 15:14:04 +0800690 self.set_visible_test(next_test)
Jon Salz4f6c7172012-06-11 20:45:36 +0800691
Jon Salz0697cbf2012-07-04 15:14:04 +0800692 def handle_event(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800693 """Handles an event from the event server."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800694 handler = self.event_handlers.get(event.type)
695 if handler:
696 handler(event)
697 else:
698 # We don't register handlers for all event types - just ignore
699 # this event.
700 logging.debug('Unbound event type %s', event.type)
Jon Salz4f6c7172012-06-11 20:45:36 +0800701
Vic Yangaabf9fd2013-04-09 18:56:13 +0800702 def check_critical_factory_note(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800703 """Returns True if the last factory note is critical."""
Vic Yangaabf9fd2013-04-09 18:56:13 +0800704 notes = self.state_instance.get_shared_data('factory_note', True)
705 return notes and notes[-1]['level'] == 'CRITICAL'
706
Jon Salz0697cbf2012-07-04 15:14:04 +0800707 def run_next_test(self):
henryhsu4cc6b022014-04-22 17:12:42 +0800708 """Runs the next eligible test (or tests) in self.tests_to_run.
709
710 We have three kinds of the next eligible test:
711 1. normal
712 2. backgroundable
713 3. force_background
714
715 And we have four situations of the ongoing invocations:
716 a. only a running normal test
717 b. all running tests are backgroundable
718 c. all running tests are force_background
719 d. all running tests are any combination of backgroundable and
720 force_background
721
722 When a test would like to be run, it must follow the rules:
723 [1] cannot run with [abd]
724 [2] cannot run with [a]
725 All the other combinations are allowed
726 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800727 self.reap_completed_tests()
Vic Yangaabf9fd2013-04-09 18:56:13 +0800728 if self.tests_to_run and self.check_critical_factory_note():
729 self.tests_to_run.clear()
730 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800731 while self.tests_to_run:
Ricky Liang6fe218c2013-12-27 15:17:17 +0800732 logging.debug('Tests to run: %s', [x.path for x in self.tests_to_run])
Jon Salz94eb56f2012-06-12 18:01:12 +0800733
Jon Salz0697cbf2012-07-04 15:14:04 +0800734 test = self.tests_to_run[0]
Jon Salz94eb56f2012-06-12 18:01:12 +0800735
Jon Salz0697cbf2012-07-04 15:14:04 +0800736 if test in self.invocations:
737 logging.info('Next test %s is already running', test.path)
738 self.tests_to_run.popleft()
739 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800740
Jon Salza1412922012-07-23 16:04:17 +0800741 for requirement in test.require_run:
742 for i in requirement.test.walk():
743 if i.get_state().status == TestState.ACTIVE:
Jon Salz304a75d2012-07-06 11:14:15 +0800744 logging.info('Waiting for active test %s to complete '
Jon Salza1412922012-07-23 16:04:17 +0800745 'before running %s', i.path, test.path)
Jon Salz304a75d2012-07-06 11:14:15 +0800746 return
747
henryhsu4cc6b022014-04-22 17:12:42 +0800748 def is_normal_test(test):
749 return not (test.backgroundable or test.force_background)
750
751 # [1] cannot run with [abd].
752 if self.invocations and is_normal_test(test) and any(
753 [not x.force_background for x in self.invocations]):
754 logging.info('Waiting for non-force_background tests to '
755 'complete before running %s', test.path)
756 return
757
758 # [2] cannot run with [a].
759 if self.invocations and test.backgroundable and any(
760 [is_normal_test(x) for x in self.invocations]):
761 logging.info('Waiting for normal tests to '
762 'complete before running %s', test.path)
Jon Salz0697cbf2012-07-04 15:14:04 +0800763 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800764
Jon Salz3e6f5202012-10-15 15:08:29 +0800765 if test.get_state().skip:
766 factory.console.info('Skipping test %s', test.path)
767 test.update_state(status=TestState.PASSED,
768 error_msg=TestState.SKIPPED_MSG)
769 self.tests_to_run.popleft()
770 continue
771
Jon Salz0697cbf2012-07-04 15:14:04 +0800772 self.tests_to_run.popleft()
Jon Salz94eb56f2012-06-12 18:01:12 +0800773
Jon Salz304a75d2012-07-06 11:14:15 +0800774 untested = set()
Jon Salza1412922012-07-23 16:04:17 +0800775 for requirement in test.require_run:
776 for i in requirement.test.walk():
777 if i == test:
Jon Salz304a75d2012-07-06 11:14:15 +0800778 # We've hit this test itself; stop checking
779 break
Jon Salza1412922012-07-23 16:04:17 +0800780 if ((i.get_state().status == TestState.UNTESTED) or
781 (requirement.passed and i.get_state().status !=
782 TestState.PASSED)):
Jon Salz304a75d2012-07-06 11:14:15 +0800783 # Found an untested test; move on to the next
784 # element in require_run.
Jon Salza1412922012-07-23 16:04:17 +0800785 untested.add(i)
Jon Salz304a75d2012-07-06 11:14:15 +0800786 break
787
788 if untested:
789 untested_paths = ', '.join(sorted([x.path for x in untested]))
790 if self.state_instance.get_shared_data('engineering_mode',
791 optional=True):
792 # In engineering mode, we'll let it go.
793 factory.console.warn('In engineering mode; running '
794 '%s even though required tests '
795 '[%s] have not completed',
796 test.path, untested_paths)
797 else:
798 # Not in engineering mode; mark it failed.
799 error_msg = ('Required tests [%s] have not been run yet'
800 % untested_paths)
801 factory.console.error('Not running %s: %s',
802 test.path, error_msg)
803 test.update_state(status=TestState.FAILED,
804 error_msg=error_msg)
805 continue
806
Ricky Liang48e47f92014-02-26 19:31:51 +0800807 if (isinstance(test, factory.ShutdownStep) and
Ricky Liangb7eb8772014-09-15 18:05:22 +0800808 self.state_instance.get_shared_data(
809 state.POST_SHUTDOWN_TAG % test.path, optional=True)):
Ricky Liang48e47f92014-02-26 19:31:51 +0800810 # Invoking post shutdown method of shutdown test. We should retain the
811 # iterations_left and retries_left of the original test state.
812 test_state = self.state_instance.get_test_state(test.path)
813 self._run_test(test, test_state.iterations_left,
814 test_state.retries_left)
815 else:
816 # Starts a new test run; reset iterations and retries.
817 self._run_test(test, test.iterations, test.retries)
Jon Salz1acc8742012-07-17 17:45:55 +0800818
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800819 def _run_test(self, test, iterations_left=None, retries_left=None):
Vic Yanga3cecf82014-12-26 00:44:21 -0800820 if not self._ui_initialized and not test.is_no_host():
821 self.init_ui()
Jon Salz1acc8742012-07-17 17:45:55 +0800822 invoc = TestInvocation(self, test, on_completion=self.run_next_test)
823 new_state = test.update_state(
Ricky Liang48e47f92014-02-26 19:31:51 +0800824 status=TestState.ACTIVE, increment_count=1, error_msg='',
825 invocation=invoc.uuid, iterations_left=iterations_left,
826 retries_left=retries_left,
827 visible=(self.visible_test == test))
Jon Salz1acc8742012-07-17 17:45:55 +0800828 invoc.count = new_state.count
829
830 self.invocations[test] = invoc
831 if self.visible_test is None and test.has_ui:
832 self.set_visible_test(test)
Vic Yang311ddb82012-09-26 12:08:28 +0800833 self.check_exclusive()
Jon Salz1acc8742012-07-17 17:45:55 +0800834 invoc.start()
Jon Salz5f2a0672012-05-22 17:14:06 +0800835
Vic Yang311ddb82012-09-26 12:08:28 +0800836 def check_exclusive(self):
Jon Salzce6a7f82013-06-10 18:22:54 +0800837 # alias since this is really long
838 EXCL_OPT = factory.FactoryTest.EXCLUSIVE_OPTIONS
839
Vic Yang311ddb82012-09-26 12:08:28 +0800840 current_exclusive_items = set([
Jon Salzce6a7f82013-06-10 18:22:54 +0800841 item for item in EXCL_OPT
Vic Yang311ddb82012-09-26 12:08:28 +0800842 if any([test.is_exclusive(item) for test in self.invocations])])
843
844 new_exclusive_items = current_exclusive_items - self.exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800845 if EXCL_OPT.NETWORKING in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800846 logging.info('Disabling network')
847 self.connection_manager.DisableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800848 if EXCL_OPT.CHARGER in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800849 logging.info('Stop controlling charger')
850
851 new_non_exclusive_items = self.exclusive_items - current_exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800852 if EXCL_OPT.NETWORKING in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800853 logging.info('Re-enabling network')
854 self.connection_manager.EnableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800855 if EXCL_OPT.CHARGER in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800856 logging.info('Start controlling charger')
857
Jon Salzce6a7f82013-06-10 18:22:54 +0800858 if self.cpufreq_manager:
859 enabled = EXCL_OPT.CPUFREQ not in current_exclusive_items
860 try:
861 self.cpufreq_manager.SetEnabled(enabled)
862 except: # pylint: disable=W0702
863 logging.exception('Unable to %s cpufreq services',
864 'enable' if enabled else 'disable')
865
Vic Yang311ddb82012-09-26 12:08:28 +0800866 # Only adjust charge state if not excluded
Jon Salzce6a7f82013-06-10 18:22:54 +0800867 if (EXCL_OPT.CHARGER not in current_exclusive_items and
868 not utils.in_chroot()):
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +0800869 if self.charge_manager:
870 self.charge_manager.AdjustChargeState()
871 else:
Dean Liao88b93192014-10-23 19:37:41 +0800872 self.charge()
Vic Yang311ddb82012-09-26 12:08:28 +0800873
874 self.exclusive_items = current_exclusive_items
Jon Salz5da61e62012-05-31 13:06:22 +0800875
Dean Liao88b93192014-10-23 19:37:41 +0800876 def charge(self):
877 """Charges the board.
878
879 It won't try again if last time SetChargeState raised an exception.
880 """
881 if not self._can_charge:
882 return
883
884 try:
885 system.GetBoard().SetChargeState(Board.ChargeState.CHARGE)
886 except NotImplementedError:
887 logging.info('Charging is not supported')
888 self._can_charge = False
889 except BoardException:
890 logging.exception('Unable to set charge state on this board')
891 self._can_charge = False
892
cychiang21886742012-07-05 15:16:32 +0800893 def check_for_updates(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800894 """Schedules an asynchronous check for updates if necessary."""
cychiang21886742012-07-05 15:16:32 +0800895 if not self.test_list.options.update_period_secs:
896 # Not enabled.
897 return
898
899 now = time.time()
900 if self.last_update_check and (
901 now - self.last_update_check <
902 self.test_list.options.update_period_secs):
903 # Not yet time for another check.
904 return
905
906 self.last_update_check = now
907
908 def handle_check_for_update(reached_shopfloor, md5sum, needs_update):
909 if reached_shopfloor:
910 new_update_md5sum = md5sum if needs_update else None
911 if system.SystemInfo.update_md5sum != new_update_md5sum:
912 logging.info('Received new update MD5SUM: %s', new_update_md5sum)
913 system.SystemInfo.update_md5sum = new_update_md5sum
Peter Ammon1e1ec572014-06-26 17:56:32 -0700914 self.run_enqueue(self.update_system_info)
cychiang21886742012-07-05 15:16:32 +0800915
916 updater.CheckForUpdateAsync(
917 handle_check_for_update,
918 self.test_list.options.shopfloor_timeout_secs)
919
Jon Salza6711d72012-07-18 14:33:03 +0800920 def cancel_pending_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800921 """Cancels any tests in the run queue."""
Jon Salza6711d72012-07-18 14:33:03 +0800922 self.run_tests([])
923
Ricky Liang4bff3e32014-02-20 18:46:11 +0800924 def restore_active_run_state(self):
925 """Restores active run id and the list of scheduled tests."""
926 self.run_id = self.state_instance.get_shared_data('run_id', optional=True)
927 self.scheduled_run_tests = self.state_instance.get_shared_data(
928 'scheduled_run_tests', optional=True)
929
930 def set_active_run_state(self):
931 """Sets active run id and the list of scheduled tests."""
932 self.run_id = str(uuid.uuid4())
933 self.scheduled_run_tests = [test.path for test in self.tests_to_run]
934 self.state_instance.set_shared_data('run_id', self.run_id)
935 self.state_instance.set_shared_data('scheduled_run_tests',
936 self.scheduled_run_tests)
937
Jon Salz0697cbf2012-07-04 15:14:04 +0800938 def run_tests(self, subtrees, untested_only=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800939 """Runs tests under subtree.
Jon Salz258a40c2012-04-19 12:34:01 +0800940
Jon Salz0697cbf2012-07-04 15:14:04 +0800941 The tests are run in order unless one fails (then stops).
942 Backgroundable tests are run simultaneously; when a foreground test is
943 encountered, we wait for all active tests to finish before continuing.
Jon Salzb1b39092012-05-03 02:05:09 +0800944
Ricky Liang6fe218c2013-12-27 15:17:17 +0800945 Args:
946 subtrees: Node or nodes containing tests to run (may either be
947 a single test or a list). Duplicates will be ignored.
948 untested_only: True to run untested tests only.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800949 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800950 if type(subtrees) != list:
951 subtrees = [subtrees]
Jon Salz258a40c2012-04-19 12:34:01 +0800952
Jon Salz0697cbf2012-07-04 15:14:04 +0800953 # Nodes we've seen so far, to avoid duplicates.
954 seen = set()
Jon Salz94eb56f2012-06-12 18:01:12 +0800955
Jon Salz0697cbf2012-07-04 15:14:04 +0800956 self.tests_to_run = deque()
957 for subtree in subtrees:
958 for test in subtree.walk():
959 if test in seen:
960 continue
961 seen.add(test)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800962
Jon Salz0697cbf2012-07-04 15:14:04 +0800963 if not test.is_leaf():
964 continue
Ricky Liang4bff3e32014-02-20 18:46:11 +0800965 if (untested_only and test.get_state().status != TestState.UNTESTED):
Jon Salz0697cbf2012-07-04 15:14:04 +0800966 continue
967 self.tests_to_run.append(test)
Ricky Liang4bff3e32014-02-20 18:46:11 +0800968 if subtrees:
969 self.set_active_run_state()
Jon Salz0697cbf2012-07-04 15:14:04 +0800970 self.run_next_test()
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800971
Jon Salz0697cbf2012-07-04 15:14:04 +0800972 def reap_completed_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800973 """Removes completed tests from the set of active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +0800974
975 Also updates the visible test if it was reaped.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800976 """
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800977 test_completed = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800978 for t, v in dict(self.invocations).iteritems():
979 if v.is_completed():
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +0800980 test_completed = True
Jon Salz1acc8742012-07-17 17:45:55 +0800981 new_state = t.update_state(**v.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +0800982 del self.invocations[t]
983
Chun-Ta Lin54e17e42012-09-06 22:05:13 +0800984 # Stop on failure if flag is true.
985 if (self.test_list.options.stop_on_failure and
986 new_state.status == TestState.FAILED):
987 # Clean all the tests to cause goofy to stop.
988 self.tests_to_run = []
989 factory.console.info("Stop on failure triggered. Empty the queue.")
990
Jon Salz1acc8742012-07-17 17:45:55 +0800991 if new_state.iterations_left and new_state.status == TestState.PASSED:
992 # Play it again, Sam!
993 self._run_test(t)
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800994 # new_state.retries_left is obtained after update.
995 # For retries_left == 0, test can still be run for the last time.
996 elif (new_state.retries_left >= 0 and
997 new_state.status == TestState.FAILED):
998 # Still have to retry, Sam!
999 self._run_test(t)
Jon Salz1acc8742012-07-17 17:45:55 +08001000
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001001 if test_completed:
Vic Yangf01c59f2013-04-19 17:37:56 +08001002 self.log_watcher.KickWatchThread()
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001003
Jon Salz0697cbf2012-07-04 15:14:04 +08001004 if (self.visible_test is None or
Jon Salz85a39882012-07-05 16:45:04 +08001005 self.visible_test not in self.invocations):
Jon Salz0697cbf2012-07-04 15:14:04 +08001006 self.set_visible_test(None)
1007 # Make the first running test, if any, the visible test
1008 for t in self.test_list.walk():
1009 if t in self.invocations:
1010 self.set_visible_test(t)
1011 break
1012
Jon Salz6dc031d2013-06-19 13:06:23 +08001013 def kill_active_tests(self, abort, root=None, reason=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001014 """Kills and waits for all active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +08001015
Jon Salz85a39882012-07-05 16:45:04 +08001016 Args:
1017 abort: True to change state of killed tests to FAILED, False for
Jon Salz0697cbf2012-07-04 15:14:04 +08001018 UNTESTED.
Jon Salz85a39882012-07-05 16:45:04 +08001019 root: If set, only kills tests with root as an ancestor.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001020 reason: If set, the abort reason.
1021 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001022 self.reap_completed_tests()
1023 for test, invoc in self.invocations.items():
Jon Salz85a39882012-07-05 16:45:04 +08001024 if root and not test.has_ancestor(root):
1025 continue
1026
Jon Salz0697cbf2012-07-04 15:14:04 +08001027 factory.console.info('Killing active test %s...' % test.path)
Jon Salz6dc031d2013-06-19 13:06:23 +08001028 invoc.abort_and_join(reason)
Jon Salz0697cbf2012-07-04 15:14:04 +08001029 factory.console.info('Killed %s' % test.path)
Jon Salz1acc8742012-07-17 17:45:55 +08001030 test.update_state(**invoc.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +08001031 del self.invocations[test]
Jon Salz1acc8742012-07-17 17:45:55 +08001032
Jon Salz0697cbf2012-07-04 15:14:04 +08001033 if not abort:
1034 test.update_state(status=TestState.UNTESTED)
1035 self.reap_completed_tests()
1036
Jon Salz6dc031d2013-06-19 13:06:23 +08001037 def stop(self, root=None, fail=False, reason=None):
1038 self.kill_active_tests(fail, root, reason)
Jon Salz85a39882012-07-05 16:45:04 +08001039 # Remove any tests in the run queue under the root.
1040 self.tests_to_run = deque([x for x in self.tests_to_run
1041 if root and not x.has_ancestor(root)])
1042 self.run_next_test()
Jon Salz0697cbf2012-07-04 15:14:04 +08001043
Jon Salz4712ac72013-02-07 17:12:05 +08001044 def clear_state(self, root=None):
Jon Salzd7550792013-07-12 05:49:27 +08001045 if root is None:
1046 root = self.test_list
Jon Salz6dc031d2013-06-19 13:06:23 +08001047 self.stop(root, reason='Clearing test state')
Jon Salz4712ac72013-02-07 17:12:05 +08001048 for f in root.walk():
1049 if f.is_leaf():
1050 f.update_state(status=TestState.UNTESTED)
1051
Jon Salz6dc031d2013-06-19 13:06:23 +08001052 def abort_active_tests(self, reason=None):
1053 self.kill_active_tests(True, reason=reason)
Jon Salz0697cbf2012-07-04 15:14:04 +08001054
1055 def main(self):
Jon Salzeff94182013-06-19 15:06:28 +08001056 syslog.openlog('goofy')
1057
Jon Salz0697cbf2012-07-04 15:14:04 +08001058 try:
Jon Salzd7550792013-07-12 05:49:27 +08001059 self.status = Status.INITIALIZING
Jon Salz0697cbf2012-07-04 15:14:04 +08001060 self.init()
1061 self.event_log.Log('goofy_init',
1062 success=True)
1063 except:
1064 if self.event_log:
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001065 try:
Jon Salz0697cbf2012-07-04 15:14:04 +08001066 self.event_log.Log('goofy_init',
1067 success=False,
1068 trace=traceback.format_exc())
1069 except: # pylint: disable=W0702
1070 pass
1071 raise
1072
Jon Salzd7550792013-07-12 05:49:27 +08001073 self.status = Status.RUNNING
Jon Salzeff94182013-06-19 15:06:28 +08001074 syslog.syslog('Goofy (factory test harness) starting')
Jon Salz0697cbf2012-07-04 15:14:04 +08001075 self.run()
1076
1077 def update_system_info(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001078 """Updates system info."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001079 system_info = system.SystemInfo()
1080 self.state_instance.set_shared_data('system_info', system_info.__dict__)
1081 self.event_client.post_event(Event(Event.Type.SYSTEM_INFO,
1082 system_info=system_info.__dict__))
1083 logging.info('System info: %r', system_info.__dict__)
1084
Jon Salzeb42f0d2012-07-27 19:14:04 +08001085 def update_factory(self, auto_run_on_restart=False, post_update_hook=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001086 """Commences updating factory software.
Jon Salzeb42f0d2012-07-27 19:14:04 +08001087
1088 Args:
1089 auto_run_on_restart: Auto-run when the machine comes back up.
1090 post_update_hook: Code to call after update but immediately before
1091 restart.
1092
1093 Returns:
1094 Never if the update was successful (we just reboot).
1095 False if the update was unnecessary (no update available).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001096 """
Jon Salz6dc031d2013-06-19 13:06:23 +08001097 self.kill_active_tests(False, reason='Factory software update')
Jon Salza6711d72012-07-18 14:33:03 +08001098 self.cancel_pending_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001099
Jon Salz5c344f62012-07-13 14:31:16 +08001100 def pre_update_hook():
1101 if auto_run_on_restart:
1102 self.state_instance.set_shared_data('tests_after_shutdown',
1103 FORCE_AUTO_RUN)
1104 self.state_instance.close()
1105
Jon Salzeb42f0d2012-07-27 19:14:04 +08001106 if updater.TryUpdate(pre_update_hook=pre_update_hook):
1107 if post_update_hook:
1108 post_update_hook()
1109 self.env.shutdown('reboot')
Jon Salz0697cbf2012-07-04 15:14:04 +08001110
Ricky Liang8fecf412014-05-22 10:56:14 +08001111 def handle_sigint(self, dummy_signum, dummy_frame): # pylint: disable=W0613
Jon Salz77c151e2012-08-28 07:20:37 +08001112 logging.error('Received SIGINT')
Peter Ammon1e1ec572014-06-26 17:56:32 -07001113 self.run_enqueue(None)
Jon Salz77c151e2012-08-28 07:20:37 +08001114 raise KeyboardInterrupt()
1115
Ricky Liang8fecf412014-05-22 10:56:14 +08001116 def handle_sigterm(self, dummy_signum, dummy_frame): # pylint: disable=W0613
1117 logging.error('Received SIGTERM')
Hung-Te Lin94ca4742014-07-09 20:13:50 +08001118 self.env.terminate()
1119 self.run_queue.put(None)
Ricky Liang8fecf412014-05-22 10:56:14 +08001120 raise RuntimeError('Received SIGTERM')
1121
Jon Salze12c2b32013-06-25 16:24:34 +08001122 def find_kcrashes(self):
1123 """Finds kcrash files, logs them, and marks them as seen."""
1124 seen_crashes = set(
1125 self.state_instance.get_shared_data('seen_crashes', optional=True)
1126 or [])
1127
1128 for path in glob.glob('/var/spool/crash/*'):
1129 if not os.path.isfile(path):
1130 continue
1131 if path in seen_crashes:
1132 continue
1133 try:
1134 stat = os.stat(path)
1135 mtime = utils.TimeString(stat.st_mtime)
1136 logging.info(
1137 'Found new crash file %s (%d bytes at %s)',
1138 path, stat.st_size, mtime)
1139 extra_log_args = {}
1140
1141 try:
1142 _, ext = os.path.splitext(path)
1143 if ext in ['.kcrash', '.meta']:
1144 ext = ext.replace('.', '')
1145 with open(path) as f:
1146 data = f.read(MAX_CRASH_FILE_SIZE)
1147 tell = f.tell()
1148 logging.info(
1149 'Contents of %s%s:%s',
1150 path,
1151 ('' if tell == stat.st_size
1152 else '(truncated to %d bytes)' % MAX_CRASH_FILE_SIZE),
1153 ('\n' + data).replace('\n', '\n ' + ext + '> '))
1154 extra_log_args['data'] = data
1155
1156 # Copy to /var/factory/kcrash for posterity
1157 kcrash_dir = factory.get_factory_root('kcrash')
1158 utils.TryMakeDirs(kcrash_dir)
1159 shutil.copy(path, kcrash_dir)
1160 logging.info('Copied to %s',
1161 os.path.join(kcrash_dir, os.path.basename(path)))
1162 finally:
1163 # Even if something goes wrong with the above, still try to
1164 # log to event log
1165 self.event_log.Log('crash_file',
1166 path=path, size=stat.st_size, mtime=mtime,
1167 **extra_log_args)
1168 except: # pylint: disable=W0702
1169 logging.exception('Unable to handle crash files %s', path)
1170 seen_crashes.add(path)
1171
1172 self.state_instance.set_shared_data('seen_crashes', list(seen_crashes))
1173
Jon Salz128b0932013-07-03 16:55:26 +08001174 def GetTestList(self, test_list_id):
1175 """Returns the test list with the given ID.
1176
1177 Raises:
1178 TestListError: The test list ID is not valid.
1179 """
1180 try:
1181 return self.test_lists[test_list_id]
1182 except KeyError:
1183 raise test_lists.TestListError(
1184 '%r is not a valid test list ID (available IDs are [%s])' % (
1185 test_list_id, ', '.join(sorted(self.test_lists.keys()))))
1186
1187 def InitTestLists(self):
1188 """Reads in all test lists and sets the active test list."""
Ricky Liang27051552014-05-04 14:22:26 +08001189 self.test_lists = test_lists.BuildAllTestLists(
1190 force_generic=(self.options.automation_mode is not None))
Jon Salzd7550792013-07-12 05:49:27 +08001191 logging.info('Loaded test lists: [%s]',
1192 test_lists.DescribeTestLists(self.test_lists))
Jon Salz128b0932013-07-03 16:55:26 +08001193
1194 if not self.options.test_list:
1195 self.options.test_list = test_lists.GetActiveTestListId()
1196
1197 if os.sep in self.options.test_list:
1198 # It's a path pointing to an old-style test list; use it.
1199 self.test_list = factory.read_test_list(self.options.test_list)
1200 else:
1201 self.test_list = self.GetTestList(self.options.test_list)
1202
1203 logging.info('Active test list: %s', self.test_list.test_list_id)
1204
1205 if isinstance(self.test_list, test_lists.OldStyleTestList):
1206 # Actually load it in. (See OldStyleTestList for an explanation
1207 # of why this is necessary.)
1208 self.test_list = self.test_list.Load()
1209
1210 self.test_list.state_instance = self.state_instance
1211
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001212 def init_hooks(self):
1213 """Initializes hooks.
1214
1215 Must run after self.test_list ready.
1216 """
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001217 module, cls = self.test_list.options.hooks_class.rsplit('.', 1)
1218 self.hooks = getattr(__import__(module, fromlist=[cls]), cls)()
1219 assert isinstance(self.hooks, factory.Hooks), (
1220 "hooks should be of type Hooks but is %r" % type(self.hooks))
1221 self.hooks.test_list = self.test_list
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001222 self.hooks.OnCreatedTestList()
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001223
Vic Yanga3cecf82014-12-26 00:44:21 -08001224 def init_ui(self):
1225 """Initialize UI."""
1226 self._ui_initialized = True
1227 if self.options.ui == 'chrome':
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001228 if self.options.standalone:
1229 self.env.launch_chrome()
1230 else:
1231 # The presenter is responsible for launching Chrome. Let's just
1232 # wait here.
1233 self.env.controller_ready_for_ui()
Vic Yanga3cecf82014-12-26 00:44:21 -08001234 logging.info('Waiting for a web socket connection')
1235 self.web_socket_manager.wait()
1236
1237 # Wait for the test widget size to be set; this is done in
1238 # an asynchronous RPC so there is a small chance that the
1239 # web socket might be opened first.
1240 for _ in range(100): # 10 s
1241 try:
1242 if self.state_instance.get_shared_data('test_widget_size'):
1243 break
1244 except KeyError:
1245 pass # Retry
1246 time.sleep(0.1) # 100 ms
1247 else:
1248 logging.warn('Never received test_widget_size from UI')
1249
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001250 logging.info('Waiting for a web socket connection')
1251 self.web_socket_manager.wait()
1252
Jon Salz0697cbf2012-07-04 15:14:04 +08001253 def init(self, args=None, env=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001254 """Initializes Goofy.
Jon Salz0697cbf2012-07-04 15:14:04 +08001255
1256 Args:
1257 args: A list of command-line arguments. Uses sys.argv if
1258 args is None.
1259 env: An Environment instance to use (or None to choose
1260 FakeChrootEnvironment or DUTEnvironment as appropriate).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001261 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001262 parser = OptionParser()
1263 parser.add_option('-v', '--verbose', dest='verbose',
Jon Salz8fa8e832012-07-13 19:04:09 +08001264 action='store_true',
1265 help='Enable debug logging')
Jon Salz0697cbf2012-07-04 15:14:04 +08001266 parser.add_option('--print_test_list', dest='print_test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001267 metavar='FILE',
1268 help='Read and print test list FILE, and exit')
Jon Salz0697cbf2012-07-04 15:14:04 +08001269 parser.add_option('--restart', dest='restart',
Jon Salz8fa8e832012-07-13 19:04:09 +08001270 action='store_true',
1271 help='Clear all test state')
Jon Salz0697cbf2012-07-04 15:14:04 +08001272 parser.add_option('--ui', dest='ui', type='choice',
Jon Salz7b5482e2014-08-04 17:48:41 +08001273 choices=['none', 'chrome'],
Jon Salz2f881df2013-02-01 17:00:35 +08001274 default='chrome',
Jon Salz8fa8e832012-07-13 19:04:09 +08001275 help='UI to use')
Jon Salz0697cbf2012-07-04 15:14:04 +08001276 parser.add_option('--ui_scale_factor', dest='ui_scale_factor',
Jon Salz8fa8e832012-07-13 19:04:09 +08001277 type='int', default=1,
1278 help=('Factor by which to scale UI '
1279 '(Chrome UI only)'))
Jon Salz0697cbf2012-07-04 15:14:04 +08001280 parser.add_option('--test_list', dest='test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001281 metavar='FILE',
1282 help='Use FILE as test list')
Jon Salzc79a9982012-08-30 04:42:01 +08001283 parser.add_option('--dummy_shopfloor', action='store_true',
1284 help='Use a dummy shopfloor server')
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001285 parser.add_option('--dummy_connection_manager', action='store_true',
1286 help='Use a dummy connection manager')
Ricky Liang6fe218c2013-12-27 15:17:17 +08001287 parser.add_option('--automation-mode',
1288 choices=[m.lower() for m in AutomationMode],
1289 default='none', help="Factory test automation mode.")
Ricky Liang117484a2014-04-14 11:14:41 +08001290 parser.add_option('--no-auto-run-on-start', dest='auto_run_on_start',
1291 action='store_false', default=True,
1292 help=('do not automatically run the test list on goofy '
1293 'start; this is only valid when factory test '
1294 'automation is enabled'))
Chun-Ta Lina8dd3172014-11-26 16:15:13 +08001295 parser.add_option('--handshake_timeout', dest='handshake_timeout',
1296 type='float', default=0.3,
1297 help=('RPC timeout when doing handshake between device '
1298 'and presenter.'))
Vic Yang7d693c42014-09-14 09:52:39 +08001299 parser.add_option('--standalone', dest='standalone',
1300 action='store_true', default=False,
1301 help=('Assume the presenter is running on the same '
1302 'machines.'))
Jon Salz0697cbf2012-07-04 15:14:04 +08001303 (self.options, self.args) = parser.parse_args(args)
1304
Hung-Te Lina846f602014-07-04 20:32:22 +08001305 signal.signal(signal.SIGINT, self.handle_sigint)
1306 # TODO(hungte) SIGTERM does not work properly without Telemetry and should
1307 # be fixed.
Hung-Te Lina846f602014-07-04 20:32:22 +08001308
Jon Salz46b89562012-07-05 11:49:22 +08001309 # Make sure factory directories exist.
1310 factory.get_log_root()
1311 factory.get_state_root()
1312 factory.get_test_data_root()
1313
Jon Salz0697cbf2012-07-04 15:14:04 +08001314 global _inited_logging # pylint: disable=W0603
1315 if not _inited_logging:
1316 factory.init_logging('goofy', verbose=self.options.verbose)
1317 _inited_logging = True
Jon Salz8fa8e832012-07-13 19:04:09 +08001318
Jon Salz0f996602012-10-03 15:26:48 +08001319 if self.options.print_test_list:
Joel Kitchingb85ed7f2014-10-08 18:24:39 +08001320 print(factory.read_test_list(
1321 self.options.print_test_list).__repr__(recursive=True))
Jon Salz0f996602012-10-03 15:26:48 +08001322 sys.exit(0)
1323
Jon Salzee85d522012-07-17 14:34:46 +08001324 event_log.IncrementBootSequence()
Jon Salzd15bbcf2013-05-21 17:33:57 +08001325 # Don't defer logging the initial event, so we can make sure
1326 # that device_id, reimage_id, etc. are all set up.
1327 self.event_log = EventLog('goofy', defer=False)
Jon Salz0697cbf2012-07-04 15:14:04 +08001328
Jon Salz0697cbf2012-07-04 15:14:04 +08001329 if env:
1330 self.env = env
1331 elif factory.in_chroot():
1332 self.env = test_environment.FakeChrootEnvironment()
1333 logging.warn(
1334 'Using chroot environment: will not actually run autotests')
Hung-Te Lina846f602014-07-04 20:32:22 +08001335 elif self.options.ui == 'chrome':
Ricky Liang09d66d82014-09-25 11:20:54 +08001336 self.env = test_environment.DUTEnvironment()
Jon Salz0697cbf2012-07-04 15:14:04 +08001337 self.env.goofy = self
Vic Yanga4931152014-08-11 16:36:24 -07001338 # web_socket_manager will be initialized later
1339 # pylint: disable=W0108
1340 self.env.has_sockets = lambda: self.web_socket_manager.has_sockets()
Jon Salz0697cbf2012-07-04 15:14:04 +08001341
1342 if self.options.restart:
1343 state.clear_state()
1344
Jon Salz0697cbf2012-07-04 15:14:04 +08001345 if self.options.ui_scale_factor != 1 and utils.in_qemu():
1346 logging.warn(
1347 'In QEMU; ignoring ui_scale_factor argument')
1348 self.options.ui_scale_factor = 1
1349
1350 logging.info('Started')
1351
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001352 if not self.options.standalone:
1353 self.link_manager = PresenterLinkManager(
1354 check_interval=1,
1355 handshake_timeout=self.options.handshake_timeout,
1356 standalone=self.options.standalone)
Peter Ammon1e1ec572014-06-26 17:56:32 -07001357
Jon Salz0697cbf2012-07-04 15:14:04 +08001358 self.start_state_server()
1359 self.state_instance.set_shared_data('hwid_cfg', get_hwid_cfg())
1360 self.state_instance.set_shared_data('ui_scale_factor',
Ricky Liang09216dc2013-02-22 17:26:45 +08001361 self.options.ui_scale_factor)
Jon Salz0697cbf2012-07-04 15:14:04 +08001362 self.last_shutdown_time = (
1363 self.state_instance.get_shared_data('shutdown_time', optional=True))
1364 self.state_instance.del_shared_data('shutdown_time', optional=True)
Jon Salzb19ea072013-02-07 16:35:00 +08001365 self.state_instance.del_shared_data('startup_error', optional=True)
Jon Salz0697cbf2012-07-04 15:14:04 +08001366
Ricky Liang6fe218c2013-12-27 15:17:17 +08001367 self.options.automation_mode = ParseAutomationMode(
1368 self.options.automation_mode)
1369 self.state_instance.set_shared_data('automation_mode',
1370 self.options.automation_mode)
1371 self.state_instance.set_shared_data(
1372 'automation_mode_prompt',
1373 AutomationModePrompt[self.options.automation_mode])
1374
Jon Salz128b0932013-07-03 16:55:26 +08001375 try:
1376 self.InitTestLists()
1377 except: # pylint: disable=W0702
1378 logging.exception('Unable to initialize test lists')
1379 self.state_instance.set_shared_data(
1380 'startup_error',
1381 'Unable to initialize test lists\n%s' % (
1382 traceback.format_exc()))
Jon Salzb19ea072013-02-07 16:35:00 +08001383 if self.options.ui == 'chrome':
1384 # Create an empty test list with default options so that the rest of
1385 # startup can proceed.
1386 self.test_list = factory.FactoryTestList(
1387 [], self.state_instance, factory.Options())
1388 else:
1389 # Bail with an error; no point in starting up.
1390 sys.exit('No valid test list; exiting.')
1391
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001392 self.init_hooks()
1393
Jon Salz822838b2013-03-25 17:32:33 +08001394 if self.test_list.options.clear_state_on_start:
1395 self.state_instance.clear_test_state()
1396
Jon Salz670ce062014-05-16 15:53:50 +08001397 # If the phase is invalid, this will raise a ValueError.
1398 phase.SetPersistentPhase(self.test_list.options.phase)
1399
Dean Liao85ca86f2014-11-03 12:28:08 +08001400 # For netboot firmware, mainfw_type should be 'netboot'.
1401 if (system.SystemInfo().mainfw_type != 'nonchrome' and
1402 system.SystemInfo().firmware_version is None):
Vic Yang9bd4f772013-06-04 17:34:00 +08001403 self.state_instance.set_shared_data('startup_error',
1404 'Netboot firmware detected\n'
1405 'Connect Ethernet and reboot to re-image.\n'
1406 u'侦测到网路开机固件\n'
1407 u'请连接乙太网并重启')
1408
Jon Salz0697cbf2012-07-04 15:14:04 +08001409 if not self.state_instance.has_shared_data('ui_lang'):
1410 self.state_instance.set_shared_data('ui_lang',
1411 self.test_list.options.ui_lang)
1412 self.state_instance.set_shared_data(
1413 'test_list_options',
1414 self.test_list.options.__dict__)
1415 self.state_instance.test_list = self.test_list
1416
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001417 self.check_log_rotation()
Jon Salz83ef34b2012-11-01 19:46:35 +08001418
Jon Salz23926422012-09-01 03:38:13 +08001419 if self.options.dummy_shopfloor:
Joel Kitchingb85ed7f2014-10-08 18:24:39 +08001420 os.environ[shopfloor.SHOPFLOOR_SERVER_ENV_VAR_NAME] = ('http://%s:%d/' %
1421 (net_utils.LOCALHOST, shopfloor.DEFAULT_SERVER_PORT))
Jon Salz23926422012-09-01 03:38:13 +08001422 self.dummy_shopfloor = Spawn(
1423 [os.path.join(factory.FACTORY_PATH, 'bin', 'shopfloor_server'),
1424 '--dummy'])
1425 elif self.test_list.options.shopfloor_server_url:
1426 shopfloor.set_server_url(self.test_list.options.shopfloor_server_url)
Jon Salz2bf2f6b2013-03-28 18:49:26 +08001427 shopfloor.set_enabled(True)
Jon Salz23926422012-09-01 03:38:13 +08001428
Jon Salz0f996602012-10-03 15:26:48 +08001429 if self.test_list.options.time_sanitizer and not utils.in_chroot():
Jon Salz8fa8e832012-07-13 19:04:09 +08001430 self.time_sanitizer = time_sanitizer.TimeSanitizer(
1431 base_time=time_sanitizer.GetBaseTimeFromFile(
1432 # lsb-factory is written by the factory install shim during
1433 # installation, so it should have a good time obtained from
Jon Salz54882d02012-08-31 01:57:54 +08001434 # the mini-Omaha server. If it's not available, we'll use
1435 # /etc/lsb-factory (which will be much older, but reasonably
1436 # sane) and rely on a shopfloor sync to set a more accurate
1437 # time.
1438 '/usr/local/etc/lsb-factory',
1439 '/etc/lsb-release'))
Jon Salz8fa8e832012-07-13 19:04:09 +08001440 self.time_sanitizer.RunOnce()
1441
Vic Yangd8990da2013-06-27 16:57:43 +08001442 if self.test_list.options.check_cpu_usage_period_secs:
1443 self.cpu_usage_watcher = Spawn(['py/tools/cpu_usage_monitor.py',
1444 '-p', str(self.test_list.options.check_cpu_usage_period_secs)],
1445 cwd=factory.FACTORY_PATH)
1446
Jon Salz0697cbf2012-07-04 15:14:04 +08001447 self.init_states()
1448 self.start_event_server()
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001449
1450 if self.options.dummy_connection_manager:
1451 # Override network manager creation to dummy implmenetation.
1452 logging.info('Using dummy network manager (--dummy_connection_manager).')
1453 self.connection_manager = connection_manager.DummyConnectionManager()
1454 else:
1455 self.connection_manager = self.env.create_connection_manager(
1456 self.test_list.options.wlans,
1457 self.test_list.options.scan_wifi_period_secs)
1458
Jon Salz0697cbf2012-07-04 15:14:04 +08001459 # Note that we create a log watcher even if
1460 # sync_event_log_period_secs isn't set (no background
1461 # syncing), since we may use it to flush event logs as well.
1462 self.log_watcher = EventLogWatcher(
1463 self.test_list.options.sync_event_log_period_secs,
Jon Salzd15bbcf2013-05-21 17:33:57 +08001464 event_log_db_file=None,
Jon Salz16d10542012-07-23 12:18:45 +08001465 handle_event_logs_callback=self.handle_event_logs)
Jon Salz0697cbf2012-07-04 15:14:04 +08001466 if self.test_list.options.sync_event_log_period_secs:
1467 self.log_watcher.StartWatchThread()
1468
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001469 # Creates a system log manager to scan logs periocially.
1470 # A scan includes clearing logs and optionally syncing logs if
1471 # enable_syng_log is True. We kick it to sync logs.
1472 self.system_log_manager = SystemLogManager(
1473 sync_log_paths=self.test_list.options.sync_log_paths,
1474 sync_log_period_secs=self.test_list.options.sync_log_period_secs,
1475 scan_log_period_secs=self.test_list.options.scan_log_period_secs,
Cheng-Yi Chiangb8a491c2014-01-20 14:37:57 +08001476 clear_log_paths=self.test_list.options.clear_log_paths,
1477 clear_log_excluded_paths=self.test_list.options.clear_log_excluded_paths)
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001478 self.system_log_manager.Start()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +08001479
Jon Salz0697cbf2012-07-04 15:14:04 +08001480 self.update_system_info()
1481
Vic Yang4953fc12012-07-26 16:19:53 +08001482 assert ((self.test_list.options.min_charge_pct is None) ==
1483 (self.test_list.options.max_charge_pct is None))
Vic Yange83d9a12013-04-19 20:00:20 +08001484 if utils.in_chroot():
1485 logging.info('In chroot, ignoring charge manager and charge state')
Ricky Liangc392a1c2014-06-20 18:24:59 +08001486 elif (self.test_list.options.enable_charge_manager and
1487 self.test_list.options.min_charge_pct is not None):
Vic Yang4953fc12012-07-26 16:19:53 +08001488 self.charge_manager = ChargeManager(self.test_list.options.min_charge_pct,
1489 self.test_list.options.max_charge_pct)
Jon Salzad7353b2012-10-15 16:22:46 +08001490 system.SystemStatus.charge_manager = self.charge_manager
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +08001491 else:
1492 # Goofy should set charger state to charge if charge_manager is disabled.
Dean Liao88b93192014-10-23 19:37:41 +08001493 self.charge()
Vic Yang4953fc12012-07-26 16:19:53 +08001494
Vic Yang6cee2472014-10-22 17:18:52 -07001495 if CoreDumpManager.CoreDumpEnabled():
1496 self.core_dump_manager = CoreDumpManager(
1497 self.test_list.options.core_dump_watchlist)
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001498
Jon Salz0697cbf2012-07-04 15:14:04 +08001499 os.environ['CROS_FACTORY'] = '1'
1500 os.environ['CROS_DISABLE_SITE_SYSINFO'] = '1'
1501
Shuo-Peng Liao1ff502e2013-06-30 18:37:02 +08001502 if not utils.in_chroot() and self.test_list.options.use_cpufreq_manager:
Ricky Liangecddbd42014-07-24 11:32:10 +08001503 logging.info('Enabling CPU frequency manager')
Jon Salzddf0d052013-06-18 12:52:44 +08001504 self.cpufreq_manager = CpufreqManager(event_log=self.event_log)
Jon Salzce6a7f82013-06-10 18:22:54 +08001505
Justin Chuang31b02432013-06-27 15:16:51 +08001506 # Startup hooks may want to skip some tests.
1507 self.update_skipped_tests()
Jon Salz416f9cc2013-05-10 18:32:50 +08001508
Jon Salze12c2b32013-06-25 16:24:34 +08001509 self.find_kcrashes()
1510
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001511 # Should not move earlier.
1512 self.hooks.OnStartup()
1513
Ricky Liang36512a32014-07-25 11:47:04 +08001514 # Only after this point the Goofy backend is ready for UI connection.
1515 self.ready_for_ui_connection = True
1516
Ricky Liang650f6bf2012-09-28 13:22:54 +08001517 # Create download path for autotest beforehand or autotests run at
1518 # the same time might fail due to race condition.
1519 if not factory.in_chroot():
1520 utils.TryMakeDirs(os.path.join('/usr/local/autotest', 'tests',
1521 'download'))
1522
Jon Salz0697cbf2012-07-04 15:14:04 +08001523 def state_change_callback(test, test_state):
1524 self.event_client.post_event(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001525 Event(Event.Type.STATE_CHANGE, path=test.path, state=test_state))
Jon Salz0697cbf2012-07-04 15:14:04 +08001526 self.test_list.state_change_callback = state_change_callback
Jon Salz73e0fd02012-04-04 11:46:38 +08001527
Vic Yange2c76a82014-10-30 12:48:19 -07001528 self.autotest_prespawner = prespawner.AutotestPrespawner()
1529 self.autotest_prespawner.start()
1530
1531 self.pytest_prespawner = prespawner.PytestPrespawner()
1532 self.pytest_prespawner.start()
Jon Salza6711d72012-07-18 14:33:03 +08001533
Ricky Liang48e47f92014-02-26 19:31:51 +08001534 tests_after_shutdown = self.state_instance.get_shared_data(
1535 'tests_after_shutdown', optional=True)
Jon Salz57717ca2012-04-04 16:47:25 +08001536
Jon Salz5c344f62012-07-13 14:31:16 +08001537 force_auto_run = (tests_after_shutdown == FORCE_AUTO_RUN)
1538 if not force_auto_run and tests_after_shutdown is not None:
Ricky Liang48e47f92014-02-26 19:31:51 +08001539 logging.info('Resuming tests after shutdown: %s', tests_after_shutdown)
Jon Salz0697cbf2012-07-04 15:14:04 +08001540 self.tests_to_run.extend(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001541 self.test_list.lookup_path(t) for t in tests_after_shutdown)
Peter Ammon1e1ec572014-06-26 17:56:32 -07001542 self.run_enqueue(self.run_next_test)
Jon Salz0697cbf2012-07-04 15:14:04 +08001543 else:
Jon Salz5c344f62012-07-13 14:31:16 +08001544 if force_auto_run or self.test_list.options.auto_run_on_start:
Ricky Liang117484a2014-04-14 11:14:41 +08001545 # If automation mode is enabled, allow suppress auto_run_on_start.
1546 if (self.options.automation_mode == 'NONE' or
1547 self.options.auto_run_on_start):
Peter Ammon1e1ec572014-06-26 17:56:32 -07001548 self.run_enqueue(
Ricky Liang117484a2014-04-14 11:14:41 +08001549 lambda: self.run_tests(self.test_list, untested_only=True))
Jon Salz5c344f62012-07-13 14:31:16 +08001550 self.state_instance.set_shared_data('tests_after_shutdown', None)
Ricky Liang4bff3e32014-02-20 18:46:11 +08001551 self.restore_active_run_state()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001552
Dean Liao592e4d52013-01-10 20:06:39 +08001553 self.may_disable_cros_shortcut_keys()
1554
1555 def may_disable_cros_shortcut_keys(self):
1556 test_options = self.test_list.options
1557 if test_options.disable_cros_shortcut_keys:
1558 logging.info('Filter ChromeOS shortcut keys.')
1559 self.key_filter = KeyFilter(
1560 unmap_caps_lock=test_options.disable_caps_lock,
1561 caps_lock_keycode=test_options.caps_lock_keycode)
1562 self.key_filter.Start()
1563
Jon Salz0e6532d2012-10-25 16:30:11 +08001564 def _should_sync_time(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001565 """Returns True if we should attempt syncing time with shopfloor.
Jon Salz0e6532d2012-10-25 16:30:11 +08001566
1567 Args:
1568 foreground: If True, synchronizes even if background syncing
1569 is disabled (e.g., in explicit sync requests from the
1570 SyncShopfloor test).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001571 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001572 return ((foreground or
1573 self.test_list.options.sync_time_period_secs) and
Jon Salz54882d02012-08-31 01:57:54 +08001574 self.time_sanitizer and
1575 (not self.time_synced) and
1576 (not factory.in_chroot()))
1577
Jon Salz0e6532d2012-10-25 16:30:11 +08001578 def sync_time_with_shopfloor_server(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001579 """Syncs time with shopfloor server, if not yet synced.
Jon Salz54882d02012-08-31 01:57:54 +08001580
Jon Salz0e6532d2012-10-25 16:30:11 +08001581 Args:
1582 foreground: If True, synchronizes even if background syncing
1583 is disabled (e.g., in explicit sync requests from the
1584 SyncShopfloor test).
1585
Jon Salz54882d02012-08-31 01:57:54 +08001586 Returns:
1587 False if no time sanitizer is available, or True if this sync (or a
1588 previous sync) succeeded.
1589
1590 Raises:
1591 Exception if unable to contact the shopfloor server.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001592 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001593 if self._should_sync_time(foreground):
Jon Salz54882d02012-08-31 01:57:54 +08001594 self.time_sanitizer.SyncWithShopfloor()
1595 self.time_synced = True
1596 return self.time_synced
1597
Jon Salzb92c5112012-09-21 15:40:11 +08001598 def log_disk_space_stats(self):
Jon Salz18e0e022013-06-11 17:13:39 +08001599 if (utils.in_chroot() or
1600 not self.test_list.options.log_disk_space_period_secs):
Jon Salzb92c5112012-09-21 15:40:11 +08001601 return
1602
1603 now = time.time()
1604 if (self.last_log_disk_space_time and
1605 now - self.last_log_disk_space_time <
1606 self.test_list.options.log_disk_space_period_secs):
1607 return
1608 self.last_log_disk_space_time = now
1609
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001610 # Upload event if stateful partition usage is above threshold.
1611 # Stateful partition is mounted on /usr/local, while
1612 # encrypted stateful partition is mounted on /var.
1613 # If there are too much logs in the factory process,
1614 # these two partitions might get full.
Jon Salzb92c5112012-09-21 15:40:11 +08001615 try:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001616 vfs_infos = disk_space.GetAllVFSInfo()
1617 stateful_info, encrypted_info = None, None
1618 for vfs_info in vfs_infos.values():
1619 if '/usr/local' in vfs_info.mount_points:
1620 stateful_info = vfs_info
1621 if '/var' in vfs_info.mount_points:
1622 encrypted_info = vfs_info
1623
1624 stateful = disk_space.GetPartitionUsage(stateful_info)
1625 encrypted = disk_space.GetPartitionUsage(encrypted_info)
1626
1627 above_threshold = (
1628 self.test_list.options.stateful_usage_threshold and
1629 max(stateful.bytes_used_pct,
1630 stateful.inodes_used_pct,
1631 encrypted.bytes_used_pct,
1632 encrypted.inodes_used_pct) >
1633 self.test_list.options.stateful_usage_threshold)
1634
1635 if above_threshold:
1636 self.event_log.Log('stateful_partition_usage',
1637 partitions={
1638 'stateful': {
1639 'bytes_used_pct': FloatDigit(stateful.bytes_used_pct, 2),
1640 'inodes_used_pct': FloatDigit(stateful.inodes_used_pct, 2)},
1641 'encrypted_stateful': {
1642 'bytes_used_pct': FloatDigit(encrypted.bytes_used_pct, 2),
1643 'inodes_used_pct': FloatDigit(encrypted.inodes_used_pct, 2)}
1644 })
1645 self.log_watcher.ScanEventLogs()
Cheng-Yi Chiang00798e72013-06-20 18:16:39 +08001646 if (not utils.in_chroot() and
1647 self.test_list.options.stateful_usage_above_threshold_action):
1648 Spawn(self.test_list.options.stateful_usage_above_threshold_action,
1649 call=True)
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001650
1651 message = disk_space.FormatSpaceUsedAll(vfs_infos)
Jon Salz3c493bb2013-02-07 17:24:58 +08001652 if message != self.last_log_disk_space_message:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001653 if above_threshold:
1654 logging.warning(message)
1655 else:
1656 logging.info(message)
Jon Salz3c493bb2013-02-07 17:24:58 +08001657 self.last_log_disk_space_message = message
Jon Salzb92c5112012-09-21 15:40:11 +08001658 except: # pylint: disable=W0702
1659 logging.exception('Unable to get disk space used')
1660
Justin Chuang83813982013-05-13 01:26:32 +08001661 def check_battery(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001662 """Checks the current battery status.
Justin Chuang83813982013-05-13 01:26:32 +08001663
1664 Logs current battery charging level and status to log. If the battery level
1665 is lower below warning_low_battery_pct, send warning event to shopfloor.
1666 If the battery level is lower below critical_low_battery_pct, flush disks.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001667 """
Justin Chuang83813982013-05-13 01:26:32 +08001668 if not self.test_list.options.check_battery_period_secs:
1669 return
1670
1671 now = time.time()
1672 if (self.last_check_battery_time and
1673 now - self.last_check_battery_time <
1674 self.test_list.options.check_battery_period_secs):
1675 return
1676 self.last_check_battery_time = now
1677
1678 message = ''
1679 log_level = logging.INFO
1680 try:
1681 power = system.GetBoard().power
1682 if not power.CheckBatteryPresent():
1683 message = 'Battery is not present'
1684 else:
1685 ac_present = power.CheckACPresent()
1686 charge_pct = power.GetChargePct(get_float=True)
1687 message = ('Current battery level %.1f%%, AC charger is %s' %
1688 (charge_pct, 'connected' if ac_present else 'disconnected'))
1689
1690 if charge_pct > self.test_list.options.critical_low_battery_pct:
1691 critical_low_battery = False
1692 else:
1693 critical_low_battery = True
1694 # Only sync disks when battery level is still above minimum
1695 # value. This can be used for offline analysis when shopfloor cannot
1696 # be connected.
1697 if charge_pct > MIN_BATTERY_LEVEL_FOR_DISK_SYNC:
1698 logging.warning('disk syncing for critical low battery situation')
1699 os.system('sync; sync; sync')
1700 else:
1701 logging.warning('disk syncing is cancelled '
1702 'because battery level is lower than %.1f',
1703 MIN_BATTERY_LEVEL_FOR_DISK_SYNC)
1704
1705 # Notify shopfloor server
1706 if (critical_low_battery or
1707 (not ac_present and
1708 charge_pct <= self.test_list.options.warning_low_battery_pct)):
1709 log_level = logging.WARNING
1710
1711 self.event_log.Log('low_battery',
1712 battery_level=charge_pct,
1713 charger_connected=ac_present,
1714 critical=critical_low_battery)
1715 self.log_watcher.KickWatchThread()
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001716 if self.test_list.options.enable_sync_log:
1717 self.system_log_manager.KickToSync()
Justin Chuang83813982013-05-13 01:26:32 +08001718 except: # pylint: disable=W0702
1719 logging.exception('Unable to check battery or notify shopfloor')
1720 finally:
1721 if message != self.last_check_battery_message:
1722 logging.log(log_level, message)
1723 self.last_check_battery_message = message
1724
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001725 def check_core_dump(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001726 """Checks if there is any core dumped file.
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001727
1728 Removes unwanted core dump files immediately.
1729 Syncs those files matching watch list to server with a delay between
1730 each sync. After the files have been synced to server, deletes the files.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001731 """
Vic Yang6cee2472014-10-22 17:18:52 -07001732 if not self.core_dump_manager:
1733 return
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001734 core_dump_files = self.core_dump_manager.ScanFiles()
1735 if core_dump_files:
1736 now = time.time()
1737 if (self.last_kick_sync_time and now - self.last_kick_sync_time <
1738 self.test_list.options.kick_sync_min_interval_secs):
1739 return
1740 self.last_kick_sync_time = now
1741
1742 # Sends event to server
1743 self.event_log.Log('core_dumped', files=core_dump_files)
1744 self.log_watcher.KickWatchThread()
1745
1746 # Syncs files to server
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001747 if self.test_list.options.enable_sync_log:
1748 self.system_log_manager.KickToSync(
Cheng-Yi Chiangd3516a32013-07-17 15:30:47 +08001749 core_dump_files, self.core_dump_manager.ClearFiles)
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001750
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001751 def check_log_rotation(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001752 """Checks log rotation file presence/absence according to test_list option.
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001753
1754 Touch /var/lib/cleanup_logs_paused if test_list.options.disable_log_rotation
1755 is True, delete it otherwise. This must be done in idle loop because
1756 autotest client will touch /var/lib/cleanup_logs_paused each time it runs
1757 an autotest.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001758 """
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001759 if utils.in_chroot():
1760 return
1761 try:
1762 if self.test_list.options.disable_log_rotation:
1763 open(CLEANUP_LOGS_PAUSED, 'w').close()
1764 else:
1765 file_utils.TryUnlink(CLEANUP_LOGS_PAUSED)
1766 except: # pylint: disable=W0702
1767 # Oh well. Logs an error (but no trace)
1768 logging.info(
1769 'Unable to %s %s: %s',
1770 'touch' if self.test_list.options.disable_log_rotation else 'delete',
1771 CLEANUP_LOGS_PAUSED, utils.FormatExceptionOnly())
1772
Jon Salz8fa8e832012-07-13 19:04:09 +08001773 def sync_time_in_background(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001774 """Writes out current time and tries to sync with shopfloor server."""
Jon Salzb22d1172012-08-06 10:38:57 +08001775 if not self.time_sanitizer:
1776 return
1777
1778 # Write out the current time.
1779 self.time_sanitizer.SaveTime()
1780
Jon Salz54882d02012-08-31 01:57:54 +08001781 if not self._should_sync_time():
Jon Salz8fa8e832012-07-13 19:04:09 +08001782 return
1783
1784 now = time.time()
1785 if self.last_sync_time and (
1786 now - self.last_sync_time <
1787 self.test_list.options.sync_time_period_secs):
1788 # Not yet time for another check.
1789 return
1790 self.last_sync_time = now
1791
1792 def target():
1793 try:
Jon Salz54882d02012-08-31 01:57:54 +08001794 self.sync_time_with_shopfloor_server()
Jon Salz8fa8e832012-07-13 19:04:09 +08001795 except: # pylint: disable=W0702
1796 # Oh well. Log an error (but no trace)
1797 logging.info(
1798 'Unable to get time from shopfloor server: %s',
1799 utils.FormatExceptionOnly())
1800
1801 thread = threading.Thread(target=target)
1802 thread.daemon = True
1803 thread.start()
1804
Peter Ammon1e1ec572014-06-26 17:56:32 -07001805 def perform_periodic_tasks(self):
1806 """Override of base method to perform periodic work.
Vic Yang4953fc12012-07-26 16:19:53 +08001807
Peter Ammon1e1ec572014-06-26 17:56:32 -07001808 This method must not raise exceptions.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001809 """
Peter Ammon1e1ec572014-06-26 17:56:32 -07001810 super(Goofy, self).perform_periodic_tasks()
Jon Salzb22d1172012-08-06 10:38:57 +08001811
Vic Yang311ddb82012-09-26 12:08:28 +08001812 self.check_exclusive()
cychiang21886742012-07-05 15:16:32 +08001813 self.check_for_updates()
Jon Salz8fa8e832012-07-13 19:04:09 +08001814 self.sync_time_in_background()
Jon Salzb92c5112012-09-21 15:40:11 +08001815 self.log_disk_space_stats()
Justin Chuang83813982013-05-13 01:26:32 +08001816 self.check_battery()
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001817 self.check_core_dump()
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001818 self.check_log_rotation()
Jon Salz57717ca2012-04-04 16:47:25 +08001819
Jon Salzd15bbcf2013-05-21 17:33:57 +08001820 def handle_event_logs(self, chunks):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001821 """Callback for event watcher.
Jon Salz258a40c2012-04-19 12:34:01 +08001822
Jon Salz0697cbf2012-07-04 15:14:04 +08001823 Attempts to upload the event logs to the shopfloor server.
Vic Yang93027612013-05-06 02:42:49 +08001824
1825 Args:
Jon Salzd15bbcf2013-05-21 17:33:57 +08001826 chunks: A list of Chunk objects.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001827 """
Vic Yang93027612013-05-06 02:42:49 +08001828 first_exception = None
1829 exception_count = 0
1830
Jon Salzd15bbcf2013-05-21 17:33:57 +08001831 for chunk in chunks:
Vic Yang93027612013-05-06 02:42:49 +08001832 try:
Jon Salzcddb6402013-05-23 12:56:42 +08001833 description = 'event logs (%s)' % str(chunk)
Vic Yang93027612013-05-06 02:42:49 +08001834 start_time = time.time()
1835 shopfloor_client = shopfloor.get_instance(
1836 detect=True,
1837 timeout=self.test_list.options.shopfloor_timeout_secs)
Jon Salzd15bbcf2013-05-21 17:33:57 +08001838 shopfloor_client.UploadEvent(chunk.log_name + "." +
1839 event_log.GetReimageId(),
1840 Binary(chunk.chunk))
Vic Yang93027612013-05-06 02:42:49 +08001841 logging.info(
1842 'Successfully synced %s in %.03f s',
1843 description, time.time() - start_time)
1844 except: # pylint: disable=W0702
Jon Salzd15bbcf2013-05-21 17:33:57 +08001845 first_exception = (first_exception or (chunk.log_name + ': ' +
Vic Yang93027612013-05-06 02:42:49 +08001846 utils.FormatExceptionOnly()))
1847 exception_count += 1
1848
1849 if exception_count:
1850 if exception_count == 1:
1851 msg = 'Log upload failed: %s' % first_exception
1852 else:
1853 msg = '%d log upload failed; first is: %s' % (
1854 exception_count, first_exception)
1855 raise Exception(msg)
1856
Jon Salz57717ca2012-04-04 16:47:25 +08001857
Jon Salz0697cbf2012-07-04 15:14:04 +08001858 def run_tests_with_status(self, statuses_to_run, starting_at=None,
1859 root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001860 """Runs all top-level tests with a particular status.
Jon Salz0405ab52012-03-16 15:26:52 +08001861
Jon Salz0697cbf2012-07-04 15:14:04 +08001862 All active tests, plus any tests to re-run, are reset.
Jon Salz57717ca2012-04-04 16:47:25 +08001863
Jon Salz0697cbf2012-07-04 15:14:04 +08001864 Args:
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001865 statuses_to_run: The particular status that caller wants to run.
Jon Salz0697cbf2012-07-04 15:14:04 +08001866 starting_at: If provided, only auto-runs tests beginning with
1867 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001868 root: The root of tests to run. If not provided, it will be
1869 the root of all tests.
1870 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001871 root = root or self.test_list
Jon Salz57717ca2012-04-04 16:47:25 +08001872
Jon Salz0697cbf2012-07-04 15:14:04 +08001873 if starting_at:
1874 # Make sure they passed a test, not a string.
1875 assert isinstance(starting_at, factory.FactoryTest)
Jon Salz0405ab52012-03-16 15:26:52 +08001876
Jon Salz0697cbf2012-07-04 15:14:04 +08001877 tests_to_reset = []
1878 tests_to_run = []
Jon Salz0405ab52012-03-16 15:26:52 +08001879
Jon Salz0697cbf2012-07-04 15:14:04 +08001880 found_starting_at = False
Jon Salz0405ab52012-03-16 15:26:52 +08001881
Jon Salz0697cbf2012-07-04 15:14:04 +08001882 for test in root.get_top_level_tests():
1883 if starting_at:
1884 if test == starting_at:
1885 # We've found starting_at; do auto-run on all
1886 # subsequent tests.
1887 found_starting_at = True
1888 if not found_starting_at:
1889 # Don't start this guy yet
1890 continue
Jon Salz0405ab52012-03-16 15:26:52 +08001891
Jon Salz0697cbf2012-07-04 15:14:04 +08001892 status = test.get_state().status
1893 if status == TestState.ACTIVE or status in statuses_to_run:
1894 # Reset the test (later; we will need to abort
1895 # all active tests first).
1896 tests_to_reset.append(test)
1897 if status in statuses_to_run:
1898 tests_to_run.append(test)
Jon Salz0405ab52012-03-16 15:26:52 +08001899
Jon Salz6dc031d2013-06-19 13:06:23 +08001900 self.abort_active_tests('Operator requested run/re-run of certain tests')
Jon Salz258a40c2012-04-19 12:34:01 +08001901
Jon Salz0697cbf2012-07-04 15:14:04 +08001902 # Reset all statuses of the tests to run (in case any tests were active;
1903 # we want them to be run again).
1904 for test_to_reset in tests_to_reset:
1905 for test in test_to_reset.walk():
1906 test.update_state(status=TestState.UNTESTED)
Jon Salz57717ca2012-04-04 16:47:25 +08001907
Jon Salz0697cbf2012-07-04 15:14:04 +08001908 self.run_tests(tests_to_run, untested_only=True)
Jon Salz0405ab52012-03-16 15:26:52 +08001909
Jon Salz0697cbf2012-07-04 15:14:04 +08001910 def restart_tests(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001911 """Restarts all tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001912 root = root or self.test_list
Jon Salz0405ab52012-03-16 15:26:52 +08001913
Jon Salz6dc031d2013-06-19 13:06:23 +08001914 self.abort_active_tests('Operator requested restart of certain tests')
Jon Salz0697cbf2012-07-04 15:14:04 +08001915 for test in root.walk():
Ricky Liangfea4ac92014-08-21 11:55:59 +08001916 test.update_state(status=TestState.UNTESTED)
Jon Salz0697cbf2012-07-04 15:14:04 +08001917 self.run_tests(root)
Hung-Te Lin96632362012-03-20 21:14:18 +08001918
Jon Salz0697cbf2012-07-04 15:14:04 +08001919 def auto_run(self, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001920 """"Auto-runs" tests that have not been run yet.
Hung-Te Lin96632362012-03-20 21:14:18 +08001921
Jon Salz0697cbf2012-07-04 15:14:04 +08001922 Args:
1923 starting_at: If provide, only auto-runs tests beginning with
1924 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001925 root: If provided, the root of tests to run. If not provided, the root
1926 will be test_list (root of all tests).
1927 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001928 root = root or self.test_list
1929 self.run_tests_with_status([TestState.UNTESTED, TestState.ACTIVE],
1930 starting_at=starting_at,
1931 root=root)
Jon Salz968e90b2012-03-18 16:12:43 +08001932
Jon Salz0697cbf2012-07-04 15:14:04 +08001933 def re_run_failed(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001934 """Re-runs failed tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08001935 root = root or self.test_list
1936 self.run_tests_with_status([TestState.FAILED], root=root)
Jon Salz57717ca2012-04-04 16:47:25 +08001937
Jon Salz0697cbf2012-07-04 15:14:04 +08001938 def show_review_information(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001939 """Event handler for showing review information screen.
Jon Salz57717ca2012-04-04 16:47:25 +08001940
Peter Ammon1e1ec572014-06-26 17:56:32 -07001941 The information screen is rendered by main UI program (ui.py), so in
Jon Salz0697cbf2012-07-04 15:14:04 +08001942 goofy we only need to kill all active tests, set them as untested, and
1943 clear remaining tests.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001944 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001945 self.kill_active_tests(False)
Jon Salza6711d72012-07-18 14:33:03 +08001946 self.cancel_pending_tests()
Jon Salz57717ca2012-04-04 16:47:25 +08001947
Jon Salz0697cbf2012-07-04 15:14:04 +08001948 def handle_switch_test(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001949 """Switches to a particular test.
Jon Salz0405ab52012-03-16 15:26:52 +08001950
Ricky Liang6fe218c2013-12-27 15:17:17 +08001951 Args:
1952 event: The SWITCH_TEST event.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001953 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001954 test = self.test_list.lookup_path(event.path)
1955 if not test:
1956 logging.error('Unknown test %r', event.key)
1957 return
Jon Salz73e0fd02012-04-04 11:46:38 +08001958
Jon Salz0697cbf2012-07-04 15:14:04 +08001959 invoc = self.invocations.get(test)
1960 if invoc and test.backgroundable:
1961 # Already running: just bring to the front if it
1962 # has a UI.
1963 logging.info('Setting visible test to %s', test.path)
Jon Salz36fbbb52012-07-05 13:45:06 +08001964 self.set_visible_test(test)
Jon Salz0697cbf2012-07-04 15:14:04 +08001965 return
Jon Salz73e0fd02012-04-04 11:46:38 +08001966
Jon Salz6dc031d2013-06-19 13:06:23 +08001967 self.abort_active_tests('Operator requested abort (switch_test)')
Jon Salz0697cbf2012-07-04 15:14:04 +08001968 for t in test.walk():
1969 t.update_state(status=TestState.UNTESTED)
Jon Salz73e0fd02012-04-04 11:46:38 +08001970
Jon Salz0697cbf2012-07-04 15:14:04 +08001971 if self.test_list.options.auto_run_on_keypress:
1972 self.auto_run(starting_at=test)
1973 else:
1974 self.run_tests(test)
Jon Salz73e0fd02012-04-04 11:46:38 +08001975
Jon Salz0697cbf2012-07-04 15:14:04 +08001976 def wait(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001977 """Waits for all pending invocations.
Jon Salz0697cbf2012-07-04 15:14:04 +08001978
1979 Useful for testing.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001980 """
Jon Salz1acc8742012-07-17 17:45:55 +08001981 while self.invocations:
1982 for k, v in self.invocations.iteritems():
1983 logging.info('Waiting for %s to complete...', k)
1984 v.thread.join()
1985 self.reap_completed_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001986
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001987if __name__ == '__main__':
Peter Ammona3d298c2014-09-23 10:11:02 -07001988 Goofy.run_main_and_exit()