Issue 894482  has been merged into this issue.

Link to stainless:
https://stainless.corp.google.com/browse/chromeos-image-archive/amd64-generic-chromium-pfq/R71-11147.0.0-rc1/vm_test_results_2/



2018/10/11 03:58:24 1 failed:
2018/10/11 03:58:24   ui.VirtualKeyboardOmnibox
stderr:
test(s) failed. Exception log follows the after_iteration_hooks.
10/11 03:58:24.899 DEBUG|              test:0386| Starting after_iteration_hooks for login_VMSanity
10/11 03:58:24.900 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/interrupts.after
10/11 03:58:24.900 DEBUG|             utils:0219| Running 'mkdir -p /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/var/spool'
10/11 03:58:24.901 DEBUG|      global_hooks:0056| 'mkdir -p /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/var/spool'
10/11 03:58:24.912 DEBUG|             utils:0219| Running 'rsync --no-perms --chmod=ugo+r -a --safe-links --exclude=/crash/**autoserv* --exclude=/crash/*.core /var/spool/crash /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/var/spool'
10/11 03:58:24.912 DEBUG|      global_hooks:0056| 'rsync --no-perms --chmod=ugo+r -a --safe-links --exclude=/crash/**autoserv* --exclude=/crash/*.core /var/spool/crash /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/var/spool'
10/11 03:58:24.952 DEBUG|             utils:0219| Running 'rm -rf /var/spool/crash/*'
10/11 03:58:24.953 DEBUG|      global_hooks:0056| 'rm -rf /var/spool/crash/*'
10/11 03:58:24.965 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/meminfo.after
10/11 03:58:24.967 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/slabinfo.after
10/11 03:58:24.968 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1/schedstat.after
10/11 03:58:24.968 DEBUG|             utils:0219| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1"'
10/11 03:58:24.968 DEBUG|      global_hooks:0056| 'logger "autotest finished iteration /usr/local/autotest/results/default/login_VMSanity/sysinfo/iteration.1"'
10/11 03:58:24.980 DEBUG|              test:0391| after_iteration_hooks completed
10/11 03:58:24.980 WARNI|              test:0606| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 600, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 800, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 464, in execute
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 371, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/login_VMSanity/login_VMSanity.py", line 13, in run_once
    vm_sanity.VMSanity().Run()
  File "/usr/local/autotest/bin/vm_sanity.py", line 53, in Run
    self.RunTastTest()
  File "/usr/local/autotest/bin/vm_sanity.py", line 111, in RunTastTest
    utils.system(tast_cmd)
  File "/usr/local/autotest/common_lib/utils.py", line 1032, in system
    stdout_tee=TEE_TO_LOGS, stderr_tee=TEE_TO_LOGS).exit_status
  File "/usr/local/autotest/common_lib/utils.py", line 759, in run
    "Command returned non-zero exit status")
CmdError: Command <local_test_runner '(!informational && !disabled && ("dep:chrome" || "dep:chrome_login"))'> failed, rc=6, Command returned non-zero exit status
* Command: 
    local_test_runner '(!informational && !disabled && ("dep:chrome" ||
    "dep:chrome_login"))'
Exit status: 6
Duration: 176.640138865
 

achuith, could you help me rout this to the correct person? This is breaking the chrome pfq.

This failure is blocking a manual uprev.

Looks like another instance on wolf-paladin:

https://cros-goldeneye.corp.google.com/chromeos/healthmonitoring/buildDetails?buildbucketId=8932946936688322768

Let's make sure that the actual error gets fixed too, since this test is still running on the PFQ outside of login_VMSanity. Here's what I see in the login_VMSanity.INFO file:

