Push notifications are not delivered to IOS app #21120

pavloburykh · 2024-08-23T08:56:18Z

Reproducing on IOS 17.5.1, iPhone 15

Preconditions: User A - message sender (any device), User B - PN receiver, IOS device

Steps:

User B enables PN notifications
User B backgrounds app
User A sends messages to any common chat with User B (1-1, group, community channel)
See if User B received PN about new message

Actual result: PN is not received by User B

Andr_PN_sender.zip
IOS_PN_receiver.zip

PNs_IOS.mp4

Additional Information

Status version: release 2.30
Operating System: iOS

pavloburykh · 2024-08-23T09:17:55Z

UPDATE: sometimes PNs go through. @mariia-skrypnyk and @churik were able to receive some PNs.

cammellos · 2024-08-23T12:04:54Z

I have investigated the issue:

What looks like, in at least one instance:

The device was correctly registered with the push notification server
The sender, queried the push notification server for informations, via lightpush. The message made it to the server
The server replied to the message
The reply was never received by the sender, therefore the push notification wasn't sent

Looking at kibana's logs, I can see that no filter node has pushed that message to the right client:

https://kibana.infra.status.im/app/discover#/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-15h,to:now))&_a=(columns:!(),filters:!(),index:ffcc22b0-0116-11ed-9719-cdd3b483481c,interval:auto,query:(language:kuery,query:'%220x9f5d30ee6c008d365e20014c749bf3194d960467edaa71f89880721abf635180%22%20AND%20kv_raw:filter'),sort:!(!('@timestamp',desc)))

This is the missing message. The peer id of the sender is "16U*hhQfss"

You can see a couple of minutes later, a successful push:

https://kibana.infra.status.im/app/discover#/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-15h,to:now))&_a=(columns:!(),filters:!(),index:ffcc22b0-0116-11ed-9719-cdd3b483481c,interval:auto,query:(language:kuery,query:'%220x34304e1a4764bb92c5ccfec8e59a56e85b99651fb70d88c956799d2a5103a139%22%20and%20kv_raw:filter'),sort:!(!('@timestamp',desc)))

But now looking at the client log, it looks like they never registered for that particular topic, so i'll start from scratch investigating.

cammellos · 2024-08-23T12:15:39Z

DEBUG[08-23|10:46:10.968|github.com/status-im/status-go/protocol/pushnotificationclient/client.go:810]                                       checking if querying necessary 
DEBUG[08-23|10:46:10.968|github.com/status-im/status-go/protocol/pushnotificationclient/client.go:815]                                       querying info 
DEBUG[08-23|10:46:10.989|github.com/status-im/status-go/wakuv2/common/filter.go:108]                                                         filters install                          id=3867b9e1d9cd67826de7426adbafac0aa6d9ec80374057c478ee92f35971477f
DEBUG[08-23|10:46:10.989|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:111]         adding filter                            filter-id=3867b9e1d9cd67826de7426adbafac0aa6d9ec80374057c478ee92f35971477f
DEBUG[08-23|10:46:10.989|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:124]         existing pubsubTopic batch               agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 topic=/waku/2/rs/16/32
DEBUG[08-23|10:46:10.989|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:145]         adding to existing pubsubTopic batch     agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 content-filter="{ pubsubTopic: /waku/2/rs/16/32, contentTopics: [ /waku/1/0x25a24866/rfc26 ] }" batch-size=3
DEBUG[08-23|10:46:10.989|github.com/status-im/status-go/protocol/transport/filters_manager.go:441]                                           registering filter for                   namespace=filtersManager chatID=contact-discovery-950 type=partitioned topic=0x25a24866
DEBUG[08-23|10:46:10.991|github.com/status-im/status-go/protocol/common/message_segmentation.go:47]                                          message segmented                        segments=1
DEBUG[08-23|10:46:11.099|github.com/status-im/status-go/wakuv2/common/filter.go:108]                                                         filters install                          id=8a08fc1993745515933e0ec0044e4ac3f8a08933e0da387c3bf5ae82c7d7ead4
DEBUG[08-23|10:46:11.099|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:111]         adding filter                            filter-id=8a08fc1993745515933e0ec0044e4ac3f8a08933e0da387c3bf5ae82c7d7ead4
DEBUG[08-23|10:46:11.099|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:124]         existing pubsubTopic batch               agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 topic=/waku/2/rs/16/32
DEBUG[08-23|10:46:11.099|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/filter/filter_manager.go:145]         adding to existing pubsubTopic batch     agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 content-filter="{ pubsubTopic: /waku/2/rs/16/32, contentTopics: [ /waku/1/0x815b41c6/rfc26 ] }" batch-size=4
DEBUG[08-23|10:46:11.099|github.com/status-im/status-go/protocol/transport/filters_manager.go:574]                                           registering filter for                   namespace=filtersManager chatID=95d7f2cdb31b8b1abbdd528aaf97d3a9c7a5285b1a184e6ff5d1a52a7b6e7b9889b38d120795e068ead5f5c27389f9696ec09ce06f1765bafd211e065ca37ce4 type=public ContentTopic=0x815b41c6 PubsubTopic=
DEBUG[08-23|10:46:11.100|github.com/status-im/status-go/protocol/common/message_sender.go:805]                                               sent-message: public message             recipient=[] messageID=0x17b3a4d64ebe9f38f5eb7fe8272feb1018d8c3ba5f63089f88b8974fe02c021b contentType=PUSH_NOTIFICATION_QUERY messageType=public hashes=[0xf7bbddd9f231f2601012b95ccc939b7dae76f5c2a5747da50c51f006588e7ca0]
DEBUG[08-23|10:46:11.100|github.com/status-im/status-go/wakuv2/common/filter.go:249]                                                         processing message: decrypted            envelopeHash=0xf7bbddd9f231f2601012b95ccc939b7dae76f5c2a5747da50c51f006588e7ca0
INFO [08-23|10:46:11.100|github.com/status-im/status-go/vendor/github.com/waku-org/go-waku/waku/v2/api/publish/message_sender.go:115]        publishing message via lightpush         envelopeHash=0xf7bbddd9f231f2601012b95ccc939b7dae76f5c2a5747da50c51f006588e7ca0 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x815b41c6/rfc26 timestamp=1,724,409,971,099,899,579

