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?