noxxi / p5-net-sip

Net::SIP Perl Module
Other
15 stars 22 forks source link

Slow DNS resolutioin #70

Open kobaz opened 1 month ago

kobaz commented 1 month ago

From the running system shell:

# time host sip.clearip.com
sip.clearip.com has address 99.83.142.252
sip.clearip.com has address 52.223.0.89

real    0m0.046s
user    0m0.008s
sys     0m0.012s

But, and not always, but randomly there will be a big delay (2-5 seconds)


  Net::SIP::Debug->level( 50 );

  my $sock_from = IO::Socket::INET->new(
    Proto     => 'tcp',
    LocalAddr => '0.0.0.0',
  );

  my $leg_from = Net::SIP::Leg->new(
    sock => $sock_from,
  );

  my $ua = Net::SIP::Simple->new(
    legs           => [$leg_from],
    from           => '123',
    outgoing_proxy => 'sip.clearip.com',
    domain         => 'sip.clearip.com',
  );

  my $invite = $ua->invite('456');
1722959154.2120 DEBUG:<10> Net::SIP::Endpoint::new_request[156]: create new request for INVITE within new call 1cd4fb7f7a6c13add9da51bee243e817
1722959154.2121 DEBUG:<50> Net::SIP::Endpoint::Context::new_request[188]: Net::SIP::Request->new, METHOD=INVITE, uri=sip:456@sip.clearip.com, from=123 <sip:123@sip.clearip.com>;tag=f0793d5fd13d5b10650c36c6b30212bc, to=456 <sip:456@sip.clearip.com\
>
1722959154.2133 DEBUG:<50> Net::SIP::Endpoint::new_request[164]: request=INVITE sip:456@sip.clearip.com SIP/2.0^M
1722959154.2133 DEBUG:<50>      Attestation-info: A^M
1722959154.2133 DEBUG:<50>      X-request-uuid: F6F9024A-540A-11EF-A406-2C06EC7E745E^M
1722959154.2133 DEBUG:<50>      Call-id: 1cd4fb7f7a6c13add9da51bee243e817^M
1722959154.2133 DEBUG:<50>      Cseq: 1 INVITE^M
1722959154.2133 DEBUG:<50>      From: 123 <sip:123@sip.clearip.com>;tag=f0793d5fd13d5b10650c36c6b30212bc^M
1722959154.2133 DEBUG:<50>      Max-forwards: 70^M
1722959154.2133 DEBUG:<50>      To: 456 <sip:456@sip.clearip.com>^M
1722959154.2133 DEBUG:<50>      Content-type: application/sdp^M
1722959154.2133 DEBUG:<50>      Content-length: 171^M
1722959154.2133 DEBUG:<50>      ^M
1722959154.2133 DEBUG:<50>      v=0^M
1722959154.2133 DEBUG:<50>      o=anonymous 1722959154 1722959154 IN IP4 0.0.0.0^M
1722959154.2133 DEBUG:<50>      s=session^M
1722959154.2133 DEBUG:<50>      c=IN IP4 0.0.0.0^M
1722959154.2133 DEBUG:<50>      t=0 0^M
1722959154.2133 DEBUG:<50>      m=audio 7354 RTP/AVP 0 101^M
1722959154.2133 DEBUG:<50>      a=rtpmap:101 telephone-event/8000^M
1722959154.2133 DEBUG:<50>      a=fmtp:101 0-16^M
1722959154.2133 DEBUG:<50>
1722959154.2142 DEBUG:<50> Net::SIP::Dispatcher::resolve_uri[779]: setting dst_addr+leg to sip.clearip.com from outgoing_proxy

<delay here>

1722959156.2161 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[178]: trigger timer(disp_expire) 1722959155.20108 repeat=<undef>

Notice: resolve_uri 1722959154.2142 to 1722959156.2161 = 2.0019 seconds

kobaz commented 1 month ago

I've been unable to reproduce this more than just a few times. Hasn't happened since last week. I'll add more debugging just in case!

kobaz commented 2 weeks ago

Found the problem. ipv6 causes slowdowns when ipv6 is not available.

Disabling ipv6 makes my test case twice as fast!

--- a/LIB/x64-perl5.28/perl/lib/perl5/Net/SIP/Util.pm
+++ b/LIB/x64-perl5.28/perl/lib/perl5/Net/SIP/Util.pm
@@ -19,7 +19,11 @@ use Net::SIP::Debug;
 use Carp qw(confess croak);
 use base 'Exporter';

+our $IPV6_ENABLE;
+
 BEGIN {
+    $IPV6_ENABLE = 1; # We'll assume we can do v6 until our tests say otherwise
+
     my $mod6 = '';
     if (eval {
    require IO::Socket::IP;
@@ -70,7 +74,7 @@ BEGIN {
    *AF_INET6 = sub() { -1 };
     }

-    *CAN_IPV6 = $mod6 ? sub() { 1 } : sub() { 0 };
+    *CAN_IPV6 = $mod6 ? sub() { $IPV6_ENABLE; } : sub() { 0 };
     Socket->import(qw(unpack_sockaddr_in6 pack_sockaddr_in6)) if $mod6;
 }

@@ -472,6 +476,7 @@ sub create_rtp_sockets {
 ###########################################################################
 sub invoke_callback {
     my ($cb,@more_args) = @_;
+
     if ( UNIVERSAL::isa( $cb,'CODE' )) {
    # anon sub
    return $cb->(@more_args)
@@ -765,6 +770,11 @@ sub mime_parse {
     return $p;
 }

+# Allow specific disable of IPv6 even if the local system is capable
+sub ipv6 {
+  $IPV6_ENABLE = $_[1];
+}
+
 package Net::SIP::Utils::_MIME;
 use fields qw(ct ctparam hdr body preamble parts postparts eol);
 Net::SIP::Util->import(qw(sip_hdrval2parts));

Usage:

  Net::SIP::Util->ipv6(0);
  my $ua = Net::SIP::Simple->new(....
kobaz commented 2 weeks ago

This allows for disabling or re-enabling ipv6 at run-time depending on needs

noxxi commented 2 weeks ago

I have a different proposal, which a) reuses the already optionally exported CAN_IPV6 function to set the value (i.e. no different functions) and b) gets called as function not method, like all other subroutines in Utils. I did not test it yet, so please check if it works. optionally-disable-ipv6.txt

kobaz commented 2 weeks ago

Thanks, I will check.

Also, I saw your old message (since deleted), about properly configured IPV6. In a perfect world: yes But in an imperfect world, for instance a service is ipv4 only.

Example: sip.clearip.com. IN AAAA is empty result.
This is an ipv4-only service.

Sometimes the query for AAAA takes 2-3 seconds waiting for a result we KNOW will be empty. So, why not skip it. My sip test is now 100ms instead of 200ms by skipping ipv6 dns lookups

kobaz commented 2 weeks ago

Also... considering this is a long-running service processing many requests (we're making 2 SIP calls per second). We should cache DNS lookups.

Can Net::SIP cache dns? Or maybe I should override the dns resolver and provide my own local-cache DNS?

kobaz commented 2 weeks ago

I have implemented DNS cache, so hopefully this should solve the rest of this for me. My goal: Process each call in less than 5 seconds with the ideal target of 100ms If the call cannot finish in 5 seconds this is a fail. We want to avoid this.

Now there's only one last issue to fix for our situation, which is when prio is missing -- #68