ubuntuuitoolkit.tests.custom_proxy_objects.test_dialog.DialogTestCase.test_dialog fails with “RuntimeError: Keyboard is not on screen”

[Jonas G. Drange]

current build number: 245
device name: mako
channel: ubuntu-touch/rc-proposed/ubuntu
last update: 1970-01-13 22:33:27
version version: 245
version ubuntu: 20150921
version device: 20150911
version custom: 20150921

(It says 1970, but actually, I wasn't even born then. Last update: 2015-09-21)

Reproduce:
Run test ubuntuuitoolkit.tests.custom_proxy_objects.test_dialog.DialogTestCase.test_dialog on mako at least 10 times. It fails reliably ~10% on my phone.

What happens:
Tests running...
16:31:53.574 INFO _logging:40 - ************************************************************
16:31:53.575 INFO _logging:41 - Starting test ubuntuuitoolkit.tests.custom_proxy_objects.test_dialog.DialogTestCase.test_dialog
16:31:53.899 WARNING testcase:181 - Process manager backend unavailable, application snapshot support disabled.
16:31:54.172 INFO _launcher:389 - Attempting to launch application '/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher' with arguments '-I /usr/lib/modules /usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.DialogTestCase.qml --desktop_file_hint=/home/phablet/.local/share/applications/tmpbn72zjav.desktop' as a normal process
16:31:54.191 INFO _launcher:447 - Launching process: ['/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher', '-testability', '-I', '/usr/lib/modules', '/usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.DialogTestCase.qml', '--desktop_file_hint=/home/phablet/.local/share/applications/tmpbn72zjav.desktop']
16:31:59.986 INFO logging:45 - TextArea: Write into the text field. Arguments ('test',). Keyword arguments: {}.
16:32:01.153 INFO _launcher:560 - waiting for process to exit.
16:32:01.154 INFO _launcher:583 - Killing process 18283
16:32:01.427 ERROR testresult:44 - ERROR: ubuntuuitoolkit.tests.custom_proxy_objects.test_dialog.DialogTestCase.test_dialog
16:32:01.433 ERROR testresult:44 - process-stderr (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher): {{{
Loading module: 'libubuntu_application_api_touch_mirclient.so.3.0.0'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'e'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 's'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'a'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'b'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'i'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'l'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'i'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'y'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'I'
Testability driver loaded. Wire protocol version is "1.4".
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:123:5: QML UbuntuShape: 'color' is deprecated. Use 'backgroundColor', 'secondaryBackgroundColor' and 'backgroundMode' instead.
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:135:5: QML UbuntuShape: 'gradientColor' is deprecated. Use 'backgroundColor', 'secondaryBackgroundColor' and 'backgroundMode' instead.
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:123:5: QML UbuntuShape: 'image' is deprecated. Use 'source' instead.
qml: Page.tools is a deprecated property. Please use Page.head instead.
UbuntuClipboard - Got invalid serialized mime data. Ignoring it.
}}}
16:32:01.435 ERROR testresult:44 - Binary attachment: "FailedTestScreenshot" (image/png)
16:32:01.435 ERROR testresult:44 - /var/log/syslog: {{{
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.654355] input: py-evdev-uinput as /devices/virtual/input/input386
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.654965] keychord: using input dev py-evdev-uinput for fevent
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.786630] input: autopilot-finger as /devices/virtual/input/input387
Sep 21 16:31:54 ubuntu-phablet powerd[920]: handle_requestSysState from :1.63 (active) - ACTIVE (1)
Sep 21 16:31:54 ubuntu-phablet powerd[920]: name_watch_add: looking for :1.63
Sep 21 16:31:54 ubuntu-phablet powerd[920]: watching :1.63 to see when it disappears on dbus
Sep 21 16:31:54 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:54 ubuntu-phablet powerd[920]: handle_requestSysState - SUCCESS
Sep 21 16:31:54 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:54 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:54 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:54 ubuntu-phablet powerd[920]: 11371543 slow avg 209.709862 fast avg 209.972302 last 210.000000
Sep 21 16:31:55 ubuntu-phablet powerd[920]: handle_requestWakeup from :1.74 - ubuntu push client, 1442846215
Sep 21 16:31:55 ubuntu-phablet powerd[920]: void {anonymous}::reset_alarm_clock() found 1 remaining wakeup requests
Sep 21 16:31:55 ubuntu-phablet powerd[920]: setting hardware wakeup time to 2015-09-21 16:36:55 for ubuntu push client
Sep 21 16:31:55 ubuntu-phablet powerd[920]: starting hardware alarm worker thread
Sep 21 16:31:55 ubuntu-phablet powerd[920]: calling wait_for_next_alarm
Sep 21 16:31:55 ubuntu-phablet powerd[920]: handle_clearSysState from :1.74, cookie: 70fc21f2-8592-4fc1-8c0e-b6cd99de0163
Sep 21 16:31:55 ubuntu-phablet powerd[920]: clear_sys_request: ubuntu push client - :1.74
Sep 21 16:31:55 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.74
Sep 21 16:31:55 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.74 is now 0
Sep 21 16:31:55 ubuntu-phablet powerd[920]: no longer watching :1.74, there are no more requests
Sep 21 16:31:55 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:55 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:55 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:55 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:58 ubuntu-phablet powerd[920]: handle_requestSysState from :1.35 (usensord) - ACTIVE (1)
Sep 21 16:31:58 ubuntu-phablet powerd[920]: name_watch_add: looking for :1.35
Sep 21 16:31:58 ubuntu-phablet powerd[920]: watching :1.35 to see when it disappears on dbus
Sep 21 16:31:58 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:58 ubuntu-phablet powerd[920]: handle_requestSysState - SUCCESS
Sep 21 16:31:58 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:58 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:58 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:59 ubuntu-phablet powerd[920]: handle_clearSysState from :1.35, cookie: 5d959095-4887-4a72-a22c-1c72a75d2002
Sep 21 16:31:59 ubuntu-phablet powerd[920]: clear_sys_request: usensord - :1.35
Sep 21 16:31:59 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.35
Sep 21 16:31:59 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.35 is now 0
Sep 21 16:31:59 ubuntu-phablet powerd[920]: no longer watching :1.35, there are no more requests
Sep 21 16:31:59 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:59 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:59 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:59 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:32:01 ubuntu-phablet powerd[920]: handle_clearSysState from :1.63, cookie: dcd208f7-3175-4514-bf90-12dc91b10f3d
Sep 21 16:32:01 ubuntu-phablet powerd[920]: clear_sys_request: active - :1.63
Sep 21 16:32:01 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.63
Sep 21 16:32:01 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.63 is now 0
Sep 21 16:32:01 ubuntu-phablet powerd[920]: no longer watching :1.63, there are no more requests
Sep 21 16:32:01 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:32:01 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:32:01 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:32:01 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
}}}
16:32:01.439 ERROR testresult:44 - process-return-code (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher): {{{
-15}}}
16:32:01.440 ERROR testresult:44 - process-stdout (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher): {{{
}}}
16:32:01.441 ERROR testresult:44 - traceback: {{{
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.py", line 36, in test_dialog
text_area.write('test')
File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
return f(instance, *args, **kwargs)
File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_textfield.py", line 49, in write
self.keyboard.type(text)
File "/usr/lib/python3/dist-packages/autopilot/input/_osk.py", line 105, in type
self._keyboard.type(string, delay)
File "/usr/lib/python3/dist-packages/ubuntu_keyboard/emulators/keyboard.py", line 211, in type
self.press_key(char)
File "/usr/lib/python3/dist-packages/ubuntu_keyboard/emulators/keyboard.py", line 165, in press_key
raise RuntimeError("Keyboard is not on screen")
RuntimeError: Keyboard is not on screen
}}}
======================================================================
ERROR: ubuntuuitoolkit.tests.custom_proxy_objects.test_dialog.DialogTestCase.test_dialog
----------------------------------------------------------------------
Binary content:
FailedTestScreenshot (image/png)
Empty attachments:
process-stdout (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher)

