New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 817957 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Mar 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: ----

Blocked on:
issue 818010



Sign in to add a comment

testForegroundTab failure on chromeos 3/1

Project Member Reported by sheriff-...@appspot.gserviceaccount.com, Mar 1 2018

Issue description

Filed by sheriff-o-matic@appspot.gserviceaccount.com on behalf of oshima@google.com

amd64-generic-telemetry:14167 failed

Builders failed on: 
- amd64-generic-telemetry: 
  https://luci-milo.appspot.com/buildbot/chromiumos.chromium/amd64-generic-telemetry/14167


 
Cc: -oshima@google.com ejcaruso@chromium.org achuith@chromium.org osh...@chromium.org erosky@chromium.org nednguyen@chromium.org
Components: Tests>Telemetry
Labels: -Pri-2 OS-Chrome Pri-1
Only failure I could find is this, although I may be missing something else. +sheriffs and telemetry folks.

---
/tmp/cbuildbotITcun6/telemetry_unit_server/test_harness/all/SimpleTestVerify/1_autotest_tests/results-1-telemetry_UnitTestsServer/telemetry_UnitTestsServer.user/telemetry_UnitTests          03/01 10:22:58.585 ERROR|         traceback:0013| CmdError: Command <ls /sys/devices/system/cpu/cpu*/cpufreq/cpuinfo_max_freq> failed, rc=2, Command returned non-zero exit status

status.log:
https://00e9e64bacdc91ef206d4e041831a0f787e91a64d2ff54a417-apidata.googleusercontent.com/download/storage/v1/b/chromeos-image-archive/o/amd64-generic-telemetry%2FR66-10449.0.0-b14167%2Fvm_test_results_1%2Ftelemetry_unit_server%2Ftest_harness%2Ffailed%2FSimpleTestVerify%2F1_autotest_tests%2Ftest_report.log?qk=AD5uMEsVKmPg9SNvZ7BQxkv0ro8f2TCdSR4iJcV2mbcCBrry-7UahYRXeNgk6PY-7vxvzLmVRduj5yvx-rSUu6ULySbvguKZY0599sm-UzKsuLUsnLtjUBR905dqjCVY_UZBZY6Rrk-Xnv70szCTWaVfpPTPGiyj5NUfZL4AclLHR10yrOOpeQiWknUnDtWru3Io4kCOs0ctU9fvux8BFv4eskvwEk6q7bpRUpXhhrIOEYHQqVKhs8GSnPugN8vdHqYjyWNVCWV0DNFsCzsXFOm-q18w87X9VRoK9r5Y39y-Z0IqbY97PflTDZJ4u8ZtogyooPKo3628Qt9LMXiM6UH0Xl2TCjgjunFNUOlEhP-WSpyq7eL7UiXCLUNqN3RV6d8vgbbRad83hvhtsCPtykJKTSJAU6up3P2rM10J0zFYNhnzlp6FtTh0yW2IJ8NXBmiSO_HmsnSsRk7qMIJY5sqeyWRLuBwlDlN0folklmzBeFVa0qlY3XRqBGuJNwpav3_6rFSDz0CoY3EdrHWjnfNByGm8bzfXpO-QHDjOT9nT0_sjsYop8PkfQna50xZbmvJLaHwz96p1lJYhJ7LOEr40nMT3DVkAspPbZ-P34zNlXEMGKSd4a8GAGD0yd2hljYSI0hZc54hHGpGym4FcySRi4XXKHqT2nFbPh3bcjf1uZfJrkn7RK3z3DWusAIbES_e8HGp7n985p-s0NHFY3RjFc-B98Ui1ctvgBd0NprZqMNtfxH5z-h1jh3Gb6aBFqm6QGK9FBjFiCp-ZntNlpnhF3LySdYbx6FO4SX0ruqr4a2eyF7GXFfnlZqIawPor1fHv4FCde09L_-kVLyrx8a5jQB4Tjdrl6plAFLh5joA2tYIb-i8Q__KWjhPIj_4yE5Reb-rT4-QIHYjfg7N8WGjKhcQpOMAjkxQpkVFjo1_MlxBUYGTO2lGfbBDiQ-OqPo2D09HJ4e8p


