Calls dropping after 25 seconds for single client.

[Two8nine]

Vicidial version: 2.14-694a
Vicidial build: 181005-1738
Asterisk version: 13.21.1-vici

Hi, hoping for some help getting to the bottom of an issue. As of the last couple weeks, we are having issues calling a particular client. 80-90% of calls made to this client fail (silence for 25 seconds then hangs up.) They worked in the past without issue, and no changes have been made.

I'm not too strong with asterisk, but things that may be important:

All calls are MANDIAL
All calls utilize the Canada PRI CIDname type function in extensions.conf. (as do all working clients.)
Retrying the dial repeatedly will usually be successful.

asterisk -r shows the cause as CHANUNAVAIL, and 'all channels are busy/congested'.

I've pulled a block of text from asterisk messages with sip debug for a failing call -- but I'm not too sure of what to look for.

Assuming this is more than needed, but covers the period in which call failed.

Any thoughts, or different steps needed for debugging this?

Code: Select all

[Feb 21 20:46:14] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for SIP - carrier
[Feb 21 20:46:14] DEBUG[2000] chan_sip.c: Checking device state for peer carrier
[Feb 21 20:46:14] DEBUG[2000] devicestate.c: Changing state for SIP/carrier - state 1 (Not in use)
[Feb 21 20:46:14] DEBUG[2000] devicestate.c: device 'SIP/carrier' state '1'
[Feb 21 20:46:14] DEBUG[2008] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.10.254:44747
[Feb 21 20:46:14] DEBUG[2008] chan_sip.c: Destroying SIP dialog 6dd0988a68c637d504384e6b53e6ca2d@192.168.10.120:5060
[Feb 21 20:46:15] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:15] DEBUG[2008] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.10.41:59736
[Feb 21 20:46:15] DEBUG[2008] chan_sip.c: Destroying SIP dialog 213f7ba40a1a535c12dd81aa13463272@192.168.10.120:5060
[Feb 21 20:46:15] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:15] DEBUG[2010] chan_iax2.c: ip callno count decremented to 5 for 192.168.10.123
[Feb 21 20:46:15] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:16] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:16] DEBUG[2027][C-00000050] chan_iax2.c: JB STATS:IAX2/127.0.0.1:40569-5916 ping=3 ljitterms=1 ljbdelayms=41 ltotlost=0 lrecentlosspct=0 ldropped=0 looo=0 lrecvd=1033 rjitterms=0 rjbdelayms=41 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=1028
[Feb 21 20:46:16] DEBUG[2037] chan_iax2.c: JB STATS:IAX2/ASTloop-2397 ping=3 ljitterms=0 ljbdelayms=41 ltotlost=0 lrecentlosspct=0 ldropped=0 looo=0 lrecvd=1029 rjitterms=1 rjbdelayms=41 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=1033
[Feb 21 20:46:16] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:17] DEBUG[12738][C-0000004f] res_rtp_asterisk.c: Got RTCP report of 96 bytes from 192.168.10.70:8001
[Feb 21 20:46:17] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:17] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:18] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:18] DEBUG[12754][C-00000051] res_rtp_asterisk.c: Got RTCP report of 72 bytes from 192.168.10.119:10087
[Feb 21 20:46:18] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:19] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:19] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:19] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:20] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:20] DEBUG[2008][C-00000051] chan_sip.c: Acked pending invite 102
[Feb 21 20:46:20] DEBUG[2008][C-00000051] chan_sip.c: Stopping retransmission on '62af5bdb2989a08e2365a6d84d1e13d7@192.168.10.120:5060' of Request 102: Match Found
[Feb 21 20:46:20] DEBUG[2008][C-00000051] chan_sip.c: SIP response 408 to standard invite
[Feb 21 20:46:20] DEBUG[2008][C-00000051] chan_sip.c: Trying to put 'ACK sip:180' onto UDP socket destined for 192.168.10.119:5060
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: SIP-Hangup-Cause
Privilege: system,all
ChannelDriver: SIP
Channel: SIP/carrier-00000028
CallerIDName: CLIENTNAME
Uniqueid: 1582339555.162
Result: 408|Request Timeout