Looking at this message now:

HASH=0xf7bbddd9f231f2601012b95ccc939b7dae76f5c2a5747da50c51f006588e7ca0
CONTENT_TOPIC=/waku/1/0x815b41c6/rfc26

The message was received by a push notification server:

https://kibana.infra.status.im/app/discover#/context/ffcc22b0-0116-11ed-9719-cdd3b483481c/C9HXfpEBaE8Vq-sg_ypD?_g=(filters:!())&_a=(columns:!(),filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:ffcc22b0-0116-11ed-9719-cdd3b483481c,key:logsource,negate:!f,params:(query:node-01.do-ams3.notify.prod),type:phrase),query:(match_phrase:(logsource:node-01.do-ams3.notify.prod)))),predecessorCount:10,successorCount:5)

cammellos · 2024-08-23T12:49:40Z

The response, was sent:

 INFO [08-23|10:46:10.404|github.com/status-im/status-go/wakuv2/waku.go:1016] publishing message via relay envelopeHash=0xbbd9ab3762e6cee821a5dddbf240018e43d96c4ed8786c44b519bcc9ac19b408 pubsubTopic=/waku/2/rs/16/32 contentTopic=/waku/1/0x25a24866/rfc26 timestamp=1,724,409,970,404,010,117 peerCnt=15

Notice the time:

10:46:10.404

And the content topic:

/0x25a24866

If we go back to the client:

10:46:10.989  adding to existing pubsubTopic batch     agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 content-filter="{ pubsubTopic: /waku/2/rs/16/32, contentTopics: [ /waku/1/0x25a24866/rfc26 ] }" batch-size=3
10:46:10.989 registering filter for                   namespace=filtersManager chatID=contact-discovery-950 type=partitioned topic=0x25a24866

That's when we register the filter.

10:46:12.569      ticker hit, hence subscribing            agg-filter-id=dcd3c805-b342-46be-a406-ebc445802ae1 batch-size=4 agg-content-filter="{ pubsubTopic: /waku/2/rs/16/32, contentTopics: [ /waku/1/0x7bcb873b/rfc26/waku/1/0xbd4cfa16/rfc26/waku/1/0x25a24866/rfc26/waku/1/0x815b41c6/rfc26 ] }"

But then 2 seconds later it's actually tried to register

10:46:12.889subscription successful                  pubSubTopic=/waku/2/rs/16/32 contentTopics="[/waku/1/0x7bcb873b/rfc26 /waku/1/0xbd4cfa16/rfc26 /waku/1/0x25a24866/rfc26 /waku/1/0x815b41c6/rfc26]" peer=16Uiu2HAmMhsfGvYqkAryRe8WZnKHJUhKRbni7hseGpRy174hRaZv

