Autopilot test fails in Autopilot plugin but works on command line

[Carla Sella]

When running this Clock app test:

TestAlarm.test_add_recurring_type_alarm_must_add_to_alarm_list

on command line you do not get the failure that occurs running the same test in Qt Creator with the new Autopilot plugin.
I am running Wily and this version of the plugin: qtcreator-plugin-autopilot_3.1.1+07.07.20150854-0ubuntu1-0vivid1_amd64.
In Qt Creator the test fails with this output:

Starting /usr/bin/autopilot3-sandbox-run...
I: Running tests ubuntu_clock_app.tests.test_clock.TestClock.test_add_city_by_searching_must_add_world_city
I: Starting X Server: /usr/bin/Xephyr :5 -ac -br -noreset -screen 320x600x24
I: Starting autopilot
sudo: no tty present and no askpass program specified
Loading tests from: /home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot

Tests running...
Xlib.xauth: warning, no xauthority details available
<class 'Xlib.protocol.request.QueryExtension'>
initctl: Unknown job: maliit-server
sudo: no tty present and no askpass program specified
======================================================================
ERROR: ubuntu_clock_app.tests.test_clock.TestClock.test_add_city_by_searching_must_add_world_city
----------------------------------------------------------------------
Binary content:
  FailedTestScreenshot (image/png)
Empty attachments:
  process-stdout (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene)

/var/log/syslog: {{{Jul 13 22:11:17 letozaf-PC kernel: [ 2450.664624] input: autopilot-finger as /devices/virtual/input/input11}}}
process-return-code (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{-15}}}
process-stderr (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{
Testability driver loaded. Wire protocol version is "1.4".
qml: [LOG]: Clock Page loaded
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/clock/ClockPage.qml:247:20: Unable to assign [undefined] to QColor
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: [LOG]: Alarm Page loaded
qml: [LOG]: Searching online for user location at http://api.geonames.org/findNearbyPlaceNameJSON?lat=42.8333&lng=12.8333&username=krnekhelesh&style=full
qml: [LOG]: Stopping geolocation update service
Source changed not found
Source changed not found
qml: [LOG]: Alarm Database loaded
qml: [LOG]: Alarm Database loaded
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/worldclock/WorldCityList.qml:251:5: QML ActivityIndicator: Theme.createStyleComponent() is deprecated. Use ThemeSettings instead.
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/worldclock/WorldCityList.qml:104:9: QML TextField: Theme.createStyleComponent() is deprecated. Use ThemeSettings instead.
}}}

test-log: {{{
22:11:18.148 INFO logging:45 - TestClock: launch_test_local. Arguments (). Keyword arguments: {}.
22:11:18.148 WARNING base:52 - This function is deprecated. Use get_toolkit_launcher_command() instead.
22:11:18.204 INFO _launcher:373 - Attempting to launch application '/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene' with arguments '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml -I /home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend' as a normal process
22:11:18.211 INFO _launcher:431 - Launching process: ['/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene', '-testability', '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml', '-I', '/home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend']
22:11:21.390 INFO logging:45 - MainView: Open the Clock Page. Arguments (). Keyword arguments: {}.
22:11:21.704 INFO logging:45 - ClockPage: Swipe to reveal WorldCityList. Arguments (). Keyword arguments: {}.
22:11:21.734 DEBUG _common:45 - Moving to object's globalRect coordinates.
22:11:21.734 DEBUG _X11:350 - Moving mouse to position 160,423 with animation.
22:11:21.871 DEBUG _X11:393 - The mouse is now at position 160,423.
22:11:21.871 DEBUG _X11:304 - Pressing mouse button 1
22:11:21.973 DEBUG _X11:311 - Releasing mouse button 1
22:11:21.975 INFO logging:45 - MainView: Return the World City List page. Arguments (). Keyword arguments: {}.
22:11:22.310 INFO logging:45 - WorldCityList: Add world city by searching the world city name. Arguments ('Venice', 'Provincia di Venezia, Veneto, Italy'). Keyword arguments: {}.
22:11:22.555 DEBUG _common:45 - Moving to object's globalRect coordinates.
22:11:22.555 DEBUG _X11:350 - Moving mouse to position 292,28 with animation.
22:11:23.005 DEBUG _X11:393 - The mouse is now at position 292,28.
22:11:23.005 DEBUG _X11:304 - Pressing mouse button 1
22:11:23.106 DEBUG _X11:311 - Releasing mouse button 1
22:11:23.406 INFO _launcher:544 - waiting for process to exit.
22:11:23.406 INFO _launcher:567 - Killing process 18697
}}}

