linphone-users
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [Linphone-users] Linphone keeps sending register messages


From: Bram Peeters
Subject: Re: [Linphone-users] Linphone keeps sending register messages
Date: Tue, 13 Oct 2015 14:23:53 +0000

Hi,

 

I looked at what is happing in linphone for my infinite registeration messages problem described below.

 

The problem is detected in  'is_contact_address_acurate' where the following ports and ip addresses are compared:

                        int channel_public_port = refresher->transaction->base.channel->public_port;

                        int contact_port = belle_sip_uri_get_listening_port(belle_sip_header_address_get_uri(BELLE_SIP_HEADER_ADDRESS(contact)));

                        const char* channel_public_ip = refresher->transaction->base.channel->public_ip;

                        const char* contact_ip = belle_sip_uri_get_host(belle_sip_header_address_get_uri(BELLE_SIP_HEADER_ADDRESS(contact)));

 

Here, the refresher->transaction->base.channel->public_port and  refresher->transaction->base.channel->public_ip are never set.

 

The only place I can find where public port and ip are configured is when an incoming packet is processed.

The call stack is then:

linphone_core_iterate->sal_iterate->belle_sip_main_loop_sleep->belle_sip_main_loop_run->belle_sip_main_loop_iterate

->on_udp_data->belle_sip_channel_process_data->on_udp_data->belle_sip_channel_process_read_data->belle_sip_channel_process_stream

->belle_sip_channel_parse_stream->belle_sip_channel_message_ready->belle_sip_channel_learn_public_ip_port

 

When such an incoming packet arrives, in 'on_udp_data' there is a check  to see to which potential existing channel the packet belongs (and it is for this channel that the public port and ip are set in 'belle_sip_channel_learn_public_ip_port').

 

err=recvfrom(lp->sock,(char*)buf,sizeof(buf),MSG_PEEK,(struct sockaddr*)&addr,&addrlen);

...

struct addrinfo ai={0};

/*preserve the V4 mapping*/

ai.ai_family=addr.ss_family;

ai.ai_addr=(struct sockaddr*)&addr;

ai.ai_addrlen=addrlen;

chan=_belle_sip_listening_point_get_channel((belle_sip_listening_point_t*)lp,NULL,&ai);

 

This function compares the current_peer->ai_addr of each of the existing channels (only 1 in my case, the channel of the refresher) with the provided ai->ai_addr parameter (cfr 'belle_sip_channel_matches').

 

In my case, the match with the existing refresher channel fails (null is returned), because the peer details  of the refresher are

10.1.3.200, port 5060

 

While the asterisk sip server's reply comes from

10.1.3.200, port 1024

 