2018/10/11 03:56:24 Running ui.VirtualKeyboardOmnibox
2018/10/11 03:56:24 Restarting ui job
2018/10/11 03:56:25 Waiting for org.chromium.SessionManager D-Bus service
2018/10/11 03:56:25 Asking session_manager to enable Chrome testing
2018/10/11 03:56:25 Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/10/11 03:56:26 Checking cryptohomed service
2018/10/11 03:56:26 Removing cryptohome for testuser@gmail.com
2018/10/11 03:56:26 Finding OOBE DevTools target
2018/10/11 03:56:26 Connecting to Chrome at ws://127.0.0.1:43695/devtools/page/011DF96DFED72664EAFAEB75C4F0ED4F
2018/10/11 03:56:27 Waiting for OOBE
2018/10/11 03:56:32 Logging in as user "testuser@gmail.com"
2018/10/11 03:56:32 Waiting for cryptohome for user "testuser@gmail.com"
2018/10/11 03:56:38 Waiting for OOBE to be dismissed
2018/10/11 03:56:40 Waiting for test API extension at chrome-extension://behllobkkfkfnphdnhnkndlbkcpglgmj/_generated_background_page.html
2018/10/11 03:56:41 Connecting to Chrome at ws://127.0.0.1:43695/devtools/page/3821835B452EE0964DA5785FB9E0700D
2018/10/11 03:56:42 Test API extension is ready
2018/10/11 03:56:42 Waiting for the virtual keyboard to show
2018/10/11 03:58:24 Error: [virtual_keyboard_omnibox.go:65] Failed to wait for the virtual keyboard to show: cdp.Runtime: Evaluate: context deadline exceeded
2018/10/11 03:58:24 Finished ui.VirtualKeyboardOmnibox

The informational attribute got removed from this test by https://crrev.com/c/1263216, making it run on the Chrome/CrOS CQ and Chrome PFQ. If it's flaky, we should probably revert that (again). :-(

I'll do the revert.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/4a6efefc91dc7ded04766b9ccfebc3dd2ae02790

commit 4a6efefc91dc7ded04766b9ccfebc3dd2ae02790
Author: Dan Erat <derat@chromium.org>
Date: Thu Oct 11 19:45:29 2018

Revert "Reland "Enable tast.ui.VirtualKeyboardOmnibox.""

This reverts commit f7436063241f35b262770996ef0fe7b9bcdbcdc6.

Reason for revert: Still flaky, per https://crbug.com/893957.

Original change's description:
> Reland "Enable tast.ui.VirtualKeyboardOmnibox."
> 
> This is a reland of 44f376e51e5df8f8a73e6251987888d875abdca5
> 
> Original change's description:
> > Enable tast.ui.VirtualKeyboardOmnibox.
> >
> > Make failures block the CQ. Test looks stable enough.
> >
> > BUG=chromium:879073
> > TEST=Linux
> >
> > Change-Id: I5ca3e21771c5ce3afb5e00d0afe3f16a9cef6760
> > Reviewed-on: https://chromium-review.googlesource.com/1235366
> > Commit-Ready: Darren Shen <shend@chromium.org>
> > Tested-by: Darren Shen <shend@chromium.org>
> > Reviewed-by: Dan Erat <derat@chromium.org>
> 
> Bug: chromium:879073
> Change-Id: Id67966081dfdcf5ced4ae295379a6b0b8ea8c579
> Reviewed-on: https://chromium-review.googlesource.com/1263216
> Commit-Ready: Darren Shen <shend@chromium.org>
> Tested-by: Darren Shen <shend@chromium.org>
> Reviewed-by: Dan Erat <derat@chromium.org>

Bug: chromium:879073,chromium:893957
Change-Id: I285b5433c633e60679a26ce23a6ef8e0d45e71bb
Reviewed-on: https://chromium-review.googlesource.com/c/1277966
Reviewed-by: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/4a6efefc91dc7ded04766b9ccfebc3dd2ae02790/src/chromiumos/tast/local/bundles/cros/ui/virtual_keyboard_omnibox.go

Dan - We don't need to urgently disable Tast then, right?

Alex - to disable just change this line:
https://cs.corp.google.com/chromeos_public/src/third_party/autotest/files/client/bin/vm_sanity.py?l=38
to: 
self.run_tast = False

#8: I still think we shouldn't run Tast from vm_sanity.py (see  issue 888887  and  https://crbug.com/876587#c53 ). But yes, I think that the issue here was just that a test that just got turned back on is still flaky.

Ok. Lets wait for the next pfq run. If something else in VMSanity goes wrong I will disable them until achiuth comes back. Sound resonable?

#10: https://crrev.com/c/1242315 (in the CQ) is equivalent to what was suggested in #8, I think, so there shouldn't be any need to do that.