Traceback (most recent call last):
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/tests/test_clock.py", line 76, in test_add_city_by_searching_must_add_world_city
    worldCityList.search_world_city_(city_Name, country_Name)
  File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
    return f(instance, *args, **kwargs)
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 302, in search_world_city_
    self._search_world_city(city_Name, country_Name)
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 307, in _search_world_city
    "TextField", objectName='searchField')
  File "/usr/lib/python3/dist-packages/autopilot/introspection/dbus.py", line 295, in wait_select_single
    return self.select_single(type_name, **kwargs)
  File "/usr/lib/python3/dist-packages/autopilot/introspection/dbus.py", line 240, in select_single
    instances = self._execute_query(new_query)
  File "/usr/lib/python3/dist-packages/autopilot/introspection/dbus.py", line 90, in _execute_query
    getattr(self, '_id', None),
  File "/usr/lib/python3/dist-packages/autopilot/introspection/backends.py", line 242, in execute_query_get_proxy_instances
    for t in data
  File "/usr/lib/python3/dist-packages/autopilot/introspection/backends.py", line 242, in <listcomp>
    for t in data
  File "/usr/lib/python3/dist-packages/autopilot/introspection/backends.py", line 292, in make_introspection_object
    return class_object(state, path, backend)
  File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_textfield.py", line 31, in __init__
    self.keyboard = _common.get_keyboard()
  File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_common.py", line 58, in get_keyboard
    if is_maliit_process_running():
  File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_common.py", line 193, in is_maliit_process_running
    return is_process_running(MALIIT)
  File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_common.py", line 188, in is_process_running
    return 'start/' in get_process_status(name)
  File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_common.py", line 177, in get_process_status
    "Unable to get {}'s status: {}".format(name, error)
ubuntuuitoolkit._custom_proxy_objects._common.ToolkitException: Unable to get maliit-server's status: Command '['/sbin/initctl', 'status', 'maliit-server']' returned non-zero exit status 1

Ran 1 test in 5.767s
FAILED (failures=1)
I: autopilot tests done
/usr/bin/autopilot3-sandbox-run exited with code 1

Starting /usr/bin/autopilot3-sandbox-run...
I: Running tests ubuntu_clock_app.tests.test_alarm.TestAlarm.test_add_recurring_type_alarm_must_add_to_alarm_list
I: Starting X Server: /usr/bin/Xephyr :5 -ac -br -noreset -screen 320x600x24
I: Starting autopilot
sudo: no tty present and no askpass program specified
Loading tests from: /home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot

Tests running...
Xlib.xauth: warning, no xauthority details available
<class 'Xlib.protocol.request.QueryExtension'>
sudo: no tty present and no askpass program specified
sudo: no tty present and no askpass program specified
sudo: no tty present and no askpass program specified
sudo: no tty present and no askpass program specified
sudo: no tty present and no askpass program specified
======================================================================
FAIL: ubuntu_clock_app.tests.test_alarm.TestAlarm.test_add_recurring_type_alarm_must_add_to_alarm_list(random)
----------------------------------------------------------------------
Binary content:
  FailedTestScreenshot (image/png)
Empty attachments:
  process-stdout (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene)

/var/log/syslog: {{{Jul 13 22:18:45 letozaf-PC kernel: [ 2898.067632] input: autopilot-finger as /devices/virtual/input/input13}}}
process-return-code (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{-15}}}
process-stderr (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{
Testability driver loaded. Wire protocol version is "1.4".
qml: [LOG]: Clock Page loaded
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/clock/ClockPage.qml:247:20: Unable to assign [undefined] to QColor
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: [LOG]: Alarm Page loaded
qml: [LOG]: Searching online for user location at http://api.geonames.org/findNearbyPlaceNameJSON?lat=42.8333&lng=12.8333&username=krnekhelesh&style=full
qml: [LOG]: Stopping geolocation update service
Source changed not found
Source changed not found
qml: [LOG]: Alarm Database loaded
qml: [LOG]: Alarm Database loaded
}}}

