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