search

BelledonneCommunications / linphone-android

Linphone.org mirror for linphone-android (https://gitlab.linphone.org/BC/public/linphone-android)
https://linphone.org
GNU General Public License v3.0
1.12k stars 688 forks source link

[liblinphone] WARNING Refresh register operation not available (network unreachable) #788

Closed brianjmurrell closed 5 years ago

brianjmurrell commented 5 years ago

I got a failure to receive an INVITE with only the following messages related to the call in the debug log:

2019-10-03 10:39:19:247 [linphone-android] MESSAGE [Push Notification] Notifying Core
2019-10-03 10:39:19:248 [liblinphone] WARNING Refresh register operation not available (network unreachable)

It's puzzling how the network unreachable state could be true when clearly linphone just received a push message over the network.

Viish commented 5 years ago

network_unreachable is a intern setting used to prevent unwanted network operation that will fail. For example, when in doze mode, you can receive a push but you won't have network to make a REGISTER.

brianjmurrell commented 5 years ago

But how can _networkunreachable actually be true when a push was just received, on the network?

network operation that will fail

What is determining that a network operation will fail and how can it be determining that when clearly the network is working. A push was received on it.

How is linphone-android even usable if this state can exist?

Viish commented 5 years ago

There are two things on Android : the network of the device and the network an application has access to. Your device can be connected to internet and receive push notifications (firebase is part of Android so it benefits from features other applications can't have access to), but at the same time an app process can be restricted for network operations (in doze mode for example).

brianjmurrell commented 5 years ago

So this seems to make linphone unusable, or at least unreliable at best on Android. Am I interpreting you correctly?

So how do the many other applications that reliably get push notifications and content deal with this problem? Are other SIP clients such as Bria and Zoiper subject to the same unreliability? What makes linphone different if not?

Does any of this help? Or is what it's saying obsolete now?

I do have priority set to high in my push requests:

++ curl -s -X POST --header 'Authorization: Key=[redacted]' --Header 'Content-Type: application/json' -d '{
        "to":"[redacted]",
        "priority":"high",
        "uuid":"<urn:uuid:f518cf03-dce8-4002-870e-8b948e08de61>",
        "send-time":"2019-10-04 12:32:45"
    }' https://fcm.googleapis.com/fcm/send
{"multicast_id":[redacted],"success":1,"failure":0,"canonical_ids":0,"results":[{"message_id":"0:[redacted]%[redacted]"}]}
brianjmurrell commented 5 years ago

I'm asking the above as a legitimate question because all of this seems to put the utility of linphone-android in serious question.

But I do also wonder if and why this is only a problem for linphone-android.

Viish commented 5 years ago

Since the version you used we have made improvements to our network manager.

brianjmurrell commented 5 years ago

Is that in the app or the sdk?

Viish commented 5 years ago

Sdk

brianjmurrell commented 5 years ago

So I want 4.2-182-g1eb2091 instead of the 4.2-143-gfa00b73 that I had?

Viish commented 5 years ago

No actually there was no change in that part of code since the 4.2-143. What commit of the app are you on ?

brianjmurrell commented 5 years ago

d753ca23

Viish commented 5 years ago

Then I'm surprised. The logs you attached in the first comment of this ticket doesn't match the version you said you are using.

brianjmurrell commented 5 years ago

Ahhh. You are reminding me that I did update the app's master commit yesterday before I built with the new SDK.

I'm pretty sure it was 053ada28 that I was on before updating yesterday.

Viish commented 5 years ago

Anyway now that you are up-to-date it should not happen anymore.

brianjmurrell commented 5 years ago

Great

brianjmurrell commented 5 years ago

Still seems to be happening:

2019-10-11 07:56:05:206 [linphone-android] MESSAGE [Push Notification] Notifying Core
2019-10-11 07:56:05:206 [liblinphone] WARNING Refresh register operation not available (network unreachable)

Log

Viish commented 5 years ago

Can you confirm you are using linphone-android with the background mode enabled ? I may have found a bug in the library that can happen in the Core still exists.

But anyway why in your log file doesn't appear the following log that is outputed at the very start of the native method we call when we receive a push notification: "Push notification received" ?

brianjmurrell commented 5 years ago

No, I am not using Background mode. I don't want it to stay awake in the background. I want it to be killable and then wake up when it receives a push notification. AFAIU background mode applications are frowned upon by Android and various phone makers with their aggressive battery savings techniques.

But anyway why in your log file doesn't appear the following log that is outputed at the very start of the native method we call when we receive a push notification: "Push notification received" ?

I don't know.

Viish commented 5 years ago

What method is called in the FirebaseMessaging class of your Android app when a push is received ?

brianjmurrell commented 5 years ago

Which Android app are you meaning? The only part of my solution that is Android is linphone.

The push message is being sent by my PBX to https://fcm.googleapis.com/fcm/send with:

Authorization: Key=[redacted]
Content-Type: application/json

{
  "to":"[redacted]",
  "priority":"high",
  "uuid":"<urn:uuid:15e94074-4ff1-4898-a3b0-53371de4c354>",
  "send-time":"2019-10-11 09:33:53"
}'

And I get a result that looks like:

{
  "multicast_id":8168460656905932761,"success":1,"failure":0,"canonical_ids":0,"results": [{"message_id":"0:1570800833693584%fafd82ecf9fd7ecd"}]
}
Viish commented 5 years ago

In the android project, in java/org/linphone/firebase/FirebaseMessaging.java

brianjmurrell commented 5 years ago

Ahhh. Sorry, I understand what you mean now:

@@ -43,7 +43,7 @@ public class FirebaseMessaging extends FirebaseMessagingService {
                         if (LinphoneManager.getInstance() != null) {
                             Core core = LinphoneManager.getCore();
                             if (core != null) {
-                                core.ensureRegistered();
+                                core.refreshRegisters();
                             }
                         }
                     }
brianjmurrell commented 5 years ago

Got another one of these:

2019-10-16 16:49:11:330 [linphone-android] MESSAGE [Push Notification] Notifying Core
2019-10-16 16:49:11:330 [liblinphone] WARNING Refresh register operation not available (network unreachable)
2019-10-16 16:49:11:417 [liblinphone] MESSAGE Destroying op [0x7bd2784c80] of type [SalOpUnknown]
2019-10-16 16:49:11:417 [belle-sip] MESSAGE Transaction [0x7bc32f8940] deleted
2019-10-16 16:49:11:418 [liblinphone] MESSAGE Destroying op [0x7bd2785680] of type [SalOpUnknown]
2019-10-16 16:49:11:418 [belle-sip] MESSAGE Transaction [0x7bc4418600] deleted
2019-10-16 16:49:11:419 [liblinphone] MESSAGE Destroying op [0x7bd2784f00] of type [SalOpUnknown]
2019-10-16 16:49:11:420 [belle-sip] MESSAGE Transaction [0x7bc05e4400] deleted
2019-10-16 16:49:11:420 [liblinphone] MESSAGE Destroying op [0x7bd2785e00] of type [SalOpUnknown]
2019-10-16 16:49:11:420 [belle-sip] MESSAGE Transaction [0x7bc05e5120] deleted

So seems it's not really fixed yet. I'm using version:

User-Agent: LinphoneAndroid/4.1-144-g60964c40 (FRD-L04) LinphoneSDK/4.2-182-g1eb2091 (master)

Can we please reopen this issue until it is resolved?

Viish commented 5 years ago

Did you revert your changes ? Because from the logs it looks like not. Anyway I recommend you to update the SDK to version 4.3.0-alpha-7-g64c3d80 or newer, I've changed a little thing in the network manager that could improve your situation.

brianjmurrell commented 5 years ago

Revert which changes? I don't see any comment about reverting changes.

update the SDK to version 4.3.0-alpha-7-g64c3d80 or newer

Is that simply a matter of clearing the gradle cache or is there a smaller hammer than clearing the entire gradle cache?

Viish commented 5 years ago

Revert which changes? I don't see any comment about reverting changes.

You have made changes to your FirebaseMessagingService implementation. This is your choice but then don't complain it doesn't work then.

Is that simply a matter of clearing the gradle cache or is there a smaller hammer than clearing the entire gradle cache?

You don't need to clear it, just building the app again in Android Studio should be enough once you changed the version in implementation "org.linphone:linphone-sdk-android:4.2+" to 4.3+.

brianjmurrell commented 5 years ago

You have made changes to your FirebaseMessagingService implementation. This is your choice but then don't complain it doesn't work then.

Do you honestly think that change is at the root of this issue though?

Besides, without this change, as I have asked before and not gotten a reasonable answer, how does the SIP proxy know linphone is ready to receive the INVITE without linphone telling it in some way, like sending a REGISTER?

Simply sending the push and waiting some arbitrary amount of time is completely unsuitable due to the variability in how long it takes linphone to (possibly have to) wake up and be ready. As a software developer, surely you can agree that a sleep here is never going to be exactly right. It's either going to be too long and callers give up waiting for the phone to be answered or it's too short and linphone isn't ready when the INVITE is sent and the call is missed.

If you have a better solution to the above problem than using a REGISTER to notify the SIP proxy that linphone is ready, I am completely open to suggestions.

changed the version in implementation "org.linphone:linphone-sdk-android:4.2+" to 4.3+.

Here: https://github.com/BelledonneCommunications/linphone-android/blob/25605f999e92a4dde6d0abb608012ffcfe120037/app/build.gradle#L189 yes?

Viish commented 5 years ago

Do you honestly think that change is at the root of this issue though?

Yes, as the work we do in ensureRegistered is specifically designed for this scenario and won't abort because the network reachability of the Core is set to false, at the contrary of refreshRegisters().

Simply sending the push and waiting some arbitrary amount of time

That's not what we do...

brianjmurrell commented 5 years ago

So does ensureRegistered() somehow give linphone access to the network stack that refreshRegisters() doesn't? So calling refreshRegisters() after ensureRegistered() should give it access to the network stack, yes?

That's not what we do...

Can you please describe what you do?

brianjmurrell commented 5 years ago

Building latest master with implementation "org.linphone:linphone-sdk-android:4.3+" produces this crash: 

10-17 10:01:18.909  9340  9340 D AndroidRuntime: Shutting down VM
10-17 10:01:18.911  9340  9340 E AndroidRuntime: FATAL EXCEPTION: main
10-17 10:01:18.911  9340  9340 E AndroidRuntime: Process: org.linphone.debug, PID: 9340
10-17 10:01:18.911  9340  9340 E AndroidRuntime: java.lang.UnsatisfiedLinkError: dalvik.system.PathClassLoader[DexPathList[[zip file "/data/app/org.linphone.debug-IsP0Umw6TE5skiysKKPnrA==/base.apk"],nativeLibraryDirectories=[/data/app/org.linphone.debug-IsP0Umw6TE5skiysKKPnrA==/lib/arm64, /data/app/org.linphone.debug-IsP0Umw6TE5skiysKKPnrA==/base.apk!/lib/arm64-v8a, /system/lib64, /vendor/lib64, /product/lib64]]] couldn't find "libc++_shared.so"
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at java.lang.Runtime.loadLibrary0(Runtime.java:1011)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at java.lang.System.loadLibrary(System.java:1660)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at org.linphone.core.FactoryImpl.<clinit>(Factory.java:295)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at org.linphone.core.Factory.instance(Factory.java:44)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at org.linphone.LinphoneContext.<init>(LinphoneContext.java:95)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at org.linphone.LinphoneService.onCreate(LinphoneService.java:54)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.app.ActivityThread.handleCreateService(ActivityThread.java:3961)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.app.ActivityThread.-wrap5(Unknown Source:0)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2092)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.os.Handler.dispatchMessage(Handler.java:108)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.os.Looper.loop(Looper.java:166)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at android.app.ActivityThread.main(ActivityThread.java:7523)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at java.lang.reflect.Method.invoke(Native Method)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:245)
10-17 10:01:18.911  9340  9340 E AndroidRuntime:        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:921)
10-17 10:01:18.913  1109  1448 W ActivityManager:   Force finishing activity org.linphone.debug/org.linphone.activities.LinphoneLauncherActivity
brianjmurrell commented 5 years ago