/var/log/syslog: {{{
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.654355] input: py-evdev-uinput as /devices/virtual/input/input386
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.654965] keychord: using input dev py-evdev-uinput for fevent
Sep 21 16:31:53 ubuntu-phablet kernel: [11370.786630] input: autopilot-finger as /devices/virtual/input/input387
Sep 21 16:31:54 ubuntu-phablet powerd[920]: handle_requestSysState from :1.63 (active) - ACTIVE (1)
Sep 21 16:31:54 ubuntu-phablet powerd[920]: name_watch_add: looking for :1.63
Sep 21 16:31:54 ubuntu-phablet powerd[920]: watching :1.63 to see when it disappears on dbus
Sep 21 16:31:54 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:54 ubuntu-phablet powerd[920]: handle_requestSysState - SUCCESS
Sep 21 16:31:54 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:54 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:54 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:54 ubuntu-phablet powerd[920]: 11371543 slow avg 209.709862 fast avg 209.972302 last 210.000000
Sep 21 16:31:55 ubuntu-phablet powerd[920]: handle_requestWakeup from :1.74 - ubuntu push client, 1442846215
Sep 21 16:31:55 ubuntu-phablet powerd[920]: void {anonymous}::reset_alarm_clock() found 1 remaining wakeup requests
Sep 21 16:31:55 ubuntu-phablet powerd[920]: setting hardware wakeup time to 2015-09-21 16:36:55 for ubuntu push client
Sep 21 16:31:55 ubuntu-phablet powerd[920]: starting hardware alarm worker thread
Sep 21 16:31:55 ubuntu-phablet powerd[920]: calling wait_for_next_alarm
Sep 21 16:31:55 ubuntu-phablet powerd[920]: handle_clearSysState from :1.74, cookie: 70fc21f2-8592-4fc1-8c0e-b6cd99de0163
Sep 21 16:31:55 ubuntu-phablet powerd[920]: clear_sys_request: ubuntu push client - :1.74
Sep 21 16:31:55 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.74
Sep 21 16:31:55 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.74 is now 0
Sep 21 16:31:55 ubuntu-phablet powerd[920]: no longer watching :1.74, there are no more requests
Sep 21 16:31:55 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:55 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:55 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:55 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:58 ubuntu-phablet powerd[920]: handle_requestSysState from :1.35 (usensord) - ACTIVE (1)
Sep 21 16:31:58 ubuntu-phablet powerd[920]: name_watch_add: looking for :1.35
Sep 21 16:31:58 ubuntu-phablet powerd[920]: watching :1.35 to see when it disappears on dbus
Sep 21 16:31:58 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:58 ubuntu-phablet powerd[920]: handle_requestSysState - SUCCESS
Sep 21 16:31:58 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:58 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:58 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:31:59 ubuntu-phablet powerd[920]: handle_clearSysState from :1.35, cookie: 5d959095-4887-4a72-a22c-1c72a75d2002
Sep 21 16:31:59 ubuntu-phablet powerd[920]: clear_sys_request: usensord - :1.35
Sep 21 16:31:59 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.35
Sep 21 16:31:59 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.35 is now 0
Sep 21 16:31:59 ubuntu-phablet powerd[920]: no longer watching :1.35, there are no more requests
Sep 21 16:31:59 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:31:59 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:31:59 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:31:59 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
Sep 21 16:32:01 ubuntu-phablet powerd[920]: handle_clearSysState from :1.63, cookie: dcd208f7-3175-4514-bf90-12dc91b10f3d
Sep 21 16:32:01 ubuntu-phablet powerd[920]: clear_sys_request: active - :1.63
Sep 21 16:32:01 ubuntu-phablet powerd[920]: name_watch_remove: looking for :1.63
Sep 21 16:32:01 ubuntu-phablet powerd[920]: name_watch: ref_count for :1.63 is now 0
Sep 21 16:32:01 ubuntu-phablet powerd[920]: no longer watching :1.63, there are no more requests
Sep 21 16:32:01 ubuntu-phablet powerd[920]: libsuspend: acquire_wake_lock: powerd_power_request
Sep 21 16:32:01 ubuntu-phablet powerd[920]: Enqueue state change to ACTIVE
Sep 21 16:32:01 ubuntu-phablet powerd[920]: queue empty && state == current, discarding
Sep 21 16:32:01 ubuntu-phablet powerd[920]: libsuspend: release_wake_lock: powerd_power_request
}}}