[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: HangupRequest
Privilege: call,all
Channel: SIP/carrier-00000028
Uniqueid: 1582339555.162
Cause: 18


[Feb 21 20:46:20] DEBUG[12754][C-00000051] channel.c: Hanging up channel 'SIP/carrier-00000028'
[Feb 21 20:46:20] DEBUG[12754][C-00000051] chan_sip.c: Hangup call SIP/carrier-00000028, SIP callid 62af5bdb2989a08e2365a6d84d1e13d7@192.168.10.120:5060
[Feb 21 20:46:20] DEBUG[12754][C-00000051] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6784012818'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: SIP/carrier-00000028
Uniqueid: 1582339555.162
CallerIDNum: 855XXXXXXX
CallerIDName: CLIENTNAME
ConnectedLineNum: 855XXXXXXX
ConnectedLineName: CLIENTNAME
AccountCode: ASTloop
Cause: 18
Cause-txt: No user responding

[Feb 21 20:46:20] VERBOSE[12754][C-00000051] app_dial.c: [Feb 21 20:46:20]   == Everyone is busy/congested at this time (1:0/0/1)
[Feb 21 20:46:20] VERBOSE[12754][C-00000051] app_dial.c: [Feb 21 20:46:20]   == Everyone is busy/congested at this time (1:0/0/1)
[Feb 21 20:46:20] DEBUG[12754][C-00000051] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for SIP - carrier
[Feb 21 20:46:20] DEBUG[12754][C-00000051] pbx.c: Launching 'Hangup'
[Feb 21 20:46:20] DEBUG[2000] chan_sip.c: Checking device state for peer carrier
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: Changing state for SIP/carrier - state 1 (Not in use)
[Feb 21 20:46:20] VERBOSE[12754][C-00000051] pbx.c: [Feb 21 20:46:20]     -- Executing [7180XXXXXXXX@loopback-no-log:4] Hangup("IAX2/ASTloop-2397", "") in new stack
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: device 'SIP/carrier' state '1'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Dial
Privilege: call,all
SubEvent: End
Channel: IAX2/ASTloop-2397
UniqueID: 1582339555.161
DialStatus: CHANUNAVAIL


[Feb 21 20:46:20] DEBUG[12754][C-00000051] channel.c: Soft-Hanging up channel 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] DEBUG[12754][C-00000051] pbx.c: Spawn extension (loopback-no-log,7180XXXXXXXX,4) exited non-zero on 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] VERBOSE[12754][C-00000051] pbx.c: [Feb 21 20:46:20]   == Spawn extension (loopback-no-log, 7180XXXXXXXX, 4) exited non-zero on 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] DEBUG[12754][C-00000051] channel.c: Soft-Hanging up channel 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] DEBUG[12754][C-00000051] channel.c: Hanging up channel 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: IAX2/ASTloop-2397
Uniqueid: 1582339555.161
Cause: 16


[Feb 21 20:46:20] DEBUG[12754][C-00000051] chan_iax2.c: We're hanging up IAX2/ASTloop-2397 now...
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: HangupRequest
Privilege: call,all
Channel: IAX2/ASTloop-2397
Uniqueid: 1582339555.161

[Feb 21 20:46:20] VERBOSE[12754][C-00000051] chan_iax2.c: [Feb 21 20:46:20]     -- Hungup 'IAX2/ASTloop-2397'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: IAX2/ASTloop-2397
Uniqueid: 1582339555.161
CallerIDNum: 855XXXXXXX
CallerIDName: CLIENTNAME
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
AccountCode: ASTloop
Cause: 18
Cause-txt: No user responding


