better error message if launched application terminates

[Javier Collado]

See comment 19 for an analysis of the root causes and actual bugs here.

I'm having trouble lately running test cases with autopilot. One of the problems is that I'm not able to launch the gallery application using something like:
launch_test_application('gallery-app', temp_sample_dir, app_type='qt')

In particular the backtrace that I obtain in this case is:

    Traceback (most recent call last):
      File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/tests/test_memory_usage.py", line 56, in test_scenario
        gallery.launch()
      File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/apps/gallery.py", line 37, in launch
        app_type='qt')
      File "/usr/lib/python2.7/dist-packages/autopilot/testcase.py", line 256, in launch_test_application
        return get_autopilot_proxy_object_for_process(process, emulator_base)
      File "/usr/lib/python2.7/dist-packages/autopilot/introspection/__init__.py", line 160, in get_autopilot_proxy_object_for_process
        return get_proxy_object_for_existing_process(pid, emulator_base=emulator_base)
      File "/usr/lib/python2.7/dist-packages/autopilot/introspection/__init__.py", line 205, in get_proxy_object_for_existing_process
        raise RuntimeError("Search criteria returned no results")
    RuntimeError: Search criteria returned no results

Something that might be related is that recently a needed to update the test cases in the device (mako) to make them work and that broke them when running them in my laptop. What I needed to do was replace `proxy.pid` with `proxy.process`. At first it looked to me like `pid` was renamed to `process`, but now I think something might be wrong with this because in the code `process` seems to be clearly set to whatever is returned by `subprocess.Popen` and `pid` is set to access `process.pid`.

[Javier Collado (javier.collado)]

The same problem happens with the media player application:

    Traceback (most recent call last):
      File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/tests/test_memory_usage.py", line 62, in test_scenari
        media_player.launch()
      File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/apps/media_player.py", line 46, in launch
        self.app = self.tc.launch_test_application(*args, app_type='qt')
      File "/usr/lib/python2.7/dist-packages/autopilot/testcase.py", line 256, in launch_test_application
        return get_autopilot_proxy_object_for_process(process, emulator_base)
      File "/usr/lib/python2.7/dist-packages/autopilot/introspection/__init__.py", line 160, in get_autopilot_proxy_object_for_process
        return get_proxy_object_for_existing_process(pid, emulator_base=emulator_base)
      File "/usr/lib/python2.7/dist-packages/autopilot/introspection/__init__.py", line 205, in get_proxy_object_for_existing_process
        raise RuntimeError("Search criteria returned no results")
    RuntimeError: Search criteria returned no results

[Christopher Lee (veebers)]

Awaiting instructions on how to reproduce as well as being able to actually reproduce.

[Christopher Lee (veebers)]

@Javier

Thanks for the details on how to replicate.
I could replicate it on my device here, but I can with the jenkins job you've provided.

I have a couple of potential ideas, but haven't solved it yet.

[Omer Akram (om26er)]

I am trying to write autopilot tests for the OSK and I am struck with the same issue.

[Martin Pitt (pitti)]

Javier, Christopher, would you mind putting the reproduction instructions here? I tried this on current saucy, and it works fine. I also tried launching ubuntuone-control-panel-qt, which works as well (using Qt4).

[Javier Collado (javier.collado)]

The way to reproduce the problem is by running this job:
https://jenkins.qa.ubuntu.com/job/memevent-saucy-touch-armhf-default-mako-01/

The way to reproduce it in a local jenkins instance, would be as follows:

$ sudo apt-get install jenkins
$ bzr branch lp:~javier.collado/ubuntu-test-runlists/memory-usage-measurement
$ cd memory-usage-measurement/jenkins
$ ./setup-jobs -j http://localhost:8080 <serial_number> <wifi_file>
(launch the job in your local jenkins instance)

where:
- <serial_number>: is the one that you get with `adb get-serialno`
- <wifi_file>: Is the active network configuration file found in
`/etc/NetworkManager/system-connections/<ssid>`

[Martin Pitt (pitti)]

I tried my test script on a nexus7, and that works fine.

