I am facing a rather strange situation. Asterisk successfully registers with the SIP trunk provider, but it is unable to place calls, and gets banned shortly after. I have been in touch with customer support and they can’t figure out what’s happening either.
This is a fresh VICIdial system installed through VICIbox.
Here is the full sequence of events.
dial1*CLI> sip reload
[May 26 12:49:13] Reloading SIP
dial1*CLI> sip show registry
Host dnsmgr Username Refresh State Reg.Time
sip5.teletek.se:5060 Y xxxxxxxxxxxx 585 Registered Thu, 26 May 2022 12:49:13
1 SIP registrations.
dial1*CLI> sip show peers
Name/username Host Dyn Forcerport Comedia ACL Port Status Description
gs102/gs102 (Unspecified) D Yes Yes 0 UNKNOWN
phone01/phone01 (Unspecified) D Yes Yes 0 UNKNOWN
phone02/phone02 xx.xxx.xxx.xxx D Yes Yes 57670 OK (380 ms)
teletek/xxxxxxxxxxxxxxxxx 185.146.140.40 Yes Yes 5060 OK (18 ms)
4 sip peers [Monitored: 2 online, 2 offline Unmonitored: 0 online, 0 offline]
At this point, asterisk is successfully registered with the provider.
I am then logging into the agent web interface, and answer the call on my PC (using MicroSIP). The logs are below:
[May 26 12:49:52] -- Called 8600051@default
[May 26 12:49:52] -- Executing [8600051@default:1] MeetMe("Local/8600051@default-0000000a;2", "8600051,F") in new stack
[May 26 12:49:52] -- Local/8600051@default-0000000a;1 answered
[May 26 12:49:52] -- Executing [900460856485160@default:1] AGI("Local/8600051@default-0000000a;1", "agi://127.0.0.1:4577/call_log") in new stack
[May 26 12:49:52] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=T1))
[May 26 12:49:52] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPDTO=60))
[May 26 12:49:52] -- <Local/8600051@default-0000000a;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[May 26 12:49:52] -- Executing [900460856485160@default:2] Dial("Local/8600051@default-0000000a;1", "SIP/00460856485160@teletek,,tTo") in new stack
[May 26 12:49:52] == Using SIP RTP CoS mark 5
[May 26 12:49:52] -- Called SIP/00460856485160@teletek
[May 26 12:49:52] NOTICE[14636][C-00000016]: chan_sip.c:24219 handle_response_invite: Failed to authenticate on INVITE to '"M5261249520000002745" <sip:0000000000@212.227.155.194>;tag=as488f806d'
[May 26 12:49:52] -- SIP/teletek-0000000b is circuit-busy
[May 26 12:49:52] == Everyone is busy/congested at this time (1:0/1/0)
[May 26 12:49:52] -- Executing [900460856485160@default:3] Hangup("Local/8600051@default-0000000a;1", "") in new stack
[May 26 12:49:52] == Spawn extension (default, 900460856485160, 3) exited non-zero on 'Local/8600051@default-0000000a;1'
[May 26 12:49:52] -- Executing [h@default:1] AGI("Local/8600051@default-0000000a;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION---------------SIP 407 Proxy Authentication Required)") in new stack
[May 26 12:49:52] -- <Local/8600051@default-0000000a;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION---------------SIP 407 Proxy Authentication Required) completed, returning 0
[May 26 12:49:52] == Spawn extension (default, 8600051, 1) exited non-zero on 'Local/8600051@default-0000000a;2'
[May 26 12:49:52] WARNING[104250][C-00000015]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[May 26 12:49:52] -- Executing [h@default:1] AGI("Local/8600051@default-0000000a;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21--------------------)") in new stack
[May 26 12:49:52] -- <Local/8600051@default-0000000a;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21--------------------) completed, returning 0
This call fails with the following message:
Call Rejected: CHANUNAVAIL
Cause: 21 - Call rejected.
SIP: 407 - Proxy Authentication Required
If I then hang up and dial again, I get the following:
[May 26 12:51:56] -- Called 8600051@default
[May 26 12:51:56] -- Executing [8600051@default:1] MeetMe("Local/8600051@default-0000000b;2", "8600051,F") in new stack
[May 26 12:51:56] -- Local/8600051@default-0000000b;1 answered
[May 26 12:51:56] -- Executing [900460856485160@default:1] AGI("Local/8600051@default-0000000b;1", "agi://127.0.0.1:4577/call_log") in new stack
[May 26 12:51:56] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=T1))
[May 26 12:51:56] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPDTO=60))
[May 26 12:51:56] -- <Local/8600051@default-0000000b;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[May 26 12:51:56] -- Executing [900460856485160@default:2] Dial("Local/8600051@default-0000000b;1", "SIP/00460856485160@teletek,,tTo") in new stack
[May 26 12:51:56] == Using SIP RTP CoS mark 5
[May 26 12:51:56] -- Called SIP/00460856485160@teletek
[May 26 12:51:56] WARNING[14636][C-00000018]: chan_sip.c:24232 handle_response_invite: Received response: "Forbidden" from '"M5261251560000002746" <sip:0000000000@212.227.155.194>;tag=as47196cc3'
[May 26 12:51:56] == Everyone is busy/congested at this time (1:0/0/1)
[May 26 12:51:56] -- Executing [900460856485160@default:3] Hangup("Local/8600051@default-0000000b;1", "") in new stack
[May 26 12:51:56] == Spawn extension (default, 900460856485160, 3) exited non-zero on 'Local/8600051@default-0000000b;1'
[May 26 12:51:56] -- Executing [h@default:1] AGI("Local/8600051@default-0000000b;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL---------------SIP 403 Try again later)") in new stack
[May 26 12:51:56] -- <Local/8600051@default-0000000b;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CHANUNAVAIL---------------SIP 403 Try again later) completed, returning 0
[May 26 12:51:56] == Spawn extension (default, 8600051, 1) exited non-zero on 'Local/8600051@default-0000000b;2'
[May 26 12:51:56] WARNING[104459][C-00000017]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[May 26 12:51:56] -- Executing [h@default:1] AGI("Local/8600051@default-0000000b;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21--------------------)") in new stack
[May 26 12:51:56] -- <Local/8600051@default-0000000b;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21--------------------) completed, returning 0
This second call fails with:
Call Rejected: CHANUNAVAIL
Cause: 21 - Call rejected.
SIP: 403 - Try again later)
A few minutes later:
[May 26 12:58:58] WARNING[14636]: chan_sip.c:24646 handle_response_register: Forbidden - wrong password on authentication for REGISTER for 'xxxxxxxxxxxxxxxxxxx' to 'sip5.teletek.se'
The password is correct though. It had just been used to register previously.
At this point, I can’t re-register anymore.
dial1*CLI> sip reload
[May 26 13:10:03] Reloading SIP
[May 26 13:10:03] WARNING[14636]: chan_sip.c:24646 handle_response_register: Forbidden - wrong password on authentication for REGISTER for 'xxxxxxxxxxxxxxxxxxxxxx' to 'sip5.teletek.se'
dial1*CLI> sip show registry
Host dnsmgr Username Refresh State Reg.Time
sip5.teletek.se:5060 Y xxxxxxxxxxxx 585 No Authentication Thu, 26 May 2022 12:49:13
1 SIP registrations.
FYI, this is my dialplan:
exten => _91XXXXXXXXXX,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _91XXXXXXXXXX,2,Dial(SIP/${EXTEN:1}@teletek,,tTo)
exten => _91XXXXXXXXXX,3,Hangup
exten => _900X.,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _900X.,2,Dial(SIP/${EXTEN:1}@teletek,,tTo)
exten => _900X.,3,Hangup
And here is where teletek is defined:
[teletek]
disallow=all
type=friend
username=user
password=pass
host=sip5.teletek.se
port=5060
dtmfmode=rfc2833
context=trunkinbound
allow=alaw
allow=ulaw
Globals string: teletek = SIP/teletek
Any thoughts on how to start debugging this further would be really appreciated.