[Feb 21 20:46:20] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for IAX2 - ASTloop
[Feb 21 20:46:20] DEBUG[2000] chan_iax2.c: Checking device state for device ASTloop
[Feb 21 20:46:20] DEBUG[2000] chan_iax2.c: Found peer. What's device state of ASTloop? addr=2130706433, defaddr=0 maxms=2000, lastms=1
[Feb 21 20:46:20] DEBUG[2045][C-00000050] chan_iax2.c: Immediately destroying 5916, having received hangup
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: Changing state for IAX2/ASTloop - state 0 (Unknown)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: device 'IAX2/ASTloop' state '0'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: HangupRequest
Privilege: call,all
Channel: IAX2/127.0.0.1:40569-5916
Uniqueid: 1582339555.160


[Feb 21 20:46:20] DEBUG[12752][C-00000050] channel.c: Hanging up channel 'IAX2/127.0.0.1:40569-5916'
[Feb 21 20:46:20] DEBUG[12752][C-00000050] chan_iax2.c: We're hanging up IAX2/127.0.0.1:40569-5916 now...
[Feb 21 20:46:20] DEBUG[12751][C-00000050] app_meetme.c: Got ignored control frame on channel Local/8600051@default-0000001d;2, f->frametype=4,f->subclass=33
[Feb 21 20:46:20] DEBUG[12752][C-00000050] chan_iax2.c: Really destroying IAX2/127.0.0.1:40569-5916 now...
[Feb 21 20:46:20] DEBUG[12752][C-00000050] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[Feb 21 20:46:20] VERBOSE[12752][C-00000050] chan_iax2.c: [Feb 21 20:46:20]     -- Hungup 'IAX2/127.0.0.1:40569-5916'
[Feb 21 20:46:20] DEBUG[2018] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: HangupRequest
Privilege: call,all
Channel: IAX2/127.0.0.1:40569-5916
Uniqueid: 1582339555.160

[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: IAX2/127.0.0.1:40569-5916
Uniqueid: 1582339555.160
CallerIDNum: 855XXXXXXX
CallerIDName: M2212045550002649675
ConnectedLineNum: 855XXXXXXX
ConnectedLineName: M2212045550002649675
AccountCode:
Cause: 18
Cause-txt: No user responding


[Feb 21 20:46:20] VERBOSE[12752][C-00000050] app_dial.c: [Feb 21 20:46:20]   == Everyone is busy/congested at this time (1:0/0/1)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for IAX2 - 127.0.0.1:40569
[Feb 21 20:46:20] DEBUG[2000] chan_iax2.c: Checking device state for device 127.0.0.1
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: Changing state for IAX2/127.0.0.1:40569 - state 4 (Invalid)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: device 'IAX2/127.0.0.1:40569' state '4'
[Feb 21 20:46:20] DEBUG[12752][C-00000050] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Dial
Privilege: call,all
SubEvent: End
Channel: Local/8600051@default-0000001d;1
UniqueID: 1582339555.158
DialStatus: CHANUNAVAIL


[Feb 21 20:46:20] DEBUG[12752][C-00000050] pbx.c: Launching 'Hangup'
[Feb 21 20:46:20] VERBOSE[12752][C-00000050] pbx.c: [Feb 21 20:46:20]     -- Executing [7180XXXXXXXX@default:3] Hangup("Local/8600051@default-0000001d;1", "") in new stack
[Feb 21 20:46:20] DEBUG[12752][C-00000050] channel.c: Soft-Hanging up channel 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] DEBUG[12752][C-00000050] pbx.c: Spawn extension (default,7180XXXXXXXX,3) exited non-zero on 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] VERBOSE[12752][C-00000050] pbx.c: [Feb 21 20:46:20]   == Spawn extension (default, 7180XXXXXXXX, 3) exited non-zero on 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] DEBUG[12752][C-00000050] channel.c: Soft-Hanging up channel 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] DEBUG[12752][C-00000050] channel.c: Soft-Hanging up channel 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: Local/8600051@default-0000001d;1
Uniqueid: 1582339555.158
Cause: 16


