blob: c5b5358c952e3c5818e0757860d441e2756de93c [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
Hung-Te Linb6287242016-05-18 14:39:05 +080028from cros.factory.device import device_utils
29from cros.factory.device import DeviceException
Hung-Te Lincc41d2a2014-10-29 13:35:20 +080030from cros.factory.goofy import connection_manager
Vic Yangd80ea752014-09-24 16:07:14 +080031from cros.factory.goofy.goofy_base import GoofyBase
32from cros.factory.goofy.goofy_rpc import GoofyRPC
33from cros.factory.goofy.invocation import TestArgEnv
34from cros.factory.goofy.invocation import TestInvocation
35from cros.factory.goofy.link_manager import PresenterLinkManager
Earl Oua3bca122016-10-21 16:00:30 +080036from cros.factory.goofy.plugins import plugin_controller
Vic Yange2c76a82014-10-30 12:48:19 -070037from cros.factory.goofy import prespawner
Vic Yangd80ea752014-09-24 16:07:14 +080038from cros.factory.goofy.system_log_manager import SystemLogManager
Wei-Ning Huang38b75f02015-02-25 18:25:14 +080039from cros.factory.goofy.terminal_manager import TerminalManager
Earl Oua3bca122016-10-21 16:00:30 +080040from cros.factory.goofy import test_environment
41from cros.factory.goofy import time_sanitizer
42from cros.factory.goofy import updater
Vic Yangd80ea752014-09-24 16:07:14 +080043from cros.factory.goofy.web_socket_manager import WebSocketManager
Hung-Te Linb6287242016-05-18 14:39:05 +080044from cros.factory.test.e2e_test.common import AutomationMode
45from cros.factory.test.e2e_test.common import AutomationModePrompt
46from cros.factory.test.e2e_test.common import ParseAutomationMode
47from cros.factory.test.env import paths
Jon Salz83591782012-06-26 11:09:58 +080048from cros.factory.test.event import Event
49from cros.factory.test.event import EventClient
50from cros.factory.test.event import EventServer
Hung-Te Linb6287242016-05-18 14:39:05 +080051from cros.factory.test import event_log
52from cros.factory.test.event_log import EventLog
53from cros.factory.test.event_log import FloatDigit
54from cros.factory.test.event_log import GetBootSequence
Hung-Te Lin91492a12014-11-25 18:56:30 +080055from cros.factory.test.event_log_watcher import EventLogWatcher
Earl Oua3bca122016-10-21 16:00:30 +080056from cros.factory.test import factory
jcliangcd688182012-08-20 21:01:26 +080057from cros.factory.test.factory import TestState
Hung-Te Lin3f096842016-01-13 17:37:06 +080058from cros.factory.test.rules import phase
Earl Oua3bca122016-10-21 16:00:30 +080059from cros.factory.test import shopfloor
60from cros.factory.test import state
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +080061from cros.factory.test.test_lists import test_lists
Earl Oua3bca122016-10-21 16:00:30 +080062from cros.factory.test import testlog
63from cros.factory.test import testlog_goofy
Hung-Te Linc367ac02015-12-22 19:33:23 +080064from cros.factory.test.utils.charge_manager import ChargeManager
65from cros.factory.test.utils.core_dump_manager import CoreDumpManager
66from cros.factory.test.utils.cpufreq_manager import CpufreqManager
Hung-Te Lind3ee0102015-12-28 17:21:50 +080067from cros.factory.tools import disk_space
Hung-Te Linb6287242016-05-18 14:39:05 +080068from cros.factory.tools.key_filter import KeyFilter
Hung-Te Linf707b242016-01-08 23:11:42 +080069from cros.factory.utils import debug_utils
Jon Salz2af235d2013-06-24 14:47:21 +080070from cros.factory.utils import file_utils
Joel Kitchingb85ed7f2014-10-08 18:24:39 +080071from cros.factory.utils import net_utils
Hung-Te Lin4e6357c2016-01-08 14:32:00 +080072from cros.factory.utils import process_utils
73from cros.factory.utils import sys_utils
74from cros.factory.utils import time_utils
Hung-Te Linf707b242016-01-08 23:11:42 +080075from cros.factory.utils import type_utils
Hung-Te Linf2f78f72012-02-08 19:27:11 +080076
77
Hung-Te Linf2f78f72012-02-08 19:27:11 +080078HWID_CFG_PATH = '/usr/local/share/chromeos-hwid/cfg'
Joel Kitching625ff0f2016-05-16 14:59:40 -070079CACHES_DIR = os.path.join(paths.GetStateRoot(), 'caches')
Hung-Te Linf2f78f72012-02-08 19:27:11 +080080
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +080081CLEANUP_LOGS_PAUSED = '/var/lib/cleanup_logs_paused'
82
Jon Salz5c344f62012-07-13 14:31:16 +080083# Value for tests_after_shutdown that forces auto-run (e.g., after
84# a factory update, when the available set of tests might change).
85FORCE_AUTO_RUN = 'force_auto_run'
86
Justin Chuang83813982013-05-13 01:26:32 +080087# Sync disks when battery level is higher than this value.
88# Otherwise, power loss during disk sync operation may incur even worse outcome.
89MIN_BATTERY_LEVEL_FOR_DISK_SYNC = 1.0
90
Ricky Liang45c73e72015-01-15 15:00:30 +080091MAX_CRASH_FILE_SIZE = 64 * 1024
Jon Salze12c2b32013-06-25 16:24:34 +080092
Hung-Te Linf707b242016-01-08 23:11:42 +080093Status = type_utils.Enum(['UNINITIALIZED', 'INITIALIZING', 'RUNNING',
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +080094 'TERMINATING', 'TERMINATED'])
Jon Salzd7550792013-07-12 05:49:27 +080095
Ricky Liang45c73e72015-01-15 15:00:30 +080096
Hung-Te Linf2f78f72012-02-08 19:27:11 +080097def get_hwid_cfg():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +080098 """Returns the HWID config tag, or an empty string if none can be found."""
Jon Salz0697cbf2012-07-04 15:14:04 +080099 if 'CROS_HWID' in os.environ:
100 return os.environ['CROS_HWID']
101 if os.path.exists(HWID_CFG_PATH):
Ricky Liang45c73e72015-01-15 15:00:30 +0800102 with open(HWID_CFG_PATH, 'r') as hwid_cfg_handle:
Jon Salz0697cbf2012-07-04 15:14:04 +0800103 return hwid_cfg_handle.read().strip()
104 return ''
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800105
106
Jon Salz73e0fd02012-04-04 11:46:38 +0800107_inited_logging = False
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800108
Ricky Liang45c73e72015-01-15 15:00:30 +0800109
Peter Ammon1e1ec572014-06-26 17:56:32 -0700110class Goofy(GoofyBase):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800111 """The main factory flow.
Jon Salz0697cbf2012-07-04 15:14:04 +0800112
113 Note that all methods in this class must be invoked from the main
114 (event) thread. Other threads, such as callbacks and TestInvocation
115 methods, should instead post events on the run queue.
116
117 TODO: Unit tests. (chrome-os-partner:7409)
118
119 Properties:
120 uuid: A unique UUID for this invocation of Goofy.
121 state_instance: An instance of FactoryState.
122 state_server: The FactoryState XML/RPC server.
123 state_server_thread: A thread running state_server.
124 event_server: The EventServer socket server.
125 event_server_thread: A thread running event_server.
126 event_client: A client to the event server.
127 connection_manager: The connection_manager object.
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800128 system_log_manager: The SystemLogManager object.
129 core_dump_manager: The CoreDumpManager object.
Earl Oua3bca122016-10-21 16:00:30 +0800130 plugin_controller: The PluginController object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800131 ui_process: The factory ui process object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800132 invocations: A map from FactoryTest objects to the corresponding
133 TestInvocations objects representing active tests.
134 tests_to_run: A deque of tests that should be run when the current
135 test(s) complete.
136 options: Command-line options.
137 args: Command-line args.
138 test_list: The test list.
Jon Salz128b0932013-07-03 16:55:26 +0800139 test_lists: All new-style test lists.
Ricky Liang4bff3e32014-02-20 18:46:11 +0800140 run_id: The identifier for latest test run.
141 scheduled_run_tests: The list of tests scheduled for latest test run.
Jon Salz0697cbf2012-07-04 15:14:04 +0800142 event_handlers: Map of Event.Type to the method used to handle that
143 event. If the method has an 'event' argument, the event is passed
144 to the handler.
Jon Salz3c493bb2013-02-07 17:24:58 +0800145 last_log_disk_space_message: The last message we logged about disk space
146 (to avoid duplication).
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800147 last_kick_sync_time: The last time to kick system_log_manager to sync
148 because of core dump files (to avoid kicking too soon then abort the
149 sync.)
Jon Salz416f9cc2013-05-10 18:32:50 +0800150 hooks: A Hooks object containing hooks for various Goofy actions.
Jon Salzd7550792013-07-12 05:49:27 +0800151 status: The current Goofy status (a member of the Status enum).
Peter Ammon948b7172014-07-15 12:43:06 -0700152 link_manager: Instance of PresenterLinkManager for communicating
153 with GoofyPresenter
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800154 """
Ricky Liang45c73e72015-01-15 15:00:30 +0800155
Jon Salz0697cbf2012-07-04 15:14:04 +0800156 def __init__(self):
Peter Ammon1e1ec572014-06-26 17:56:32 -0700157 super(Goofy, self).__init__()
Jon Salz0697cbf2012-07-04 15:14:04 +0800158 self.uuid = str(uuid.uuid4())
159 self.state_instance = None
160 self.state_server = None
161 self.state_server_thread = None
Jon Salz16d10542012-07-23 12:18:45 +0800162 self.goofy_rpc = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800163 self.event_server = None
164 self.event_server_thread = None
165 self.event_client = None
166 self.connection_manager = None
Vic Yang4953fc12012-07-26 16:19:53 +0800167 self.charge_manager = None
Dean Liao88b93192014-10-23 19:37:41 +0800168 self._can_charge = True
Jon Salz8fa8e832012-07-13 19:04:09 +0800169 self.time_sanitizer = None
170 self.time_synced = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800171 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800172 self.system_log_manager = None
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800173 self.core_dump_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800174 self.event_log = None
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +0800175 self.testlog = None
Vic Yange2c76a82014-10-30 12:48:19 -0700176 self.autotest_prespawner = None
Earl Oua3bca122016-10-21 16:00:30 +0800177 self.plugin_controller = None
Vic Yange2c76a82014-10-30 12:48:19 -0700178 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800179 self.ui_process = None
Vic Yanga3cecf82014-12-26 00:44:21 -0800180 self._ui_initialized = False
Jon Salzc79a9982012-08-30 04:42:01 +0800181 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800182 self.invocations = {}
183 self.tests_to_run = deque()
184 self.visible_test = None
185 self.chrome = None
Jon Salz416f9cc2013-05-10 18:32:50 +0800186 self.hooks = None
Vic Yangd8990da2013-06-27 16:57:43 +0800187 self.cpu_usage_watcher = None
Hung-Te Lin23cb7612016-01-19 19:19:32 +0800188 self.thermal_watcher = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800189
190 self.options = None
191 self.args = None
192 self.test_list = None
Jon Salz128b0932013-07-03 16:55:26 +0800193 self.test_lists = None
Ricky Liang4bff3e32014-02-20 18:46:11 +0800194 self.run_id = None
195 self.scheduled_run_tests = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800196 self.env = None
Jon Salzb22d1172012-08-06 10:38:57 +0800197 self.last_idle = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800198 self.last_shutdown_time = None
cychiang21886742012-07-05 15:16:32 +0800199 self.last_update_check = None
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800200 self._suppress_periodic_update_messages = False
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +0800201 self._suppress_event_log_error_messages = False
Jon Salz8fa8e832012-07-13 19:04:09 +0800202 self.last_sync_time = None
Jon Salzb92c5112012-09-21 15:40:11 +0800203 self.last_log_disk_space_time = None
Jon Salz3c493bb2013-02-07 17:24:58 +0800204 self.last_log_disk_space_message = None
Justin Chuang83813982013-05-13 01:26:32 +0800205 self.last_check_battery_time = None
206 self.last_check_battery_message = None
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800207 self.last_kick_sync_time = None
Vic Yang311ddb82012-09-26 12:08:28 +0800208 self.exclusive_items = set()
Dean Liao592e4d52013-01-10 20:06:39 +0800209 self.key_filter = None
Jon Salzce6a7f82013-06-10 18:22:54 +0800210 self.cpufreq_manager = None
Jon Salzd7550792013-07-12 05:49:27 +0800211 self.status = Status.UNINITIALIZED
Ricky Liang36512a32014-07-25 11:47:04 +0800212 self.ready_for_ui_connection = False
Peter Ammon1e1ec572014-06-26 17:56:32 -0700213 self.link_manager = None
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800214 self.is_restart_requested = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800215
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800216 # TODO(hungte) Support controlling remote DUT.
Hung-Te Linb6287242016-05-18 14:39:05 +0800217 self.dut = device_utils.CreateDUTInterface()
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800218
Jon Salz85a39882012-07-05 16:45:04 +0800219 def test_or_root(event, parent_or_group=True):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800220 """Returns the test affected by a particular event.
Jon Salz85a39882012-07-05 16:45:04 +0800221
222 Args:
223 event: The event containing an optional 'path' attribute.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800224 parent_or_group: If True, returns the top-level parent for a test (the
Jon Salz85a39882012-07-05 16:45:04 +0800225 root node of the tests that need to be run together if the given test
226 path is to be run).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800227 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800228 try:
229 path = event.path
230 except AttributeError:
231 path = None
232
233 if path:
Jon Salz85a39882012-07-05 16:45:04 +0800234 test = self.test_list.lookup_path(path)
235 if parent_or_group:
236 test = test.get_top_level_parent_or_group()
237 return test
Jon Salz0697cbf2012-07-04 15:14:04 +0800238 else:
239 return self.test_list
240
241 self.event_handlers = {
Ricky Liang45c73e72015-01-15 15:00:30 +0800242 Event.Type.SWITCH_TEST: self.handle_switch_test,
Ricky Liang45c73e72015-01-15 15:00:30 +0800243 Event.Type.RESTART_TESTS:
244 lambda event: self.restart_tests(root=test_or_root(event)),
245 Event.Type.AUTO_RUN:
246 lambda event: self.auto_run(root=test_or_root(event)),
Ricky Liang45c73e72015-01-15 15:00:30 +0800247 Event.Type.RUN_TESTS_WITH_STATUS:
248 lambda event: self.run_tests_with_status(
249 event.status,
250 root=test_or_root(event)),
Ricky Liang45c73e72015-01-15 15:00:30 +0800251 Event.Type.UPDATE_SYSTEM_INFO:
252 lambda event: self.update_system_info(),
253 Event.Type.STOP:
254 lambda event: self.stop(root=test_or_root(event, False),
255 fail=getattr(event, 'fail', False),
256 reason=getattr(event, 'reason', None)),
257 Event.Type.SET_VISIBLE_TEST:
258 lambda event: self.set_visible_test(
259 self.test_list.lookup_path(event.path)),
260 Event.Type.CLEAR_STATE:
261 lambda event: self.clear_state(
262 self.test_list.lookup_path(event.path)),
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800263 Event.Type.KEY_FILTER_MODE: self.handle_key_filter_mode,
Jon Salz0697cbf2012-07-04 15:14:04 +0800264 }
265
Jon Salz0697cbf2012-07-04 15:14:04 +0800266 self.web_socket_manager = None
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800267 self.terminal_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800268
269 def destroy(self):
Ricky Liang74237a02014-09-18 15:11:23 +0800270 """Performs any shutdown tasks. Overrides base class method."""
Jon Salzd7550792013-07-12 05:49:27 +0800271 self.status = Status.TERMINATING
Jon Salz0697cbf2012-07-04 15:14:04 +0800272 if self.chrome:
273 self.chrome.kill()
274 self.chrome = None
Jon Salzc79a9982012-08-30 04:42:01 +0800275 if self.dummy_shopfloor:
276 self.dummy_shopfloor.kill()
277 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800278 if self.ui_process:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800279 process_utils.KillProcessTree(self.ui_process, 'ui')
Jon Salz0697cbf2012-07-04 15:14:04 +0800280 self.ui_process = None
281 if self.web_socket_manager:
282 logging.info('Stopping web sockets')
283 self.web_socket_manager.close()
284 self.web_socket_manager = None
285 if self.state_server_thread:
286 logging.info('Stopping state server')
287 self.state_server.shutdown()
288 self.state_server_thread.join()
289 self.state_server.server_close()
290 self.state_server_thread = None
291 if self.state_instance:
292 self.state_instance.close()
293 if self.event_server_thread:
294 logging.info('Stopping event server')
295 self.event_server.shutdown() # pylint: disable=E1101
296 self.event_server_thread.join()
297 self.event_server.server_close()
298 self.event_server_thread = None
299 if self.log_watcher:
300 if self.log_watcher.IsThreadStarted():
301 self.log_watcher.StopWatchThread()
302 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800303 if self.system_log_manager:
304 if self.system_log_manager.IsThreadRunning():
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +0800305 self.system_log_manager.Stop()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800306 self.system_log_manager = None
Vic Yange2c76a82014-10-30 12:48:19 -0700307 if self.autotest_prespawner:
308 logging.info('Stopping autotest prespawner')
309 self.autotest_prespawner.stop()
310 self.autotest_prespawner = None
311 if self.pytest_prespawner:
312 logging.info('Stopping pytest prespawner')
313 self.pytest_prespawner.stop()
314 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800315 if self.event_client:
316 logging.info('Closing event client')
317 self.event_client.close()
318 self.event_client = None
Jon Salzddf0d052013-06-18 12:52:44 +0800319 if self.cpufreq_manager:
320 self.cpufreq_manager.Stop()
Jon Salz0697cbf2012-07-04 15:14:04 +0800321 if self.event_log:
322 self.event_log.Close()
323 self.event_log = None
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +0800324 if self.testlog:
325 self.testlog.Close()
326 self.testlog = None
Dean Liao592e4d52013-01-10 20:06:39 +0800327 if self.key_filter:
328 self.key_filter.Stop()
Vic Yangd8990da2013-06-27 16:57:43 +0800329 if self.cpu_usage_watcher:
330 self.cpu_usage_watcher.terminate()
Hung-Te Lin23cb7612016-01-19 19:19:32 +0800331 if self.thermal_watcher:
332 self.thermal_watcher.terminate()
Peter Ammon1e1ec572014-06-26 17:56:32 -0700333 if self.link_manager:
334 self.link_manager.Stop()
335 self.link_manager = None
Earl Oua3bca122016-10-21 16:00:30 +0800336 if self.plugin_controller:
337 self.plugin_controller.StopAndDestroyAllPlugins()
338 self.plugin_controller = None
Dean Liao592e4d52013-01-10 20:06:39 +0800339
Peter Ammon1e1ec572014-06-26 17:56:32 -0700340 super(Goofy, self).destroy()
Jon Salz0697cbf2012-07-04 15:14:04 +0800341 logging.info('Done destroying Goofy')
Jon Salzd7550792013-07-12 05:49:27 +0800342 self.status = Status.TERMINATED
Jon Salz0697cbf2012-07-04 15:14:04 +0800343
344 def start_state_server(self):
Jon Salz2af235d2013-06-24 14:47:21 +0800345 # Before starting state server, remount stateful partitions with
346 # no commit flag. The default commit time (commit=600) makes corruption
347 # too likely.
Hung-Te Lin1968d9c2016-01-08 22:55:46 +0800348 sys_utils.ResetCommitTime()
Jon Salz2af235d2013-06-24 14:47:21 +0800349
Jon Salz0697cbf2012-07-04 15:14:04 +0800350 self.state_instance, self.state_server = (
Ricky Liang45c73e72015-01-15 15:00:30 +0800351 state.create_server(bind_address='0.0.0.0'))
Jon Salz16d10542012-07-23 12:18:45 +0800352 self.goofy_rpc = GoofyRPC(self)
353 self.goofy_rpc.RegisterMethods(self.state_instance)
Jon Salz0697cbf2012-07-04 15:14:04 +0800354 logging.info('Starting state server')
355 self.state_server_thread = threading.Thread(
Ricky Liang45c73e72015-01-15 15:00:30 +0800356 target=self.state_server.serve_forever,
357 name='StateServer')
Jon Salz0697cbf2012-07-04 15:14:04 +0800358 self.state_server_thread.start()
359
360 def start_event_server(self):
361 self.event_server = EventServer()
362 logging.info('Starting factory event server')
363 self.event_server_thread = threading.Thread(
Ricky Liang45c73e72015-01-15 15:00:30 +0800364 target=self.event_server.serve_forever,
365 name='EventServer') # pylint: disable=E1101
Jon Salz0697cbf2012-07-04 15:14:04 +0800366 self.event_server_thread.start()
367
368 self.event_client = EventClient(
Ricky Liang45c73e72015-01-15 15:00:30 +0800369 callback=self.handle_event, event_loop=self.run_queue)
Jon Salz0697cbf2012-07-04 15:14:04 +0800370
371 self.web_socket_manager = WebSocketManager(self.uuid)
Ricky Liang45c73e72015-01-15 15:00:30 +0800372 self.state_server.add_handler('/event',
373 self.web_socket_manager.handle_web_socket)
Jon Salz0697cbf2012-07-04 15:14:04 +0800374
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800375 def start_terminal_server(self):
376 self.terminal_manager = TerminalManager()
377 self.state_server.add_handler('/pty',
378 self.terminal_manager.handle_web_socket)
379
Jon Salz0697cbf2012-07-04 15:14:04 +0800380 def start_ui(self):
381 ui_proc_args = [
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +0800382 os.path.join(paths.FACTORY_PACKAGE_PATH, 'test', 'ui.py'),
Ricky Liang45c73e72015-01-15 15:00:30 +0800383 self.options.test_list
384 ]
Jon Salz0697cbf2012-07-04 15:14:04 +0800385 if self.options.verbose:
386 ui_proc_args.append('-v')
387 logging.info('Starting ui %s', ui_proc_args)
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800388 self.ui_process = process_utils.Spawn(ui_proc_args)
Jon Salz0697cbf2012-07-04 15:14:04 +0800389 logging.info('Waiting for UI to come up...')
390 self.event_client.wait(
Ricky Liang45c73e72015-01-15 15:00:30 +0800391 lambda event: event.type == Event.Type.UI_READY)
Jon Salz0697cbf2012-07-04 15:14:04 +0800392 logging.info('UI has started')
393
394 def set_visible_test(self, test):
395 if self.visible_test == test:
396 return
Jon Salz2f2d42c2012-07-30 12:30:34 +0800397 if test and not test.has_ui:
398 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800399
400 if test:
401 test.update_state(visible=True)
402 if self.visible_test:
403 self.visible_test.update_state(visible=False)
404 self.visible_test = test
405
Ricky Liang48e47f92014-02-26 19:31:51 +0800406 def log_startup_messages(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800407 """Logs the tail of var/log/messages and mosys and EC console logs."""
Jon Salzd4306c82012-11-30 15:16:36 +0800408 # TODO(jsalz): This is mostly a copy-and-paste of code in init_states,
409 # for factory-3004.B only. Consolidate and merge back to ToT.
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800410 if sys_utils.InChroot():
Jon Salzd4306c82012-11-30 15:16:36 +0800411 return
412
413 try:
Hung-Te Lin1a4e30c2016-01-08 23:25:10 +0800414 var_log_messages = sys_utils.GetVarLogMessagesBeforeReboot()
Jon Salzd4306c82012-11-30 15:16:36 +0800415 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +0800416 'Tail of /var/log/messages before last reboot:\n'
417 '%s', ('\n'.join(
418 ' ' + x for x in var_log_messages)))
Jon Salzd4306c82012-11-30 15:16:36 +0800419 except: # pylint: disable=W0702
420 logging.exception('Unable to grok /var/log/messages')
421
422 try:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800423 mosys_log = process_utils.Spawn(
Jon Salzd4306c82012-11-30 15:16:36 +0800424 ['mosys', 'eventlog', 'list'],
425 read_stdout=True, log_stderr_on_error=True).stdout_data
426 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
427 except: # pylint: disable=W0702
428 logging.exception('Unable to read mosys eventlog')
429
Dean Liao88b93192014-10-23 19:37:41 +0800430 self.log_ec_console()
431 self.log_ec_panic_info()
432
433 @staticmethod
434 def log_ec_console():
435 """Logs EC console log into logging.info.
436
437 It logs an error message in logging.exception if an exception is raised
438 when getting EC console log.
439 For unsupported device, it logs unsupport message in logging.info
440
441 Returns:
442 EC console log string.
443 """
Jon Salzd4306c82012-11-30 15:16:36 +0800444 try:
Hung-Te Linb6287242016-05-18 14:39:05 +0800445 ec_console_log = device_utils.CreateDUTInterface().ec.GetECConsoleLog()
Jon Salzd4306c82012-11-30 15:16:36 +0800446 logging.info('EC console log after reboot:\n%s\n', ec_console_log)
Dean Liao88b93192014-10-23 19:37:41 +0800447 return ec_console_log
448 except NotImplementedError:
449 logging.info('EC console log not supported')
Jon Salzd4306c82012-11-30 15:16:36 +0800450 except: # pylint: disable=W0702
451 logging.exception('Error retrieving EC console log')
452
Dean Liao88b93192014-10-23 19:37:41 +0800453 @staticmethod
454 def log_ec_panic_info():
455 """Logs EC panic info into logging.info.
456
457 It logs an error message in logging.exception if an exception is raised
458 when getting EC panic info.
459 For unsupported device, it logs unsupport message in logging.info
460
461 Returns:
462 EC panic info string.
463 """
Vic Yang079f9872013-07-01 11:32:00 +0800464 try:
Hung-Te Linb6287242016-05-18 14:39:05 +0800465 ec_panic_info = device_utils.CreateDUTInterface().ec.GetECPanicInfo()
Vic Yang079f9872013-07-01 11:32:00 +0800466 logging.info('EC panic info after reboot:\n%s\n', ec_panic_info)
Dean Liao88b93192014-10-23 19:37:41 +0800467 return ec_panic_info
468 except NotImplementedError:
469 logging.info('EC panic info is not supported')
Vic Yang079f9872013-07-01 11:32:00 +0800470 except: # pylint: disable=W0702
471 logging.exception('Error retrieving EC panic info')
472
Ricky Liang48e47f92014-02-26 19:31:51 +0800473 def shutdown(self, operation):
474 """Starts shutdown procedure.
475
476 Args:
Vic (Chun-Ju) Yang05b0d952014-04-28 17:39:09 +0800477 operation: The shutdown operation (reboot, full_reboot, or halt).
Ricky Liang48e47f92014-02-26 19:31:51 +0800478 """
479 active_tests = []
480 for test in self.test_list.walk():
481 if not test.is_leaf():
482 continue
483
484 test_state = test.get_state()
485 if test_state.status == TestState.ACTIVE:
486 active_tests.append(test)
487
Ricky Liang48e47f92014-02-26 19:31:51 +0800488 if not (len(active_tests) == 1 and
489 isinstance(active_tests[0], factory.ShutdownStep)):
490 logging.error(
491 'Calling Goofy shutdown outside of the shutdown factory test')
492 return
493
494 logging.info('Start Goofy shutdown (%s)', operation)
495 # Save pending test list in the state server
496 self.state_instance.set_shared_data(
497 'tests_after_shutdown',
498 [t.path for t in self.tests_to_run])
499 # Save shutdown time
500 self.state_instance.set_shared_data('shutdown_time', time.time())
501
502 with self.env.lock:
503 self.event_log.Log('shutdown', operation=operation)
504 shutdown_result = self.env.shutdown(operation)
505 if shutdown_result:
506 # That's all, folks!
Peter Ammon1e1ec572014-06-26 17:56:32 -0700507 self.run_enqueue(None)
Ricky Liang48e47f92014-02-26 19:31:51 +0800508 else:
509 # Just pass (e.g., in the chroot).
510 self.state_instance.set_shared_data('tests_after_shutdown', None)
511 # Send event with no fields to indicate that there is no
512 # longer a pending shutdown.
513 self.event_client.post_event(Event(Event.Type.PENDING_SHUTDOWN))
514
515 def handle_shutdown_complete(self, test):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800516 """Handles the case where a shutdown was detected during a shutdown step.
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800517
Ricky Liang6fe218c2013-12-27 15:17:17 +0800518 Args:
519 test: The ShutdownStep.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800520 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800521 test_state = test.update_state(increment_shutdown_count=1)
522 logging.info('Detected shutdown (%d of %d)',
Ricky Liang48e47f92014-02-26 19:31:51 +0800523 test_state.shutdown_count, test.iterations)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800524
Ricky Liang48e47f92014-02-26 19:31:51 +0800525 # Insert current shutdown test at the front of the list of tests to run
526 # after shutdown. This is to continue on post-shutdown verification in the
527 # shutdown step.
528 tests_after_shutdown = self.state_instance.get_shared_data(
529 'tests_after_shutdown', optional=True)
530 if not tests_after_shutdown:
531 self.state_instance.set_shared_data('tests_after_shutdown', [test.path])
532 elif isinstance(tests_after_shutdown, list):
533 self.state_instance.set_shared_data(
534 'tests_after_shutdown', [test.path] + tests_after_shutdown)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800535
Ricky Liang48e47f92014-02-26 19:31:51 +0800536 # Set 'post_shutdown' to inform shutdown test that a shutdown just occurred.
Ricky Liangb7eb8772014-09-15 18:05:22 +0800537 self.state_instance.set_shared_data(
538 state.POST_SHUTDOWN_TAG % test.path,
539 self.state_instance.get_test_state(test.path).invocation)
Jon Salz258a40c2012-04-19 12:34:01 +0800540
Jon Salz0697cbf2012-07-04 15:14:04 +0800541 def init_states(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800542 """Initializes all states on startup."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800543 for test in self.test_list.get_all_tests():
544 # Make sure the state server knows about all the tests,
545 # defaulting to an untested state.
546 test.update_state(update_parent=False, visible=False)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800547
Jon Salz0697cbf2012-07-04 15:14:04 +0800548 var_log_messages = None
Vic Yanga9c32212012-08-16 20:07:54 +0800549 mosys_log = None
Vic Yange4c275d2012-08-28 01:50:20 +0800550 ec_console_log = None
Vic Yang079f9872013-07-01 11:32:00 +0800551 ec_panic_info = None
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800552
Jon Salz0697cbf2012-07-04 15:14:04 +0800553 # Any 'active' tests should be marked as failed now.
554 for test in self.test_list.walk():
Jon Salza6711d72012-07-18 14:33:03 +0800555 if not test.is_leaf():
556 # Don't bother with parents; they will be updated when their
557 # children are updated.
558 continue
559
Jon Salz0697cbf2012-07-04 15:14:04 +0800560 test_state = test.get_state()
561 if test_state.status != TestState.ACTIVE:
562 continue
563 if isinstance(test, factory.ShutdownStep):
564 # Shutdown while the test was active - that's good.
Ricky Liang48e47f92014-02-26 19:31:51 +0800565 self.handle_shutdown_complete(test)
Jon Salz0697cbf2012-07-04 15:14:04 +0800566 else:
567 # Unexpected shutdown. Grab /var/log/messages for context.
568 if var_log_messages is None:
569 try:
570 var_log_messages = (
Hung-Te Lin1a4e30c2016-01-08 23:25:10 +0800571 sys_utils.GetVarLogMessagesBeforeReboot())
Jon Salz0697cbf2012-07-04 15:14:04 +0800572 # Write it to the log, to make it easier to
573 # correlate with /var/log/messages.
574 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +0800575 'Unexpected shutdown. '
576 'Tail of /var/log/messages before last reboot:\n'
577 '%s', ('\n'.join(
578 ' ' + x for x in var_log_messages)))
Jon Salz0697cbf2012-07-04 15:14:04 +0800579 except: # pylint: disable=W0702
580 logging.exception('Unable to grok /var/log/messages')
581 var_log_messages = []
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800582
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800583 if mosys_log is None and not sys_utils.InChroot():
Jon Salz008f4ea2012-08-28 05:39:45 +0800584 try:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800585 mosys_log = process_utils.Spawn(
Jon Salz008f4ea2012-08-28 05:39:45 +0800586 ['mosys', 'eventlog', 'list'],
587 read_stdout=True, log_stderr_on_error=True).stdout_data
588 # Write it to the log also.
589 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
590 except: # pylint: disable=W0702
591 logging.exception('Unable to read mosys eventlog')
Vic Yanga9c32212012-08-16 20:07:54 +0800592
Vic Yange4c275d2012-08-28 01:50:20 +0800593 if ec_console_log is None:
Dean Liao88b93192014-10-23 19:37:41 +0800594 ec_console_log = self.log_ec_console()
Vic Yange4c275d2012-08-28 01:50:20 +0800595
Vic Yang079f9872013-07-01 11:32:00 +0800596 if ec_panic_info is None:
Dean Liao88b93192014-10-23 19:37:41 +0800597 ec_panic_info = self.log_ec_panic_info()
Vic Yang079f9872013-07-01 11:32:00 +0800598
Jon Salz0697cbf2012-07-04 15:14:04 +0800599 error_msg = 'Unexpected shutdown while test was running'
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +0800600 # TODO(itspeter): Add testlog to collect expired session infos.
Jon Salz0697cbf2012-07-04 15:14:04 +0800601 self.event_log.Log('end_test',
Ricky Liang45c73e72015-01-15 15:00:30 +0800602 path=test.path,
603 status=TestState.FAILED,
604 invocation=test.get_state().invocation,
605 error_msg=error_msg,
606 var_log_messages='\n'.join(var_log_messages),
607 mosys_log=mosys_log)
Jon Salz0697cbf2012-07-04 15:14:04 +0800608 test.update_state(
Ricky Liang45c73e72015-01-15 15:00:30 +0800609 status=TestState.FAILED,
610 error_msg=error_msg)
Chun-Ta Lin87c2dac2015-05-02 01:35:01 -0700611 # Trigger the OnTestFailure callback.
Claire Changd1961a22015-08-05 16:15:55 +0800612 self.run_queue.put(lambda: self.test_fail(test))
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800613
Jon Salz50efe942012-07-26 11:54:10 +0800614 if not test.never_fails:
615 # For "never_fails" tests (such as "Start"), don't cancel
616 # pending tests, since reboot is expected.
617 factory.console.info('Unexpected shutdown while test %s '
618 'running; cancelling any pending tests',
619 test.path)
620 self.state_instance.set_shared_data('tests_after_shutdown', [])
Jon Salz69806bb2012-07-20 18:05:02 +0800621
Jon Salz008f4ea2012-08-28 05:39:45 +0800622 self.update_skipped_tests()
623
624 def update_skipped_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800625 """Updates skipped states based on run_if."""
Jon Salz885dcac2013-07-23 16:39:50 +0800626 env = TestArgEnv()
Ricky Liang45c73e72015-01-15 15:00:30 +0800627
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800628 def _evaluate_skip_from_run_if(test):
629 """Returns the run_if evaluation of the test.
630
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800631 Evaluates test's run_if argument to decide skipping the test or not. If
632 run_if argument is not set, the test will never be skipped.
633
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800634 Args:
635 test: A FactoryTest object.
636
637 Returns:
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800638 True if this test should be skipped, otherwise False.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800639 """
640 value = None
641 if test.run_if_expr:
642 try:
643 value = test.run_if_expr(env)
644 except: # pylint: disable=W0702
645 logging.exception('Unable to evaluate run_if expression for %s',
646 test.path)
647 # But keep going; we have no choice. This will end up
648 # always activating the test.
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800649 return False
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800650 elif test.run_if_table_name:
651 try:
652 aux = shopfloor.get_selected_aux_data(test.run_if_table_name)
653 value = aux.get(test.run_if_col)
654 except ValueError:
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800655 # Cannot find corresponding value, use default value (None)
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800656 pass
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800657 else: # run_if is not set
658 return False
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800659
Wei-Han Chen7f3877d2016-10-07 22:41:27 +0800660 return (not value) ^ t.run_if_not
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800661
662 # Gets all run_if evaluation, and stores results in skip_map.
663 skip_map = dict()
Jon Salz008f4ea2012-08-28 05:39:45 +0800664 for t in self.test_list.walk():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800665 skip_map[t.path] = _evaluate_skip_from_run_if(t)
Jon Salz885dcac2013-07-23 16:39:50 +0800666
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800667 # Propagates the skip value from root of tree and updates skip_map.
668 def _update_skip_map_from_node(test, skip_from_parent):
669 """Updates skip_map from a given node.
Jon Salz885dcac2013-07-23 16:39:50 +0800670
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800671 Given a FactoryTest node and the skip value from parent, updates the
672 skip value of current node in the skip_map if skip value from parent is
673 True. If this node has children, recursively propagate this value to all
674 its children, that is, all its subtests.
675 Note that this function only updates value in skip_map, not the actual
676 test_list tree.
Jon Salz008f4ea2012-08-28 05:39:45 +0800677
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800678 Args:
679 test: The given FactoryTest object. It is a node in the test_list tree.
680 skip_from_parent: The skip value which propagates from the parent of
681 input node.
682 """
683 skip_this_tree = skip_from_parent or skip_map[test.path]
684 if skip_this_tree:
685 logging.info('Skip from node %r', test.path)
686 skip_map[test.path] = True
687 if test.is_leaf():
688 return
689 # Propagates skip value to its subtests
690 for subtest in test.subtests:
691 _update_skip_map_from_node(subtest, skip_this_tree)
692
693 _update_skip_map_from_node(self.test_list, False)
694
695 # Updates the skip value from skip_map to test_list tree. Also, updates test
696 # status if needed.
697 for t in self.test_list.walk():
698 skip = skip_map[t.path]
699 test_state = t.get_state()
700 if ((not skip) and
701 (test_state.status == TestState.PASSED) and
702 (test_state.error_msg == TestState.SKIPPED_MSG)):
703 # It was marked as skipped before, but now we need to run it.
704 # Mark as untested.
705 t.update_state(skip=skip, status=TestState.UNTESTED, error_msg='')
706 else:
707 t.update_state(skip=skip)
Jon Salz008f4ea2012-08-28 05:39:45 +0800708
Jon Salz0697cbf2012-07-04 15:14:04 +0800709 def handle_event(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800710 """Handles an event from the event server."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800711 handler = self.event_handlers.get(event.type)
712 if handler:
713 handler(event)
714 else:
715 # We don't register handlers for all event types - just ignore
716 # this event.
717 logging.debug('Unbound event type %s', event.type)
Jon Salz4f6c7172012-06-11 20:45:36 +0800718
Vic Yangaabf9fd2013-04-09 18:56:13 +0800719 def check_critical_factory_note(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800720 """Returns True if the last factory note is critical."""
Vic Yangaabf9fd2013-04-09 18:56:13 +0800721 notes = self.state_instance.get_shared_data('factory_note', True)
722 return notes and notes[-1]['level'] == 'CRITICAL'
723
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800724 def schedule_restart(self):
725 """Schedules a restart event when any invocation is completed."""
726 self.is_restart_requested = True
727
728 def invocation_completion(self):
729 """Callback when an invocation is completed."""
730 if self.is_restart_requested:
731 logging.info('Restart by scheduled event.')
732 self.is_restart_requested = False
733 self.restart_tests()
734 else:
735 self.run_next_test()
736
Jon Salz0697cbf2012-07-04 15:14:04 +0800737 def run_next_test(self):
henryhsu4cc6b022014-04-22 17:12:42 +0800738 """Runs the next eligible test (or tests) in self.tests_to_run.
739
740 We have three kinds of the next eligible test:
741 1. normal
742 2. backgroundable
743 3. force_background
744
745 And we have four situations of the ongoing invocations:
746 a. only a running normal test
747 b. all running tests are backgroundable
748 c. all running tests are force_background
749 d. all running tests are any combination of backgroundable and
750 force_background
751
752 When a test would like to be run, it must follow the rules:
753 [1] cannot run with [abd]
754 [2] cannot run with [a]
755 All the other combinations are allowed
756 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800757 self.reap_completed_tests()
Vic Yangaabf9fd2013-04-09 18:56:13 +0800758 if self.tests_to_run and self.check_critical_factory_note():
759 self.tests_to_run.clear()
760 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800761 while self.tests_to_run:
Ricky Liang6fe218c2013-12-27 15:17:17 +0800762 logging.debug('Tests to run: %s', [x.path for x in self.tests_to_run])
Jon Salz94eb56f2012-06-12 18:01:12 +0800763
Jon Salz0697cbf2012-07-04 15:14:04 +0800764 test = self.tests_to_run[0]
Jon Salz94eb56f2012-06-12 18:01:12 +0800765
Jon Salz0697cbf2012-07-04 15:14:04 +0800766 if test in self.invocations:
767 logging.info('Next test %s is already running', test.path)
768 self.tests_to_run.popleft()
769 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800770
Jon Salza1412922012-07-23 16:04:17 +0800771 for requirement in test.require_run:
772 for i in requirement.test.walk():
773 if i.get_state().status == TestState.ACTIVE:
Jon Salz304a75d2012-07-06 11:14:15 +0800774 logging.info('Waiting for active test %s to complete '
Jon Salza1412922012-07-23 16:04:17 +0800775 'before running %s', i.path, test.path)
Jon Salz304a75d2012-07-06 11:14:15 +0800776 return
777
henryhsu4cc6b022014-04-22 17:12:42 +0800778 def is_normal_test(test):
779 return not (test.backgroundable or test.force_background)
780
781 # [1] cannot run with [abd].
782 if self.invocations and is_normal_test(test) and any(
783 [not x.force_background for x in self.invocations]):
784 logging.info('Waiting for non-force_background tests to '
785 'complete before running %s', test.path)
786 return
787
788 # [2] cannot run with [a].
789 if self.invocations and test.backgroundable and any(
790 [is_normal_test(x) for x in self.invocations]):
791 logging.info('Waiting for normal tests to '
792 'complete before running %s', test.path)
Jon Salz0697cbf2012-07-04 15:14:04 +0800793 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800794
Jon Salz3e6f5202012-10-15 15:08:29 +0800795 if test.get_state().skip:
796 factory.console.info('Skipping test %s', test.path)
797 test.update_state(status=TestState.PASSED,
798 error_msg=TestState.SKIPPED_MSG)
799 self.tests_to_run.popleft()
800 continue
801
Jon Salz0697cbf2012-07-04 15:14:04 +0800802 self.tests_to_run.popleft()
Jon Salz94eb56f2012-06-12 18:01:12 +0800803
Jon Salz304a75d2012-07-06 11:14:15 +0800804 untested = set()
Jon Salza1412922012-07-23 16:04:17 +0800805 for requirement in test.require_run:
806 for i in requirement.test.walk():
807 if i == test:
Jon Salz304a75d2012-07-06 11:14:15 +0800808 # We've hit this test itself; stop checking
809 break
Jon Salza1412922012-07-23 16:04:17 +0800810 if ((i.get_state().status == TestState.UNTESTED) or
811 (requirement.passed and i.get_state().status !=
812 TestState.PASSED)):
Jon Salz304a75d2012-07-06 11:14:15 +0800813 # Found an untested test; move on to the next
814 # element in require_run.
Jon Salza1412922012-07-23 16:04:17 +0800815 untested.add(i)
Jon Salz304a75d2012-07-06 11:14:15 +0800816 break
817
818 if untested:
819 untested_paths = ', '.join(sorted([x.path for x in untested]))
820 if self.state_instance.get_shared_data('engineering_mode',
821 optional=True):
822 # In engineering mode, we'll let it go.
823 factory.console.warn('In engineering mode; running '
824 '%s even though required tests '
825 '[%s] have not completed',
826 test.path, untested_paths)
827 else:
828 # Not in engineering mode; mark it failed.
829 error_msg = ('Required tests [%s] have not been run yet'
830 % untested_paths)
831 factory.console.error('Not running %s: %s',
832 test.path, error_msg)
833 test.update_state(status=TestState.FAILED,
834 error_msg=error_msg)
835 continue
836
Ricky Liang48e47f92014-02-26 19:31:51 +0800837 if (isinstance(test, factory.ShutdownStep) and
Ricky Liangb7eb8772014-09-15 18:05:22 +0800838 self.state_instance.get_shared_data(
839 state.POST_SHUTDOWN_TAG % test.path, optional=True)):
Ricky Liang48e47f92014-02-26 19:31:51 +0800840 # Invoking post shutdown method of shutdown test. We should retain the
841 # iterations_left and retries_left of the original test state.
842 test_state = self.state_instance.get_test_state(test.path)
843 self._run_test(test, test_state.iterations_left,
844 test_state.retries_left)
845 else:
846 # Starts a new test run; reset iterations and retries.
847 self._run_test(test, test.iterations, test.retries)
Jon Salz1acc8742012-07-17 17:45:55 +0800848
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800849 def _run_test(self, test, iterations_left=None, retries_left=None):
Vic Yanga3cecf82014-12-26 00:44:21 -0800850 if not self._ui_initialized and not test.is_no_host():
851 self.init_ui()
Vic Yang08505c72015-01-06 17:01:53 -0800852 invoc = TestInvocation(
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800853 self, test, on_completion=self.invocation_completion,
Claire Changd1961a22015-08-05 16:15:55 +0800854 on_test_failure=lambda: self.test_fail(test))
Jon Salz1acc8742012-07-17 17:45:55 +0800855 new_state = test.update_state(
Ricky Liang48e47f92014-02-26 19:31:51 +0800856 status=TestState.ACTIVE, increment_count=1, error_msg='',
857 invocation=invoc.uuid, iterations_left=iterations_left,
858 retries_left=retries_left,
859 visible=(self.visible_test == test))
Jon Salz1acc8742012-07-17 17:45:55 +0800860 invoc.count = new_state.count
861
862 self.invocations[test] = invoc
863 if self.visible_test is None and test.has_ui:
864 self.set_visible_test(test)
Vic Yang311ddb82012-09-26 12:08:28 +0800865 self.check_exclusive()
Earl Oua3bca122016-10-21 16:00:30 +0800866 self.check_plugins()
Jon Salz1acc8742012-07-17 17:45:55 +0800867 invoc.start()
Jon Salz5f2a0672012-05-22 17:14:06 +0800868
Vic Yang311ddb82012-09-26 12:08:28 +0800869 def check_exclusive(self):
Jon Salzce6a7f82013-06-10 18:22:54 +0800870 # alias since this is really long
871 EXCL_OPT = factory.FactoryTest.EXCLUSIVE_OPTIONS
872
Vic Yang311ddb82012-09-26 12:08:28 +0800873 current_exclusive_items = set([
Jon Salzce6a7f82013-06-10 18:22:54 +0800874 item for item in EXCL_OPT
Vic Yang311ddb82012-09-26 12:08:28 +0800875 if any([test.is_exclusive(item) for test in self.invocations])])
876
877 new_exclusive_items = current_exclusive_items - self.exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800878 if EXCL_OPT.NETWORKING in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800879 logging.info('Disabling network')
880 self.connection_manager.DisableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800881 if EXCL_OPT.CHARGER in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800882 logging.info('Stop controlling charger')
883
884 new_non_exclusive_items = self.exclusive_items - current_exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800885 if EXCL_OPT.NETWORKING in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800886 logging.info('Re-enabling network')
887 self.connection_manager.EnableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800888 if EXCL_OPT.CHARGER in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800889 logging.info('Start controlling charger')
890
Jon Salzce6a7f82013-06-10 18:22:54 +0800891 if self.cpufreq_manager:
892 enabled = EXCL_OPT.CPUFREQ not in current_exclusive_items
893 try:
894 self.cpufreq_manager.SetEnabled(enabled)
895 except: # pylint: disable=W0702
896 logging.exception('Unable to %s cpufreq services',
897 'enable' if enabled else 'disable')
898
Ricky Liang0f9978e2015-01-30 08:19:17 +0000899 # Only adjust charge state if not excluded
900 if (EXCL_OPT.CHARGER not in current_exclusive_items and
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800901 not sys_utils.InChroot()):
Ricky Liang0f9978e2015-01-30 08:19:17 +0000902 if self.charge_manager:
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +0800903 self.charge_manager.AdjustChargeState()
Vic Yang311ddb82012-09-26 12:08:28 +0800904
905 self.exclusive_items = current_exclusive_items
Jon Salz5da61e62012-05-31 13:06:22 +0800906
Earl Oua3bca122016-10-21 16:00:30 +0800907 def check_plugins(self):
908 """Check plugins to be paused or resumed."""
909 exclusive_resources = set()
910 for test in self.invocations:
911 exclusive_resources = exclusive_resources.union(
912 test.get_exclusive_resources())
913 self.plugin_controller.PauseAndResumePluginByResource(exclusive_resources)
914
Dean Liao88b93192014-10-23 19:37:41 +0800915 def charge(self):
916 """Charges the board.
917
918 It won't try again if last time SetChargeState raised an exception.
919 """
920 if not self._can_charge:
921 return
922
923 try:
Ricky Liang9ac35e02015-01-30 16:01:32 +0800924 if self.charge_manager:
925 self.charge_manager.StartCharging()
926 else:
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800927 self.dut.power.SetChargeState(self.dut.power.ChargeState.CHARGE)
Dean Liao88b93192014-10-23 19:37:41 +0800928 except NotImplementedError:
929 logging.info('Charging is not supported')
930 self._can_charge = False
Hung-Te Linb6287242016-05-18 14:39:05 +0800931 except DeviceException:
Dean Liao88b93192014-10-23 19:37:41 +0800932 logging.exception('Unable to set charge state on this board')
933 self._can_charge = False
934
cychiang21886742012-07-05 15:16:32 +0800935 def check_for_updates(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800936 """Schedules an asynchronous check for updates if necessary."""
cychiang21886742012-07-05 15:16:32 +0800937 if not self.test_list.options.update_period_secs:
938 # Not enabled.
939 return
940
941 now = time.time()
942 if self.last_update_check and (
943 now - self.last_update_check <
944 self.test_list.options.update_period_secs):
945 # Not yet time for another check.
946 return
947
948 self.last_update_check = now
949
950 def handle_check_for_update(reached_shopfloor, md5sum, needs_update):
951 if reached_shopfloor:
952 new_update_md5sum = md5sum if needs_update else None
Hung-Te Line594e5d2015-12-16 02:36:05 +0800953 if self.dut.info.update_md5sum != new_update_md5sum:
cychiang21886742012-07-05 15:16:32 +0800954 logging.info('Received new update MD5SUM: %s', new_update_md5sum)
Hung-Te Line594e5d2015-12-16 02:36:05 +0800955 self.dut.info.Overrides('update_md5sum', new_update_md5sum)
Peter Ammon1e1ec572014-06-26 17:56:32 -0700956 self.run_enqueue(self.update_system_info)
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800957 else:
958 if not self._suppress_periodic_update_messages:
959 logging.warning('Suppress error messages for periodic update checking'
960 ' after the first one.')
961 self._suppress_periodic_update_messages = True
cychiang21886742012-07-05 15:16:32 +0800962
963 updater.CheckForUpdateAsync(
Ricky Liang45c73e72015-01-15 15:00:30 +0800964 handle_check_for_update,
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800965 self.test_list.options.shopfloor_timeout_secs,
966 self._suppress_periodic_update_messages)
cychiang21886742012-07-05 15:16:32 +0800967
Jon Salza6711d72012-07-18 14:33:03 +0800968 def cancel_pending_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800969 """Cancels any tests in the run queue."""
Jon Salza6711d72012-07-18 14:33:03 +0800970 self.run_tests([])
971
Ricky Liang4bff3e32014-02-20 18:46:11 +0800972 def restore_active_run_state(self):
973 """Restores active run id and the list of scheduled tests."""
974 self.run_id = self.state_instance.get_shared_data('run_id', optional=True)
975 self.scheduled_run_tests = self.state_instance.get_shared_data(
976 'scheduled_run_tests', optional=True)
977
978 def set_active_run_state(self):
979 """Sets active run id and the list of scheduled tests."""
980 self.run_id = str(uuid.uuid4())
981 self.scheduled_run_tests = [test.path for test in self.tests_to_run]
982 self.state_instance.set_shared_data('run_id', self.run_id)
983 self.state_instance.set_shared_data('scheduled_run_tests',
984 self.scheduled_run_tests)
985
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +0800986 def run_tests(self, subtrees, status_filter=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800987 """Runs tests under subtree.
Jon Salz258a40c2012-04-19 12:34:01 +0800988
Jon Salz0697cbf2012-07-04 15:14:04 +0800989 The tests are run in order unless one fails (then stops).
990 Backgroundable tests are run simultaneously; when a foreground test is
991 encountered, we wait for all active tests to finish before continuing.
Jon Salzb1b39092012-05-03 02:05:09 +0800992
Ricky Liang6fe218c2013-12-27 15:17:17 +0800993 Args:
994 subtrees: Node or nodes containing tests to run (may either be
995 a single test or a list). Duplicates will be ignored.
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +0800996 status_filter: List of available test states. Only run the tests which
997 states are in the list. Set to None if all test states are available.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800998 """
Hung-Te Lin410f70a2015-12-15 14:53:42 +0800999 self.dut.hooks.OnTestStart()
Vic Yang08505c72015-01-06 17:01:53 -08001000
Jon Salz0697cbf2012-07-04 15:14:04 +08001001 if type(subtrees) != list:
1002 subtrees = [subtrees]
Jon Salz258a40c2012-04-19 12:34:01 +08001003
Jon Salz0697cbf2012-07-04 15:14:04 +08001004 # Nodes we've seen so far, to avoid duplicates.
1005 seen = set()
Jon Salz94eb56f2012-06-12 18:01:12 +08001006
Jon Salz0697cbf2012-07-04 15:14:04 +08001007 self.tests_to_run = deque()
1008 for subtree in subtrees:
1009 for test in subtree.walk():
1010 if test in seen:
1011 continue
1012 seen.add(test)
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001013
Jon Salz0697cbf2012-07-04 15:14:04 +08001014 if not test.is_leaf():
1015 continue
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08001016 if (status_filter is not None and
1017 test.get_state().status not in status_filter):
Jon Salz0697cbf2012-07-04 15:14:04 +08001018 continue
1019 self.tests_to_run.append(test)
Ricky Liang4bff3e32014-02-20 18:46:11 +08001020 if subtrees:
1021 self.set_active_run_state()
Jon Salz0697cbf2012-07-04 15:14:04 +08001022 self.run_next_test()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001023
Jon Salz0697cbf2012-07-04 15:14:04 +08001024 def reap_completed_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001025 """Removes completed tests from the set of active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +08001026
1027 Also updates the visible test if it was reaped.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001028 """
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001029 test_completed = False
Jon Salz0697cbf2012-07-04 15:14:04 +08001030 for t, v in dict(self.invocations).iteritems():
1031 if v.is_completed():
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001032 test_completed = True
Jon Salz1acc8742012-07-17 17:45:55 +08001033 new_state = t.update_state(**v.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +08001034 del self.invocations[t]
1035
Johny Lin62ed2a32015-05-13 11:57:12 +08001036 # Stop on failure if flag is true and there is no retry chances.
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001037 if (self.test_list.options.stop_on_failure and
Johny Lin62ed2a32015-05-13 11:57:12 +08001038 new_state.retries_left < 0 and
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001039 new_state.status == TestState.FAILED):
1040 # Clean all the tests to cause goofy to stop.
1041 self.tests_to_run = []
Ricky Liang45c73e72015-01-15 15:00:30 +08001042 factory.console.info('Stop on failure triggered. Empty the queue.')
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001043
Jon Salz1acc8742012-07-17 17:45:55 +08001044 if new_state.iterations_left and new_state.status == TestState.PASSED:
1045 # Play it again, Sam!
1046 self._run_test(t)
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +08001047 # new_state.retries_left is obtained after update.
1048 # For retries_left == 0, test can still be run for the last time.
1049 elif (new_state.retries_left >= 0 and
1050 new_state.status == TestState.FAILED):
1051 # Still have to retry, Sam!
1052 self._run_test(t)
Jon Salz1acc8742012-07-17 17:45:55 +08001053
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001054 if test_completed:
Vic Yangf01c59f2013-04-19 17:37:56 +08001055 self.log_watcher.KickWatchThread()
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001056
Jon Salz0697cbf2012-07-04 15:14:04 +08001057 if (self.visible_test is None or
Jon Salz85a39882012-07-05 16:45:04 +08001058 self.visible_test not in self.invocations):
Jon Salz0697cbf2012-07-04 15:14:04 +08001059 self.set_visible_test(None)
1060 # Make the first running test, if any, the visible test
1061 for t in self.test_list.walk():
1062 if t in self.invocations:
1063 self.set_visible_test(t)
1064 break
1065
Jon Salz6dc031d2013-06-19 13:06:23 +08001066 def kill_active_tests(self, abort, root=None, reason=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001067 """Kills and waits for all active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +08001068
Jon Salz85a39882012-07-05 16:45:04 +08001069 Args:
1070 abort: True to change state of killed tests to FAILED, False for
Jon Salz0697cbf2012-07-04 15:14:04 +08001071 UNTESTED.
Jon Salz85a39882012-07-05 16:45:04 +08001072 root: If set, only kills tests with root as an ancestor.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001073 reason: If set, the abort reason.
1074 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001075 self.reap_completed_tests()
1076 for test, invoc in self.invocations.items():
Jon Salz85a39882012-07-05 16:45:04 +08001077 if root and not test.has_ancestor(root):
1078 continue
1079
Ricky Liang45c73e72015-01-15 15:00:30 +08001080 factory.console.info('Killing active test %s...', test.path)
Jon Salz6dc031d2013-06-19 13:06:23 +08001081 invoc.abort_and_join(reason)
Ricky Liang45c73e72015-01-15 15:00:30 +08001082 factory.console.info('Killed %s', test.path)
Jon Salz1acc8742012-07-17 17:45:55 +08001083 test.update_state(**invoc.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +08001084 del self.invocations[test]
Jon Salz1acc8742012-07-17 17:45:55 +08001085
Jon Salz0697cbf2012-07-04 15:14:04 +08001086 if not abort:
1087 test.update_state(status=TestState.UNTESTED)
1088 self.reap_completed_tests()
1089
Jon Salz6dc031d2013-06-19 13:06:23 +08001090 def stop(self, root=None, fail=False, reason=None):
1091 self.kill_active_tests(fail, root, reason)
Jon Salz85a39882012-07-05 16:45:04 +08001092 # Remove any tests in the run queue under the root.
1093 self.tests_to_run = deque([x for x in self.tests_to_run
1094 if root and not x.has_ancestor(root)])
1095 self.run_next_test()
Jon Salz0697cbf2012-07-04 15:14:04 +08001096
Jon Salz4712ac72013-02-07 17:12:05 +08001097 def clear_state(self, root=None):
Jon Salzd7550792013-07-12 05:49:27 +08001098 if root is None:
1099 root = self.test_list
Jon Salz6dc031d2013-06-19 13:06:23 +08001100 self.stop(root, reason='Clearing test state')
Jon Salz4712ac72013-02-07 17:12:05 +08001101 for f in root.walk():
1102 if f.is_leaf():
1103 f.update_state(status=TestState.UNTESTED)
1104
Jon Salz6dc031d2013-06-19 13:06:23 +08001105 def abort_active_tests(self, reason=None):
1106 self.kill_active_tests(True, reason=reason)
Jon Salz0697cbf2012-07-04 15:14:04 +08001107
1108 def main(self):
Jon Salzeff94182013-06-19 15:06:28 +08001109 syslog.openlog('goofy')
1110
Jon Salz0697cbf2012-07-04 15:14:04 +08001111 try:
Jon Salzd7550792013-07-12 05:49:27 +08001112 self.status = Status.INITIALIZING
Jon Salz0697cbf2012-07-04 15:14:04 +08001113 self.init()
1114 self.event_log.Log('goofy_init',
Ricky Liang45c73e72015-01-15 15:00:30 +08001115 success=True)
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001116 testlog.Log(
Joel Kitching9eb203a2016-04-21 15:36:30 +08001117 testlog.StationInit({
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001118 'stationDeviceId': testlog_goofy.GetDeviceID(),
Joel Kitching21bc69b2016-07-13 08:29:52 -07001119 'stationInstallationId': testlog_goofy.GetInstallationID(),
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001120 'count': testlog_goofy.GetInitCount(),
Joel Kitching9eb203a2016-04-21 15:36:30 +08001121 'success': True}))
Jon Salz0697cbf2012-07-04 15:14:04 +08001122 except:
Joel Kitching9eb203a2016-04-21 15:36:30 +08001123 try:
1124 if self.event_log:
Jon Salz0697cbf2012-07-04 15:14:04 +08001125 self.event_log.Log('goofy_init',
Ricky Liang45c73e72015-01-15 15:00:30 +08001126 success=False,
1127 trace=traceback.format_exc())
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001128 if self.testlog:
1129 testlog.Log(
Joel Kitching9eb203a2016-04-21 15:36:30 +08001130 testlog.StationInit({
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001131 'stationDeviceId': testlog_goofy.GetDeviceID(),
Joel Kitching21bc69b2016-07-13 08:29:52 -07001132 'stationInstallationId': testlog_goofy.GetInstallationID(),
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001133 'count': testlog_goofy.GetInitCount(),
Joel Kitching9eb203a2016-04-21 15:36:30 +08001134 'success': False,
1135 'failureMessage': traceback.format_exc()}))
1136 except: # pylint: disable=W0702
1137 pass
Jon Salz0697cbf2012-07-04 15:14:04 +08001138 raise
1139
Jon Salzd7550792013-07-12 05:49:27 +08001140 self.status = Status.RUNNING
Jon Salzeff94182013-06-19 15:06:28 +08001141 syslog.syslog('Goofy (factory test harness) starting')
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001142 syslog.syslog('Boot sequence = %d' % GetBootSequence())
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001143 syslog.syslog('Goofy init count = %d' % testlog_goofy.GetInitCount())
Jon Salz0697cbf2012-07-04 15:14:04 +08001144 self.run()
1145
1146 def update_system_info(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001147 """Updates system info."""
Hung-Te Line594e5d2015-12-16 02:36:05 +08001148 info = self.dut.info.GetAll()
1149 self.state_instance.set_shared_data('system_info', info)
Jon Salz0697cbf2012-07-04 15:14:04 +08001150 self.event_client.post_event(Event(Event.Type.SYSTEM_INFO,
Hung-Te Line594e5d2015-12-16 02:36:05 +08001151 system_info=info))
1152 logging.info('System info: %r', info)
Jon Salz0697cbf2012-07-04 15:14:04 +08001153
Jon Salzeb42f0d2012-07-27 19:14:04 +08001154 def update_factory(self, auto_run_on_restart=False, post_update_hook=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001155 """Commences updating factory software.
Jon Salzeb42f0d2012-07-27 19:14:04 +08001156
1157 Args:
1158 auto_run_on_restart: Auto-run when the machine comes back up.
1159 post_update_hook: Code to call after update but immediately before
1160 restart.
1161
1162 Returns:
1163 Never if the update was successful (we just reboot).
1164 False if the update was unnecessary (no update available).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001165 """
Jon Salz6dc031d2013-06-19 13:06:23 +08001166 self.kill_active_tests(False, reason='Factory software update')
Jon Salza6711d72012-07-18 14:33:03 +08001167 self.cancel_pending_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001168
Jon Salz5c344f62012-07-13 14:31:16 +08001169 def pre_update_hook():
1170 if auto_run_on_restart:
1171 self.state_instance.set_shared_data('tests_after_shutdown',
1172 FORCE_AUTO_RUN)
1173 self.state_instance.close()
1174
Jon Salzeb42f0d2012-07-27 19:14:04 +08001175 if updater.TryUpdate(pre_update_hook=pre_update_hook):
1176 if post_update_hook:
1177 post_update_hook()
1178 self.env.shutdown('reboot')
Jon Salz0697cbf2012-07-04 15:14:04 +08001179
Ricky Liang8fecf412014-05-22 10:56:14 +08001180 def handle_sigint(self, dummy_signum, dummy_frame): # pylint: disable=W0613
Jon Salz77c151e2012-08-28 07:20:37 +08001181 logging.error('Received SIGINT')
Peter Ammon1e1ec572014-06-26 17:56:32 -07001182 self.run_enqueue(None)
Jon Salz77c151e2012-08-28 07:20:37 +08001183 raise KeyboardInterrupt()
1184
Ricky Liang8fecf412014-05-22 10:56:14 +08001185 def handle_sigterm(self, dummy_signum, dummy_frame): # pylint: disable=W0613
1186 logging.error('Received SIGTERM')
Hung-Te Lin94ca4742014-07-09 20:13:50 +08001187 self.env.terminate()
1188 self.run_queue.put(None)
Ricky Liang8fecf412014-05-22 10:56:14 +08001189 raise RuntimeError('Received SIGTERM')
1190
Jon Salze12c2b32013-06-25 16:24:34 +08001191 def find_kcrashes(self):
1192 """Finds kcrash files, logs them, and marks them as seen."""
1193 seen_crashes = set(
1194 self.state_instance.get_shared_data('seen_crashes', optional=True)
1195 or [])
1196
1197 for path in glob.glob('/var/spool/crash/*'):
1198 if not os.path.isfile(path):
1199 continue
1200 if path in seen_crashes:
1201 continue
1202 try:
1203 stat = os.stat(path)
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001204 mtime = time_utils.TimeString(stat.st_mtime)
Jon Salze12c2b32013-06-25 16:24:34 +08001205 logging.info(
1206 'Found new crash file %s (%d bytes at %s)',
1207 path, stat.st_size, mtime)
1208 extra_log_args = {}
1209
1210 try:
1211 _, ext = os.path.splitext(path)
1212 if ext in ['.kcrash', '.meta']:
1213 ext = ext.replace('.', '')
1214 with open(path) as f:
1215 data = f.read(MAX_CRASH_FILE_SIZE)
1216 tell = f.tell()
1217 logging.info(
1218 'Contents of %s%s:%s',
1219 path,
1220 ('' if tell == stat.st_size
1221 else '(truncated to %d bytes)' % MAX_CRASH_FILE_SIZE),
1222 ('\n' + data).replace('\n', '\n ' + ext + '> '))
1223 extra_log_args['data'] = data
1224
1225 # Copy to /var/factory/kcrash for posterity
Joel Kitching625ff0f2016-05-16 14:59:40 -07001226 kcrash_dir = paths.GetFactoryRoot('kcrash')
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001227 file_utils.TryMakeDirs(kcrash_dir)
Jon Salze12c2b32013-06-25 16:24:34 +08001228 shutil.copy(path, kcrash_dir)
1229 logging.info('Copied to %s',
1230 os.path.join(kcrash_dir, os.path.basename(path)))
1231 finally:
1232 # Even if something goes wrong with the above, still try to
1233 # log to event log
1234 self.event_log.Log('crash_file',
1235 path=path, size=stat.st_size, mtime=mtime,
1236 **extra_log_args)
1237 except: # pylint: disable=W0702
1238 logging.exception('Unable to handle crash files %s', path)
1239 seen_crashes.add(path)
1240
1241 self.state_instance.set_shared_data('seen_crashes', list(seen_crashes))
1242
Jon Salz128b0932013-07-03 16:55:26 +08001243 def GetTestList(self, test_list_id):
1244 """Returns the test list with the given ID.
1245
1246 Raises:
1247 TestListError: The test list ID is not valid.
1248 """
1249 try:
1250 return self.test_lists[test_list_id]
1251 except KeyError:
1252 raise test_lists.TestListError(
1253 '%r is not a valid test list ID (available IDs are [%s])' % (
1254 test_list_id, ', '.join(sorted(self.test_lists.keys()))))
1255
1256 def InitTestLists(self):
Joel Kitching50a63ea2016-02-22 13:15:09 +08001257 """Reads in all test lists and sets the active test list.
1258
1259 Returns:
1260 True if the active test list could be set, False if failed.
1261 """
1262 startup_errors = []
1263 self.test_lists, failed_files = test_lists.BuildAllTestLists(
Ricky Liang27051552014-05-04 14:22:26 +08001264 force_generic=(self.options.automation_mode is not None))
Jon Salzd7550792013-07-12 05:49:27 +08001265 logging.info('Loaded test lists: [%s]',
1266 test_lists.DescribeTestLists(self.test_lists))
Jon Salz128b0932013-07-03 16:55:26 +08001267
Joel Kitching50a63ea2016-02-22 13:15:09 +08001268 # Check for any syntax errors in test list files.
1269 if failed_files:
1270 logging.info('Failed test list files: [%s]',
1271 ' '.join(failed_files.keys()))
1272 for f, exc_info in failed_files.iteritems():
1273 logging.error('Error in test list file: %s', f,
1274 exc_info=exc_info)
1275
1276 # Limit the stack trace to the very last entry.
1277 exc_type, exc_value, exc_traceback = exc_info
1278 while exc_traceback and exc_traceback.tb_next:
1279 exc_traceback = exc_traceback.tb_next
1280
1281 exc_string = ''.join(
1282 traceback.format_exception(
1283 exc_type, exc_value, exc_traceback)).rstrip()
1284 startup_errors.append('Error in test list file (%s):\n%s'
1285 % (f, exc_string))
1286
Jon Salz128b0932013-07-03 16:55:26 +08001287 if not self.options.test_list:
1288 self.options.test_list = test_lists.GetActiveTestListId()
1289
Joel Kitching50a63ea2016-02-22 13:15:09 +08001290 # Check for a non-existent test list ID.
1291 try:
Wei-Han Chen84fee7c2016-08-26 21:56:25 +08001292 self.test_list = self.GetTestList(self.options.test_list)
Joel Kitching50a63ea2016-02-22 13:15:09 +08001293 logging.info('Active test list: %s', self.test_list.test_list_id)
1294 except test_lists.TestListError as e:
1295 logging.exception('Invalid active test list: %s',
1296 self.options.test_list)
1297 startup_errors.append(e.message)
Jon Salz128b0932013-07-03 16:55:26 +08001298
Joel Kitching50a63ea2016-02-22 13:15:09 +08001299 # We may have failed loading the active test list.
1300 if self.test_list:
Joel Kitching50a63ea2016-02-22 13:15:09 +08001301 self.test_list.state_instance = self.state_instance
Jon Salz128b0932013-07-03 16:55:26 +08001302
Joel Kitching50a63ea2016-02-22 13:15:09 +08001303 # Prepare DUT link.
1304 if self.test_list.options.dut_options:
1305 logging.info('dut_options set by %s: %r', self.test_list.test_list_id,
1306 self.test_list.options.dut_options)
Hung-Te Linb6287242016-05-18 14:39:05 +08001307 device_utils.PrepareDUTLink(**self.test_list.options.dut_options)
Wei-Han Chene8a025f2016-01-14 16:42:02 +08001308
Joel Kitching50a63ea2016-02-22 13:15:09 +08001309 # Show all startup errors.
1310 if startup_errors:
1311 self.state_instance.set_shared_data(
1312 'startup_error', '\n\n'.join(startup_errors))
1313
1314 # Only return False if failed to load the active test list.
1315 return bool(self.test_list)
Jon Salz128b0932013-07-03 16:55:26 +08001316
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001317 def init_hooks(self):
1318 """Initializes hooks.
1319
1320 Must run after self.test_list ready.
1321 """
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001322 module, cls = self.test_list.options.hooks_class.rsplit('.', 1)
1323 self.hooks = getattr(__import__(module, fromlist=[cls]), cls)()
1324 assert isinstance(self.hooks, factory.Hooks), (
Ricky Liang45c73e72015-01-15 15:00:30 +08001325 'hooks should be of type Hooks but is %r' % type(self.hooks))
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001326 self.hooks.test_list = self.test_list
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001327 self.hooks.OnCreatedTestList()
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001328
Vic Yanga3cecf82014-12-26 00:44:21 -08001329 def init_ui(self):
1330 """Initialize UI."""
1331 self._ui_initialized = True
1332 if self.options.ui == 'chrome':
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001333 if self.options.monolithic:
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001334 self.env.launch_chrome()
1335 else:
1336 # The presenter is responsible for launching Chrome. Let's just
1337 # wait here.
1338 self.env.controller_ready_for_ui()
Vic Yanga3cecf82014-12-26 00:44:21 -08001339 logging.info('Waiting for a web socket connection')
1340 self.web_socket_manager.wait()
1341
1342 # Wait for the test widget size to be set; this is done in
1343 # an asynchronous RPC so there is a small chance that the
1344 # web socket might be opened first.
1345 for _ in range(100): # 10 s
1346 try:
1347 if self.state_instance.get_shared_data('test_widget_size'):
1348 break
1349 except KeyError:
1350 pass # Retry
1351 time.sleep(0.1) # 100 ms
1352 else:
1353 logging.warn('Never received test_widget_size from UI')
1354
Jon Salz0697cbf2012-07-04 15:14:04 +08001355 def init(self, args=None, env=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001356 """Initializes Goofy.
Jon Salz0697cbf2012-07-04 15:14:04 +08001357
1358 Args:
1359 args: A list of command-line arguments. Uses sys.argv if
1360 args is None.
1361 env: An Environment instance to use (or None to choose
1362 FakeChrootEnvironment or DUTEnvironment as appropriate).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001363 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001364 parser = OptionParser()
1365 parser.add_option('-v', '--verbose', dest='verbose',
Jon Salz8fa8e832012-07-13 19:04:09 +08001366 action='store_true',
1367 help='Enable debug logging')
Jon Salz0697cbf2012-07-04 15:14:04 +08001368 parser.add_option('--print_test_list', dest='print_test_list',
Wei-Han Chen84fee7c2016-08-26 21:56:25 +08001369 metavar='TEST_LIST_ID',
1370 help='Print the content of TEST_LIST_ID and exit')
Jon Salz0697cbf2012-07-04 15:14:04 +08001371 parser.add_option('--restart', dest='restart',
Jon Salz8fa8e832012-07-13 19:04:09 +08001372 action='store_true',
1373 help='Clear all test state')
Jon Salz0697cbf2012-07-04 15:14:04 +08001374 parser.add_option('--ui', dest='ui', type='choice',
Jon Salz7b5482e2014-08-04 17:48:41 +08001375 choices=['none', 'chrome'],
Jon Salz2f881df2013-02-01 17:00:35 +08001376 default='chrome',
Jon Salz8fa8e832012-07-13 19:04:09 +08001377 help='UI to use')
Jon Salz0697cbf2012-07-04 15:14:04 +08001378 parser.add_option('--ui_scale_factor', dest='ui_scale_factor',
Jon Salz8fa8e832012-07-13 19:04:09 +08001379 type='int', default=1,
1380 help=('Factor by which to scale UI '
1381 '(Chrome UI only)'))
Jon Salz0697cbf2012-07-04 15:14:04 +08001382 parser.add_option('--test_list', dest='test_list',
Wei-Han Chen84fee7c2016-08-26 21:56:25 +08001383 metavar='TEST_LIST_ID',
1384 help='Use test list whose id is TEST_LIST_ID')
Jon Salzc79a9982012-08-30 04:42:01 +08001385 parser.add_option('--dummy_shopfloor', action='store_true',
1386 help='Use a dummy shopfloor server')
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001387 parser.add_option('--dummy_connection_manager', action='store_true',
1388 help='Use a dummy connection manager')
Ricky Liang6fe218c2013-12-27 15:17:17 +08001389 parser.add_option('--automation-mode',
1390 choices=[m.lower() for m in AutomationMode],
Ricky Liang45c73e72015-01-15 15:00:30 +08001391 default='none', help='Factory test automation mode.')
Ricky Liang117484a2014-04-14 11:14:41 +08001392 parser.add_option('--no-auto-run-on-start', dest='auto_run_on_start',
1393 action='store_false', default=True,
1394 help=('do not automatically run the test list on goofy '
1395 'start; this is only valid when factory test '
1396 'automation is enabled'))
Chun-Ta Lina8dd3172014-11-26 16:15:13 +08001397 parser.add_option('--handshake_timeout', dest='handshake_timeout',
1398 type='float', default=0.3,
1399 help=('RPC timeout when doing handshake between device '
1400 'and presenter.'))
Vic Yang7d693c42014-09-14 09:52:39 +08001401 parser.add_option('--standalone', dest='standalone',
1402 action='store_true', default=False,
1403 help=('Assume the presenter is running on the same '
1404 'machines.'))
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001405 parser.add_option('--monolithic', dest='monolithic',
1406 action='store_true', default=False,
1407 help='Run in monolithic mode (without presenter)')
Jon Salz0697cbf2012-07-04 15:14:04 +08001408 (self.options, self.args) = parser.parse_args(args)
1409
Hung-Te Lina846f602014-07-04 20:32:22 +08001410 signal.signal(signal.SIGINT, self.handle_sigint)
1411 # TODO(hungte) SIGTERM does not work properly without Telemetry and should
1412 # be fixed.
Hung-Te Lina846f602014-07-04 20:32:22 +08001413
Jon Salz46b89562012-07-05 11:49:22 +08001414 # Make sure factory directories exist.
Joel Kitching625ff0f2016-05-16 14:59:40 -07001415 paths.GetLogRoot()
1416 paths.GetStateRoot()
1417 paths.GetTestDataRoot()
Jon Salz46b89562012-07-05 11:49:22 +08001418
Jon Salz0697cbf2012-07-04 15:14:04 +08001419 global _inited_logging # pylint: disable=W0603
1420 if not _inited_logging:
1421 factory.init_logging('goofy', verbose=self.options.verbose)
1422 _inited_logging = True
Jon Salz8fa8e832012-07-13 19:04:09 +08001423
Jon Salz0f996602012-10-03 15:26:48 +08001424 if self.options.print_test_list:
Wei-Han Chen84fee7c2016-08-26 21:56:25 +08001425 test_list = test_lists.BuildTestList(self.options.print_test_list)
1426 print(test_list.__repr__(recursive=True))
Jon Salz0f996602012-10-03 15:26:48 +08001427 sys.exit(0)
1428
Jon Salzee85d522012-07-17 14:34:46 +08001429 event_log.IncrementBootSequence()
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001430 testlog_goofy.IncrementInitCount()
1431
Jon Salzd15bbcf2013-05-21 17:33:57 +08001432 # Don't defer logging the initial event, so we can make sure
1433 # that device_id, reimage_id, etc. are all set up.
1434 self.event_log = EventLog('goofy', defer=False)
Chun-Ta Lin53cbbd52016-06-08 21:42:19 +08001435 self.testlog = testlog.Testlog(
1436 log_root=paths.GetLogRoot(), uuid=self.uuid)
1437 # Direct the logging calls to testlog as well.
1438 testlog.CapturePythonLogging(
1439 callback=self.testlog.primary_json.Log,
1440 level=logging.getLogger().getEffectiveLevel())
Jon Salz0697cbf2012-07-04 15:14:04 +08001441
Jon Salz0697cbf2012-07-04 15:14:04 +08001442 if env:
1443 self.env = env
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001444 elif sys_utils.InChroot():
Jon Salz0697cbf2012-07-04 15:14:04 +08001445 self.env = test_environment.FakeChrootEnvironment()
1446 logging.warn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001447 'Using chroot environment: will not actually run autotests')
Hung-Te Lina846f602014-07-04 20:32:22 +08001448 elif self.options.ui == 'chrome':
Ricky Liang09d66d82014-09-25 11:20:54 +08001449 self.env = test_environment.DUTEnvironment()
Jon Salz0697cbf2012-07-04 15:14:04 +08001450 self.env.goofy = self
Vic Yanga4931152014-08-11 16:36:24 -07001451 # web_socket_manager will be initialized later
1452 # pylint: disable=W0108
1453 self.env.has_sockets = lambda: self.web_socket_manager.has_sockets()
Jon Salz0697cbf2012-07-04 15:14:04 +08001454
1455 if self.options.restart:
1456 state.clear_state()
1457
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001458 if self.options.ui_scale_factor != 1 and sys_utils.InQEMU():
Jon Salz0697cbf2012-07-04 15:14:04 +08001459 logging.warn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001460 'In QEMU; ignoring ui_scale_factor argument')
Jon Salz0697cbf2012-07-04 15:14:04 +08001461 self.options.ui_scale_factor = 1
1462
1463 logging.info('Started')
1464
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001465 if not self.options.monolithic:
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001466 self.link_manager = PresenterLinkManager(
1467 check_interval=1,
1468 handshake_timeout=self.options.handshake_timeout,
1469 standalone=self.options.standalone)
Peter Ammon1e1ec572014-06-26 17:56:32 -07001470
Jon Salz0697cbf2012-07-04 15:14:04 +08001471 self.start_state_server()
1472 self.state_instance.set_shared_data('hwid_cfg', get_hwid_cfg())
1473 self.state_instance.set_shared_data('ui_scale_factor',
Ricky Liang09216dc2013-02-22 17:26:45 +08001474 self.options.ui_scale_factor)
Jon Salz0697cbf2012-07-04 15:14:04 +08001475 self.last_shutdown_time = (
Ricky Liang45c73e72015-01-15 15:00:30 +08001476 self.state_instance.get_shared_data('shutdown_time', optional=True))
Jon Salz0697cbf2012-07-04 15:14:04 +08001477 self.state_instance.del_shared_data('shutdown_time', optional=True)
Jon Salzb19ea072013-02-07 16:35:00 +08001478 self.state_instance.del_shared_data('startup_error', optional=True)
Jon Salz0697cbf2012-07-04 15:14:04 +08001479
Ricky Liang6fe218c2013-12-27 15:17:17 +08001480 self.options.automation_mode = ParseAutomationMode(
1481 self.options.automation_mode)
1482 self.state_instance.set_shared_data('automation_mode',
1483 self.options.automation_mode)
1484 self.state_instance.set_shared_data(
1485 'automation_mode_prompt',
1486 AutomationModePrompt[self.options.automation_mode])
1487
Joel Kitching50a63ea2016-02-22 13:15:09 +08001488 success = False
1489 exc_info = None
Jon Salz128b0932013-07-03 16:55:26 +08001490 try:
Joel Kitching50a63ea2016-02-22 13:15:09 +08001491 success = self.InitTestLists()
Jon Salz128b0932013-07-03 16:55:26 +08001492 except: # pylint: disable=W0702
Joel Kitching50a63ea2016-02-22 13:15:09 +08001493 exc_info = sys.exc_info()
1494
1495 if not success:
1496 if exc_info:
1497 logging.exception('Unable to initialize test lists')
1498 self.state_instance.set_shared_data(
1499 'startup_error',
1500 'Unable to initialize test lists\n%s' % (
1501 traceback.format_exc()))
Jon Salzb19ea072013-02-07 16:35:00 +08001502 if self.options.ui == 'chrome':
1503 # Create an empty test list with default options so that the rest of
1504 # startup can proceed.
1505 self.test_list = factory.FactoryTestList(
1506 [], self.state_instance, factory.Options())
1507 else:
1508 # Bail with an error; no point in starting up.
1509 sys.exit('No valid test list; exiting.')
1510
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001511 self.init_hooks()
1512
Jon Salz822838b2013-03-25 17:32:33 +08001513 if self.test_list.options.clear_state_on_start:
1514 self.state_instance.clear_test_state()
1515
Jon Salz670ce062014-05-16 15:53:50 +08001516 # If the phase is invalid, this will raise a ValueError.
1517 phase.SetPersistentPhase(self.test_list.options.phase)
1518
Dean Liao85ca86f2014-11-03 12:28:08 +08001519 # For netboot firmware, mainfw_type should be 'netboot'.
Hung-Te Line594e5d2015-12-16 02:36:05 +08001520 if (self.dut.info.mainfw_type != 'nonchrome' and
1521 self.dut.info.firmware_version is None):
Ricky Liang45c73e72015-01-15 15:00:30 +08001522 self.state_instance.set_shared_data(
1523 'startup_error',
Vic Yang9bd4f772013-06-04 17:34:00 +08001524 'Netboot firmware detected\n'
1525 'Connect Ethernet and reboot to re-image.\n'
1526 u'侦测到网路开机固件\n'
1527 u'请连接乙太网并重启')
1528
Jon Salz0697cbf2012-07-04 15:14:04 +08001529 if not self.state_instance.has_shared_data('ui_lang'):
1530 self.state_instance.set_shared_data('ui_lang',
Ricky Liang45c73e72015-01-15 15:00:30 +08001531 self.test_list.options.ui_lang)
Jon Salz0697cbf2012-07-04 15:14:04 +08001532 self.state_instance.set_shared_data(
Ricky Liang45c73e72015-01-15 15:00:30 +08001533 'test_list_options',
1534 self.test_list.options.__dict__)
Jon Salz0697cbf2012-07-04 15:14:04 +08001535 self.state_instance.test_list = self.test_list
1536
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001537 self.check_log_rotation()
Jon Salz83ef34b2012-11-01 19:46:35 +08001538
Jon Salz23926422012-09-01 03:38:13 +08001539 if self.options.dummy_shopfloor:
Ricky Liang45c73e72015-01-15 15:00:30 +08001540 os.environ[shopfloor.SHOPFLOOR_SERVER_ENV_VAR_NAME] = (
1541 'http://%s:%d/' %
Joel Kitchingb85ed7f2014-10-08 18:24:39 +08001542 (net_utils.LOCALHOST, shopfloor.DEFAULT_SERVER_PORT))
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001543 self.dummy_shopfloor = process_utils.Spawn(
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001544 [os.path.join(paths.FACTORY_PATH, 'bin', 'shopfloor_server'),
Jon Salz23926422012-09-01 03:38:13 +08001545 '--dummy'])
1546 elif self.test_list.options.shopfloor_server_url:
1547 shopfloor.set_server_url(self.test_list.options.shopfloor_server_url)
Jon Salz2bf2f6b2013-03-28 18:49:26 +08001548 shopfloor.set_enabled(True)
Jon Salz23926422012-09-01 03:38:13 +08001549
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001550 if self.test_list.options.time_sanitizer and not sys_utils.InChroot():
Jon Salz8fa8e832012-07-13 19:04:09 +08001551 self.time_sanitizer = time_sanitizer.TimeSanitizer(
Ricky Liang45c73e72015-01-15 15:00:30 +08001552 base_time=time_sanitizer.GetBaseTimeFromFile(
1553 # lsb-factory is written by the factory install shim during
1554 # installation, so it should have a good time obtained from
1555 # the mini-Omaha server. If it's not available, we'll use
1556 # /etc/lsb-factory (which will be much older, but reasonably
1557 # sane) and rely on a shopfloor sync to set a more accurate
1558 # time.
1559 '/usr/local/etc/lsb-factory',
1560 '/etc/lsb-release'))
Jon Salz8fa8e832012-07-13 19:04:09 +08001561 self.time_sanitizer.RunOnce()
1562
Vic Yangd8990da2013-06-27 16:57:43 +08001563 if self.test_list.options.check_cpu_usage_period_secs:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001564 self.cpu_usage_watcher = process_utils.Spawn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001565 ['py/tools/cpu_usage_monitor.py', '-p',
1566 str(self.test_list.options.check_cpu_usage_period_secs)],
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001567 cwd=paths.FACTORY_PATH)
Vic Yangd8990da2013-06-27 16:57:43 +08001568
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001569 # Enable thermal monitor
1570 if self.test_list.options.thermal_monitor_period_secs > 0:
Hung-Te Lin23cb7612016-01-19 19:19:32 +08001571 self.thermal_watcher = process_utils.Spawn(
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001572 ['py/tools/thermal_monitor.py',
1573 '-p', str(self.test_list.options.thermal_monitor_period_secs),
1574 '-d', str(self.test_list.options.thermal_monitor_delta)],
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001575 cwd=paths.FACTORY_PATH)
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001576
Jon Salz0697cbf2012-07-04 15:14:04 +08001577 self.init_states()
1578 self.start_event_server()
Wei-Ning Huang38b75f02015-02-25 18:25:14 +08001579 self.start_terminal_server()
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001580
Earl Oua3bca122016-10-21 16:00:30 +08001581 # Load and run Goofy plugins.
1582 self.plugin_controller = plugin_controller.PluginController(
1583 self.test_list.options.plugin_config_name, self)
1584 self.plugin_controller.StartAllPlugins()
1585
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001586 if self.options.dummy_connection_manager:
1587 # Override network manager creation to dummy implmenetation.
1588 logging.info('Using dummy network manager (--dummy_connection_manager).')
1589 self.connection_manager = connection_manager.DummyConnectionManager()
1590 else:
1591 self.connection_manager = self.env.create_connection_manager(
1592 self.test_list.options.wlans,
Mao Huang4340c632015-04-14 14:35:22 +08001593 self.test_list.options.scan_wifi_period_secs,
1594 self.test_list.options.override_blacklisted_network_devices)
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001595
Jon Salz0697cbf2012-07-04 15:14:04 +08001596 # Note that we create a log watcher even if
1597 # sync_event_log_period_secs isn't set (no background
1598 # syncing), since we may use it to flush event logs as well.
1599 self.log_watcher = EventLogWatcher(
Ricky Liang45c73e72015-01-15 15:00:30 +08001600 self.test_list.options.sync_event_log_period_secs,
1601 event_log_db_file=None,
1602 handle_event_logs_callback=self.handle_event_logs)
Jon Salz0697cbf2012-07-04 15:14:04 +08001603 if self.test_list.options.sync_event_log_period_secs:
1604 self.log_watcher.StartWatchThread()
1605
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001606 # Creates a system log manager to scan logs periocially.
1607 # A scan includes clearing logs and optionally syncing logs if
1608 # enable_syng_log is True. We kick it to sync logs.
1609 self.system_log_manager = SystemLogManager(
Ricky Liang45c73e72015-01-15 15:00:30 +08001610 sync_log_paths=self.test_list.options.sync_log_paths,
1611 sync_log_period_secs=self.test_list.options.sync_log_period_secs,
1612 scan_log_period_secs=self.test_list.options.scan_log_period_secs,
1613 clear_log_paths=self.test_list.options.clear_log_paths,
1614 clear_log_excluded_paths=self.test_list.options.clear_log_excluded_paths)
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001615 self.system_log_manager.Start()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +08001616
Jon Salz0697cbf2012-07-04 15:14:04 +08001617 self.update_system_info()
1618
Vic Yang4953fc12012-07-26 16:19:53 +08001619 assert ((self.test_list.options.min_charge_pct is None) ==
1620 (self.test_list.options.max_charge_pct is None))
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001621 if sys_utils.InChroot():
Vic Yange83d9a12013-04-19 20:00:20 +08001622 logging.info('In chroot, ignoring charge manager and charge state')
Ricky Liangc392a1c2014-06-20 18:24:59 +08001623 elif (self.test_list.options.enable_charge_manager and
1624 self.test_list.options.min_charge_pct is not None):
Vic Yang4953fc12012-07-26 16:19:53 +08001625 self.charge_manager = ChargeManager(self.test_list.options.min_charge_pct,
1626 self.test_list.options.max_charge_pct)
Hung-Te Linc17b3d82015-12-15 15:26:08 +08001627 self.dut.status.Overrides('charge_manager', self.charge_manager)
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +08001628 else:
1629 # Goofy should set charger state to charge if charge_manager is disabled.
Dean Liao88b93192014-10-23 19:37:41 +08001630 self.charge()
Vic Yang4953fc12012-07-26 16:19:53 +08001631
Vic Yang6cee2472014-10-22 17:18:52 -07001632 if CoreDumpManager.CoreDumpEnabled():
1633 self.core_dump_manager = CoreDumpManager(
1634 self.test_list.options.core_dump_watchlist)
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001635
Jon Salz0697cbf2012-07-04 15:14:04 +08001636 os.environ['CROS_FACTORY'] = '1'
1637 os.environ['CROS_DISABLE_SITE_SYSINFO'] = '1'
1638
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001639 if not sys_utils.InChroot() and self.test_list.options.use_cpufreq_manager:
Ricky Liangecddbd42014-07-24 11:32:10 +08001640 logging.info('Enabling CPU frequency manager')
Jon Salzddf0d052013-06-18 12:52:44 +08001641 self.cpufreq_manager = CpufreqManager(event_log=self.event_log)
Jon Salzce6a7f82013-06-10 18:22:54 +08001642
Justin Chuang31b02432013-06-27 15:16:51 +08001643 # Startup hooks may want to skip some tests.
1644 self.update_skipped_tests()
Jon Salz416f9cc2013-05-10 18:32:50 +08001645
Jon Salze12c2b32013-06-25 16:24:34 +08001646 self.find_kcrashes()
1647
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001648 # Should not move earlier.
1649 self.hooks.OnStartup()
1650
Ricky Liang36512a32014-07-25 11:47:04 +08001651 # Only after this point the Goofy backend is ready for UI connection.
1652 self.ready_for_ui_connection = True
1653
Ricky Liang650f6bf2012-09-28 13:22:54 +08001654 # Create download path for autotest beforehand or autotests run at
1655 # the same time might fail due to race condition.
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001656 if not sys_utils.InChroot():
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001657 file_utils.TryMakeDirs(os.path.join('/usr/local/autotest', 'tests',
1658 'download'))
Ricky Liang650f6bf2012-09-28 13:22:54 +08001659
Jon Salz0697cbf2012-07-04 15:14:04 +08001660 def state_change_callback(test, test_state):
1661 self.event_client.post_event(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001662 Event(Event.Type.STATE_CHANGE, path=test.path, state=test_state))
Jon Salz0697cbf2012-07-04 15:14:04 +08001663 self.test_list.state_change_callback = state_change_callback
Jon Salz73e0fd02012-04-04 11:46:38 +08001664
Vic Yange2c76a82014-10-30 12:48:19 -07001665 self.autotest_prespawner = prespawner.AutotestPrespawner()
1666 self.autotest_prespawner.start()
1667
1668 self.pytest_prespawner = prespawner.PytestPrespawner()
1669 self.pytest_prespawner.start()
Jon Salza6711d72012-07-18 14:33:03 +08001670
Ricky Liang48e47f92014-02-26 19:31:51 +08001671 tests_after_shutdown = self.state_instance.get_shared_data(
1672 'tests_after_shutdown', optional=True)
Jon Salz57717ca2012-04-04 16:47:25 +08001673
Jon Salz5c344f62012-07-13 14:31:16 +08001674 force_auto_run = (tests_after_shutdown == FORCE_AUTO_RUN)
1675 if not force_auto_run and tests_after_shutdown is not None:
Ricky Liang48e47f92014-02-26 19:31:51 +08001676 logging.info('Resuming tests after shutdown: %s', tests_after_shutdown)
Jon Salz0697cbf2012-07-04 15:14:04 +08001677 self.tests_to_run.extend(
Ricky Liang4bff3e32014-02-20 18:46:11 +08001678 self.test_list.lookup_path(t) for t in tests_after_shutdown)
Peter Ammon1e1ec572014-06-26 17:56:32 -07001679 self.run_enqueue(self.run_next_test)
Jon Salz0697cbf2012-07-04 15:14:04 +08001680 else:
Jon Salz5c344f62012-07-13 14:31:16 +08001681 if force_auto_run or self.test_list.options.auto_run_on_start:
Ricky Liang117484a2014-04-14 11:14:41 +08001682 # If automation mode is enabled, allow suppress auto_run_on_start.
1683 if (self.options.automation_mode == 'NONE' or
1684 self.options.auto_run_on_start):
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08001685 status_filter = [TestState.UNTESTED]
1686 if self.test_list.options.retry_failed_on_start:
1687 status_filter.append(TestState.FAILED)
1688 self.run_enqueue(lambda: self.run_tests(self.test_list, status_filter))
Jon Salz5c344f62012-07-13 14:31:16 +08001689 self.state_instance.set_shared_data('tests_after_shutdown', None)
Ricky Liang4bff3e32014-02-20 18:46:11 +08001690 self.restore_active_run_state()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001691
Hung-Te Lin410f70a2015-12-15 14:53:42 +08001692 self.dut.hooks.OnTestStart()
Vic Yang08505c72015-01-06 17:01:53 -08001693
Dean Liao592e4d52013-01-10 20:06:39 +08001694 self.may_disable_cros_shortcut_keys()
1695
1696 def may_disable_cros_shortcut_keys(self):
1697 test_options = self.test_list.options
1698 if test_options.disable_cros_shortcut_keys:
1699 logging.info('Filter ChromeOS shortcut keys.')
1700 self.key_filter = KeyFilter(
1701 unmap_caps_lock=test_options.disable_caps_lock,
1702 caps_lock_keycode=test_options.caps_lock_keycode)
1703 self.key_filter.Start()
1704
Jon Salz0e6532d2012-10-25 16:30:11 +08001705 def _should_sync_time(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001706 """Returns True if we should attempt syncing time with shopfloor.
Jon Salz0e6532d2012-10-25 16:30:11 +08001707
1708 Args:
1709 foreground: If True, synchronizes even if background syncing
1710 is disabled (e.g., in explicit sync requests from the
1711 SyncShopfloor test).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001712 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001713 return ((foreground or
1714 self.test_list.options.sync_time_period_secs) and
Jon Salz54882d02012-08-31 01:57:54 +08001715 self.time_sanitizer and
1716 (not self.time_synced) and
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001717 (not sys_utils.InChroot()))
Jon Salz54882d02012-08-31 01:57:54 +08001718
Jon Salz0e6532d2012-10-25 16:30:11 +08001719 def sync_time_with_shopfloor_server(self, foreground=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001720 """Syncs time with shopfloor server, if not yet synced.
Jon Salz54882d02012-08-31 01:57:54 +08001721
Jon Salz0e6532d2012-10-25 16:30:11 +08001722 Args:
1723 foreground: If True, synchronizes even if background syncing
1724 is disabled (e.g., in explicit sync requests from the
1725 SyncShopfloor test).
1726
Jon Salz54882d02012-08-31 01:57:54 +08001727 Returns:
1728 False if no time sanitizer is available, or True if this sync (or a
1729 previous sync) succeeded.
1730
1731 Raises:
1732 Exception if unable to contact the shopfloor server.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001733 """
Jon Salz0e6532d2012-10-25 16:30:11 +08001734 if self._should_sync_time(foreground):
Jon Salz54882d02012-08-31 01:57:54 +08001735 self.time_sanitizer.SyncWithShopfloor()
1736 self.time_synced = True
1737 return self.time_synced
1738
Jon Salzb92c5112012-09-21 15:40:11 +08001739 def log_disk_space_stats(self):
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001740 if (sys_utils.InChroot() or
Jon Salz18e0e022013-06-11 17:13:39 +08001741 not self.test_list.options.log_disk_space_period_secs):
Jon Salzb92c5112012-09-21 15:40:11 +08001742 return
1743
1744 now = time.time()
1745 if (self.last_log_disk_space_time and
1746 now - self.last_log_disk_space_time <
1747 self.test_list.options.log_disk_space_period_secs):
1748 return
1749 self.last_log_disk_space_time = now
1750
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001751 # Upload event if stateful partition usage is above threshold.
1752 # Stateful partition is mounted on /usr/local, while
1753 # encrypted stateful partition is mounted on /var.
1754 # If there are too much logs in the factory process,
1755 # these two partitions might get full.
Jon Salzb92c5112012-09-21 15:40:11 +08001756 try:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001757 vfs_infos = disk_space.GetAllVFSInfo()
1758 stateful_info, encrypted_info = None, None
1759 for vfs_info in vfs_infos.values():
1760 if '/usr/local' in vfs_info.mount_points:
1761 stateful_info = vfs_info
1762 if '/var' in vfs_info.mount_points:
1763 encrypted_info = vfs_info
1764
1765 stateful = disk_space.GetPartitionUsage(stateful_info)
1766 encrypted = disk_space.GetPartitionUsage(encrypted_info)
1767
Ricky Liang45c73e72015-01-15 15:00:30 +08001768 above_threshold = (
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001769 self.test_list.options.stateful_usage_threshold and
1770 max(stateful.bytes_used_pct,
1771 stateful.inodes_used_pct,
1772 encrypted.bytes_used_pct,
1773 encrypted.inodes_used_pct) >
Ricky Liang45c73e72015-01-15 15:00:30 +08001774 self.test_list.options.stateful_usage_threshold)
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001775
1776 if above_threshold:
1777 self.event_log.Log('stateful_partition_usage',
Ricky Liang45c73e72015-01-15 15:00:30 +08001778 partitions={
1779 'stateful': {
1780 'bytes_used_pct': FloatDigit(stateful.bytes_used_pct, 2),
1781 'inodes_used_pct': FloatDigit(stateful.inodes_used_pct, 2)},
1782 'encrypted_stateful': {
1783 'bytes_used_pct': FloatDigit(encrypted.bytes_used_pct, 2),
1784 'inodes_used_pct': FloatDigit(encrypted.inodes_used_pct, 2)}
1785 })
Cheng-Yi Chiang1b722322015-03-16 20:07:03 +08001786 self.log_watcher.KickWatchThread()
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001787 if (not sys_utils.InChroot() and
Cheng-Yi Chiang00798e72013-06-20 18:16:39 +08001788 self.test_list.options.stateful_usage_above_threshold_action):
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001789 process_utils.Spawn(
1790 self.test_list.options.stateful_usage_above_threshold_action,
1791 call=True)
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001792
1793 message = disk_space.FormatSpaceUsedAll(vfs_infos)
Jon Salz3c493bb2013-02-07 17:24:58 +08001794 if message != self.last_log_disk_space_message:
Cheng-Yi Chiangd0406522013-04-01 15:40:18 +08001795 if above_threshold:
1796 logging.warning(message)
1797 else:
1798 logging.info(message)
Jon Salz3c493bb2013-02-07 17:24:58 +08001799 self.last_log_disk_space_message = message
Jon Salzb92c5112012-09-21 15:40:11 +08001800 except: # pylint: disable=W0702
1801 logging.exception('Unable to get disk space used')
1802
Justin Chuang83813982013-05-13 01:26:32 +08001803 def check_battery(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001804 """Checks the current battery status.
Justin Chuang83813982013-05-13 01:26:32 +08001805
1806 Logs current battery charging level and status to log. If the battery level
1807 is lower below warning_low_battery_pct, send warning event to shopfloor.
1808 If the battery level is lower below critical_low_battery_pct, flush disks.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001809 """
Justin Chuang83813982013-05-13 01:26:32 +08001810 if not self.test_list.options.check_battery_period_secs:
1811 return
1812
1813 now = time.time()
1814 if (self.last_check_battery_time and
1815 now - self.last_check_battery_time <
1816 self.test_list.options.check_battery_period_secs):
1817 return
1818 self.last_check_battery_time = now
1819
1820 message = ''
1821 log_level = logging.INFO
1822 try:
Hung-Te Lin6a72c642015-12-13 22:09:09 +08001823 power = self.dut.power
Justin Chuang83813982013-05-13 01:26:32 +08001824 if not power.CheckBatteryPresent():
1825 message = 'Battery is not present'
1826 else:
1827 ac_present = power.CheckACPresent()
1828 charge_pct = power.GetChargePct(get_float=True)
1829 message = ('Current battery level %.1f%%, AC charger is %s' %
1830 (charge_pct, 'connected' if ac_present else 'disconnected'))
1831
1832 if charge_pct > self.test_list.options.critical_low_battery_pct:
1833 critical_low_battery = False
1834 else:
1835 critical_low_battery = True
1836 # Only sync disks when battery level is still above minimum
1837 # value. This can be used for offline analysis when shopfloor cannot
1838 # be connected.
1839 if charge_pct > MIN_BATTERY_LEVEL_FOR_DISK_SYNC:
1840 logging.warning('disk syncing for critical low battery situation')
1841 os.system('sync; sync; sync')
1842 else:
1843 logging.warning('disk syncing is cancelled '
1844 'because battery level is lower than %.1f',
1845 MIN_BATTERY_LEVEL_FOR_DISK_SYNC)
1846
1847 # Notify shopfloor server
1848 if (critical_low_battery or
1849 (not ac_present and
1850 charge_pct <= self.test_list.options.warning_low_battery_pct)):
1851 log_level = logging.WARNING
1852
1853 self.event_log.Log('low_battery',
1854 battery_level=charge_pct,
1855 charger_connected=ac_present,
1856 critical=critical_low_battery)
1857 self.log_watcher.KickWatchThread()
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001858 if self.test_list.options.enable_sync_log:
1859 self.system_log_manager.KickToSync()
Ricky Liang45c73e72015-01-15 15:00:30 +08001860 except: # pylint: disable=W0702
Justin Chuang83813982013-05-13 01:26:32 +08001861 logging.exception('Unable to check battery or notify shopfloor')
1862 finally:
1863 if message != self.last_check_battery_message:
1864 logging.log(log_level, message)
1865 self.last_check_battery_message = message
1866
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001867 def check_core_dump(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001868 """Checks if there is any core dumped file.
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001869
1870 Removes unwanted core dump files immediately.
1871 Syncs those files matching watch list to server with a delay between
1872 each sync. After the files have been synced to server, deletes the files.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001873 """
Vic Yang6cee2472014-10-22 17:18:52 -07001874 if not self.core_dump_manager:
1875 return
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001876 core_dump_files = self.core_dump_manager.ScanFiles()
1877 if core_dump_files:
1878 now = time.time()
1879 if (self.last_kick_sync_time and now - self.last_kick_sync_time <
1880 self.test_list.options.kick_sync_min_interval_secs):
1881 return
1882 self.last_kick_sync_time = now
1883
1884 # Sends event to server
1885 self.event_log.Log('core_dumped', files=core_dump_files)
1886 self.log_watcher.KickWatchThread()
1887
1888 # Syncs files to server
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +08001889 if self.test_list.options.enable_sync_log:
1890 self.system_log_manager.KickToSync(
Cheng-Yi Chiangd3516a32013-07-17 15:30:47 +08001891 core_dump_files, self.core_dump_manager.ClearFiles)
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001892
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001893 def check_log_rotation(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001894 """Checks log rotation file presence/absence according to test_list option.
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001895
1896 Touch /var/lib/cleanup_logs_paused if test_list.options.disable_log_rotation
1897 is True, delete it otherwise. This must be done in idle loop because
1898 autotest client will touch /var/lib/cleanup_logs_paused each time it runs
1899 an autotest.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001900 """
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001901 if sys_utils.InChroot():
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001902 return
1903 try:
1904 if self.test_list.options.disable_log_rotation:
1905 open(CLEANUP_LOGS_PAUSED, 'w').close()
1906 else:
1907 file_utils.TryUnlink(CLEANUP_LOGS_PAUSED)
1908 except: # pylint: disable=W0702
1909 # Oh well. Logs an error (but no trace)
1910 logging.info(
1911 'Unable to %s %s: %s',
1912 'touch' if self.test_list.options.disable_log_rotation else 'delete',
Hung-Te Linf707b242016-01-08 23:11:42 +08001913 CLEANUP_LOGS_PAUSED, debug_utils.FormatExceptionOnly())
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001914
Jon Salz8fa8e832012-07-13 19:04:09 +08001915 def sync_time_in_background(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001916 """Writes out current time and tries to sync with shopfloor server."""
Jon Salzb22d1172012-08-06 10:38:57 +08001917 if not self.time_sanitizer:
1918 return
1919
1920 # Write out the current time.
1921 self.time_sanitizer.SaveTime()
1922
Jon Salz54882d02012-08-31 01:57:54 +08001923 if not self._should_sync_time():
Jon Salz8fa8e832012-07-13 19:04:09 +08001924 return
1925
1926 now = time.time()
1927 if self.last_sync_time and (
1928 now - self.last_sync_time <
1929 self.test_list.options.sync_time_period_secs):
1930 # Not yet time for another check.
1931 return
1932 self.last_sync_time = now
1933
1934 def target():
1935 try:
Jon Salz54882d02012-08-31 01:57:54 +08001936 self.sync_time_with_shopfloor_server()
Jon Salz8fa8e832012-07-13 19:04:09 +08001937 except: # pylint: disable=W0702
1938 # Oh well. Log an error (but no trace)
1939 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +08001940 'Unable to get time from shopfloor server: %s',
Hung-Te Linf707b242016-01-08 23:11:42 +08001941 debug_utils.FormatExceptionOnly())
Jon Salz8fa8e832012-07-13 19:04:09 +08001942
1943 thread = threading.Thread(target=target)
1944 thread.daemon = True
1945 thread.start()
1946
Peter Ammon1e1ec572014-06-26 17:56:32 -07001947 def perform_periodic_tasks(self):
1948 """Override of base method to perform periodic work.
Vic Yang4953fc12012-07-26 16:19:53 +08001949
Peter Ammon1e1ec572014-06-26 17:56:32 -07001950 This method must not raise exceptions.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001951 """
Peter Ammon1e1ec572014-06-26 17:56:32 -07001952 super(Goofy, self).perform_periodic_tasks()
Jon Salzb22d1172012-08-06 10:38:57 +08001953
Vic Yang311ddb82012-09-26 12:08:28 +08001954 self.check_exclusive()
Earl Oua3bca122016-10-21 16:00:30 +08001955 self.check_plugins()
cychiang21886742012-07-05 15:16:32 +08001956 self.check_for_updates()
Jon Salz8fa8e832012-07-13 19:04:09 +08001957 self.sync_time_in_background()
Jon Salzb92c5112012-09-21 15:40:11 +08001958 self.log_disk_space_stats()
Justin Chuang83813982013-05-13 01:26:32 +08001959 self.check_battery()
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001960 self.check_core_dump()
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001961 self.check_log_rotation()
Jon Salz57717ca2012-04-04 16:47:25 +08001962
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001963 def handle_event_logs(self, chunks, periodic=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001964 """Callback for event watcher.
Jon Salz258a40c2012-04-19 12:34:01 +08001965
Jon Salz0697cbf2012-07-04 15:14:04 +08001966 Attempts to upload the event logs to the shopfloor server.
Vic Yang93027612013-05-06 02:42:49 +08001967
1968 Args:
Jon Salzd15bbcf2013-05-21 17:33:57 +08001969 chunks: A list of Chunk objects.
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001970 periodic: This event log handling is periodic. Error messages
1971 will only be shown for the first time.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001972 """
Vic Yang93027612013-05-06 02:42:49 +08001973 first_exception = None
1974 exception_count = 0
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001975 # Suppress error messages for periodic event syncing except for the
1976 # first time. If event syncing is not periodic, always show the error
1977 # messages.
1978 quiet = self._suppress_event_log_error_messages if periodic else False
Vic Yang93027612013-05-06 02:42:49 +08001979
Jon Salzd15bbcf2013-05-21 17:33:57 +08001980 for chunk in chunks:
Vic Yang93027612013-05-06 02:42:49 +08001981 try:
Jon Salzcddb6402013-05-23 12:56:42 +08001982 description = 'event logs (%s)' % str(chunk)
Vic Yang93027612013-05-06 02:42:49 +08001983 start_time = time.time()
1984 shopfloor_client = shopfloor.get_instance(
Ricky Liang45c73e72015-01-15 15:00:30 +08001985 detect=True,
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001986 timeout=self.test_list.options.shopfloor_timeout_secs,
1987 quiet=quiet)
Ricky Liang45c73e72015-01-15 15:00:30 +08001988 shopfloor_client.UploadEvent(chunk.log_name + '.' +
Jon Salzd15bbcf2013-05-21 17:33:57 +08001989 event_log.GetReimageId(),
1990 Binary(chunk.chunk))
Vic Yang93027612013-05-06 02:42:49 +08001991 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +08001992 'Successfully synced %s in %.03f s',
1993 description, time.time() - start_time)
1994 except: # pylint: disable=W0702
Hung-Te Linf707b242016-01-08 23:11:42 +08001995 first_exception = (first_exception or
1996 (chunk.log_name + ': ' +
1997 debug_utils.FormatExceptionOnly()))
Vic Yang93027612013-05-06 02:42:49 +08001998 exception_count += 1
1999
2000 if exception_count:
2001 if exception_count == 1:
2002 msg = 'Log upload failed: %s' % first_exception
2003 else:
2004 msg = '%d log upload failed; first is: %s' % (
2005 exception_count, first_exception)
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08002006 # For periodic event log syncing, only show the first error messages.
2007 if periodic:
2008 if not self._suppress_event_log_error_messages:
2009 self._suppress_event_log_error_messages = True
2010 logging.warning('Suppress periodic shopfloor error messages for '
2011 'event log syncing after the first one.')
2012 raise Exception(msg)
2013 # For event log syncing by request, show the error messages.
2014 else:
2015 raise Exception(msg)
Vic Yang93027612013-05-06 02:42:49 +08002016
Ricky Liang45c73e72015-01-15 15:00:30 +08002017 def run_tests_with_status(self, statuses_to_run, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002018 """Runs all top-level tests with a particular status.
Jon Salz0405ab52012-03-16 15:26:52 +08002019
Jon Salz0697cbf2012-07-04 15:14:04 +08002020 All active tests, plus any tests to re-run, are reset.
Jon Salz57717ca2012-04-04 16:47:25 +08002021
Jon Salz0697cbf2012-07-04 15:14:04 +08002022 Args:
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002023 statuses_to_run: The particular status that caller wants to run.
Jon Salz0697cbf2012-07-04 15:14:04 +08002024 starting_at: If provided, only auto-runs tests beginning with
2025 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002026 root: The root of tests to run. If not provided, it will be
2027 the root of all tests.
2028 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002029 root = root or self.test_list
Jon Salz57717ca2012-04-04 16:47:25 +08002030
Jon Salz0697cbf2012-07-04 15:14:04 +08002031 if starting_at:
2032 # Make sure they passed a test, not a string.
2033 assert isinstance(starting_at, factory.FactoryTest)
Jon Salz0405ab52012-03-16 15:26:52 +08002034
Jon Salz0697cbf2012-07-04 15:14:04 +08002035 tests_to_reset = []
2036 tests_to_run = []
Jon Salz0405ab52012-03-16 15:26:52 +08002037
Jon Salz0697cbf2012-07-04 15:14:04 +08002038 found_starting_at = False
Jon Salz0405ab52012-03-16 15:26:52 +08002039
Jon Salz0697cbf2012-07-04 15:14:04 +08002040 for test in root.get_top_level_tests():
2041 if starting_at:
2042 if test == starting_at:
2043 # We've found starting_at; do auto-run on all
2044 # subsequent tests.
2045 found_starting_at = True
2046 if not found_starting_at:
2047 # Don't start this guy yet
2048 continue
Jon Salz0405ab52012-03-16 15:26:52 +08002049
Jon Salz0697cbf2012-07-04 15:14:04 +08002050 status = test.get_state().status
2051 if status == TestState.ACTIVE or status in statuses_to_run:
2052 # Reset the test (later; we will need to abort
2053 # all active tests first).
2054 tests_to_reset.append(test)
2055 if status in statuses_to_run:
2056 tests_to_run.append(test)
Jon Salz0405ab52012-03-16 15:26:52 +08002057
Jon Salz6dc031d2013-06-19 13:06:23 +08002058 self.abort_active_tests('Operator requested run/re-run of certain tests')
Jon Salz258a40c2012-04-19 12:34:01 +08002059
Jon Salz0697cbf2012-07-04 15:14:04 +08002060 # Reset all statuses of the tests to run (in case any tests were active;
2061 # we want them to be run again).
2062 for test_to_reset in tests_to_reset:
2063 for test in test_to_reset.walk():
2064 test.update_state(status=TestState.UNTESTED)
Jon Salz57717ca2012-04-04 16:47:25 +08002065
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08002066 self.run_tests(tests_to_run, [TestState.UNTESTED])
Jon Salz0405ab52012-03-16 15:26:52 +08002067
Jon Salz0697cbf2012-07-04 15:14:04 +08002068 def restart_tests(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002069 """Restarts all tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08002070 root = root or self.test_list
Jon Salz0405ab52012-03-16 15:26:52 +08002071
Jon Salz6dc031d2013-06-19 13:06:23 +08002072 self.abort_active_tests('Operator requested restart of certain tests')
Jon Salz0697cbf2012-07-04 15:14:04 +08002073 for test in root.walk():
Ricky Liangfea4ac92014-08-21 11:55:59 +08002074 test.update_state(status=TestState.UNTESTED)
Jon Salz0697cbf2012-07-04 15:14:04 +08002075 self.run_tests(root)
Hung-Te Lin96632362012-03-20 21:14:18 +08002076
Jon Salz0697cbf2012-07-04 15:14:04 +08002077 def auto_run(self, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002078 """"Auto-runs" tests that have not been run yet.
Hung-Te Lin96632362012-03-20 21:14:18 +08002079
Jon Salz0697cbf2012-07-04 15:14:04 +08002080 Args:
2081 starting_at: If provide, only auto-runs tests beginning with
2082 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002083 root: If provided, the root of tests to run. If not provided, the root
2084 will be test_list (root of all tests).
2085 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002086 root = root or self.test_list
2087 self.run_tests_with_status([TestState.UNTESTED, TestState.ACTIVE],
Ricky Liang45c73e72015-01-15 15:00:30 +08002088 starting_at=starting_at,
2089 root=root)
Jon Salz968e90b2012-03-18 16:12:43 +08002090
Jon Salz0697cbf2012-07-04 15:14:04 +08002091 def handle_switch_test(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002092 """Switches to a particular test.
Jon Salz0405ab52012-03-16 15:26:52 +08002093
Ricky Liang6fe218c2013-12-27 15:17:17 +08002094 Args:
2095 event: The SWITCH_TEST event.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002096 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002097 test = self.test_list.lookup_path(event.path)
2098 if not test:
2099 logging.error('Unknown test %r', event.key)
2100 return
Jon Salz73e0fd02012-04-04 11:46:38 +08002101
Jon Salz0697cbf2012-07-04 15:14:04 +08002102 invoc = self.invocations.get(test)
2103 if invoc and test.backgroundable:
2104 # Already running: just bring to the front if it
2105 # has a UI.
2106 logging.info('Setting visible test to %s', test.path)
Jon Salz36fbbb52012-07-05 13:45:06 +08002107 self.set_visible_test(test)
Jon Salz0697cbf2012-07-04 15:14:04 +08002108 return
Jon Salz73e0fd02012-04-04 11:46:38 +08002109
Jon Salz6dc031d2013-06-19 13:06:23 +08002110 self.abort_active_tests('Operator requested abort (switch_test)')
Jon Salz0697cbf2012-07-04 15:14:04 +08002111 for t in test.walk():
2112 t.update_state(status=TestState.UNTESTED)
Jon Salz73e0fd02012-04-04 11:46:38 +08002113
Jon Salz0697cbf2012-07-04 15:14:04 +08002114 if self.test_list.options.auto_run_on_keypress:
2115 self.auto_run(starting_at=test)
2116 else:
2117 self.run_tests(test)
Jon Salz73e0fd02012-04-04 11:46:38 +08002118
Wei-Ning Huang38b75f02015-02-25 18:25:14 +08002119 def handle_key_filter_mode(self, event):
2120 if self.key_filter:
2121 if getattr(event, 'enabled'):
2122 self.key_filter.Start()
2123 else:
2124 self.key_filter.Stop()
2125
Jon Salz0697cbf2012-07-04 15:14:04 +08002126 def wait(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002127 """Waits for all pending invocations.
Jon Salz0697cbf2012-07-04 15:14:04 +08002128
2129 Useful for testing.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002130 """
Jon Salz1acc8742012-07-17 17:45:55 +08002131 while self.invocations:
2132 for k, v in self.invocations.iteritems():
2133 logging.info('Waiting for %s to complete...', k)
2134 v.thread.join()
2135 self.reap_completed_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08002136
Claire Changd1961a22015-08-05 16:15:55 +08002137 def test_fail(self, test):
Hung-Te Lin410f70a2015-12-15 14:53:42 +08002138 self.dut.hooks.OnTestFailure(test)
Claire Changd1961a22015-08-05 16:15:55 +08002139 if self.link_manager:
2140 self.link_manager.UpdateStatus(False)
2141
Hung-Te Linf2f78f72012-02-08 19:27:11 +08002142if __name__ == '__main__':
Peter Ammona3d298c2014-09-23 10:11:02 -07002143 Goofy.run_main_and_exit()