test-log: {{{
22:18:45.556 INFO logging:45 - TestAlarm: launch_test_local. Arguments (). Keyword arguments: {}.
22:18:45.556 WARNING base:52 - This function is deprecated. Use get_toolkit_launcher_command() instead.
22:18:45.610 INFO _launcher:373 - Attempting to launch application '/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene' with arguments '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml -I /home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend' as a normal process
22:18:45.617 INFO _launcher:431 - Launching process: ['/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene', '-testability', '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml', '-I', '/home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend']
22:18:48.465 INFO logging:45 - MainView: Open the Alarm Page. Arguments (). Keyword arguments: {}.
22:18:48.465 INFO logging:45 - MainView: Open the Clock Page. Arguments (). Keyword arguments: {}.
22:18:48.814 DEBUG _X11:350 - Moving mouse to position 159,552 with animation.
22:18:49.087 DEBUG _X11:393 - The mouse is now at position 159,552.
22:18:49.088 DEBUG _X11:304 - Pressing mouse button 1
22:18:49.092 DEBUG _X11:350 - Moving mouse to position 159,160 with animation.
22:18:51.184 DEBUG _X11:393 - The mouse is now at position 159,160.
22:18:51.184 DEBUG _X11:311 - Releasing mouse button 1
22:19:01.523 INFO _launcher:544 - waiting for process to exit.
22:19:01.524 INFO _launcher:567 - Killing process 19531
}}}

Traceback (most recent call last):
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/tests/test_alarm.py", line 70, in setUp
    self.page = self.app.main_view.open_alarm()
  File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
    return f(instance, *args, **kwargs)
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 69, in open_alarm
    clockPage.reveal_bottom_edge_page()
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 117, in reveal_bottom_edge_page
    self.isReady.wait_for(True)
  File "/usr/lib/python3/dist-packages/autopilot/introspection/types.py", line 180, in wait_for
    failure_msg))
AssertionError: After 10.0 seconds test on ClockPage.isReady failed: True != dbus.Boolean(False, variant_level=1)
======================================================================
FAIL: ubuntu_clock_app.tests.test_alarm.TestAlarm.test_add_recurring_type_alarm_must_add_to_alarm_list(weekday)
----------------------------------------------------------------------
Binary content:
  FailedTestScreenshot (image/png)
Empty attachments:
  /var/log/syslog
  process-stdout (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene)

process-return-code (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{-15}}}
process-stderr (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{
Testability driver loaded. Wire protocol version is "1.4".
qml: [LOG]: Clock Page loaded
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/clock/ClockPage.qml:247:20: Unable to assign [undefined] to QColor
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: [LOG]: Alarm Page loaded
qml: [LOG]: Searching online for user location at http://api.geonames.org/findNearbyPlaceNameJSON?lat=42.8333&lng=12.8333&username=krnekhelesh&style=full
qml: [LOG]: Stopping geolocation update service
Source changed not found
qml: [LOG]: Alarm Database loaded
Source changed not found
qml: [LOG]: Alarm Database loaded
}}}

test-log: {{{
22:19:01.600 INFO logging:45 - TestAlarm: launch_test_local. Arguments (). Keyword arguments: {}.
22:19:01.600 WARNING base:52 - This function is deprecated. Use get_toolkit_launcher_command() instead.
22:19:01.600 INFO _launcher:373 - Attempting to launch application '/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene' with arguments '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml -I /home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend' as a normal process
22:19:01.607 INFO _launcher:431 - Launching process: ['/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene', '-testability', '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml', '-I', '/home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend']
22:19:04.047 INFO logging:45 - MainView: Open the Alarm Page. Arguments (). Keyword arguments: {}.
22:19:04.049 INFO logging:45 - MainView: Open the Clock Page. Arguments (). Keyword arguments: {}.
22:19:04.432 DEBUG _X11:350 - Moving mouse to position 159,552 with animation.
22:19:04.714 DEBUG _X11:393 - The mouse is now at position 159,552.
22:19:04.715 DEBUG _X11:304 - Pressing mouse button 1
22:19:04.716 DEBUG _X11:350 - Moving mouse to position 159,160 with animation.
22:19:06.839 DEBUG _X11:393 - The mouse is now at position 159,160.
22:19:06.839 DEBUG _X11:311 - Releasing mouse button 1
22:19:17.088 INFO _launcher:544 - waiting for process to exit.
22:19:17.088 INFO _launcher:567 - Killing process 19619
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/tests/test_alarm.py", line 70, in setUp
    self.page = self.app.main_view.open_alarm()
  File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
    return f(instance, *args, **kwargs)
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 69, in open_alarm
    clockPage.reveal_bottom_edge_page()
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 117, in reveal_bottom_edge_page
    self.isReady.wait_for(True)
  File "/usr/lib/python3/dist-packages/autopilot/introspection/types.py", line 180, in wait_for
    failure_msg))
AssertionError: After 10.0 seconds test on ClockPage.isReady failed: True != dbus.Boolean(False, variant_level=1)
}}}
======================================================================
FAIL: ubuntu_clock_app.tests.test_alarm.TestAlarm.test_add_recurring_type_alarm_must_add_to_alarm_list(weekend)
----------------------------------------------------------------------
Binary content:
  FailedTestScreenshot (image/png)
