1# Copyright 2016 The Chromium OS Authors. All rights reserved. 2# Use of this source code is governed by a BSD-style license that can be 3# found in the LICENSE file. 4 5import datetime 6import logging 7import time 8 9from autotest_lib.client.common_lib import error 10from autotest_lib.server import autotest 11from autotest_lib.server import test 12 13_POWERD_LOG_PATH = '/var/log/power_manager/powerd.LATEST' 14_RESUME_END_LOG = '\"daemon.* Chrome is using normal display mode$\"' 15_RESUME_START_LOG = '\"suspender.* Finishing request [0-9]+ successfully$\"' 16_SERVO_USB_NUM = 2 17_SHORT_WAIT_ = 5 18_SUSPEND_END_LOG = '\"suspender.* Starting suspend$\"' 19_SUSPEND_START_LOG = '\"suspender.* Starting request [0-9]+$\"' 20_SUSPEND_TIME = 15 21_TIME_TO_RESUME_BAR = 3 22_TIME_TO_SUSPEND_BAR = 3 23 24 25class platform_SuspendResumeTiming(test.test): 26 """Checks suspend and resume happen in reasonable timelines.""" 27 version = 1 28 29 30 def cleanup(self): 31 """ Disconnect servo hub.""" 32 self.host.servo.set('dut_hub1_rst1', 'on') 33 self.host.servo.set('usb_mux_sel3', 'servo_sees_usbkey') 34 35 36 def get_suspender_log_stamp(self, pwrd_log): 37 """ Reads powerd log and takes suspend and resume logs timestamps. 38 39 @param pwrd_log: log string to search for. 40 41 @raises TestError: if suspender log is met more than once. 42 43 @returns log timestamp as datetime. 44 """ 45 out_log = self.host.run('tac %s | grep -E %s' 46 % (_POWERD_LOG_PATH, pwrd_log), 47 ignore_status=True).stdout.strip() 48 log_count = len(out_log.split('\n')) 49 if log_count != 1: 50 raise error.TestError('Log \"%s\" is found %d times!' 51 % (pwrd_log, log_count)) 52 return datetime.datetime.strptime(out_log[1:12], "%m%d/%H%M%S") 53 54 55 def get_display_mode_timestamp(self): 56 """ Takes the first _RESUME_END_LOG line after _RESUME_START_LOG line 57 and returns its timestamp. 58 59 @returns log timestamp as datetime. 60 """ 61 62 cmd = ('sed -nr \'/%s/,$p\' %s | grep -E %s | head -n 1' 63 % (_RESUME_START_LOG.replace("\"",""), 64 _POWERD_LOG_PATH, _RESUME_END_LOG)) 65 out_log = self.host.run(cmd, ignore_status=True).stdout.strip() 66 return datetime.datetime.strptime(out_log[1:12], "%m%d/%H%M%S") 67 68 69 def get_suspend_resume_time(self): 70 """ Reads powerd log and takes suspend and resume timestamps. 71 72 @returns times took to suspend and resume as a tuple. 73 74 @raises error.TestError: if timestamps are not sequential. 75 """ 76 77 suspend_start = self.get_suspender_log_stamp(_SUSPEND_START_LOG) 78 suspend_end = self.get_suspender_log_stamp(_SUSPEND_END_LOG) 79 resume_start = self.get_suspender_log_stamp(_RESUME_START_LOG) 80 resume_end = self.get_display_mode_timestamp() 81 82 83 logging.info([suspend_start, suspend_end, 84 resume_start, resume_end]) 85 86 if not all([resume_end >= resume_start, 87 resume_start > suspend_end, 88 suspend_end >= suspend_start]): 89 raise error.TestError('Log timestamps are not sequental!') 90 91 time_to_susp = (suspend_end - suspend_start).total_seconds() 92 time_to_res = (resume_end - resume_start).total_seconds() 93 94 return (time_to_susp, time_to_res) 95 96 97 def get_lsusb_lines(self): 98 """ Executes lsusb and returns list of the output lines.""" 99 output =self.host.run('lsusb', ignore_status=True).stdout 100 return output.strip().split('\n') 101 102 103 def run_once(self, host, plug_usb=False): 104 """ Running the suspend-resume timing test. 105 106 @param host: device under test host. 107 @param plug_usb: whether to plug extetrnal USB through servo. 108 109 @raises TestFail: if time to suspend to resume exceeds the bar 110 and if no peripherals are connected to servo. 111 """ 112 self.host = host 113 self.host.servo.set('dut_hub1_rst1', 'on') 114 115 # Reboot to create new powerd.Latest log file. 116 self.host.reboot() 117 118 # Test user login. 119 autotest_client = autotest.Autotest(self.host) 120 autotest_client.run_test("desktopui_SimpleLogin", 121 exit_without_logout=True) 122 123 # Plug USB hub with peripherals. 124 if plug_usb: 125 lsusb_unplugged_len = len(self.get_lsusb_lines()) 126 self.host.servo.switch_usbkey('dut') 127 self.host.servo.set('usb_mux_sel3', 'dut_sees_usbkey') 128 self.host.servo.set('dut_hub1_rst1', 'off') 129 time.sleep(_SHORT_WAIT_) 130 lsusb_plugged_len = len(self.get_lsusb_lines()) 131 if lsusb_plugged_len - lsusb_unplugged_len < _SERVO_USB_NUM + 1: 132 raise error.TestFail('No peripherals are connected to servo!') 133 134 self.host.suspend(suspend_time=_SUSPEND_TIME) 135 self.host.run('sync') 136 137 138 errors = [] 139 time_to_suspend, time_to_resume = self.get_suspend_resume_time() 140 if time_to_suspend > _TIME_TO_SUSPEND_BAR: 141 errors.append('Suspend time is too long: %d' % time_to_suspend) 142 if time_to_resume > _TIME_TO_RESUME_BAR: 143 errors.append('Resume time is too long: %d' % time_to_resume) 144 if errors: 145 raise error.TestFail('; '.join(set(errors))) 146 147 148