process-return-code (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher): {{{-15}}}
process-stderr (/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher): {{{
Loading module: 'libubuntu_application_api_touch_mirclient.so.3.0.0'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'e'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 's'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'a'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'b'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'i'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'l'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'i'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 't'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'y'
/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher: invalid option -- 'I'
Testability driver loaded. Wire protocol version is "1.4".
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:123:5: QML UbuntuShape: 'color' is deprecated. Use 'backgroundColor', 'secondaryBackgroundColor' and 'backgroundMode' instead.
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:135:5: QML UbuntuShape: 'gradientColor' is deprecated. Use 'backgroundColor', 'secondaryBackgroundColor' and 'backgroundMode' instead.
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Themes/Ambiance/1.2/ButtonStyle.qml:123:5: QML UbuntuShape: 'image' is deprecated. Use 'source' instead.
qml: Page.tools is a deprecated property. Please use Page.head instead.
UbuntuClipboard - Got invalid serialized mime data. Ignoring it.
}}}

test-log: {{{
16:31:53.899 WARNING testcase:181 - Process manager backend unavailable, application snapshot support disabled.
16:31:54.172 INFO _launcher:389 - Attempting to launch application '/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher' with arguments '-I /usr/lib/modules /usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.DialogTestCase.qml --desktop_file_hint=/home/phablet/.local/share/applications/tmpbn72zjav.desktop' as a normal process
16:31:54.191 INFO _launcher:447 - Launching process: ['/usr/lib/arm-linux-gnueabihf/ubuntu-ui-toolkit/launcher', '-testability', '-I', '/usr/lib/modules', '/usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.DialogTestCase.qml', '--desktop_file_hint=/home/phablet/.local/share/applications/tmpbn72zjav.desktop']
16:31:59.986 INFO logging:45 - TextArea: Write into the text field. Arguments ('test',). Keyword arguments: {}.
16:32:01.153 INFO _launcher:560 - waiting for process to exit.
16:32:01.154 INFO _launcher:583 - Killing process 18283
}}}

Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/tests/custom_proxy_objects/test_dialog.py", line 36, in test_dialog
text_area.write('test')
File "/usr/lib/python3/dist-packages/autopilot/logging.py", line 46, in inner
return f(instance, *args, **kwargs)
File "/usr/lib/python3/dist-packages/ubuntuuitoolkit/_custom_proxy_objects/_textfield.py", line 49, in write
self.keyboard.type(text)
File "/usr/lib/python3/dist-packages/autopilot/input/_osk.py", line 105, in type
self._keyboard.type(string, delay)
File "/usr/lib/python3/dist-packages/ubuntu_keyboard/emulators/keyboard.py", line 211, in type
self.press_key(char)
File "/usr/lib/python3/dist-packages/ubuntu_keyboard/emulators/keyboard.py", line 165, in press_key
raise RuntimeError("Keyboard is not on screen")
RuntimeError: Keyboard is not on screen

Ran 1 test in 7.871s
FAILED (failures=1)