According to http://bazaar.launchpad.net/~javier.collado/ubuntu-test-runlists/memory-usage-measurement/view/head:/utah/master.run , the actual test case is in https://code.launchpad.net/~javier.collado/ubuntu-test-cases/memory-usage-measurement/utah, but that isn't a valid branch. Javier, where is the actual test that runs on the device? I'd like to run this on the device to investigate.

[Martin Pitt (pitti)]

Ah, nevermind; I tried to checkout lp:~javier.collado/ubuntu-test-cases/memory-usage-measurement as well (without the extra /utah), and that failed some minutes ago, but that was just due to LP being down.

So I checked out lp:~javier.collado/ubuntu-test-cases/memory-usage-measurement, installed {webbrowser,camera,mediaplayer}-app-autopilot, autopilot-touch, and smem and ran "autopilot run ubuntu_test_cases" in the "autopilot" subdir.

With that I get some failures:

---------------------- 8< ---------------------------
Loading tests from: /home/phablet/memory-usage-measurement/autopilot

Tests running...
__pthread_gettid -2
======================================================================
ERROR: ubuntu_test_cases.memory_usage_measurement.tests.test_memory_usage.MemoryUsageTests.test_scenario
----------------------------------------------------------------------
_StringException: Empty attachments:
  process-stdout

