Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Constant repeated registration well below the registration timeout #570

Closed
brianjmurrell opened this issue Apr 15, 2019 · 23 comments
Closed

Comments

@brianjmurrell
Copy link

Here's a log showing linphone spending a lot of battery on constantly trying to re-register even though though the expiry from an existing registration is nowhere near expired.

The problem with this is that while constantly trying to register, it seems that only one of them, every hour seems to make it onto the network. In the above log, it seem to be 53 minutes after every hour, Android allows access to the network to complete "house keeping".

In between those allowed network periods linphone spins trying to re-register, chewing up a lot of battery.

So this raises two issues. Why is linphone trying to do stuff outside of the Doze allotted housekeeping periods and why is it trying to register so frequently inside of a 172800s expiry period. It really has no reason to register so frequently when it knows that it's last registration is good for 48hrs.

@Viish
Copy link
Member

Viish commented Apr 15, 2019

From your logs, linphone doesn't try to register while doze mode is active ([Platform Helper] Device idle mode: true logs).

There are indeed a lot of REGISTER sent but most of them are retransmissions because it wasn't acknowledged by the proxy. I know you don't want to hear about how UDP is bad but you might want to either check if your router doesn't have a SIP ALG enabled or switch to a more reliable protocol...

The other REGISTER are triggered by network changes, in this case we have to send a new REGISTER with the correct contact information.

@brianjmurrell
Copy link
Author

Yes, they are re-transmissions because the application is not allowed to use the network. I can see this by sniffing right on the wireless AP that the phone is connected to. This is not a UDP or ALG problem. The packets don't get even that far. The AP does not even receive the packets because Android is not allowing them to be sent out because the phone is in Doze mode, where the network-allowed time is ~53 minutes after the top of very hour.

But none of that answers the question of why linphone is even trying to register so frequently when it's been configured to use and is using (as evidenced by the "Expires: 172800" in the SIP transactions) a 48hr expiry.

@Viish
Copy link
Member

Viish commented Apr 15, 2019

As I said, some of the REGISTER sent are trigger because the network you are connected to changes:
2019-04-13 22:35:19:609 [linphone-android] MESSAGE [Platform Helper] Network type has changed (last one was MOBILE), disabling network reachability first

@Viish
Copy link
Member

Viish commented Apr 15, 2019

