[Home]

Summary:ASTERISK-25528: DNS: System resolver issues with TTL parse
Reporter:dtryba (dtryba)Labels:
Date Opened:2015-11-06 08:06:51.000-0600Date Closed:2015-11-16 11:31:21.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Core/General
Versions:SVN Frequency of
Occurrence		Frequent
Related
Issues:
Environment:Debian/jessie Build from source with checkout 40574a2ea31f03d5a4d3914f1e20895a9b49d7f0 and pjsip svn revision 5193 from http://svn.pjsip.org/reposAttachments:( 0) dns.pcap
( 1) full.txt
Description:Trying to register to a SIP cluster using NAPTR/SRV records fails due to DNS lookup failures. The failures are due to incorrect parsing the TTL for the records.

sip.itco.nl has both NAPT and SRV records (with short ttls (300)), The real edge proxies (sip[01].itco.nl)) have a longer ttl (86400). Responses aren't added to the result set with debug responses:
{noformat}
dns_core.c: Query '0x7f66cc00a3c8': Could not add record, invalid TTL '-822083584'
{noformat}
resulting in
{noformat}
res_pjsip/pjsip_resolver.c: [0x7f66cc009588] Resolution completed - 0 viable targets
{noformat}
{noformat}
[transport-udp]
type=transport
protocol=udp
bind=0.0.0.0

[transport-tcp]
type=transport
protocol=tcp
bind=0.0.0.0

[tryba]
type=endpoint
transport=transport-udp
context=tryba
disallow=all
allow=alaw
outbound_auth=tryba_auth
force_rport=yes
direct_media=no
ice_support=yes
auth=tryba_auth

[tryba_auth]
type=auth
auth_type=userpass
password=******
username=tryba

[tryba_register]
type=registration
server_uri=sip:sip.itco.nl
client_uri=sip:tryba@sip.itco.nl
contact_user = tryba
outbound_auth=tryba_auth
expiration=60
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2015-11-06 08:06:51.907-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: dtryba (dtryba) 2015-11-06 08:08:06.753-0600

logs and packet capture
By: Rusty Newton (rnewton) 2015-11-06 09:13:32.560-0600

Reattaching full log as full.txt for accessibility.
By: George Joseph (gjoseph) 2015-11-06 10:17:56.926-0600

Daniel,

Can you check with the current released version of Asterisk (13.6.0)?  The commit you reference is only in the "master" branch and should not be considered stable.

By: dtryba (dtryba) 2015-11-06 10:57:51.249-0600

13.6.0 behave completly different. The A records appear to be cached somewhere (dnsmgr is disabled)

A restart of asterisk (during previous tests a register was succefully resolved):

{noformat}
[Nov  6 17:47:57] DEBUG[7562] pjsip:          endpoint Request msg REGISTER/cseq=55164 (tdta0x7f0c8c004fd0) created.
[Nov  6 17:47:57] DEBUG[7562] res_pjsip_outbound_registration.c: Outbound REGISTER attempt 1 to 'sip:sip.itco.nl' with client 'sip:tryba@sip.itco.nl'
[Nov  6 17:47:57] DEBUG[7562] pjsip:    tsx0x7f0c8c006 .Transaction created for Request msg REGISTER/cseq=55165 (tdta0x7f0c8c004fd0)
[Nov  6 17:47:57] DEBUG[7562] pjsip:    tsx0x7f0c8c006 Sending Request msg REGISTER/cseq=55165 (tdta0x7f0c8c004fd0) in state Null
[Nov  6 17:47:57] DEBUG[7562] pjsip:     sip_resolve.c .Starting async DNS SRV query: target=_sip._udp.sip.itco.nl, transport=Unspecified, port=0
[Nov  6 17:47:57] DEBUG[7562] pjsip:    _sip._udp.sip. .Starting async DNS SRV query_job: target=_sip._udp.sip.itco.nl:5060
[Nov  6 17:47:57] DEBUG[7562] pjsip:        resolver.c .Nameserver 10.0.1.71:53 state changed Active --> Probing
[Nov  6 17:47:57] DEBUG[7562] pjsip:        resolver.c .Nameserver 10.255.254.79:53 state changed Active --> Probing
[Nov  6 17:47:57] DEBUG[7562] pjsip:        resolver.c .Transmitting 39 bytes to NS 0 (10.0.1.71:53): DNS SRV query for _sip._udp.sip.itco.nl: Success
[Nov  6 17:47:57] DEBUG[7562] pjsip:        resolver.c .Transmitting 39 bytes to NS 1 (10.255.254.79:53): DNS SRV query for _sip._udp.sip.itco.nl: Success
[Nov  6 17:47:57] DEBUG[7562] pjsip:    tsx0x7f0c8c006 .State changed from Null to Calling, event=TX_MSG
[Nov  6 17:47:57] DEBUG[7567] pjsip:        resolver.c Received 135 bytes DNS response from 10.0.1.71:53
[Nov  6 17:47:57] DEBUG[7567] pjsip:        resolver.c Nameserver 10.0.1.71:53 state changed Probing --> Active
[Nov  6 17:47:57] DEBUG[7567] pjsip:    _sip._udp.sip. SRV query_job for _sip._udp.sip.itco.nl completed, 2 of 2 total entries selected:
[Nov  6 17:47:57] DEBUG[7567] pjsip:    _sip._udp.sip.  0: SRV 1 1 5060 sip1.itco.nl (109.235.32.56)
[Nov  6 17:47:57] DEBUG[7567] pjsip:    _sip._udp.sip.  1: SRV 1 1 5060 sip0.itco.nl (109.235.32.55)
[Nov  6 17:47:57] DEBUG[7567] pjsip:    _sip._udp.sip. Server resolution complete, 2 server entry(s) found
{noformat}