[Feb 21 20:46:20] DEBUG[12752][C-00000050] pbx.c: Launching 'AGI'
[Feb 21 20:46:20] VERBOSE[12752][C-00000050] pbx.c: [Feb 21 20:46:20]     -- Executing [h@default:1] AGI("Local/8600051@default-0000001d;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----18-----CHANUNAVAIL----------") in new stack
[Feb 21 20:46:20] DEBUG[12752][C-00000050] res_agi.c: Hungup channel detected, running agi in dead mode.
[Feb 21 20:46:20] DEBUG[12752][C-00000050] res_agi.c: Wow, connected!
[Feb 21 20:46:20] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:20] VERBOSE[12752][C-00000050] res_agi.c: [Feb 21 20:46:20]     -- <Local/8600051@default-0000001d;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----18-----CHANUNAVAIL---------- completed, returning 0
[Feb 21 20:46:20] DEBUG[12752][C-00000050] channel.c: Hanging up channel 'Local/8600051@default-0000001d;1'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: HangupRequest
Privilege: call,all
Channel: Local/8600051@default-0000001d;2
Uniqueid: 1582339555.159

[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: Local/8600051@default-0000001d;1
Uniqueid: 1582339555.158
CallerIDNum: 855XXXXXXX
CallerIDName: M2212045550002649675
ConnectedLineNum: 855XXXXXXX
ConnectedLineName: M2212045550002649675
AccountCode:
Cause: 18
Cause-txt: No user responding


[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: MeetmeLeave
Privilege: call,all
Channel: Local/8600051@default-0000001d;2
Uniqueid: 1582339555.159
Meetme: 8600051
Usernum: 2
CallerIDNum: 855XXXXXXX
CallerIDName: M2212045550002649675
ConnectedLineNum: 855XXXXXXX
ConnectedLineName: M2212045550002649675
Duration: 25

[Feb 21 20:46:20] DEBUG[12751][C-00000050] pbx.c: Spawn extension (default,8600051,1) exited non-zero on 'Local/8600051@default-0000001d;2'
[Feb 21 20:46:20] VERBOSE[12751][C-00000050] pbx.c: [Feb 21 20:46:20]   == Spawn extension (default, 8600051, 1) exited non-zero on 'Local/8600051@default-0000001d;2'
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for Local - 8600051@default
[Feb 21 20:46:20] DEBUG[12751][C-00000050] channel.c: Soft-Hanging up channel 'Local/8600051@default-0000001d;2'
[Feb 21 20:46:20] DEBUG[2000] chan_local.c: Checking if extension 8600051@default exists (devicestate)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: Changing state for Local/8600051@default - state 1 (Not in use)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: device 'Local/8600051@default' state '1'
[Feb 21 20:46:20] DEBUG[12751][C-00000050] channel.c: Soft-Hanging up channel 'Local/8600051@default-0000001d;2'
[Feb 21 20:46:20] DEBUG[12751][C-00000050] pbx.c: Launching 'AGI'
[Feb 21 20:46:20] VERBOSE[12751][C-00000050] pbx.c: [Feb 21 20:46:20]     -- Executing [h@default:1] AGI("Local/8600051@default-0000001d;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 21 20:46:20] DEBUG[12751][C-00000050] res_agi.c: Hungup channel detected, running agi in dead mode.
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: Local/8600051@default-0000001d;2
Uniqueid: 1582339555.159
Cause: 16


[Feb 21 20:46:20] DEBUG[12751][C-00000050] res_agi.c: Wow, connected!
[Feb 21 20:46:20] VERBOSE[12751][C-00000050] res_agi.c: [Feb 21 20:46:20]     -- <Local/8600051@default-0000001d;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 21 20:46:20] DEBUG[12751][C-00000050] channel.c: Hanging up channel 'Local/8600051@default-0000001d;2'
[Feb 21 20:46:20] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: Local/8600051@default-0000001d;2
Uniqueid: 1582339555.159
CallerIDNum: 855XXXXXXX
CallerIDName: M2212045550002649675
ConnectedLineNum: 855XXXXXXX
ConnectedLineName: M2212045550002649675
AccountCode:
Cause: 0
Cause-txt: Unknown


[Feb 21 20:46:20] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for Local - 8600051@default
[Feb 21 20:46:20] DEBUG[2000] chan_local.c: Checking if extension 8600051@default exists (devicestate)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: Changing state for Local/8600051@default - state 1 (Not in use)
[Feb 21 20:46:20] DEBUG[2000] devicestate.c: device 'Local/8600051@default' state '1'
[Feb 21 20:46:21] DEBUG[2008] chan_sip.c: Auto destroying SIP dialog '3fc972dd-cfc0-1238-1690-009027eff86e'
[Feb 21 20:46:21] DEBUG[2008] chan_sip.c: Destroying SIP dialog 3fc972dd-cfc0-1238-1690-009027eff86e
[Feb 21 20:46:21] DEBUG[2008] rtp_engine.c: Destroyed RTP instance '0x7f679c006598'
[Feb 21 20:46:21] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:21] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:22] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:22] DEBUG[2010] chan_iax2.c: ip callno count decremented to 4 for 192.168.10.123
[Feb 21 20:46:22] DEBUG[2212] manager.c: Running action 'Command'
[Feb 21 20:46:22] DEBUG[12833] manager.c: Running action 'Login'
[Feb 21 20:46:22] VERBOSE[12833] manager.c: [Feb 21 20:46:22]   == Manager 'sendcron' logged on from 127.0.0.1
[Feb 21 20:46:22] DEBUG[12833] manager.c: Running action 'Hangup'
[Feb 21 20:46:22] NOTICE[12833] manager.c: Request to hangup non-existent channel: IAX2/127.0.0.1:40569-5916
[Feb 21 20:46:22] DEBUG[12834] manager.c: Running action 'Login'
[Feb 21 20:46:22] VERBOSE[12834] manager.c: [Feb 21 20:46:22]   == Manager 'sendcron' logged on from 127.0.0.1
[Feb 21 20:46:22] DEBUG[12834] manager.c: Running action 'Hangup'
[Feb 21 20:46:22] VERBOSE[12834] manager.c: [Feb 21 20:46:22]     -- Manager 'sendcron' from 127.0.0.1, hanging up channel: Local/58600051@default-0000001e;2
[Feb 21 20:46:22] DEBUG[12834] channel.c: Soft-Hanging up channel 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] DEBUG[2214] manager.c: Examining event:
Event: MeetmeLeave
Privilege: call,all
Channel: Local/58600051@default-0000001e;2
Uniqueid: 1582339571.165
Meetme: 8600051
Usernum: 3
CallerIDNum: <unknown>
CallerIDName: 20200221-204610_80XXXXXXXX
ConnectedLineNum: <unknown>
ConnectedLineName: 20200221-204610_80XXXXXXXX
Duration: 10

