3CX Android Push Notification

[Trizzn]

Hello,

I'm having trouble with push notification to multiple Android clients, sometimes it rings and sometimes it doens't. This has been happening since april.

Info of the installation:
On premise
Windows version: Windows 10 20H2
3CX Version: 16.0.9

Info of the smartphone with app:
Model: Samsung Galaxy A40 5G
3CXPhone for Android version: 16.7.6.105

I have tested with a Huawei phone aswell and there it also failed sometimes (1/5 calls). On iOS i couldn't reproduce the problem.

This also happens with internal calls, over WiFi & mobile data.

Troubleshooting steps taken:
- Reprovisioned the phones with a new QR code & reinstalled app
- Firewall checker all green
- Triple checked accept push notification settings under extension --> Phone provisioning & forwarding
- Reinstalled 3CX on the machine with a backup
- Compared pretty much all settings with a working on premise installation using the same setup

I've managed to snatch the following entries from a verbose log of an Android phone the moment the push was not working:
See THESE entries regarding push

06-30 11:58:39.936 I/3CXPhone.FcmService( 425): (thread 425) Creating FcmService
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): (thread 2835) Got FCM message, sent at 1625047121096, now is 1625047119939 (diff -1157 ms), TimeToLive: 0s, priority: 1, original priority: 1
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): (thread 2835) Received FCM message:
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): callid = 290
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): reason = 0
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): replaces = EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): callerid =
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): f1 = 172.16.20.250:5001
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): f2 = bethanie.3cx.be:5001
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): ver = 1
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): inst = profile.a43253a9-b068-44fc-9a1e-e46d8cc0bcf5
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): type = 0
06-30 11:58:39.939 I/3CXPhone.FcmService( 425): callername =
06-30 11:58:39.939 D/3CXPhone.Push( 425): (thread 2835) onFcmMessage: callerid = , replaces = EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53, inst = profile.a43253a9-b068-44fc-9a1e-e46d8cc0bcf5, reason = 0
06-30 11:58:39.940 I/3CXPhone.Push( 425): (thread 2835) current stand-by bucket is ACTIVE [10]
06-30 11:58:39.940 E/3CXPhone.Push( 425): (thread 2835) cannot make call - parameters are malformed [ name=, number=, replaces=EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53 ]
06-30 11:58:39.941 D/3CXPhone.Push( 425): (thread 2835) Operation startCall - elapsed_time = 1 ms
06-30 11:58:56.846 I/3CXPhone.FcmService( 425): (thread 425) Creating FcmService
06-30 11:58:56.848 I/3CXPhone.FcmService( 425): (thread 2838) Got FCM message, sent at 1625047138115, now is 1625047136848 (diff -1267 ms), TimeToLive: 0s, priority: 1, original priority: 1
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): (thread 2838) Received FCM message:
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): callid = 290
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): reason = 1
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): replaces = EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): callerid =
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): f1 = 172.16.20.250:5001
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): f2 = bethanie.3cx.be:5001
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): ver = 1
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): inst = profile.a43253a9-b068-44fc-9a1e-e46d8cc0bcf5
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): type = 0
06-30 11:58:56.849 I/3CXPhone.FcmService( 425): callername =
06-30 11:58:56.849 D/3CXPhone.Push( 425): (thread 2838) onFcmMessage: callerid = , replaces = EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53, inst = profile.a43253a9-b068-44fc-9a1e-e46d8cc0bcf5, reason = 1
06-30 11:58:56.850 I/3CXPhone.Push( 425): (thread 2838) current stand-by bucket is ACTIVE [10]
06-30 11:58:56.851 I/3CXPhone.Core( 425): (thread 425) stopCall, replaces=EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53
06-30 11:58:56.851 W/3CXPhone.Core( 425): (thread 425) stopCall - call is not found
06-30 11:58:56.851 I/3CXPhone.Push( 425): (thread 2838) canceled the call with replaces EksVfe3LPuV9S796eRj4Yg..;from-tag=1a70547b;to-tag=6e78ff53
06-30 11:58:56.851 D/3CXPhone.Push( 425): (thread 2838) Operation stopCall - elapsed_time = 1 ms