Empty attachments:
  /var/log/syslog
  process-stdout (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene)

process-return-code (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{-15}}}
process-stderr (/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene): {{{
Testability driver loaded. Wire protocol version is "1.4".
qml: [LOG]: Clock Page loaded
file:///home/letozaf/autopilot-tests/ubuntu-clock-app/app/clock/ClockPage.qml:247:20: Unable to assign [undefined] to QColor
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: WARNING! Do not put Page/Tabs/PageStack inside another Page because that causes confusion which is the active page that sets the title and actions.
qml: [LOG]: Alarm Page loaded
qml: [LOG]: Searching online for user location at http://api.geonames.org/findNearbyPlaceNameJSON?lat=42.8333&lng=12.8333&username=krnekhelesh&style=full
Source changed not found
qml: [LOG]: Stopping geolocation update service
qml: [LOG]: Alarm Database loaded
Source changed not found
qml: [LOG]: Alarm Database loaded
}}}

test-log: {{{
22:19:17.163 INFO logging:45 - TestAlarm: launch_test_local. Arguments (). Keyword arguments: {}.
22:19:17.163 WARNING base:52 - This function is deprecated. Use get_toolkit_launcher_command() instead.
22:19:17.163 INFO _launcher:373 - Attempting to launch application '/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene' with arguments '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml -I /home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend' as a normal process
22:19:17.171 INFO _launcher:431 - Launching process: ['/usr/lib/x86_64-linux-gnu/qt5/bin/qmlscene', '-testability', '/home/letozaf/autopilot-tests/ubuntu-clock-app/app/ubuntu-clock-app.qml', '-I', '/home/letozaf/autopilot-tests/build-ubuntu-clock-app-Desktop-Default/backend']
22:19:19.917 INFO logging:45 - MainView: Open the Alarm Page. Arguments (). Keyword arguments: {}.
22:19:19.917 INFO logging:45 - MainView: Open the Clock Page. Arguments (). Keyword arguments: {}.
22:19:20.040 DEBUG _X11:350 - Moving mouse to position 159,552 with animation.
22:19:20.320 DEBUG _X11:393 - The mouse is now at position 159,552.
22:19:20.320 DEBUG _X11:304 - Pressing mouse button 1
22:19:20.321 DEBUG _X11:350 - Moving mouse to position 159,160 with animation.
22:19:22.442 DEBUG _X11:393 - The mouse is now at position 159,160.
22:19:22.443 DEBUG _X11:311 - Releasing mouse button 1
22:19:32.737 INFO _launcher:544 - waiting for process to exit.
22:19:32.738 INFO _launcher:567 - Killing process 19651
}}}

traceback-2: {{{
Traceback (most recent call last):
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/tests/test_alarm.py", line 70, in setUp
    self.page = self.app.main_view.open_alarm()
  File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
    return f(instance, *args, **kwargs)
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 69, in open_alarm
    clockPage.reveal_bottom_edge_page()
  File "/home/letozaf/autopilot-tests/ubuntu-clock-app/tests/autopilot/ubuntu_clock_app/__init__.py", line 117, in reveal_bottom_edge_page
    self.isReady.wait_for(True)
  File "/usr/lib/python3/dist-packages/autopilot/introspection/types.py", line 180, in wait_for
    failure_msg))
AssertionError: After 10.0 seconds test on ClockPage.isReady failed: True != dbus.Boolean(False, variant_level=1)
}}}

Ran 3 tests in 47.710s
FAILED (failures=3)
I: autopilot tests done
/usr/bin/autopilot3-sandbox-run exited with code 1

This is my hardware:

https://gist.github.com/anonymous/3203c7c5a43a509c0f22