autopilot failures when closing the toolbar at startup

[Olivier Tilloy]

We’re seeing autopilot test failures on notes-app from time to time. It seems they happen most frequently (only?) on mako.

Here’s an instance of one such failure: http://ci.ubuntu.com/smokeng/trusty/touch/mako/138:20140120.1:20140115.1/6181/notes-app-autopilot/686155/

It seems to affect tests randomly, not a specific test. The failure happens in the setUp method of NotesAppTestCase, after the application window has appeared, the first thing that is done is to close the toolbar. The request is correctly forwarded to the UITK emulator for the toolbar, the swipe gesture is issued, but the tests fail on self.animating.wait_for(False) (where self is the toolbar):

Traceback (most recent call last):
File "/home/phablet/autopilot/notes_app/tests/test_images.py", line 24, in setUp
super(BaseForTestImages, self).setUp()
File "/home/phablet/autopilot/notes_app/tests/__init__.py", line 51, in setUp
self.main_window.close_toolbar()
File "/usr/lib/python2.7/dist-packages/autopilot/logging.py", line 46, in inner
return f(instance, *args, **kwargs)
File "/home/phablet/autopilot/ubuntuuitoolkit/emulators.py", line 101, in close_toolbar
self.get_toolbar().close()
File "/usr/lib/python2.7/dist-packages/autopilot/logging.py", line 46, in inner
return f(instance, *args, **kwargs)
File "/home/phablet/autopilot/ubuntuuitoolkit/emulators.py", line 261, in close
self.animating.wait_for(False)
File "/usr/lib/python2.7/dist-packages/autopilot/introspection/types.py", line 179, in wait_for
failure_msg))
AssertionError: After 10.0 seconds test on Toolbar.animating failed: False != dbus.Boolean(True, variant_level=1)

[Olivier Tilloy (osomon)]

Here is the full autopilot log (without the traceback):

14:28:24.237 INFO globals:57 - Starting test notes_app.tests.test_images.TestImageLargeWide.test_no_crash (with touch)
14:28:24.241 WARNING testcase:117 - No tracing available - install the python-autopilot-trace package!
14:28:24.404 WARNING testcase:154 - Process manager backend unavailable, application snapshot support disabled.
initctl: Unknown instance: com.ubuntu.notes_notes_1.4.242
14:28:27.252 INFO testcase:352 - Click package com.ubuntu.notes_notes_1.4.242 has been launched with PID 7501
127.0.0.1 - - [20/Jan/2014 14:28:28] "GET /large_wide.png HTTP/1.1" 200 -
127.0.0.1 - - [20/Jan/2014 14:28:28] "GET /large_wide.png HTTP/1.1" 200 -
14:28:29.271 DEBUG dbus:431 - Selecting objects of type NotesApp with attributes: {}
14:28:29.380 DEBUG dbus:431 - Selecting objects of type NotesApp with attributes: {}
14:28:29.429 INFO logging:45 - NotesApp: Close the toolbar if it's opened. Arguments (). Keyword arguments: {}.
14:28:29.429 DEBUG dbus:431 - Selecting objects of type Toolbar with attributes: {}
14:28:29.460 INFO logging:45 - Toolbar: Close the toolbar if it's opened. Arguments (). Keyword arguments: {}.
14:28:29.609 DEBUG _uinput:366 - Dragging from 384,1136 to 384,1279
14:28:40.409 INFO testcase:540 - waiting for process to exit.
14:28:40.410 INFO testcase:542 - Killing process 7501
14:28:41.863 ERROR testresult:37 - FAIL: notes_app.tests.test_images.TestImageLargeWide.test_no_crash(with touch)

[Olivier Tilloy (osomon)]

Apparently, the toolbar is actually closed when the failure happens (because the previous assertion, self.opened.wait_for(False), succeeded), but for some reason its 'animating' property is still true:

    def close(self):
        self.animating.wait_for(False)
        if self.opened:
            self._drag_to_close()
            self.opened.wait_for(False)
            self.animating.wait_for(False) <<< failure

Could it be a bug (some sort of race condition) in the toolbar component itself?

[Olivier Tilloy (osomon)]

The 'animating' property is defined like this (in Panel.qml):

    readonly property bool animating: draggingArea.pressed || transitionToAll.running || transitionToHint.running || transitionToSpread.running

For the 'opened' property to be false, the state has to be "", so I’m assuming no transition is running. Therefore, if 'animating' remains True, it means that draggingArea.pressed is True. Not really sure what that proves, but there might be an issue with sending input events too early to the application.

[Olivier Tilloy (osomon)]

This is what the notes-app tests do at startup:

    def setUp(self):
        self.pointing_device = Pointer(self.input_device_class.create())
        super(NotesAppTestCase, self).setUp()
        self.launch_app()
        self.main_window.visible.wait_for(True)
        self.main_window.close_toolbar()

Could it be that (main_window.visible == True) is still too early to start interacting with the application, and we could use a more reliable assertion to verify that the application is ready to be interacted with?

[Timo Jyrinki (timo-jyrinki)]

Mark the UI Toolkit part as invalid if/when it's determined that there's nothing to fix on the UI Toolkit side.

[Olivier Tilloy (osomon)]

In the attached branch (lp:~osomon/notes-app/wait-toolbar-autohide) I’ve tried something a bit different: instead of proactively closing the toolbar at test startup, I’ve let the autohide behaviour kick in, and passively wait for the toolbar to hide before doing anything else.

Łukasz (sil2100) tested this branch on a Nexus 4, he ran the entire test suite 7 times in a row, it all passed. But the CI job failed for the same branch: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-runner-mako/4763/console.

So back to square one, the problem doesn’t seem to be with sending input events too early after all.

[Para Siva (psivaa)]

We are seeing similar failure with one of the latest images on Mako:
http://ci.ubuntu.com/smokeng/trusty/touch/mako/191:20140219:20140115.1/6667/notes_app/794050/

This is being seen now and then and was seen on 186 with mako as well.

[Tim Peeters (tpeeters)]

Leo can you have a look at this bug?

[Leo Arias (elopio)]

<elopio> I did many runs of the notes app a couple of weeks ago, and it never failed that way. Is that still happening to you?
<oSoMoN> elopio, not heard of such a failure recently, tbh notes-app is not on my radar (nor on anyone’s afaict)
<elopio> oSoMoN: I'll mark it as incomplete for now, but keep an eye to see if it appears in other apps.
<oSoMoN> elopio, ok