Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
siskin-im
Code
Pull Requests
Issues
List
Boards
Iterations
Builds
Statistics
Child Projects
OneDev 11.5.2
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _clients siskin-im Issues #554
Push notifications not working (prosody.im) (#554)
Unknown opened 3 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

  • Siskin Version: 7.1
  • iOS version: 15.4
  • iPhone model: iPhone 7
  • Prosody: 0.11.13 (modules cloud_notify and cloud_notify_extensions are loaded)
> require"core.modulemanager".is_loaded("tcpower.eu", "cloud_notify")
| Result: true
> require"core.modulemanager".is_loaded("tcpower.eu", "cloud_notify_extensions")
| Result: true

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]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
May 18 12:28:41 s2sout55b2e9a6fa70      debug   Received[s2sout_unauthed]: <features xmlns='http://etherx.jabber.org/streams'>
May 18 12:28:41 s2sout55b2e9a6fa70      debug   Sending[s2sout_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
May 18 12:28:41 s2sout55b2e9a6fa70      debug   Received[s2sout_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
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]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
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]: <features xmlns='http://etherx.jabber.org/streams'>
May 18 12:28:42 s2sout55b2e9a6fa70      debug   Sending[s2sout_unauthed]: <auth mechanism='EXTERNAL' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
May 18 12:28:42 s2sout55b2e9a6fa70      debug   Received[s2sout_unauthed]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
May 18 12:28:42 s2sout55b2e9a6fa70      debug   Sending[s2sout_unauthed]: <?xml version='1.0'?>
May 18 12:28:42 s2sout55b2e9a6fa70      debug   Sending[s2sout_unauthed]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
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]: <features xmlns='http://etherx.jabber.org/streams'>
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 <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='tcpower.eu' from='push.tigase.im'>
May 18 12:28:46 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <?xml version='1.0'?>
May 18 12:28:46 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' id='fc5cb4cf-2533-42de-aaff-2da453b3f697' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
May 18 12:28:46 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <stream:features>
May 18 12:28:46 s2sin55b2e902df50       debug   Received[s2sin_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
May 18 12:28:46 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
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 <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='tcpower.eu' from='push.tigase.im'>
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]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' id='1f4df87e-798f-40a3-91bb-aef85155dfb7' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
May 18 12:28:47 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <stream:features>
May 18 12:28:47 s2sin55b2e902df50       debug   Received[s2sin_unauthed]: <auth mechanism='EXTERNAL' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
May 18 12:28:47 s2sin55b2e902df50       debug   Sending[s2sin_unauthed]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
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]: <iq type='set' to='push.tigase.im' from='alice@tcpower.eu/iPhone' id='511A4D4A-EF51-4E53-B6F5-3843B2B36A43'>

after a while the server replies:

May 18 12:28:47 s2sin55b2e902df50       debug   Incoming s2s received <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='tcpower.eu' from='push.tigase.im'>
May 18 12:28:47 s2sin55b2e902df50       debug   Sending[s2sin]: <?xml version='1.0'?>
May 18 12:28:47 s2sin55b2e902df50       debug   Sending[s2sin]: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='tcpower.eu' id='c3ab5870-f56e-4117-86d8-c6e2d4f3d9c9' to='push.tigase.im' version='1.0' xmlns='jabber:server'>
May 18 12:28:47 s2sin55b2e902df50       debug   Sending[s2sin]: <stream:features>
May 18 12:28:47 s2sin55b2e902df50       debug   Received[s2sin]: <iq id='511A4D4A-EF51-4E53-B6F5-3843B2B36A43' type='result' to='alice@tcpower.eu/iPhone' from='push.tigase.im'>

But nothing appears on the iphone's screen...
Unknown commented 3 years ago

Do you ask here first for the latest push setup advice for iOS compat: xmpp:prosody@conference.prosody.im?join
Unknown commented 3 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?
Unknown commented 3 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
Unknown commented 3 years ago

You're right, that UUID confirms it.
Unknown commented 3 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...
Unknown commented 3 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).
Unknown commented 3 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
Unknown commented 3 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");
Unknown commented 3 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.
Unknown commented 3 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)...
Unknown commented 3 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.
Unknown commented 3 years ago

@sirrosh Also, be sure you have lua-ossl installed, as per https://modules.prosody.im/mod_cloud_notify_encrypted
Unknown commented 3 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?
Unknown commented 3 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.
Unknown commented 3 years ago

@sirrosh Maybe @mwild1 will be able to help you. I'm not a prosody developer or user.
Unknown commented 3 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???
Unknown commented 3 years ago

Pretty please join the Prosody support MUC so they can help you.
issue 1 of 1
Type
Bug
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_clients/siskin-im#554
Please wait...
Page is in error, reload to recover