|
From: | Bram Peeters |
Subject: | [Linphone-users] Linphone keeps sending register messages |
Date: | Wed, 7 Oct 2015 13:32:03 +0000 |
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
|
[Prev in Thread] | Current Thread | [Next in Thread] |