[Feb 21 20:46:22] DEBUG[12814][C-00000052] pbx.c: Spawn extension (default,58600051,1) exited non-zero on 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] VERBOSE[12814][C-00000052] pbx.c: [Feb 21 20:46:22]   == Spawn extension (default, 58600051, 1) exited non-zero on 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] DEBUG[12814][C-00000052] channel.c: Soft-Hanging up channel 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] DEBUG[12814][C-00000052] channel.c: Soft-Hanging up channel 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] DEBUG[12814][C-00000052] pbx.c: Launching 'AGI'
[Feb 21 20:46:22] DEBUG[2214] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: Local/58600051@default-0000001e;2
Uniqueid: 1582339571.165
Cause: 16


[Feb 21 20:46:22] VERBOSE[12814][C-00000052] pbx.c: [Feb 21 20:46:22]     -- Executing [h@default:1] AGI("Local/58600051@default-0000001e;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 21 20:46:22] DEBUG[12814][C-00000052] res_agi.c: Hungup channel detected, running agi in dead mode.
[Feb 21 20:46:22] DEBUG[12814][C-00000052] res_agi.c: Wow, connected!
[Feb 21 20:46:22] VERBOSE[12814][C-00000052] res_agi.c: [Feb 21 20:46:22]     -- <Local/58600051@default-0000001e;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 21 20:46:22] DEBUG[12814][C-00000052] channel.c: Hanging up channel 'Local/58600051@default-0000001e;2'
[Feb 21 20:46:22] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: Local/58600051@default-0000001e;2
Uniqueid: 1582339571.165
CallerIDNum: <unknown>
CallerIDName: 20200221-204610_80XXXXXXXX
ConnectedLineNum: <unknown>
ConnectedLineName: 20200221-204610_80XXXXXXXX
AccountCode:
Cause: 0
Cause-txt: Unknown

