Notification received on the phone but the rapns_notifications database still list the notification as not delivered

[ileitch]

Issue by dc85 from Wednesday Jan 29, 2014 at 21:54 GMT
Originally opened as ileitch/rapns#198

---

I am using rapns to notify iOS devices of incoming chat messages when the app on the receiver is off. When the message is sent on the sender phone, I see the push notification pop up, but the database does not update the delivered status.

In rapns log it shows

1477 sent to xxxx (pid:20518)
Connected to feedback.sandbox.push.apple.com:2196 (pid:20518)

but in the database list 1477 delivered as false.

Now if I send a second message or if rapns.push gets called anywhere else in the app, it will send a push notification with this message again which why this is causing me a lot of problems.

The log for this behaviour is

[2014-01-29 16:33:42.545] [INFO] [2014-01-29 16:33:42] [app_name] 1475 sent to 567f512bd87864be86ddb1a5c0096f00fb86db03c29e45c08fbc44bc16d91654 (pid:20518)
[2014-01-29 16:33:43.519] [INFO] [2014-01-29 16:33:43] [app_name] Connected to feedback.sandbox.push.apple.com:2196 (pid:20518)
[2014-01-29 16:33:57.733] [INFO] [2014-01-29 16:33:57] [app_name] Started, 5 handlers. (pid:20515)
[2014-01-29 16:33:57.940] [INFO] [2014-01-29 16:33:57] [app_name] Started, 5 handlers. (pid:20515)
[2014-01-29 16:33:58.361] [INFO] [2014-01-29 16:33:58] [app_name] Connected to gateway.sandbox.push.apple.com:2195 (pid:20515)
[2014-01-29 16:33:58.370] [INFO] [2014-01-29 16:33:58] [app_name] Connected to gateway.sandbox.push.apple.com:2195 (pid:20515)
[2014-01-29 16:33:58.564] [INFO] [2014-01-29 16:33:58] [app_name] 1475 sent to 567f512bd87864be86ddb1a5c0096f00fb86db03c29e45c08fbc44bc16d91654 (pid:20515)
[2014-01-29 16:33:58.577] [INFO] [2014-01-29 16:33:58] [app_name] 1476 sent to 567f512bd87864be86ddb1a5c0096f00fb86db03c29e45c08fbc44bc16d91654 (pid:20515)
[2014-01-29 16:33:59.205] [INFO] [2014-01-29 16:33:59] [app_name] Connected to feedback.sandbox.push.apple.com:2196 (pid:20515)
[2014-01-29 16:40:50.114] [INFO] [2014-01-29 16:40:50] [app_name] Started, 5 handlers. (pid:20518)
[2014-01-29 16:40:50.115] [INFO] [2014-01-29 16:40:50] [app_name] Started, 5 handlers. (pid:20518)
[2014-01-29 16:40:50.709] [INFO] [2014-01-29 16:40:50] [app_name] Connected to gateway.sandbox.push.apple.com:2195 (pid:20518)
[2014-01-29 16:40:50.913] [INFO] [2014-01-29 16:40:50] [app_name] 1476 sent to 567f512bd87864be86ddb1a5c0096f00fb86db03c29e45c08fbc44bc16d91654 (pid:20518)
[2014-01-29 16:40:51.597] [INFO] [2014-01-29 16:40:51] [app_name] Connected to feedback.sandbox.push.apple.com:2196 (pid:20518)
[2014-01-29 16:41:35.677] [INFO] [2014-01-29 16:41:35] [app_name] Started, 5 handlers. (pid:20518)
[2014-01-29 16:41:35.678] [INFO] [2014-01-29 16:41:35] [app_name] Started, 5 handlers. (pid:20518)

Thanks in advance

[dc85]

Hey,

Thanks for investigating this issue.

Some additional information. I noticed when I do large batch of notification pushes, all notifications get out. So this only happens when notifications are sent one by one and maybe in tiny batches.

[ileitch]

What version are you running?

[dc85]

3.4.1

just updated last week to see if fixed this problem

[dc85]

This problem is happening in rpush

