search

tigase / siskin-im

(M) Public Project of Tigase Messenger for iOS devices based on Tigase Swift XMPP library.
GNU General Public License v3.0
173 stars 37 forks source link

Push notifications not working (prosody.im) #184

Open sirrosh opened 2 years ago

sirrosh commented 2 years ago

Describe the bug Push notifications not working, meaning no notifications at all while the app is in the background.

To Reproduce Steps to reproduce the behavior:

  1. Create an account on a current Prosody server
  2. Log into the account on the phone, enable push service, enable all notifications
  3. Start a conversation with another user, lock the phone with power button
  4. Wait for 1 minute and ask your party to write you a message
  5. The phone won't receive this offline message until you wake it up and start the app again

Expected behavior After step 5 you should hear an incoming message notification on a locked phone.

Details


**Additional context**
The moment the phone stop receiving notifications is exactly when the socket closes, after the "Connection closed" log message in Prosody.
Both incoming and outgoing s2s connections to the push server are active:

| <- push.tigase.im [s2sin55b2e902df50] (authenticated) (encrypted) | -> push.tigase.im [s2sout55b2e9a6fa70] (authenticated) (encrypted)

Outgoing connection establishing:

May 18 12:28:41 s2sout55b2e9a6fa70 debug First attempt to connect to push.tigase.im, starting with SRV lookup... May 18 12:28:41 s2sout55b2e9a6fa70 debug push.tigase.im has SRV records, handling... May 18 12:28:41 s2sout55b2e9a6fa70 debug Best record found, will connect to tigase.me.:5269 May 18 12:28:41 s2sout55b2e9a6fa70 debug DNS reply for tigase.me. gives us 52.38.60.72 May 18 12:28:41 s2sout55b2e9a6fa70 debug DNS reply for tigase.me. gives us 35.80.215.249 May 18 12:28:41 s2sout55b2e9a6fa70 debug DNS reply for tigase.me. gives us 34.213.114.115 May 18 12:28:41 s2sout55b2e9a6fa70 debug Beginning new connection attempt to push.tigase.im ([52.38.60.72]:5269) May 18 12:28:41 s2sout55b2e9a6fa70 debug Connection attempt in progress... May 18 12:28:41 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: <?xml version='1.0'?> May 18 12:28:41 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: May 18 12:28:41 s2sout55b2e9a6fa70 debug Received[s2sout_unauthed]: May 18 12:28:41 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: May 18 12:28:41 s2sout55b2e9a6fa70 debug Received[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending stream header... May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: <?xml version='1.0'?> May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 info Stream encrypted (TLSv1.3 with TLS_AES_256_GCM_SHA384) May 18 12:28:42 s2sout55b2e9a6fa70 debug certificate chain validation result: valid May 18 12:28:42 s2sout55b2e9a6fa70 debug certificate identity validation result: valid May 18 12:28:42 s2sout55b2e9a6fa70 debug Received[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 debug Received[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: <?xml version='1.0'?> May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout_unauthed]: May 18 12:28:42 s2sout55b2e9a6fa70 debug connection tcpower.eu->push.tigase.im is now authenticated for push.tigase.im May 18 12:28:42 s2sout55b2e9a6fa70 debug Received[s2sout]: May 18 12:28:42 s2sout55b2e9a6fa70 info Outgoing s2s connection tcpower.eu->push.tigase.im complete

As well as the incoming:

May 18 12:28:46 s2sin55b2e902df50 debug Incoming s2s connection May 18 12:28:46 s2sin55b2e902df50 debug Incoming s2s received May 18 12:28:46 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: <?xml version='1.0'?> May 18 12:28:46 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:46 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:46 s2sin55b2e902df50 debug Received[s2sin_unauthed]: May 18 12:28:46 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:46 s2sin55b2e902df50 debug TLS negotiation started for s2sin_unauthed... May 18 12:28:47 s2sin55b2e902df50 info Stream encrypted (TLSv1.3 with TLS_AES_256_GCM_SHA384) May 18 12:28:47 s2sin55b2e902df50 debug Incoming s2s received May 18 12:28:47 s2sin55b2e902df50 debug certificate chain validation result: valid May 18 12:28:47 s2sin55b2e902df50 debug certificate identity validation result: valid May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: <?xml version='1.0'?> May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:47 s2sin55b2e902df50 debug Received[s2sin_unauthed]: May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin_unauthed]: May 18 12:28:47 s2sin55b2e902df50 debug connection push.tigase.im->tcpower.eu is now authenticated for push.tigase.im May 18 12:28:47 s2sin55b2e902df50 info Incoming s2s connection push.tigase.im->tcpower.eu complete


An offline stanza is being sent to the tigase push server:

May 18 12:28:42 s2sout55b2e9a6fa70 debug sending 1 queued stanzas across new outgoing connection to push.tigase.im May 18 12:28:42 s2sout55b2e9a6fa70 debug Sending[s2sout]: 

after a while the server replies:

May 18 12:28:47 s2sin55b2e902df50 debug Incoming s2s received May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin]: <?xml version='1.0'?> May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin]: May 18 12:28:47 s2sin55b2e902df50 debug Sending[s2sin]: May 18 12:28:47 s2sin55b2e902df50 debug Received[s2sin]: 



