1# Copyright (c) 2012 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
5"""Provides utility methods for controlling powerd in ChromiumOS."""
6
7import errno
8import logging
9import multiprocessing
10import os
11import rtc
12import time
13import upstart
14
15SYSFS_POWER_STATE = '/sys/power/state'
16SYSFS_WAKEUP_COUNT = '/sys/power/wakeup_count'
17
18
19class SuspendFailure(Exception):
20    """Base class for a failure during a single suspend/resume cycle."""
21    pass
22
23
24class SuspendTimeout(SuspendFailure):
25    """Suspend took too long, got wakeup event (RTC tick) before it was done."""
26    pass
27
28
29class KernelError(SuspendFailure):
30    """Kernel problem encountered during suspend/resume.
31
32    Whitelist is an array of a 2-entry tuples consisting of (source regexp, text
33    regexp).  For example, kernel output might look like,
34
35      [  597.079950] WARNING: CPU: 0 PID: 21415 at \
36      <path>/v3.18/drivers/gpu/drm/i915/intel_pm.c:3687 \
37      skl_update_other_pipe_wm+0x136/0x18a()
38      [  597.079962] WARN_ON(!wm_changed)
39
40    source regexp should match first line above while text regexp can match
41    up to 2 lines below the source.  Note timestamps are stripped prior to
42    comparing regexp.
43    """
44    WHITELIST = [
45            # crosbug.com/37594: debug tracing clock desync we don't care about
46            (r'kernel/trace/ring_buffer.c:\d+ rb_reserve_next_event',
47             r'Delta way too big!'),
48            # TODO(crosbug.com/p/52008): Remove from whitelist once watermark
49            # implementation has landed.
50            (r'v3.18/\S+/intel_pm.c:\d+ skl_update_other_pipe_wm',
51            r'WARN_ON\(\!wm_changed\)')
52        ]
53
54
55class FirmwareError(SuspendFailure):
56    """String 'ERROR' found in firmware log after resume."""
57    WHITELIST = [
58            # crosbug.com/36762: no one knows, but it has always been there
59            ('^stumpy', r'PNP: 002e\.4 70 irq size: 0x0000000001 not assigned'),
60            # crbug.com/221538: no one knows what ME errors mean anyway
61            ('^parrot', r'ME failed to respond'),
62        ]
63
64
65class SpuriousWakeupError(SuspendFailure):
66    """Received spurious wakeup while suspending or woke before schedule."""
67    S3_WHITELIST = [  # (<board>, <eventlog wake source>, <syslog wake source>)
68            # crbug.com/220014: spurious trackpad IRQs
69            ('^link', 'Wake Source | GPIO | 12', ''),
70            # crbug.com/345327: unknown, probably same as crbug.com/290923
71            ('^x86-alex', '', ''),   # alex can report neither, blanket ignore
72            # crbug.com/355106: unknown, possibly related to crbug.com/290923
73            ('^lumpy|^parrot', '', 'PM1_STS: WAK PWRBTN'),
74        ]
75    S0_WHITELIST = [  # (<board>, <kernel wake source>)
76            # crbug.com/290923: spurious keyboard IRQ, believed to be from Servo
77            ('^x86-alex|^lumpy|^parrot|^butterfly', 'serio0'),
78            # crosbug.com/p/46140: battery event caused by MKBP
79            ('^elm|^oak', 'spi32766.0'),
80        ]
81
82class MemoryError(SuspendFailure):
83    """memory_suspend_test found memory corruption."""
84    pass
85
86
87class SuspendNotAllowed(SuspendFailure):
88    """Suspend was not allowed to be performed."""
89    pass
90
91
92class S0ixResidencyNotChanged(SuspendFailure):
93    """power_SuspendStress test found CPU/SoC is unable to idle properly
94    when suspended to S0ix. """
95    pass
96
97def prepare_wakeup(seconds):
98    """Prepare the device to wake up from an upcoming suspend.
99
100    @param seconds: The number of seconds to allow the device to suspend.
101    """
102    # May cause DUT not wake from sleep if the suspend time is 1 second.
103    # It happens when the current clock (floating point) is close to the
104    # next integer, as the RTC sysfs interface only accepts integers.
105    # Make sure it is larger than or equal to 2.
106    assert seconds >= 2
107    wakeup_count = read_wakeup_count()
108    alarm = int(rtc.get_seconds() + seconds)
109    logging.debug('Suspend for %d seconds, wakealarm = %d', seconds, alarm)
110    rtc.set_wake_alarm(alarm)
111    return (alarm, wakeup_count)
112
113
114def check_wakeup(alarm):
115    """Verify that the device did not wakeup early.
116
117    @param alarm: The time at which the device was expected to wake up.
118    """
119    now = rtc.get_seconds()
120    if now < alarm:
121        logging.error('Woke up early at %d', now)
122        raise SpuriousWakeupError('Woke from suspend early')
123
124
125def do_suspend(suspend_seconds, delay_seconds=0):
126    """Do a suspend using the power manager.
127
128    Wait for |delay_seconds|, suspend the system to RAM (S3), waking up again
129    after having been suspended for |suspend_seconds|, using the
130    powerd_dbus_suspend program. Function will block until suspend/resume
131    has completed or failed. Returns the wake alarm time from the RTC as epoch.
132
133    @param suspend_seconds: Number of seconds to suspend the DUT.
134    @param delay_seconds: Number of seconds wait before suspending the DUT.
135
136    """
137    alarm, wakeup_count = prepare_wakeup(suspend_seconds)
138    upstart.ensure_running('powerd')
139    command = ('/usr/bin/powerd_dbus_suspend --delay=%d --timeout=30 '
140               '--wakeup_count=%d') % (delay_seconds, wakeup_count)
141    logging.info("Running '%s'", command)
142    os.system(command)
143    check_wakeup(alarm)
144    return alarm
145
146
147def suspend_bg_for_dark_resume(delay_seconds=0):
148    """Do a non-blocking indefinite suspend using power manager. ONLY USE THIS
149    IF YOU ARE ABSOLUTELY CERTAIN YOU NEED TO.
150
151    Wait for |delay_seconds|, then suspend to RAM (S3). This does not set an RTC
152    alarm and does not pass an external wakeup count. It is meant to be used for
153    dark resume testing, where the server-side API exposes it in such a fashion
154    that the DUT will be woken by the server no matter how the test is exited.
155
156    @param delay_seconds: Number of seconds wait before suspending the DUT.
157
158    """
159    upstart.ensure_running('powerd')
160    command = ('/usr/bin/powerd_dbus_suspend --delay=%d '
161               '--timeout=30') % delay_seconds
162    logging.info("Running '%s'", command)
163    process = multiprocessing.Process(target=os.system, args=(command,))
164    process.start()
165
166
167def kernel_suspend(seconds, state='mem'):
168    """Do a kernel suspend.
169
170    Suspend the system to @state, waking up again after |seconds|, by directly
171    writing to /sys/power/state. Function will block until suspend/resume has
172    completed or failed.
173
174    @param seconds: The number of seconds to suspend the device.
175    @param state: power state to suspend to.  DEFAULT mem.
176    """
177    alarm, wakeup_count = prepare_wakeup(seconds)
178    logging.debug('Saving wakeup count: %d', wakeup_count)
179    write_wakeup_count(wakeup_count)
180    try:
181        logging.info('Suspending at %d', rtc.get_seconds())
182        with open(SYSFS_POWER_STATE, 'w') as sysfs_file:
183            sysfs_file.write(state)
184    except IOError as e:
185        logging.exception('Writing to %s failed', SYSFS_POWER_STATE)
186        if e.errno == errno.EBUSY and rtc.get_seconds() >= alarm:
187            # The kernel returns EBUSY if it has to abort because
188            # another wakeup fires before we've reached suspend.
189            raise SpuriousWakeupError('Received spurious wakeup in kernel.')
190        else:
191            # Some driver probably failed to suspend properly.
192            # A hint as to what failed is in errno.
193            raise KernelError('Suspend failed: %s' % e.strerror)
194    else:
195        logging.info('Woke from suspend at %d', rtc.get_seconds())
196    logging.debug('New wakeup count: %d', read_wakeup_count())
197    check_wakeup(alarm)
198
199
200def idle_suspend(seconds):
201    """
202    Wait for the system to suspend to RAM (S3), scheduling the RTC to wake up
203    |seconds| after this function was called. Caller must ensure that the system
204    will idle-suspend in time for this to happen. Returns the wake alarm time
205    from the RTC as epoch.
206
207    @param seconds: The number of seconds before wakeup.
208    """
209    alarm, _ = prepare_wakeup(seconds)
210    while rtc.get_seconds() < alarm:
211        time.sleep(0.2)
212
213    # tell powerd something happened, or it will immediately idle-suspend again
214    # TODO: switch to cros.power_utils#call_powerd_dbus_method once this
215    # horrible mess with the WiFi tests and this file's imports is solved
216    logging.debug('Simulating user activity after idle suspend...')
217    os.system('dbus-send --type=method_call --system '
218              '--dest=org.chromium.PowerManager /org/chromium/PowerManager '
219              'org.chromium.PowerManager.HandleUserActivity')
220
221    return alarm
222
223
224def memory_suspend(seconds, size=0):
225    """Do a memory suspend.
226
227    Suspend the system to RAM (S3), waking up again after |seconds|, using
228    the memory_suspend_test tool. Function will block until suspend/resume has
229    completed or failed. Returns the wake alarm time from the RTC as epoch.
230
231    @param seconds: The number of seconds to suspend the device.
232    @param size: Amount of memory to allocate, in bytes.
233                 Set to 0 to let memory_suspend_test determine amount of memory.
234    """
235    # since we cannot have utils.system_output in here, we need a workaround
236    output = '/tmp/memory_suspend_output'
237    alarm, wakeup_count = prepare_wakeup(seconds)
238    status = os.system('/usr/bin/memory_suspend_test --wakeup_count=%d '
239                       '--size=%d > %s' % (wakeup_count, size, output))
240    status = os.WEXITSTATUS(status)
241    if status == 2:
242        logging.error('memory_suspend_test found the following errors:')
243        for line in open(output, 'r'):
244            logging.error(line)
245        raise MemoryError('Memory corruption found after resume')
246    elif status == 1:
247        raise SuspendFailure('Failure in powerd_suspend during memory test')
248    elif status:
249        raise SuspendFailure('Unknown failure in memory_suspend_test (crash?)')
250    check_wakeup(alarm)
251    return alarm
252
253
254def read_wakeup_count():
255    """
256    Retrieves the current value of /sys/power/wakeup_count.
257    """
258    with open(SYSFS_WAKEUP_COUNT) as sysfs_file:
259        return int(sysfs_file.read().rstrip('\n'))
260
261
262def write_wakeup_count(wakeup_count):
263    """Writes a value to /sys/power/wakeup_count.
264
265    @param wakeup_count: The wakeup count value to write.
266    """
267    try:
268        with open(SYSFS_WAKEUP_COUNT, 'w') as sysfs_file:
269            sysfs_file.write(str(wakeup_count))
270    except IOError as e:
271        if (e.errno == errno.EINVAL and read_wakeup_count() != wakeup_count):
272            raise SpuriousWakeupError('wakeup_count changed before suspend')
273        else:
274            raise
275