Net::SIP Will randomly send sometimes TWO INVITEs when multiple A records found for destination

[kobaz]

Situation: Sending INVITE to sip.clearip.com $ host sip.clearip.com sip.clearip.com has address 52.223.0.89 sip.clearip.com has address 99.83.142.252

Problem: Randomly (one in every 1000 calls roughly), Net::SIP will send an INVITE to EACH A record found for sip.clearip.com, instead of picking one and sending only one INVITE as one would expect.

Using this test code:

#!/usr/bin/perl
use lib '/usr/local/library/perl/lib/perl5';

use warnings;
use strict;
no strict 'refs';
use feature 'say';
use feature 'state';

use Net::SIP qw(:debug);
use Net::SIP::Simple;
use Net::SIP::Simple::Call;
use URI::Simple;
use Scalar::Util qw(weaken);
use File::Slurp;

sub call {
  Net::SIP::Debug->level( 100 );
  Net::SIP::Util->ipv6(0);

  my $stopvar = 0;
  my $timeout = 5;

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

  my $leg_from = Net::SIP::Leg->new(
    sock => $sock_from,
    cb_handle_response_pre => sub {
      my ($ctx, $endpoint, $method, $code, $leg, $from) = @_;

      if ($code eq '302') {
         say "cb_handle_response_pre $code";

         $stopvar = 1;

         return 0; # Don't continue to process the 302 and create a new INVITE
      };

      return 1;
    },
  );

  say 'Invite Start';

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

  $ua->add_timer($timeout, \$stopvar );

  my $invite = $ua->invite('11231231234',
    cb_final => sub {
      $stopvar = 1;
    },
  );

  say 'Invite Done';

  $ua->loop($timeout, \$stopvar);

  say 'Loop Done';

  $ua->{loop}->reset();

  close($sock_from);
  $invite->cleanup();
  $ua->cleanup();

  # Force immediate destroy
  $invite = undef;
  $ua     = undef;
}

my $i = 1;

while ( $i++ ) {
  say "Call: $i";
  call();
  say "Call Done: $i";
  sleep(1);
}

1;

Notice this in the log: 1724517905.0212 DEBUG:<2> Net::SIP::Leg::deliver[442]: delivery with tcp from 0.0.0.0 to 99.83.142.252:5060: 1724517905.2815 DEBUG:<2> Net::SIP::Leg::deliver[442]: delivery with tcp from 0.0.0.0 to 52.223.0.89:5060:

One INVITE sent to each A record. But this does not happen every single run! You need hundreds or thousands of calls to run into this situation.

Log attached log.txt

[kobaz]

Also from the log: This looks strange:

1724517904.1801 DEBUG:<90> Net::SIP::Dispatcher::__resolve_uri_final[895]: __resolve_uri_final
1724517904.1802 DEBUG:<100> Net::SIP::Dispatcher::__resolve_uri_final[896]: $VAR1 = [
1724517904.1802 DEBUG:<100>               {
1724517904.1802 DEBUG:<100>                 'proto' => 'udp',
1724517904.1802 DEBUG:<100>                 'port' => 5060,
1724517904.1802 DEBUG:<100>                 'family' => 2,
1724517904.1802 DEBUG:<100>                 'host' => 'sip.clearip.com',
1724517904.1802 DEBUG:<100>                 'addr' => '99.83.142.252',
1724517904.1802 DEBUG:<100>                 'prio' => 65536
1724517904.1802 DEBUG:<100>               },
1724517904.1802 DEBUG:<100>               {
1724517904.1802 DEBUG:<100>                 'family' => 2,
1724517904.1802 DEBUG:<100>                 'proto' => 'udp',
1724517904.1802 DEBUG:<100>                 'port' => 5060,
1724517904.1802 DEBUG:<100>                 'prio' => 65536,
1724517904.1802 DEBUG:<100>                 'addr' => '52.223.0.89',
1724517904.1802 DEBUG:<100>                 'host' => 'sip.clearip.com'
1724517904.1802 DEBUG:<100>               },
1724517904.1802 DEBUG:<100>               {
1724517904.1802 DEBUG:<100>                 'host' => 'sip.clearip.com',
1724517904.1802 DEBUG:<100>                 'prio' => 65536,
1724517904.1802 DEBUG:<100>                 'family' => 2,
1724517904.1802 DEBUG:<100>                 'addr' => '99.83.142.252',
1724517904.1802 DEBUG:<100>                 'proto' => 'tcp',
1724517904.1802 DEBUG:<100>                 'port' => 5060
1724517904.1802 DEBUG:<100>               },
1724517904.1802 DEBUG:<100>               {
1724517904.1802 DEBUG:<100>                 'addr' => '52.223.0.89',
1724517904.1802 DEBUG:<100>                 'proto' => 'tcp',
1724517904.1802 DEBUG:<100>                 'port' => 5060,
1724517904.1802 DEBUG:<100>                 'prio' => 65536,
1724517904.1802 DEBUG:<100>                 'host' => 'sip.clearip.com',
1724517904.1802 DEBUG:<100>                 'family' => 2
1724517904.1802 DEBUG:<100>               }
1724517904.1802 DEBUG:<100>             ];
1724517904.1802 DEBUG:<100>

Why is there four entries now for this lookup, half with tcp and half with udp. My local socket opened is tcp only

[kobaz]

I have added a lot of new logging to Net::SIP. I will upload my patch for this as well, as soon as possible.

[kobaz]

Also. Notice this in the log (related to the other issue where 'prio' is not found, so the sort() throws warnings in resolve_uri_final

1724517905.2701 DEBUG:<90> Net::SIP::Dispatcher::__resolve_uri_final[912]: __resolve_uri_final resp > 1
1724517905.2701 DEBUG:<90> Net::SIP::Dispatcher::__resolve_uri_final[923]: __resolve_uri_final resp > 1 (We do NOT have prio)
1724517905.2701 DEBUG:<90> Net::SIP::Dispatcher::__resolve_uri_final[924]: $VAR1 = [
1724517905.2701 DEBUG:<90>                {
1724517905.2701 DEBUG:<90>                  'addr' => '52.223.0.89',
1724517905.2701 DEBUG:<90>                  'host' => 'sip.clearip.com',
1724517905.2701 DEBUG:<90>                  'family' => 2,
1724517905.2701 DEBUG:<90>                  'port' => 5060,
1724517905.2701 DEBUG:<90>                  'proto' => undef
1724517905.2701 DEBUG:<90>                },
1724517905.2701 DEBUG:<90>                {
1724517905.2701 DEBUG:<90>                  'host' => 'sip.clearip.com',
1724517905.2701 DEBUG:<90>                  'addr' => '99.83.142.252',
1724517905.2701 DEBUG:<90>                  'proto' => undef,
1724517905.2701 DEBUG:<90>                  'port' => 5060,
1724517905.2701 DEBUG:<90>                  'family' => 2
1724517905.2701 DEBUG:<90>                }
1724517905.2701 DEBUG:<90>              ];
1724517905.2701 DEBUG:<90>

Randomly (not every single run) 'prio' hash field is missing from the list

[noxxi]

Unfortunately I cannot associate the log messages with the actual released code in Net::SIP. There seems to be at least added debug messages and maybe more changes. To fully understand the log I would need get the exact source code of (patched) Net::SIP and test program which was used to create the log.

[kobaz]

Yes of course. I will be submitting a patch with the new logs added.

But, I figured with the code, plus the logs that you are familiar with... possibly that might help uncover the issue.