1#!/usr/bin/env python3

2"""

3 Program to automate system entering and resuming from sleep states

4

5 Copyright (C) 2010-2014 Canonical Ltd.

6

7 Author:

8 Jeff Lane <jeffrey.lane@canonical.com>

9 Daniel Manrique <roadmr@ubuntu.com>

10

11 This program is free software: you can redistribute it and/or modify

12 it under the terms of the GNU General Public License version 2,

13 as published by the Free Software Foundation.

14

15 This program is distributed in the hope that it will be useful,

16 but WITHOUT ANY WARRANTY; without even the implied warranty of

17 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the

18 GNU General Public License for more details.

19

20 You should have received a copy of the GNU General Public License

21 along with this program. If not, see <http://www.gnu.org/licenses/>.

22"""

23

24 import logging

25 import os

26 import re

27 import sys

28 import syslog

29

30 from optparse import OptionParser, OptionGroup

31 from subprocess import call

32

33

34 class ListDictHandler(logging.StreamHandler):

35 """

36 Extends logging.StreamHandler to handle list, tuple and dict objects

37 internally, rather than through external code, mainly used for debugging

38 purposes.

39

40 """

41

42 def emit(self, record):

43 if isinstance(

44 record.msg,

45 (

46 list,

47 tuple,

48 ),

49 ):

50 for msg in record.msg:

51 logger = logging.getLogger(record.name)

52 new_record = logger.makeRecord(

53 record.name,

54 record.levelno,

55 record.pathname,

56 record.lineno,

57 msg,

58 record.args,

59 record.exc_info,

60 record.funcName,

61 )

62 logging.StreamHandler.emit(self, new_record)

63 elif isinstance(record.msg, dict):

64 for key, val in record.msg.items():

65 logger = logging.getLogger(record.name)

66 new_msg = "%s: %s" % (key, val)

67 new_record = logger.makeRecord(

68 record.name,

69 record.levelno,

70 record.pathname,

71 record.lineno,

72 new_msg,

73 record.args,

74 record.exc_info,

75 record.funcName,

76 )

77 logging.StreamHandler.emit(self, new_record)

78 else:

79 logging.StreamHandler.emit(self, record)

80

81

82 class SuspendTest:

83 """

84 Creates an object to handle the actions necessary for suspend/resume

85 testing.

86

87 """

88

89 def __init__(self):

90 self.wake_time = 0

91 self.current_time = 0

92 self.last_time = 0

93

94 def CanWeSleep(self, mode):

95 """

96 Test to see if S3 state is available to us. /proc/acpi/* is old

97 and will be deprecated, using /sys/power to maintain usefulness for

98 future kernels.

99

100 """

101 states_fh = open("/sys/power/state", "rb", 0)

102 try:

103 states = states_fh.read().decode("ascii").split()

104 finally:

105 states_fh.close()

106 logging.debug("The following sleep states were found:")

107 logging.debug(states)

108

109 if mode in states:

110 return True

111 else:

112 return False

113

114 def GetCurrentTime(self):

115

116 time_fh = open("/sys/class/rtc/rtc0/since_epoch", "rb", 0)

117 try:

118 time = int(time_fh.read().decode("ascii"))

119 finally:

120 time_fh.close()

121 return time

122

123 def SetWakeTime(self, time):

124 """

125 Get the current epoch time from /sys/class/rtc/rtc0/since_epoch

126 then add time and write our new wake_alarm time to

127 /sys/class/rtc/rtc0/wakealarm.

128

129 The math could probably be done better but this method avoids having to

130 worry about whether or not we're using UTC or local time for both the

131 hardware and system clocks.

132

133 """

134 self.last_time = self.GetCurrentTime()

135 logging.debug("Current epoch time: %s" % self.last_time)

136

137 wakealarm_fh = open("/sys/class/rtc/rtc0/wakealarm", "wb", 0)

138

139 try:

140 wakealarm_fh.write("0\n".encode("ascii"))

141 wakealarm_fh.flush()

142

143 wakealarm_fh.write("+{}\n".format(time).encode("ascii"))

144 wakealarm_fh.flush()

145 finally:

146 wakealarm_fh.close()

147

148 logging.debug("Wake alarm in %s seconds" % time)

149

150 def DoSuspend(self, mode):

151 """

152 Suspend the system and hope it wakes up.

153 Previously tried writing new state to /sys/power/state but that

154 seems to put the system into an uncrecoverable S3 state. So far,

155 pm-suspend seems to be the most reliable way to go.

156

157 """

158 # Set up our start and finish markers

159 self.time_stamp = self.GetCurrentTime()

160 self.start_marker = "CHECKBOX SLEEP TEST START %s" % self.time_stamp

161 self.end_marker = "CHECKBOX SLEEP TEST STOP %s" % self.time_stamp

162 self.MarkLog(self.start_marker)

163

164 if mode == "mem":

