blob: 0fde8c52cbe1fb35201e69fed5632822172e1e1e [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 Lin91492a12014-11-25 18:56:30 +080028from cros.factory.test import event_log
Joel Kitching9eb203a2016-04-21 15:36:30 +080029from cros.factory.test import log_writer
30from cros.factory.test import testlog
Joel Kitching4b1b6c02016-05-10 14:34:30 +080031from cros.factory.test.env import paths
Chun-Ta Lin5d12b592015-06-30 00:54:23 -070032from cros.factory.test.event_log import EventLog, FloatDigit, GetBootSequence
Hung-Te Lincc41d2a2014-10-29 13:35:20 +080033from cros.factory.goofy import connection_manager
Vic Yangd80ea752014-09-24 16:07:14 +080034from cros.factory.goofy import test_environment
35from cros.factory.goofy import time_sanitizer
36from cros.factory.goofy import updater
37from cros.factory.goofy.goofy_base import GoofyBase
38from cros.factory.goofy.goofy_rpc import GoofyRPC
39from cros.factory.goofy.invocation import TestArgEnv
40from cros.factory.goofy.invocation import TestInvocation
41from cros.factory.goofy.link_manager import PresenterLinkManager
Vic Yange2c76a82014-10-30 12:48:19 -070042from cros.factory.goofy import prespawner
Vic Yangd80ea752014-09-24 16:07:14 +080043from cros.factory.goofy.system_log_manager import SystemLogManager
Wei-Ning Huang38b75f02015-02-25 18:25:14 +080044from cros.factory.goofy.terminal_manager import TerminalManager
Vic Yangd80ea752014-09-24 16:07:14 +080045from cros.factory.goofy.web_socket_manager import WebSocketManager
Hung-Te Lin6a72c642015-12-13 22:09:09 +080046from cros.factory.test import dut
jcliangcd688182012-08-20 21:01:26 +080047from cros.factory.test import factory
Jon Salz51528e12012-07-02 18:54:45 +080048from cros.factory.test import shopfloor
Hung-Te Lin6a72c642015-12-13 22:09:09 +080049from cros.factory.test import state
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +080050from cros.factory.test.env import paths
Wei-Han Chene8a025f2016-01-14 16:42:02 +080051from cros.factory.test.dut import utils as dut_utils
Ricky Liang6fe218c2013-12-27 15:17:17 +080052from cros.factory.test.e2e_test.common import (
53 AutomationMode, AutomationModePrompt, ParseAutomationMode)
Jon Salz83591782012-06-26 11:09:58 +080054from cros.factory.test.event import Event
55from cros.factory.test.event import EventClient
56from cros.factory.test.event import EventServer
Hung-Te Lin91492a12014-11-25 18:56:30 +080057from cros.factory.test.event_log_watcher import EventLogWatcher
jcliangcd688182012-08-20 21:01:26 +080058from cros.factory.test.factory import TestState
Hung-Te Lin3f096842016-01-13 17:37:06 +080059from cros.factory.test.rules import phase
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +080060from cros.factory.test.test_lists import test_lists
Hung-Te Linc367ac02015-12-22 19:33:23 +080061from cros.factory.test.utils.charge_manager import ChargeManager
62from cros.factory.test.utils.core_dump_manager import CoreDumpManager
63from cros.factory.test.utils.cpufreq_manager import CpufreqManager
Dean Liao592e4d52013-01-10 20:06:39 +080064from cros.factory.tools.key_filter import KeyFilter
Hung-Te Lind3ee0102015-12-28 17:21:50 +080065from cros.factory.tools import disk_space
Hung-Te Linf707b242016-01-08 23:11:42 +080066from cros.factory.utils import debug_utils
Jon Salz2af235d2013-06-24 14:47:21 +080067from cros.factory.utils import file_utils
Joel Kitchingb85ed7f2014-10-08 18:24:39 +080068from cros.factory.utils import net_utils
Hung-Te Lin4e6357c2016-01-08 14:32:00 +080069from cros.factory.utils import process_utils
70from cros.factory.utils import sys_utils
71from cros.factory.utils import time_utils
Hung-Te Linf707b242016-01-08 23:11:42 +080072from cros.factory.utils import type_utils
Hung-Te Linf2f78f72012-02-08 19:27:11 +080073
74
Hung-Te Linf2f78f72012-02-08 19:27:11 +080075HWID_CFG_PATH = '/usr/local/share/chromeos-hwid/cfg'
Joel Kitching625ff0f2016-05-16 14:59:40 -070076CACHES_DIR = os.path.join(paths.GetStateRoot(), 'caches')
Hung-Te Linf2f78f72012-02-08 19:27:11 +080077
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +080078CLEANUP_LOGS_PAUSED = '/var/lib/cleanup_logs_paused'
79
Jon Salz5c344f62012-07-13 14:31:16 +080080# Value for tests_after_shutdown that forces auto-run (e.g., after
81# a factory update, when the available set of tests might change).
82FORCE_AUTO_RUN = 'force_auto_run'
83
Justin Chuang83813982013-05-13 01:26:32 +080084# Sync disks when battery level is higher than this value.
85# Otherwise, power loss during disk sync operation may incur even worse outcome.
86MIN_BATTERY_LEVEL_FOR_DISK_SYNC = 1.0
87
Ricky Liang45c73e72015-01-15 15:00:30 +080088MAX_CRASH_FILE_SIZE = 64 * 1024
Jon Salze12c2b32013-06-25 16:24:34 +080089
Hung-Te Linf707b242016-01-08 23:11:42 +080090Status = type_utils.Enum(['UNINITIALIZED', 'INITIALIZING', 'RUNNING',
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +080091 'TERMINATING', 'TERMINATED'])
Jon Salzd7550792013-07-12 05:49:27 +080092
Ricky Liang45c73e72015-01-15 15:00:30 +080093
Hung-Te Linf2f78f72012-02-08 19:27:11 +080094def get_hwid_cfg():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +080095 """Returns the HWID config tag, or an empty string if none can be found."""
Jon Salz0697cbf2012-07-04 15:14:04 +080096 if 'CROS_HWID' in os.environ:
97 return os.environ['CROS_HWID']
98 if os.path.exists(HWID_CFG_PATH):
Ricky Liang45c73e72015-01-15 15:00:30 +080099 with open(HWID_CFG_PATH, 'r') as hwid_cfg_handle:
Jon Salz0697cbf2012-07-04 15:14:04 +0800100 return hwid_cfg_handle.read().strip()
101 return ''
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800102
103
Jon Salz73e0fd02012-04-04 11:46:38 +0800104_inited_logging = False
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800105
Ricky Liang45c73e72015-01-15 15:00:30 +0800106
Peter Ammon1e1ec572014-06-26 17:56:32 -0700107class Goofy(GoofyBase):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800108 """The main factory flow.
Jon Salz0697cbf2012-07-04 15:14:04 +0800109
110 Note that all methods in this class must be invoked from the main
111 (event) thread. Other threads, such as callbacks and TestInvocation
112 methods, should instead post events on the run queue.
113
114 TODO: Unit tests. (chrome-os-partner:7409)
115
116 Properties:
117 uuid: A unique UUID for this invocation of Goofy.
118 state_instance: An instance of FactoryState.
119 state_server: The FactoryState XML/RPC server.
120 state_server_thread: A thread running state_server.
121 event_server: The EventServer socket server.
122 event_server_thread: A thread running event_server.
123 event_client: A client to the event server.
124 connection_manager: The connection_manager object.
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800125 system_log_manager: The SystemLogManager object.
126 core_dump_manager: The CoreDumpManager object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800127 ui_process: The factory ui process object.
Jon Salz0697cbf2012-07-04 15:14:04 +0800128 invocations: A map from FactoryTest objects to the corresponding
129 TestInvocations objects representing active tests.
130 tests_to_run: A deque of tests that should be run when the current
131 test(s) complete.
132 options: Command-line options.
133 args: Command-line args.
134 test_list: The test list.
Jon Salz128b0932013-07-03 16:55:26 +0800135 test_lists: All new-style test lists.
Ricky Liang4bff3e32014-02-20 18:46:11 +0800136 run_id: The identifier for latest test run.
137 scheduled_run_tests: The list of tests scheduled for latest test run.
Jon Salz0697cbf2012-07-04 15:14:04 +0800138 event_handlers: Map of Event.Type to the method used to handle that
139 event. If the method has an 'event' argument, the event is passed
140 to the handler.
Jon Salz3c493bb2013-02-07 17:24:58 +0800141 last_log_disk_space_message: The last message we logged about disk space
142 (to avoid duplication).
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800143 last_kick_sync_time: The last time to kick system_log_manager to sync
144 because of core dump files (to avoid kicking too soon then abort the
145 sync.)
Jon Salz416f9cc2013-05-10 18:32:50 +0800146 hooks: A Hooks object containing hooks for various Goofy actions.
Jon Salzd7550792013-07-12 05:49:27 +0800147 status: The current Goofy status (a member of the Status enum).
Peter Ammon948b7172014-07-15 12:43:06 -0700148 link_manager: Instance of PresenterLinkManager for communicating
149 with GoofyPresenter
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800150 """
Ricky Liang45c73e72015-01-15 15:00:30 +0800151
Jon Salz0697cbf2012-07-04 15:14:04 +0800152 def __init__(self):
Peter Ammon1e1ec572014-06-26 17:56:32 -0700153 super(Goofy, self).__init__()
Jon Salz0697cbf2012-07-04 15:14:04 +0800154 self.uuid = str(uuid.uuid4())
155 self.state_instance = None
156 self.state_server = None
157 self.state_server_thread = None
Jon Salz16d10542012-07-23 12:18:45 +0800158 self.goofy_rpc = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800159 self.event_server = None
160 self.event_server_thread = None
161 self.event_client = None
162 self.connection_manager = None
Vic Yang4953fc12012-07-26 16:19:53 +0800163 self.charge_manager = None
Dean Liao88b93192014-10-23 19:37:41 +0800164 self._can_charge = True
Jon Salz8fa8e832012-07-13 19:04:09 +0800165 self.time_sanitizer = None
166 self.time_synced = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800167 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800168 self.system_log_manager = None
Cheng-Yi Chiang835f2682013-05-06 22:15:48 +0800169 self.core_dump_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800170 self.event_log = None
Joel Kitching9eb203a2016-04-21 15:36:30 +0800171 self.log_writer = None
Vic Yange2c76a82014-10-30 12:48:19 -0700172 self.autotest_prespawner = None
173 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800174 self.ui_process = None
Vic Yanga3cecf82014-12-26 00:44:21 -0800175 self._ui_initialized = False
Jon Salzc79a9982012-08-30 04:42:01 +0800176 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800177 self.invocations = {}
178 self.tests_to_run = deque()
179 self.visible_test = None
180 self.chrome = None
Jon Salz416f9cc2013-05-10 18:32:50 +0800181 self.hooks = None
Vic Yangd8990da2013-06-27 16:57:43 +0800182 self.cpu_usage_watcher = None
Hung-Te Lin23cb7612016-01-19 19:19:32 +0800183 self.thermal_watcher = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800184
185 self.options = None
186 self.args = None
187 self.test_list = None
Jon Salz128b0932013-07-03 16:55:26 +0800188 self.test_lists = None
Ricky Liang4bff3e32014-02-20 18:46:11 +0800189 self.run_id = None
190 self.scheduled_run_tests = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800191 self.env = None
Jon Salzb22d1172012-08-06 10:38:57 +0800192 self.last_idle = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800193 self.last_shutdown_time = None
cychiang21886742012-07-05 15:16:32 +0800194 self.last_update_check = None
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800195 self._suppress_periodic_update_messages = False
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +0800196 self._suppress_event_log_error_messages = False
Jon Salz8fa8e832012-07-13 19:04:09 +0800197 self.last_sync_time = None
Jon Salzb92c5112012-09-21 15:40:11 +0800198 self.last_log_disk_space_time = None
Jon Salz3c493bb2013-02-07 17:24:58 +0800199 self.last_log_disk_space_message = None
Justin Chuang83813982013-05-13 01:26:32 +0800200 self.last_check_battery_time = None
201 self.last_check_battery_message = None
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +0800202 self.last_kick_sync_time = None
Vic Yang311ddb82012-09-26 12:08:28 +0800203 self.exclusive_items = set()
Dean Liao592e4d52013-01-10 20:06:39 +0800204 self.key_filter = None
Jon Salzce6a7f82013-06-10 18:22:54 +0800205 self.cpufreq_manager = None
Jon Salzd7550792013-07-12 05:49:27 +0800206 self.status = Status.UNINITIALIZED
Ricky Liang36512a32014-07-25 11:47:04 +0800207 self.ready_for_ui_connection = False
Peter Ammon1e1ec572014-06-26 17:56:32 -0700208 self.link_manager = None
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800209 self.is_restart_requested = False
Jon Salz0697cbf2012-07-04 15:14:04 +0800210
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800211 # TODO(hungte) Support controlling remote DUT.
212 self.dut = dut.Create()
213
Jon Salz85a39882012-07-05 16:45:04 +0800214 def test_or_root(event, parent_or_group=True):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800215 """Returns the test affected by a particular event.
Jon Salz85a39882012-07-05 16:45:04 +0800216
217 Args:
218 event: The event containing an optional 'path' attribute.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800219 parent_or_group: If True, returns the top-level parent for a test (the
Jon Salz85a39882012-07-05 16:45:04 +0800220 root node of the tests that need to be run together if the given test
221 path is to be run).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800222 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800223 try:
224 path = event.path
225 except AttributeError:
226 path = None
227
228 if path:
Jon Salz85a39882012-07-05 16:45:04 +0800229 test = self.test_list.lookup_path(path)
230 if parent_or_group:
231 test = test.get_top_level_parent_or_group()
232 return test
Jon Salz0697cbf2012-07-04 15:14:04 +0800233 else:
234 return self.test_list
235
236 self.event_handlers = {
Ricky Liang45c73e72015-01-15 15:00:30 +0800237 Event.Type.SWITCH_TEST: self.handle_switch_test,
238 Event.Type.SHOW_NEXT_ACTIVE_TEST:
239 lambda event: self.show_next_active_test(),
240 Event.Type.RESTART_TESTS:
241 lambda event: self.restart_tests(root=test_or_root(event)),
242 Event.Type.AUTO_RUN:
243 lambda event: self.auto_run(root=test_or_root(event)),
244 Event.Type.RE_RUN_FAILED:
245 lambda event: self.re_run_failed(root=test_or_root(event)),
246 Event.Type.RUN_TESTS_WITH_STATUS:
247 lambda event: self.run_tests_with_status(
248 event.status,
249 root=test_or_root(event)),
250 Event.Type.REVIEW:
251 lambda event: self.show_review_information(),
252 Event.Type.UPDATE_SYSTEM_INFO:
253 lambda event: self.update_system_info(),
254 Event.Type.STOP:
255 lambda event: self.stop(root=test_or_root(event, False),
256 fail=getattr(event, 'fail', False),
257 reason=getattr(event, 'reason', None)),
258 Event.Type.SET_VISIBLE_TEST:
259 lambda event: self.set_visible_test(
260 self.test_list.lookup_path(event.path)),
261 Event.Type.CLEAR_STATE:
262 lambda event: self.clear_state(
263 self.test_list.lookup_path(event.path)),
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800264 Event.Type.KEY_FILTER_MODE: self.handle_key_filter_mode,
Jon Salz0697cbf2012-07-04 15:14:04 +0800265 }
266
Jon Salz0697cbf2012-07-04 15:14:04 +0800267 self.web_socket_manager = None
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800268 self.terminal_manager = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800269
270 def destroy(self):
Ricky Liang74237a02014-09-18 15:11:23 +0800271 """Performs any shutdown tasks. Overrides base class method."""
Jon Salzd7550792013-07-12 05:49:27 +0800272 self.status = Status.TERMINATING
Jon Salz0697cbf2012-07-04 15:14:04 +0800273 if self.chrome:
274 self.chrome.kill()
275 self.chrome = None
Jon Salzc79a9982012-08-30 04:42:01 +0800276 if self.dummy_shopfloor:
277 self.dummy_shopfloor.kill()
278 self.dummy_shopfloor = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800279 if self.ui_process:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800280 process_utils.KillProcessTree(self.ui_process, 'ui')
Jon Salz0697cbf2012-07-04 15:14:04 +0800281 self.ui_process = None
282 if self.web_socket_manager:
283 logging.info('Stopping web sockets')
284 self.web_socket_manager.close()
285 self.web_socket_manager = None
286 if self.state_server_thread:
287 logging.info('Stopping state server')
288 self.state_server.shutdown()
289 self.state_server_thread.join()
290 self.state_server.server_close()
291 self.state_server_thread = None
292 if self.state_instance:
293 self.state_instance.close()
294 if self.event_server_thread:
295 logging.info('Stopping event server')
296 self.event_server.shutdown() # pylint: disable=E1101
297 self.event_server_thread.join()
298 self.event_server.server_close()
299 self.event_server_thread = None
300 if self.log_watcher:
301 if self.log_watcher.IsThreadStarted():
302 self.log_watcher.StopWatchThread()
303 self.log_watcher = None
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800304 if self.system_log_manager:
305 if self.system_log_manager.IsThreadRunning():
Cheng-Yi Chianga0f6eff2014-01-09 18:27:22 +0800306 self.system_log_manager.Stop()
Cheng-Yi Chiang344b10f2013-05-03 16:44:03 +0800307 self.system_log_manager = None
Vic Yange2c76a82014-10-30 12:48:19 -0700308 if self.autotest_prespawner:
309 logging.info('Stopping autotest prespawner')
310 self.autotest_prespawner.stop()
311 self.autotest_prespawner = None
312 if self.pytest_prespawner:
313 logging.info('Stopping pytest prespawner')
314 self.pytest_prespawner.stop()
315 self.pytest_prespawner = None
Jon Salz0697cbf2012-07-04 15:14:04 +0800316 if self.event_client:
317 logging.info('Closing event client')
318 self.event_client.close()
319 self.event_client = None
Jon Salzddf0d052013-06-18 12:52:44 +0800320 if self.cpufreq_manager:
321 self.cpufreq_manager.Stop()
Jon Salz0697cbf2012-07-04 15:14:04 +0800322 if self.event_log:
323 self.event_log.Close()
324 self.event_log = None
Joel Kitching9eb203a2016-04-21 15:36:30 +0800325 if self.log_writer:
326 self.log_writer.Close()
327 self.log_writer = None
Dean Liao592e4d52013-01-10 20:06:39 +0800328 if self.key_filter:
329 self.key_filter.Stop()
Vic Yangd8990da2013-06-27 16:57:43 +0800330 if self.cpu_usage_watcher:
331 self.cpu_usage_watcher.terminate()
Hung-Te Lin23cb7612016-01-19 19:19:32 +0800332 if self.thermal_watcher:
333 self.thermal_watcher.terminate()
Peter Ammon1e1ec572014-06-26 17:56:32 -0700334 if self.link_manager:
335 self.link_manager.Stop()
336 self.link_manager = None
Dean Liao592e4d52013-01-10 20:06:39 +0800337
Peter Ammon1e1ec572014-06-26 17:56:32 -0700338 super(Goofy, self).destroy()
Jon Salz0697cbf2012-07-04 15:14:04 +0800339 logging.info('Done destroying Goofy')
Jon Salzd7550792013-07-12 05:49:27 +0800340 self.status = Status.TERMINATED
Jon Salz0697cbf2012-07-04 15:14:04 +0800341
342 def start_state_server(self):
Jon Salz2af235d2013-06-24 14:47:21 +0800343 # Before starting state server, remount stateful partitions with
344 # no commit flag. The default commit time (commit=600) makes corruption
345 # too likely.
Hung-Te Lin1968d9c2016-01-08 22:55:46 +0800346 sys_utils.ResetCommitTime()
Jon Salz2af235d2013-06-24 14:47:21 +0800347
Jon Salz0697cbf2012-07-04 15:14:04 +0800348 self.state_instance, self.state_server = (
Ricky Liang45c73e72015-01-15 15:00:30 +0800349 state.create_server(bind_address='0.0.0.0'))
Jon Salz16d10542012-07-23 12:18:45 +0800350 self.goofy_rpc = GoofyRPC(self)
351 self.goofy_rpc.RegisterMethods(self.state_instance)
Jon Salz0697cbf2012-07-04 15:14:04 +0800352 logging.info('Starting state server')
353 self.state_server_thread = threading.Thread(
Ricky Liang45c73e72015-01-15 15:00:30 +0800354 target=self.state_server.serve_forever,
355 name='StateServer')
Jon Salz0697cbf2012-07-04 15:14:04 +0800356 self.state_server_thread.start()
357
358 def start_event_server(self):
359 self.event_server = EventServer()
360 logging.info('Starting factory event server')
361 self.event_server_thread = threading.Thread(
Ricky Liang45c73e72015-01-15 15:00:30 +0800362 target=self.event_server.serve_forever,
363 name='EventServer') # pylint: disable=E1101
Jon Salz0697cbf2012-07-04 15:14:04 +0800364 self.event_server_thread.start()
365
366 self.event_client = EventClient(
Ricky Liang45c73e72015-01-15 15:00:30 +0800367 callback=self.handle_event, event_loop=self.run_queue)
Jon Salz0697cbf2012-07-04 15:14:04 +0800368
369 self.web_socket_manager = WebSocketManager(self.uuid)
Ricky Liang45c73e72015-01-15 15:00:30 +0800370 self.state_server.add_handler('/event',
371 self.web_socket_manager.handle_web_socket)
Jon Salz0697cbf2012-07-04 15:14:04 +0800372
Wei-Ning Huang38b75f02015-02-25 18:25:14 +0800373 def start_terminal_server(self):
374 self.terminal_manager = TerminalManager()
375 self.state_server.add_handler('/pty',
376 self.terminal_manager.handle_web_socket)
377
Jon Salz0697cbf2012-07-04 15:14:04 +0800378 def start_ui(self):
379 ui_proc_args = [
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +0800380 os.path.join(paths.FACTORY_PACKAGE_PATH, 'test', 'ui.py'),
Ricky Liang45c73e72015-01-15 15:00:30 +0800381 self.options.test_list
382 ]
Jon Salz0697cbf2012-07-04 15:14:04 +0800383 if self.options.verbose:
384 ui_proc_args.append('-v')
385 logging.info('Starting ui %s', ui_proc_args)
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800386 self.ui_process = process_utils.Spawn(ui_proc_args)
Jon Salz0697cbf2012-07-04 15:14:04 +0800387 logging.info('Waiting for UI to come up...')
388 self.event_client.wait(
Ricky Liang45c73e72015-01-15 15:00:30 +0800389 lambda event: event.type == Event.Type.UI_READY)
Jon Salz0697cbf2012-07-04 15:14:04 +0800390 logging.info('UI has started')
391
392 def set_visible_test(self, test):
393 if self.visible_test == test:
394 return
Jon Salz2f2d42c2012-07-30 12:30:34 +0800395 if test and not test.has_ui:
396 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800397
398 if test:
399 test.update_state(visible=True)
400 if self.visible_test:
401 self.visible_test.update_state(visible=False)
402 self.visible_test = test
403
Ricky Liang48e47f92014-02-26 19:31:51 +0800404 def log_startup_messages(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800405 """Logs the tail of var/log/messages and mosys and EC console logs."""
Jon Salzd4306c82012-11-30 15:16:36 +0800406 # TODO(jsalz): This is mostly a copy-and-paste of code in init_states,
407 # for factory-3004.B only. Consolidate and merge back to ToT.
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800408 if sys_utils.InChroot():
Jon Salzd4306c82012-11-30 15:16:36 +0800409 return
410
411 try:
Hung-Te Lin1a4e30c2016-01-08 23:25:10 +0800412 var_log_messages = sys_utils.GetVarLogMessagesBeforeReboot()
Jon Salzd4306c82012-11-30 15:16:36 +0800413 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +0800414 'Tail of /var/log/messages before last reboot:\n'
415 '%s', ('\n'.join(
416 ' ' + x for x in var_log_messages)))
Jon Salzd4306c82012-11-30 15:16:36 +0800417 except: # pylint: disable=W0702
418 logging.exception('Unable to grok /var/log/messages')
419
420 try:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800421 mosys_log = process_utils.Spawn(
Jon Salzd4306c82012-11-30 15:16:36 +0800422 ['mosys', 'eventlog', 'list'],
423 read_stdout=True, log_stderr_on_error=True).stdout_data
424 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
425 except: # pylint: disable=W0702
426 logging.exception('Unable to read mosys eventlog')
427
Dean Liao88b93192014-10-23 19:37:41 +0800428 self.log_ec_console()
429 self.log_ec_panic_info()
430
431 @staticmethod
432 def log_ec_console():
433 """Logs EC console log into logging.info.
434
435 It logs an error message in logging.exception if an exception is raised
436 when getting EC console log.
437 For unsupported device, it logs unsupport message in logging.info
438
439 Returns:
440 EC console log string.
441 """
Jon Salzd4306c82012-11-30 15:16:36 +0800442 try:
Hung-Te Linb3a09642015-12-14 18:57:23 +0800443 ec_console_log = dut.Create().ec.GetECConsoleLog()
Jon Salzd4306c82012-11-30 15:16:36 +0800444 logging.info('EC console log after reboot:\n%s\n', ec_console_log)
Dean Liao88b93192014-10-23 19:37:41 +0800445 return ec_console_log
446 except NotImplementedError:
447 logging.info('EC console log not supported')
Jon Salzd4306c82012-11-30 15:16:36 +0800448 except: # pylint: disable=W0702
449 logging.exception('Error retrieving EC console log')
450
Dean Liao88b93192014-10-23 19:37:41 +0800451 @staticmethod
452 def log_ec_panic_info():
453 """Logs EC panic info into logging.info.
454
455 It logs an error message in logging.exception if an exception is raised
456 when getting EC panic info.
457 For unsupported device, it logs unsupport message in logging.info
458
459 Returns:
460 EC panic info string.
461 """
Vic Yang079f9872013-07-01 11:32:00 +0800462 try:
Hung-Te Linb3a09642015-12-14 18:57:23 +0800463 ec_panic_info = dut.Create().ec.GetECPanicInfo()
Vic Yang079f9872013-07-01 11:32:00 +0800464 logging.info('EC panic info after reboot:\n%s\n', ec_panic_info)
Dean Liao88b93192014-10-23 19:37:41 +0800465 return ec_panic_info
466 except NotImplementedError:
467 logging.info('EC panic info is not supported')
Vic Yang079f9872013-07-01 11:32:00 +0800468 except: # pylint: disable=W0702
469 logging.exception('Error retrieving EC panic info')
470
Ricky Liang48e47f92014-02-26 19:31:51 +0800471 def shutdown(self, operation):
472 """Starts shutdown procedure.
473
474 Args:
Vic (Chun-Ju) Yang05b0d952014-04-28 17:39:09 +0800475 operation: The shutdown operation (reboot, full_reboot, or halt).
Ricky Liang48e47f92014-02-26 19:31:51 +0800476 """
477 active_tests = []
478 for test in self.test_list.walk():
479 if not test.is_leaf():
480 continue
481
482 test_state = test.get_state()
483 if test_state.status == TestState.ACTIVE:
484 active_tests.append(test)
485
Ricky Liang48e47f92014-02-26 19:31:51 +0800486 if not (len(active_tests) == 1 and
487 isinstance(active_tests[0], factory.ShutdownStep)):
488 logging.error(
489 'Calling Goofy shutdown outside of the shutdown factory test')
490 return
491
492 logging.info('Start Goofy shutdown (%s)', operation)
493 # Save pending test list in the state server
494 self.state_instance.set_shared_data(
495 'tests_after_shutdown',
496 [t.path for t in self.tests_to_run])
497 # Save shutdown time
498 self.state_instance.set_shared_data('shutdown_time', time.time())
499
500 with self.env.lock:
501 self.event_log.Log('shutdown', operation=operation)
502 shutdown_result = self.env.shutdown(operation)
503 if shutdown_result:
504 # That's all, folks!
Peter Ammon1e1ec572014-06-26 17:56:32 -0700505 self.run_enqueue(None)
Ricky Liang48e47f92014-02-26 19:31:51 +0800506 else:
507 # Just pass (e.g., in the chroot).
508 self.state_instance.set_shared_data('tests_after_shutdown', None)
509 # Send event with no fields to indicate that there is no
510 # longer a pending shutdown.
511 self.event_client.post_event(Event(Event.Type.PENDING_SHUTDOWN))
512
513 def handle_shutdown_complete(self, test):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800514 """Handles the case where a shutdown was detected during a shutdown step.
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800515
Ricky Liang6fe218c2013-12-27 15:17:17 +0800516 Args:
517 test: The ShutdownStep.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800518 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800519 test_state = test.update_state(increment_shutdown_count=1)
520 logging.info('Detected shutdown (%d of %d)',
Ricky Liang48e47f92014-02-26 19:31:51 +0800521 test_state.shutdown_count, test.iterations)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800522
Ricky Liang48e47f92014-02-26 19:31:51 +0800523 # Insert current shutdown test at the front of the list of tests to run
524 # after shutdown. This is to continue on post-shutdown verification in the
525 # shutdown step.
526 tests_after_shutdown = self.state_instance.get_shared_data(
527 'tests_after_shutdown', optional=True)
528 if not tests_after_shutdown:
529 self.state_instance.set_shared_data('tests_after_shutdown', [test.path])
530 elif isinstance(tests_after_shutdown, list):
531 self.state_instance.set_shared_data(
532 'tests_after_shutdown', [test.path] + tests_after_shutdown)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800533
Ricky Liang48e47f92014-02-26 19:31:51 +0800534 # Set 'post_shutdown' to inform shutdown test that a shutdown just occurred.
Ricky Liangb7eb8772014-09-15 18:05:22 +0800535 self.state_instance.set_shared_data(
536 state.POST_SHUTDOWN_TAG % test.path,
537 self.state_instance.get_test_state(test.path).invocation)
Jon Salz258a40c2012-04-19 12:34:01 +0800538
Jon Salz0697cbf2012-07-04 15:14:04 +0800539 def init_states(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800540 """Initializes all states on startup."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800541 for test in self.test_list.get_all_tests():
542 # Make sure the state server knows about all the tests,
543 # defaulting to an untested state.
544 test.update_state(update_parent=False, visible=False)
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800545
Jon Salz0697cbf2012-07-04 15:14:04 +0800546 var_log_messages = None
Vic Yanga9c32212012-08-16 20:07:54 +0800547 mosys_log = None
Vic Yange4c275d2012-08-28 01:50:20 +0800548 ec_console_log = None
Vic Yang079f9872013-07-01 11:32:00 +0800549 ec_panic_info = None
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800550
Jon Salz0697cbf2012-07-04 15:14:04 +0800551 # Any 'active' tests should be marked as failed now.
552 for test in self.test_list.walk():
Jon Salza6711d72012-07-18 14:33:03 +0800553 if not test.is_leaf():
554 # Don't bother with parents; they will be updated when their
555 # children are updated.
556 continue
557
Jon Salz0697cbf2012-07-04 15:14:04 +0800558 test_state = test.get_state()
559 if test_state.status != TestState.ACTIVE:
560 continue
561 if isinstance(test, factory.ShutdownStep):
562 # Shutdown while the test was active - that's good.
Ricky Liang48e47f92014-02-26 19:31:51 +0800563 self.handle_shutdown_complete(test)
Jon Salz0697cbf2012-07-04 15:14:04 +0800564 else:
565 # Unexpected shutdown. Grab /var/log/messages for context.
566 if var_log_messages is None:
567 try:
568 var_log_messages = (
Hung-Te Lin1a4e30c2016-01-08 23:25:10 +0800569 sys_utils.GetVarLogMessagesBeforeReboot())
Jon Salz0697cbf2012-07-04 15:14:04 +0800570 # Write it to the log, to make it easier to
571 # correlate with /var/log/messages.
572 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +0800573 'Unexpected shutdown. '
574 'Tail of /var/log/messages before last reboot:\n'
575 '%s', ('\n'.join(
576 ' ' + x for x in var_log_messages)))
Jon Salz0697cbf2012-07-04 15:14:04 +0800577 except: # pylint: disable=W0702
578 logging.exception('Unable to grok /var/log/messages')
579 var_log_messages = []
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800580
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800581 if mosys_log is None and not sys_utils.InChroot():
Jon Salz008f4ea2012-08-28 05:39:45 +0800582 try:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +0800583 mosys_log = process_utils.Spawn(
Jon Salz008f4ea2012-08-28 05:39:45 +0800584 ['mosys', 'eventlog', 'list'],
585 read_stdout=True, log_stderr_on_error=True).stdout_data
586 # Write it to the log also.
587 logging.info('System eventlog from mosys:\n%s\n', mosys_log)
588 except: # pylint: disable=W0702
589 logging.exception('Unable to read mosys eventlog')
Vic Yanga9c32212012-08-16 20:07:54 +0800590
Vic Yange4c275d2012-08-28 01:50:20 +0800591 if ec_console_log is None:
Dean Liao88b93192014-10-23 19:37:41 +0800592 ec_console_log = self.log_ec_console()
Vic Yange4c275d2012-08-28 01:50:20 +0800593
Vic Yang079f9872013-07-01 11:32:00 +0800594 if ec_panic_info is None:
Dean Liao88b93192014-10-23 19:37:41 +0800595 ec_panic_info = self.log_ec_panic_info()
Vic Yang079f9872013-07-01 11:32:00 +0800596
Jon Salz0697cbf2012-07-04 15:14:04 +0800597 error_msg = 'Unexpected shutdown while test was running'
598 self.event_log.Log('end_test',
Ricky Liang45c73e72015-01-15 15:00:30 +0800599 path=test.path,
600 status=TestState.FAILED,
601 invocation=test.get_state().invocation,
602 error_msg=error_msg,
603 var_log_messages='\n'.join(var_log_messages),
604 mosys_log=mosys_log)
Jon Salz0697cbf2012-07-04 15:14:04 +0800605 test.update_state(
Ricky Liang45c73e72015-01-15 15:00:30 +0800606 status=TestState.FAILED,
607 error_msg=error_msg)
Chun-Ta Lin87c2dac2015-05-02 01:35:01 -0700608 # Trigger the OnTestFailure callback.
Claire Changd1961a22015-08-05 16:15:55 +0800609 self.run_queue.put(lambda: self.test_fail(test))
Hung-Te Linf2f78f72012-02-08 19:27:11 +0800610
Jon Salz50efe942012-07-26 11:54:10 +0800611 if not test.never_fails:
612 # For "never_fails" tests (such as "Start"), don't cancel
613 # pending tests, since reboot is expected.
614 factory.console.info('Unexpected shutdown while test %s '
615 'running; cancelling any pending tests',
616 test.path)
617 self.state_instance.set_shared_data('tests_after_shutdown', [])
Jon Salz69806bb2012-07-20 18:05:02 +0800618
Jon Salz008f4ea2012-08-28 05:39:45 +0800619 self.update_skipped_tests()
620
621 def update_skipped_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800622 """Updates skipped states based on run_if."""
Jon Salz885dcac2013-07-23 16:39:50 +0800623 env = TestArgEnv()
Ricky Liang45c73e72015-01-15 15:00:30 +0800624
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800625 def _evaluate_skip_from_run_if(test):
626 """Returns the run_if evaluation of the test.
627
628 Args:
629 test: A FactoryTest object.
630
631 Returns:
632 The run_if evaluation result. Returns False if the test has no
633 run_if argument.
634 """
635 value = None
636 if test.run_if_expr:
637 try:
638 value = test.run_if_expr(env)
639 except: # pylint: disable=W0702
640 logging.exception('Unable to evaluate run_if expression for %s',
641 test.path)
642 # But keep going; we have no choice. This will end up
643 # always activating the test.
644 elif test.run_if_table_name:
645 try:
646 aux = shopfloor.get_selected_aux_data(test.run_if_table_name)
647 value = aux.get(test.run_if_col)
648 except ValueError:
649 # Not available; assume it shouldn't be skipped
650 pass
651
652 if value is None:
653 skip = False
654 else:
655 skip = (not value) ^ t.run_if_not
656 return skip
657
658 # Gets all run_if evaluation, and stores results in skip_map.
659 skip_map = dict()
Jon Salz008f4ea2012-08-28 05:39:45 +0800660 for t in self.test_list.walk():
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800661 skip_map[t.path] = _evaluate_skip_from_run_if(t)
Jon Salz885dcac2013-07-23 16:39:50 +0800662
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800663 # Propagates the skip value from root of tree and updates skip_map.
664 def _update_skip_map_from_node(test, skip_from_parent):
665 """Updates skip_map from a given node.
Jon Salz885dcac2013-07-23 16:39:50 +0800666
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800667 Given a FactoryTest node and the skip value from parent, updates the
668 skip value of current node in the skip_map if skip value from parent is
669 True. If this node has children, recursively propagate this value to all
670 its children, that is, all its subtests.
671 Note that this function only updates value in skip_map, not the actual
672 test_list tree.
Jon Salz008f4ea2012-08-28 05:39:45 +0800673
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800674 Args:
675 test: The given FactoryTest object. It is a node in the test_list tree.
676 skip_from_parent: The skip value which propagates from the parent of
677 input node.
678 """
679 skip_this_tree = skip_from_parent or skip_map[test.path]
680 if skip_this_tree:
681 logging.info('Skip from node %r', test.path)
682 skip_map[test.path] = True
683 if test.is_leaf():
684 return
685 # Propagates skip value to its subtests
686 for subtest in test.subtests:
687 _update_skip_map_from_node(subtest, skip_this_tree)
688
689 _update_skip_map_from_node(self.test_list, False)
690
691 # Updates the skip value from skip_map to test_list tree. Also, updates test
692 # status if needed.
693 for t in self.test_list.walk():
694 skip = skip_map[t.path]
695 test_state = t.get_state()
696 if ((not skip) and
697 (test_state.status == TestState.PASSED) and
698 (test_state.error_msg == TestState.SKIPPED_MSG)):
699 # It was marked as skipped before, but now we need to run it.
700 # Mark as untested.
701 t.update_state(skip=skip, status=TestState.UNTESTED, error_msg='')
702 else:
703 t.update_state(skip=skip)
Jon Salz008f4ea2012-08-28 05:39:45 +0800704
Jon Salz0697cbf2012-07-04 15:14:04 +0800705 def show_next_active_test(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800706 """Rotates to the next visible active test."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800707 self.reap_completed_tests()
708 active_tests = [
Ricky Liang45c73e72015-01-15 15:00:30 +0800709 t for t in self.test_list.walk()
710 if t.is_leaf() and t.get_state().status == TestState.ACTIVE]
Jon Salz0697cbf2012-07-04 15:14:04 +0800711 if not active_tests:
712 return
Jon Salz4f6c7172012-06-11 20:45:36 +0800713
Jon Salz0697cbf2012-07-04 15:14:04 +0800714 try:
715 next_test = active_tests[
Ricky Liang45c73e72015-01-15 15:00:30 +0800716 (active_tests.index(self.visible_test) + 1) % len(active_tests)]
Jon Salz0697cbf2012-07-04 15:14:04 +0800717 except ValueError: # visible_test not present in active_tests
718 next_test = active_tests[0]
Jon Salz4f6c7172012-06-11 20:45:36 +0800719
Jon Salz0697cbf2012-07-04 15:14:04 +0800720 self.set_visible_test(next_test)
Jon Salz4f6c7172012-06-11 20:45:36 +0800721
Jon Salz0697cbf2012-07-04 15:14:04 +0800722 def handle_event(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800723 """Handles an event from the event server."""
Jon Salz0697cbf2012-07-04 15:14:04 +0800724 handler = self.event_handlers.get(event.type)
725 if handler:
726 handler(event)
727 else:
728 # We don't register handlers for all event types - just ignore
729 # this event.
730 logging.debug('Unbound event type %s', event.type)
Jon Salz4f6c7172012-06-11 20:45:36 +0800731
Vic Yangaabf9fd2013-04-09 18:56:13 +0800732 def check_critical_factory_note(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800733 """Returns True if the last factory note is critical."""
Vic Yangaabf9fd2013-04-09 18:56:13 +0800734 notes = self.state_instance.get_shared_data('factory_note', True)
735 return notes and notes[-1]['level'] == 'CRITICAL'
736
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800737 def schedule_restart(self):
738 """Schedules a restart event when any invocation is completed."""
739 self.is_restart_requested = True
740
741 def invocation_completion(self):
742 """Callback when an invocation is completed."""
743 if self.is_restart_requested:
744 logging.info('Restart by scheduled event.')
745 self.is_restart_requested = False
746 self.restart_tests()
747 else:
748 self.run_next_test()
749
Jon Salz0697cbf2012-07-04 15:14:04 +0800750 def run_next_test(self):
henryhsu4cc6b022014-04-22 17:12:42 +0800751 """Runs the next eligible test (or tests) in self.tests_to_run.
752
753 We have three kinds of the next eligible test:
754 1. normal
755 2. backgroundable
756 3. force_background
757
758 And we have four situations of the ongoing invocations:
759 a. only a running normal test
760 b. all running tests are backgroundable
761 c. all running tests are force_background
762 d. all running tests are any combination of backgroundable and
763 force_background
764
765 When a test would like to be run, it must follow the rules:
766 [1] cannot run with [abd]
767 [2] cannot run with [a]
768 All the other combinations are allowed
769 """
Jon Salz0697cbf2012-07-04 15:14:04 +0800770 self.reap_completed_tests()
Vic Yangaabf9fd2013-04-09 18:56:13 +0800771 if self.tests_to_run and self.check_critical_factory_note():
772 self.tests_to_run.clear()
773 return
Jon Salz0697cbf2012-07-04 15:14:04 +0800774 while self.tests_to_run:
Ricky Liang6fe218c2013-12-27 15:17:17 +0800775 logging.debug('Tests to run: %s', [x.path for x in self.tests_to_run])
Jon Salz94eb56f2012-06-12 18:01:12 +0800776
Jon Salz0697cbf2012-07-04 15:14:04 +0800777 test = self.tests_to_run[0]
Jon Salz94eb56f2012-06-12 18:01:12 +0800778
Jon Salz0697cbf2012-07-04 15:14:04 +0800779 if test in self.invocations:
780 logging.info('Next test %s is already running', test.path)
781 self.tests_to_run.popleft()
782 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800783
Jon Salza1412922012-07-23 16:04:17 +0800784 for requirement in test.require_run:
785 for i in requirement.test.walk():
786 if i.get_state().status == TestState.ACTIVE:
Jon Salz304a75d2012-07-06 11:14:15 +0800787 logging.info('Waiting for active test %s to complete '
Jon Salza1412922012-07-23 16:04:17 +0800788 'before running %s', i.path, test.path)
Jon Salz304a75d2012-07-06 11:14:15 +0800789 return
790
henryhsu4cc6b022014-04-22 17:12:42 +0800791 def is_normal_test(test):
792 return not (test.backgroundable or test.force_background)
793
794 # [1] cannot run with [abd].
795 if self.invocations and is_normal_test(test) and any(
796 [not x.force_background for x in self.invocations]):
797 logging.info('Waiting for non-force_background tests to '
798 'complete before running %s', test.path)
799 return
800
801 # [2] cannot run with [a].
802 if self.invocations and test.backgroundable and any(
803 [is_normal_test(x) for x in self.invocations]):
804 logging.info('Waiting for normal tests to '
805 'complete before running %s', test.path)
Jon Salz0697cbf2012-07-04 15:14:04 +0800806 return
Jon Salz94eb56f2012-06-12 18:01:12 +0800807
Jon Salz3e6f5202012-10-15 15:08:29 +0800808 if test.get_state().skip:
809 factory.console.info('Skipping test %s', test.path)
810 test.update_state(status=TestState.PASSED,
811 error_msg=TestState.SKIPPED_MSG)
812 self.tests_to_run.popleft()
813 continue
814
Jon Salz0697cbf2012-07-04 15:14:04 +0800815 self.tests_to_run.popleft()
Jon Salz94eb56f2012-06-12 18:01:12 +0800816
Jon Salz304a75d2012-07-06 11:14:15 +0800817 untested = set()
Jon Salza1412922012-07-23 16:04:17 +0800818 for requirement in test.require_run:
819 for i in requirement.test.walk():
820 if i == test:
Jon Salz304a75d2012-07-06 11:14:15 +0800821 # We've hit this test itself; stop checking
822 break
Jon Salza1412922012-07-23 16:04:17 +0800823 if ((i.get_state().status == TestState.UNTESTED) or
824 (requirement.passed and i.get_state().status !=
825 TestState.PASSED)):
Jon Salz304a75d2012-07-06 11:14:15 +0800826 # Found an untested test; move on to the next
827 # element in require_run.
Jon Salza1412922012-07-23 16:04:17 +0800828 untested.add(i)
Jon Salz304a75d2012-07-06 11:14:15 +0800829 break
830
831 if untested:
832 untested_paths = ', '.join(sorted([x.path for x in untested]))
833 if self.state_instance.get_shared_data('engineering_mode',
834 optional=True):
835 # In engineering mode, we'll let it go.
836 factory.console.warn('In engineering mode; running '
837 '%s even though required tests '
838 '[%s] have not completed',
839 test.path, untested_paths)
840 else:
841 # Not in engineering mode; mark it failed.
842 error_msg = ('Required tests [%s] have not been run yet'
843 % untested_paths)
844 factory.console.error('Not running %s: %s',
845 test.path, error_msg)
846 test.update_state(status=TestState.FAILED,
847 error_msg=error_msg)
848 continue
849
Ricky Liang48e47f92014-02-26 19:31:51 +0800850 if (isinstance(test, factory.ShutdownStep) and
Ricky Liangb7eb8772014-09-15 18:05:22 +0800851 self.state_instance.get_shared_data(
852 state.POST_SHUTDOWN_TAG % test.path, optional=True)):
Ricky Liang48e47f92014-02-26 19:31:51 +0800853 # Invoking post shutdown method of shutdown test. We should retain the
854 # iterations_left and retries_left of the original test state.
855 test_state = self.state_instance.get_test_state(test.path)
856 self._run_test(test, test_state.iterations_left,
857 test_state.retries_left)
858 else:
859 # Starts a new test run; reset iterations and retries.
860 self._run_test(test, test.iterations, test.retries)
Jon Salz1acc8742012-07-17 17:45:55 +0800861
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +0800862 def _run_test(self, test, iterations_left=None, retries_left=None):
Vic Yanga3cecf82014-12-26 00:44:21 -0800863 if not self._ui_initialized and not test.is_no_host():
864 self.init_ui()
Vic Yang08505c72015-01-06 17:01:53 -0800865 invoc = TestInvocation(
Hung-Te Linef7f2be2015-07-20 20:38:51 +0800866 self, test, on_completion=self.invocation_completion,
Claire Changd1961a22015-08-05 16:15:55 +0800867 on_test_failure=lambda: self.test_fail(test))
Jon Salz1acc8742012-07-17 17:45:55 +0800868 new_state = test.update_state(
Ricky Liang48e47f92014-02-26 19:31:51 +0800869 status=TestState.ACTIVE, increment_count=1, error_msg='',
870 invocation=invoc.uuid, iterations_left=iterations_left,
871 retries_left=retries_left,
872 visible=(self.visible_test == test))
Jon Salz1acc8742012-07-17 17:45:55 +0800873 invoc.count = new_state.count
874
875 self.invocations[test] = invoc
876 if self.visible_test is None and test.has_ui:
877 self.set_visible_test(test)
Vic Yang311ddb82012-09-26 12:08:28 +0800878 self.check_exclusive()
Jon Salz1acc8742012-07-17 17:45:55 +0800879 invoc.start()
Jon Salz5f2a0672012-05-22 17:14:06 +0800880
Vic Yang311ddb82012-09-26 12:08:28 +0800881 def check_exclusive(self):
Jon Salzce6a7f82013-06-10 18:22:54 +0800882 # alias since this is really long
883 EXCL_OPT = factory.FactoryTest.EXCLUSIVE_OPTIONS
884
Vic Yang311ddb82012-09-26 12:08:28 +0800885 current_exclusive_items = set([
Jon Salzce6a7f82013-06-10 18:22:54 +0800886 item for item in EXCL_OPT
Vic Yang311ddb82012-09-26 12:08:28 +0800887 if any([test.is_exclusive(item) for test in self.invocations])])
888
889 new_exclusive_items = current_exclusive_items - self.exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800890 if EXCL_OPT.NETWORKING in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800891 logging.info('Disabling network')
892 self.connection_manager.DisableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800893 if EXCL_OPT.CHARGER in new_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800894 logging.info('Stop controlling charger')
895
896 new_non_exclusive_items = self.exclusive_items - current_exclusive_items
Jon Salzce6a7f82013-06-10 18:22:54 +0800897 if EXCL_OPT.NETWORKING in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800898 logging.info('Re-enabling network')
899 self.connection_manager.EnableNetworking()
Jon Salzce6a7f82013-06-10 18:22:54 +0800900 if EXCL_OPT.CHARGER in new_non_exclusive_items:
Vic Yang311ddb82012-09-26 12:08:28 +0800901 logging.info('Start controlling charger')
902
Jon Salzce6a7f82013-06-10 18:22:54 +0800903 if self.cpufreq_manager:
904 enabled = EXCL_OPT.CPUFREQ not in current_exclusive_items
905 try:
906 self.cpufreq_manager.SetEnabled(enabled)
907 except: # pylint: disable=W0702
908 logging.exception('Unable to %s cpufreq services',
909 'enable' if enabled else 'disable')
910
Ricky Liang0f9978e2015-01-30 08:19:17 +0000911 # Only adjust charge state if not excluded
912 if (EXCL_OPT.CHARGER not in current_exclusive_items and
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +0800913 not sys_utils.InChroot()):
Ricky Liang0f9978e2015-01-30 08:19:17 +0000914 if self.charge_manager:
Cheng-Yi Chiangd8186952013-04-04 23:41:14 +0800915 self.charge_manager.AdjustChargeState()
916 else:
Dean Liao88b93192014-10-23 19:37:41 +0800917 self.charge()
Vic Yang311ddb82012-09-26 12:08:28 +0800918
919 self.exclusive_items = current_exclusive_items
Jon Salz5da61e62012-05-31 13:06:22 +0800920
Dean Liao88b93192014-10-23 19:37:41 +0800921 def charge(self):
922 """Charges the board.
923
924 It won't try again if last time SetChargeState raised an exception.
925 """
926 if not self._can_charge:
927 return
928
929 try:
Ricky Liang9ac35e02015-01-30 16:01:32 +0800930 if self.charge_manager:
931 self.charge_manager.StartCharging()
932 else:
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800933 self.dut.power.SetChargeState(self.dut.power.ChargeState.CHARGE)
Dean Liao88b93192014-10-23 19:37:41 +0800934 except NotImplementedError:
935 logging.info('Charging is not supported')
936 self._can_charge = False
Hung-Te Lin6a72c642015-12-13 22:09:09 +0800937 except dut.DUTException:
Dean Liao88b93192014-10-23 19:37:41 +0800938 logging.exception('Unable to set charge state on this board')
939 self._can_charge = False
940
cychiang21886742012-07-05 15:16:32 +0800941 def check_for_updates(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800942 """Schedules an asynchronous check for updates if necessary."""
cychiang21886742012-07-05 15:16:32 +0800943 if not self.test_list.options.update_period_secs:
944 # Not enabled.
945 return
946
947 now = time.time()
948 if self.last_update_check and (
949 now - self.last_update_check <
950 self.test_list.options.update_period_secs):
951 # Not yet time for another check.
952 return
953
954 self.last_update_check = now
955
956 def handle_check_for_update(reached_shopfloor, md5sum, needs_update):
957 if reached_shopfloor:
958 new_update_md5sum = md5sum if needs_update else None
Hung-Te Line594e5d2015-12-16 02:36:05 +0800959 if self.dut.info.update_md5sum != new_update_md5sum:
cychiang21886742012-07-05 15:16:32 +0800960 logging.info('Received new update MD5SUM: %s', new_update_md5sum)
Hung-Te Line594e5d2015-12-16 02:36:05 +0800961 self.dut.info.Overrides('update_md5sum', new_update_md5sum)
Peter Ammon1e1ec572014-06-26 17:56:32 -0700962 self.run_enqueue(self.update_system_info)
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800963 else:
964 if not self._suppress_periodic_update_messages:
965 logging.warning('Suppress error messages for periodic update checking'
966 ' after the first one.')
967 self._suppress_periodic_update_messages = True
cychiang21886742012-07-05 15:16:32 +0800968
969 updater.CheckForUpdateAsync(
Ricky Liang45c73e72015-01-15 15:00:30 +0800970 handle_check_for_update,
Cheng-Yi Chiang194d3c02015-03-16 14:37:15 +0800971 self.test_list.options.shopfloor_timeout_secs,
972 self._suppress_periodic_update_messages)
cychiang21886742012-07-05 15:16:32 +0800973
Jon Salza6711d72012-07-18 14:33:03 +0800974 def cancel_pending_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800975 """Cancels any tests in the run queue."""
Jon Salza6711d72012-07-18 14:33:03 +0800976 self.run_tests([])
977
Ricky Liang4bff3e32014-02-20 18:46:11 +0800978 def restore_active_run_state(self):
979 """Restores active run id and the list of scheduled tests."""
980 self.run_id = self.state_instance.get_shared_data('run_id', optional=True)
981 self.scheduled_run_tests = self.state_instance.get_shared_data(
982 'scheduled_run_tests', optional=True)
983
984 def set_active_run_state(self):
985 """Sets active run id and the list of scheduled tests."""
986 self.run_id = str(uuid.uuid4())
987 self.scheduled_run_tests = [test.path for test in self.tests_to_run]
988 self.state_instance.set_shared_data('run_id', self.run_id)
989 self.state_instance.set_shared_data('scheduled_run_tests',
990 self.scheduled_run_tests)
991
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +0800992 def run_tests(self, subtrees, status_filter=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +0800993 """Runs tests under subtree.
Jon Salz258a40c2012-04-19 12:34:01 +0800994
Jon Salz0697cbf2012-07-04 15:14:04 +0800995 The tests are run in order unless one fails (then stops).
996 Backgroundable tests are run simultaneously; when a foreground test is
997 encountered, we wait for all active tests to finish before continuing.
Jon Salzb1b39092012-05-03 02:05:09 +0800998
Ricky Liang6fe218c2013-12-27 15:17:17 +0800999 Args:
1000 subtrees: Node or nodes containing tests to run (may either be
1001 a single test or a list). Duplicates will be ignored.
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08001002 status_filter: List of available test states. Only run the tests which
1003 states are in the list. Set to None if all test states are available.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001004 """
Hung-Te Lin410f70a2015-12-15 14:53:42 +08001005 self.dut.hooks.OnTestStart()
Vic Yang08505c72015-01-06 17:01:53 -08001006
Jon Salz0697cbf2012-07-04 15:14:04 +08001007 if type(subtrees) != list:
1008 subtrees = [subtrees]
Jon Salz258a40c2012-04-19 12:34:01 +08001009
Jon Salz0697cbf2012-07-04 15:14:04 +08001010 # Nodes we've seen so far, to avoid duplicates.
1011 seen = set()
Jon Salz94eb56f2012-06-12 18:01:12 +08001012
Jon Salz0697cbf2012-07-04 15:14:04 +08001013 self.tests_to_run = deque()
1014 for subtree in subtrees:
1015 for test in subtree.walk():
1016 if test in seen:
1017 continue
1018 seen.add(test)
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001019
Jon Salz0697cbf2012-07-04 15:14:04 +08001020 if not test.is_leaf():
1021 continue
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08001022 if (status_filter is not None and
1023 test.get_state().status not in status_filter):
Jon Salz0697cbf2012-07-04 15:14:04 +08001024 continue
1025 self.tests_to_run.append(test)
Ricky Liang4bff3e32014-02-20 18:46:11 +08001026 if subtrees:
1027 self.set_active_run_state()
Jon Salz0697cbf2012-07-04 15:14:04 +08001028 self.run_next_test()
Hung-Te Linf2f78f72012-02-08 19:27:11 +08001029
Jon Salz0697cbf2012-07-04 15:14:04 +08001030 def reap_completed_tests(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001031 """Removes completed tests from the set of active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +08001032
1033 Also updates the visible test if it was reaped.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001034 """
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001035 test_completed = False
Jon Salz0697cbf2012-07-04 15:14:04 +08001036 for t, v in dict(self.invocations).iteritems():
1037 if v.is_completed():
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001038 test_completed = True
Jon Salz1acc8742012-07-17 17:45:55 +08001039 new_state = t.update_state(**v.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +08001040 del self.invocations[t]
1041
Johny Lin62ed2a32015-05-13 11:57:12 +08001042 # Stop on failure if flag is true and there is no retry chances.
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001043 if (self.test_list.options.stop_on_failure and
Johny Lin62ed2a32015-05-13 11:57:12 +08001044 new_state.retries_left < 0 and
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001045 new_state.status == TestState.FAILED):
1046 # Clean all the tests to cause goofy to stop.
1047 self.tests_to_run = []
Ricky Liang45c73e72015-01-15 15:00:30 +08001048 factory.console.info('Stop on failure triggered. Empty the queue.')
Chun-Ta Lin54e17e42012-09-06 22:05:13 +08001049
Jon Salz1acc8742012-07-17 17:45:55 +08001050 if new_state.iterations_left and new_state.status == TestState.PASSED:
1051 # Play it again, Sam!
1052 self._run_test(t)
Cheng-Yi Chiangce05c002013-04-04 02:13:17 +08001053 # new_state.retries_left is obtained after update.
1054 # For retries_left == 0, test can still be run for the last time.
1055 elif (new_state.retries_left >= 0 and
1056 new_state.status == TestState.FAILED):
1057 # Still have to retry, Sam!
1058 self._run_test(t)
Jon Salz1acc8742012-07-17 17:45:55 +08001059
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001060 if test_completed:
Vic Yangf01c59f2013-04-19 17:37:56 +08001061 self.log_watcher.KickWatchThread()
Cheng-Yi Chiang5ac22ca2013-04-12 17:45:26 +08001062
Jon Salz0697cbf2012-07-04 15:14:04 +08001063 if (self.visible_test is None or
Jon Salz85a39882012-07-05 16:45:04 +08001064 self.visible_test not in self.invocations):
Jon Salz0697cbf2012-07-04 15:14:04 +08001065 self.set_visible_test(None)
1066 # Make the first running test, if any, the visible test
1067 for t in self.test_list.walk():
1068 if t in self.invocations:
1069 self.set_visible_test(t)
1070 break
1071
Jon Salz6dc031d2013-06-19 13:06:23 +08001072 def kill_active_tests(self, abort, root=None, reason=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001073 """Kills and waits for all active tests.
Jon Salz0697cbf2012-07-04 15:14:04 +08001074
Jon Salz85a39882012-07-05 16:45:04 +08001075 Args:
1076 abort: True to change state of killed tests to FAILED, False for
Jon Salz0697cbf2012-07-04 15:14:04 +08001077 UNTESTED.
Jon Salz85a39882012-07-05 16:45:04 +08001078 root: If set, only kills tests with root as an ancestor.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001079 reason: If set, the abort reason.
1080 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001081 self.reap_completed_tests()
1082 for test, invoc in self.invocations.items():
Jon Salz85a39882012-07-05 16:45:04 +08001083 if root and not test.has_ancestor(root):
1084 continue
1085
Ricky Liang45c73e72015-01-15 15:00:30 +08001086 factory.console.info('Killing active test %s...', test.path)
Jon Salz6dc031d2013-06-19 13:06:23 +08001087 invoc.abort_and_join(reason)
Ricky Liang45c73e72015-01-15 15:00:30 +08001088 factory.console.info('Killed %s', test.path)
Jon Salz1acc8742012-07-17 17:45:55 +08001089 test.update_state(**invoc.update_state_on_completion)
Jon Salz0697cbf2012-07-04 15:14:04 +08001090 del self.invocations[test]
Jon Salz1acc8742012-07-17 17:45:55 +08001091
Jon Salz0697cbf2012-07-04 15:14:04 +08001092 if not abort:
1093 test.update_state(status=TestState.UNTESTED)
1094 self.reap_completed_tests()
1095
Jon Salz6dc031d2013-06-19 13:06:23 +08001096 def stop(self, root=None, fail=False, reason=None):
1097 self.kill_active_tests(fail, root, reason)
Jon Salz85a39882012-07-05 16:45:04 +08001098 # Remove any tests in the run queue under the root.
1099 self.tests_to_run = deque([x for x in self.tests_to_run
1100 if root and not x.has_ancestor(root)])
1101 self.run_next_test()
Jon Salz0697cbf2012-07-04 15:14:04 +08001102
Jon Salz4712ac72013-02-07 17:12:05 +08001103 def clear_state(self, root=None):
Jon Salzd7550792013-07-12 05:49:27 +08001104 if root is None:
1105 root = self.test_list
Jon Salz6dc031d2013-06-19 13:06:23 +08001106 self.stop(root, reason='Clearing test state')
Jon Salz4712ac72013-02-07 17:12:05 +08001107 for f in root.walk():
1108 if f.is_leaf():
1109 f.update_state(status=TestState.UNTESTED)
1110
Jon Salz6dc031d2013-06-19 13:06:23 +08001111 def abort_active_tests(self, reason=None):
1112 self.kill_active_tests(True, reason=reason)
Jon Salz0697cbf2012-07-04 15:14:04 +08001113
1114 def main(self):
Jon Salzeff94182013-06-19 15:06:28 +08001115 syslog.openlog('goofy')
1116
Jon Salz0697cbf2012-07-04 15:14:04 +08001117 try:
Jon Salzd7550792013-07-12 05:49:27 +08001118 self.status = Status.INITIALIZING
Jon Salz0697cbf2012-07-04 15:14:04 +08001119 self.init()
1120 self.event_log.Log('goofy_init',
Ricky Liang45c73e72015-01-15 15:00:30 +08001121 success=True)
Joel Kitching9eb203a2016-04-21 15:36:30 +08001122 self.log_writer.Log(
1123 testlog.StationInit({
1124 'count': log_writer.GetInitCount(),
1125 'success': True}))
Jon Salz0697cbf2012-07-04 15:14:04 +08001126 except:
Joel Kitching9eb203a2016-04-21 15:36:30 +08001127 try:
1128 if self.event_log:
Jon Salz0697cbf2012-07-04 15:14:04 +08001129 self.event_log.Log('goofy_init',
Ricky Liang45c73e72015-01-15 15:00:30 +08001130 success=False,
1131 trace=traceback.format_exc())
Joel Kitching9eb203a2016-04-21 15:36:30 +08001132 if self.log_writer:
1133 self.log_writer.Log(
1134 testlog.StationInit({
1135 'count': log_writer.GetInitCount(),
1136 'success': False,
1137 'failureMessage': traceback.format_exc()}))
1138 except: # pylint: disable=W0702
1139 pass
Jon Salz0697cbf2012-07-04 15:14:04 +08001140 raise
1141
Jon Salzd7550792013-07-12 05:49:27 +08001142 self.status = Status.RUNNING
Jon Salzeff94182013-06-19 15:06:28 +08001143 syslog.syslog('Goofy (factory test harness) starting')
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001144 syslog.syslog('Boot sequence = %d' % GetBootSequence())
Joel Kitching9eb203a2016-04-21 15:36:30 +08001145 syslog.syslog('Goofy init count = %d' % log_writer.GetInitCount())
Jon Salz0697cbf2012-07-04 15:14:04 +08001146 self.run()
1147
1148 def update_system_info(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001149 """Updates system info."""
Hung-Te Line594e5d2015-12-16 02:36:05 +08001150 info = self.dut.info.GetAll()
1151 self.state_instance.set_shared_data('system_info', info)
Jon Salz0697cbf2012-07-04 15:14:04 +08001152 self.event_client.post_event(Event(Event.Type.SYSTEM_INFO,
Hung-Te Line594e5d2015-12-16 02:36:05 +08001153 system_info=info))
1154 logging.info('System info: %r', info)
Jon Salz0697cbf2012-07-04 15:14:04 +08001155
Jon Salzeb42f0d2012-07-27 19:14:04 +08001156 def update_factory(self, auto_run_on_restart=False, post_update_hook=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001157 """Commences updating factory software.
Jon Salzeb42f0d2012-07-27 19:14:04 +08001158
1159 Args:
1160 auto_run_on_restart: Auto-run when the machine comes back up.
1161 post_update_hook: Code to call after update but immediately before
1162 restart.
1163
1164 Returns:
1165 Never if the update was successful (we just reboot).
1166 False if the update was unnecessary (no update available).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001167 """
Jon Salz6dc031d2013-06-19 13:06:23 +08001168 self.kill_active_tests(False, reason='Factory software update')
Jon Salza6711d72012-07-18 14:33:03 +08001169 self.cancel_pending_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08001170
Jon Salz5c344f62012-07-13 14:31:16 +08001171 def pre_update_hook():
1172 if auto_run_on_restart:
1173 self.state_instance.set_shared_data('tests_after_shutdown',
1174 FORCE_AUTO_RUN)
1175 self.state_instance.close()
1176
Jon Salzeb42f0d2012-07-27 19:14:04 +08001177 if updater.TryUpdate(pre_update_hook=pre_update_hook):
1178 if post_update_hook:
1179 post_update_hook()
1180 self.env.shutdown('reboot')
Jon Salz0697cbf2012-07-04 15:14:04 +08001181
Ricky Liang8fecf412014-05-22 10:56:14 +08001182 def handle_sigint(self, dummy_signum, dummy_frame): # pylint: disable=W0613
Jon Salz77c151e2012-08-28 07:20:37 +08001183 logging.error('Received SIGINT')
Peter Ammon1e1ec572014-06-26 17:56:32 -07001184 self.run_enqueue(None)
Jon Salz77c151e2012-08-28 07:20:37 +08001185 raise KeyboardInterrupt()
1186
Ricky Liang8fecf412014-05-22 10:56:14 +08001187 def handle_sigterm(self, dummy_signum, dummy_frame): # pylint: disable=W0613
1188 logging.error('Received SIGTERM')
Hung-Te Lin94ca4742014-07-09 20:13:50 +08001189 self.env.terminate()
1190 self.run_queue.put(None)
Ricky Liang8fecf412014-05-22 10:56:14 +08001191 raise RuntimeError('Received SIGTERM')
1192
Jon Salze12c2b32013-06-25 16:24:34 +08001193 def find_kcrashes(self):
1194 """Finds kcrash files, logs them, and marks them as seen."""
1195 seen_crashes = set(
1196 self.state_instance.get_shared_data('seen_crashes', optional=True)
1197 or [])
1198
1199 for path in glob.glob('/var/spool/crash/*'):
1200 if not os.path.isfile(path):
1201 continue
1202 if path in seen_crashes:
1203 continue
1204 try:
1205 stat = os.stat(path)
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001206 mtime = time_utils.TimeString(stat.st_mtime)
Jon Salze12c2b32013-06-25 16:24:34 +08001207 logging.info(
1208 'Found new crash file %s (%d bytes at %s)',
1209 path, stat.st_size, mtime)
1210 extra_log_args = {}
1211
1212 try:
1213 _, ext = os.path.splitext(path)
1214 if ext in ['.kcrash', '.meta']:
1215 ext = ext.replace('.', '')
1216 with open(path) as f:
1217 data = f.read(MAX_CRASH_FILE_SIZE)
1218 tell = f.tell()
1219 logging.info(
1220 'Contents of %s%s:%s',
1221 path,
1222 ('' if tell == stat.st_size
1223 else '(truncated to %d bytes)' % MAX_CRASH_FILE_SIZE),
1224 ('\n' + data).replace('\n', '\n ' + ext + '> '))
1225 extra_log_args['data'] = data
1226
1227 # Copy to /var/factory/kcrash for posterity
Joel Kitching625ff0f2016-05-16 14:59:40 -07001228 kcrash_dir = paths.GetFactoryRoot('kcrash')
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001229 file_utils.TryMakeDirs(kcrash_dir)
Jon Salze12c2b32013-06-25 16:24:34 +08001230 shutil.copy(path, kcrash_dir)
1231 logging.info('Copied to %s',
1232 os.path.join(kcrash_dir, os.path.basename(path)))
1233 finally:
1234 # Even if something goes wrong with the above, still try to
1235 # log to event log
1236 self.event_log.Log('crash_file',
1237 path=path, size=stat.st_size, mtime=mtime,
1238 **extra_log_args)
1239 except: # pylint: disable=W0702
1240 logging.exception('Unable to handle crash files %s', path)
1241 seen_crashes.add(path)
1242
1243 self.state_instance.set_shared_data('seen_crashes', list(seen_crashes))
1244
Jon Salz128b0932013-07-03 16:55:26 +08001245 def GetTestList(self, test_list_id):
1246 """Returns the test list with the given ID.
1247
1248 Raises:
1249 TestListError: The test list ID is not valid.
1250 """
1251 try:
1252 return self.test_lists[test_list_id]
1253 except KeyError:
1254 raise test_lists.TestListError(
1255 '%r is not a valid test list ID (available IDs are [%s])' % (
1256 test_list_id, ', '.join(sorted(self.test_lists.keys()))))
1257
1258 def InitTestLists(self):
Joel Kitching50a63ea2016-02-22 13:15:09 +08001259 """Reads in all test lists and sets the active test list.
1260
1261 Returns:
1262 True if the active test list could be set, False if failed.
1263 """
1264 startup_errors = []
1265 self.test_lists, failed_files = test_lists.BuildAllTestLists(
Ricky Liang27051552014-05-04 14:22:26 +08001266 force_generic=(self.options.automation_mode is not None))
Jon Salzd7550792013-07-12 05:49:27 +08001267 logging.info('Loaded test lists: [%s]',
1268 test_lists.DescribeTestLists(self.test_lists))
Jon Salz128b0932013-07-03 16:55:26 +08001269
Joel Kitching50a63ea2016-02-22 13:15:09 +08001270 # Check for any syntax errors in test list files.
1271 if failed_files:
1272 logging.info('Failed test list files: [%s]',
1273 ' '.join(failed_files.keys()))
1274 for f, exc_info in failed_files.iteritems():
1275 logging.error('Error in test list file: %s', f,
1276 exc_info=exc_info)
1277
1278 # Limit the stack trace to the very last entry.
1279 exc_type, exc_value, exc_traceback = exc_info
1280 while exc_traceback and exc_traceback.tb_next:
1281 exc_traceback = exc_traceback.tb_next
1282
1283 exc_string = ''.join(
1284 traceback.format_exception(
1285 exc_type, exc_value, exc_traceback)).rstrip()
1286 startup_errors.append('Error in test list file (%s):\n%s'
1287 % (f, exc_string))
1288
Jon Salz128b0932013-07-03 16:55:26 +08001289 if not self.options.test_list:
1290 self.options.test_list = test_lists.GetActiveTestListId()
1291
Joel Kitching50a63ea2016-02-22 13:15:09 +08001292 # Check for a non-existent test list ID.
1293 try:
1294 if os.sep in self.options.test_list:
1295 # It's a path pointing to an old-style test list; use it.
1296 self.test_list = factory.read_test_list(self.options.test_list)
1297 else:
1298 self.test_list = self.GetTestList(self.options.test_list)
1299 logging.info('Active test list: %s', self.test_list.test_list_id)
1300 except test_lists.TestListError as e:
1301 logging.exception('Invalid active test list: %s',
1302 self.options.test_list)
1303 startup_errors.append(e.message)
Jon Salz128b0932013-07-03 16:55:26 +08001304
Joel Kitching50a63ea2016-02-22 13:15:09 +08001305 # We may have failed loading the active test list.
1306 if self.test_list:
1307 if isinstance(self.test_list, test_lists.OldStyleTestList):
1308 # Actually load it in. (See OldStyleTestList for an explanation
1309 # of why this is necessary.)
1310 self.test_list = self.test_list.Load()
Jon Salz128b0932013-07-03 16:55:26 +08001311
Joel Kitching50a63ea2016-02-22 13:15:09 +08001312 self.test_list.state_instance = self.state_instance
Jon Salz128b0932013-07-03 16:55:26 +08001313
Joel Kitching50a63ea2016-02-22 13:15:09 +08001314 # Prepare DUT link.
1315 if self.test_list.options.dut_options:
1316 logging.info('dut_options set by %s: %r', self.test_list.test_list_id,
1317 self.test_list.options.dut_options)
1318 dut_utils.PrepareLink(**self.test_list.options.dut_options)
Wei-Han Chene8a025f2016-01-14 16:42:02 +08001319
Joel Kitching50a63ea2016-02-22 13:15:09 +08001320 # Show all startup errors.
1321 if startup_errors:
1322 self.state_instance.set_shared_data(
1323 'startup_error', '\n\n'.join(startup_errors))
1324
1325 # Only return False if failed to load the active test list.
1326 return bool(self.test_list)
Jon Salz128b0932013-07-03 16:55:26 +08001327
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001328 def init_hooks(self):
1329 """Initializes hooks.
1330
1331 Must run after self.test_list ready.
1332 """
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001333 module, cls = self.test_list.options.hooks_class.rsplit('.', 1)
1334 self.hooks = getattr(__import__(module, fromlist=[cls]), cls)()
1335 assert isinstance(self.hooks, factory.Hooks), (
Ricky Liang45c73e72015-01-15 15:00:30 +08001336 'hooks should be of type Hooks but is %r' % type(self.hooks))
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001337 self.hooks.test_list = self.test_list
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001338 self.hooks.OnCreatedTestList()
Shuo-Peng Liao52b90da2013-06-30 17:00:06 +08001339
Vic Yanga3cecf82014-12-26 00:44:21 -08001340 def init_ui(self):
1341 """Initialize UI."""
1342 self._ui_initialized = True
1343 if self.options.ui == 'chrome':
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001344 if self.options.monolithic:
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001345 self.env.launch_chrome()
1346 else:
1347 # The presenter is responsible for launching Chrome. Let's just
1348 # wait here.
1349 self.env.controller_ready_for_ui()
Vic Yanga3cecf82014-12-26 00:44:21 -08001350 logging.info('Waiting for a web socket connection')
1351 self.web_socket_manager.wait()
1352
1353 # Wait for the test widget size to be set; this is done in
1354 # an asynchronous RPC so there is a small chance that the
1355 # web socket might be opened first.
1356 for _ in range(100): # 10 s
1357 try:
1358 if self.state_instance.get_shared_data('test_widget_size'):
1359 break
1360 except KeyError:
1361 pass # Retry
1362 time.sleep(0.1) # 100 ms
1363 else:
1364 logging.warn('Never received test_widget_size from UI')
1365
Jon Salz0697cbf2012-07-04 15:14:04 +08001366 def init(self, args=None, env=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001367 """Initializes Goofy.
Jon Salz0697cbf2012-07-04 15:14:04 +08001368
1369 Args:
1370 args: A list of command-line arguments. Uses sys.argv if
1371 args is None.
1372 env: An Environment instance to use (or None to choose
1373 FakeChrootEnvironment or DUTEnvironment as appropriate).
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001374 """
Jon Salz0697cbf2012-07-04 15:14:04 +08001375 parser = OptionParser()
1376 parser.add_option('-v', '--verbose', dest='verbose',
Jon Salz8fa8e832012-07-13 19:04:09 +08001377 action='store_true',
1378 help='Enable debug logging')
Jon Salz0697cbf2012-07-04 15:14:04 +08001379 parser.add_option('--print_test_list', dest='print_test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001380 metavar='FILE',
1381 help='Read and print test list FILE, and exit')
Jon Salz0697cbf2012-07-04 15:14:04 +08001382 parser.add_option('--restart', dest='restart',
Jon Salz8fa8e832012-07-13 19:04:09 +08001383 action='store_true',
1384 help='Clear all test state')
Jon Salz0697cbf2012-07-04 15:14:04 +08001385 parser.add_option('--ui', dest='ui', type='choice',
Jon Salz7b5482e2014-08-04 17:48:41 +08001386 choices=['none', 'chrome'],
Jon Salz2f881df2013-02-01 17:00:35 +08001387 default='chrome',
Jon Salz8fa8e832012-07-13 19:04:09 +08001388 help='UI to use')
Jon Salz0697cbf2012-07-04 15:14:04 +08001389 parser.add_option('--ui_scale_factor', dest='ui_scale_factor',
Jon Salz8fa8e832012-07-13 19:04:09 +08001390 type='int', default=1,
1391 help=('Factor by which to scale UI '
1392 '(Chrome UI only)'))
Jon Salz0697cbf2012-07-04 15:14:04 +08001393 parser.add_option('--test_list', dest='test_list',
Jon Salz8fa8e832012-07-13 19:04:09 +08001394 metavar='FILE',
1395 help='Use FILE as test list')
Jon Salzc79a9982012-08-30 04:42:01 +08001396 parser.add_option('--dummy_shopfloor', action='store_true',
1397 help='Use a dummy shopfloor server')
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001398 parser.add_option('--dummy_connection_manager', action='store_true',
1399 help='Use a dummy connection manager')
Ricky Liang6fe218c2013-12-27 15:17:17 +08001400 parser.add_option('--automation-mode',
1401 choices=[m.lower() for m in AutomationMode],
Ricky Liang45c73e72015-01-15 15:00:30 +08001402 default='none', help='Factory test automation mode.')
Ricky Liang117484a2014-04-14 11:14:41 +08001403 parser.add_option('--no-auto-run-on-start', dest='auto_run_on_start',
1404 action='store_false', default=True,
1405 help=('do not automatically run the test list on goofy '
1406 'start; this is only valid when factory test '
1407 'automation is enabled'))
Chun-Ta Lina8dd3172014-11-26 16:15:13 +08001408 parser.add_option('--handshake_timeout', dest='handshake_timeout',
1409 type='float', default=0.3,
1410 help=('RPC timeout when doing handshake between device '
1411 'and presenter.'))
Vic Yang7d693c42014-09-14 09:52:39 +08001412 parser.add_option('--standalone', dest='standalone',
1413 action='store_true', default=False,
1414 help=('Assume the presenter is running on the same '
1415 'machines.'))
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001416 parser.add_option('--monolithic', dest='monolithic',
1417 action='store_true', default=False,
1418 help='Run in monolithic mode (without presenter)')
Jon Salz0697cbf2012-07-04 15:14:04 +08001419 (self.options, self.args) = parser.parse_args(args)
1420
Hung-Te Lina846f602014-07-04 20:32:22 +08001421 signal.signal(signal.SIGINT, self.handle_sigint)
1422 # TODO(hungte) SIGTERM does not work properly without Telemetry and should
1423 # be fixed.
Hung-Te Lina846f602014-07-04 20:32:22 +08001424
Jon Salz46b89562012-07-05 11:49:22 +08001425 # Make sure factory directories exist.
Joel Kitching625ff0f2016-05-16 14:59:40 -07001426 paths.GetLogRoot()
1427 paths.GetStateRoot()
1428 paths.GetTestDataRoot()
Jon Salz46b89562012-07-05 11:49:22 +08001429
Jon Salz0697cbf2012-07-04 15:14:04 +08001430 global _inited_logging # pylint: disable=W0603
1431 if not _inited_logging:
1432 factory.init_logging('goofy', verbose=self.options.verbose)
1433 _inited_logging = True
Jon Salz8fa8e832012-07-13 19:04:09 +08001434
Jon Salz0f996602012-10-03 15:26:48 +08001435 if self.options.print_test_list:
Joel Kitchingb85ed7f2014-10-08 18:24:39 +08001436 print(factory.read_test_list(
1437 self.options.print_test_list).__repr__(recursive=True))
Jon Salz0f996602012-10-03 15:26:48 +08001438 sys.exit(0)
1439
Jon Salzee85d522012-07-17 14:34:46 +08001440 event_log.IncrementBootSequence()
Joel Kitching9eb203a2016-04-21 15:36:30 +08001441 log_writer.IncrementInitCount()
Jon Salzd15bbcf2013-05-21 17:33:57 +08001442 # Don't defer logging the initial event, so we can make sure
1443 # that device_id, reimage_id, etc. are all set up.
1444 self.event_log = EventLog('goofy', defer=False)
Joel Kitching9eb203a2016-04-21 15:36:30 +08001445 self.log_writer = log_writer.GetGlobalLogWriter()
Jon Salz0697cbf2012-07-04 15:14:04 +08001446
Jon Salz0697cbf2012-07-04 15:14:04 +08001447 if env:
1448 self.env = env
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001449 elif sys_utils.InChroot():
Jon Salz0697cbf2012-07-04 15:14:04 +08001450 self.env = test_environment.FakeChrootEnvironment()
1451 logging.warn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001452 'Using chroot environment: will not actually run autotests')
Hung-Te Lina846f602014-07-04 20:32:22 +08001453 elif self.options.ui == 'chrome':
Ricky Liang09d66d82014-09-25 11:20:54 +08001454 self.env = test_environment.DUTEnvironment()
Jon Salz0697cbf2012-07-04 15:14:04 +08001455 self.env.goofy = self
Vic Yanga4931152014-08-11 16:36:24 -07001456 # web_socket_manager will be initialized later
1457 # pylint: disable=W0108
1458 self.env.has_sockets = lambda: self.web_socket_manager.has_sockets()
Jon Salz0697cbf2012-07-04 15:14:04 +08001459
1460 if self.options.restart:
1461 state.clear_state()
1462
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001463 if self.options.ui_scale_factor != 1 and sys_utils.InQEMU():
Jon Salz0697cbf2012-07-04 15:14:04 +08001464 logging.warn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001465 'In QEMU; ignoring ui_scale_factor argument')
Jon Salz0697cbf2012-07-04 15:14:04 +08001466 self.options.ui_scale_factor = 1
1467
1468 logging.info('Started')
1469
Hung-Te Lin8f6a3782015-01-06 22:58:32 +08001470 if not self.options.monolithic:
Hung-Te Lin7bd55312014-12-30 16:43:36 +08001471 self.link_manager = PresenterLinkManager(
1472 check_interval=1,
1473 handshake_timeout=self.options.handshake_timeout,
1474 standalone=self.options.standalone)
Peter Ammon1e1ec572014-06-26 17:56:32 -07001475
Jon Salz0697cbf2012-07-04 15:14:04 +08001476 self.start_state_server()
1477 self.state_instance.set_shared_data('hwid_cfg', get_hwid_cfg())
1478 self.state_instance.set_shared_data('ui_scale_factor',
Ricky Liang09216dc2013-02-22 17:26:45 +08001479 self.options.ui_scale_factor)
Jon Salz0697cbf2012-07-04 15:14:04 +08001480 self.last_shutdown_time = (
Ricky Liang45c73e72015-01-15 15:00:30 +08001481 self.state_instance.get_shared_data('shutdown_time', optional=True))
Jon Salz0697cbf2012-07-04 15:14:04 +08001482 self.state_instance.del_shared_data('shutdown_time', optional=True)
Jon Salzb19ea072013-02-07 16:35:00 +08001483 self.state_instance.del_shared_data('startup_error', optional=True)
Jon Salz0697cbf2012-07-04 15:14:04 +08001484
Ricky Liang6fe218c2013-12-27 15:17:17 +08001485 self.options.automation_mode = ParseAutomationMode(
1486 self.options.automation_mode)
1487 self.state_instance.set_shared_data('automation_mode',
1488 self.options.automation_mode)
1489 self.state_instance.set_shared_data(
1490 'automation_mode_prompt',
1491 AutomationModePrompt[self.options.automation_mode])
1492
Joel Kitching50a63ea2016-02-22 13:15:09 +08001493 success = False
1494 exc_info = None
Jon Salz128b0932013-07-03 16:55:26 +08001495 try:
Joel Kitching50a63ea2016-02-22 13:15:09 +08001496 success = self.InitTestLists()
Jon Salz128b0932013-07-03 16:55:26 +08001497 except: # pylint: disable=W0702
Joel Kitching50a63ea2016-02-22 13:15:09 +08001498 exc_info = sys.exc_info()
1499
1500 if not success:
1501 if exc_info:
1502 logging.exception('Unable to initialize test lists')
1503 self.state_instance.set_shared_data(
1504 'startup_error',
1505 'Unable to initialize test lists\n%s' % (
1506 traceback.format_exc()))
Jon Salzb19ea072013-02-07 16:35:00 +08001507 if self.options.ui == 'chrome':
1508 # Create an empty test list with default options so that the rest of
1509 # startup can proceed.
1510 self.test_list = factory.FactoryTestList(
1511 [], self.state_instance, factory.Options())
1512 else:
1513 # Bail with an error; no point in starting up.
1514 sys.exit('No valid test list; exiting.')
1515
Shuo-Peng Liao268b40b2013-07-01 15:58:59 +08001516 self.init_hooks()
1517
Jon Salz822838b2013-03-25 17:32:33 +08001518 if self.test_list.options.clear_state_on_start:
1519 self.state_instance.clear_test_state()
1520
Jon Salz670ce062014-05-16 15:53:50 +08001521 # If the phase is invalid, this will raise a ValueError.
1522 phase.SetPersistentPhase(self.test_list.options.phase)
1523
Dean Liao85ca86f2014-11-03 12:28:08 +08001524 # For netboot firmware, mainfw_type should be 'netboot'.
Hung-Te Line594e5d2015-12-16 02:36:05 +08001525 if (self.dut.info.mainfw_type != 'nonchrome' and
1526 self.dut.info.firmware_version is None):
Ricky Liang45c73e72015-01-15 15:00:30 +08001527 self.state_instance.set_shared_data(
1528 'startup_error',
Vic Yang9bd4f772013-06-04 17:34:00 +08001529 'Netboot firmware detected\n'
1530 'Connect Ethernet and reboot to re-image.\n'
1531 u'侦测到网路开机固件\n'
1532 u'请连接乙太网并重启')
1533
Jon Salz0697cbf2012-07-04 15:14:04 +08001534 if not self.state_instance.has_shared_data('ui_lang'):
1535 self.state_instance.set_shared_data('ui_lang',
Ricky Liang45c73e72015-01-15 15:00:30 +08001536 self.test_list.options.ui_lang)
Jon Salz0697cbf2012-07-04 15:14:04 +08001537 self.state_instance.set_shared_data(
Ricky Liang45c73e72015-01-15 15:00:30 +08001538 'test_list_options',
1539 self.test_list.options.__dict__)
Jon Salz0697cbf2012-07-04 15:14:04 +08001540 self.state_instance.test_list = self.test_list
1541
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001542 self.check_log_rotation()
Jon Salz83ef34b2012-11-01 19:46:35 +08001543
Jon Salz23926422012-09-01 03:38:13 +08001544 if self.options.dummy_shopfloor:
Ricky Liang45c73e72015-01-15 15:00:30 +08001545 os.environ[shopfloor.SHOPFLOOR_SERVER_ENV_VAR_NAME] = (
1546 'http://%s:%d/' %
Joel Kitchingb85ed7f2014-10-08 18:24:39 +08001547 (net_utils.LOCALHOST, shopfloor.DEFAULT_SERVER_PORT))
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001548 self.dummy_shopfloor = process_utils.Spawn(
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001549 [os.path.join(paths.FACTORY_PATH, 'bin', 'shopfloor_server'),
Jon Salz23926422012-09-01 03:38:13 +08001550 '--dummy'])
1551 elif self.test_list.options.shopfloor_server_url:
1552 shopfloor.set_server_url(self.test_list.options.shopfloor_server_url)
Jon Salz2bf2f6b2013-03-28 18:49:26 +08001553 shopfloor.set_enabled(True)
Jon Salz23926422012-09-01 03:38:13 +08001554
Hung-Te Linf5f2d7f2016-01-08 17:12:46 +08001555 if self.test_list.options.time_sanitizer and not sys_utils.InChroot():
Jon Salz8fa8e832012-07-13 19:04:09 +08001556 self.time_sanitizer = time_sanitizer.TimeSanitizer(
Ricky Liang45c73e72015-01-15 15:00:30 +08001557 base_time=time_sanitizer.GetBaseTimeFromFile(
1558 # lsb-factory is written by the factory install shim during
1559 # installation, so it should have a good time obtained from
1560 # the mini-Omaha server. If it's not available, we'll use
1561 # /etc/lsb-factory (which will be much older, but reasonably
1562 # sane) and rely on a shopfloor sync to set a more accurate
1563 # time.
1564 '/usr/local/etc/lsb-factory',
1565 '/etc/lsb-release'))
Jon Salz8fa8e832012-07-13 19:04:09 +08001566 self.time_sanitizer.RunOnce()
1567
Vic Yangd8990da2013-06-27 16:57:43 +08001568 if self.test_list.options.check_cpu_usage_period_secs:
Hung-Te Lin4e6357c2016-01-08 14:32:00 +08001569 self.cpu_usage_watcher = process_utils.Spawn(
Ricky Liang45c73e72015-01-15 15:00:30 +08001570 ['py/tools/cpu_usage_monitor.py', '-p',
1571 str(self.test_list.options.check_cpu_usage_period_secs)],
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001572 cwd=paths.FACTORY_PATH)
Vic Yangd8990da2013-06-27 16:57:43 +08001573
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001574 # Enable thermal monitor
1575 if self.test_list.options.thermal_monitor_period_secs > 0:
Hung-Te Lin23cb7612016-01-19 19:19:32 +08001576 self.thermal_watcher = process_utils.Spawn(
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001577 ['py/tools/thermal_monitor.py',
1578 '-p', str(self.test_list.options.thermal_monitor_period_secs),
1579 '-d', str(self.test_list.options.thermal_monitor_delta)],
Wei-Han Chen2ebb92d2016-01-12 14:51:41 +08001580 cwd=paths.FACTORY_PATH)
Chun-Ta Lin5d12b592015-06-30 00:54:23 -07001581
Jon Salz0697cbf2012-07-04 15:14:04 +08001582 self.init_states()
1583 self.start_event_server()
Wei-Ning Huang38b75f02015-02-25 18:25:14 +08001584 self.start_terminal_server()
Hung-Te Lincc41d2a2014-10-29 13:35:20 +08001585
1586 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()
cychiang21886742012-07-05 15:16:32 +08001955 self.check_for_updates()
Jon Salz8fa8e832012-07-13 19:04:09 +08001956 self.sync_time_in_background()
Jon Salzb92c5112012-09-21 15:40:11 +08001957 self.log_disk_space_stats()
Justin Chuang83813982013-05-13 01:26:32 +08001958 self.check_battery()
Cheng-Yi Chiangcdfa4182013-05-05 03:20:19 +08001959 self.check_core_dump()
Cheng-Yi Chiang39d32ad2013-07-23 15:02:38 +08001960 self.check_log_rotation()
Jon Salz57717ca2012-04-04 16:47:25 +08001961
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001962 def handle_event_logs(self, chunks, periodic=False):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001963 """Callback for event watcher.
Jon Salz258a40c2012-04-19 12:34:01 +08001964
Jon Salz0697cbf2012-07-04 15:14:04 +08001965 Attempts to upload the event logs to the shopfloor server.
Vic Yang93027612013-05-06 02:42:49 +08001966
1967 Args:
Jon Salzd15bbcf2013-05-21 17:33:57 +08001968 chunks: A list of Chunk objects.
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001969 periodic: This event log handling is periodic. Error messages
1970 will only be shown for the first time.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08001971 """
Vic Yang93027612013-05-06 02:42:49 +08001972 first_exception = None
1973 exception_count = 0
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001974 # Suppress error messages for periodic event syncing except for the
1975 # first time. If event syncing is not periodic, always show the error
1976 # messages.
1977 quiet = self._suppress_event_log_error_messages if periodic else False
Vic Yang93027612013-05-06 02:42:49 +08001978
Jon Salzd15bbcf2013-05-21 17:33:57 +08001979 for chunk in chunks:
Vic Yang93027612013-05-06 02:42:49 +08001980 try:
Jon Salzcddb6402013-05-23 12:56:42 +08001981 description = 'event logs (%s)' % str(chunk)
Vic Yang93027612013-05-06 02:42:49 +08001982 start_time = time.time()
1983 shopfloor_client = shopfloor.get_instance(
Ricky Liang45c73e72015-01-15 15:00:30 +08001984 detect=True,
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08001985 timeout=self.test_list.options.shopfloor_timeout_secs,
1986 quiet=quiet)
Ricky Liang45c73e72015-01-15 15:00:30 +08001987 shopfloor_client.UploadEvent(chunk.log_name + '.' +
Jon Salzd15bbcf2013-05-21 17:33:57 +08001988 event_log.GetReimageId(),
1989 Binary(chunk.chunk))
Vic Yang93027612013-05-06 02:42:49 +08001990 logging.info(
Ricky Liang45c73e72015-01-15 15:00:30 +08001991 'Successfully synced %s in %.03f s',
1992 description, time.time() - start_time)
1993 except: # pylint: disable=W0702
Hung-Te Linf707b242016-01-08 23:11:42 +08001994 first_exception = (first_exception or
1995 (chunk.log_name + ': ' +
1996 debug_utils.FormatExceptionOnly()))
Vic Yang93027612013-05-06 02:42:49 +08001997 exception_count += 1
1998
1999 if exception_count:
2000 if exception_count == 1:
2001 msg = 'Log upload failed: %s' % first_exception
2002 else:
2003 msg = '%d log upload failed; first is: %s' % (
2004 exception_count, first_exception)
Cheng-Yi Chiangf5b21012015-03-17 15:37:14 +08002005 # For periodic event log syncing, only show the first error messages.
2006 if periodic:
2007 if not self._suppress_event_log_error_messages:
2008 self._suppress_event_log_error_messages = True
2009 logging.warning('Suppress periodic shopfloor error messages for '
2010 'event log syncing after the first one.')
2011 raise Exception(msg)
2012 # For event log syncing by request, show the error messages.
2013 else:
2014 raise Exception(msg)
Vic Yang93027612013-05-06 02:42:49 +08002015
Ricky Liang45c73e72015-01-15 15:00:30 +08002016 def run_tests_with_status(self, statuses_to_run, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002017 """Runs all top-level tests with a particular status.
Jon Salz0405ab52012-03-16 15:26:52 +08002018
Jon Salz0697cbf2012-07-04 15:14:04 +08002019 All active tests, plus any tests to re-run, are reset.
Jon Salz57717ca2012-04-04 16:47:25 +08002020
Jon Salz0697cbf2012-07-04 15:14:04 +08002021 Args:
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002022 statuses_to_run: The particular status that caller wants to run.
Jon Salz0697cbf2012-07-04 15:14:04 +08002023 starting_at: If provided, only auto-runs tests beginning with
2024 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002025 root: The root of tests to run. If not provided, it will be
2026 the root of all tests.
2027 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002028 root = root or self.test_list
Jon Salz57717ca2012-04-04 16:47:25 +08002029
Jon Salz0697cbf2012-07-04 15:14:04 +08002030 if starting_at:
2031 # Make sure they passed a test, not a string.
2032 assert isinstance(starting_at, factory.FactoryTest)
Jon Salz0405ab52012-03-16 15:26:52 +08002033
Jon Salz0697cbf2012-07-04 15:14:04 +08002034 tests_to_reset = []
2035 tests_to_run = []
Jon Salz0405ab52012-03-16 15:26:52 +08002036
Jon Salz0697cbf2012-07-04 15:14:04 +08002037 found_starting_at = False
Jon Salz0405ab52012-03-16 15:26:52 +08002038
Jon Salz0697cbf2012-07-04 15:14:04 +08002039 for test in root.get_top_level_tests():
2040 if starting_at:
2041 if test == starting_at:
2042 # We've found starting_at; do auto-run on all
2043 # subsequent tests.
2044 found_starting_at = True
2045 if not found_starting_at:
2046 # Don't start this guy yet
2047 continue
Jon Salz0405ab52012-03-16 15:26:52 +08002048
Jon Salz0697cbf2012-07-04 15:14:04 +08002049 status = test.get_state().status
2050 if status == TestState.ACTIVE or status in statuses_to_run:
2051 # Reset the test (later; we will need to abort
2052 # all active tests first).
2053 tests_to_reset.append(test)
2054 if status in statuses_to_run:
2055 tests_to_run.append(test)
Jon Salz0405ab52012-03-16 15:26:52 +08002056
Jon Salz6dc031d2013-06-19 13:06:23 +08002057 self.abort_active_tests('Operator requested run/re-run of certain tests')
Jon Salz258a40c2012-04-19 12:34:01 +08002058
Jon Salz0697cbf2012-07-04 15:14:04 +08002059 # Reset all statuses of the tests to run (in case any tests were active;
2060 # we want them to be run again).
2061 for test_to_reset in tests_to_reset:
2062 for test in test_to_reset.walk():
2063 test.update_state(status=TestState.UNTESTED)
Jon Salz57717ca2012-04-04 16:47:25 +08002064
Chih-Yu Huang85dc63c2015-08-12 15:21:28 +08002065 self.run_tests(tests_to_run, [TestState.UNTESTED])
Jon Salz0405ab52012-03-16 15:26:52 +08002066
Jon Salz0697cbf2012-07-04 15:14:04 +08002067 def restart_tests(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002068 """Restarts all tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08002069 root = root or self.test_list
Jon Salz0405ab52012-03-16 15:26:52 +08002070
Jon Salz6dc031d2013-06-19 13:06:23 +08002071 self.abort_active_tests('Operator requested restart of certain tests')
Jon Salz0697cbf2012-07-04 15:14:04 +08002072 for test in root.walk():
Ricky Liangfea4ac92014-08-21 11:55:59 +08002073 test.update_state(status=TestState.UNTESTED)
Jon Salz0697cbf2012-07-04 15:14:04 +08002074 self.run_tests(root)
Hung-Te Lin96632362012-03-20 21:14:18 +08002075
Jon Salz0697cbf2012-07-04 15:14:04 +08002076 def auto_run(self, starting_at=None, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002077 """"Auto-runs" tests that have not been run yet.
Hung-Te Lin96632362012-03-20 21:14:18 +08002078
Jon Salz0697cbf2012-07-04 15:14:04 +08002079 Args:
2080 starting_at: If provide, only auto-runs tests beginning with
2081 this test.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002082 root: If provided, the root of tests to run. If not provided, the root
2083 will be test_list (root of all tests).
2084 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002085 root = root or self.test_list
2086 self.run_tests_with_status([TestState.UNTESTED, TestState.ACTIVE],
Ricky Liang45c73e72015-01-15 15:00:30 +08002087 starting_at=starting_at,
2088 root=root)
Jon Salz968e90b2012-03-18 16:12:43 +08002089
Jon Salz0697cbf2012-07-04 15:14:04 +08002090 def re_run_failed(self, root=None):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002091 """Re-runs failed tests."""
Jon Salz0697cbf2012-07-04 15:14:04 +08002092 root = root or self.test_list
2093 self.run_tests_with_status([TestState.FAILED], root=root)
Jon Salz57717ca2012-04-04 16:47:25 +08002094
Jon Salz0697cbf2012-07-04 15:14:04 +08002095 def show_review_information(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002096 """Event handler for showing review information screen.
Jon Salz57717ca2012-04-04 16:47:25 +08002097
Peter Ammon1e1ec572014-06-26 17:56:32 -07002098 The information screen is rendered by main UI program (ui.py), so in
Jon Salz0697cbf2012-07-04 15:14:04 +08002099 goofy we only need to kill all active tests, set them as untested, and
2100 clear remaining tests.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002101 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002102 self.kill_active_tests(False)
Jon Salza6711d72012-07-18 14:33:03 +08002103 self.cancel_pending_tests()
Jon Salz57717ca2012-04-04 16:47:25 +08002104
Jon Salz0697cbf2012-07-04 15:14:04 +08002105 def handle_switch_test(self, event):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002106 """Switches to a particular test.
Jon Salz0405ab52012-03-16 15:26:52 +08002107
Ricky Liang6fe218c2013-12-27 15:17:17 +08002108 Args:
2109 event: The SWITCH_TEST event.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002110 """
Jon Salz0697cbf2012-07-04 15:14:04 +08002111 test = self.test_list.lookup_path(event.path)
2112 if not test:
2113 logging.error('Unknown test %r', event.key)
2114 return
Jon Salz73e0fd02012-04-04 11:46:38 +08002115
Jon Salz0697cbf2012-07-04 15:14:04 +08002116 invoc = self.invocations.get(test)
2117 if invoc and test.backgroundable:
2118 # Already running: just bring to the front if it
2119 # has a UI.
2120 logging.info('Setting visible test to %s', test.path)
Jon Salz36fbbb52012-07-05 13:45:06 +08002121 self.set_visible_test(test)
Jon Salz0697cbf2012-07-04 15:14:04 +08002122 return
Jon Salz73e0fd02012-04-04 11:46:38 +08002123
Jon Salz6dc031d2013-06-19 13:06:23 +08002124 self.abort_active_tests('Operator requested abort (switch_test)')
Jon Salz0697cbf2012-07-04 15:14:04 +08002125 for t in test.walk():
2126 t.update_state(status=TestState.UNTESTED)
Jon Salz73e0fd02012-04-04 11:46:38 +08002127
Jon Salz0697cbf2012-07-04 15:14:04 +08002128 if self.test_list.options.auto_run_on_keypress:
2129 self.auto_run(starting_at=test)
2130 else:
2131 self.run_tests(test)
Jon Salz73e0fd02012-04-04 11:46:38 +08002132
Wei-Ning Huang38b75f02015-02-25 18:25:14 +08002133 def handle_key_filter_mode(self, event):
2134 if self.key_filter:
2135 if getattr(event, 'enabled'):
2136 self.key_filter.Start()
2137 else:
2138 self.key_filter.Stop()
2139
Jon Salz0697cbf2012-07-04 15:14:04 +08002140 def wait(self):
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002141 """Waits for all pending invocations.
Jon Salz0697cbf2012-07-04 15:14:04 +08002142
2143 Useful for testing.
Cheng-Yi Chiang1e3e2692013-12-24 18:02:36 +08002144 """
Jon Salz1acc8742012-07-17 17:45:55 +08002145 while self.invocations:
2146 for k, v in self.invocations.iteritems():
2147 logging.info('Waiting for %s to complete...', k)
2148 v.thread.join()
2149 self.reap_completed_tests()
Jon Salz0697cbf2012-07-04 15:14:04 +08002150
Claire Changd1961a22015-08-05 16:15:55 +08002151 def test_fail(self, test):
Hung-Te Lin410f70a2015-12-15 14:53:42 +08002152 self.dut.hooks.OnTestFailure(test)
Claire Changd1961a22015-08-05 16:15:55 +08002153 if self.link_manager:
2154 self.link_manager.UpdateStatus(False)
2155
Hung-Te Linf2f78f72012-02-08 19:27:11 +08002156if __name__ == '__main__':
Peter Ammona3d298c2014-09-23 10:11:02 -07002157 Goofy.run_main_and_exit()