[Home]

Summary:ASTERISK-20562: Contact information appears to be mis-parsed and registered incorrectly
Reporter:Nir Simionovich (GreenfieldTech - Israel) (greenfieldtech)Labels:
Date Opened:2012-10-15 04:26:54Date Closed:2012-11-08 23:18:08.000-0600
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:10.9.0 Frequency of
Occurrence
Related
Issues:
Environment:Amazon EC2, 4ECU, 7.5GB RAM, CentOS 5.8 64bit, sip friends are configured via MySQL RealtimeAttachments:
Description:When utilizing mobile phones, using csipsimple (Android + PJSIP) or iPhone (idoubs), for some odd reason contact information appears to contain information that isn't supposed to be there.

Issue manifests when elevating logger, the following appears:

{noformat}
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'
{noformat}

it is true that my return port is 45183, however, why is the Agent version appearing in there? In the SIP trace, the information appears to be clean, at least from what I can tell.

Following below is a SIP trace:


{noformat}
<--- SIP read from UDP:46.19.81.28:61832 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.28:37784;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 46.19.81.28:61832 (NAT)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- Transmitting (NAT) to 46.19.81.28:61832 --->
SIP/2.0 401 Unauthorized
ia: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s;received=46.19.81.28;rport=61832
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>;tag=as328366cb
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="06b15c02"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB' in 32000 ms (Method: REGISTER)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- SIP read from UDP:46.19.81.28:61832 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.28:37784;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 46.19.81.28:61832 (NAT)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- Transmitting (NAT) to 46.19.81.28:61832 --->
SIP/2.0 401 Unauthorized
ia: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s;received=46.19.81.28;rport=61832
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>;tag=as328366cb
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="06b15c02"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB' in 32000 ms (Method: REGISTER)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- SIP read from UDP:46.19.81.28:61832 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.28:37784;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 46.19.81.28:61832 (NAT)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- Transmitting (NAT) to 46.19.81.28:61832 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjXF5Fl8qPZaVEEuV9I6.Z.2LP8mPoj-6s;received=46.19.81.28;rport=61832
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>;tag=as328366cb
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50867 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="06b15c02"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB' in 32000 ms (Method: REGISTER)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'

<--- SIP read from UDP:46.19.81.28:61832 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjPxbivdyWIZU6yQkWnVGqL3A7WuHRLRJs
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50868 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.28:37784;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="972546982826", realm="asterisk", nonce="06b15c02", uri="sip:107.21.118.127", response="4473e2fb85a4f63853e23ebcf6c56989", algorithm=MD5
Content-Length: 0

<------------->
--- (14 headers 0 lines) ---
Sending to 46.19.81.28:61832 (NAT)
[Oct 15 05:20:08] ERROR[1721]: netsock2.c:269 ast_sockaddr_resolve: getaddrinfo("46.19.81.28", "45183^CSipSimple_GT-I9100T", ...): Servname not supported for ai_socktype
[Oct 15 05:20:08] WARNING[1721]: chan_sip.c:14460 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '46.19.81.28:45183^CSipSimple_GT-I9100T'
   -- Registered SIP '972546982826' at 46.19.81.28:61832
      > Saved useragent "CSipSimple_GT-I9100T-15/r1916" for peer 972546982826

<--- Transmitting (NAT) to 46.19.81.28:61832 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 46.19.81.28:37784;branch=z9hG4bKPjPxbivdyWIZU6yQkWnVGqL3A7WuHRLRJs;received=46.19.81.28;rport=61832
From: <sip:972546982826@107.21.118.127>;tag=U.Mb.Mzii-pItvZ4ptMc3jsvxFSRn5JB
To: <sip:972546982826@107.21.118.127>;tag=as328366cb
Call-ID: xaZ7Ogr6KCYuTwyBZO4SS61cBsqK4rZB
CSeq: 50868 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 900
Contact: <sip:972546982826@46.19.81.28:37784;ob>;expires=900
Date: Mon, 15 Oct 2012 09:20:08 GMT
Content-Length: 0
{noformat}
Comments:By: Michael L. Young (elguero) 2012-10-15 09:38:58.684-0500

A SIP pcap might be helpful to confirm what is being displayed on the console.  Are you able to upload a pcap please?

Thanks
By: Walter Doekes (wdoekes) 2012-10-15 09:50:04.702-0500

Is there some realtime going on too, perhaps?

