Possible races in tst_daemon tests.

[James Henstridge]

While building online-accounts-api in a silo, I hit test failures on two builds. Here is the yakkety armhf build that failed, and the relevant output:

https://launchpadlibrarian.net/273307128/buildlog_ubuntu-yakkety-armhf.online-accounts-api_0.1+16.10.20160716-0ubuntu1_BUILDING.txt.gz

1468639216.012 getIdentity 35
1468639216.013 getAuthSessionObjectPath 35 "oauth2"
1468639216.015 process {"host": "coolmail.ex", "UiPolicy": 2, "delay": 3, "requestorPid": 7466} "user_agent"
FAIL! : FunctionalTests::testLifetime() '!reply.isError()' returned FALSE. ()
   Loc: [/«BUILDDIR»/online-accounts-api-0.1+16.10.20160716/tests/daemon/functional_tests/functional_tests.cpp(603)]

And here is the vivid armhf build failure:

https://launchpadlibrarian.net/273311762/buildlog_ubuntu-vivid-armhf.online-accounts-api_0.1+15.04.20160716-0ubuntu1_BUILDING.txt.gz

1468640752.957 GetConnectionAppArmorSecurityContext ":1.11"
QWARN : FunctionalTests::testAccountChanges() QDBusConnection: name 'com.ubuntu.OnlineAccounts.Manager' had owner '' but we thought it was ':1.8'
FAIL! : FunctionalTests::testAccountChanges() Compared values are not the same
   Actual (((accountChanged.count()))): 0
   Expected (1) : 1
   Loc: [/«BUILDDIR»/online-accounts-api-0.1+15.04.20160716/tests/daemon/functional_tests/functional_tests.cpp(567)]

I don't know what caused the failures. I tried updating the assertion in the first case to print the D-Bus error on failure, but the test passed on the next build. There's obviously something going on here, but I don't have time to track it down.

[Alberto Mardegan (mardy)]

I definitely see how these failures can happen: the tests set the OnlineAccounts.Manager service's auto-termination timeout to 2 seconds, which is generally appropriate. However, the testAccountChanges() test is not even trying to keep the service alive, because it's modifying the accounts DB via libaccounts; so, on a slower testing machine, indeed the service could auto-terminate itself during the lifetime of the test.

The error in vivid shows exactly this; in the yakkety case, the auto-termination happens a bit later, allowing the testAccountChanges() test to succeed, but then by the time the next test (testLifetime()) sets up its watch, the OnlineAccounts.Manager service has already quit, causing the other test to fail.

[Alberto Mardegan (mardy)]

I've spent some time to investigate this bug, here's my understanding.

The inactivity timer operates on a property of the OA.Manager object, called "idle". If "idle" becomes true and stays true for the whole duration of the timeout period (which by default is 5 seconds, and in the tests is set to 2 seconds), then the service process quits.

The "idle" property is set to false if any client makes a call on the D-Bus interface, and stays false until there are no active calls from any client (that is, until not all client requests have been answered). This means that the D-Bus service is free to come and go during the lifetime of a long-running client, depending on whether the client is actively using the D-Bus service or not.

