Unable to receive incoming calls via SIP

hishamjan · September 5, 2024, 10:28pm

Hi everyone!

I upgraded my SIP server (NewPBX) from Asterisk 1.8.9 to Asterisk 18.22, swapped the IP addresses (old PBX IP to New PBX IP), and successfully configured trunks to communicate with other SIP servers in different locations.

Good part?
I am able to make outgoing calls to all the servers, via trunk, within the same VLAN, via Dahdi etc.

Bad part?
I can’t receive incoming calls on my new server (which is essentially the same as before)…it gives me the following error (trunkA is the trunk between this NewPBX and another server elsewhere; OtherPBX):

 -- Called SIP/trunkA/5601
    -- Got SIP response 603 "Declined" back from NewPBX:5060
    -- SIP/inehtrunk-0000008f is busy
  == Everyone is busy/congested at this time (1:1/0/0)

SIP debug is:

– Executing [5601@default:1] AGI(“SIP/16611-0000008c", “agi.php”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
some info redacted
– Setting call duration limit to 54713256720.000 seconds.
== Using UDPTL TOS bits 184
== Using UDPTL CoS mark 5
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
We think we can do text
Audio is at 11996
Video is at OtherPBX:10562
Adding codec 0x8 (alaw) to SDP
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding codec 0x10 (g726aal2) to SDP
Adding codec 0x20 (adpcm) to SDP
Adding codec 0x40 (slin) to SDP
Adding codec 0x80 (lpc10) to SDP
Adding codec 0x800 (g726) to SDP
Adding codec 0x1000 (g722) to SDP
Adding codec 0x8000 (slin16) to SDP
Adding video codec 0x10000 (jpeg) to SDP
Adding video codec 0x20000 (png) to SDP
Adding video codec 0x40000 (h261) to SDP
Adding video codec 0x80000 (h263) to SDP
Adding video codec 0x100000 (h263p) to SDP
Adding video codec 0x200000 (h264) to SDP
Adding video codec 0x400000 (mpeg4) to SDP
Adding codec 0x800000000000 (testlaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to NewPBX:5060:
INVITE sip:5601@NewPBX SIP/2.0
Via: SIP/2.0/UDP OtherPBX:5060;branch=z9hG4bK70796db5;rport
Max-Forwards: 70
From: “6611test” sip:6611@OtherPBX;tag=as15b53661
To: <sip:5601@NewPBX >
Contact: sip:6611@OtherPBX:5060
Call-ID: 690513ca3ce3c2ac31d063101717f031@OtherPBX:5060
CSeq: 102 INVITE
User-Agent: tpadpbx
Date: Thu, 05 Sep 2024 22:09:50 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
P-Asserted-Identity: “6611test” sip:6611@OtherPBX
Content-Type: application/sdp
Content-Length: 689
v=0
o=root 1939122451 1939122451 IN IP4 OtherPBX
s=Asterisk PBX 1.8.9.0
c=IN IP4 OtherPBX
b=CT:384
t=0 0
m=audio 11996 RTP/AVP 8 0 3 112 5 10 7 111 9 118 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:112 AAL2-G726-32/8000
a=rtpmap:5 DVI4/8000
a=rtpmap:10 L16/8000
a=rtpmap:7 LPC/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:118 L16/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=video 10562 RTP/AVP 26 31 34 98 99 104
a=rtpmap:26 JPEG/90000
a=rtpmap:31 H261/90000
a=rtpmap:34 H263/90000
a=rtpmap:98 h263-1998/90000
a=rtpmap:99 H264/90000
a=rtpmap:104 MP4V-ES/90000
a=sendrecv
–
– Called SIP/inehtrunk/5601
<— Transmitting (NAT) to SoftPhone:9114 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP SoftPhone:9114;branch=z9hG4bK-d87543-627061510-1–d87543-;received=SoftPhone;rport=9114
From: 6611sip:1*6611@OtherPBX;tag=ef118504
To: sip:5601@OtherPBX;tag=as3f5948a5
Call-ID: a6237c6040012b54
CSeq: 2 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5601@OtherPBX:5060
Content-Length: 0
<------------>
<— SIP read from UDP:NewPBX:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP OtherPBX:5060;branch=z9hG4bK70796db5;received=OtherPBX;rport=5060
From: “6611test” sip:6611@OtherPBX;tag=as15b53661
To: sip:5601@NewPBX
Call-ID: 690513ca3ce3c2ac31d063101717f031@OtherPBX:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:5601@NewPBX:5060
Content-Length: 0
<------------->
— (12 headers 0 lines) —
<— SIP read from UDP:NewPBX:5060 —>
SIP/2.0 603 Declined
Via: SIP/2.0/UDP OtherPBX:5060;branch=z9hG4bK70796db5;received=OtherPBX;rport=5060
From: “6611test” sip:6611@OtherPBX;tag=as15b53661
To: sip:5601@NewPBX;tag=as6f67e5b3
Call-ID: 690513ca3ce3c2ac31d063101717f031@OtherPBX:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
<------------->
— (11 headers 0 lines) —
– Got SIP response 603 “Declined” back from NewPBX:5060
Transmitting (NAT) to NewPBX:5060:
ACK sip:5601@NewPBX SIP/2.0
Via: SIP/2.0/UDP OtherPBX:5060;branch=z9hG4bK70796db5;rport
Max-Forwards: 70
From: “6611test” sip:6611@OtherPBX;tag=as15b53661
To: sip:5601@NewPBX;tag=as6f67e5b3
Contact: sip:6611@OtherPBX:5060
Call-ID: 690513ca3ce3c2ac31d063101717f031@OtherPBX:5060
CSeq: 102 ACK
User-Agent: tpadpbx
Content-Length: 0
– SIP/inehtrunk-0000008d is busy
== Everyone is busy/congested at this time (1:1/0/0)
– <SIP/16611-0000008c>AGI Script agi.php completed, returning 4
== Spawn extension (default, 5601, 1) exited non-zero on 'SIP/16611-0000008c’
– Executing [h@default:1] AGI("SIP/16611-0000008c”, “agi.php,CDR”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
Scheduling destruction of SIP dialog ‘a6237c6040012b54’ in 6400 ms (Method: INVITE)
<— Reliably Transmitting (NAT) to SoftPhone:9114 —>
SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP SoftPhone:9114;branch=z9hG4bK-d87543-627061510-1–d87543-;received=SoftPhone;rport=9114
From: 6611sip:1*6611@OtherPBX;tag=ef118504
To: sip:5601@OtherPBX;tag=as3f5948a5
Call-ID: a6237c6040012b54
CSeq: 2 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0
<------------>
Really destroying SIP dialog ‘690513ca3ce3c2ac31d063101717f031@OtherPBX:5060’ Method: INVITE
<— SIP read from UDP:SoftPhone:9114 —>
ACK sip:5601@OtherPBX SIP/2.0
To: sip:5601@OtherPBX;tag=as3f5948a5
From: 6611sip:1*6611@OtherPBX;tag=ef118504
Via: SIP/2.0/UDP SoftPhone:9114;branch=z9hG4bK-d87543-627061510-1–d87543-;rport
Call-ID: a6237c6040012b54
CSeq: 2 ACK
Content-Length: 0
<------------->
— (7 headers 0 lines) —
Really destroying SIP dialog ‘7d44da653da6048466f0139109fe193c@NewPBX:5060’ Method: OPTIONS
Really destroying SIP dialog ‘772256ca26cff5b65a7a328f3858253e@NewPBX’ Method: REGISTER
<— SIP read from UDP:SoftPhone:9114 —>

I have uploaded the softphone where the 403 forbidden is shown as well ^

Can someone please guide me what might the issue be and how to resolve it?

Feel free to ask for info which I might have missed out on…

Best,
Hisham

hishamjan · September 5, 2024, 11:15pm

Additonal Info:
outgoing call PCAP (successful):

Above, x.6.82 is an ip phone registered with x.6.254 server, calling a phone connected to x.12.221 server

incoming call PCAP (unsuccessful):

Here, an ip phone connected to x.9.254 is trying to call a peer on x.6.254 server.

david551 · September 6, 2024, 11:03am

I’m confused as to which is which. Also, your successful message sequence chart shows good incoming calls, and you detailed logging shows the failure on the outgoing leg, whereas failing message sequence chart shows it on the incoming leg.

For the one with the detailed logs, we need to see the logs from the other side.

For the last one, it is likely that the caller isn’t matching any entry in sip.conf, and you don’t have always auth reject enabled, which would result in a faked 401 at the first attempt.

hishamjan · September 6, 2024, 12:54pm

Hi @david551

I’m confused as to which is which. Also, your successful message sequence chart shows good incoming calls, and you detailed logging shows the failure on the outgoing leg, whereas failing message sequence chart shows it on the incoming leg.

the sip debug logs are for the failed call which is indeed the incoming call to ther server which i have named as NewPBX.

The PCAPs are for the outgoing (which is succesful) and for incoming (which is failing in all scenarios).

For the last one, it is likely that the caller isn’t matching any entry in sip.conf, and you don’t have always auth reject enabled, which would result in a faked 401 at the first attempt.

the sip.conf entires are rather realtime, attached to the web interface, and those extensions are successfully registered with my NewPBX as well.

For the one with the detailed logs, we need to see the logs from the other side.

I have pasted pcaps from both sides, please see below:

at NewPBX side:

at OtherPBX side:

Let me know if you require any other info…I still can’t seem to understand the problem

david551 · September 6, 2024, 1:07pm

The full log from the system that is sending the 603, with, for Asterisk, verbosity at least 3.

hishamjan · September 6, 2024, 5:41pm

Sure, @david551…here you go

logs on OtherPBX (getting 603):

Connected to Asterisk 1.8.9.0 currently running on sip (pid = 2907)
Verbosity is at least 9
  == Using UDPTL TOS bits 184
  == Using UDPTL CoS mark 5
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Executing [8610@default:1] AGI("SIP/1*6611-00000192", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
 agi.php: Callerid 6611 not blacklisted
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1237 - uniqueid:1725644518.442 -  check_auth_account Username 6611, CustID 1 , AccountID 111 Source : 6611test <6611>, Destination :8610
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:583 - uniqueid:1725644518.442 - [EXTEN to OUTBOUND number Routing]
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:635 - uniqueid:1725644518.442 - [Account Balance  : 9118.64102]
 agi.php: app is 'EXTEN': Setting dst_account_id to
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:649 - uniqueid:1725644518.442 - [EXTEN info CustomerID : 1, AccountID : ]
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1313 - uniqueid:1725644518.442 - [Add Dialpattern Prefix : ; Remove Dialpattern Prefix : ]
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1317 - uniqueid:1725644518.442 - [New dst after dial pattern process : 8610]
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1328 - uniqueid:1725644518.442 - [New dst after internal Prefix  rate management process : 8610]
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:676 - uniqueid:1725644518.442 - [Dialled number has not modified via dial pattern; Old Number 8610 and Return Number : 8610]
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1131 - uniqueid:1725644518.442 -  get_rates Function
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:936 - uniqueid:1725644518.442 -  get_minutes PBX2PBX = 1
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:937 - uniqueid:1725644518.442 -  get_minutes Credit = 9118.64102
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:938 - uniqueid:1725644518.442 -  get_minutes Sale Rate = 0.00001
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:939 - uniqueid:1725644518.442 -  get_minutes Total Time = 15197735 hours 1 minute 59 seconds
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:940 - uniqueid:1725644518.442 -  get_minutes MaxCall Time = 7200 Sec
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1014 - uniqueid:1725644518.442 -  get_trunk Function
 agi.php: BEFORE 8610,
 agi.php: AFTER 8610,
 agi.php: app is 'EXTEN': Setting dst_account_id to
 agi.php: app is 'EXTEN': Setting dst_account_id to
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:661 - uniqueid:1725644518.442 - Max outbound calls : 1
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:643 - uniqueid:1725644518.442 - *************** CALLERID NUMBER: ***************
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:645 - uniqueid:1725644518.442 - *************** CALLERID NUMBER: DNID LENGTH IS 4 for 8610***************
    -- AGI Script Executing Application: (SIPRemoveHeader) Options: (Alert-Info:Ring Answer)
    -- AGI Script Executing Application: (SIPRemoveHeader) Options: (Call-Info:<uri>;answer-after=0)
 agi.php: Dialing with parameters: SIP/inehtrunknew/8610,30,rRwL(54711846120000:60000)M(recording^^1725644518.442^)
    -- AGI Script Executing Application: (DIAL) Options: (SIP/inehtrunknew/8610,30,rRwL(54711846120000:60000)M(recording^^1725644518.442^))
    -- Setting call duration limit to 54711846120.000 seconds.
  == Using UDPTL TOS bits 184
  == Using UDPTL CoS mark 5
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Called SIP/inehtrunknew/8610
    -- Got SIP response 603 "Declined" back from 10.10.6.253:5060
    -- SIP/inehtrunknew-00000193 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- <SIP/1*6611-00000192>AGI Script agi.php completed, returning 4
  == Spawn extension (default, 8610, 1) exited non-zero on 'SIP/1*6611-00000192'
    -- Executing [h@default:1] AGI("SIP/1*6611-00000192", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
 agi.php,CDR: Callerid 6611 not blacklisted
 agi.php,CDR: app is 'EXTEN': Setting dst_account_id to
 agi.php,CDR: --value of cmdstring is: SIP/inehtrunknew-00000193
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:2569 - uniqueid:1725644518.442 -  cmdstring: SIP/inehtrunknew-00000193
    -- Remote UNIX connection
    -- Remote UNIX connection disconnected
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1237 - uniqueid:1725644518.442 -  check_auth_account Username 6611, CustID 1 , AccountID 111 Source : 6611test <6611>, Destination :h
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/agi.php - line:2910 - uniqueid:1725644518.442 - CDR  clid 6611test <6611> src 6611 dst 8610 dcontext default channel SIP/1*6611-00000192 dstchannel SIP/inehtrunknew-00000193 lastapp AGI lastdata HANGUP starttime 2024-09-06 21:41:58 answertime  endtime  duration  billduration  disposition BUSY Stotime 2024-09-06 21:41:58
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1131 - uniqueid:1725644518.442 -  get_rates Function
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:762 - uniqueid:1725644518.442 -  get_billcost Sale Cost:  Buy Cost:
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/agi.php - line:2982 - uniqueid:1725644518.442 - CDR  Query INSERT INTO `tp_cdr` (`customer_id`, `account_id`, `trunk_id`, `rate_id`, `rateplan_id`, `callplan_id`, `trunkgroup_id`, `uniqueid`, `starttime`, `stoptime`, `answertime`, `ringduration`, `billsec`, `callduration`, `destination`, `src`, `terminatecause`, `sale_rate`, `sale_cost`, `buy_rate`, `buy_cost`, `sipiax`, `recording_file`, `call_type`,`app_billsec`,`last_app`, `dst`,`last_credit`,`bill_level`,`provider_id`, `destination_name`,bill_account_id) VALUES ('1', '111', '19', '9109', '5', '1', '3', '1725644518.442', '2024-09-06 21:41:58', '2024-09-06 21:41:58', '', '0', '0', '0','8610', '6611', 'BUSY', '0.00001', '0', '0.00000', '0', '', '', 'OUTBOUND','0','AGI','8610','9118.64102','1','1','P2P','111')
    -- <SIP/1*6611-00000192>AGI Script agi.php completed, returning 0
    -- Remote UNIX connection
    -- Remote UNIX connection disconnected
    -- Remote UNIX connection
    -- Remote UNIX connection disconnected

Logs on NewPBX (sending 603):

Using SIP VIDEO CoS mark 6
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
       > 0x7f751415b900 -- Strict RTP learning after remote address set to: 10.10.9.254:13848
       > 0x7f7514162150 -- Strict RTP learning after remote address set to: 10.10.9.254:10404
[Sep  6 21:38:43] ERROR[4594]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ehtrunknew-00000036
[Sep  6 21:38:43] ERROR[4594]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ehtrunknew-00000036
[Sep  6 21:38:43] ERROR[4594]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ehtrunknew-00000036
    -- Executing [8610@default:1] AGI("SIP/ehtrunknew-00000036", "agi.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - set_serverid QUERY : select server_id FROM `blf_serverlist` WHERE islocal = '1'
 agi.php: cdrsrc is:
 agi.php: Callerid 6611 not blacklisted
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - check_auth_account QUERY : SELECT `tp_account`.`hosted`,`tp_account`.`voicemail_passwd`, `tp_account`.`ringtime` as exten_ringtime, `tp_customer`.`trunk_accountcode`, `tp_account`.`dialpatterngroup_id`, `tp_account`.`hidecallerid`, `tp_account`.`trunk_exten`, `tp_account`.`agentexten_type`, `tp_customer`.`email` AS customer_email, `tp_customer`.`commoncredit` AS customer_commoncredit , `tp_customer`.`recording_override` AS customer_recording_override, `tp_account`.`account_id`,  `tp_account`.`name`,  `tp_account`.`username`,  `tp_account`.`accountcode`, `tp_account`.`customer_id`,  `tp_account`.`credit`,  `tp_account`.`callplan_id`, `tp_account`.`calleridlocal`,  `tp_account`.`calleridexternal`, `tp_account`.`musiconhold`,  `tp_account`.`voicemail`,  `tp_account`.`fax`,  `tp_account`.`inuse`,  `tp_account`.`sipuser`, `tp_account`.`iaxuser`, `tp_account`.`billing_type`, `tp_account`.`failover_app`, `tp_account`.`failover_appnumber`, `tp_account`.`recording`, `tp_customer`.`dial_option`, `tp_customer`.`ringtime`, `tp_customer`.`recording_path` , `tp_account`.`extennumber` , `tp_customer`.`maxcallduration` FROM  `tp_account`  INNER JOIN `tp_customer`  ON `tp_account`.`customer_id` = `tp_customer`.`customer_id`   WHERE  `tp_account`.`activated` = 't' AND `tp_account`.`status` = '1'  AND `tp_customer`.`status` = '1' AND `accountcode` = 'ehtrunk'
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1208 - uniqueid:sip.tt-1725644323.88 -  check_auth_account Username ehtrunk, CustID 1 , AccountID 21 Source : 6611test <6611>, Destination :8610
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - GetSystemCode QUERY : SELECT code,code_name FROM `tp_featurecode` where customer_id='1'  order by length(code) DESC
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - check_numberinfo QUERY : SELECT `table_id`, `app` from `tp_numberinfo` where `customer_id` = '1' AND `number_info` = '8610'
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1370 - uniqueid:sip.tt-1725644323.88 - check_numberinfo; Table ID: 125 Application : EXTEN
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - get_blacklist QUERY : select `customer_id`, `account_id`, `phonenumber`  from `tp_blacklist`  where `phonenumber` = '6611' AND `customer_id` = '1' AND ( `account_id`='' OR `account_id` is NULL OR `account_id` = '125')
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:2424 - uniqueid:sip.tt-1725644323.88 -  CALLTABLEQUERY: CALLTABLEQUERY
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : INSERT INTO `tp_livecall` (`server_id`,`dst_account_id`, `customer_id`, `account_id`, `trunk_id`, `uniqueid`, `starttime`, `dst`, `destination`, `src`, `channel`, `dstchannel`, `call_type`, `app`,`call_status`,`uniqueid2`,last_updated,queue_name,account_name,dst_account_name)VALUES ('2','125', '1', '21', NULL,   'sip.tt-1725644323.88', now(), '8610', '8610',  '6611',  'SIP/ehtrunknew-00000036', NULL,  'INTERNAL','EXTEN','RINGING','sip.tt-1725644323.88',now(),'','ehtrunk','') ON DUPLICATE KEY UPDATE  `dst` = '8610', `call_type` = 'INTERNAL',`trunk_id` = NULL,  `app` = 'EXTEN', `dst_account_id` = '125',  last_updated = now(),queue_name = '', account_name = 'ehtrunk', dst_account_name = ''
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : INSERT INTO `tp_livecall` (`server_id`,`dst_account_id`, `customer_id`, `account_id`, `trunk_id`, `uniqueid`, `starttime`, `dst`, `destination`, `src`, `channel`, `dstchannel`, `call_type`, `app`,`call_status`,`uniqueid2`,last_updated,queue_name,account_name,dst_account_name)VALUES ('2','125', '1', '21', NULL,   'sip.tt-1725644323.88', now(), '8610', '8610',  '6611',  'SIP/ehtrunknew-00000036', NULL,  'INTERNAL','EXTEN','RINGING','sip.tt-1725644323.88',now(),'','ehtrunk','') ON DUPLICATE KEY UPDATE  `dst` = '8610', `call_type` = 'INTERNAL',`trunk_id` = NULL,  `app` = 'EXTEN', `dst_account_id` = '125',  last_updated = now(),queue_name = '', account_name = 'ehtrunk', dst_account_name = ''
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - check_numberinfo QUERY : SELECT `table_id`, `app` from `tp_numberinfo` where `customer_id` = '1' AND `number_info` = '8610'
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1370 - uniqueid:sip.tt-1725644323.88 - check_numberinfo; Table ID: 125 Application : EXTEN
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:955 - uniqueid:sip.tt-1725644323.88 - [Caller Account ID : 125]
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - check_local_dst QUERY : SELECT `tp_account`.`ringtime` as exten_ringtime, `tp_account`.`trunk_exten`, `tp_account`.`custom_status`, `tp_customer`.`recording_override` AS customer_recording_override, `tp_account`.`account_id`, `tp_account`.`name`, `tp_account`.`username`, `tp_account`.`customer_id`, `tp_account`.`credit`, `tp_account`.`callplan_id`, `tp_account`.`calleridlocal`, `tp_account`.`calleridexternal`, `tp_account`.`musiconhold`, `tp_account`.`voicemail`, `tp_account`.`fax`, `tp_account`.`inuse`, `tp_account`.`sipuser`, `tp_account`.`iaxuser`, `tp_account`.`failover_app`, `tp_account`.`failover_appnumber`, `tp_account`.`callforward`, `tp_account`.`followme`, `tp_account`.`recording`, `tp_customer`.`dial_option`, `tp_customer`.`ringtime`, `tp_customer`.`recording_path`   FROM  `tp_account`  INNER JOIN `tp_customer` ON `tp_account`.`customer_id` = `tp_customer`.`customer_id`       WHERE (`tp_account`.`sipuser` = '1' or `tp_account`.`iaxuser` = '1') and `tp_account`.`activated`='t' AND `tp_account`.`status` = '1' AND `tp_account`.`customer_id` = '1' AND `tp_account`.`account_id` = '125' AND `tp_customer`.`status` = '1'
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1343 - uniqueid:sip.tt-1725644323.88 -  check_local_dst IAX 0 SIP 1
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:2424 - uniqueid:sip.tt-1725644323.88 -  CALLTABLEQUERY: CALLTABLEQUERY
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : INSERT INTO `tp_livecall` (`server_id`,`dst_account_id`, `customer_id`, `account_id`, `trunk_id`, `uniqueid`, `starttime`, `dst`, `destination`, `src`, `channel`, `dstchannel`, `call_type`, `app`,`call_status`,`uniqueid2`,last_updated,queue_name,account_name,dst_account_name)VALUES ('2','125', '1', '21', NULL,   'sip.tt-1725644323.88', now(), '8610', '8610',  '6611',  'SIP/ehtrunknew-00000036', NULL,  'INTERNAL','EXTEN','RINGING','sip.tt-1725644323.88',now(),'','ehtrunk','8610test') ON DUPLICATE KEY UPDATE  `dst` = '8610', `call_type` = 'INTERNAL',`trunk_id` = NULL,  `app` = 'EXTEN', `dst_account_id` = '125',  last_updated = now(),queue_name = '', account_name = 'ehtrunk', dst_account_name = '8610test'
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : INSERT INTO `tp_livecall` (`server_id`,`dst_account_id`, `customer_id`, `account_id`, `trunk_id`, `uniqueid`, `starttime`, `dst`, `destination`, `src`, `channel`, `dstchannel`, `call_type`, `app`,`call_status`,`uniqueid2`,last_updated,queue_name,account_name,dst_account_name)VALUES ('2','125', '1', '21', NULL,   'sip.tt-1725644323.88', now(), '8610', '8610',  '6611',  'SIP/ehtrunknew-00000036', NULL,  'INTERNAL','EXTEN','RINGING','sip.tt-1725644323.88',now(),'','ehtrunk','8610test') ON DUPLICATE KEY UPDATE  `dst` = '8610', `call_type` = 'INTERNAL',`trunk_id` = NULL,  `app` = 'EXTEN', `dst_account_id` = '125',  last_updated = now(),queue_name = '', account_name = 'ehtrunk', dst_account_name = '8610test'
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:1561 - uniqueid:sip.tt-1725644323.88 - Recoding file:
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:1567 - uniqueid:sip.tt-1725644323.88 - Dial starting 8610
 agi.php: file:/var/lib/asterisk/agi-bin/agi.php - line:1599 - uniqueid:sip.tt-1725644323.88 - Dial starting SIP/1*8610,30,kXwM(recording^^sip.tt-1725644323.88)
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:658 - uniqueid:sip.tt-1725644323.88 - *************** CALLERID NUMBER: ***************
 agi.php: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:661 - uniqueid:sip.tt-1725644323.88 - *************** CALLERID NUMBER: DNID LENGTH IS 4 for 8610***************
    -- <SIP/ehtrunknew-00000036>AGI Script agi.php completed, returning 0
    -- Executing [8610@default:2] Hangup("SIP/ehtrunknew-00000036", "") in new stack
  == Spawn extension (default, 8610, 2) exited non-zero on 'SIP/ehtrunknew-00000036'
    -- Executing [h@default:1] AGI("SIP/ehtrunknew-00000036", "agi.php,CDR") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/agi.php
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - set_serverid QUERY : select server_id FROM `blf_serverlist` WHERE islocal = '1'
 agi.php,CDR: cdrsrc is:
 agi.php,CDR: Callerid 6611 not blacklisted
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:2424 - uniqueid:sip.tt-1725644323.88 -  CALLTABLEQUERY: CALLTABLEQUERY
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : select recording,account_id, dst_account_id FROM `tp_livecall` WHERE `uniqueid` = 'sip.tt-1725644323.88' or  `uniqueid2` = 'sip.tt-1725644323.88' AND server_id = '2'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:2565 - uniqueid:sip.tt-1725644323.88 -  cmdstring:
    -- Remote UNIX connection
    -- Remote UNIX connection disconnected
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : update blf_livestatus set exten_status_update = now() where account_id = '21' or account_id = '125'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - livecall QUERY : DELETE FROM `tp_livecall` WHERE `uniqueid` = 'sip.tt-1725644323.88' or  `uniqueid2` = 'sip.tt-1725644323.88' AND server_id = '2'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - check_auth_account QUERY : SELECT `tp_account`.`hosted`,`tp_account`.`voicemail_passwd`, `tp_account`.`ringtime` as exten_ringtime, `tp_customer`.`trunk_accountcode`, `tp_account`.`dialpatterngroup_id`, `tp_account`.`hidecallerid`, `tp_account`.`trunk_exten`, `tp_account`.`agentexten_type`, `tp_customer`.`email` AS customer_email, `tp_customer`.`commoncredit` AS customer_commoncredit , `tp_customer`.`recording_override` AS customer_recording_override, `tp_account`.`account_id`,  `tp_account`.`name`,  `tp_account`.`username`,  `tp_account`.`accountcode`, `tp_account`.`customer_id`,  `tp_account`.`credit`,  `tp_account`.`callplan_id`, `tp_account`.`calleridlocal`,  `tp_account`.`calleridexternal`, `tp_account`.`musiconhold`,  `tp_account`.`voicemail`,  `tp_account`.`fax`,  `tp_account`.`inuse`,  `tp_account`.`sipuser`, `tp_account`.`iaxuser`, `tp_account`.`billing_type`, `tp_account`.`failover_app`, `tp_account`.`failover_appnumber`, `tp_account`.`recording`, `tp_customer`.`dial_option`, `tp_customer`.`ringtime`, `tp_customer`.`recording_path` , `tp_account`.`extennumber` , `tp_customer`.`maxcallduration` FROM  `tp_account`  INNER JOIN `tp_customer`  ON `tp_account`.`customer_id` = `tp_customer`.`customer_id`   WHERE  `tp_account`.`activated` = 't' AND `tp_account`.`status` = '1'  AND `tp_customer`.`status` = '1' AND `accountcode` = 'ehtrunk'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:1208 - uniqueid:sip.tt-1725644323.88 -  check_auth_account Username ehtrunk, CustID 1 , AccountID 21 Source : 6611test <6611>, Destination :h
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/agi.php - line:2910 - uniqueid:sip.tt-1725644323.88 - CDR  clid 6611test <6611> src 6611 dst 8610 dcontext default channel SIP/ehtrunknew-00000036 dstchannel  lastapp Hangup lastdata  starttime 2024-09-06 21:38:43 answertime  disposition FAILED Stotime 2024-09-06 21:38:43
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - cdr QUERY : INSERT INTO `tp_cdr` (`customer_id`, `account_id`, `trunk_id`, `rate_id`, `rateplan_id`, `callplan_id`, `trunkgroup_id`, `uniqueid`, `starttime`, `stoptime`, `answertime`, `ringduration`, `billsec`, `callduration`, `destination`, `src`, `terminatecause`, `sale_rate`, `sale_cost`, `buy_rate`, `buy_cost`, `sipiax`, `recording_file`, `call_type`,`app_billsec`,`last_app`, `dst`) VALUES ('1', '21', '', '', '', '', '', 'sip.tt-1725644323.88', '2024-09-06 21:38:43', '2024-09-06 21:38:43', '', '0', '0', '0','8610', '6611', 'FAILED', '', '', '', '', '', '', 'INTERNAL','0','Hangup','')
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/agi.php - line:3001 - uniqueid:sip.tt-1725644323.88 - CDR  Query INSERT INTO `tp_cdr` (`customer_id`, `account_id`, `trunk_id`, `rate_id`, `rateplan_id`, `callplan_id`, `trunkgroup_id`, `uniqueid`, `starttime`, `stoptime`, `answertime`, `ringduration`, `billsec`, `callduration`, `destination`, `src`, `terminatecause`, `sale_rate`, `sale_cost`, `buy_rate`, `buy_cost`, `sipiax`, `recording_file`, `call_type`,`app_billsec`,`last_app`, `dst`) VALUES ('1', '21', '', '', '', '', '', 'sip.tt-1725644323.88', '2024-09-06 21:38:43', '2024-09-06 21:38:43', '', '0', '0', '0','8610', '6611', 'FAILED', '', '', '', '', '', '', 'INTERNAL','0','Hangup','')
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - cdr QUERY : delete from `tp_call_status` where `dead_call` = '1' AND `callId` = 'sip.tt-1725644323.88'  AND `status` = 'NEW' AND `callerId` = ''
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - missedcall_count QUERY : UPDATE blf_livestatus SET missed_call = ifnull(missed_call,0) + 1, exten_status_update = now() where customer_id = '1' AND extension IN ('' , '8610') AND account_id<> '21'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/agi.php - line:3011 - uniqueid:sip.tt-1725644323.88 - CDR  Query UPDATE blf_livestatus SET missed_call = ifnull(missed_call,0) + 1, exten_status_update = now() where customer_id = '1' AND extension IN ('' , '8610') AND account_id<> '21'
 agi.php,CDR: file:/var/lib/asterisk/agi-bin/Class.TpadPBX.php - line:190 - uniqueid:sip.tt-1725644323.88 - cdr QUERY : SELECT email from as_voicemail where mailbox = ''
    -- <SIP/ehtrunknew-00000036>AGI Script agi.php completed, returning 0
    -- Executing [h@default:2] Hangup("SIP/ehtrunknew-00000036", "") in new stack
  == Spawn extension (default, h, 2) exited non-zero on 'SIP/ehtrunknew-00000036'

david551 · September 6, 2024, 6:29pm

Your dialplan seems to consist of a user supplied AGI script, followed by a call to Hangup. As the script doesn’t look as though it answers the call, the call is hungup unanswered, which is why it is rejected.

As it is user supplied, you need to contact its author to explain how it is supposed to work.

hishamjan · September 6, 2024, 7:17pm

No, it is not user supplied. I have worked on the AGI on this server (upgraded its PHPAGI and PHP versions) and the same script works when dialing for outbound calls. For reference, the call lands on a server where a similar AGI code exists, therefore, if outgoing calls are working between servers with the same AGI scripts, it is supposed to work for incoming calls as well, in my opinion. Also, the dialplan has MaroExit() function in place to handle exiting the macro without hanging up the channel.

Can it be a server level issue? I have checked firewalls and it allows such connections, so there’s no issue on the network level…

Let me know if I can provide any more info…

david551 · September 6, 2024, 7:51pm

You need to contact whoever supplied it. I think all the AGI code supplied with Asterisk is user contributed, but that would have names explaining what it did, so, from Asterisk’s point of view, your agi.php will, absolutely, be user supplied, and we won’t be able to debug it without sight of its source code.

hishamjan · September 7, 2024, 10:26pm

Hi @david551 ,

To isolate the issue, I actually did a revamp of the dialplan and removed the AGI script altogether. Now the dialpal looks as below:

extensions.conf

[default]
exten => _X.,1,NoOp(===NEW DIALPLAN from A to B====)
same => n,NoOp(Dialed Number: ${EXTEN})
same => n,NoOp(Caller ID: ${CALLERID(ALL)})

exten => _5XXX,1,Dial(SIP/ip_add/1*${EXTEN},20)
same => n,Hangup()

sip.conf is:

[ServerA]
host=dynamic
username=ServerA
secret=password
type=friend
qualify=yes
disallow=all
insecure=invite,port
allow=alaw
allow=ulaw
allow=gsm
allow=g729
allow=all
nat=force_rport,comedia
context=default
accountcode=ServerA
directmedia=no
sendrpid=pai
trustrpid=yes
rpid_update=yes
deny=0.0.0.0/0.0.0.0
permit=ip_add_A/255.255.255.255

sip debug logs on ServerB are:

– Executing [6498@default:1] Dial(“SIP/15610-0000000a", "SIP/ip_add_B/16498,20”) in new stack
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
[Sep 8 02:07:49] ERROR[24992]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_B-0000000b
[Sep 8 02:07:49] ERROR[24992]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_B-0000000b
[Sep 8 02:07:49] ERROR[24992]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_B-0000000b
Audio is at 19540
Adding codec alaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to ip_add_B:5060:
INVITE sip:16498@ip_add_B SIP/2.0
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK3ad54033;rport
Max-Forwards: 70
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as31114440
To: sip:1*6498@ip_add_B
Contact: sip:5610@ip_add_A:5060
Call-ID: 186d8c7f449cb24869d8854758f5df3d@ip_add_A:5060
CSeq: 102 INVITE
User-Agent: tpadpbx
Date: Sat, 07 Sep 2024 22:07:49 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
P-Asserted-Identity: “Hisham Ahmad” sip:5610@ip_add_A
Content-Type: application/sdp
Content-Length: 238
v=0
o=root 1175385570 1175385570 IN IP4 ip_add_A
s=Asterisk PBX 18.22.0
c=IN IP4 ip_add_A
t=0 0
m=audio 19540 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:140
a=sendrecv
– Called SIP/ip_add_B/16498
<— SIP read from UDP:ip_add_B:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK3ad54033;received=ip_add_A;rport=5060
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as31114440
To: sip:1*6498@ip_add_B
Call-ID: 186d8c7f449cb24869d8854758f5df3d@ip_add_A:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:1*6498@ip_add_B:5060
Content-Length: 0
<------------->
— (12 headers 0 lines) —
<— SIP read from UDP:ip_add_B:5060 —>
SIP/2.0 603 Declined
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK3ad54033;received=ip_add_A;rport=5060
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as31114440
To: sip:1*6498@ip_add_B;tag=as0169d1b2
Call-ID: 186d8c7f449cb24869d8854758f5df3d@ip_add_A:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
<------------->
— (11 headers 0 lines) —
– Got SIP response 603 “Declined” back from ip_add_B:5060
Transmitting (NAT) to ip_add_B:5060:
ACK sip:16498@ip_add_B SIP/2.0
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK3ad54033;rport
Max-Forwards: 70
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as31114440
To: sip:1*6498@ip_add_B;tag=as0169d1b2
Contact: sip:5610@ip_add_A:5060
Call-ID: 186d8c7f449cb24869d8854758f5df3d@ip_add_A:5060
CSeq: 102 ACK
User-Agent: tpadpbx
Content-Length: 0
– SIP/ip_add_B-0000000b is busy
== Everyone is busy/congested at this time (1:1/0/0)
– Executing [6498@default:2] Hangup("SIP/15610-0000000a", “”) in new stack
== Spawn extension (default, 6498, 2) exited non-zero on ‘SIP/1*5610-0000000a’
Really destroying SIP dialog ‘186d8c7f449cb24869d8854758f5df3d@ip_add_A:5060’ Method: INVITE

sip debug logs on ServerA are:

<— SIP read from UDP:ip_add_A:5060 —>
INVITE sip:16498@ip_add_B SIP/2.0
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK1e86f714;rport
Max-Forwards: 70
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as71297c4e
To: sip:1*6498@ip_add_B
Contact: sip:5610@ip_add_A:5060
Call-ID: 58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060
CSeq: 102 INVITE
User-Agent: tpadpbx
Date: Sat, 07 Sep 2024 22:19:12 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
P-Asserted-Identity: “Hisham Ahmad” sip:5610@ip_add_A
Content-Type: application/sdp
Content-Length: 238
v=0
o=root 2014035438 2014035438 IN IP4 ip_add_A
s=Asterisk PBX 18.22.0
c=IN IP4 ip_add_A
t=0 0
m=audio 16152 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:140
a=sendrecv
<------------->
— (15 headers 11 lines) —
Sending to ip_add_A:5060 (NAT)
Sending to ip_add_A:5060 (NAT)
Using INVITE request as basis request - 58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060
Found peer ‘ip_add_A’ for ‘5610’ from ip_add_A:5060
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Got SDP version 2014035438 and unique parts [root 2014035438 IN IP4 ip_add_A]
Found RTP audio format 8
Found RTP audio format 101
Found audio description format PCMA for ID 8
Found audio description format telephone-event for ID 101
Capabilities: us - (alaw|ulaw|gsm|g729|codec2|g723|g726|g726aal2|adpcm|slin|slin12|slin16|slin24|slin32|slin44|slin48|slin96|slin192|lpc10|speex|speex16|speex32|ilbc|g722|siren7|siren14|testlaw|g719|opus|jpeg|png|h261|h263|h263p|h264|h265|mpeg4|vp8|vp9|red|t140|t38|silk8|silk12|silk16|silk24), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port ip_add_A:16152
Peer doesn’t provide video
Looking for 16498 in default (domain ip_add_B)
[Sep 7 23:19:10] ERROR[13430]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_A-00000007
[Sep 7 23:19:10] ERROR[13430]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_A-00000007
[Sep 7 23:19:10] ERROR[13430]: cdr.c:3397 ast_cdr_getvar: Unable to find CDR for channel SIP/ip_add_A-00000007
sip_route_dump: route/path hop: sip:5610@ip_add_A:5060
<— Transmitting (NAT) to ip_add_A:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK1e86f714;received=ip_add_A;rport=5060
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as71297c4e
To: sip:1*6498@ip_add_B
Call-ID: 58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:1*6498@ip_add_B:5060
Content-Length: 0
<------------>
– Executing [16498@default:1] NoOp(“SIP/ip_add_A-00000007”, “===NEW DIALPLAN B to A====”) in new stack
– Executing [16498@default:2] NoOp(“SIP/ip_add_A-00000007”, "Dialed Number: 16498") in new stack
– Executing [16498@default:3] NoOp(“SIP/ip_add_A-00000007”, “Caller ID: “Hisham Ahmad” <5610>”) in new stack
– Auto fallthrough, channel ‘SIP/ip_add_A-00000007’ status is ‘UNKNOWN’
Scheduling destruction of SIP dialog ‘58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060’ in 6400 ms (Method: INVITE)
<— Reliably Transmitting (NAT) to ip_add_A:5060 —>
SIP/2.0 603 Declined
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK1e86f714;received=ip_add_A;rport=5060
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as71297c4e
To: sip:1*6498@ip_add_B;tag=as2dce00df
Call-ID: 58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060
CSeq: 102 INVITE
Server: tpadpbx
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
<------------>
<— SIP read from UDP:ip_add_A:5060 —>
ACK sip:1*6498@ip_add_B SIP/2.0
Via: SIP/2.0/UDP ip_add_A:5060;branch=z9hG4bK1e86f714;rport
Max-Forwards: 70
From: “Hisham Ahmad” sip:5610@ip_add_A;tag=as71297c4e
To: sip:1*6498@ip_add_B;tag=as2dce00df
Contact: sip:5610@ip_add_A:5060
Call-ID: 58b1a626156f3bfc1f244ef03936879f@ip_add_A:5060
CSeq: 102 ACK
User-Agent: tpadpbx
Content-Length: 0
<------------->
— (10 headers 0 lines) —

I am still getting the SIP/2.0 603 Declined…any guidance as to why is this happening? I would appreciate your help!

david551 · September 7, 2024, 10:59pm

You are calling a five digit extension beginning with 1, but your dialplan only does anything other than NoOps for four digit numbers, beginning with 5. It drops off the end of the three NoOp,s so there is an implied Hangup. As no dial has been attempted, the hangup is treated as a refusal to accept the call and 603 is sent. Asterisk is working correctly.