165 status = call("/usr/sbin/pm-suspend")

166 elif mode == "disk":

167 status = call("/usr/sbin/pm-hibernate")

168 else:

169 logging.debug("Unknown sleep state passed: %s" % mode)

170 status == 1

171

172 if status == 0:

173 logging.debug("Successful suspend")

174 else:

175 logging.debug("Error while running pm-suspend")

176 self.MarkLog(self.end_marker)

177

178 def GetResults(self, mode, perf):

179 """

180 This will parse /var/log/messages for our start and end markers. Then

181 it'll find a few key phrases that are part of the sleep and resume

182 process, grab their timestamps, Bob's your Uncle and return a

183 three-tuple consisting of: (PASS/FAIL,Sleep elapsed time, Resume

184 elapsed time)

185 """

186 # figure out our elapsed time

187 logfile = "/var/log/syslog"

188 log_fh = open(logfile, "r")

189 line = ""

190 run_complete = "Fail"

191 sleep_start_time = 0.0

192 sleep_end_time = 0.0

193 resume_start_time = 0.0

194 resume_end_time = 0.0

195

196 while self.start_marker not in line:

197 line = log_fh.readline()

198 if self.start_marker in line:

199 logging.debug("Found Start Marker")

200 loglist = log_fh.readlines()

201

202 if perf:

203 for idx in range(0, len(loglist)):

204 if "PM: Syncing filesystems" in loglist[idx]:

205 sleep_start_time = re.split(r"[\[\]]", loglist[idx])[

206 1

207 ].strip()

208 logging.debug("Sleep started at %s" % sleep_start_time)

209 if "ACPI: Low-level resume complete" in loglist[idx]:

210 sleep_end_time = re.split(r"[\[\]]", loglist[idx - 1])[

211 1

212 ].strip()

213 logging.debug("Sleep ended at %s" % sleep_end_time)

214 resume_start_time = re.split(r"[\[\]]", loglist[idx])[

215 1

216 ].strip()

217 logging.debug("Resume started at %s" % resume_start_time)

218 idx += 1

219 if "Restarting tasks" in loglist[idx]:

220 resume_end_time = re.split(r"[\[\]]", loglist[idx])[

221 1

222 ].strip()

223 logging.debug("Resume ended at %s" % resume_end_time)

224 if self.end_marker in loglist[idx]:

225 logging.debug(

226 "End Marker found, run appears to " "have completed"

227 )

228 run_complete = "Pass"

229 break

230

231 sleep_elapsed = float(sleep_end_time) - float(sleep_start_time)

232 resume_elapsed = float(resume_end_time) - float(resume_start_time)

233 logging.debug("Sleep elapsed: %.4f seconds" % sleep_elapsed)

234 logging.debug("Resume elapsed: %.4f seconds" % resume_elapsed)

235 else:

236 if self.end_marker in loglist:

237 logging.debug(

238 "End Marker found, " "run appears to have completed"

239 )

240 run_complete = "Pass"

241 sleep_elapsed = None

242 resume_elapsed = None

243

244 return (run_complete, sleep_elapsed, resume_elapsed)

245

246 def MarkLog(self, marker):

247 """

248 Write a stamped marker to syslogd (will appear in /var/log/messages).

249 This is used to calculate the elapsed time for each iteration.

250 """

251 syslog.syslog(syslog.LOG_INFO, "---" + marker + "---")

252

253 def CheckAlarm(self, mode):

254 """

255 A better method for checking if system woke via rtc alarm IRQ. If the

256 system woke via IRQ, then alarm_IRQ will be 'no' and wakealarm will be

257 an empty file. Otherwise, alarm_IRQ should still say yes and wakealarm

258 should still have a number in it (the original alarm time), indicating

259 the system did not wake by alarm IRQ, but by some other means.

260 """

261 rtc = {}

262 rtc_fh = open("/proc/driver/rtc", "rb", 0)

263 alarm_fh = open("/sys/class/rtc/rtc0/wakealarm", "rb", 0)

264 try:

265 rtc_data = rtc_fh.read().decode("ascii").splitlines()

266 for item in rtc_data:

267 rtc_entry = item.partition(":")

268 rtc[rtc_entry[0].strip()] = rtc_entry[2].strip()

269 finally:

270 rtc_fh.close()

271

272 try:

273 alarm = int(alarm_fh.read().decode("ascii"))

274 except ValueError:

275 alarm = None

276 finally:

277 alarm_fh.close()

278

279 logging.debug("Current RTC entries")

280 logging.debug(rtc)

281 logging.debug("Current wakealarm %s" % alarm)

282

283 # see if there's something in wakealarm or alarm_IRQ

284 # Return True indicating the alarm is still set

285 # Return False indicating the alarm is NOT set.

286 # This is currently held up by a bug in PM scripts that

287 # does not reset alarm_IRQ when waking from hibernate.

