Ubuntu Push Notifications

Push notifications never seem to arrive

Bug #1390663 reported by Stuart Langridge
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Canonical System Image
Fix Released
High
Unassigned
Canonical System Image ww05-2015
Ubuntu Push Notifications
Fix Released
Critical
John Lenton
ubuntu-push (Ubuntu RTM)
Fix Released
Undecided
Unassigned

Bug Description

When I send push notifications, they never seem to arrive on my device (the x86 emulator, OS Ubuntu 14.10 (r5) according to System Settings).

I have created a simple QML app which registers for push notifications. Relevant QML is:

    PushClient {
        id: pushClient
        Component.onCompleted: {
            notificationsChanged.connect(function(msgs) {
                console.log("GOT MESSAGES", msgs);
            });
            error.connect(function(err) {
                console.log("GOT ERROR", err);
            });
            getNotifications();
        }
        appId: "org.kryogenix.murmur_murmur"
    }
            Button {
                objectName: "button"
                width: parent.width

                text: i18n.tr("Tap me!")

                onClicked: {
                    console.log("token", pushClient.token, "!");
                }

On clicking the button, I get printed: qml: token BLAHBLAHBLAH== ! as expected.

I have also edited manifest.json:

    "hooks": {
        "murmur": {
            "apparmor": "murmur.apparmor",
            "desktop": "murmur.desktop"
        },
        "murmurHelper": {
            "apparmor": "murmurHelper.apparmor",
            "push-helper": "murmurHelper.json"
        }
    },

and created extra files
murmurHelper.apparmor:
{
    "policy_groups": [
        "push-notification-client"
    ],
    "policy_version": 1.2,
    "template": "ubuntu-push-helper"
}
murmurHelper.json:
{
    "exec": "murmurHelper",
    "app_id": "org.kryogenix.murmur_murmur"
}
and murmurHelper:
#!/usr/bin/python3
import sys
f1, f2 = sys.argv[1:3]
open(f2, "w").write(open(f1).read())

I then try and send a push notification to this device with the following (from my main machine):

curl -d '{"appid":"org.kryogenix.murmur_murmur","token":"BLAHBLAHBLAH==","data":{"message":"mymsg","notification":{"tag":"tag1","card":{"summary":"summ","body":"hi","popup":true,"persist":true,"timestamp":0}}},"expire_on":"2014-11-11T11:11:11.000Z"}' -H "Content-Type: application/json" https://push.ubuntu.com/notify

and this returns the result
{"ok":true}

I believe that, although my helper just passes the input through, I am sending in the correct format from the server and so it should work. No notification arrives, according to the QML app.

To go further, I looked at /home/phablet/.cache/upstart/ubuntu-push-client.log on the device. It shows output when my app starts and attempts to receive any outstanding messages. However, it shows no other output; in particular, I would expect it to show some output when a new message arrives, and it does not. That log looks like the below. So, I think that messages never arrive at the device, because the push client never receives them. How can I proceed?

2014/11/08 01:19:18.052240 DEBUG poking polld.
2014/11/08 01:19:18.052981 DEBUG waiting for polld to signal Done.
2014/11/08 01:19:18.053149 DEBUG polld Done.
2014/11/08 01:19:23.065840 DEBUG requested wakeup at 2014-11-08 01:24:23 +0000 UTC
2014/11/08 01:19:23.067090 DEBUG cleared wakelock cookie 5c5bc5e5-f470-4a32-9ff1-dc91f340db90.
2014/11/08 01:24:20.275830 DEBUG getting authorization for https://push.ubuntu.com/register
2014/11/08 01:24:21.067323 DEBUG WatchMethod: Register(/com/ubuntu/PushNotifications/org_2ekryogenix_2emurmur, []interface {}{"org.kryogenix.murmur_murmur"}, []interface {}{(*service.DBusService)(0x95c87a20)}) success: []string{"LooksLikeAToken=="}
2014/11/08 01:24:21.350463 DEBUG WatchMethod: PopAll(/com/ubuntu/Postal/org_2ekryogenix_2emurmur, []interface {}{"org.kryogenix.murmur_murmur"}, []interface {}{(*service.DBusService)(0x95c882c0)}) success: []string{"[]"}
2014/11/08 01:24:21.505552 DEBUG WatchMethod: PopAll(/com/ubuntu/Postal/org_2ekryogenix_2emurmur, []interface {}{"org.kryogenix.murmur_murmur"}, []interface {}{(*service.DBusService)(0x95c882c0)}) success: []string{"[]"}
2014/11/08 01:24:23.017607 DEBUG got woken up; time is 2014-11-08 01:24:23.017577506 +0000 UTC
2014/11/08 01:24:23.019321 DEBUG got wakelock cookie of 88886d14-79c2-442d-a207-e9d588b221c1
2014/11/08 01:24:23.057149 DEBUG poking polld.
2014/11/08 01:24:23.057749 DEBUG waiting for polld to signal Done.
2014/11/08 01:24:23.057789 DEBUG polld Done.
2014/11/08 01:24:28.068062 DEBUG requested wakeup at 2014-11-08 01:29:28 +0000 UTC
2014/11/08 01:24:28.069016 DEBUG cleared wakelock cookie 88886d14-79c2-442d-a207-e9d588b221c1.
2014/11/08 01:29:28.013458 DEBUG got woken up; time is 2014-11-08 01:29:28.013428177 +0000 UTC
2014/11/08 01:29:28.015106 DEBUG got wakelock cookie of 8c0487c1-a2b3-4e2e-b05a-5819425cb0fc
2014/11/08 01:29:28.052101 DEBUG poking polld.
2014/11/08 01:29:28.052985 DEBUG waiting for polld to signal Done.
2014/11/08 01:29:28.053044 DEBUG polld Done.
2014/11/08 01:29:33.064036 DEBUG requested wakeup at 2014-11-08 01:34:33 +0000 UTC
2014/11/08 01:29:33.064914 DEBUG cleared wakelock cookie 8c0487c1-a2b3-4e2e-b05a-5819425cb0fc.
2014/11/08 01:34:33.017382 DEBUG got woken up; time is 2014-11-08 01:34:33.017309395 +0000 UTC
2014/11/08 01:34:33.021196 DEBUG got wakelock cookie of c8fd9e97-8d41-4eb0-9ce9-68761a001113
2014/11/08 01:34:33.056186 DEBUG poking polld.
2014/11/08 01:34:33.057449 DEBUG waiting for polld to signal Done.
2014/11/08 01:34:33.057538 DEBUG polld Done.
2014/11/08 01:34:38.066430 DEBUG requested wakeup at 2014-11-08 01:39:38 +0000 UTC
2014/11/08 01:34:38.067096 DEBUG cleared wakelock cookie c8fd9e97-8d41-4eb0-9ce9-68761a001113.

Related branches

lp:~chipaca/ubuntu-push/flapping-fixes
Bret Barker (community): Approve
Diff: 674 lines (+139/-87)
23 files modified
bus/connectivity/connectivity.go (+11/-7)
bus/connectivity/connectivity_test.go (+10/-11)
bus/endpoint.go (+6/-6)
bus/networkmanager/networkmanager.go (+6/-6)
bus/notifications/raw.go (+1/-1)
client/client.go (+2/-3)
client/client_test.go (+1/-1)
client/service/service.go (+3/-3)
client/session/session.go (+34/-2)
identifier/identifier.go (+1/-1)
identifier/identifier_test.go (+1/-1)
launch_helper/helper_finder/helper_finder.go (+1/-1)
launch_helper/helper_finder/helper_finder_test.go (+1/-1)
launch_helper/legacy/legacy.go (+1/-1)
launch_helper/legacy/legacy_test.go (+1/-1)
messaging/messaging.go (+1/-1)
testing/helpers.go (+1/-1)
urldispatcher/curldispatcher/curldispatcher.go (+1/-1)
urldispatcher/urldispatcher.go (+2/-2)
urldispatcher/urldispatcher_test.go (+2/-2)
util/redialer.go (+36/-27)
util/redialer_states.gv (+9/-0)
util/redialer_test.go (+7/-7)
Superseded for merging into lp:ubuntu-push
Ubuntu Push Hackers: Pending requested
Diff: 488 lines (+116/-70)
14 files modified
bus/connectivity/connectivity.go (+16/-12)
bus/connectivity/connectivity_test.go (+10/-11)
bus/connectivity/webchecker.go (+4/-4)
bus/endpoint.go (+1/-1)
bus/systemimage/systemimage.go (+1/-1)
client/client.go (+1/-2)
client/service/postal.go (+0/-1)
client/session/session.go (+28/-1)
dependencies.tsv (+1/-1)
launch_helper/kindpool.go (+1/-1)
poller/poller.go (+1/-1)
util/redialer.go (+36/-27)
util/redialer_states.gv (+9/-0)
util/redialer_test.go (+7/-7)
lp:~chipaca/ubuntu-push/fix-1390663-for-rtm
Bret Barker (community): Approve
Diff: 937 lines (+185/-104)
31 files modified
bus/connectivity/connectivity.go (+23/-12)
bus/connectivity/connectivity_test.go (+10/-11)
bus/connectivity/webchecker.go (+4/-4)
bus/endpoint.go (+7/-7)
bus/networkmanager/networkmanager.go (+6/-6)
bus/notifications/raw.go (+1/-1)
bus/systemimage/systemimage.go (+1/-1)
client/client.go (+3/-3)
client/client_test.go (+1/-1)
client/service/postal.go (+0/-1)
client/service/service.go (+3/-3)
client/session/session.go (+38/-2)
dependencies.tsv (+1/-1)
identifier/identifier.go (+1/-1)
identifier/identifier_test.go (+1/-1)
launch_helper/helper_finder/helper_finder.go (+1/-1)
launch_helper/helper_finder/helper_finder_test.go (+1/-1)
launch_helper/kindpool.go (+1/-1)
launch_helper/legacy/legacy.go (+1/-1)
launch_helper/legacy/legacy_test.go (+1/-1)
messaging/messaging.go (+1/-1)
poller/poller.go (+1/-1)
server/acceptance/acceptanceclient.go (+2/-0)
server/acceptance/suites/suite.go (+9/-2)
testing/helpers.go (+1/-1)
ubuntu-push-client.go (+18/-0)
urldispatcher/curldispatcher/curldispatcher.go (+1/-1)
urldispatcher/urldispatcher.go (+2/-2)
urldispatcher/urldispatcher_test.go (+2/-2)
util/redialer.go (+36/-27)
util/redialer_test.go (+7/-7)
Revision history for this message
Stuart Langridge (sil) wrote :

ubuntu-push-client was restarted at approx 02.04.

Revision history for this message
Stuart Langridge (sil) wrote :
Download full text (4.2 KiB)

Relevant search for "dialed in":

$ zgrep "dialed in" /home/phablet/.cache/upstart/ubuntu-push-client.log*
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.717683 INFO "com.ubuntu.PushNotifications" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.743225 INFO "com.ubuntu.Postal" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747241 INFO "com.canonical.Unity.WindowStack" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747383 DEBUG windowstack dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747592 INFO "com.canonical.UnityGreeter" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747718 DEBUG unitygreeter dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747842 INFO "com.canonical.usensord" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.747972 DEBUG haptic dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.748099 INFO "com.canonical.Unity.Launcher" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.748214 DEBUG emblemcounter dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.748330 INFO "org.freedesktop.Notifications" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.748443 DEBUG notifications dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.755832 INFO "org.freedesktop.NetworkManager" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:52.756215 INFO "com.canonical.SystemImage" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:53.435606 INFO "com.ubuntu.AccountPolld" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:53.435627 DEBUG polld dialed in on try 1
/home/phablet/.cache/upstart/ubuntu-push-client.log:2014/11/08 02:03:53.437599 INFO "com.canonical.powerd" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:28.946657 INFO "com.ubuntu.PushNotifications" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:28.948261 INFO "com.ubuntu.Postal" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.022496 INFO "com.canonical.usensord" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.022891 DEBUG haptic dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.023571 INFO "org.freedesktop.Notifications" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.023779 DEBUG notifications dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.023878 INFO "com.canonical.Unity.Launcher" dialed in.
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.023953 DEBUG emblemcounter dialed in
/home/phablet/.cache/upstart/ubuntu-push-client.log.1.gz:2014/11/08 00:28:29.024108 INFO "com.canonical.UnityGreeter"...

Read more...

Revision history for this message
Stuart Langridge (sil) wrote :
Revision history for this message
Stuart Langridge (sil) wrote :
Lucio Torre (lucio.torre)
Changed in ubuntu-push:
importance: Undecided → High
status: New → Confirmed
assignee: nobody → John Lenton (chipaca)
Revision history for this message
John Lenton (chipaca) wrote :

I can reproduce this in the emulator too; the emulator seems to fire network manager state changes at random, faster than push can check for "online"-ness:

2014/11/21 11:43:41.441928 DEBUG got state: Connecting
2014/11/21 11:43:41.613006 DEBUG State changed to Connecting. Assuming disconnect.
2014/11/21 11:43:41.613062 INFO Sending 'disconnected'.
2014/11/21 11:43:41.615175 ERROR session exited: read tcp 91.189.88.31:443: use of closed network connection
2014/11/21 11:43:41.967574 DEBUG got state: Connected Global
2014/11/21 11:43:41.967639 DEBUG State changed to Connected Global. Assuming disconnect.
2014/11/21 11:43:43.984534 DEBUG May be connected; checking...
2014/11/21 11:43:44.125264 INFO Connectivity check passed.
2014/11/21 11:43:44.127468 DEBUG Connection check says: true
2014/11/21 11:43:44.128519 INFO Sending 'connected'.
2014/11/21 11:43:45.419137 DEBUG got state: Connecting
2014/11/21 11:43:45.435692 DEBUG got state: Connected Global
2014/11/21 11:43:45.447396 DEBUG State changed to Connecting. Assuming disconnect.
2014/11/21 11:43:45.448081 INFO Sending 'disconnected'.
2014/11/21 11:43:45.448608 DEBUG State changed to Connected Global. Assuming disconnect.
2014/11/21 11:43:46.024479 DEBUG adding authorization
2014/11/21 11:43:46.024590 DEBUG getting authorization for https://push.ubuntu.com/
2014/11/21 11:43:47.440696 ERROR unable to get the authorization token from the account: exit status 1
2014/11/21 11:43:47.440814 DEBUG trying to connect to: 91.189.88.31:443
2014/11/21 11:43:47.464975 DEBUG May be connected; checking...
2014/11/21 11:43:47.581720 INFO Connectivity check passed.
2014/11/21 11:43:47.586226 DEBUG Connection check says: true
2014/11/21 11:43:47.587671 INFO Sending 'connected'.
2014/11/21 11:43:47.716391 DEBUG Connected 91.189.88.31:443.
2014/11/21 11:43:48.439023 DEBUG got state: Connecting
2014/11/21 11:43:48.440283 DEBUG got state: Connected Global
2014/11/21 11:43:48.440357 DEBUG State changed to Connecting. Assuming disconnect.

Lucio Torre (lucio.torre)
Changed in ubuntu-push:
importance: High → Critical
Revision history for this message
John Lenton (chipaca) wrote :

After much digging, we believe we found the issue.

There's a deadlock in the client/session interface, triggered by network state flapping. While it happens readily on the emulator and almost not at all on mobile, it's a real issue: any situation where the network's state changes quicker than the connection dance takes (which can be several seconds) will likely trigger it.

Setting to critical, and aiming for RTM.

Changed in ubuntu-push:
status: Confirmed → In Progress
Pat McGowan (pat-mcgowan)
Changed in canonical-devices-system-image:
importance: Undecided → High
milestone: none → ww05-2015
status: New → Confirmed
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package ubuntu-push - 0.64.1+15.04.20150122~rtm-0ubuntu1

---------------
ubuntu-push (0.64.1+15.04.20150122~rtm-0ubuntu1) 14.09; urgency=low

  [ John R. Lenton ]
  * Chery pick r140 from trunk to fix lp:1390663 for RTM. (LP: #1390663)
 -- Ubuntu daily release <email address hidden> Thu, 22 Jan 2015 17:56:39 +0000

Changed in ubuntu-push (Ubuntu RTM):
status: New → Fix Released
Pat McGowan (pat-mcgowan)
Changed in canonical-devices-system-image:
status: Confirmed → Fix Released
Samuele Pedroni (pedronis)
Changed in ubuntu-push:
status: In Progress → Fix Committed
Samuele Pedroni (pedronis)
Changed in ubuntu-push:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.