-----
03/01 11:09:46.215 ERROR|               log:0027| pre-test siteration sysinfo error:
03/01 11:09:46.227 ERROR|         traceback:0013| Traceback (most recent call last):
03/01 11:09:46.237 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/log.py", line 25, in decorated_func
03/01 11:09:46.247 ERROR|         traceback:0013|     fn(*args, **dargs)
03/01 11:09:46.256 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/base_sysinfo.py", line 394, in log_before_each_iteration
03/01 11:09:46.266 ERROR|         traceback:0013|     board = utils.get_board_with_frequency_and_memory()
03/01 11:09:46.275 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/utils.py", line 2025, in get_board_with_frequency_and_memory
03/01 11:09:46.286 ERROR|         traceback:0013|     frequency = int(round(get_cpu_max_frequency() * 1e-8)) * 0.1
03/01 11:09:46.295 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/utils.py", line 1852, in get_cpu_max_frequency
03/01 11:09:46.304 ERROR|         traceback:0013|     paths = _get_cpufreq_paths('cpuinfo_max_freq')
03/01 11:09:46.313 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/utils.py", line 2109, in _get_cpufreq_paths
03/01 11:09:46.323 ERROR|         traceback:0013|     paths = utils.run(cmd, verbose=False).stdout.splitlines()
03/01 11:09:46.332 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/utils.py", line 748, in run
03/01 11:09:46.343 ERROR|         traceback:0013|     "Command returned non-zero exit status")
03/01 11:09:46.363 ERROR|         traceback:0013| CmdError: Command <ls /sys/devices/system/cpu/cpu*/cpufreq/cpuinfo_max_freq> failed, rc=2, Command returned non-zero exit status
03/01 11:09:46.373 ERROR|         traceback:0013| * Command: 
03/01 11:09:46.382 ERROR|         traceback:0013|     ls /sys/devices/system/cpu/cpu*/cpufreq/cpuinfo_max_freq
03/01 11:09:46.390 ERROR|         traceback:0013| Exit status: 2
03/01 11:09:46.399 ERROR|         traceback:0013| Duration: 0.0055730342865
03/01 11:09:46.409 ERROR|         traceback:0013| 
03/01 11:09:46.417 ERROR|         traceback:0013| stderr:
03/01 11:09:46.426 ERROR|         traceback:0013| ls: cannot access '/sys/devices/system/cpu/cpu*/cpufreq/cpuinfo_max_freq': No such file or directory
03/01 11:09:46.435 DEBUG|              test:0384| before_iteration_hooks completed
Cc: bleung@chromium.org
Just found this :  crbug.com/815220 

bleung@, looks like this is the same issue?
Really strange:
3/01 07:43:52.002 INFO |run_chromeos_tests:0052| [347/1152] telemetry.internal.browser.browser_unittest.BrowserTest.testForegroundTab failed unexpectedly 11.3489s:
03/01 07:43:52.003 INFO |run_chromeos_tests:0052|   Traceback (most recent call last):
03/01 07:43:52.005 INFO |run_chromeos_tests:0052|     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/testing/browser_test_case.py", line 39, in WrappedMethod
03/01 07:43:52.007 INFO |run_chromeos_tests:0052|       method(self)
03/01 07:43:52.009 INFO |run_chromeos_tests:0052|     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_unittest.py", line 80, in testForegroundTab
03/01 07:43:52.010 INFO |run_chromeos_tests:0052|       self.assertEqual(self._browser.foreground_tab, original_tab)
03/01 07:43:52.011 INFO |run_chromeos_tests:0052|     File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 95, in foreground_tab
03/01 07:43:52.013 INFO |run_chromeos_tests:0052|       raise exceptions.TabMissingError("No foreground tab found")
03/01 07:43:52.014 INFO |run_chromeos_tests:0052|   TabMissingError: No foreground tab found
Summary: testForegroundTab failure on chromeos 3/1 (was: amd64-generic-telemetry:14167 failed)
Seems to be a consistent failure in testForegroundTab

This is the list of catapult CLs and none of them stand out:
https://chromium.googlesource.com/catapult.git/+log/b019720d08b2..279fcf542e09

This could be a change in behavior in chrome
None of the rest of the chrome CLs particularly stand out either. Oshima-san, would you be possibly able to do a bisect?
which log file was it?
Owner: erosky@chromium.org
Details on how to run the test are here:
https://chromium.googlesource.com/chromiumos/docs/+/master/cros_vm.md

Basically enter the cros-chrome SDK:
achuith@achuithz620:~/code/chrome$ cros chrome-sdk --debug --download-vm --board=amd64-generic --clear-sdk-cache

Start the VM:
(sdk amd64-generic R66-10436.0.0-b21303) achuith@achuithz620 ~/code/chrome $ cros_vm --start

Run the test:
(sdk amd64-generic R66-10448.0.0-b21345) achuith@achuithz620 ~/code/chrome $ src/third_party/catapult/telemetry/bin/run_tests --browser=cros-chrome --remote=localhost --remote-ssh-port=9222 testForegroundTab

To update chrome in the VM in the doc:
(sdk) .../chrome/src $ autoninja -C out_$SDK_BOARD/Release/ chrome chrome_sandbox nacl_helper
(sdk) .../chrome/src $ deploy_chrome --build-dir=out_$SDK_BOARD/Release/ --to=localhost --port=9222
For the log, click on telemetry_UnitTestsServer, which will take you to pantheon.
Click on telemetry_UnitTests->debug->telemetry_UnitTest.DEBUG. Search for 'failed unexpectedly'
It looks like Tab.Activate() isn't always finishing or we're not waiting long enough for it to finish?

It is trying to locate the "foreground tab" by iterating through the tabs and checking for "!document.hidden".

On failure: the original tab IS in the foreground, but "document.hidden" is true (on both tabs) so the test fails.

Not sure why document.hidden would be true on the foreground tab unless maybe the test isn't waiting long enough or something? If I open the inspector and print document.hidden, it is false.
Blockedon: 818010
Cc: x...@chromium.org
Status: Fixed (was: Available)
CL was reverted.
https://chromium-review.googlesource.com/c/chromium/src/+/947802
Cc: oshima@google.com
 Issue 818229  has been merged into this issue.
Last 20 builds have been green - thank you for tracking this down, Evan and Oshima-san!

Sign in to add a comment