Reverting the implementation "org.linphone:linphone-sdk-android:4.3+" and rebuilding/installing doesn't seem to fix the crash. :-(

brianjmurrell commented 5 years ago

That'll teach me to not keep previous copies of the .apks.

Viish commented 5 years ago

Just tried it, works like a charm. Clean your cache.

brianjmurrell commented 5 years ago

I can see that libc++_shared.so is not being included in the .apk. Let me try cleaning the cache...

brianjmurrell commented 5 years ago

Even after doing a rm -rf /home/brian/.gradle/caches/* and running ./gradlew installDebug the .apk still only contains these libs:

 15754304  00-00-1980 00:00   lib/arm64-v8a/liblinphone.so
  4651048  00-00-1980 00:00   lib/arm64-v8a/libmediastreamer.so
    43488  00-00-1980 00:00   lib/arm64-v8a/libmsaaudio.so
    51456  00-00-1980 00:00   lib/arm64-v8a/libmsandroidcamera2.so
   383080  00-00-1980 00:00   lib/arm64-v8a/libmswebrtc.so
 12161424  00-00-1980 00:00   lib/armeabi-v7a/liblinphone.so
  3631788  00-00-1980 00:00   lib/armeabi-v7a/libmediastreamer.so
    26544  00-00-1980 00:00   lib/armeabi-v7a/libmsaaudio.so
    34620  00-00-1980 00:00   lib/armeabi-v7a/libmsandroidcamera2.so
   290524  00-00-1980 00:00   lib/armeabi-v7a/libmswebrtc.so
 15098856  00-00-1980 00:00   lib/x86/liblinphone.so
  4975300  00-00-1980 00:00   lib/x86/libmediastreamer.so
    38784  00-00-1980 00:00   lib/x86/libmsaaudio.so
    46856  00-00-1980 00:00   lib/x86/libmsandroidcamera2.so
   372444  00-00-1980 00:00   lib/x86/libmswebrtc.so
 15680952  00-00-1980 00:00   lib/x86_64/liblinphone.so
  4967360  00-00-1980 00:00   lib/x86_64/libmediastreamer.so
    43776  00-00-1980 00:00   lib/x86_64/libmsaaudio.so
    51736  00-00-1980 00:00   lib/x86_64/libmsandroidcamera2.so
   387496  00-00-1980 00:00   lib/x86_64/libmswebrtc.so

I even checked out linphone-android master and see the same thing.

brianjmurrell commented 5 years ago

Hrm. git clean -dfx seems to have resolved it.

So back to the open questions in the thread:

That's not what we do...

Can you please describe what you do?

Can you please describe how a SIP proxy is to know that linphone is ready for an INVITE if you don't send it a signal, such as a REGISTER when it wake up?

brianjmurrell commented 5 years ago

Yeah, there is an issue with trying to go to the 4.3+ SDK without doing a git clean -dfx before ./gradlew installDebug that causes some libs to be missing from the .apk,

Viish commented 5 years ago

Can you please describe how a SIP proxy is to know that linphone is ready for an INVITE if you don't send it a signal, such as a REGISTER when it wake up?

Take a look at the code in linphone project at the ensureRegistered method, it is quite well documented.

brianjmurrell commented 5 years ago

Ahhh. Let me see if I can guess at what is going on here...

linphone REGISTERs to the SIP proxy on a TCP connection. The SIP proxy uses the state of that TCP connection to know if linphone is still alive or not because when the phone kills linphone, the TCP session will be torn down.

So as long as the TCP socket is still in the ESTABLISHED state on the SIP proxy, the SIP proxy knows linphone is still alive and ready to receive an INVITE -- it probably doesn't even need to send a push!. If the TCP session is torn down, then the SIP proxy knows linphone has been killed and has to send a push and wait for a REGISTER before it can send an INVITE.

Correspondingly, ensureRegistered() is effectively implementing the above protocol. If the connection to the proxy is still in an ESTABLISHED state, it does nothing because it knows the SIP server knows it's still alive. However if the TCP session is no longer ESTABLISHED, for example, because linphone has been woken up (by way of a push) from being previously killed, it knows it has to REGISTER again to let the SIP proxy know it's alive.

So this is basically just an optimization of the protocol I was using which was to always push and always REGISTER after receiving a push.

There is problem with your protocol however. Some phones, mine included, will stop responding to TCP sessions when it goes into doze mode. The TCP session is not actually torn down, with a TCP RST or anything like that, the phone just stops responding to keepalives. This can be seen in a packet trace as TCP packets being sent from the SIP proxy to the phone with no response from the phone at all.

It further can be seen on the SIP proxy when the Send-Q is > 0:

Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0   2002 10.75.22.8:5060         10.75.22.32:58234       ESTABLISHED 28946/asterisk

Sending a push when in this state doesn't result in linphone REGISTERing, so it must still be alive on the phone and the TCP session ESTABLISHED even though the packets from the SIP proxy are not being responded to.

Here's a log of that happening. A push was sent to linphone here:

2019-10-18 12:47:44:194 [linphone-android] MESSAGE [Push Notification] Notifying Core
2019-10-18 12:47:44:195 [liblinphone] MESSAGE Push notification received
2019-10-18 12:49:47:250 [linphone-android] MESSAGE [Contacts Manager] Content observer detected a changing in at least one contact
2019-10-18 12:49:47:251 [linphone-android] MESSAGE [Contacts Manager] Synchronization started
2019-10-18 12:49:47:254 [linphone-android] MESSAGE [Contacts Manager] Background synchronization started
2019-10-18 12:49:47:254 [linphone-android] MESSAGE [Contacts Manager] Only fetching contacts in default directory
2019-10-18 12:49:47:315 [linphone-android] MESSAGE [Contacts Manager] Found 1260 entries in cursor

but as you can see nothing was done by linphone after the push was received until a couple of minutes later.

Viish commented 5 years ago

Issue should be fixed in SDK 4.3.0-alpha.25+f810940

JitainSharma commented 4 years ago

Actually not fixed. Linphone SDK: 4.3.3 Android 10 device

On register Push received, the refreshRegisters is called in a job scheduled via work manager with NetworkType.CONNECTED Constraints.

Job is started but even after it gives the same error as Refresh register operation not available (network unreachable)

The attached log will show that the internet is connected via wifi.

Android_Log.pdf

Viish commented 4 years ago

Without logs from the SDK I can't say what's happening. Also don't use any SDK method on a different thread than the main one!