**But nothing appears on the iphone's screen...**
licaon-kter commented 2 years ago

Do you ask here first for the latest push setup advice for iOS compat: xmpp:prosody@conference.prosody.im?join

sirrosh commented 2 years ago

Do you ask here first for the latest push setup advice for iOS compat:

Latest? For how long the documented way is obsolete?

It's clearly seen from the above that the stanza's being sent to the push.tigase.im and it even ack's it. But nothing arrives on the phone. Anything else the im server can do?

hantu85 commented 2 years ago

This outgoing stanza looks like a stanza used to register for push notifications at our push component and not the actual stanza with push notification (it is sent from a full JID, instead of bare JID or even just a domain name which is used for sending push notifications and its id is UUID which is used for generation of ids by SiskinIM and not used by Prosody for push notifications AFAIK)

https://hg.prosody.im/prosody-modules/file/fe5303da99cb/mod_cloud_notify/mod_cloud_notify.lua#l341

sirrosh commented 2 years ago

You're right, that UUID confirms it.

sirrosh commented 2 years ago

There are however "Invoking cloud handle_notify_request() for offline stanza":

May 18 12:31:07 tcpower.eu:mam  debug   Archiving stanza: <message id='83933E42-56F0-4559-B9D3-E99AC25DD356' type='chat' to='alice@tcpower.eu' from='bob@tcpower.eu/kd4ajdoz'>
May 18 12:31:07 tcpower.eu:cloud_notify debug   Invoking cloud handle_notify_request() for offline stanza

P.S.: It's a freakin' nightmare debugging on a live server...

hantu85 commented 2 years ago

Could you check if in your case Prosody is conffigured to send last-message-body? I do recall issues when this was not sent (even no dummuy body) as in this case those notifications are marked as "non important" and may be dropped by Apple Push Notification Services.

If possible, I would recommend if possible and available, enabling this module https://hg.prosody.im/prosody-modules/file/tip/mod_cloud_notify_encrypted/mod_cloud_notify_encrypted.lua as it has support for sending encrypted push notifications over APNS and it is supported by SiskinIM (I'm not sure whether it is enabled on your installation or not).

licaon-kter commented 2 years ago

Latest? For how long the documented way is obsolete?

I only know from random chats that for Snikket iOS some prosody stuff for better push was developed.

@mwild1 Ping

sirrosh commented 2 years ago

Could you check if in your case Prosody is conffigured to send last-message-body? I do recall issues when this was not sent (even no dummuy body) as in this case those notifications are marked as "non important" and may be dropped by Apple Push Notification Services.

The inclusion of a last-message-body is regulated by the push_notification_with_body parameter, tried both variants with no effect. Here's a lua code:

-- configuration
local include_body = module:get_option_boolean("push_notification_with_body", false);
local include_sender = module:get_option_boolean("push_notification_with_sender", false);
local max_push_errors = module:get_option_number("push_max_errors", 16);
local max_push_devices = module:get_option_number("push_max_devices", 5);
local dummy_body = module:get_option_string("push_notification_important_body", "New Message!");
...

local function handle_notify_request(stanza, node, user_push_services, log_push_decline)
...
if stanza and include_sender then
                form_data["last-message-sender"] = stanza.attr.from;
        end
            if stanza and include_body then
                form_data["last-message-body"] = stanza:get_child_text("body");
            elseif stanza and dummy_body and is_important(stanza) then
                form_data["last-message-body"] = tostring(dummy_body);
            end

Another good question is how to make a stanza important if your statement is true? There are some hardcoded workarounds, may be Tigase also needs one?

If possible, I would recommend if possible and available, enabling this module https://hg.prosody.im/prosody-modules/file/tip/mod_cloud_notify_encrypted/mod_cloud_notify_encrypted.lua as it has support for sending encrypted push notifications over APNS and it is supported by SiskinIM (I'm not sure whether it is enabled on your installation or not).

As I said cloud_notify_extensions is enabled and this is a wrapper for all (three) notify extension modules, including this one:

module:depends("cloud_notify_encrypted");
module:depends("cloud_notify_priority_tag");
module:depends("cloud_notify_filters");
sirrosh commented 2 years ago

Latest? For how long the documented way is obsolete?

I only know from random chats that for Snikket iOS some prosody stuff for better push was developed.

Thank you, will check on it.

sirrosh commented 2 years ago

I only know from random chats that for Snikket iOS some prosody stuff for better push was developed.

