I am pulling my hair out here hope there is some help out there…
been running a trixbox for several months working great, about a week ago it started dropping calls if they route through the ivr, thing is the calls are routed properly, the extension rings, but even if the extension is answered the call will be dropped after about 20 seconds…
this happens if the inbound route goes through IVR, DISA, VMBLASTER pretty much if it goes anywhere other than a direct DID or CID to extension mapping.
below is the CLI readings with PHP debug on and level 5 verbose.
-- Executing Set("SIP/209.247.17.175-b7b5b7a0", "__FROM_DID=18652719427") in
new stack
– Executing Gosub(“SIP/209.247.17.175-b7b5b7a0”, “app-blacklist-check|s|1”)
in new stack
– Executing LookupBlacklist(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “0?blacklisted”) in new s
tack
– Executing Return(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1 ?cidok”) in new stack
– Goto (from-pstn,18652719427,5)
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, "CallerID is “Anonymous” ") in new stack
– Executing Ringing(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
– Executing Goto(“SIP/209.247.17.175-b7b5b7a0”, “ivr-2|s|1”) in new stack
– Goto (ivr-2,s,1)
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “LOOPCOUNT=0”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “__DIR-CONTEXT=default”) in
new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “_IVR_CONTEXT_ivr-2=”) in ne
w stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “_IVR_CONTEXT=ivr-2”) in new
stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “0?begin”) in new stack
– Executing Answer(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
– Executing Wait(“SIP/209.247.17.175-b7b5b7a0”, “1”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “TIMEOUT(digit)=3”) in new s
tack
– Digit timeout set to 3
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “TIMEOUT(response)=100”) in
new stack
– Response timeout set to 100
– Executing BackGround(“SIP/209.247.17.175-b7b5b7a0”, “enter-ext-of-person”
) in new stack
– Playing ‘enter-ext-of-person’ (language ‘en’)
– Executing WaitExten(“SIP/209.247.17.175-b7b5b7a0”, “|”) in new stack
== CDR updated on SIP/209.247.17.175-b7b5b7a0
– Executing ExecIf(“SIP/209.247.17.175-b7b5b7a0”, “0|dbDel|”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “__NODEST=”) in new stack
– Executing Goto(“SIP/209.247.17.175-b7b5b7a0”, “from-did-direct|1601|1”) i
n new stack
– Goto (from-did-direct,1601,1)
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “__RINGTIMER=35”) in new sta
ck
– Executing Macro(“SIP/209.247.17.175-b7b5b7a0”, “exten-vm|1601|1601”) in n
ew stack
– Executing Macro(“SIP/209.247.17.175-b7b5b7a0”, “user-callerid”) in new st
ack
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, “user-callerid: Anonymous r
estricted”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “AMPUSER=restricted”) in new
stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “0?report”) in new stack
– Executing ExecIf(“SIP/209.247.17.175-b7b5b7a0”, “1|Set|REALCALLERIDNUM=re
stricted”) in new stack
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, “REALCALLERIDNUM is restric
ted”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “AMPUSER=”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “AMPUSERCIDNAME=”) in new st
ack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, “TTL: ARG1: 1601”) in new
stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “0?continue”) in new stac
k
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “__TTL=64”) in new stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?continue”) in new stac
k
– Goto (macro-user-callerid,s,23)
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, “Using CallerID “Anonymous”
”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “FROMCONTEXT=exten-vm”) in n
ew stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “VMBOX=1601”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “EXTTOCALL=1601”) in new sta
ck
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “CFUEXT=”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “CFBEXT=”) in new stack
– Executing Set(“SIP/209.247.17.175-b7b5b7a0”, “RT=35”) in new stack
– Executing Macro(“SIP/209.247.17.175-b7b5b7a0”, “record-enable|1601|IN”) i
n new stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing AGI(“SIP/209.247.17.175-b7b5b7a0”, “recordingcheck|20080606-175
139|1212763889.30”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
AGI Tx >> agi_request: recordingcheck
AGI Tx >> agi_channel: SIP/209.247.17.175-b7b5b7a0
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1212763889.30
AGI Tx >> agi_callerid: restricted
AGI Tx >> agi_calleridname: Anonymous
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 18652719427
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-record-enable
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 4
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << GET VARIABLE ARG2
AGI Tx >> 200 result=1 (IN)
AGI Rx << GET VARIABLE ARG1
AGI Tx >> 200 result=1 (1601)
AGI Rx << DATABASE GET “AMPUSER” "1601/recording"
AGI Tx >> 200 result=1 (out=Never|in=Never)
AGI Rx << VERBOSE “Inbound recording not enabled” 1
recordingcheck|20080606-175139|1212763889.30: Inbound recording not enabled
AGI Tx >> 200 result=1
– AGI Script recordingcheck completed, returning 0
– Executing NoOp(“SIP/209.247.17.175-b7b5b7a0”, “No recording needed”) in e
w stack
– Executing Macro(“SIP/209.247.17.175-b7b5b7a0”, “dial|35|tr|1601”) in news
tack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing AGI(“SIP/209.247.17.175-b7b5b7a0”, “dialparties.agi”) in new sa
ck
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
AGI Tx >> agi_request: dialparties.agi
AGI Tx >> agi_channel: SIP/209.247.17.175-b7b5b7a0
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1212763889.30
AGI Tx >> agi_callerid: restricted
AGI Tx >> agi_calleridname: Anonymous
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 18652719427
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-dial
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << VERBOSE “Starting New Dialparties.agi” 1
dialparties.agi: Starting New Dialparties.agi
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE AMPMGRUSER
AGI Tx >> 200 result=1 (admin)
AGI Rx << GET VARIABLE AMPMGRPASS
AGI Tx >> 200 result=1 (fugem)
AGI Rx << GET VARIABLE CWINUSEBUSY
AGI Tx >> 200 result=1 (true)
AGI Rx << GET VARIABLE ASTVERSION
AGI Tx >> 200 result=1 (1.2.26.1)
AGI Rx << GET VARIABLE CWIGNORE
AGI Tx >> 200 result=0
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_additional.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘admin’ logged on from 127.0.0.1
AGI Rx << GET VARIABLE priority
AGI Tx >> 200 result=0
AGI Rx << VERBOSE “Caller ID name is ‘Anonymous’ number is ‘restricted’” 1
dialparties.agi: Caller ID name is ‘Anonymous’ number is 'restricted’
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE __KEEPCID "TRUE"
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE DIALSTATUS_CW ""
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE ARG1
AGI Tx >> 200 result=1 (35)
AGI Rx << GET VARIABLE ARG2
AGI Tx >> 200 result=1 (tr)
AGI Rx << GET VARIABLE RingGroupMethod
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE ALERT_INFO
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE SIPADDHEADER
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE PR_DIALSTATUS
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE FMGRP
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE NODEST
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE RINGGROUP_INDEX
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE USE_CONFIRMATION
AGI Tx >> 200 result=0
AGI Rx << VERBOSE “USE_CONFIRMATION: ‘FALSE’” 5
dialparties.agi: USE_CONFIRMATION: 'FALSE’
AGI Tx >> 200 result=1
AGI Rx << VERBOSE “RINGGROUP_INDEX: ‘’” 5
dialparties.agi: RINGGROUP_INDEX: ''
AGI Tx >> 200 result=1
AGI Rx << VERBOSE “Methodology of ring is ‘none’” 1
dialparties.agi: Methodology of ring is 'none’
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE ARG3
AGI Tx >> 200 result=1 (1601)
AGI Rx << VERBOSE “Added extension 1601 to extension map” 3
– dialparties.agi: Added extension 1601 to extension map
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE ARG4
AGI Tx >> 200 result=0
AGI Rx << DATABASE GET “CF” "1601"
AGI Tx >> 200 result=0
AGI Rx << VERBOSE “Extension 1601 cf is disabled” 3
– dialparties.agi: Extension 1601 cf is disabled
AGI Tx >> 200 result=1
AGI Rx << DATABASE GET “DND” "1601"
AGI Tx >> 200 result=0
AGI Rx << VERBOSE “Extension 1601 do not disturb is disabled” 3
– dialparties.agi: Extension 1601 do not disturb is disabled
AGI Tx >> 200 result=1
AGI Rx << DATABASE GET “CW” "1601"
AGI Tx >> 200 result=1 (ENABLED)
AGI Rx << DATABASE GET “CFB” "1601"
AGI Tx >> 200 result=0
AGI Rx << DATABASE GET “CFU” "1601"
AGI Tx >> 200 result=0
AGI Rx << VERBOSE “extnum 1601 has: cw: 1; hascfb: 0 [] hascfu: 0 []” 4
> dialparties.agi: extnum 1601 has: cw: 1; hascfb: 0 [] hascfu: 0 []
AGI Tx >> 200 result=1
AGI Rx << VERBOSE “ExtensionState: 0” 4
> dialparties.agi: ExtensionState: 0
AGI Tx >> 200 result=1
AGI Rx << DATABASE GET “AMPUSER” "1601/device"
AGI Tx >> 200 result=1 (1601)
AGI Rx << DATABASE GET “DEVICE” "1601/dial"
AGI Tx >> 200 result=1 (SIP/1601)
AGI Rx << DATABASE DEL “CALLTRACE” "1601"
AGI Tx >> 200 result=1
AGI Rx << VERBOSE “DbDel CALLTRACE/1601 - Caller ID is not defined” 3
– dialparties.agi: DbDel CALLTRACE/1601 - Caller ID is not defined
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE FILTERED_DIAL "1601"
AGI Tx >> 200 result=1
AGI Rx << VERBOSE “Filtered ARG3: 1601” 3
– dialparties.agi: Filtered ARG3: 1601
AGI Tx >> 200 result=1
AGI Rx << SET VARIABLE ds "SIP/1601|35|tr"
AGI Tx >> 200 result=1
AGI Rx << SET PRIORITY normdial
AGI Tx >> 200 result=0
== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing Dial(“SIP/209.247.17.175-b7b5b7a0”, “SIP/1601|35|tr”) in new st
ack
– Called 1601
– SIP/1601-09958b10 is ringing
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/209.247.17.175-b
7b5b7a0’ in macro ‘dial’
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/209.247.17.175-b
7b5b7a0’ in macro ‘exten-vm’
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘SIP/209.247.17.175-b
7b5b7a0’
– Executing Macro(“SIP/209.247.17.175-b7b5b7a0”, “hangupcall”) in new stack
– Executing ResetCDR(“SIP/209.247.17.175-b7b5b7a0”, “w”) in new stack
– Executing NoCDR(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?skipblkvm”) in new sta
ck
– Goto (macro-hangupcall,s,9)
– Executing GotoIf(“SIP/209.247.17.175-b7b5b7a0”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing Hangup(“SIP/209.247.17.175-b7b5b7a0”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/209.247.1
7.175-b7b5b7a0’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/209.247.1
7.175-b7b5b7a0’
asterisk1*CLI>