Reopening this bug for me to fix the root cause of the test flakiness.

Ok I'm going to look at this today. One of the more recent failures points to a JavaScript error: https://stainless.corp.google.com/browse/chromeos-autotest-results/251846068-chromeos-test/

2018/10/25 02:03:34 [02:03:33.419] Waiting for the virtual keyboard to show
2018/10/25 02:03:34 [02:03:33.562] Waiting for the virtual keyboard to render buttons
2018/10/25 02:03:34 [02:03:33.674] Error at virtual_keyboard_omnibox.go:71: Failed to wait for the virtual keyboard to render: got exception: TypeError: Method called without a valid receiver (this). Did you forget to call .bind()?
2018/10/25 02:03:34 [02:03:33.674] Stack trace:
Failed to wait for the virtual keyboard to render
	at chromiumos/tast/local/bundles/cros/ui.VirtualKeyboardOmnibox (virtual_keyboard_omnibox.go:71)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:189)
	at chromiumos/tast/testing.runAndRecover.func1 (stage.go:68)
	at runtime.goexit (asm_amd64.s:2361)
got exception: TypeError: Method called without a valid receiver (this). Did you forget to call .bind()?
	at chromiumos/tast/local/chrome.(*Conn).doEval (conn.go:101)
	at chromiumos/tast/local/chrome.(*Conn).EvalPromise (conn.go:83)
	at chromiumos/tast/local/bundles/cros/ui/vkb.WaitUntilButtonsRender (vkb.go:71)
	at chromiumos/tast/local/bundles/cros/ui.VirtualKeyboardOmnibox (virtual_keyboard_omnibox.go:70)
	at chromiumos/tast/testing.(*Test).Run.func4 (test.go:189)
	at chromiumos/tast/testing.runAndRecover.func1 (stage.go:68)
	at runtime.goexit (asm_amd64.s:2361)
2018/10/25 02:03:35 Completed test ui.VirtualKeyboardOmnibox in 26.946s with 1 error(s)

Regarding the original failure, here's a recent example: https://stainless.corp.google.com/browse/chromeos-autotest-results/251801795-chromeos-test/

If you look at the screenshot in the logs, the virtual keyboard is shown. But for some reason, the test doesn't detect it and thus fails.

Anyway, both types of failures point to vkb.WaitUntilButtonsRender [1] as being the culprit.

+nya@. Takahashi-san, have you ever see the "TypeError: Method called without a valid receiver (this). Did you forget to call .bind()" error before?

[1] https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/HEAD/src/chromiumos/tast/local/bundles/cros/ui/vkb/vkb.go#70

I haven't seen such error in other tests. It's weird...

I could repro the issue locally with sentry, and here's (a bit broken) stacktrace:

2018-10-26 12:53:06 [exception] TypeError: Method called without a valid receiver (this). Did you forget to call .bind()?
        at  (extensions::automationNode:1219:13)
        at get children (extensions::automationNode:466:41)
        at get (extensions::utils:165:37)
        at forAllDescendants_ (extensions::automationNode:897:26)
        at findInternal_ (extensions::automationNode:870:9)
        at find (extensions::automationNode:676:16)
        at publicClassPrototype.(anonymous function) (extensions::utils:137:25)
        at check (.:4:25)
        at chrome.automation.getDesktop.root (.:11:2)
        at  (extensions::automation:149:6)
        at  (extensions::binding:63:26)
        at  (extensions::binding:373:31)
        at Promise (.:2:19)
        at  (.:1:0)

So the exception seems raised in chrome.automation.getDesktop.

Ah thank you. Error occurring in "find" makes sense, as it's the only difference between WaitUntilShown (which works) and WaitUntilRender (which doesn't).

The error message doesn't say which method is causing the error, but maybe it's the closure passed to forAllDescendents [1]? But I can't see anything wrong there and it's a flaky failure too.

Anyway, it could also just be the same root cause as the context timeout error. I'll try and repro the timeout error.

+accessibility API folks for ideas

[1] https://cs.chromium.org/chromium/src/chrome/renderer/resources/extensions/automation/automation_node.js?type=cs&q=forAllDescendants_&sq=package:chromium&g=0&l=871

