Intermittent / Unreliable Originate Response
I’m sure hopeful that someone out there can point me in the right direction. It’s as if everything has been going fine but all at once nothing works.
I believe this is the problem I previously posted as
Sometimes the Originate successfully connects the call, but often we see “busy” when we look closely at the verbose CLI trace.
A speciallized difference of verbose CLI listings between two successive attempts, first successful, second failing is below:
[listing]
< simpleAMI_Originate_joined_running_ast30_success.txt
simpleAMI_Originate_joined_running_ast30_failure.txt
39d38
< Reloading unistim.conf…
48a48
Reloading unistim.conf…
119,123c119,123
-- Time to scan old dialplan and merge leftovers back into the new: 0.000811 sec -- Time to restore hints and swap in new dialplan: 0.000001 sec -- Time to delete the old dialplan: 0.000048 sec -- Total time merge_contexts_delete: 0.000860 sec
591,619c591,592
< == Using SIP RTP CoS mark 5
< – Executing [date] Goto(“SIP/152.148.200.236-00000005”, “incoming,51206,1”) in new stack
< – Goto (incoming,51206,1)
< – Executing [date] Verbose(“SIP/152.148.200.236-00000005”, “51206 incoming”) in new stack
< 51206 incoming
< – Executing [date] Read(“SIP/152.148.200.236-00000005”, “dtmf51206,20,99999”) in new stack
< – Accepting a maximum of 20 digits.
< – Started music on hold, class ‘default’, on SIP/152.148.200.236:5060-00000002
< > Channel SIP/152.148.200.236:5060-00000004 was answered
< – Executing [date] Verbose(“SIP/152.148.200.236:5060-00000004”, “51207 outgoing”) in new stack
< 51207 outgoing
< – Executing [date] Wait(“SIP/152.148.200.236:5060-00000004”, “1”) in new stack
< > 0x9f44e30 – Probation passed - setting RTP source address to 192.168.15.224:12638
< > 0xb722fc00 – Probation passed - setting RTP source address to 152.148.200.230:32628
< – Executing [date] Dial(“SIP/152.148.200.236:5060-00000004”, “SIP/51207@152.148.200.236:5060,20,rt”) in new stack
< == Using SIP RTP CoS mark 5
< – Called SIP/51207@152.148.200.236:5060
< == Using SIP RTP CoS mark 5
< – Executing [date] Goto(“SIP/152.148.200.236-00000007”, “incoming,51207,1”) in new stack
< – Goto (incoming,51207,1)
< – Executing [date] Verbose(“SIP/152.148.200.236-00000007”, “51207 incoming”) in new stack
< 51207 incoming
< – Executing [date] Read(“SIP/152.148.200.236-00000007”, “dtmf51207,20,99999”) in new stack
< – Accepting a maximum of 20 digits.
< – SIP/152.148.200.236:5060-00000006 is ringing
< – SIP/152.148.200.236:5060-00000006 is making progress passing it to SIP/152.148.200.236:5060-00000004
< – Started music on hold, class ‘default’, on SIP/152.148.200.236:5060-00000000
< – SIP/152.148.200.236:5060-00000006 answered SIP/152.148.200.236:5060-00000004
< > 0xb7510680 – Probation passed - setting RTP source address to 152.148.200.230:32636
-- Got SIP response 486 "Busy Here" back from 152.148.200.236:5060 > Channel SIP/152.148.200.236:5060-00000008 was never answered.
([/listing]
Program Output, showing two identical runs:
[listing]
testbuddy[121] ./simpleAMI.pl -host ao1 -out ast03 -running
Joining already running asterisk
To join again cmd:
asterisk -C/nfs/newadmin/public/users/crs/testbuddy/log/ast03/asterisk/asterisk.conf -r
Successfull Asterisk::AMI(
PeerAddr=>192.168.15.224,
PeerPort=>5039,
UserName=>admin,
Secret=>secret);
Connected to driverIP=192.168.15.224 PeerPort=5039
reload
Registered
Host dnsmgr Username Refresh State Reg.Time
152.148.200.236:5060 N 51210 3585 Registered Mon, 16 Feb 2015 16:39:27
152.148.200.236:5060 N 51209 3585 Registered Mon, 16 Feb 2015 16:39:27
152.148.200.236:5060 N 51208 3585 Registered Mon, 16 Feb 2015 16:39:27
152.148.200.236:5060 N 51207 3585 Registered Mon, 16 Feb 2015 16:39:27
152.148.200.236:5060 N 51206 3585 Registered Mon, 16 Feb 2015 16:39:27
192.168.90.50:5260 N 62025 1785 Registered Mon, 16 Feb 2015 16:39:27
192.168.90.50:5260 N 62024 1785 Registered Mon, 16 Feb 2015 16:39:27
192.168.90.50:5260 N 62023 1785 Registered Mon, 16 Feb 2015 16:39:27
192.168.90.50:5260 N 62022 1785 Registered Mon, 16 Feb 2015 16:39:28
192.168.90.50:5260 N 62021 1785 Registered Mon, 16 Feb 2015 16:38:42
10 SIP registrations.
Asterisk::AMI(Action=>Originate, Callerid=>AO1ID001, Channel=>SIP/51206@152.148.200.236:5060, Context=>outgoing, Exten=>51207, Priority=>1, Timeout=>20000)
AMI Response:
$VAR1 = {
‘Message’ => ‘Originate successfully queued’,
‘ActionID’ => ‘4’,
‘GOOD’ => 1,
‘COMPLETED’ => 1,
‘Response’ => ‘Success’
};
Sleeping for 20 sec
End of Test
testbuddy[122] ./simpleAMI.pl -host ao1 -out ast03 -running
Joining already running asterisk
To join again cmd:
asterisk -C/nfs/newadmin/public/users/crs/testbuddy/log/ast03/asterisk/asterisk.conf -r
Successfull Asterisk::AMI(
PeerAddr=>192.168.15.224,
PeerPort=>5039,
UserName=>admin,
Secret=>secret);
Connected to driverIP=192.168.15.224 PeerPort=5039
reload
Registered
Host dnsmgr Username Refresh State Reg.Time
152.148.200.236:5060 N 51210 3585 Registered Mon, 16 Feb 2015 16:40:00
152.148.200.236:5060 N 51209 3585 Registered Mon, 16 Feb 2015 16:40:00
152.148.200.236:5060 N 51208 3585 Registered Mon, 16 Feb 2015 16:40:00
152.148.200.236:5060 N 51207 3585 Registered Mon, 16 Feb 2015 16:40:00
152.148.200.236:5060 N 51206 3585 Registered Mon, 16 Feb 2015 16:40:00
192.168.90.50:5260 N 62025 1785 Registered Mon, 16 Feb 2015 16:40:00
192.168.90.50:5260 N 62024 1785 Registered Mon, 16 Feb 2015 16:40:01
192.168.90.50:5260 N 62023 1785 Registered Mon, 16 Feb 2015 16:40:01
192.168.90.50:5260 N 62022 1785 Registered Mon, 16 Feb 2015 16:40:01
192.168.90.50:5260 N 62021 1785 Registered Mon, 16 Feb 2015 16:39:28
10 SIP registrations.
Asterisk::AMI(Action=>Originate, Callerid=>AO1ID001, Channel=>SIP/51206@152.148.200.236:5060, Context=>outgoing, Exten=>51207, Priority=>1, Timeout=>20000)
AMI Response:
$VAR1 = {
‘Message’ => ‘Originate failed’,
‘ActionID’ => ‘4’,
‘GOOD’ => 0,
‘COMPLETED’ => 1,
‘Response’ => ‘Error’
};
Sleeping for 20 sec
End of Test
[/listing]
Program Run:
#!/usr/bin/perl -w
use strict;
use warnings;
use Getopt::Long;
use Asterisk::AMI;
use Asterisk::config;
use Data::Dumper;
my $OutDirParent = "log";
my $OutDir = "ast40";
my $Running = 0; # 1 - asterisk is alreay running
# Assumes asterisk started vie:
# asterisk -C /nfs/newadmin/public/users/crs/testbuddy/log/$outdir/asterisk/
# asterisk.conf -c
#
#
my $Verbose = 0;
my $Callid = "ADBG0001";
my $CallerNum;
my $CalleeNum;
my $Host;
my $HostShortName = "ao8";
my $TimeoutDef = 20; # Seconds
my $Registrar;
my $RegistrarIp;
my $TypePhone = "OXE";
my %HostInfoH = (
ao1 => {
host => "acs-ao1.nlt01.com",
hostIp => "192,157,90.201",
registrar => "acs-ao1.nlt01.com",
registrarIp => "192.168.90.201",
regPort => 5060,
registrarOxe => "ao1-oxe-ed.inse.lucent.com",
registrarOxeIp => "152.148.200.236",
regPortOxe => 5060,
callerId => "AO1ID001",
callerNum => 51206,
calleeNum => 51207,
},
ao8 => {
host => "ao8-ed.inse.lucent.com",
hostIp => "152.148.200.152",
registrar => "acs-ao1.nlt01.com",
registrarIp => "192.168.90.201",
regPort => 5060,
registrarOxe => "ao2-oxe.inse.lucent.com",
registrarOxeIp => "158.148.200.242",
regPortOxe => 5060,
callerId => "AO8ID001",
callerNum => 46001,
calleeNum => 46002,
},
);
my $sayHelp; # defined -> print help and exit
my $helpstr = <<HELPSTR;
$0
[
--? -> Print this help
--hostShortName - ao1, ao8 - short name
--OutDir - Output/asterisk dir if "/" - prefixed by "log"
Directes choices
--p1 - caller phone# (overrides host)
--p2 - callee phone# (overrides hos1, p1+1
--[NO]running - asterisk is running, else start asterisk Default: $Running
--typePhone = phone type OXE/ICM Default: $TypePhone
--verbose - lots of tracing to display
]
HELPSTR
GetOptions(
'_|?' => \$sayHelp,
'hostShort=s' => \$HostShortName,
'outDir=s' => \$OutDir,
'p1=s' => \$CallerNum,
'p2=s' => \$CalleeNum,
'running!' => \$Running,
'timeoutDef=f' => \$TimeoutDef,
'typePhone=s' => \$TypePhone,
'verbose' => \$Verbose,
) or die "Illegal options$helpstr\n";
if ($sayHelp) {
print "Usage: $helpstr\n";
exit(0);
}
if (!defined($OutDir)) {
$OutDir = $HostShortName;
}
if ($OutDir !~ m&/&) {
$OutDir = "$OutDirParent/$OutDir";
}
if (! -d "$OutDir/asterisk") {
die "No asterisk dir in $OutDir";
}
my $r_host_info = $HostInfoH{$HostShortName} or die "No host info for $HostShortName";
my $registrarIp = $r_host_info->{'registrarIp'};
my $callerNum = $r_host_info->{'callerNum'};
$callerNum = $CallerNum if defined($CallerNum);
my $callerId = $r_host_info->{'callerId'};
my $calleeNum = $r_host_info->{'calleeNum'};
$calleeNum = $CalleeNum if defined($CalleeNum);
my $regPort = $r_host_info->{'regPort'};
# Calculated
if ($TypePhone eq "OXE") {
$registrarIp = $r_host_info->{'registrarOxeIp'};
}
my $channel = "SIP/$callerNum\@$registrarIp:$regPort",
my $context = "outgoing";
my $exten = $calleeNum;
my $timeoutMs = $TimeoutDef * 1000.;
my $cmd = qq{asterisk -C}
. qq{/nfs/newadmin/public/users/crs/testbuddy/}
. qq{$OutDir/asterisk/asterisk.conf}
;
if ($Running) {
print "Joining already running asterisk\n";
$cmd .= qq{ -r};
print "To join again cmd:\n$cmd\n";
} else {
print "Starting asterisk\n";
print "via cmd:\n$cmd\n";
print qx{$cmd};
my $amiwait = 5; # Second wait
print "Waiting $amiwait sec\n";
sleep $amiwait;
}
my $astSecret = "secret";
my $astUserName = "admin";
my $driverIp = "192.168.15.224";
my $simPort = 5039;
my $astAMI = Asterisk::AMI->new(PeerAddr => $driverIp,
PeerPort => $simPort,
Username => $astUserName,
Secret => $astSecret
);
if (!defined($astAMI)) {
print("Can't connect to Asterisk::AMI("
. "PeerAddr=>$driverIp"
. ",PeerPort=>$simPort"
. ",UserName=>$astUserName"
. ",Secret=>$astSecret"
. "): $!\n");
exit(1);
}
print "Successfull Asterisk::AMI("
. "\n\tPeerAddr=>$driverIp"
. ",\n\tPeerPort=>$simPort"
. ",\n\tUserName=>$astUserName"
. ",\n\tSecret=>$astSecret"
. ");\n";
print "Connected to driverIP=$driverIp PeerPort=$simPort\n";
print "reload\n";
my $reload_res = AsteriskCliCmd("core reload");
if (!$reload_res || !$reload_res->{'GOOD'}) {
print "core reload failed\n";
exit(1);
}
sleep 1;
my $show_reg = 1;
if ($show_reg) {
my $reg_res = AsteriskCliCmd("sip show registry");
if (!$reg_res || !$reg_res->{'GOOD'}) {
print "core reload failed\n";
exit(1);
}
my $r_cmds = $reg_res->{'CMD'};
print "Registered\n";
foreach my $cmd (@$r_cmds) {
print "$cmd\n";
}
}
my %acmd = (
Action => 'Originate',
Channel => $channel,
Context => $context,
Exten => $exten,
Priority => 1,
Callerid => $callerId,
Timeout => $timeoutMs,
);
my $r_ami_cmd = \%acmd;
print "Asterisk::AMI("
. AsteriskCmd2Str($r_ami_cmd)
. ")\n";
my $actionid = $astAMI->send_action($r_ami_cmd);
my $r_resp = $astAMI->get_response($actionid);
print "AMI Response:\n" . Dumper($r_resp) . "\n";
my $waitup = 20;
print "Sleeping for $waitup sec\n";
sleep $waitup;
print "End of Test\n";
#
# Set global variable
sub asteriskSetGlobal { # Returns: 1 iff successful
my (
$astAMI, # AMI ref
$name, # variable name
$value, # Value to set
) = @_;
my $cmd = "dialplan set global $name $value";
my $r_resp = $astAMI->action({
Action => 'Command',
Command => $cmd,
});
if (!defined($r_resp)) {
print "AsteriskSetGlobal:: undefined ($name $value)\n";
return 0;
}
if (!$r_resp->{'GOOD'}) {
print "AsteriskSetGlobal error:" . $r_resp->{'message'} . "\n";
return 0;
}
return 1;
}
#
# CLI cmd
sub AsteriskCliCmd { # Returns: response
my (
$clicmd
) = @_;
return "No AMI connected" if !defined($astAMI);
my %acmdh = (Action=>'Command',
Command=>$clicmd,
);
my $resp = $astAMI->action(\%acmdh);
return $resp;
}
# Asterisk Reteturn to string
# STATIC function
sub AsteriskCmd2Str { # Returns: string version
my (
$r_res, # AMI result hash
) = @_;
return "UNDEF" if !defined($r_res);
my $resstr = "";
for my $key (sort keys %$r_res) {
my $value = $r_res->{$key};
$value = "UNDEF" if !defined($value);
$resstr .= ", " if $resstr ne "";
if (ref $value eq "ARRAY") {
$value = "[" . join(",", @$value) . "]";
}
$resstr .= "$key=>$value";
}
return $resstr;
}