The result is a new channel is created in 'on_udp_data' :

                        if (chan==NULL){

                                               /*TODO: should rather create the channel with real local ip and port and not just 0.0.0.0"*/

                                               chan=belle_sip_channel_new_udp_with_addr(lp->base.stack

                                                                                                                      ,lp->sock

                                                                                                                      ,belle_sip_uri_get_host(lp->base.listening_uri)

                                                                                                                      ,belle_sip_uri_get_port(lp->base.listening_uri)

                                                                                                                      ,&ai);

 

And this has the effect that the public ip/port of the refresher channel are never set and I end up with null/0 values.

 

 

Question: how is this supposed to work normally? Should the server reply using port 5060 io 1024 (and do I have a configuration problem in my asterisk server causing it to reply using a 'random' port 1024 io 5060).

Or is it OK for the server to reply using a different port, and is there a different mechanism that should set the public port/ip of the refresher ? Which one ?

 

Regards

Bram

 

 

 

 

From: linphone-users-bounces+address@hidden [mailto:linphone-users-bounces+address@hidden On Behalf Of Bram Peeters
Sent: woensdag 7 oktober 2015 15:32
To: address@hidden
Subject: [Linphone-users] Linphone keeps sending register messages

 

Hi,

 

I am using linphone 3.8.5 on a windows 7 pc with ip address 10.1.3.37 (one of several nics)  to connect to a openwrt/asteriks sip server running on 10.1.3.200.

 

For some reason, linphone keeps sending register messages even though asteriks OK's them.

 

Eg a wireshark (overview) log from the pc running linphone shows:

10.1.3.37->10.1.3.200 SIP 671 Request: REGISTER sip:10.1.3.200    ([1])

10.1.3.200->10.1.3.37 SIP 626 Status:401 Unauthorized (0 bindings)

10.1.3.37->10.1.3.200 SIP 671 Request: REGISTER sip:10.1.3.200

10.1.3.200->10.1.3.37 SIP 562 Request: OPTIONS sip:address@hidden

10.1.3.200->10.1.3.37 SIP 522 Status: 200 OK (1 bindings)

10.1.3.37->10.1.3.200 SIP 299 Status: 200 OK

 

This is immediately followed by another run of that same sequence (Note: [1] already contains the 'Authorization' part because it is not the first request message, but it is stilled flagged as unauthorized by asterisk probably because it reuses the same auth info as the previous register message (?))

 

The same sequence can be found in the asterisk debug logs:

 

<--- SIP read from UDP:10.1.3.37:5060 --->

REGISTER sip:10.1.3.200 SIP/2.0

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.nrn1PrqNK;rport

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden

CSeq: 62044 REGISTER

Call-ID: QS4qjJyxxk

Max-Forwards: 70

Supported: outbound

Accept: application/sdp, text/plain, application/vnd.gsma.rcs-ft-http+xml

Contact: <sip:address@hidden>;+sip.instance="<urn:uuid:62fc6856-74fb-42cb-9fe4-8058743c792a>"

Expires: 3600

User-Agent: Linphone/3.8.5 (belle-sip/1.4.1)

Authorization: Digest realm="asterisk", nonce="035b046f", algorithm=MD5, username="77", uri="sip:10.1.3.200", response="dce8290e1c9f773f58ed45471024be0e"

 

<------------->

--- (13 headers 0 lines) ---

Sending to 10.1.3.37:5060 (NAT)

 

<--- Transmitting (NAT) to 10.1.3.37:5060 --->

SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.nrn1PrqNK;received=10.1.3.37;rport=5060

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden;tag=as6c3bca9e

Call-ID: QS4qjJyxxk

CSeq: 62044 REGISTER

Server: Asterisk PBX 1.8.7.1

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

Supported: replaces, timer

WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="49ab3765", stale=true

Content-Length: 0

 

 

<------------>

Scheduling destruction of SIP dialog 'QS4qjJyxxk' in 32000 ms (Method: REGISTER)

 

<--- SIP read from UDP:10.1.3.37:5060 --->

REGISTER sip:10.1.3.200 SIP/2.0

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.UJpKHfkZN;rport

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden

CSeq: 62045 REGISTER

Call-ID: QS4qjJyxxk

Max-Forwards: 70

Supported: outbound

Accept: application/sdp, text/plain, application/vnd.gsma.rcs-ft-http+xml

Contact: <sip:address@hidden>;+sip.instance="<urn:uuid:62fc6856-74fb-42cb-9fe4-8058743c792a>"

Expires: 3600

User-Agent: Linphone/3.8.5 (belle-sip/1.4.1)

Authorization: Digest realm="asterisk", nonce="49ab3765", algorithm=MD5, username="77", uri="sip:10.1.3.200", response="0b35c87e55aaaea646984f3529dad85d"

 

<------------->

--- (13 headers 0 lines) ---

Sending to 10.1.3.37:5060 (NAT)

Reliably Transmitting (NAT) to 10.1.3.37:5060:

OPTIONS sip:address@hidden SIP/2.0

Via: SIP/2.0/UDP 10.1.3.200:5060;branch=z9hG4bK17d8fa03;rport

Max-Forwards: 70

From: "asterisk" <sip:address@hidden>;tag=as7b396113

To: <sip:address@hidden>

Contact: <sip:address@hidden:5060>

Call-ID: address@hidden:5060

CSeq: 102 OPTIONS

User-Agent: Asterisk PBX 1.8.7.1

Date: Sat, 05 May 2012 21:04:08 GMT

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

Supported: replaces, timer

Content-Length: 0

 

 

---

 

<--- Transmitting (NAT) to 10.1.3.37:5060 --->

SIP/2.0 200 OK

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.UJpKHfkZN;received=10.1.3.37;rport=5060

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden;tag=as6c3bca9e

Call-ID: QS4qjJyxxk

CSeq: 62045 REGISTER

Server: Asterisk PBX 1.8.7.1

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

Supported: replaces, timer

Expires: 3600

Contact: <sip:address@hidden>;expires=3600

Date: Sat, 05 May 2012 21:04:08 GMT

Content-Length: 0

 

 

<------------>

Scheduling destruction of SIP dialog 'QS4qjJyxxk' in 32000 ms (Method: REGISTER)

 

<--- SIP read from UDP:10.1.3.37:5060 --->

SIP/2.0 200 Ok

Via: SIP/2.0/UDP 10.1.3.200:5060;branch=z9hG4bK17d8fa03;rport=1026

From: "asterisk" <sip:address@hidden>;tag=as7b396113

To: <sip:address@hidden>;tag=MESi8

Call-ID: address@hidden:5060

CSeq: 102 OPTIONS

 

<------------->

--- (6 headers 0 lines) ---

Really destroying SIP dialog 'address@hidden:5060' Method: OPTIONS

 

 

[ And it immediately continues (first one with the same nonce): ]

 

<--- SIP read from UDP:10.1.3.37:5060 --->

REGISTER sip:10.1.3.200 SIP/2.0

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.t41NI6mn1;rport

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden

CSeq: 62046 REGISTER

Call-ID: QS4qjJyxxk

Max-Forwards: 70

Supported: outbound

Accept: application/sdp, text/plain, application/vnd.gsma.rcs-ft-http+xml

Contact: <sip:address@hidden>;+sip.instance="<urn:uuid:62fc6856-74fb-42cb-9fe4-8058743c792a>"

Expires: 3600

User-Agent: Linphone/3.8.5 (belle-sip/1.4.1)

Authorization: Digest realm="asterisk", nonce="49ab3765", algorithm=MD5, username="77", uri="sip:10.1.3.200", response="0b35c87e55aaaea646984f3529dad85d"

 

<------------->

--- (13 headers 0 lines) ---

Sending to 10.1.3.37:5060 (NAT)

 

<--- Transmitting (NAT) to 10.1.3.37:5060 --->

SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.t41NI6mn1;received=10.1.3.37;rport=5060

From: <sip:address@hidden>;tag=G-i3nv0qe

To: sip:address@hidden;tag=as6c3bca9e

Call-ID: QS4qjJyxxk

CSeq: 62046 REGISTER

Server: Asterisk PBX 1.8.7.1

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

Supported: replaces, timer

WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6395e8c4", stale=true

Content-Length: 0

 

 

<------------>

 

[etc...]

 

 

I tried gathering debug info from linphones end, but the method described in

https://lists.gnu.org/archive/html/linphone-users/2012-03/msg00020.html

does not seem to work anymore (linphone just immediately crashes even before the gui appears).

Any info on how to do this on windows these days is appreciated :)

 

But in the meantime I grabbed to following snippit from the debug window (note: a different iteration then the one from asteriks, they fly by really fast ;p ):

 

message: 2015-10-07 15:21:07:876 Changing [client] [REGISTER] transaction [03447248], from state [COMPLETED] to [TERMINATED]

message: 2015-10-07 15:21:07:876 Client internal REGISTER transaction [03447248] terminated

message: 2015-10-07 15:21:07:905 channel [0344AFE8]: received [482] new bytes from [UDP://10.1.3.200:1024]:

SIP/2.0 200 OK

 

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.~p1S77YhH;received=10.1.3.37;rport=5060

 

From: <sip:address@hidden>;tag=1tpWmNlhF

 

To: sip:address@hidden;tag=as1eefda73

 

Call-ID: TtysfD1gLH

 

CSeq: 20133 REGISTER

 

Server: Asterisk PBX 1.8.7.1

 

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

 

Supported: replaces, timer

 

Expires: 3600

 

Contact: <sip:address@hidden>;expires=3600

 

Date: Sun, 29 Apr 2012 19:07:13 GMT

 

Content-Length: 0

 

 

 

 

message: 2015-10-07 15:21:07:905 channel [0344AFE8] [482] bytes parsed

message: 2015-10-07 15:21:07:905 Found transaction matching response.

message: 2015-10-07 15:21:07:905 Changing [client] [REGISTER] transaction [03447068], from state [TRYING] to [COMPLETED]

message: 2015-10-07 15:21:07:905 Refresher [03446AC8]: contact address [10.1.3.37:5060] does not match channel address[(null):0].

message: 2015-10-07 15:21:07:905 belle_sip_refresher_start(): refresher [03446AC8] is resubmitting request because contact sent was not correct in original request.

message: 2015-10-07 15:21:07:906 Auth info found for [77] realm [asterisk]

message: 2015-10-07 15:21:07:906 Changing [client] [REGISTER] transaction [034470C8], from state [INIT] to [TRYING]

message: 2015-10-07 15:21:07:906 channel [03421138]: message sent to [UDP://10.1.3.200:5060], size: [631] bytes

REGISTER sip:10.1.3.200 SIP/2.0

 

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.oQEynrqlP;rport

 

From: <sip:address@hidden>;tag=1tpWmNlhF

 

To: sip:address@hidden

 

CSeq: 20134 REGISTER

 

Call-ID: TtysfD1gLH

 

Max-Forwards: 70

 

Supported: outbound

 

Accept: application/sdp, text/plain, application/vnd.gsma.rcs-ft-http+xml

 

Contact: <sip:address@hidden>;+sip.instance="<urn:uuid:62fc6856-74fb-42cb-9fe4-8058743c792a>"

 

Expires: 3600

 

User-Agent: Linphone/3.8.5 (belle-sip/1.4.1)

 

Authorization:  Digest realm="asterisk", nonce="277674ca", algorithm=MD5, username="77",  uri="sip:10.1.3.200", response="d91efa320a7eb039766f7ab022fc7c58"

 

 

 

 

message: 2015-10-07 15:21:07:906 Changing [client] [REGISTER] transaction [03447008], from state [COMPLETED] to [TERMINATED]

message: 2015-10-07 15:21:07:906 Client internal REGISTER transaction [03447008] terminated

message: 2015-10-07 15:21:07:906 Garbage collecting unowned object of type belle_sip_header_contact_t

message: 2015-10-07 15:21:07:935 channel [0344AFE8]: received [486] new bytes from [UDP://10.1.3.200:1024]:

SIP/2.0 401 Unauthorized

 

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.oQEynrqlP;received=10.1.3.37;rport=5060

 

From: <sip:address@hidden>;tag=1tpWmNlhF

 

To: sip:address@hidden;tag=as1eefda73

 

Call-ID: TtysfD1gLH

 

CSeq: 20134 REGISTER

 

Server: Asterisk PBX 1.8.7.1

 

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

 

Supported: replaces, timer

 

WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="313657f1", stale=true

 

Content-Length: 0

 

 

 

 

message: 2015-10-07 15:21:07:935 channel [0344AFE8] [486] bytes parsed

message: 2015-10-07 15:21:07:935 Found transaction matching response.

message: 2015-10-07 15:21:07:935 Changing [client] [REGISTER] transaction [034470C8], from state [TRYING] to [COMPLETED]

message: 2015-10-07 15:21:07:935 Auth info found for [77] realm [asterisk]

message: 2015-10-07 15:21:07:936 Changing [client] [REGISTER] transaction [03447248], from state [INIT] to [TRYING]

message: 2015-10-07 15:21:07:936 channel [03421138]: message sent to [UDP://10.1.3.200:5060], size: [631] bytes

REGISTER sip:10.1.3.200 SIP/2.0

 

Via: SIP/2.0/UDP 10.1.3.37:5060;branch=z9hG4bK.sPxy3XCXz;rport

 

From: <sip:address@hidden>;tag=1tpWmNlhF

 

To: sip:address@hidden

 

CSeq: 20135 REGISTER

 

Call-ID: TtysfD1gLH

 

Max-Forwards: 70

 

Supported: outbound

 

Accept: application/sdp, text/plain, application/vnd.gsma.rcs-ft-http+xml

 

Contact: <sip:address@hidden>;+sip.instance="<urn:uuid:62fc6856-74fb-42cb-9fe4-8058743c792a>"

 

Expires: 3600

 

User-Agent: Linphone/3.8.5 (belle-sip/1.4.1)

 

Authorization:  Digest realm="asterisk", nonce="313657f1", algorithm=MD5, username="77",  uri="sip:10.1.3.200", response="55d81e85b4e3fd9e971182de93db433a"

 

 

 

 

message: 2015-10-07 15:21:07:965 channel [0344AFE8]: received [520] new bytes from [UDP://10.1.3.200:1024]:

OPTIONS sip:address@hidden SIP/2.0

 

Via: SIP/2.0/UDP 10.1.3.200:5060;branch=z9hG4bK19660533;rport

 

Max-Forwards: 70

 

From: "asterisk" <sip:address@hidden>;tag=as13bb3ac8

 

To: <sip:address@hidden>

 

Contact: <sip:address@hidden:5060>

 

Call-ID: address@hidden:5060

 

CSeq: 102 OPTIONS

 

User-Agent: Asterisk PBX 1.8.7.1

 

Date: Sun, 29 Apr 2012 19:07:13 GMT

 

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH

 

Supported: replaces, timer

 

Content-Length: 0

 

 

 

 

message: 2015-10-07 15:21:07:966 channel [0344AFE8] [520] bytes parsed

message: 2015-10-07 15:21:07:966 channel [0344AFE8]: message sent to [UDP://10.1.3.200:1024], size: [257] bytes

SIP/2.0 200 Ok

 

Via: SIP/2.0/UDP 10.1.3.200:5060;branch=z9hG4bK19660533;rport=1024

 

From: "asterisk" <sip:address@hidden>;tag=as13bb3ac8

 

To: <sip:address@hidden>;tag=gAoXT

 

Call-ID: address@hidden:5060

 

CSeq: 102 OPTIONS

 

 

message: 2015-10-07 15:21:07:966 Changing [client] [REGISTER] transaction [03446F48], from state [COMPLETED] to [TERMINATED]

message: 2015-10-07 15:21:07:966 Client internal REGISTER transaction [03446F48] terminated

 

 

[etc...]

 

 

Here I find the following suspicious:

message: 2015-10-07 15:21:07:905 Refresher [03446AC8]: contact address [10.1.3.37:5060] does not match channel address[(null):0].

message: 2015-10-07 15:21:07:905 belle_sip_refresher_start(): refresher [03446AC8] is resubmitting request because contact sent was not correct in original request.

 

But googling this message does not give me much hints what it is all about ... ?

 

 

 

I've found a reference to someone else who had this problem but it never got resolved

https://lists.gnu.org/archive/html/linphone-users/2008-07/msg00010.html

 

 

Note: if I connect to sip.linphone.org (through a different nic) then it works correctly

 

Any suggestions ?

 

Thanks,

Bram


reply via email to

[Prev in Thread] Current Thread [Next in Thread]