But as I wrote in the comment above, this is not playing nice with the testAccountChanges() test case, which makes one D-Bus method call on its starts and then expects the service to stay alive and deliver change notifications.
We either need to increase the timeout during the tests (I wouldn't do that, since the next test duration would then need to be increased, to be meaningful) or place some method calls on the D-Bus service in testAccountChanges(), to keep the service alive. I'll try to go for this latter option.

Note: in the real world, this is not a problem: clients cannot directly modify the accounts DB (it's read-only), all accounts modifications are done through the online-accounts-service process (which is part of the ubuntu-system-settings-online-accounts project), which was also chosen to be the host for the OnlineAccounts.Manager D-Bus service. This means that whenever an account is modified, the OnlineAccounts.Manager D-Bus service will be active and able to detect modifications on the accounts DB and signal them out.

[James Henstridge (jamesh)]

With the attached branch added to the silo, we got failures for 2 out of the 20 builds.

First was the vivid i386 build: https://launchpadlibrarian.net/273878957/buildlog_ubuntu-vivid-i386.online-accounts-api_0.1+15.04.20160719-0ubuntu1_BUILDING.txt.gz

    1468915489.236 GetConnectionAppArmorSecurityContext ":1.11"
    QWARN : FunctionalTests::testAccountChanges() QDBusConnection: name 'com.ubuntu.OnlineAccounts.Manager' had owner '' but we thought it was ':1.8'
    FAIL! : FunctionalTests::testAccountChanges() Compared values are not the same
       Actual (accountInfo.data()) : {"authMethod":0,"changeType":2,"displayName":"New account","serviceId":"com.ubuntu.tests_coolshare"}
       Expected (expectedAccountInfo): {"authMethod":0,"changeType":0,"displayName":"New account","serviceId":"com.ubuntu.tests_coolshare"}
       Loc: [/«BUILDDIR»/online-accounts-api-0.1+15.04.20160719/tests/daemon/functional_tests/functional_tests.cpp(550)]

Second was yakkety arm64: https://launchpadlibrarian.net/273879816/buildlog_ubuntu-yakkety-arm64.online-accounts-api_0.1+16.10.20160719-0ubuntu1_BUILDING.txt.gz

    1468915517.823 GetConnectionAppArmorSecurityContext ":1.11"
    QWARN : FunctionalTests::testAccountChanges() QDBusConnection: name 'com.ubuntu.OnlineAccounts.Manager' had owner '' but we thought it was ':1.8'
    FAIL! : FunctionalTests::testAccountChanges() Compared values are not the same
       Actual (((accountChanged.count()))): 0
       Expected (1) : 1
       Loc: [/«BUILDDIR»/online-accounts-api-0.1+16.10.20160719/tests/daemon/functional_tests/functional_tests.cpp(561)]

Both look consistent with this being related to the "exit on idle" code. As discussed on IRC, it might be best to run the majority of tests with the exit on idle behaviour disabled, and have have one test with it enabled that is explicitly testing the behaviour.

[Alberto Mardegan (mardy)]

I'm trying to fix this as discussed in IRC, that is respawning the D-Bus test connection (and related mock services) at every test, and having a longer timeout.

However I'm getting a crash when calling startServices():

http://paste.ubuntu.com/20160205/

The crash seems to happen after one Accounts::Manager object has been created, and must be related to D-Bus: if I comment out all "new Accounts::Manager()" from the tests or if I add the Accounts::Manager::DisableNotifications option to the Accounts::Manager constructor (which effectively disables any usage of D-Bus in the library), I don't get any crash when invoking startServices() in later tests.

I'm still trying to understand why this happens. Note that libaccounts-qt doesn't use D-Bus itself: it wraps libaccounts-glib, which calls

  g_bus_get_sync (G_BUS_TYPE_SESSION, NULL, &error_int);

This must return the right thing, as the testAccountChanges() test works fine itself -- it just causes any startServices() invoked afterwards to fail.

Will continue investigating...

[Alberto Mardegan (mardy)]

For the record, I've found the cause of the issue I wrote about in comment 4: the Accounts::Manager object was not being deleted at the end of the test. Given that the D-Bus connection was being torn down, there probably was some GLib event about that left in the mainloop, which was processed only when the next startServices() was called. Deleting the Accounts::Manager fixed the problem.

[Launchpad Janitor (janitor)]

This bug was fixed in the package online-accounts-api - 0.1+16.10.20160722.4-0ubuntu1

---------------
online-accounts-api (0.1+16.10.20160722.4-0ubuntu1) yakkety; urgency=medium

  [ Alberto Mardegan ]
  * Tests: keep the service alive while running the test (LP: #1603706)
  * Enable coverage reporting for the OnlineAccountsDaemon library

  [ James Henstridge ]
  * Add a constructor for OnlineAccounts::Manager that takes a custom D-
    Bus connection. (LP: #1602153)
  * Expose all serviceIds for each account rather than ignoring all but
    the first. (LP: #1602159)

 -- Michi Henning <email address hidden> Fri, 22 Jul 2016 05:09:23 +0000