Notification received on the phone but the rapns_notifications database still list the notification as not delivered about rpush HOT 10 CLOSED

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.

from rpush.

What version are you running?

from rpush.

3.4.1

just updated last week to see if fixed this problem

from rpush.

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

from rpush.

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

from rpush.

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

from rpush.

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?

from rpush.

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

from rpush.

Fixed

Row locking issue on my side

from rpush.

Cool, glad you figure it out.

from rpush.