Beta 3.2.3 (36): Push Notifications don't seem to work

[ghost]

XMPP Server: Prosody 0.10 nightly build 266 (2016-06-24, 726b088f9408) Prosody Modules (where I got mod_cloud_notify): rev: 7be1ca7a51a4

1. Made sure ChatSecure is forced quit
2. Sent message via Conversations
3. Message is marked as sent in Conversations
4. iPhone never receives push notification
5. Open iPhone, message never comes in
6. Message in Conversations immediately gets marked as Delivery failed

Perhaps unrelated, but found while testing for Push Notifications:

Messages sent offline no longer queue in Prosody. I assume force quitting ChatSecure makes the account "Sign Out". I can confirm this in Prosody's logs that "Client disconnected: closed". Messages sent from Conversations to ChatSecure does not queue up anymore.

[chrisballinger]

There's a lot of server side issues with Prosody and push that I've noticed so far.

Try enabling all three of these:

1. mod_smacks
2. mod_smacks_offline
3. mod_pinger

The combination of these can prevent messages from going missing, and it helps if you use a low-ish timeout. Sometimes the server thinks the client is still connected and does funky stuff when the socket is closed remotely by iOS without a clean disconnect.

OH also! If you force quit ChatSecure you will no longer receive pushes until you re-open the app. This is due to a limitation with the style of APNS messages we need to use.

[chrisballinger]

When the app is force-quit, the pushes get sent to Apple's server but are permanently discarded. The same thing will happen if you reboot the phone, you'll need to open the app again.

To test more easily without waiting for the natural timeout, you can log out of your account on the settings screen and then background the app without closing it.

[chrisballinger]

@TaroPuff any luck?

[ghost]

@chrisballinger Sorry, was busy at work, going on leave soon. Did some sporadic testing.

Prosody settings: as you've instructed added mod_smacks (already had this), mod_smacks_offline, mod_pinger. Set mod_pinger timeout to the following:

c2s_idle_timeout = 30
c2s_ping_timeout = 30

Push did work when I tested it initially, both with the recommended method, as well as just letting ChatSecure background normally.

But I just tested it a few minutes ago and it didn't push after leaving ChatSecure for about 3 hours. If you have any logs on your push server, anything for xmppify.com? Probably around 21:30 GMT. Server did show "going to send stanza to pubsub.chatsecure.org" and "stanza sent over s2sout".

Some comments, perhaps unrelate to push itself, more of how it "feels" (perhaps a different issue to open):

1. Push notifications don't clear when ChatSecure is loaded. When one is tapped specifically, only that is cleared.
2. Notification bubble seems to always only show 1.

[chrisballinger]

The push notification class we are using (content-available) are not entirely reliable 100% of the time because they are designed to be used with updating content in the background like download a podcast or whatnot, so they can be throttled or not delivered. IIRC they don't work in low power mode either.

Also yeah we recently changed the badge icon to be based on unread messages, not necessarily pushes themselves. If you have an unread message you might need to click on every contact until you "read" the unread one.

So glad to hear it's working (at least somewhat)!

[chrisballinger]

Telegram messages aren't encrypted unless you specifically turn on encryption and it all goes through their central server, so they probably just send regular plaintext push notifications.

Apple will be releasing a new end-to-end push notification type in iOS 10 that allows us to decrypt a payload, but I think it will be tricky to implement. Perhaps a better solution will be to add some form of VoIP to be able to use PushKit...

[ge0rg]

I can confirm push not working on 3.2.3 final (reported so yesterday on IRC). I'm the admin of yax.im and interested in providing this feature, feel free to ping me on IRC or Jabber for short-term comms.

Situation so far:

1. Whenever ChatSecure connects, it creates a new pubsub node for the Push service (so my server keeps adding more and more nodes!)
2. After ChatSecure is sent to background, mod_smacks hibernates the session
3. I send a new private message to the JID and see the following in prosody log:

Jul 27 14:52:54 c2s554e970      debug   hibernating, stanza queued
Jul 27 14:53:15 c2s554e970      debug   Invoking cloud handle_notify_request for new smacks hibernated stanza...