So the timeline is:

Client schedule registering filter on content topic A
Client pubilshes message
Server receives message and replies on content topic A
Client actually registers the filter on content topic A

Message would be received between 3 & 4, but filter is not pushed as the client hasn't yet register the filter.

You can see similar examples from the logs, where we query store nodes just after scheduling register a filter, but we receive messages too early.

status-im/status-go#5440 introduced the ticker.

Before the issue was probably already present (registering a filter was probably asynchronous, although I think on v1 it was sync), but most likely was never picked up as the window was smaller.

Potential solutions:

we mitigate but reducing the timing, but the window would still be present
we delay the sending until the filter is registered, that would add a concept of dependency to sending a message (i.e sending message X depends on having registered message Y)
we refetch from store node once a new filter is subscribed, for the period between scheduling the filter and once the filter has been actually registered, with some padding of course to accomoddate the timing. (there's still a window where the message would not be on the store node, nor the message has been pushed by the filter though).

Either ways, this looks like a fairly critical message reliability issue, lowering the batch ticker (it's currently I believe 5 seconds, which is quite high) is probably the quickest to lower the possibility of that happening.

cc @churik @fryorcraken @chaitanyaprem @richard-ramos @ilmotta and thank you @pavloburykh for all the logs

richard-ramos · 2024-08-23T13:34:06Z

As a way to not block release, I'd say that we can reduce the ticker length to a length which fast enough to make this issue potentially not happen (maybe something like 500ms or less?).

Then we can try work out a proper solution. @chaitanyaprem and I had talked before about this possible window on which messages would not be received due to the ticker and doing the storenode request could be a good solution indeed, taking into account that there might be a delay for the message to arrive to the storenode.

Nwaku storenodes will only accept messages with a timestamp +-20s its current time, so based on this, when we register a filter and the ticker is triggered, we asynchronously wait 20s, and then send a store request. What do you think, @cammellos and @chaitanyaprem?

churik · 2024-08-26T13:33:46Z

Improved in status-im/status-go@4a18c85 as a temp measure; the issue requires more investigation / actions, so postponed to 2.31

chaitanyaprem · 2024-09-02T11:48:14Z

Nwaku storenodes will only accept messages with a timestamp +-20s its current time, so based on this, when we register a filter and the ticker is triggered, we asynchronously wait 20s, and then send a store request. What do you think, @cammellos and @chaitanyaprem?

I am wondering if doing a store query after 20secs would help, because current missing messages periodic store query anyways happens every 20seconds. Which means anyways worst-case these messages would be fetched in next store query isn't it (unless i am missing something)?

pavloburykh · 2024-09-19T14:30:05Z

Issue is still valid for me. @status-im/mobile could you please also re-check if you are receiving push notifications on IOS?

VolodLytvynenko · 2024-09-19T14:35:56Z

still valid. No pushes on IOS.

Devices:

iPhone 11 Pro Max, IOS 17

mariia-skrypnyk · 2024-09-19T14:35:59Z

@pavloburykh checked on 19/09 nightly on iOS - no PN .

iPhone 13, iOS 17

churik · 2024-09-19T14:45:01Z

I still have notifications working on release 2.30 and in PRs (enabled from profile - and from onboarding)

IPhone 14 Pro, IOS 17.6.1

chaitanyaprem · 2024-09-20T06:25:17Z

referring issue being tracked for go-waku waku-org/go-waku#1211
we thought after reducing the ticker the issue has not happened.

but looks like the fix has not been propagated correctly it into the develop branch which is why push notifications must be failing. let me create a PR with fix pushed to develop branch as well and we can verify the same.

This is why @churik is not facing any issues as she is testing on 2.30 whereas others might be testing on develop branch.

chaitanyaprem · 2024-09-20T07:39:12Z

pushed a fix in #21297

@pavloburykh @churik can you please get this revalidated and confirm if the issue still happens.

86doteth · 2024-09-24T17:23:45Z

i havent gotten any push notification in 2.30 release. tested it just now in dms nothing arrives. iphone xs @chaitanyaprem @churik

edit: its worse actually. after 5 hours decided to open the mobile app and then had to wait for about 3-4 minutes before any new messages appeared inside the app including the DM i sent from another account. unfortunately this is how its been for the past months: to just load any new messages i need to wait for multiple minutes upon opening the app every time. there doesnt seem to be any prioritization either i can wait just as long for any dm to appear as i can for any random channel in a community having unread messages. i hope there are issues addressing these loading times bc i just have status inu status and like 3 sparse dm chats

churik · 2024-09-25T09:47:02Z

@ilmotta
I believe this is related to the changes in login process, but frankly I'm not sure how we should log and track such performance issues.
If user has several communities / 1-1 chats / group chats that indeed might lead to some delay after login in starting fetching messages, and afaik we're aware of that.
Should I log this separately?

ilmotta · 2024-09-25T16:53:07Z

I believe this is related to the #20729

Could be, but I don't see how at the moment. If we could reproduce this issue reliably it would be pretty easy to create a new build to login in the old way and check if it's related to the issue you mentioned. But basically we just moved one step from the messenger to happen after login, but the time to setup is 100% the same.

But I think what we did in #20173 was a necessary step. We can't mess up the login and onboarding step. Based on past investigation, a big slice of the cost to set-up filters during login is related to the cost of decrypting communities. Assuming many don't want to use communities and chats and might just want to use the wallet or something else, login should happen as fast as possible.

We have a few ways to improve the login:

Optimize the code setting up filters and processing community chats.
Improve UX to take in consideration that, realistically, after a user logs in we can't guarantee chats will be immediately available.

I remember that we still had room left to optimize the way we process community chats. This is the problematic function https://github.com/status-im/status-go/blob/77ef8f1fb7e6ee08b6f09e4e19cf7b4b5f062a16/protocol/messenger.go#L1769

to just load any new messages i need to wait for multiple minutes upon opening the app every time. there doesnt seem to be any prioritization either i can wait just as long for any dm to appear as i can for any random channel in a community having unread messages.

This is a terrible experience @86doteth...

Should I log this separately?

I would say so. The performance problem to initialize the messenger is well known to us, we are just now seeing that it can get worse quickly depending on the type/amount of data the user has.

churik · 2024-09-26T14:49:06Z

I'll try to investigate the timing and report it as a separate performance issue. Basically, the more communities you have, the later you'll start to receive the messages.

And yes, it was not a question of the necessity of changing the login; rather, this problematic function is now handled after login, which gives the impression of a significant delay (to my understanding)

Thank you for reply, @ilmotta

pavloburykh · 2024-10-01T13:42:18Z

@

I'll try to investigate the timing and report it as a separate performance issue. Basically, the more communities you have, the later you'll start to receive the messages.

And yes, it was not a question of the necessity of changing the login; rather, this problematic function is now handled after login, which gives the impression of a significant delay (to my understanding)

Thank you for reply, @ilmotta

@churik I have logged a separate issue here #21358
cc @ilmotta

churik · 2024-10-07T11:55:25Z

we're closing this one as the problem with performance moved here and so far we're receiving IOS push notifications in develop and in release. Will open a new one if it will reproduce again

86doteth · 2024-10-07T13:15:16Z

we're closing this one as the problem with performance moved here and so far we're receiving IOS push notifications in develop and in release. Will open a new one if it will reproduce again

with release i guess you mean 2.31? bc i havent gotten any push notifs on 2.30

churik · 2024-10-07T14:22:41Z

@86doteth I'm not sure if I asked you (can't see from the comments here), but there are some things to consider:

did you upgrade from 1.20.6? If yes, you need to re-enable Push notifications in your profile, it won't work without that (it is known)
please, check if status is allowed app in your Focus settings in the app.

Push notifications were working for me on release 2.30.
Please let me know if the issue persist.

86doteth · 2024-10-07T15:12:01Z

@churik

i upgraded from the testflight to 2.30. before testflight i was on 1.20.6 and removed the old app before installing testflight. and the push notifications have been enabled inside status settings all along.
dont see app specific settings under Focus in ios settings but status does have all push notifications enabled in ios settings.

churik · 2024-10-07T15:24:05Z

@86doteth please, try to re-enable it in Profile, re-login and see if it helps.
Thank you for your patience, and apologies for these workarounds.

86doteth · 2024-10-07T15:42:51Z

@churik
i disabled push notifications in profile then re-enabled it. then force-closed the app. then re-opened the app, logged in, and then left the app. then sent a test message from another account to mobile and 4 mins later havent received any push notification yet (and havent opened the app since)

churik · 2024-10-07T16:16:47Z

reopened it with no-steps, as we're unable to reproduce it.

86doteth · 2024-10-07T16:45:17Z

@churik
maybe more parts of my setup that are useful:

ive sent the test message from another account on desktop
my account is a member of status community+status inu
this account also has at least two other desktop instances on which i logged in in recent weeks (one today even but closed it before doing the test)

pavloburykh added high-prio bug labels Aug 23, 2024

pavloburykh added this to the 2.30.0 Beta milestone Aug 23, 2024

richard-ramos mentioned this issue Aug 23, 2024

chore: reduce filter batch duration to 500ms status-im/status-go#5760

Closed

churik modified the milestones: 2.30.0 Beta, 2.31.0 Beta Aug 26, 2024

This was referenced Aug 26, 2024

fix_: reduce filter loop to 300ms status-im/status-go#5768

Merged

bug: missing messages while doing filter subscription waku-org/go-waku#1211

Open

churik added the re-check label Sep 19, 2024

This was referenced Sep 20, 2024

chore_: take fixes from go-waku status-im/status-go#5861

Open

chore: take status-go fixes for push notifications that is already in 2.30 #21297

Open

pavloburykh mentioned this issue Oct 1, 2024

Chats and message history loading after login takes too much time (30-40 seconds) #21358

Open

churik removed the re-check label Oct 7, 2024

churik closed this as completed Oct 7, 2024

churik reopened this Oct 7, 2024

churik added the no-steps label Oct 7, 2024

ilmotta added the mobile-core label Oct 9, 2024

churik removed this from the 2.31.0 Beta milestone Oct 9, 2024

churik added push-notifications and removed bug labels Oct 9, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Push notifications are not delivered to IOS app #21120

Push notifications are not delivered to IOS app #21120

pavloburykh commented Aug 23, 2024

pavloburykh commented Aug 23, 2024

cammellos commented Aug 23, 2024

cammellos commented Aug 23, 2024

cammellos commented Aug 23, 2024

richard-ramos commented Aug 23, 2024

churik commented Aug 26, 2024

chaitanyaprem commented Sep 2, 2024

pavloburykh commented Sep 19, 2024

VolodLytvynenko commented Sep 19, 2024

mariia-skrypnyk commented Sep 19, 2024 •

edited

Loading

churik commented Sep 19, 2024 •

edited

Loading

chaitanyaprem commented Sep 20, 2024 •

edited

Loading

chaitanyaprem commented Sep 20, 2024

86doteth commented Sep 24, 2024 •

edited

Loading

churik commented Sep 25, 2024

ilmotta commented Sep 25, 2024 •

edited

Loading

churik commented Sep 26, 2024 •

edited

Loading

pavloburykh commented Oct 1, 2024

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024 •

edited

Loading

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024 •

edited

Loading

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024

Push notifications are not delivered to IOS app #21120

Push notifications are not delivered to IOS app #21120

Comments

pavloburykh commented Aug 23, 2024

Additional Information

pavloburykh commented Aug 23, 2024

cammellos commented Aug 23, 2024

cammellos commented Aug 23, 2024

cammellos commented Aug 23, 2024

richard-ramos commented Aug 23, 2024

churik commented Aug 26, 2024

chaitanyaprem commented Sep 2, 2024

pavloburykh commented Sep 19, 2024

VolodLytvynenko commented Sep 19, 2024

Devices:

mariia-skrypnyk commented Sep 19, 2024 • edited Loading

churik commented Sep 19, 2024 • edited Loading

chaitanyaprem commented Sep 20, 2024 • edited Loading

chaitanyaprem commented Sep 20, 2024

86doteth commented Sep 24, 2024 • edited Loading

churik commented Sep 25, 2024

ilmotta commented Sep 25, 2024 • edited Loading

churik commented Sep 26, 2024 • edited Loading

pavloburykh commented Oct 1, 2024

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024 • edited Loading

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024 • edited Loading

churik commented Oct 7, 2024

86doteth commented Oct 7, 2024

mariia-skrypnyk commented Sep 19, 2024 •

edited

Loading

churik commented Sep 19, 2024 •

edited

Loading

chaitanyaprem commented Sep 20, 2024 •

edited

Loading

86doteth commented Sep 24, 2024 •

edited

Loading

ilmotta commented Sep 25, 2024 •

edited

Loading

churik commented Sep 26, 2024 •

edited

Loading

86doteth commented Oct 7, 2024 •

edited

Loading

86doteth commented Oct 7, 2024 •

edited

Loading