is backed by only these DNS requests:

{noformat}
25 129.994977   10.0.3.176 -> 10.0.1.71    DNS 83 Standard query 0x0001  SRV _sip._udp.sip.itco.nl
26 129.995046   10.0.3.176 -> 10.255.254.79 DNS 83 Standard query 0x0001  SRV _sip._udp.sip.itco.nl
27 129.995309    10.0.1.71 -> 10.0.3.176   DNS 179 Standard query response 0x0001  SRV 1 1 5060 sip0.itco.nl SRV 1 1 5060 sip1.itco.nl
28 129.997371 10.255.254.79 -> 10.0.3.176   DNS 179 Standard query response 0x0001  SRV 1 1 5060 sip1.itco.nl SRV 1 1 5060 sip0.itco.nl
{noformat}

By: George Joseph (gjoseph) 2015-11-06 12:09:10.090-0600

In other words, you get the correct results in 13.6.0, correct?
By: dtryba (dtryba) 2015-11-06 13:09:13.223-0600

Yes, 13.6.0 resolves the destination and gets registered. No problem during the short testing run. I'll continue my observations on monday.

But I'm amazed by the fact I can't see Asterisk resolving the A records returned for the hostnames in the SRV records. There is no caching of DNS results on the system level and a quick scan the places where asterisk might store results on disk don't show me anything. Also lacking compared to git master is the use of NAPTR.
By: George Joseph (gjoseph) 2015-11-06 13:30:38.980-0600

Ok, so I'm going to change the affected version to SVN (which is actually git master).

The A records are actually in the "additional section" of the SRV answer.

I can reproduce this now so let me look at it more.


By: George Joseph (gjoseph) 2015-11-06 13:31:17.219-0600

Confirmed bug in master.  Working on it.

By: dtryba (dtryba) 2015-11-11 09:31:47.512-0600

Resolving of the endpoints is apparantly solved.  But....

Lookin at the following output:
{noformat}
[Nov 11 16:13:45] DEBUG[31857] res_pjsip_outbound_registration.c: Outbound REGISTER attempt 1 to 'sip:sip.itco.nl' with client 'sip:tryba@sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31857] pjsip:   tsx0x7f06bc006 .Transaction created for Request msg REGISTER/cseq=56207 (tdta0x7f06bc005600)
[Nov 11 16:13:45] DEBUG[31857] pjsip:   tsx0x7f06bc006 Sending Request msg REGISTER/cseq=56207 (tdta0x7f06bc005600) in state Null
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target 'sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: Transport type for target 'sip.itco.nl' is 'Unspecified'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Created resolution tracking for target 'sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target 'sip.itco.nl' with record type '35', transport 'Unspecified', and port '0'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target '_sip._tcp.sip.itco.nl' with record type '33', transport 'TCP', and port '5060'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target '_sip._udp.sip.itco.nl' with record type '33', transport 'UDP', and port '5060'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target 'sip.itco.nl' with record type '1', transport 'UDP', and port '5060'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Starting initial resolution using parallel queries for target 'sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31857] pjsip:   tsx0x7f06bc006 .State changed from Null to Calling, event=TX_MSG
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] All parallel queries completed
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] NAPTR record received on target 'sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target '_sip._tcp.sip.itco.nl' with record type '33', transport 'TCP', and port '5060'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] SRV record received on target '_sip._tcp.sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target 'sip1.itco.nl' with record type '1', transport 'TCP', and port '5060'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] SRV record received on target '_sip._udp.sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target 'sip1.itco.nl' with record type '1', transport 'UDP', and port '5060'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] A record being skipped on target 'sip.itco.nl' because NAPTR or SRV record exists
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] New queries added, performing parallel resolution again
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] All parallel queries completed
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] SRV record received on target '_sip._tcp.sip.itco.nl'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Added target 'sip0.itco.nl' with record type '1', transport 'TCP', and port '5060'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] A record being skipped on target 'sip1.itco.nl' because NAPTR or SRV record exists
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] A record being skipped on target 'sip1.itco.nl' because NAPTR or SRV record exists
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] New queries added, performing parallel resolution again
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] All parallel queries completed
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] A record received on target 'sip0.itco.nl'
[Nov 11 16:13:45] DEBUG[31847] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Resolution completed - 1 viable targets
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Address '0' is 109.235.32.55:5060 with transport 'TCP'
[Nov 11 16:13:45] DEBUG[31857] res_pjsip/pjsip_resolver.c: [0x7f06bc009868] Invoking user callback with '1' addresses
[Nov 11 16:13:45] DEBUG[31857] pjsip:   tcpc0x7f06bc00 TCP client transport created
{noformat}

A register is being attempted using TCP. NAPTR records have UDP as highest priority, so protocol selection is faulty
{noformat}
$ host -t NAPTR sip.itco.nl
sip.itco.nl has NAPTR record 10 1 "s" "SIP+D2U" "" _sip._udp.sip.itco.nl.
sip.itco.nl has NAPTR record 100 1 "s" "SIP+D2T" "" _sip._tcp.sip.itco.nl.
{noformat}

tested with git: c1abe8906dd4696bc85697cfbbff2c9fca6af4d6
By: Asterisk Team (asteriskteam) 2015-11-11 09:31:48.437-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: George Joseph (gjoseph) 2015-11-11 18:07:11.539-0600

Ok, I'm looking at it again.

By: George Joseph (gjoseph) 2015-11-16 11:31:21.511-0600

I'm closing this issue and opening another for the naptr priority problem

Opened bug

https://issues.asterisk.org/jira/browse/ASTERISK-25565