Any help is much appreciated,
Tristan

 

[NickD_3CX]

Hi Tristan,

Thanks for the very detailed explanation.
A few days ago we also release a new Beta version of the App 16.7.7.118. Could you please try this version as well and check if this remains?

One more detail, could you next test be with WiFi on the mobile phone completely switched off and only operate over LTE?

 

[Trizzn]

Hi Nick,

Thanks for your response, i have tested with the beta app and could reproduce the same issue (also 1 / 5 calls don't receive push notification). I have also configured an iOS device on the same extension and the iOS phone ringed everytime, so it's only Android phones having the issue.

I have logs of the following things:
Activity log with verbose on
Log from the app with verbose on
packet capture of the moment the problem did

2 times from the basic app and one time from the beta app.

Can i perhaps send you these logs by any chance to inspect this further?

Thanks for your time,
Tristan

 

[NickD_3CX]

Hi Tristan,

After having a look at the log snippet you sent, it looks like the issue is "callerid =", that generally should contain the Callers' Number.
Because this is empty, the Android App is not able to create the re-INVITE message required to answer the call.

Are there are settings you have made on your PBX to not show the Caller Number to the extensions?
E.g. Have you by any chance changed the "Inbound Parameters" of your SIP Trunk and specifically the "CallerNum"?

 

[Trizzn]

Hello Nick,

Thank you for the response.

It's a Telenet trunk configured on the phone system, attached you can find a screenshot with the inbound parameters settings of the trunk.

Regards,
Tristan

 

[NickD_3CX]

The Trunk settings look OK.

When this happens again, have a look in the Activity Log at the call and check the "from" in the SIP messages to make sure that there is a value there of the Caller. Then check the messages after this to check the 3CX did in fact read this value from the SIP message.

Make sure you have set the logging level to Verbose before doing this.

If you don't manage to find some clue to point to some settings, I would suggest contacting the 3CX Support Team to have a deeper look into the logs to try and help you get to the bottom of this.

 

[NickD_3CX]

On second thought, there is one more thing I would be curious if you could try, seeing that you say this does not happen on iOS App.

If possible, provision an Android and an iOS to the same 3CX Extension. On incoming calls always answer with the Android but before you do, check what Caller ID shows on the iOS.
If the issue happens when answering from the Android, what Caller ID did you see on the iOS before you answered?

 

[Vali_3CX]

@Trizzn
Also, how does such call is shown in client's Recents? Do they have a number (ie, callerID), can you call them back?

 

[Trizzn]

Hello Nick & Vali,

I have checked the activity log of a moment when the Android didnt ring and i think this is the info we need right?:
07/01/2021 10:36:46 AM - SendMsg from <sip:[email protected];user=phone>;tag=4c343351 to <sip:[email protected];user=phone>;tag=2613
07/01/2021 10:36:46 AM - L:375.2[Extn:30] got Provisional Recv 180/INVITE from 127.0.0.1:5483 tid=8265fd279c092477 Call-ID=LMc67OpnfJnAGUpFAN1w8w..:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK-524287-1---8265fd279c092477;rport=5060
Contact: <sip:[email protected]:5483;rinstance=0779979616005638>
To: <sip:[email protected]>;tag=33216216
From: <sip:[email protected]:5060;nf=e>;tag=521aa63f
Call-ID: LMc67OpnfJnAGUpFAN1w8w..
CSeq: 1 INVITE
User-Agent: 3CX Mobile Client
Content-Length: 0

I see that the number (+3250598472) is filled in but i don't know if this is in ok format.

For the other questions i have reproduced the problem with both an iOS and Android on the same extension and the incoming call on the iOS was formatted as:
+3250598472

Same for the Android (see attached the phone call that didn't push to the Android at 10:36)


Here you can see the entries in the call log of 3CX:


Thank you for your time,
Tristan

 

[ChrisC_3CX]

@Trizzn

I'll PM you shortly for more information regarding this issue.