That ^ looks like the asterisk DB escape for ;
By: Walter Doekes (wdoekes) 2012-10-15 09:50:43.656-0500

I'd be interested in a 'core set debug 10' debug output.
By: Nir Simionovich (GreenfieldTech - Israel) (greenfieldtech) 2012-10-17 15:53:14.806-0500

@Walter, you are correct - the backend is a an Asterisk realtime used for sip friends only.

By: Nir Simionovich (GreenfieldTech - Israel) (greenfieldtech) 2012-10-17 16:39:49.632-0500

Ok, this is really odd - suddenly, without changing anything - it simply stopped doing it.
Here is a level 10 debug of the registration:

{noformat}
<--- SIP read from UDP:46.19.81.113:55873 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjYbiZO.-EiE32j69hoNSl2gssAKNTCQf0
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
To: <sip:972546982826@107.21.118.127>
Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
CSeq: 26493 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.113:42605>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  0 [ 35]: REGISTER sip:107.21.118.127 SIP/2.0
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  1 [ 84]: Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjYbiZO.-EiE32j69hoNSl2gssAKNTCQf0
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  2 [ 44]: Route: <sip:107.21.118.127;transport=udp;lr>
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  3 [ 16]: Max-Forwards: 70
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  4 [ 76]: From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  5 [ 37]: To: <sip:972546982826@107.21.118.127>
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  6 [ 41]: Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  7 [ 20]: CSeq: 26493 REGISTER
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  8 [ 41]: User-Agent: CSipSimple_GT-I9100T-15/r1916
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  9 [ 46]: Contact: <sip:972546982826@46.19.81.113:42605>
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 10 [ 12]: Expires: 900
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 11 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 12 [ 17]: Content-Length: 0
--- (13 headers 0 lines) ---
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:8329 find_call: = Looking for  Call ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J (Checking From) --From tag 23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh --To-tag  
[Oct 17 17:38:51] DEBUG[13129]: acl.c:736 ast_ouraddrfor: For destination '46.19.81.113', our source address is '10.100.202.22'.
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:3540 ast_sip_ouraddrfor: Target address 46.19.81.113:55873 is not local, substituting externaddr
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:3573 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 107.21.118.127:5060
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:7960 sip_alloc: Allocating new SIP dialog for EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J - REGISTER (No RTP)
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:26169 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:25994 handle_request_register: Initializing initreq for method REGISTER - callid EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113:42605' into...
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port '42605'.
Sending to 46.19.81.113:55873 (NAT)
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '107.21.118.127' into...
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '107.21.118.127' and port ''.
[Oct 17 17:38:51] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:51] DEBUG[13129]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '972546982826' AND host = 'dynamic'
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:28405 build_peer: -REALTIME- peer built. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113:42605' into...
[Oct 17 17:38:51] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port '42605'.
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:28951 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:51] DEBUG[13129]: chan_sip.c:28954 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:51] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:51] DEBUG[13129]: res_config_mysql.c:641 update_mysql: MySQL RealTime: Update SQL: UPDATE sipfriends SET `fullcontact` = '', `ipaddr` = '', `port` = '', `regseconds` = '0', `regserver` = '', `useragent` = '', `lastms` = '0' WHERE `name` = '972546982826'
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:655 update_mysql: MySQL RealTime: Updated 1 rows on table: sipfriends
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28967 build_peer: Bah, we're expired (4/1350509927/1350509931)!
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:5067 realtime_peer: -REALTIME- loading peer from database to memory. Name: 972546982826. Peer objects: 1

--- Transmitting (NAT) to 46.19.81.113:55873 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjYbiZO.-EiE32j69hoNSl2gssAKNTCQf0;received=46.19.81.113;rport=55873
From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
To: <sip:972546982826@107.21.118.127>;tag=as6b6c4a14
Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
CSeq: 26493 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2ea842f5"
Content-Length: 0


<------------>
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:3421 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 46.19.81.113:55873
Scheduling destruction of SIP dialog 'EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J' in 32000 ms (Method: REGISTER)
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4695 sip_destroy_peer: Destroying SIP peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4732 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 972546982826. Realtime Peer objects: 0
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '972546982826' AND host = 'dynamic'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28405 build_peer: -REALTIME- peer built. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28946 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28949 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28951 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28954 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28967 build_peer: Bah, we're expired (1350509932/0/1350509932)!
[Oct 17 17:38:52] DEBUG[13129]: db.c:329 ast_db_get: Unable to find key '972546982826' in family 'SIP/Registry'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:5067 realtime_peer: -REALTIME- loading peer from database to memory. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4695 sip_destroy_peer: Destroying SIP peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4732 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 972546982826. Realtime Peer objects: 0

