asterisk users - Aug 2020 - PJSIP trunk is down when DNS was not available during the Asterisk start.

I see that pjsip_resolver.c tries unsuccessfuly to resolve the
hostname each 10 seconds:

[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Wrapper created
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Set timer to 2000
msec
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Performing SIP DNS
resolution of target 'rpi6.in.xorcom.com'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Transport type for
target 'rpi6.in.xorcom.com' is 'Unspecified'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Created resolution tracking for target 'rpi6.in.xorcom.com'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Added target 'rpi6.in.xorcom.com' with record type '35',
transport
'Unspecified', and port '0'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Added target '_sips._tcp.rpi6.in.xorcom.com' with record type
'33',
transport 'TLS', and port '5061'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Added target '_sip._tcp.rpi6.in.xorcom.com' with record type
'33',
transport 'TCP', and port '5060'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Added target '_sip._udp.rpi6.in.xorcom.com' with record type
'33',
transport 'UDP', and port '5060'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Added target 'rpi6.in.xorcom.com' with record type '1',
transport 'UDP',
and port '5060'
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Starting initial resolution using parallel queries for target '
rpi6.in.xorcom.com'
[Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
All parallel queries completed
[Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Resolution completed - 0 viable targets
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
Invoking user callback with '0' addresses
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: PJSIP tsx
response received
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Cancelling timer
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Timer cancelled
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Callbacks
executed
[Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: wrapper destroyed
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: Contact g145/sip:
rpi6.in.xorcom.com status didn't change: Unreachable, RTT: 0.000 msec
[Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: AOR 'g145' now
has
0 available contacts

But a DNS server is available at this time:
# host rpi6.in.xorcom.com
rpi6.in.xorcom.com has address 192.168.0.175

# ping rpi6.in.xorcom.com
PING rpi6.in.xorcom.com (192.168.0.175) 56(84) bytes of data.
64 bytes from rpi6.in.xorcom.com (192.168.0.175): icmp_seq=1 ttl=64
time=0.990 ms

Thank you,
Leonid Fainshtein



On Thu, Aug 27, 2020 at 1:52 PM Joshua C. Colp <jcolp at sangoma.com>
wrote:
> On Thu, Aug 27, 2020 at 7:48 AM Leonid Fainshtein <
> leonid.fainshtein at xorcom.com> wrote:
>
>> Hi,
>> I have Asterisk 16.x with a trunk configured with a hostname in PJSIP
AOR.
>> The registration is not required for this trunk.
>> I paid attention that Asterisk performs DNS resolving of the hostname
>> that is configured in the AOR 'contact' parameter only upon the
Asterisk
>> start only.
>> Thus, if Asterisk is started when the DNS server is unreachable due to
>> the Internet connection failure then the 'contact' will be not
resolvable
>> forever even when the Internet connection is returned. As a result of
that,
>> the 'qualify' procedure is not performed and the trunk status
is 'Unavail'.
>> The only way to revive the trunk is to restart Asterisk. Even
'pjsip
>> reload' doesn't solve the problem.
>> Is it the 'by design' Asterisk behavior or I have missed
something?
>>
>
> PJSIP in Asterisk uses asynchronous DNS, so it should resolve at the time
> the request is actually made and should work afterwards. Not doing so would
> be a bug, and collecting a debug level log (debug to a file in logger.conf
> with core set debug 9) would explicitly show what is going on for DNS.
>
> --
> Joshua C. Colp
> Asterisk Technical Lead
> Sangoma Technologies
> Check us out at www.sangoma.com and www.asterisk.org
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
>
> Check out the new Asterisk community forum at:
> https://community.asterisk.org/
>
> New to Asterisk? Start here:
>       https://wiki.asterisk.org/wiki/display/AST/Getting+Started
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20200827/878d4160/attachment.html>

On Thu, Aug 27, 2020 at 8:58 AM Leonid Fainshtein <
leonid.fainshtein at xorcom.com> wrote:
> I see that pjsip_resolver.c tries unsuccessfuly to resolve the
> hostname each 10 seconds:
>
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Wrapper created
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Set timer to
> 2000 msec
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Performing SIP
> DNS resolution of target 'rpi6.in.xorcom.com'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Transport type
> for target 'rpi6.in.xorcom.com' is 'Unspecified'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Created resolution tracking for target 'rpi6.in.xorcom.com'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Added target 'rpi6.in.xorcom.com' with record type '35',
transport
> 'Unspecified', and port '0'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Added target '_sips._tcp.rpi6.in.xorcom.com' with record type
'33',
> transport 'TLS', and port '5061'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Added target '_sip._tcp.rpi6.in.xorcom.com' with record type
'33',
> transport 'TCP', and port '5060'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Added target '_sip._udp.rpi6.in.xorcom.com' with record type
'33',
> transport 'UDP', and port '5060'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Added target 'rpi6.in.xorcom.com' with record type '1',
transport 'UDP',
> and port '5060'
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Starting initial resolution using parallel queries for target '
> rpi6.in.xorcom.com'
> [Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> All parallel queries completed
> [Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Resolution completed - 0 viable targets
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: [0x7f75282fe7f8]
> Invoking user callback with '0' addresses
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: PJSIP tsx
> response received
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Cancelling timer
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Timer cancelled
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Callbacks
> executed
> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: wrapper
> destroyed
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: Contact g145/sip:
> rpi6.in.xorcom.com status didn't change: Unreachable, RTT: 0.000 msec
> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: AOR 'g145'
now has
> 0 available contacts
>
> But a DNS server is available at this time:
> # host rpi6.in.xorcom.com
> rpi6.in.xorcom.com has address 192.168.0.175
>
> # ping rpi6.in.xorcom.com
> PING rpi6.in.xorcom.com (192.168.0.175) 56(84) bytes of data.
> 64 bytes from rpi6.in.xorcom.com (192.168.0.175): icmp_seq=1 ttl=64
> time=0.990 ms
>
What DNS resolver implementation is in use? system or unbound?

Asterisk itself doesn't do any caching, we defer it to the underlying
implementation. It could be caching a negative response.

-- 
Joshua C. Colp
Asterisk Technical Lead
Sangoma Technologies
Check us out at www.sangoma.com and www.asterisk.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20200827/5580586e/attachment.html>

I deleted the res_resolver_unbound.so module, and now it works as expected.
So, the problem is related to the 'unbound' resolver?
FYI: I'm using Asterisk 16.2 installed from Debian 10 repository.

Best regards,
Leonid Fainshtein

On Thu, Aug 27, 2020 at 3:01 PM Joshua C. Colp <jcolp at sangoma.com>
wrote:
> On Thu, Aug 27, 2020 at 8:58 AM Leonid Fainshtein <
> leonid.fainshtein at xorcom.com> wrote:
>
>> I see that pjsip_resolver.c tries unsuccessfuly to resolve the
>> hostname each 10 seconds:
>>
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Wrapper
created
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Set timer to
>> 2000 msec
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Performing SIP
>> DNS resolution of target 'rpi6.in.xorcom.com'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c: Transport type
>> for target 'rpi6.in.xorcom.com' is 'Unspecified'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Created resolution tracking for target 'rpi6.in.xorcom.com'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Added target 'rpi6.in.xorcom.com' with record type
'35', transport
>> 'Unspecified', and port '0'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Added target '_sips._tcp.rpi6.in.xorcom.com' with record type
'33',
>> transport 'TLS', and port '5061'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Added target '_sip._tcp.rpi6.in.xorcom.com' with record type
'33',
>> transport 'TCP', and port '5060'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Added target '_sip._udp.rpi6.in.xorcom.com' with record type
'33',
>> transport 'UDP', and port '5060'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Added target 'rpi6.in.xorcom.com' with record type '1',
transport 'UDP',
>> and port '5060'
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Starting initial resolution using parallel queries for target '
>> rpi6.in.xorcom.com'
>> [Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> All parallel queries completed
>> [Aug 27 07:51:36] DEBUG[605] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Resolution completed - 0 viable targets
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_resolver.c:
[0x7f75282fe7f8]
>> Invoking user callback with '0' addresses
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: PJSIP tsx
>> response received
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Cancelling
>> timer
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Timer
cancelled
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: Callbacks
>> executed
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip.c: 0x7f75282eb150: wrapper
>> destroyed
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: Contact
g145/sip:
>> rpi6.in.xorcom.com status didn't change: Unreachable, RTT: 0.000
msec
>> [Aug 27 07:51:36] DEBUG[595] res_pjsip/pjsip_options.c: AOR
'g145' now
>> has 0 available contacts
>>
>> But a DNS server is available at this time:
>> # host rpi6.in.xorcom.com
>> rpi6.in.xorcom.com has address 192.168.0.175
>>
>> # ping rpi6.in.xorcom.com
>> PING rpi6.in.xorcom.com (192.168.0.175) 56(84) bytes of data.
>> 64 bytes from rpi6.in.xorcom.com (192.168.0.175): icmp_seq=1 ttl=64
>> time=0.990 ms
>>
>
> What DNS resolver implementation is in use? system or unbound?
>
> Asterisk itself doesn't do any caching, we defer it to the underlying
> implementation. It could be caching a negative response.
>
> --
> Joshua C. Colp
> Asterisk Technical Lead
> Sangoma Technologies
> Check us out at www.sangoma.com and www.asterisk.org
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
>
> Check out the new Asterisk community forum at:
> https://community.asterisk.org/
>
> New to Asterisk? Start here:
>       https://wiki.asterisk.org/wiki/display/AST/Getting+Started
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20200827/d740bb35/attachment.html>