There is nothing indicating the message on the iOS device.

[chrisballinger]

@ge0rg I'm not sure why it creates new nodes, it should re-register with the same UUID though because if the server restarts it loses all the info. It seems there's an issue preventing successful registration which is the root of the problem.

You put log statements in handle_notify_request to help debug: https://hg.prosody.im/prosody-modules/file/tip/mod_cloud_notify/mod_cloud_notify.lua#l91

I'm guessing that user_push_services is nil because the registration is failing for whatever reason. https://hg.prosody.im/prosody-modules/file/tip/mod_cloud_notify/mod_cloud_notify.lua#l27

You can also put log statements in module:hook("iq-set/self/"..xmlns_push..":enable", function (event) to help narrow down the error. I'm guessing it's hitting line 40 origin.send(st.error_reply(stanza, "modify", "bad-request", "Invalid publish options")); and that our registration stanza is malformed. If you can log the full stanza and paste it here, it'll be helpful. You can scrub any identifying info or send it to me privately.

[Zash]

I've added some logging and changed how it extracts the publish options, so that unknown elements are ignored, as they should be.

[ge0rg]

Okay, it turns out to be an error that is not quite related to the ChatSecure client. I can not establish an s2s session from my server to pubsub.chatsecure.org, it looks like the service is sending an invalid stream header.

The xmpp.net report claims that no encryption is supported, but this looks like a service/domain configuration problem.

[Zash]

Whatever is running on pubsub.chatsecure.org seems to be talking something closer to pre-RFC Jabber, rather than modern XMPP. And no TLS?

[stigger]

Did anyone succeed at making this work with ejabberd+mod_push? After some tweaking push notifications do arrive, but that does not help. What I'm experiencing:

1. The setup works fine, client enables push and provides the token
2. Some time later (I guess when the client hibernates) the server switches into "waiting for stream resumption" mode:

2016-08-06 17:35:06.348 [info] <0.4337.0>@ejabberd_c2s:fsm_next_state:2474 Waiting for resumption of stream for test@example.com/chatsecure69353
2016-08-06 17:35:06.349 [debug] <0.4337.0>@mod_push:dispatch:691 +++++ dispatch: found push_user
2016-08-06 17:35:06.349 [debug] <0.4337.0>@mod_push:dispatch:698 +++++ NewSubscrs = [{subscription,<<"chatsecure69353">>,true,<<"20A8D89C-xxxx-xxxx-xxxx-94AD2013B00C">>,{remote_reg,{jid,<<>>,<<"pubsub.chatsecure.org">>,<<>>,<<>>,<<"pubsub.chatsecure.org">>,<<>>},<<"[token here]">>}}]
2016-08-06 17:35:06.349 [debug] <0.4337.0>@mod_push:dispatch:705 +++++ dispatch: found subscription
2016-08-06 17:35:06.349 [debug] <0.4337.0>@mod_push:on_wait_for_resume:1026 +++++++ adjusting timeout to 8640000

1. The resource is still online though. Sending a message triggers push:

2016-08-06 17:47:50.056 [debug] <0.4337.0>@mod_push:on_store_stanza:655 ++++++++++++ Stored Stanza for {jid,<<"test">>,<<"example.com">>,<<"chatsecure69353">>,<<"test">>,<<"example.com">>,<<"chatsecure69353">>}: {xmlel,<<"message">>,[{<<"from">>,<<"stigger@example.com/Psi@laptop">>},{<<"to">>,<<"test@example.com">>},{<<"xml:lang">>,<<"en">>},{<<"type">>,<<"chat">>},{<<"id">>,<<"abe5a">>}],[{xmlcdata,<<"\n">>},{xmlel,<<"body">>,[],[{xmlcdata,<<208,176,208,178,209,139,208,176,208,178,209,139>>}]},{xmlcdata,<<"\n">>}]}
2016-08-06 17:47:50.056 [debug] <0.4337.0>@mod_push:dispatch:691 +++++ dispatch: found push_user
2016-08-06 17:47:50.056 [debug] <0.4337.0>@mod_push:dispatch:698 +++++ NewSubscrs = [{subscription,<<"chatsecure69353">>,true,<<"20A8D89C-xxxx-xxxx-xxxx-94AD2013B00C">>,{remote_reg,{jid,<<>>,<<"pubsub.chatsecure.org">>,<<>>,<<>>,<<"pubsub.chatsecure.org">>,<<>>},<<"[token here]">>}}]
2016-08-06 17:47:50.056 [debug] <0.4337.0>@mod_push:dispatch:705 +++++ dispatch: found subscription
2016-08-06 17:47:50.056 [debug] <0.4337.0>@mod_push:do_dispatch:778 ++++ do_dispatch: dispatching remotely
2016-08-06 17:47:50.056 [debug] <0.4337.0>@ejabberd_router:do_route:351 route
        from {jid,<<"test">>,<<"example.com">>,<<>>,<<"test">>,<<"example.com">>,<<>>}
        to {jid,<<>>,<<"pubsub.chatsecure.org">>,<<>>,<<>>,<<"pubsub.chatsecure.org">>,<<>>}
        packet {xmlel,<<"iq">>,[{<<"type">>,<<"set">>}],[{xmlel,<<"pubsub">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub">>}],[{xmlel,<<"publish">>,[{<<"node">>,<<"20A8D89C-xxxx-xxxx-xxxx-94AD2013B00C">>}],[{xmlel,<<"item">>,[],[{xmlel,<<"notification">>,[{<<"xmlns">>,<<"urn:xmpp:push:0">>}],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"var">>,<<"message-count">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"1">>}]}]},{xmlel,<<"field">>,[{<<"type">>,<<"hidden">>},{<<"var">>,<<"FORM_TYPE">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"urn:xmpp:push:summary">>}]}]}]}]}]}]},{xmlel,<<"publish-options">>,[],[{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:data">>},{<<"type">>,<<"submit">>}],[{xmlel,<<"field">>,[{<<"type">>,<<"hidden">>},{<<"var">>,<<"FORM_TYPE">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"http://jabber.org/protocol/pubsub#publish-options">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"token">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"[token here]">>}]}]},{xmlel,<<"field">>,[{<<"var">>,<<"endpoint">>}],[{xmlel,<<"value">>,[],[{xmlcdata,<<"https://push.chatsecure.org/api/v1/messages/">>}]}]}]}]}]}]}

