Asterisk banned shortly after a 407 Proxy Authentication Required. Unable to place calls

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.

The reply Failed to authenticate on INVITE to '"M5261249520000002745" likely indicates a wrong configuration or bad syntax in the declarations. It could be a wrong password or a wrong account name, or something else. I have no idea why this is happening, but it could be related to the other software you are using or special requirements by your service provider. Do normal calls (without the other click2call software) work?

As usual, a meaningful SIP trace would be highly appreciated…

That said, you should not use chan_sip and switch to pjsip.

Thank you! I am working to get voipmonitor running, not sure how else to provide a SIP trace. If you have any suggestions I am happy to do it.

I have managed to connect to the SIP provider using a MicroSIP phone and place outbound calls. MicroSIP works, but VICIdial doesn’t.

Also, my provider tells me that no traffic is even reaching their system from my VICIdial box.

Now, outbound calls from VICIdial fail with:

DIAL ALERT:

Call Rejected: CHANUNAVAIL
Cause: 58 - Bearer capability not presently available.
SIP: 488 - Not Acceptable Here)

And here are the corresponding messages in the CLI:

[May 27 11:54:18]        > 0x7f0384008620 -- Strict RTP learning complete - Locking on source address 27.147.201.159:4028
[May 27 11:54:18]     -- Called 8600051@default
[May 27 11:54:18]     -- Executing [8600051@default:1] MeetMe("Local/8600051@default-00000001;2", "8600051,F") in new stack
[May 27 11:54:18]     -- Local/8600051@default-00000001;1 answered
[May 27 11:54:18]     -- Executing [900460856485160@default:1] AGI("Local/8600051@default-00000001;1", "agi://127.0.0.1:4577/call_log") in new stack
[May 27 11:54:18]     -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=T1))
[May 27 11:54:18]     -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPDTO=60))
[May 27 11:54:18]     -- <Local/8600051@default-00000001;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[May 27 11:54:18]     -- Executing [900460856485160@default:2] Dial("Local/8600051@default-00000001;1", "SIP/00460856485160@teletek,,tTo") in new stack
[May 27 11:54:18]   == Using SIP RTP CoS mark 5
[May 27 11:54:18]     -- Called SIP/00460856485160@teletek
[May 27 11:54:18]   == Everyone is busy/congested at this time (1:0/0/1)
[May 27 11:54:18]     -- Executing [900460856485160@default:3] Hangup("Local/8600051@default-00000001;1", "") in new stack
[May 27 11:54:18]   == Spawn extension (default, 900460856485160, 3) exited non-zero on 'Local/8600051@default-00000001;1'
[May 27 11:54:18]     -- Executing [h@default:1] AGI("Local/8600051@default-00000001;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----58-----CHANUNAVAIL---------------SIP 488 Not Acceptable Here)") in new stack
[May 27 11:54:18]     -- <Local/8600051@default-00000001;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----58-----CHANUNAVAIL---------------SIP 488 Not Acceptable Here) completed, returning 0
[May 27 11:54:18]   == Spawn extension (default, 8600051, 1) exited non-zero on 'Local/8600051@default-00000001;2'
[May 27 11:54:18] WARNING[121330][C-00000002]: func_hangupcause.c:140 hangupcause_read: Unable to find information for channel
[May 27 11:54:18]     -- Executing [h@default:1] AGI("Local/8600051@default-00000001;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----58--------------------)") in new stack
[May 27 11:54:18]     -- <Local/8600051@default-00000001;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----58--------------------) completed, returning 0
[May 27 11:54:36]        > Saved useragent "MicroSIP/3.21.1" for peer phone02

My current dialplan is:

exten => _90X.,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _90X.,2,Dial(SIP/${EXTEN:1}@teletek,,tTo)
exten => _90X.,3,Hangup

And my carrier setup:

[teletek]
disallow=all
allow=ulaw
type=peer
username=xxxx
secret=xxxx
host=sip5.teletek.se
dtmfmode=rfc2833
context=trunkinbound
nat=yes

https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information#CollectingDebugInformation-Enablechanneltechorfeaturespecificdebug

That typically means that either you have specified incompatible encryption options, or none of the codecs you have offered are supported by the other side.

Thank you for the Wiki link! See the SIP trace here: removed

Re: codecs, I am offering ulaw and alaw, should be pretty standard, right? Happy to add other codecs as well.

Re: encryption, I haven’t myself specified any encryption options, so I’m not sure how to check if that’s the problem.

Actually you are only offering ulaw (µ-Law). Possibility one is that they aren’t prepared to transcode. European PSTN systems use A-law, not µ-law.

Possibility two is that they either don’t like RFC 4733/2833, or they will only accept it without digit code 16, for hook flash. Try dtmfmode=inband.

This… was it. It’s working now! @david551 you’re a life saver!

For anyone else finding this in the future, my initial problem was solved by changing type=friend to type=peer and changing password=myawesomepass to secret=myawesomepass. I’m not sure why this worked (maybe others can chime in), but it did solve my authentication issue.

I then ran into a 488 error which was a codec compatibility issue, had to use alaw instead of ulaw.

It looks as if there was an ISDN device involved. You can usually configure it with the proper G.711 codec, so that no transcoding is necessary. The missing bearer capability message came from such a device.

Your “488 Not Acceptable Here” had a reason header with the message “Q.850;cause=65”.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.