[Feb 21 20:46:22] DEBUG[12815][C-00000052] pbx.c: Spawn extension (default,8309,3) exited non-zero on 'Local/58600051@default-0000001e;1'
[Feb 21 20:46:22] VERBOSE[12815][C-00000052] pbx.c: [Feb 21 20:46:22]   == Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600051@default-0000001e;1'
[Feb 21 20:46:22] DEBUG[12815][C-00000052] channel.c: Soft-Hanging up channel 'Local/58600051@default-0000001e;1'
[Feb 21 20:46:22] DEBUG[2000] devicestate.c: No provider found, checking channel drivers for Local - 58600051@default
[Feb 21 20:46:22] DEBUG[12815][C-00000052] channel.c: Soft-Hanging up channel 'Local/58600051@default-0000001e;1'
[Feb 21 20:46:22] DEBUG[2000] chan_local.c: Checking if extension 58600051@default exists (devicestate)
[Feb 21 20:46:22] DEBUG[2214] manager.c: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: Local/58600051@default-0000001e;1
Uniqueid: 1582339571.164
Cause: 16


[Feb 21 20:46:22] DEBUG[2000] devicestate.c: Changing state for Local/58600051@default - state 1 (Not in use)
[Feb 21 20:46:22] DEBUG[12815][C-00000052] pbx.c: Launching 'AGI'
[Feb 21 20:46:22] DEBUG[2000] devicestate.c: device 'Local/58600051@default' state '1'
[Feb 21 20:46:22] VERBOSE[12815][C-00000052] pbx.c: [Feb 21 20:46:22]     -- Executing [h@default:1] AGI("Local/58600051@default-0000001e;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 21 20:46:22] DEBUG[12815][C-00000052] res_agi.c: Hungup channel detected, running agi in dead mode.
[Feb 21 20:46:22] DEBUG[12815][C-00000052] res_agi.c: Wow, connected!
[Feb 21 20:46:22] VERBOSE[12815][C-00000052] res_agi.c: [Feb 21 20:46:22]     -- <Local/58600051@default-0000001e;1>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 21 20:46:22] DEBUG[12815][C-00000052] channel.c: Hanging up channel 'Local/58600051@default-0000001e;1'
[Feb 21 20:46:22] DEBUG[2214] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: Local/58600051@default-0000001e;1
Uniqueid: 1582339571.164
CallerIDNum: <unknown>
CallerIDName: 20200221-204610_80XXXXXXXX
ConnectedLineNum: <unknown>
ConnectedLineName: 20200221-204610_80XXXXXXXX
AccountCode:
Cause: 0
Cause-txt: Unknown


[williamconley]