For Snikket it's all the same, no notifications whatsoever. It has two small lua modules, tried them with no luck. Seeing Invoking cloud handle_notify_request() for offline stanza but then no Sending %s push notification for %s@%s to %s (%s)...

hantu85 commented 2 years ago

In this case, would you be able to catch the full XML stanza of the message which is not triggering a push notification? Maybe with that and the example Prosody configuration of your installation we would be able to find out why no push notification is being triggered.

mwild1 commented 2 years ago

@sirrosh Also, be sure you have lua-ossl installed, as per https://modules.prosody.im/mod_cloud_notify_encrypted

sirrosh commented 2 years ago

@sirrosh Also, be sure you have lua-ossl installed, as per https://modules.prosody.im/mod_cloud_notify_encrypted

Yes it is, otherwise mod_cloud_notify_encrypted throws an error on loading. Is there a way to check the "sanity" of a luaossl somehow?

sirrosh commented 2 years ago

In this case, would you be able to catch the full XML stanza of the message which is not triggering a push notification? Maybe with that and the example Prosody configuration of your installation we would be able to find out why no push notification is being triggered.

Would appreciate your help on how to do it ;)

As I said the Invoking cloud handle_notify_request() for offline stanza is clearly seen but Sending %s push notification for %s@%s to %s (%s) doesn't follow.

hantu85 commented 2 years ago

@sirrosh Maybe @mwild1 will be able to help you. I'm not a prosody developer or user.

sirrosh commented 2 years ago

In this case, would you be able to catch the full XML stanza of the message which is not triggering a push notification? Maybe with that and the example Prosody configuration of your installation we would be able to find out why no push notification is being triggered.

Continuing deeper into the mod_cloud_notify. This is an example of a notification subscription stanza for push.tigase.im, does it look ok?

May 20 13:22:55 c2s56111e6323f0 info    Attempting to enable push notifications
May 20 13:22:55 c2s56111e6323f0 info    No publish options in request
May 20 13:22:55 c2s56111e6323f0 info    Push notifications enabled for bob@tcpower.eu/iPhone (push.tigase.im<01#36749B8A3321876356DB71AFD4B5EC04C875E3200F12070B0AB4D7B11551188C)
May 20 13:22:55 c2s56111e6323f0 info    STANZA: <iq id='4E462E75-CEFB-4983-BC40-E9E83837971A' type='set' from='bob@tcpower.eu/iPhone'><enable jid='push.tigase.im' node='01#36749B8A3321876356DB71AFD4B5EC04C875E3200F12070B0AB4D7B11551188C' xmlns='urn:xmpp:push:0'><groupchat xmlns='tigase:push:filter:groupchat:0'/><priority xmlns='tigase:push:priority:0'/><encrypt alg='aes-128-gcm' max-size='3072' xmlns='tigase:push:encrypt:0'>pdqpDgUGNIcT9aRiXdQLsA==</encrypt><jingle xmlns='tigase:push:jingle:0'/></enable></iq>

This is how other (non-tigase) cloud_notify event and push stanza look:

May 20 13:29:29 c2s56111ae9b5d0 info    Invoking cloud handle_notify_request() for newly smacks queued stanzas (now in timer)
May 20 13:29:29 c2s56111ae9b5d0 info    Invoking cloud handle_notify_request() for smacks queued stanza: 1
May 20 13:29:29 tcpower.eu:cloud_notify info    Sending unimportant push notification for joe@tcpower.eu to p2.siacs.eu (9IKm1YIgBofR)
May 20 13:29:29 tcpower.eu:cloud_notify info    PUSH STANZA: <iq id='adb27750f405a01941ddb886102632dc62f88232af6e9a9f4e52b29b60cd3022' type='set' to='p2.siacs.eu' from='tcpower.eu'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='9IKm1YIgBofR'><item><notification xmlns='urn:xmpp:push:0'><x type='form' xmlns='jabber:x:data'><field type='hidden' var='FORM_TYPE'><value>urn:xmpp:push:summary</value></field><field type='text-single' var='message-count'><value>1</value></field><field type='text-single' var='pending-subscription-count'/><field type='jid-single' var='last-message-sender'><value>joe@tcpower.eu</value></field><field type='text-single' var='last-message-body'/></x></notification></item></publish><publish-options><x type='submit' xmlns='jabber:x:data'><field type='hidden' var='FORM_TYPE'><value>http://jabber.org/protocol/pubsub#publish-options</value></field><field var='secret'><value>4lLCWe1fygdbm+29ULys9PXd</value></field></x></publish-options></pubsub></iq>
May 20 13:29:29 c2s56111ae9b5d0 info    Cloud handle_notify_request() > 0, not notifying for other push queued stanzas of type unimportant

But for the tigase push client it's only: May 20 13:30:31 tcpower.eu:cloud_notify info Invoking cloud handle_notify_request() for offline stanza and here it stops. Waddaheck is going on???

licaon-kter commented 2 years ago

Pretty please join the Prosody support MUC so they can help you.