process-stderr: {{{
unknown option -- t
unknown option -- e
unknown option -- s
unknown option -- t
unknown option -- a
unknown option -- b
unknown option -- i
unknown option -- l
unknown option -- i
unknown option -- t
unknown option -- y
loaded the dummy plugin
loaded the Linux plugin
Registered the AalSensorPlugin types

Loading testability driver.

WARNING: This project is using the experimental QML API extensions for QtWebKit and is therefore tied to a specific QtWebKit release.
WARNING: The experimental API will change from version to version, or even be removed. You have been warned!

file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/TabsList.qml:34: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Chrome.qml:131: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Suggestions.qml:35: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/TabsList.qml:83: ReferenceError: UbuntuColors is not defined
callbacks 0x428f5495 0x428f5499
creating surface at (0, 44) with size (800, 1236)loaded the dummy plugin
loaded the Linux plugin
Registered the AalSensorPlugin types

file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Suggestions.qml:110: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Suggestions.qml:110: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Suggestions.qml:110: ReferenceError: UbuntuColors is not defined
file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/Extras/Browser/Suggestions.qml:110: ReferenceError: UbuntuColors is not defined
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/autopilot/utilities.py", line 253, in action_on_test_end
    obj.on_test_end(test_instance)
  File "/usr/lib/python2.7/dist-packages/autopilot/input/_X11.py", line 464, in on_test_end
    move_mouse_to_screen(0)
  File "/usr/lib/python2.7/dist-packages/autopilot/display/_...

[Javier Collado (javier.collado)]

`smem-tabs` is a custom version of `smem` that prints the whole command line
for each process. It was manually installed in the lab, but I decided to
include it in the `ubuntu-test-cases` package in my PPA
(ppa:javier.collado/ppa) since I'll probably reuse it in other test cases in
the future.

Note that the test cases are also in my PPA in the package
`ubuntu-test-cases-memory-usage-measurement`.

[Martin Pitt (pitti)]

Got smem-tabs from https://launchpad.net/~javier.collado/+archive/ppa/+packages (ubuntu-test-cases). The "RuntimeError: Unable to instantiate any backends" problem remains.

Now I see

Tests running...
__pthread_gettid -2
----------------------------Browser started-----------------------------
PID: 3431, command: /usr/bin/webbrowser-app -testability, PSS: 27301, USS: 17604

but there is no actual webbrowser starting up (I don't see it on the screen, and it's not in unity's "running apps" section). Consequently, this fails:

  File "/home/phablet/memory-usage-measurement/autopilot/ubuntu_test_cases/memory_usage_measurement/apps/browser.py", line 92, in reveal_chrome
    self.tc.assertThat(panel.state, Eventually(Equals('spread')))
MismatchError: After 20.0 seconds test on Panel.state failed: 'spread' != dbus.String(u'', variant_level=1)

Could this perhaps be a problem of how the apps are being started up? E. g. when launching them from a shell, they usually need something like "webbrowser-app --desktop_file_hint=/usr/share/applications/webbrowser-app.desktop", just running "webbrowser-app" does not make them actually appear anywhere.

[Martin Pitt (pitti)]

Running "autopilot run ubuntu_test_cases" works in general for me when I do it from the terminal app from the device (that sets some env variables for proper startup, which are missing in ssh/adb shell). I get a test case failure ("NoneType has no attribute enabled") in take_picture(), but otherwise it runs. So this doesn't seem to reproduce this failure either.

So could this be a problem with either the environment that the jenkins job or the utah script is run under, so that these use two different D-BUSes or so?

[Martin Pitt (pitti)]

Christopher, can you please expand on "I have a couple of potential ideas", i. e. how to reproduce this issue?

[Christopher Lee (veebers)]

I'm pasting in this email text that I originally sent so that others can also see it (with one slight addition *).

I've been working on and exploring this bug #1198277 [0]. I don't have a
solution yet, but I've noticed a couple of odd things during my pondering.
I fear this email is a long one but contains my brain dump of the situation.

I've been poking around the device itself (I put a sleep 30m into the jenkins
job so the device was still marked as in use while I did so).
What I found is that I was unable to do any of the things that I could do
manually on my local desktop/device.

For instance what I was doing in a terminal was:

  1. Starting `gallery-app -testability`
  2. using a simple python script to determine the bus name (i.e. :1.209)
  3. using qdus and dbus-send to query it manually (i.e. qdbus :1.209 will
     return the available object paths. Specifically interested in
     /com/canonical/Autopilot/Introspection for instance.)

When I first logged onto the device step 3 didn't work as expected, I got an
error (examples to come).
After rebooting the device however my manual tests worked, it wasn't until after
I ran the memory usage did it get into the state were my tests didn't work.

So I'm not entirely certain at this stage that the issue is specifically an
Autopilot testcase bug.

Description and steps for testing and reproducing:.

I'm using this script here [1]
What it does is launch an introspectable application (i.e. gallery-app
-testability) and queries it using qdbus/dbus-send. It outputs the object paths
and PIDs so we can ensure we're looking at the correct objects.
*[I tested this script with the shell both enabled and disabled and it worked multiple times in a row with both]

The process to my madness is this:

  1. Run the pid test script `./test_pids.sh` -> output will show success,
     example here [2]
  2. Run the memory_usage_measurement tests -> will fail as expected
     (utah-autopilot run -v ubuntu_test_cases.memory_usage_measurement.tests.test_memory_usage.MemoryUsageTests.test_scenario)
  3. Re-run the pid test script -> The output will show failure [3]

Also, during this I realised this:

  1. Run the memory_usage_measurement tests -> Will fail at the gallery app step
  2. Run the memory_usage_measurement tests again -> Will fail at the browser
     app step (i.e. the first app launch)

So after the first run a second run will fail with 'raise RuntimeError("Search
criteria returned no results")' at browser launch (where as the first run does
this at the gallery-app launch step).

So there we go, that's my findings so far. To be honest I'm not sure what the
issue is at the moment so I'm wondering if anyone else might be able to shed
some light for me or point me in a new direction?

Is there something happening in the test code that is causing the system to do
something weird? Perhaps something on the device is crashing in an odd way,
either dbus or libautopilot-qt or <something>.

I'll ponder this tonight and try again in the morning.
Please let me know if I'm missing any part of my explanation or you would like
a clarification of any points.

-- Links --
[0:bug] https://bugs.launchpad.net/autopilot...

[Martin Pitt (pitti)]

I think I've found something. I noticed that when I try to launch apps from ssh, this usually works, but after running ubuntu_test_cases.memory_usage_measurement this fails with

$ gallery-app
[...]
(process:4913): GLib-GIO-CRITICAL **: g_dbus_connection_register_object: assertion 'G_IS_DBUS_CONNECTION (connection)' failed
[...]
** (process:4913): ERROR **: Unable to get session bus: Could not connect: Connection refused

This is because running memory_usage_measurement crashes the whole existing session, and after that the session d-bus, unity8, and everythign else gets restarted. That means that in an existing process $DBUS_SESSION_BUS_ADDRESS is now invalid, and (in my case) I have to log out and back in. If something similar happens in the tests that means that their test session bus that they started will become invalid when it crashes. Javier, can you please verify the identity (pid/startup time) of the session dbus-daemon when you run your tests?

[Martin Pitt (pitti)]

The "crashes the shell" was bogus, that's the intended result of phablet-test-run's -n switch. I think this is what confused Christopher as well, as presumably he ran his test python script in the same session before and after the test.

Also, the RuntimeError about AP's input backend disappeared with the latest saucy phablet build. The full output that I get is now the one below, which is just a "normal" test case failure. So I'm back to not being able to reproduce this :-/

__pthread_gettid -2
----------------------------Browser started-----------------------------
PID: 3039, command: /usr/bin/webbrowser-app -testability, PSS: 23686, USS: 16360
------------------------Browser finished loading------------------------
PID: 3039, command: /usr/bin/webbrowser-app -testability, PSS: 31590, USS: 21136
---------------------------Camera app started---------------------------
PID: 3039, command: /usr/bin/webbrowser-app -testability, PSS: 28954, USS: 20508
PID: 3138, command: /usr/bin/camera-app -testability, PSS: 13930, USS: 9884
======================================================================
FAIL: ubuntu_test_cases.memory_usage_measurement.tests.test_memory_usage.MemoryUsageTests.test_scenario
----------------------------------------------------------------------
_StringException: Empty attachments:
  process-stdout

process-stderr: {{{
unknown option -- t
unknown option -- e
unknown option -- s
unknown option -- t
unknown option -- a
unknown option -- b
unknown option -- i
unknown option -- l
unknown option -- i
unknown option -- t
unknown option -- y
loaded the dummy plugin
loaded the Linux plugin
Registered the AalSensorPlugin types

Loading testability driver.

WARNING: This project is using the experimental QML API extensions for QtWebKit and is therefore tied to a specific QtWebKit release.
WARNING: The experimental API will change from version to version, or even be removed. You have been warned!

callbacks 0x428ca499 0x428ca49d
creating surface at (0, 44) with size (800, 1236)loaded the dummy plugin
loaded the Linux plugin
Registered the AalSensorPlugin types

Detectable autorepeat not supported.
}}}

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/tests/test_memory_usage.py", line 52, in test_scenario
    camera.take_picture()
  File "/usr/lib/python2.7/dist-packages/ubuntu_test_cases/memory_usage_measurement/apps/camera.py", line 45, in take_picture
    self.tc.assertThat(exposure_button.enabled, Eventually(Equals(True)))
MismatchError: After 20.0 seconds test on ShootButton.enabled failed: True != dbus.Boolean(False, variant_level=1)

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

[Martin Pitt (pitti)]

I tried the very same on the nexus 4 now, and I do get the original "Search criteria returned no results" error now. So this works on the n7, but fails on the n4.

[Martin Pitt (pitti)]

This is the complete output when I run "autopilot run -v ubuntu_test_cases.memory_usage_measurement 2>&1 | tee log" directly in terminal-app. This skips all the magic and shell shutdown/restart of phablet-run-test.

Note that I got the bug with media-player-app in this run. But in the next run I see this in the log:

08:48:52.449 INFO __init__:140 - Launching process: ['/usr/bin/camera-app', '-testability']
08:48:55.296 INFO __init__:299 - DBusException while attempting to get PID for org.freedesktop.DBus: DBusException("Could not get PID of name 'org.freedesktop.DBus': no such name",)
08:49:22.887 ERROR proxies:410 - Introspect error on :1.76:/com/canonical/Autopilot/Introspection: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

and camera app never got started. The first run (in attached log) did not have this "Did not receive a reply" error/timeout. So with this the problem still doesn't reproduce well.

[Martin Pitt (pitti)]

Keeping notes: I installed ubuntu-test-cases and ubuntu-test-cases-memory-usage-measurement from jcollado's PPA, then purged ubuntu-test-cases-memory-usage-measurement, and use the bzr branch instead (which makes it easier to change/revert things):

bzr branch lp:~javier.collado/ubuntu-test-cases/memory-usage-measurement

This is my test script:

$ cat ~/do
#!/bin/sh
cd memory-usage-measurement/autopilot
autopilot run -v ubuntu_test_cases.memory_usage_measurement 2>&1 | tee ~/log

With that I open terminal-app, and run "./do". This gives me a fairly fast turnaround time and no unnecessary layers in between.

- Disabling smem: bug happens
- Disable the 'Media player app finished playback' block: test works multiple times
- only run the two last "media player" tests, disable everything else (including smem): bug happens

My suspicion is that this is due to launching mediaplayer-app twice. A simple test like

        self.media = self.launch_test_application('mediaplayer-app', app_type='qt')
        self.media2 = self.launch_test_application('mediaplayer-app', '-w', 'small.mp4', app_type='qt')

works though. So a minimal reproducer must be somewhere in between.

Christopher, Thomi, is it supported to run an app two times? Does ap and U phone support that in general?

[Martin Pitt (pitti)]

Oh dear, it is so infinitely simpler than all of the above:

phablet 11623 15.5 0.0 0 0 ? Zs 10:31 0:00 [mediaplayer-app] <defunct>

The reason is simply that mediaplayer-app immediately exits with the given arguments, so that it never actually registers at the bus:

$ mediaplayer-app -w file:///usr/share/mediaplayer-app/videos/small.mp4
__pthread_gettid -2
unknown option -- w
[...]
Segmentation fault

So there are several actual bugs here:

 * Javier's tests call mediaplayer-app with an invalid argument

 * mediaplayer-app doesn't handle invalid arguments gracefully and just crashes

 * autopilot's launch_test_application() should check whether a process is still actually running, and abort the waiting for the D-BUS interface with a proper error message, so that this is easier to debug in the future. Ideally it would show the application's stderr in that case, so that one actually sees the "unknown option -- w" and "Segmentation fault". This is a simple test case:

----------------- 8< --------------------
#!/usr/bin/python
import time
from autopilot.testcase import AutopilotTestCase

class T(AutopilotTestCase):
    def setUp(self):
        super(T, self).setUp()
        self.p = self.launch_test_application('true', app_type='qt')

    def test_dummy(self):
        print(self.p)

unittest.main()
----------------- 8< --------------------

[Javier Collado (javier.collado)]

Yesterday I wasn't able to reproduce the segmentation fault; but, after updating to the latest build, what I get is a segmentation fault with the following two command lines:

mediaplayer-app -w file:///usr/share/mediaplayer-app/videos/small.mp4

mediaplayer-app file:///usr/share/mediaplayer-app/videos/small.mp4 --fullscreen --desktop_file_hint=/usr/share/applications/mediaplayer-app.desktop

The second one is what I've seen in the test cases in the application branch, so it should be valid. Anyway, my point is that the segmentation fault is not happening because of an invalid option being passed.

I also need to understand why the test case seems to work in a nexus7 and why the test case fails in the gallery app which is executed before the media player app, that is, when the test case fails, the media player app hasn't been launched yet.

To summarize, one problem has been found, but not the whole problem. Otherwise, I should be able to fix the command line for the media-player application and the test should run perfectly and that doesn't happen.

[Martin Pitt (pitti)]

> I also need to understand why the test case seems to work in a nexus7

It doesn't, it just fails before it gets to the mediaplayer-app tests because on the nexus7 camera-app is totally dysfunctional (which your test detects, and rightfully fails :) ). See comment 15.

> To summarize, one problem has been found, but not the whole problem.

Yes, there are obviously bugs in the actual apps, but I didn't look into them. Those should get new bug reports against the apps, these are unrelated to autopilot.

[Javier Collado (javier.collado)]

I've tried to run the test cases in the media player application in a terminal in the phone itself with the following command:
autopilot run -v mediaplayer_app.tests

and the ouput was basically the same failure while creating the proxy object five times in a row.

[PS Jenkins bot (ps-jenkins)]

Fix committed into lp:autopilot at revision 292, scheduled for release in autopilot, milestone 1.3.2

[Launchpad Janitor (janitor)]

This bug was fixed in the package autopilot - 1.3.1+13.10.20130727-0ubuntu1

---------------
autopilot (1.3.1+13.10.20130727-0ubuntu1) saucy; urgency=low

  [ Christopher Lee ]
  * Better errors when searching to create a proxy object and the
    process no longer is running. (LP: #1198277)

  [ Ubuntu daily release ]
  * Automatic snapshot from revision 293
 -- Ubuntu daily release <email address hidden> Sat, 27 Jul 2013 00:02:50 +0000