platform_SuspendResumeTiming failed unable to find resume start log in powerd.LATEST |
||||
Issue descriptionplatform_SuspendResumeTiming runs in a high-touch pool and is failing being unable to parse out timestamps of empty regexp match result in powerd.LATEST log file. Started with R69-10873.0.0 Devices affected: all Dashboard screenshot: https://screenshot.googleplex.com/jf2P8z66wf2 These few tests search for strings indicating start and end of suspend and resume in powerd.LATEST log. The test log indicates there is no start of resuming string i.e. the string "suspender.* Finishing request [0-9]+ successfully$" Log: 07/14 07:43:31.067 DEBUG| ssh_host:0301| Running (ssh) 'tac /var/log/power_manager/powerd.LATEST | grep -E "suspender.* Starting request [0-9]+$"' from '_call_run_once|run_once|get_suspend_resume_time|get_suspender_log_stamp|run|run_very_slowly' 07/14 07:43:31.481 DEBUG| utils:0286| [stdout] [0714/074303:INFO:suspender.cc(377)] Starting request 102170625 07/14 07:43:31.542 DEBUG| ssh_host:0301| Running (ssh) 'tac /var/log/power_manager/powerd.LATEST | grep -E "suspender.* Starting suspend$"' from '_call_run_once|run_once|get_suspend_resume_time|get_suspender_log_stamp|run|run_very_slowly' 07/14 07:43:31.948 DEBUG| utils:0286| [stdout] [0714/074304:INFO:suspender.cc(457)] Starting suspend 07/14 07:43:32.004 DEBUG| ssh_host:0301| Running (ssh) 'tac /var/log/power_manager/powerd.LATEST | grep -E "suspender.* Finishing request [0-9]+ successfully$"' from '_call_run_once|run_once|get_suspend_resume_time|get_suspender_log_stamp|run|run_very_slowly' 07/14 07:43:32.406 DEBUG| test:0410| Test failed due to time data '' does not match format '%m%d/%H%M%S'. Exception log follows the after_iteration_hooks. There was a suspender related change that came in with this build: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1132428 It seems changed the logged string(s) AI: test manually suspend-resume iteration, and check if a different resume start(and end too) indication string is there or if such missing by some reason.
,
Jul 16
Issue 780063 has been merged into this issue.
,
Jul 18
From the failure's powerd.LATEST: [0718/094357:INFO:suspender.cc(377)] Starting request 83689473 [0718/094357:INFO:daemon.cc(533)] Reading wakeup count from /sys/power/wakeup_count [0718/094357:INFO:daemon.cc(537)] Read wakeup count 3 [0718/094357:INFO:internal_backlight_controller.cc(734)] Setting brightness to 0 (0%) over 0 ms [0718/094357:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 83689473 with 3 pending delay(s) and 0 outstanding delay(s) from previous request [0718/094357:INFO:suspend_delay_controller.cc(86)] Got notification that delay 83689475 (btdispatch) is ready for suspend request 83689473 from :1.23 [0718/094357:INFO:suspend_delay_controller.cc(86)] Got notification that delay 83689473 (shill) is ready for suspend request 83689473 from :1.10 [0718/094357:INFO:daemon.cc(1054)] Chrome is using normal display mode [0718/094357:INFO:suspend_delay_controller.cc(86)] Got notification that delay 83689476 (chrome) is ready for suspend request 83689473 from :1.35 [0718/094357:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready [0718/094357:INFO:suspender.cc(457)] Starting suspend [0718/094357:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7" [0718/094358:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_wakeup_count_valid --suspend_wakeup_count=3" [0718/094413:INFO:daemon.cc(625)] powerd_suspend returned 0 [0718/094413:INFO:main.cc(240)] Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8" [0718/094413:INFO:suspender.cc(416)] Finishing request 83689473 successfully after 15s From a passed powerd.LATEST (R68): [0718/052546:INFO:suspender.cc(377)] Starting request 79036417 [0718/052546:INFO:daemon.cc(606)] Reading wakeup count from /sys/power/wakeup_count [0718/052546:INFO:daemon.cc(610)] Read wakeup count 4 [0718/052546:INFO:internal_backlight_controller.cc(688)] Setting brightness to 0 (0%) over 0 ms [0718/052546:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 79036417 with 4 pending delay(s) and 0 outstanding delay(s) from previous request [0718/052546:INFO:suspend_delay_controller.cc(86)] Got notification that delay 79036420 (btdispatch) is ready for suspend request 79036417 from :1.42 [0718/052546:INFO:suspend_delay_controller.cc(86)] Got notification that delay 79036418 (shill) is ready for suspend request 79036417 from :1.9 [0718/052547:INFO:daemon.cc(1289)] Chrome is using normal display mode [0718/052547:INFO:suspend_delay_controller.cc(86)] Got notification that delay 79036421 (chrome) is ready for suspend request 79036417 from :1.57 [0718/052552:INFO:suspend_delay_controller.cc(86)] Got notification that delay 79036419 (trunksd) is ready for suspend request 79036417 from :1.22 [0718/052552:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready [0718/052552:INFO:suspender.cc(450)] Starting suspend [0718/052552:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_wakeup_count_valid --suspend_wakeup_count=4" [0718/052602:INFO:daemon.cc(698)] powerd_suspend returned 0 [0718/052602:INFO:suspender.cc(408)] Finishing request 79036417 successfully The grep command being run is: 'tac /var/log/power_manager/powerd.LATEST | grep -E "suspender.* Finishing request [0-9]+ successfully$" But it's expecting 'successfully' will be at the end of the string. In the R69 failure log, there is an additional string 'after XX s(econds)' added.
,
Jul 18
Great finding. Lets have the test changed accordingly. Also, can we use this new piece of info? E.g. compare with the _SUSPEND_TIME and add another test failure point.
,
Jul 18
,
Jul 18
https://chromium-review.googlesource.com/c/chromiumos/third_party/autotest/+/1142373 to get the test back to green.
,
Jul 19
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/autotest/+/cc7333e5269994005cc6fc9bf6cb2bcec4e62e93 commit cc7333e5269994005cc6fc9bf6cb2bcec4e62e93 Author: Kalin Stoyanov <kalin@chromium.org> Date: Thu Jul 19 19:14:02 2018 Fix log reading for resume start time. BUG= chromium:863732 TEST=Tested against lab hosts Change-Id: I154ac4fd84dc3fccf5b185b31d8f8948f3ae9ece Reviewed-on: https://chromium-review.googlesource.com/1142373 Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com> Tested-by: Kalin Stoyanov <kalin@chromium.org> Reviewed-by: Harpreet Grewal <harpreet@chromium.org> [modify] https://crrev.com/cc7333e5269994005cc6fc9bf6cb2bcec4e62e93/server/site_tests/platform_SuspendResumeTiming/platform_SuspendResumeTiming.py
,
Jul 23
|
||||
►
Sign in to add a comment |
||||
Comment 1 by ka...@chromium.org
, Jul 16