<--- SIP read from UDP:46.19.81.113:55873 --->
REGISTER sip:107.21.118.127 SIP/2.0
Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjkjNwAckaQhNVC5fLMBugfo.ncl2JEk7Q
Route: <sip:107.21.118.127;transport=udp;lr>
Max-Forwards: 70
From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
To: <sip:972546982826@107.21.118.127>
Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
CSeq: 26494 REGISTER
User-Agent: CSipSimple_GT-I9100T-15/r1916
Contact: <sip:972546982826@46.19.81.113:42605>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="972546982826", realm="asterisk", nonce="2ea842f5", uri="sip:107.21.118.127", response="64a75833fb7c53af42f30890b7d33308", algorithm=MD5
Content-Length: 0

<------------->
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  0 [ 35]: REGISTER sip:107.21.118.127 SIP/2.0
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  1 [ 84]: Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjkjNwAckaQhNVC5fLMBugfo.ncl2JEk7Q
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  2 [ 44]: Route: <sip:107.21.118.127;transport=udp;lr>
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  3 [ 16]: Max-Forwards: 70
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  4 [ 76]: From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  5 [ 37]: To: <sip:972546982826@107.21.118.127>
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  6 [ 41]: Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  7 [ 20]: CSeq: 26494 REGISTER
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  8 [ 41]: User-Agent: CSipSimple_GT-I9100T-15/r1916
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header  9 [ 46]: Contact: <sip:972546982826@46.19.81.113:42605>
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 10 [ 12]: Expires: 900
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 11 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 12 [167]: Authorization: Digest username="972546982826", realm="asterisk", nonce="2ea842f5", uri="sip:107.21.118.127", response="64a75833fb7c53af42f30890b7d33308", algorithm=MD5
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8766 parse_request:  Header 13 [ 17]: Content-Length: 0
--- (14 headers 0 lines) ---
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:8329 find_call: = Looking for  Call ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J (Checking From) --From tag 23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh --To-tag  
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '107.21.118.127' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '107.21.118.127' and port ''.
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '107.21.118.127' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '107.21.118.127' and port ''.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:26169 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:25994 handle_request_register: Initializing initreq for method REGISTER - callid EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113:42605' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port '42605'.
Sending to 46.19.81.113:55873 (NAT)
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '107.21.118.127' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '107.21.118.127' and port ''.
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '972546982826' AND host = 'dynamic'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28405 build_peer: -REALTIME- peer built. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28946 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28949 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28951 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28954 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28967 build_peer: Bah, we're expired (1350509932/0/1350509932)!
[Oct 17 17:38:52] DEBUG[13129]: db.c:329 ast_db_get: Unable to find key '972546982826' in family 'SIP/Registry'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:5067 realtime_peer: -REALTIME- loading peer from database to memory. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:14623 parse_register_contact: Store REGISTER's src-IP:port for call routing.
   -- Registered SIP '972546982826' at 46.19.81.113:55873
      > Saved useragent "CSipSimple_GT-I9100T-15/r1916" for peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:641 update_mysql: MySQL RealTime: Update SQL: UPDATE sipfriends SET `ipaddr` = '46.19.81.113', `port` = '55873', `regseconds` = '1350510832', `defaultuser` = '972546982826', `useragent` = 'CSipSimple_GT-I9100T-15/r1916', `lastms` = '0', `fullcontact` = 'sip:972546982826@46.19.81.113:42605' WHERE `name` = '972546982826'
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:655 update_mysql: MySQL RealTime: Updated 1 rows on table: sipfriends

<--- Transmitting (NAT) to 46.19.81.113:55873 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 46.19.81.113:42605;branch=z9hG4bKPjkjNwAckaQhNVC5fLMBugfo.ncl2JEk7Q;received=46.19.81.113;rport=55873
From: <sip:972546982826@107.21.118.127>;tag=23izG6DF9KDkHIdn0IOGbmIrRaO0ZlDh
To: <sip:972546982826@107.21.118.127>;tag=as6b6c4a14
Call-ID: EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J
CSeq: 26494 REGISTER
Server: Asterisk PBX 10.9.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 900
Contact: <sip:972546982826@46.19.81.113:42605>;expires=900
Date: Wed, 17 Oct 2012 21:38:52 GMT
Content-Length: 0