288 # https://bugs.launchpad.net/ubuntu/+source/linux/+bug/571977

289 if mode == "mem":

290 if (alarm is not None) or (rtc["alarm_IRQ"] == "yes"):

291 logging.debug("alarm is %s" % alarm)

292 logging.debug("rtc says alarm_IRQ: %s" % rtc["alarm_IRQ"])

293 return True

294 else:

295 logging.debug("alarm was cleared")

296 return False

297 else:

298 # This needs to be changed after we get a way around the

299 # hibernate bug. For now, pretend that the alarm is unset for

300 # hibernate tests.

301 logging.debug("mode is %s so we're skipping success check" % mode)

302 return False

303

304

305 def main():

306 usage = "Usage: %prog [OPTIONS]"

307 parser = OptionParser(usage)

308 group = OptionGroup(

309 parser,

310 "This will not work for hibernat testing due"

311 " to a kernel timestamp bug when doing an S4 "

312 "(hibernate/resume) sleep cycle",

313 )

314 group.add_option(

315 "-p",

316 "--perf",

317 action="store_true",

318 default=False,

319 help="Add some output that tells you how long it "

320 "takes to enter a sleep state and how long it "

321 "takes to resume.",

322 )

323 parser.add_option(

324 "-i",

325 "--iterations",

326 action="store",

327 type="int",

328 metavar="NUM",

329 default=1,

330 help="The number of times to run the suspend/resume "

331 "loop. Default is %default",

332 )

333 parser.add_option(

334 "-w",

335 "--wake-in",

336 action="store",

337 type="int",

338 metavar="NUM",

339 default=60,

340 dest="wake_time",

341 help="Sets wake up time (in seconds) in the future "

342 "from now. Default is %default.",

343 )

344 parser.add_option(

345 "-s",

346 "--sleep-state",

347 action="store",

348 default="mem",

349 metavar="MODE",

350 dest="mode",

351 help="Sets the sleep state to test. Passing mem will "

352 "set the sleep state to Suspend-To-Ram or S3. Passing "

353 "disk will set the sleep state to Suspend-To-Disk or S4 "

354 "(hibernate). Default sleep state is %default",

355 )

356 parser.add_option(

357 "-d",

358 "--debug",

359 action="store_true",

360 default=False,

361 help="Choose this to add verbose output for debug \

362 purposes",

363 )

364 parser.add_option_group(group)

365 (options, args) = parser.parse_args()

366 options_dict = vars(options)

367

368 if not (os.geteuid() == 0):

369 parser.error("Must be run as root.")

370 return 1

371

372 # Set up logging handler

373 format = "%(message)s"

374 handler = ListDictHandler(sys.stdout)

375 handler.setFormatter(logging.Formatter(format))

376 handler.setLevel(logging.INFO)

377

378 # Set up the logger

379 logger = logging.getLogger()

380 logger.setLevel(logging.DEBUG)

381

382 if options.debug:

383 handler.setLevel(logging.DEBUG)

384

385 logger.addHandler(handler)

386 logging.debug("Running with these options")

387 logging.debug(options_dict)

388

389 suspender = SuspendTest()

390 run_result = {}

391 run_count = 0

392 fail_count = 0

393

394 # Chcek fo the S3 state availability

395 if not suspender.CanWeSleep(options.mode):

396 logging.error("%s sleep state not supported" % options.mode)

397 return 1

398 else:

399 logging.debug(

400 "%s sleep state supported, continuing test" % options.mode

401 )

402

403 # We run the following for the number of iterations requested

404 for iteration in range(0, options.iterations):

405 # Set new alarm time and suspend.

406 suspender.SetWakeTime(options.wake_time)

407 suspender.DoSuspend(options.mode)

408 run_count += 1

409 run_result[run_count] = suspender.GetResults(

410 options.mode, options.perf

411 )

412 if suspender.CheckAlarm(options.mode):

413 logging.debug("The alarm is still set")

414

415 if options.perf:

416 sleep_total = 0.0

417 resume_total = 0.0

418 logging.info("=" * 20 + " Test Results " + "=" * 20)

419 logging.info(run_result)

420

421 for k in run_result.keys():

422 sleep_total += run_result[k][1]

423 resume_total += run_result[k][2]

424 sleep_avg = sleep_total / run_count

425 resume_avg = resume_total / run_count

426 logging.info("Average time to sleep: %.4f" % sleep_avg)

427 logging.info("Average time to resume: %.4f" % resume_avg)

428 for run in run_result.keys():

429 if "Fail" in run_result[run]:

430 fail_count += 1

431

432 if fail_count > 0:

433 logging.error("%s sleep/resume test cycles failed" % fail_count)

434 logging.error(run_result)

435 return 1

436 else:

437 logging.info(

438 "Successfully completed %s sleep iterations" % options.iterations

439 )

440 return 0

441

442

443 if __name__ == "__main__":

444 sys.exit(main())