Using the loopback method for canadian calls to set the callerid name? is loopback running? is there a channel limit? is this carrier different from your autodial carrier (ie: is manual dial failing because it's going through a different carrier than other calls)?

[Two8nine]

Yes to set the callerid name (all of our clients require us to do so.)

It is running as far as I can tell, the calls that work display the set name/number ok.

Not 100% sure on what is meant by channel limit. Client/campaign specific, or just the number of sip channels we have?

We have 46 total channels, I've tried dedicating a specific number of channels to the campaigns of the given client in the server config menu, but the issue remains. I've also done lots of test calls with no one else in the building, and the issue remains, so doesn't seem to be a resource usage issue.

Carrier is the same for all calls, and this client is dialed via the same method as all others.

[williamconley]

What is different about this client then?

CallerID? If so .. change the callerID on some test calls. It's possible they have pissed off someone and their CID is blocked. It happens.

If that's not it, find EVERY tiny difference between how these failing calls execute and how the succeeding calls execute. Use SIP debug if necessary. IAX2 debug as well for those portions of the calls. Dialplan debug, too ... Obviously there's a difference if other Vicidial calls through the same carrier succeed where these fail. You just have to find out which one makes the call die.

Happy Hunting!

[Two8nine]

Ok, appreciated. I'll play around see if I can get it to work.

[Two8nine]

Ok, hoping I'm getting somewhere.

One thing I notice is that if I dial test calls with this client to local numbers, the success rate is 100%. The only difference between these and live calls is location. (We are in Manitoba Can, all failing calls are in Ontario.)

Can location play a factor in this? (Or as you suggested, does this point more towards a blocking issue?)

For testing I removed the loopback-no-log and altered the dial plan to call the failing numbers directly, but no difference was observed.

I also tried changing the CID name, but no effect.

For reference, this is the dial plan for the failing client as it is now:

Code: Select all

exten => _7NXXNXXXXXX,1, AGI(agi://127.0.0.1:4577/call_log)
exten => _7NXXNXXXXXX,n, Dial(${TRUNKloop}/886${EXTEN:1},55,o)
exten => _7NXXNXXXXXX,n, Hangup()

exten => _71NXXNXXXXXX,1, AGI(agi://127.0.0.1:4577/call_log)
exten => _71NXXNXXXXXX,n, Dial(${TRUNKloop}/886${EXTEN:1},55,o)
exten => _71NXXNXXXXXX,n, Hangup()

exten => _886NXXNXXXXXX,1,Goto(loopback-no-log,7${EXTEN:3},1)
exten => _886NXXNXXXXXX,n,Hangup()

exten => _8861NXXNXXXXXX,1,Goto(loopback-no-log,7${EXTEN:3},1)
exten => _8861NXXNXXXXXX,n,Hangup()


And here is the entry for loopback:

Code: Select all

;CLIENT Local Calling
exten => _7NXXNXXXXXX,1,Set(CALLERID(name)=CLIENT-NAME)
exten => _7NXXNXXXXXX,n,AGI(agi-CANADA_PRI_CIDname.agi)
exten => _7NXXNXXXXXX,n,Dial(${BELLSIP}/${EXTEN:1},,To)
exten => _7NXXNXXXXXX,n,Hangup()

;CLIENT LD Calling
exten => _71NXXNXXXXXX,1,Set(CALLERID(name)=CLIENT-NAME)
exten => _71NXXNXXXXXX,n,AGI(agi-CANADA_PRI_CIDname.agi)
exten => _71NXXNXXXXXX,n,Dial(${BELLSIP}/${EXTEN:1},,To)
exten => _71NXXNXXXXXX,n,Hangup()


The only thing I've done that appears to help is changing the campaign-callerID. With a different number in this field the success rate went from 10% to ~75%. Still not ideal but much better. I'm unsure if I'm jumping to conclusions though, as the fact that some succeed and some fail either way (including the same numbers on repeat attempts) seems strange to me.

[williamconley]

Change the caller ID back and forth a few times and verify your results solidly. If the Caller ID change is, in fact, a provable factor in success, then the fact that some calls are still being blocked is not really surprising. Does that province have a small number of Telcos? Are the failing calls traceable to a single or group of Telcos? Or are the successes traceable to a single or group of telcos?

Try another Caller ID. Perhaps one that's never been used before. Caller ID name and number both.

Are the failing calls all to a single province? Do other clients call the same province with measurably better results? Or was this the only client calling that province?

[Two8nine]

Still testing, but believe I've tracked down the problem. All calls for this client are controlled by the client (large telco) a short while ago they implemented Canada's new anti-spam regulations. They tell me that it has about a 90% success rate, and using custom callerid's, voip systems, and custom names are all factors in flagging a call as spam.

Trouble is they still require us to do all of those thing.

Working with them to find a solution.