I can't reproduce with a veyron_minnie or eve, but the JS logs from the bots match those in c#18.

The error is happening when we call AutomationRootNodeImpl.getNodeFromTree in [1], which is defined in [2]. In getNodeFromTree, we run:

    privates(AutomationRootNodeImpl.get(treeId)).impl

The JavaScript error that we're getting is that the first argument to privates(...) is null [3]. Therefore, it must be that AutomationRootNodeImpl.get(treeId) returned null, which is defined in [4]. This seems to suggest that treeId is invalid (no entry in AutomationRootNodeImpl.idToAutomationRootNode_). Since the error is happening in getChildren(), treeId should be the ID for a child node of the current node.

Perhaps there is some race condition where we added a child to a node, but it didn't update AutomationRootNodeImpl.idToAutomationRootNode_?

[1] https://cs.chromium.org/chromium/src/chrome/renderer/resources/extensions/automation/automation_node.js?type=cs&q=forAllDescendants_&sq=package:chromium&g=0&l=467

[2] https://cs.chromium.org/chromium/src/chrome/renderer/resources/extensions/automation/automation_node.js?type=cs&q=forAllDescendants_&sq=package:chromium&g=0&l=1220

[3] https://cs.chromium.org/chromium/src/extensions/renderer/module_system.cc?type=cs&sq=package:chromium&g=0&l=666

[4] https://cs.chromium.org/chromium/src/chrome/renderer/resources/extensions/automation/automation_node.js?type=cs&q=AutomationRootNodeImpl&sq=package:chromium&g=0&l=1205

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/820a1874649791da0cb04f67ac70e216d75d8551

commit 820a1874649791da0cb04f67ac70e216d75d8551
Author: Darren Shen <shend@chromium.org>
Date: Wed Nov 07 14:34:43 2018

vkb: Use try/catch in vkb tests and add debugging.

Speculative fix for crbug.com/893957.

Add try/catch to catch any runtime errors.
Also added a debug print to dump the entire automation tree
after some timeout. This will help us debug those flaky timeouts.

Will revert once we figured out the root cause.

BUG=chromium:893957
TEST=minnie

Change-Id: I81db7cceea256fae4ef03715616b4b694e17835b
Reviewed-on: https://chromium-review.googlesource.com/1317221
Commit-Ready: Darren Shen <shend@chromium.org>
Tested-by: Darren Shen <shend@chromium.org>
Reviewed-by: Shuhei Takahashi <nya@chromium.org>

[modify] https://crrev.com/820a1874649791da0cb04f67ac70e216d75d8551/src/chromiumos/tast/local/bundles/cros/ui/vkb/vkb.go

Got a log: https://stainless.corp.google.com/browse/chromeos-autotest-results/256403468-chromeos-test/

The print out shows that the automation tree does indeed have an element with role "keyboard". So either:

A) root.find didn't find the element
B) the element was found, but it was invisible

I should've put some more logging to distinguish between these two cases :(

Another observation: most of the time, the test times out due to a second call to getDesktop. For example, VirtualKeyboardOmnibox times out on WaitUntilShown (first call to getDesktop is for clicking the omnibox). VirtualKeyboardTyping times out on WaitUntilRender (first call is in WaitUntilShown).

Starting work on this again. I can only see two different types of failures:

1. Context deadline timeout e.g. https://stainless.corp.google.com/browse/chromeos-autotest-results/272639908-chromeos-test/

If you look at the screenshot, the VK actually doesn't show. So this legitimately looks like a VK issue.

Could be related to 903543.

2. No method receiver e.g. https://stainless.corp.google.com/browse/chromeos-autotest-results/272222559-chromeos-test/

From the JS log:

2018-11-04 00:23:12 [eval-error] TypeError: Method called without a valid receiver (this). Did you forget to call .bind()?
	at ??? (extensions::automationNode [1219:13])
	at get children (extensions::automationNode [466:41])
	at get (extensions::utils [165:37])
	at forAllDescendants_ (extensions::automationNode [897:26])
	at findInternal_ (extensions::automationNode [870:9])
	at find (extensions::automationNode [676:16])
	at publicClassPrototype.(anonymous function) (extensions::utils [137:25])
	at check ( [4:25])
	at chrome.automation.getDesktop.root ( [11:2])
	at ??? (extensions::automation [149:6])
	at ??? (extensions::binding [63:26])
	at ??? (extensions::binding [373:31])
	at Promise ( [2:19])
	at ??? ( [1:0])

