firebase PNR 0x17ba3e8 failed: Invalid server response: Unexpected HTTP response value (not 200 OK)

[dipenpatel235]

See Below Pushnotification error log. so push notification sent successfully but HTTP error 200 Not Ok. thats why mobile app is not wakeup.

it is work with few devices and not working with few devices. so not getting idea where is issue in response of Pushnotification related error.

2020-01-06 12:08:59:719 flexisip-debug-tport(0x12fed90): found 0x130be60 by name TCP/219.91.196.67:8038
2020-01-06 12:08:59:719 flexisip-debug-tport(0x130be60): found from primary TCP/219.91.196.67:8038
2020-01-06 12:08:59:719 flexisip-debug-tport_tsend(0x130be60) tpn = TCP/219.91.196.67:54096
2020-01-06 12:08:59:719 flexisip-debug-tport_vsend returned 269
2020-01-06 12:08:59:719 flexisip-debug-tport(0x130be60): set timer at 1800000 ms because keepalive
2020-01-06 12:08:59:719 flexisip-debug-nta_msg_tsend(response)
2020-01-06 12:08:59:719 flexisip-debug-Terminate SipEvent 0x131c3b8
2020-01-06 12:08:59:719 flexisip-debug-tport(0x130c310): set timer at 1799997 ms because keepalive
2020-01-06 12:08:59:745 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 sent 589/589 data
2020-01-06 12:08:59:745 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 waiting for server response
2020-01-06 12:08:59:767 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 read 687 data:
HTTP/1.1 200 OK
Content-Type: application/json; charset=UTF-8
Date: Mon, 06 Jan 2020 11:08:59 GMT
Expires: Mon, 06 Jan 2020 11:08:59 GMT
Cache-Control: private, max-age=0
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
Server: GSE
Alt-Svc: quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000
Accept-Ranges: none
Vary: Accept-Encoding
Transfer-Encoding: chunked

8f
{"multicast_id":1918435360665515386,"success":1,"failure":0,"canonical_ids":0,"results":[{"message_id":"0:1578308939759111%64af3761f9fd7ecd"}]}

2020-01-06 12:09:01:713 flexisip-debug-nta: timer set next to 30003 ms
2020-01-06 12:09:04:717 flexisip-debug-PNR 0x1313f38: timeout
2020-01-06 12:09:04:717 flexisip-debug-PNR 0x1313f38: notifying call context...
2020-01-06 12:09:04:717 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 running, queue_size=0
2020-01-06 12:09:04:717 flexisip-debug-PNR 0x1313f38: setting retry timer to 5s
2020-01-06 12:09:04:717 flexisip-debug-PushNotificationClient firebase next, queue_size=1
2020-01-06 12:09:04:717 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 sent 589/589 data
2020-01-06 12:09:04:717 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 waiting for server response
2020-01-06 12:09:04:717 flexisip-debug-PushNotificationClient firebase PNR 0x1313f38 read 5 data:
0

2020-01-06 12:09:04:717 flexisip-warning-PushNotificationClient firebase PNR 0x1313f38 failed: Invalid server response: Unexpected HTTP response value (not 200 OK)

[petervnv]

I think it's a silly bug that can be ignored.

If you look closely you can see that Google does return a 200 OK response, so all should be fine.

Do you receive the push notification?

[dipenpatel235]

Do you receive the push notification? - No. not received push notification also.

[pdarcos]

Hi guys,

I can confirm I have the exact same bug in my tests. Running a fresh Flexisip 2.0 beta installation on Debian 9.

Apple's push notifications work fine, while Google's firebase push notification has the bug that @dipenpatel235 describes above. Even though the Flexisip logs show that Google does at first reply with 200 OK, afterwards it replies with the "Invalid server response: Unexpected HTTP response value (not 200 OK)" message and the client device DOES NOT get woken up.

@fgrisez can you confirm on your end that this is a known bug?

[pdarcos]

I stand corrected. Sometimes it seems the pushes do work even though the flexisip logs show the error mentioned above. Other times the push notification never seems to arrive at the client device.

Doing some digging I think the reason for this strange behaviour is that FCM has upgraded to a newer version, 1, as detailed here https://firebase.google.com/docs/cloud-messaging/migrate-v1

Looking at the flexisip code it seems to still use the legacy version even though the http headers seem to imply it is using v1. I presume this mismatch is the reason for the buggy behavior, but only belledonne can confirm if this is the case.

[pdarcos]

Looking through the source code it seems confirmed that flexisip is using only legacy FCM, which could explain the buggy behavior since Google is pushing companies to migrate to the the newer v1.

https://github.com/BelledonneCommunications/flexisip/blob/b9bfcc6f4f4bea778db51d78aed5c092f40f83d6/src/pushnotification/firebasepush.cc#L11