1. Client wakes up, reconnects and that's when everything falls apart:

2016-08-06 17:47:53.566 [info] <0.4373.0>@ejabberd_c2s:wait_for_sasl_response:902 ({socket_state,fast_tls,{tlssock,#Port<0.23019>,#Port<0.23020>},<0.4372.0>}) Accepted authentication for test by undefined from 2A02:810D:14C0:....
2016-08-06 17:47:53.566 [debug] <0.4373.0>@ejabberd_c2s:send_text:1865 Send XML on stream = <<"<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>...</success>">>
2016-08-06 17:47:53.737 [debug] <0.4373.0>@ejabberd_c2s:send_text:1865 Send XML on stream = <<"<?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='17912566814232921261' from='example.com' version='1.0' xml:lang='en'>">>
2016-08-06 17:47:53.737 [debug] <0.4373.0>@ejabberd_c2s:send_text:1865 Send XML on stream = <<"<stream:features><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='UXk39+cTXCsKov0u77Emm42bGP8='/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><sm xmlns='urn:xmpp:sm:2'/><sm xmlns='urn:xmpp:sm:3'/></stream:features>">>
2016-08-06 17:47:53.853 [info] <0.4373.0>@ejabberd_c2s:open_session:1113 ({socket_state,fast_tls,{tlssock,#Port<0.23019>,#Port<0.23020>},<0.4372.0>}) Opened session for test@example.com/chatsecure69353
2016-08-06 17:47:53.854 [debug] <0.4337.0>@ejabberd_c2s:send_element:1869 Cannot send element while waiting for resumption: {xmlel,<<"stream:error">>,[],[{xmlel,<<"conflict">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[{xmlcdata,<<>>}]},{xmlel,<<"text">>,[{<<"xml:lang">>,<<>>},{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[{xmlcdata,<<"Replaced by new connection">>}]}]}
2016-08-06 17:47:53.854 [debug] <0.4373.0>@ejabberd_c2s:send_text:1865 Send XML on stream = <<"<iq id='B543D717-xxxx-xxxx-xxxx-76E6E477142C' type='result'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>test@example.com/chatsecure69353</jid></bind></iq>">>
2016-08-06 17:47:53.854 [info] <0.4337.0>@ejabberd_c2s:terminate:1773 ({socket_state,fast_tls,{tlssock,#Port<0.22983>,#Port<0.22984>},<0.4336.0>}) Replaced session for test@example.com/chatsecure69353
2016-08-06 17:47:53.854 [debug] <0.4337.0>@mod_shared_roster:unset_presence:813 unset_presence for <<"test">> @ <<"example.com">> / <<"chatsecure69353">> -> <<"Replaced by new connection">> (1 resources)
2016-08-06 17:47:53.855 [debug] <0.4337.0>@mod_push:delete_subscriptions:609 +++++ Deleting subscriptions for user <<"test">>@<<"example.com">>

Although, sometimes it works fine: stream resumes correctly and server delivers the message, but I can't find the pattern yet, and I'm not sure whether the problem is in ejabberd, in mod_push or in ChatSecure. Does anyone have any ideas on how to troubleshoot this further?

Update: Another strange issue is that on my second phone (iPhone 5) the client does not seem to wake up on pushes: there are no attempts to reconnect in the logs. If I grab the token from the log and send the push with text via push.chatsecure.org, then it arrives, but the client is still dead. Another phone (iPhone 6) always reconnects on push.

[chrisballinger]

@stigger On the iPhone 5, double check that the password is correct and cert doesnt need to be approved. Sometimes the keychain has issues and passwords disappear. Low battery mode will also prevent pushes from arriving.

I experienced a lot of issues with Prosody's mod_smacks 0198 interacting poorly with push, where queued messages would get dropped after hibernation period expires. I believe our client implementation of 0198 is broken, and another problem is that we fully logout instead of closing the TCP socket, but that shouldn't cause the Cannot send element while waiting for resumption error. When iOS suspends the socket it doesn't get cleanly closed and the server thinks the client is still active and never closes the socket until the OS TCP timeout which can be extremely long, which is why we were fully logging out.

[stigger]

On the iPhone 5, double check that the password is correct and cert doesnt need to be approved. Sometimes the keychain has issues and passwords disappear. Low battery mode will also prevent pushes from arriving.

The phone's charged, password's correct: after launching it manually it successfully connects and downloads the messages.

another problem is that we fully logout instead of closing the TCP socket

Interesting, I haven't noticed that. In my case the ChatSecure clients are always online, no mater how long the app is in background.

[stigger]

OK, the problem with iPhone 5 resolved: turned out that it's main "Background App Refresh" switch was turned off. My only problem at the moment is that I still often get the replacement by new connection upon reconnect, and after whole day of testing I haven't seen the full log out even once.

[stigger]

Problem with connection replacement turned out to be on the server side.

[thundergreen]

A cntact told me that she got one notifvato today ;) but still under investigation as she is not reliable because of non knowledge usage of chat secure

Thorsten Fröhlich

Am 08.08.2016 15:22 schrieb "Vyacheslav Karpukhin" <notifications@github.com

:

Problem with connection replacement turned out to be on the server side.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/ChatSecure/ChatSecure-iOS/issues/533#issuecomment-238233292, or mute the thread https://github.com/notifications/unsubscribe-auth/AMtAf7_PmJv76czcRSI1cn0kfTQ2qmp3ks5qdy2IgaJpZM4JIxGn .

[chrisballinger]

@stigger All issues are resolved now?

@thundergreen Great news

[stigger]

All issues are resolved now?

Yeah, I think so. There are still occasional glitches that I can't pinpoint, but most of the time everything is working as intended.

[ge0rg]

Okay, it looks like the pubsub server is now accessible from prosody land, and ChatSecure doesn't create a new push node on every connection anymore.

However, if a second client is online with the same JID, the push notification makes ChatSecure launch and connect in the background, but the message is already delivered to the other client, so the iOS device does not show any activity.

Update: apparently ChatSecure doesn't support MAM, and does not resume the hibernated 0198 session, so this feature only works if it is the only client connected to that JID, which is a pity.

[chrisballinger]

@ge0rg Our 0198 support is broken at the moment but that should be fixed in the next update. MAM is on the roadmap.

[tmolitor-stud-tu]

I experienced a lot of issues with Prosody's mod_smacks 0198 interacting poorly with push, where queued messages would get dropped after hibernation period expires. I believe our client implementation of 0198 is broken, and another problem is that we fully logout instead of closing the TCP socket, but that shouldn't cause the Cannot send element while waiting for resumption error. When iOS suspends the socket it doesn't get cleanly closed and the server thinks the client is still active and never closes the socket until the OS TCP timeout which can be extremely long, which is why we were fully logging out.

Yes, the TCP-timeout can be quite long. I'm planning to add an event to prosody's mod_smacks for messages not being acked by smacks for a configurable amount of time (say about 60 seconds or so). This event can be used by mod_cloud_notify to send push notifications as it already does for messages received while the session is hibernated by mod_smacks (something I added some months ago).

Prosody's mod_smacks drops all queued messages when the client doesn't resume the session in time. That is a known issue which cannot easily be solved in a clean way (thus the simple approach of dropping messages and sending delivery errors back to the sender). The module mod_smacks_offline (I think it's named that way) solves that issue by monkey-patching mod_smacks to import all queued messages as offline messages once the hibernation times out. But it has issues when used with multiple ressources and also doesn't play nicely with Conversations: It causes problems with Conversations seeing some messages twice (messages that got not acked because of a network outage but were correctly received by Conversations nonetheless. Those messages don't get deduplicated when they are received again as offline messages).

Thus, the best would be to implement MAM in Chatsecure (which solves the lost message problem when the smacks session isn't resumed in time) and to have push notifications for messages even while the TCP connection seems to be alive from the server's perspective (as outlined above) (which would solve the potential long delay between the message and it's push notification which would otherwise have to wait for the TCP timeout).

[chrisballinger]

@tmolitor-stud-tu Thank you for the insightful writeup of this issue! MAM does fix a lot of issues but it's a shame that mod_smacks doesn't already play well with clients going offline without using mod_smacks_offline.

[ge0rg]

@chrisballinger mod_smacks behavior is unfortunate, but it corresponds to the standard (and sends error responses back for all queued messages). All of this is only relevant if ChatSecure is the user's only client; if there is a second client online, you need to either fix 0198 and come back soon enough to resume the session, or you need to implement MAM.

[tmolitor-stud-tu]

@chrisballinger: @ge0rg is right. Smacks is only designed to make xmpp sessions survive short network outages. When using multiple clients it is very difficult to decide what to do with the messages still in the queue of client 1 when the session finally terminates and client 2 is still online. Because of all this difficult questions the smacks XEP decides to not solve these but rather leave them for other XEPs to solve. And MAM solves all of those problems and also some more which are not smacks related.

[joostrijneveld]

@tmolitor-stud-tu Does the push notification class have support for catching the needlessly sent notifications when the app is actually foregrounded? Sending push messages also when the TCP connection is alive has the obvious downside of having to somehow block those notifications (or simply accept the reduced UX).

[tmolitor-stud-tu]

@joostrijneveld I can only talk about the prosody's smacks module. And there a push notification is sent only when the session is hibernated or no session exists at all (offline messages).

The change I proposed was to add a timer to send out notifications if an ack is not received in a configurable timeframe (I would use something about 60 to 240 seconds) to wake up a device before the TCP timeout would actually happen and put the session into hibernated mode.

But nothing of this would send push messages when the TCP connection is alive and healthy. So don't worry :)

[Echolon]

Hi,

just started an EtherCalc Pad to collect information about your and others experience about push. Feel free to add your data or additional columns (suggest only to add columns where the information can be given from a normal user)

https://ethercalc.org/29iyo1nunqdp

Cheers