which is an issue in the automation API as mentioned in c#20.

Actually, there's a third type of failure:

3. Context deadline timeout on waiting to render e.g. https://stainless.corp.google.com/browse/chromeos-autotest-results/272543011-chromeos-test/

The screenshot shows that the VK appears. So either the automation framework is buggy or our test expectations are wrong.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/fc778ec243c6efd3f402672f432717bc287c9dfb

commit fc778ec243c6efd3f402672f432717bc287c9dfb
Author: Darren Shen <shend@chromium.org>
Date: Mon Jan 07 21:45:18 2019

[automation] Add null check in AutomationNode.getNodeFromTree.

We wrote some automated UI tests using the Chrome automation framework,
but encountered some errors happening inside the JavaScript code for
AutomationNode: https://crbug.com/893957#c24

The error is:

    TypeError: Method called without a valid receiver (this). Did you
    forget to call .bind()?"

After codesearching, this error seems to occur when we pass an invalid
object to the "privates" function [1].

From the JavaScript stack trace, it looks like this is the line in
AutomationNode.getNodeFromTree that raises the error:

    privates(AutomationRootNodeImpl.get(treeId)).impl

which suggests AutomationRootNodeImpl.get(treeId) was null.

I'm not familiar enough with this code to figure out the root cause,
so I'll just add an additional null check to prevent this error from
happening again.

[1] https://cs.chromium.org/chromium/src/extensions/renderer/module_system.cc?type=cs&sq=package:chromium&g=0&l=666

Bug: 893957
Change-Id: I3d4d6edb6d22eabf85a9b5b4399c1a75cf16956b
Reviewed-on: https://chromium-review.googlesource.com/c/1393683
Reviewed-by: David Tseng <dtseng@chromium.org>
Commit-Queue: Darren Shen <shend@chromium.org>
Cr-Commit-Position: refs/heads/master@{#620486}
[modify] https://crrev.com/fc778ec243c6efd3f402672f432717bc287c9dfb/chrome/renderer/resources/extensions/automation/automation_node.js

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/ad0c54453350c3a943ac08c09886ca938940b198

commit ad0c54453350c3a943ac08c09886ca938940b198
Author: Darren Shen <shend@chromium.org>
Date: Tue Jan 08 03:40:54 2019

tast: Add more logging to vkb.

To find the root cause for flaky timeouts / JavaScript errors.

BUG=chromium:893957
TEST=eve

Change-Id: I22541dc7af2418efcf96978c344f55aae5a819ea
Reviewed-on: https://chromium-review.googlesource.com/1392964
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Darren Shen <shend@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>
Reviewed-by: Shuhei Takahashi <nya@chromium.org>

[modify] https://crrev.com/ad0c54453350c3a943ac08c09886ca938940b198/src/chromiumos/tast/local/bundles/cros/ui/vkb/vkb.go

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/a3c635b5c0b02aa25bd43358c183f6775299b824

commit a3c635b5c0b02aa25bd43358c183f6775299b824
Author: Darren Shen <shend@chromium.org>
Date: Fri Jan 11 17:47:56 2019

tast: Don't wait for keyboard node when checking visiblity.

Sometimes tast.ui.VirtualKeyboardOmnibox times out when
checking if the virtual keyboard is initially visible or not.
In the current code we wait for the keyboard node to be
present in the automation tree before checking visibility.

However, this is causing timeouts sometimes, so we'll just
change it so that if the keyboard is not in the automation
tree then the keyboard is considered to be visible.

TEST=eve
BUG=chromium:893957

Change-Id: I7f3b34b5b1e7a5f31245fe4e6ca30b95a7cde1df
Reviewed-on: https://chromium-review.googlesource.com/1404514
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Darren Shen <shend@chromium.org>
Reviewed-by: Shuhei Takahashi <nya@chromium.org>

[modify] https://crrev.com/a3c635b5c0b02aa25bd43358c183f6775299b824/src/chromiumos/tast/local/bundles/cros/ui/vkb/vkb.go