Actions
action #28297
closed[qam] test fails in firefox_developertool - missed click
Start date:
2017-11-23
Due date:
% Done:
100%
Estimated time:
Difficulty:
Description
Observation¶
openQA test in scenario sle-12-SP3-Desktop-DVD-Updates-x86_64-qam-regression-firefox@64bit fails in
firefox_developertool
Reproducible¶
Fails since (at least) Build 20170804-1
Expected result¶
Last good: (unknown) (or more recent)
Further details¶
Always latest result in this scenario: latest
It looks like lost mouse click on firefox_developertool-firefox-developertool-check_element and firefox-developertool-element is not matched.
12:19:32.6282 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:30 called testapi::assert_and_click
12:19:32.6284 1058 <<< testapi::mouse_set(x=1023, y=767)
12:19:32.6294 1060 mouse_move 1023, 767
12:19:32.6295 1060 send_pointer_event 0, 1023, 767, 1
12:19:32.6298 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
12:19:32.6299 1058 <<< testapi::assert_screen(mustmatch='firefox-developertool-check_element', timeout=30)
12:19:32.6425 1060 MATCH(firefox_developertool-firefox-developertool-check_element-20170704:1.00)
12:19:32.7202 1058 >>> testapi::_handle_found_needle: found firefox_developertool-firefox-developertool-check_element-20170704, similarity 1.00 @ 12/125
12:19:32.7210 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
12:19:32.7211 1058 <<< testapi::assert_and_click(mustmatch='firefox-developertool-check_element', button=undef, timeout=30)
12:19:32.7212 1058 clicking at 50/149
12:19:32.7212 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
12:19:32.7212 1058 <<< testapi::mouse_set(x=50, y=149)
12:19:32.7215 1060 mouse_move 50, 149
12:19:32.7216 1060 send_pointer_event 0, 50, 149, 1
12:19:32.7219 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
12:19:32.7220 1058 <<< testapi::mouse_click(button='left', cursor_down='0.15')
12:19:32.7223 1060 pointer_event 1 50, 149
12:19:32.7223 1060 send_pointer_event 1, 50, 149, 1
12:19:32.8732 1060 pointer_event 0 50, 149
12:19:32.8733 1060 send_pointer_event 0, 50, 149, 1
12:19:33.8738 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
12:19:33.8740 1058 <<< testapi::mouse_set(x=1023, y=767)
12:19:33.8746 1060 mouse_move 1023, 767
12:19:33.8747 1060 send_pointer_event 0, 1023, 767, 1
12:19:33.8750 Debug: /var/lib/openqa/cache/tests/sle/tests/x11regressions/firefox/firefox_developertool.pm:32 called testapi::assert_screen
12:19:33.8751 1058 <<< testapi::assert_screen(mustmatch='firefox-developertool-element', timeout=30)
12:19:33.8930 1060 MATCH(firefox-developertool-element-20160814:0.00)
12:19:33.8932 1060 no match: 29.9s
12:19:34.8853 1060 MATCH(firefox-developertool-element-20160814:0.00)
12:19:34.8854 1060 no match: 28.9s
12:19:35.8832 1060 no change: 27.9s
12:19:36.8843 1060 no change: 26.9s
Updated by emiura almost 7 years ago
- Status changed from New to In Progress
- Assignee set to emiura
Updated by pcervinka over 6 years ago
Updated by bfilho over 6 years ago
I wasn't able to reproduce the issue on the local instance, so analyzing the previous log we believed that a timing issue was happening between the steps 15 and 16, and we proposed that adding a wait_still_screen between these two steps would likely solve the issue.
After I sent the pull request and was analyzing the review from okurz (https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/4852#pullrequestreview-112596702), I wondered if that might not be the case.
In my local instance, below we can see the assert_and_click event and the mouse_move and send_pointer_event happening after the 150ms described, and the match on assert_screen happening over ~3 seconds:
[2018-04-17T11:32:58.0025 -03] [debug] /var/lib/openqa/share/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-17T11:32:58.0025 -03] [debug] <<< testapi::mouse_click(button='left', cursor_down='0.15')
[2018-04-17T11:32:58.0025 -03] [debug] pointer_event 1 50, 149
[2018-04-17T11:32:58.0025 -03] [debug] send_pointer_event 1, 50, 149, 1
[2018-04-17T11:32:58.0176 -03] [debug] pointer_event 0 50, 149
[2018-04-17T11:32:58.0176 -03] [debug] send_pointer_event 0, 50, 149, 1
[2018-04-17T11:32:59.0177 -03] [debug] /var/lib/openqa/share/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-17T11:32:59.0177 -03] [debug] <<< testapi::mouse_set(x=1023, y=767)
[2018-04-17T11:32:59.0177 -03] [debug] mouse_move 1023, 767
[2018-04-17T11:32:59.0177 -03] [debug] send_pointer_event 0, 1023, 767, 1
[2018-04-17T11:32:59.0177 -03] [debug] /var/lib/openqa/share/tests/sle/tests/x11/firefox/firefox_developertool.pm:33 called testapi::assert_screen
[2018-04-17T11:32:59.0178 -03] [debug] <<< testapi::assert_screen(mustmatch='firefox-developertool-element', timeout=30)
[2018-04-17T11:32:59.0190 -03] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-17T11:32:59.0190 -03] [debug] no match: 29.9s
[2018-04-17T11:33:00.0184 -03] [debug] MATCH(firefox-developertool-element-20160814:0.51)
[2018-04-17T11:33:00.0185 -03] [debug] no match: 28.9s
[2018-04-17T11:33:01.0185 -03] [debug] MATCH(firefox-developertool-element-20160814:0.51)
[2018-04-17T11:33:01.0185 -03] [debug] no match: 27.9s
[2018-04-17T11:33:02.0186 -03] [debug] MATCH(firefox-developertool-element-20160814:0.51)
[2018-04-17T11:33:02.0186 -03] [debug] no match: 26.9s
[2018-04-17T11:33:03.0228 -03] [debug] MATCH(firefox-developertool-element-20160814:0.98)
[2018-04-17T11:33:03.0286 -03] [debug] >>> testapi::_handle_found_needle: found firefox-developertool-element-20160814, similarity 0.98 @ 85/604
Running in the server, previous logs shown that the match from assert_screen would happen after ~4 seconds when successful.
[2018-04-15T03:34:53.0106 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:30 called testapi::assert_and_click
[2018-04-15T03:34:53.0106 CEST] [debug] <<< testapi::mouse_set(x=1023, y=767)
[2018-04-15T03:34:53.0107 CEST] [debug] mouse_move 1023, 767
[2018-04-15T03:34:53.0107 CEST] [debug] send_pointer_event 0, 1023, 767, 1
[2018-04-15T03:34:53.0108 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-15T03:34:53.0108 CEST] [debug] <<< testapi::assert_screen(mustmatch='firefox-developertool-check_element', timeout=30)
[2018-04-15T03:34:53.0130 CEST] [debug] MATCH(firefox_developertool-firefox-developertool-check_element-20170704:1.00)
[2018-04-15T03:34:53.0267 CEST] [debug] >>> testapi::_handle_found_needle: found firefox_developertool-firefox-developertool-check_element-20170704, similarity 1.00 @ 12/125
[2018-04-15T03:34:53.0268 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-15T03:34:53.0268 CEST] [debug] <<< testapi::assert_and_click(mustmatch='firefox-developertool-check_element', button=undef, timeout=30)
[2018-04-15T03:34:53.0268 CEST] [debug] clicking at 50/149
[2018-04-15T03:34:53.0268 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-15T03:34:53.0268 CEST] [debug] <<< testapi::mouse_set(x=50, y=149)
[2018-04-15T03:34:53.0269 CEST] [debug] mouse_move 50, 149
[2018-04-15T03:34:53.0269 CEST] [debug] send_pointer_event 0, 50, 149, 1
[2018-04-15T03:34:53.0269 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-15T03:34:53.0270 CEST] [debug] <<< testapi::mouse_click(button='left', cursor_down='0.15')
[2018-04-15T03:34:53.0270 CEST] [debug] pointer_event 1 50, 149
[2018-04-15T03:34:53.0270 CEST] [debug] send_pointer_event 1, 50, 149, 1
[2018-04-15T03:34:53.0421 CEST] [debug] pointer_event 0 50, 149
[2018-04-15T03:34:53.0421 CEST] [debug] send_pointer_event 0, 50, 149, 1
[2018-04-15T03:34:54.0422 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-15T03:34:54.0422 CEST] [debug] <<< testapi::mouse_set(x=1023, y=767)
[2018-04-15T03:34:54.0423 CEST] [debug] mouse_move 1023, 767
[2018-04-15T03:34:54.0423 CEST] [debug] send_pointer_event 0, 1023, 767, 1
[2018-04-15T03:34:54.0424 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:32 called testapi::assert_screen
[2018-04-15T03:34:54.0424 CEST] [debug] <<< testapi::assert_screen(mustmatch='firefox-developertool-element', timeout=30)
[2018-04-15T03:34:54.0452 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-15T03:34:54.0453 CEST] [debug] no match: 29.9s
[2018-04-15T03:34:55.0438 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-15T03:34:55.0438 CEST] [debug] no match: 28.9s
[2018-04-15T03:34:56.0439 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.51)
[2018-04-15T03:34:56.0440 CEST] [debug] no match: 27.9s
[2018-04-15T03:34:57.0434 CEST] [debug] no change: 26.9s
[2018-04-15T03:34:58.0538 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.98)
[2018-04-15T03:34:58.0668 CEST] [debug] >>> testapi::_handle_found_needle: found firefox-developertool-element-20160814, similarity 0.98 @ 85/604
But when it fails, it seems that assert_screen call would take up to 30 seconds waiting for the needle to match:
[2018-04-16T01:42:15.0708 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-16T01:42:15.0708 CEST] [debug] <<< testapi::mouse_click(button='left', cursor_down='0.15')
[2018-04-16T01:42:15.0708 CEST] [debug] pointer_event 1 50, 149
[2018-04-16T01:42:15.0708 CEST] [debug] send_pointer_event 1, 50, 149, 1
[2018-04-16T01:42:15.0859 CEST] [debug] pointer_event 0 50, 149
[2018-04-16T01:42:15.0859 CEST] [debug] send_pointer_event 0, 50, 149, 1
[2018-04-16T01:42:16.0860 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:31 called testapi::assert_and_click
[2018-04-16T01:42:16.0860 CEST] [debug] <<< testapi::mouse_set(x=1023, y=767)
[2018-04-16T01:42:16.0861 CEST] [debug] mouse_move 1023, 767
[2018-04-16T01:42:16.0861 CEST] [debug] send_pointer_event 0, 1023, 767, 1
[2018-04-16T01:42:16.0861 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/x11/firefox/firefox_developertool.pm:32 called testapi::assert_screen
[2018-04-16T01:42:16.0861 CEST] [debug] <<< testapi::assert_screen(mustmatch='firefox-developertool-element', timeout=30)
[2018-04-16T01:42:16.0877 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-16T01:42:16.0877 CEST] [debug] no match: 29.9s
[2018-04-16T01:42:17.0870 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-16T01:42:17.0871 CEST] [debug] no match: 28.9s
[2018-04-16T01:42:18.0868 CEST] [debug] no change: 27.9s
[2018-04-16T01:42:19.0869 CEST] [debug] no change: 26.9s
[2018-04-16T01:42:20.0929 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-16T01:42:20.0929 CEST] [debug] no match: 25.9s
[2018-04-16T01:42:21.0871 CEST] [debug] no change: 24.9s
[2018-04-16T01:42:22.0872 CEST] [debug] no change: 23.9s
[2018-04-16T01:42:23.0874 CEST] [debug] no change: 22.9s
[2018-04-16T01:42:24.0875 CEST] [debug] no change: 21.9s
[2018-04-16T01:42:25.0875 CEST] [debug] no change: 20.9s
[2018-04-16T01:42:26.0876 CEST] [debug] no change: 19.9s
[2018-04-16T01:42:27.0878 CEST] [debug] no change: 18.9s
[2018-04-16T01:42:28.0879 CEST] [debug] no change: 17.9s
[2018-04-16T01:42:29.0879 CEST] [debug] no change: 16.9s
[2018-04-16T01:42:30.0880 CEST] [debug] no change: 15.9s
[2018-04-16T01:42:31.0882 CEST] [debug] no change: 14.9s
[2018-04-16T01:42:32.0883 CEST] [debug] no change: 13.9s
[2018-04-16T01:42:33.0883 CEST] [debug] no change: 12.9s
[2018-04-16T01:42:34.0884 CEST] [debug] no change: 11.9s
[2018-04-16T01:42:35.0886 CEST] [debug] no change: 10.9s
[2018-04-16T01:42:36.0887 CEST] [debug] no change: 9.9s
[2018-04-16T01:42:37.0887 CEST] [debug] no change: 8.9s
[2018-04-16T01:42:38.0889 CEST] [debug] no change: 7.9s
[2018-04-16T01:42:39.0890 CEST] [debug] no change: 6.9s
[2018-04-16T01:42:40.0891 CEST] [debug] no change: 5.9s
[2018-04-16T01:42:41.0891 CEST] [debug] no change: 4.9s
[2018-04-16T01:42:42.0892 CEST] [debug] no change: 3.9s
[2018-04-16T01:42:43.0893 CEST] [debug] no change: 2.9s
[2018-04-16T01:42:44.0895 CEST] [debug] no change: 1.9s
[2018-04-16T01:42:45.0895 CEST] [debug] no change: 0.9s
[2018-04-16T01:42:46.0986 CEST] [debug] MATCH(firefox-developertool-element-20160814:0.00)
[2018-04-16T01:42:47.0156 CEST] [debug] >>> testapi::_check_backend_response: match=firefox-developertool-element timed out after 30
And I don't see how adding the 7s to the assert_screen would solve this.
Perhaps adding a extra time between the assert and click call?
Updated by pcervinka over 6 years ago
- Related to action #33781: [sle15sp1][desktop]Update test case firefox_developertool. added
Updated by bfilho over 6 years ago
- % Done changed from 0 to 100
Pull request successfully merged
https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/4975
Added a new needle to solve the issue
https://gitlab.suse.de/openqa/os-autoinst-needles-sles/merge_requests/833
Please verify the discussion about the solution on the pull request #4975 and previous (https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/4852)
Sucessfully running on production after the merge, last one from:
https://openqa.suse.de/tests/1684057#step/firefox_developertool/15
Please let me know if any additional information is required.
Actions