<------------>
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:3421 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 46.19.81.113:55873
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4695 sip_destroy_peer: Destroying SIP peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4732 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 972546982826. Realtime Peer objects: 0
Scheduling destruction of SIP dialog 'EzDrkRInbwQzWUUe0ReLny.s9MPs5q6J' in 32000 ms (Method: REGISTER)
[Oct 17 17:38:52] DEBUG[13109]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 972546982826
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:27520 sip_devicestate: Checking device state for peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:52] DEBUG[13129]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '972546982826' AND host = 'dynamic'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28405 build_peer: -REALTIME- peer built. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port ''.
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113:42605' into...
[Oct 17 17:38:52] DEBUG[13129]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port '42605'.
[Oct 17 17:38:52] DEBUG[13109]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28951 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:28954 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:5067 realtime_peer: -REALTIME- loading peer from database to memory. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13109]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sipfriends WHERE name = '972546982826' AND host = 'dynamic'
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4695 sip_destroy_peer: Destroying SIP peer 972546982826
[Oct 17 17:38:52] DEBUG[13129]: chan_sip.c:4732 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 972546982826. Realtime Peer objects: 0
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:28405 build_peer: -REALTIME- peer built. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13109]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '46.19.81.113' into...
[Oct 17 17:38:52] DEBUG[13109]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '46.19.81.113' and port ''.
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:28951 build_peer: Not an IPv4 nor IPv6 address, cannot get port.
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:28954 build_peer: Not an IPv4 nor IPv6 address, cannot set port.
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:5067 realtime_peer: -REALTIME- loading peer from database to memory. Name: 972546982826. Peer objects: 1
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:4695 sip_destroy_peer: Destroying SIP peer 972546982826
[Oct 17 17:38:52] DEBUG[13109]: chan_sip.c:4732 sip_destroy_peer: -REALTIME- peer Destroyed. Name: 972546982826. Realtime Peer objects: 0
[Oct 17 17:38:52] DEBUG[13109]: devicestate.c:460 do_state_change: Changing state for SIP/972546982826 - state 1 (Not in use)
[Oct 17 17:38:52] DEBUG[13109]: devicestate.c:440 devstate_event: device 'SIP/972546982826' state '1'
[Oct 17 17:38:52] DEBUG[13138]: app_queue.c:1514 handle_statechange: Device 'SIP/972546982826' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
ip-10-100-202-22*CLI>
{noformat}

By: Richard Mudgett (rmudgett) 2012-10-17 17:38:49.115-0500

Please attach log files as .txt files.  Don't paste them inline.  Logs make it difficult to scroll through the issue.  Also JIRA loves to format the comments.
By: Nir Simionovich (GreenfieldTech - Israel) (greenfieldtech) 2012-10-18 03:06:44.883-0500

oops, sorry
By: Walter Doekes (wdoekes) 2012-10-18 03:30:23.691-0500

Nir, earlier, your trace contained this:
{noformat}
Contact: <sip:972546982826@46.19.81.28:37784;ob>
{noformat}

In your later trace (where it didn't occur, it contains this):
{noformat}
Contact: <sip:972546982826@46.19.81.113:42605>
{noformat}

What happens if you reenable that ob tag in your CSipSimple?
{quote}
  "ob" Parameter: [...]
     In a Contact or Route header field
     value, it indicates that the UA would like other requests in the
     same dialog to be routed over the same flow.
{quote}
By: Rusty Newton (rnewton) 2012-11-08 15:47:49.266-0600

Nir, can the problem still be reproduced?
By: Nir Simionovich (GreenfieldTech - Israel) (greenfieldtech) 2012-11-08 15:53:03.219-0600

Well, we've upgraded the version of Csipsimple, and it would appear that the information is now sent in a different manner - allowing Asterisk to work correctly. I'm still not confident if this is a csipsimple issue, a pjsip issue or an Asterisk issue.

I will conduct more tests on this issue to verify and see what can be obtained - for the time being, it just works for some reason.
By: Michael L. Young (elguero) 2012-11-08 23:17:11.721-0600

I just played around with adding the "ob" parameter to the contact header field in the code right before Asterisk parses it and everything seemed to be parsed properly.

It looks like this can be closed for now.  If you come across this problem again, let us know and we can take a look at it with fresh debug information.