id | delivered | delivered_at | failed | type
----+-----------+----------------------------+--------+---------------------------
1 | t | 2014-03-03 09:00:24.374484 | f | Rpush::Apns::Notification
2 | t | 2014-03-03 09:00:24.374484 | f | Rpush::Apns::Notification
3 | t | 2014-03-03 14:13:00.717094 | f | Rpush::Apns::Notification
4 | t | 2014-03-03 14:13:23.328416 | f | Rpush::Apns::Notification
6 | f | | f | Rpush::Apns::Notification
5 | t | 2014-03-03 14:14:10.150115 | f | Rpush::Apns::Notification

Though i have this in my debug log

[2014-03-03 09:14:10.183] [DEBUG] ^[[1m^[[36mSQL (2.5ms)^[[0m ^[[1mUPDATE "rpush_notifications" SET delivered = 't', delivered_at = '2014-03-03 14:14:10.150115' WHERE "rpush_notifications"."id" IN (5, 6)^[[0m (pid:694)

Using postgres

[ileitch]

You're saying notifications 5 &n 6 are still not marked as delivered?

[dc85]

5 is marked as delivered... 6 isn't, it seems like its always the last one in the table that is not.

But I'm not sure how that could have to do with rpush though.

Oh and on the phone I did get both 5 and 6

[ileitch]

I've no clue what could be causing this.

How are you creating notifications? At what point in your app lifecycle?
How are you running rpush? Rpush.push? How frequently?

What version of the pg gem & postgres?

[dc85]

So for the particular part that is very easy to reproduce this is the chat.

Basically the user compose the message, press send, the app searches through a list of recipients that is supposed to get this message, for each one it checks to see what push service they use, if it is APNS they call this method below defined in another model

def self.push_to(service, token, message, session_id, sender, badge)
n = Rpush::Apns::Notification.new
n.app = Rpush::Apns::App.find_by_name("application")
n.device_token = token
n.alert = message
n.badge = badge
n.sound = "default"
n.attributes_for_device = {
  :category => "chat",
  :org_id => sender[:active_org],
  :session_id => session_id,
  :sender_name => sender[:first_name] + " " + sender[:last_name],
  :chat_handle => sender[:chat_handle]
}
n.save!

end

After the previous look is finished, it calls Rpush.push

on the log it looks like

[2014-03-05 09:36:37.899] [DEBUG] ^[[1m^[[36mSQL (2.4ms)^[[0m ^[[1mINSERT INTO "rpush_notifications" ("alert", "app_id", "badge", "created_at", "data", "device_token", "registration_ids", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id"^[[0m ["alert", "Daniel Chen: Hello"], ["app_id", 1], ["badge", 2], ["created_at", Wed, 05 Mar 2014 09:36:37 EST -05:00], ["data", "{"category":"chat","org_id":1,"session_id":1,"sender_name":"Daniel Chen","chat_handle":"xxx"}"], ["device_token", "xxx"], ["registration_ids", nil], ["type", "Rpush::Apns::Notification"], ["updated_at", Wed, 05 Mar 2014 09:36:37 EST -05:00]

Since the session has me and one other user so this is the only insert followed by the rpush call that causes these database query

[2014-03-05 09:36:38.242] [DEBUG] ^[[1m^[[35mRpush::Notification Load (2.5ms)^[[0m SELECT "rpush_notifications".* FROM "rpush_notifications" WHERE (delivered = 'f' AND failed = 'f' AND (deliver_after IS NULL OR deliver_after < '2014-03-05 14:36:38.238624')) AND (app_id IN (1,2)) (pid:7523)
[2014-03-05 09:36:41.410] [DEBUG] ^[[1m^[[36mSQL (41.7ms)^[[0m ^[[1mUPDATE "rpush_notifications" SET delivered = 't', delivered_at = '2014-03-05 14:36:41.258814' WHERE "rpush_notifications"."id" IN (187, 188)^[[0m (pid:7523)

but after this I go to the database again it shows notification id 188 as being not pushed again

id | delivered | delivered_at | failed | failed_at
-----+-----------+----------------------------+--------+----------------------------
188 | f | | f |
187 | t | 2014-03-05 14:36:41.258814 | f |
186 | t | 2014-03-05 14:33:55.845077 | f |

I understand this probably has nothing to do with you but I just thought I'd post here to see if you know anyone else that ran into this

[dc85]

Fixed

Row locking issue on my side

[ileitch]

Cool, glad you figure it out.