Some other REGISTER are triggered because the LEAVE the doze mode, but there aren't any one sent while doze mode is enabled.
If you can find a log that says otherwise I'll take a look on it, but so far in your log file I didn't (even if I didn't look at all the file).

@Viish Viish closed this as completed Apr 15, 2019
@brianjmurrell
Copy link
Author

The logging of Device idle mode (and Doze) in the linphone logs cannot be accurate. In the log I attached the most recent report of Doze mode is:

2019-04-14 18:42:03:135 [linphone-android] MESSAGE [Platform Helper] Doze mode enabled: false
2019-04-14 18:42:03:137 [linphone-android] MESSAGE [Platform Helper] Device idle mode: false

There is no way that is the last time my phone entered Doze mode. It sat plugged in all night last night (2019-04-14 ~21:00:00 - 2019-04-15 ~06:00:00) completely untouched/unmoved/etc. It should have been Dozing most of that whole time.

As I said, some of the REGISTER sent are trigger because the network you are connected to changes:
Network type has changed:

The last occurrence of that in the log was:

2019-04-14 12:53:06:663 [linphone-android] MESSAGE [Platform Helper] Network type has changed (last one was MOBILE), disabling network reachability first

Followed by a successful registration:

2019-04-14 12:53:06:813 [belle-sip] MESSAGE channel [0x7d38ee48c0]: message sent to [UDP://pbx.example.com:5060], size: [876] bytes
REGISTER sip:pbx.example.com SIP/2.0
Via: SIP/2.0/UDP 10.75.22.32:47305;branch=z9hG4bK.tWadUMhuh;rport
From: <sip:brian_h8@pbx.example.com>;tag=u42gBlgND
To: sip:brian_h8@pbx.example.com
CSeq: 20 REGISTER
Call-ID: gsJ8NQ5ijf
Max-Forwards: 70
Supported: replaces, outbound, gruu
Accept: application/sdp
Accept: text/plain
Accept: application/vnd.gsma.rcs-ft-http+xml
Contact: <sip:brian_h8@10.75.22.32:47305;app-id=755770037818;pn-type=firebase;pn-tok==[redacted];pn-silent=1;transport=udp>;+sip.instance="<urn:uuid:312eea04-3559-00ae-9920-aac6701fd648>";+org.linphone.specs="lime"
Expires: 172800
User-Agent: LinphoneAndroid/4.1-debug (FRD-L04) LinphoneSDK/4.1-363-gd4fdc2e-debug (master) (belle-sip/1.6.3)


2019-04-14 12:53:06:813 [belle-sip] MESSAGE channel [0x7d38ee48c0]: ending send background task with id=[31e6].
2019-04-14 12:53:06:814 [belle-sip] MESSAGE bellesip_wake_lock_release(): Android wake lock released [ref=0x31e6]
2019-04-14 12:53:06:833 [belle-sip] MESSAGE bellesip_wake_lock_acquire(): Android wake lock [belle-sip recv channel] acquired [ref=0x31d2]
2019-04-14 12:53:06:833 [belle-sip] MESSAGE channel [0x7d38ee48c0]: starting recv background task with id=[31d2].
2019-04-14 12:53:06:833 [belle-sip] MESSAGE channel [0x7d38ee48c0]: received [476] new bytes from [UDP://pbx.example.com:5060]:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.75.22.32:47305;rport=47305;received=10.75.22.32;branch=z9hG4bK.tWadUMhuh
Call-ID: gsJ8NQ5ijf
From: <sip:brian_h8@pbx.example.com>;tag=u42gBlgND
To: <sip:brian_h8@pbx.example.com>;tag=z9hG4bK.tWadUMhuh
CSeq: 20 REGISTER
WWW-Authenticate: [redacted]
Server: Asterisk PBX 13.25.0
Content-Length:  0


2019-04-14 12:53:06:837 [belle-sip] MESSAGE channel [0x7d38ee48c0] [476] bytes parsed
2019-04-14 12:53:06:837 [belle-sip] MESSAGE channel [0x7d38ee48c0]: discovered public ip and port are [10.75.22.32:47305]
2019-04-14 12:53:06:837 [belle-sip] MESSAGE Found transaction matching response.
2019-04-14 12:53:06:837 [belle-sip] MESSAGE Changing [client] [REGISTER] transaction [0x7d2a182200], from state [TRYING] to [COMPLETED]
2019-04-14 12:53:06:837 [liblinphone] MESSAGE linphone_core_find_auth_info(): returning auth info username=brian_h8, realm=asterisk
2019-04-14 12:53:06:837 [belle-sip] MESSAGE Auth info found for [brian_h8] realm [asterisk]
2019-04-14 12:53:06:840 [belle-sip] MESSAGE bellesip_wake_lock_acquire(): Android wake lock [belle-sip transaction(0x7d3769f1c0)] acquired [ref=0x316a]
2019-04-14 12:53:06:840 [belle-sip] MESSAGE transaction [0x7d3769f1c0]: starting transaction background task with id=[316a].
2019-04-14 12:53:06:841 [belle-sip] MESSAGE Changing [client] [REGISTER] transaction [0x7d3769f1c0], from state [INIT] to [TRYING]
2019-04-14 12:53:06:841 [belle-sip] MESSAGE channel [0x7d38ee48c0]: message sent to [UDP://pbx.example.com:5060], size: [1160] bytes
REGISTER sip:pbx.example.com SIP/2.0
Via: SIP/2.0/UDP 10.75.22.32:47305;branch=z9hG4bK.qvMqNNNSA;rport
From: <sip:brian_h8@pbx.example.com>;tag=u42gBlgND
To: sip:brian_h8@pbx.example.com
CSeq: 21 REGISTER
Call-ID: gsJ8NQ5ijf
Max-Forwards: 70
Supported: replaces, outbound, gruu
Accept: application/sdp
Accept: text/plain
Accept: application/vnd.gsma.rcs-ft-http+xml
Contact: <sip:brian_h8@10.75.22.32:47305;app-id=755770037818;pn-type=firebase;pn-tok==[redacted];pn-silent=1;transport=udp>;+sip.instance="<urn:uuid:312eea04-3559-00ae-9920-aac6701fd648>";+org.linphone.specs="lime"
Expires: 172800
User-Agent: LinphoneAndroid/4.1-debug (FRD-L04) LinphoneSDK/4.1-363-gd4fdc2e-debug (master) (belle-sip/1.6.3)
Authorization: :[redacted]


2019-04-14 12:53:06:841 [belle-sip] MESSAGE channel [0x7d38ee48c0]: ending recv background task with id=[31d2].
2019-04-14 12:53:06:843 [belle-sip] MESSAGE bellesip_wake_lock_release(): Android wake lock released [ref=0x31d2]
2019-04-14 12:53:07:058 [belle-sip] MESSAGE bellesip_wake_lock_acquire(): Android wake lock [belle-sip recv channel] acquired [ref=0x3152]
2019-04-14 12:53:07:059 [belle-sip] MESSAGE channel [0x7d38ee48c0]: starting recv background task with id=[3152].
2019-04-14 12:53:07:059 [belle-sip] MESSAGE channel [0x7d38ee48c0]: received [655] new bytes from [UDP://pbx.example.com:5060]:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.75.22.32:47305;rport=47305;received=10.75.22.32;branch=z9hG4bK.qvMqNNNSA
Call-ID: gsJ8NQ5ijf
From: <sip:brian_h8@pbx.example.com>;tag=u42gBlgND
To: <sip:brian_h8@pbx.example.com>;tag=z9hG4bK.qvMqNNNSA
CSeq: 21 REGISTER
Date: Sun, 14 Apr 2019 16:53:07 GMT
Contact: <sip:brian_h8@10.75.22.32:47305;transport=udp;app-id=755770037818;pn-type=firebase;pn-tok==[redacted];pn-silent=1>;expires=172799
Expires: 172800
Server: Asterisk PBX 13.25.0
Content-Length:  0

And yet there were another ~1870 REGISTERs after that and ~15 "SIP/2.0 200 OK" responses.

So again, why so much registration? The one above at 2019-04-14 12:53:06:841 should have been all that was required for 48hrs after it. Why did this registration:

2019-04-14 13:53:08:040 [belle-sip] MESSAGE channel [0x7d38ee4f40]: message sent to [UDP://pbx.example.com:5060], size: [1220] bytes
REGISTER sip:pbx.example.com SIP/2.0
Via: SIP/2.0/UDP [2001:1234:5678:abcd:fd9c:35ad:a810:fb17]:47305;branch=z9hG4bK.57AATnmSz;rport
From: <sip:brian_h8@pbx.example.com>;tag=u42gBlgND
To: sip:brian_h8@pbx.example.com
CSeq: 22 REGISTER
Call-ID: gsJ8NQ5ijf
Max-Forwards: 70
Supported: replaces, outbound, gruu
Accept: application/sdp
Accept: text/plain
Accept: application/vnd.gsma.rcs-ft-http+xml
Contact: <sip:brian_h8@[2001:1234:5678:abcd:fd9c:35ad:a810:fb17]:47305;app-id=755770037818;pn-type=firebase;pn-tok==[redacted];pn-silent=1;transport=udp>;+sip.instance="<urn:uuid:312eea04-3559-00ae-9920-aac6701fd648>";+org.linphone.specs="lime"
Expires: 172800
User-Agent: LinphoneAndroid/4.1-debug (FRD-L04) LinphoneSDK/4.1-363-gd4fdc2e-debug (master) (belle-sip/1.6.3)
Authorization: :[redacted]

only an hour later need to be done?

@brianjmurrell
Copy link
Author

What is this:

2019-04-14 23:46:05:006 [belle-sip] MESSAGE Channel [0x7d38856a00]: inactivity timeout reached.

That seems to be what prompted this attempted registration:

2019-04-14 23:46:09:632 [belle-sip] MESSAGE channel [0x7d38856b00]: message sent to [UDP://pbx.example.com:5060], size: [1220] bytes
REGISTER sip:pbx.example.com SIP/2.0
Via: SIP/2.0/UDP [2001:1234:5678:abcd:fd9c:35ad:a810:fb17]:49017;branch=z9hG4bK.WxGX80nd-;rport
From: <sip:brian_h8@pbx.example.com>;tag=THAILF5nQ
To: sip:brian_h8@pbx.example.com
CSeq: 24 REGISTER
Call-ID: xfsPYrbSC3
Max-Forwards: 70
Supported: replaces, outbound, gruu
Accept: application/sdp
Accept: text/plain
Accept: application/vnd.gsma.rcs-ft-http+xml
Contact: <sip:brian_h8@[2001:1234:5678:abcd:fd9c:35ad:a810:fb17]:49017;app-id=755770037818;pn-type=firebase;pn-tok==[redacted];pn-silent=1;transport=udp>;+sip.instance="<urn:uuid:312eea04-3559-00ae-9920-aac6701fd648>";+org.linphone.specs="lime"
Expires: 172800
User-Agent: LinphoneAndroid/4.1-debug (FRD-L04) LinphoneSDK/4.1-363-gd4fdc2e-debug (master) (belle-sip/1.6.3)
Authorization: :[redacted]

that was unanswered because the phone was presumably in Doze mode and did not allow linphone to use the network. The above is followed by a storm of retries.

@Viish
Copy link
Member

Viish commented Apr 15, 2019

We register a callback to the Android OS to be notified when the doze mode changes.
Even if it's unreliable we don't have any other option. And if your phone is plugged, it is possible it doesn't go into doze.

@brianjmurrell
Copy link
Author

brianjmurrell commented Apr 15, 2019

I still don't think that is explaining why the frequent REGISTERs.

What about the one in this comment above? It seems to have been triggered by:

2019-04-14 23:46:05:006 [belle-sip] MESSAGE Channel [0x7d38856a00]: inactivity timeout reached.

What is that message reporting?

@Viish
Copy link
Member

Viish commented Apr 15, 2019

I asked around the office, it seems it is normal: the channel hasn't received data for a while, it goes to disconnect state that creates a new channel a does a register.
Anyway this isn't related to linphone-android application directly, if you still want to pursue on that please open a ticket to the relevant project, like linphone or belle-sip.

@brianjmurrell
Copy link
Author

But clearly that message (or rather the state that it's reporting) is what is causing linphone to re-REGISTER so frequently and particularly when it is in Doze mode causing it to continually re-transmit the REGISTERs.

Surely as an app using belle-sip you need to understand what it means and how it affects the performance of a linphone port working on a device that has restrictions such as Android does.

Hrm. I was going to go ask on belle-sip but I see they have disabled the issue tracker. What is the best means of communicating with them about this issue?

@brianjmurrell
Copy link
Author

@Viish You have previously reported that your linphone instances use a very small single digit of battery or less. Can you post a log of one of these so that I can see how a properly behaving linphone looks?

@brianjmurrell
Copy link
Author

@Viish It seems that this belle-sip timeout is this:
https://github.com/BelledonneCommunications/belle-sip/blob/1d083c76be5b5959db2cc1f52a61836d8f43aa7f/src/sipstack.c#L137

which is accessed and set by this:
https://github.com/BelledonneCommunications/belle-sip/blob/1d083c76be5b5959db2cc1f52a61836d8f43aa7f/src/sipstack.c#L294-L300

Should linphone-android be setting this timeout equal to the Expiry?

I would still be very interested in seeing the log of a linphone instance that uses small percentage of CPU to see how it functions in comparison to my device.

@brianjmurrell
Copy link
Author

@Viish So is that simply no, you won't post a log of a phone that runs linphone at a very few percentage of battery use?

Can you comment on the above identified timeout?

Surely given that you are all in the same GitHub organisation, there is somebody you can talk to that works on belle-sip about how you can influence the value of that timeout, yes? Particularly since I am getting zero response from the mailing list that they invite people to use to inquire about the SDK.

@Viish
Copy link
Member

Viish commented Apr 17, 2019

@brianjmurrell Me not replying simply means I don't have time at the moment to handle your request.
By the way, I'm not at your disposition, and I'm only monitoring and helping on github on my personal time.
If you want a low battery usage of Linphone, simply use a sip.linphone.org account and use the default setting of the app.
Finally, our main belle-sip developer is in holidays and the mailing list is on a best-effort policy for us. We are in the process of releasing the new mobile version and we also work on a lot of other projects right now, we don't have much free time.

@brianjmurrell
Copy link
Author

brianjmurrell commented Apr 17, 2019

@Viish

Me not replying simply means I don't have time at the moment to handle your request.

If you don't have time, but do intend to follow-through when you do have time saying as much would be helpful. But surely in the time it took to write a reply, surely you could have pressed Send Log in linphone and pasted the URL, no?

If you want a low battery usage of Linphone, simply use a sip.linphone.org account and use the default setting of the app.

Would high battery use when using sip.linphone.org attract any more attention to the issue being described in this ticket? Because I don't believe this issue is particular to the use of a particular SIP server. The issue is with the app (including the stack it's built upon of course) itself and assumptions it is making about it's operating environment. Assumptions that may be valid when working on an always-connected (both power and network) "desktop" type devices but are not valid on frequently disconnected mobile, power-saving devices.

But if using sip.linphone.org is the only way to prove that the issue is with linphone, I would be happy to do that. I just want to be sure before I go to that effort though, that the results will be looked at and acted upon.

@Viish
Copy link
Member

Viish commented Apr 17, 2019

If you can provide logs that show an issue between linphone and our flexisip on sip.linphone.org, yes it will looked at and fixed.
Regarding the logs, I can't just upload logs and put my private messages exchange online just like that...

@brianjmurrell
Copy link
Author

Regarding the logs, I can't just upload logs and put my private messages exchange online just like that...

Wait! The logs that linphone-android uploads to the log server when (you request someone to send logs and) someone clicks About->Send Logs has private messages in them?

Surely you can see the problem when you don't want to use a log-send facility that you expect others to use because you don't want your private messages uploaded, yes?

Shouldn't the log-send functionality sanitise the log (or better yet the logging facilities not even log content/data) at least to the point where you would use it freely without concern?

@Viish
Copy link
Member

Viish commented Apr 17, 2019

Wait! The logs that linphone-android uploads to the log server when (you request someone to send logs and) someone clicks About->Send Logs has private messages in them?

When you don't use end-to-end encryption, yes messages are transmitted in plain text, and are logged the same way.

Surely you can see the problem when you don't want to use a log-send facility that you expect others to use because you don't want your private messages uploaded, yes?

Log upload isn't enabled by default, the server to which they are uploaded is configurable, and once you do upload them you are supposed to know what you do. Besides our company is the only people that have access to it.

Shouldn't the log-send functionality sanitise the log (or better yet the logging facilities not even log content/data) at least to the point where you would use it freely without concern?

This really isn't easy to do, and for some debug cases we need this information.

@brianjmurrell
Copy link
Author

When you don't use end-to-end encryption, yes messages are transmitted in plain text, and are logged the same way.

Is E2E encryption relevant here? I think the issue is the inclusion of the message payloads in the logs that are being uploaded to the log server isn't it? How does E2E impact that one way or another?

Log upload isn't enabled by default,

Yes, understood, But it is as soon as you ask for a log because of a ticket for example.

the server to which they are uploaded is configurable,

I missed that configuration option. Where is it? But really, how many people are going to stand up their own server to cleanse the logs when they report a bug and are asked for logs from the About screen?

Besides our company is the only people that have access to it.

That you know of. ;-) Seriously though, why store data that you don't need to that puts you at risk of disclosing people's private information?

This really isn't easy to do, and for some debug cases we need this information.

Some debug cases need access to message contents? I would thing that would be very rare, particularly where a randomised replacement (i.e. preserve the message length, etc. by randomly replacing characters in it with substitute characters) was done.

Anyway, "Send Log" really ought to disclose to people that they are sending private message content to the server and for how long it will be stored there, etc.

@Viish
Copy link
Member

Viish commented Apr 17, 2019

Is E2E encryption relevant here? I think the issue is the inclusion of the message payloads in the logs that are being uploaded to the log server isn't it? How does E2E impact that one way or another?

Yes it is. If you enable E2E encryption, the content of the messages will never appear anywhere, just an ecrypted blob will be visible. That's kinda the point.

I missed that configuration option. Where is it?

In chat options, sharing server setting.

Seriously though, why store data that you don't need to that puts you at risk of disclosing people's private information?

We don't store anything. We merely provide a sharing feature. Each uploaded file is deleted after a week.

@brianjmurrell
Copy link
Author

Yes it is. If you enable E2E encryption, the content of the messages will never appear anywhere, just an ecrypted blob will be visible. That's kinda the point.

But given that linphone is one of the ends, it's not infeasible that the message contents were in the log before they got encrypted. Good to know that that is not the case.

In chat options, sharing server setting.

Ahhh. I never really ventured very far into chat settings since my primary use-case is voice. But I see it now. It's not obvious though that Sharing server in Chat options is also where the debug log goes.

We don't store anything.

Yes you do...

Each uploaded file is deleted after a week.

That's storing, even if it's just for a week it' still being stored (i.e. at rest, probably unencrypted) and as such is at risk for that week.

@brianjmurrell
Copy link
Author

Will a linphone-android built from current master work with sip.linphone.org's push or do I need to use an APK built by you/linphone.org?

@Viish
Copy link
Member

Viish commented Apr 18, 2019

Either one of them have push available

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants