Hello all,
Weird trouble here: we have 60-some happy subscribers on a FreePBX box, each with its own phone number, with no problem at all, except for one (and only one) subscriber who has this problem:
his outgoing calls are ok, but when someone dials his phone number (be it from our network or from any other place in the world), the caller ears the standard message signalling he has entered the echo test mode and must dial “hash” to exit that mode.
Most callers don’t understand what’s going on, then give up and hang up without dialling “hash”. Very few dial “hash” one or more times, then those few get our customer’s phone ringing and are then able to reach our customer.
I went through all the docs, wikis and discussions I found on the web, without finding any data on how to solve that problem.
I tried many things on our FreePBX box and found out the problem seems somehow linked with the customer’s extension (or phone number), not his inbound route (changing the latter has no effect on the problem).
Creating a new extension with another phone number would solve the problem (I tried it and it works), but this customer wants to keep his current phone number and when I tried deleting his extension then creating a new one with his current phone number, the new extension presented the same problem as the previous one…
Anyone knows what could cause such a problem and/or how to solve it ?
I’m appending a silghtly reformatted asterisk log of such a call, where the caller dialled “hash” twice after a few seconds and thus got our customer’s phone ringing, then got no answer and hung up. Phone numbers IP addresses and extension numbers have been anonymized. Furthermore this post was rejected with "new users can
The distro version is FreePBX 2.10.1.16
Thanks,
Norman.
[email protected]
Welcome to The FreePBX Distro
======================================
– Accepting AUTHENTICATED call from www . xxx . yyy . zzz :
> requested format = ulaw,
> requested prefs = (ulaw÷g729),
> actual format = ulaw,
> host prefs = (gsm÷ulaw÷g729),
> priority = mine
– Executing [1112223333©from-trunk-iax2-voipms:1]
– Set(“IAX2÷provider-88888”, “GROUP()=OUT_3”)
– Executing [1112223333©from-trunk-iax2-voipms:2]
– Goto(“IAX2÷provider-88888”, “from-trunk,1112223333,1”)
– Goto (from-trunk,1112223333,1)
– Executing [1112223333©from-trunk:1]
Set(“IAX2÷provider-88888”, “__FROM_DID=1112223333”)
– Executing [1112223333©from-trunk:2]
Set(“IAX2÷provider-88888”, “CHANNEL(language)=fr”)
– Executing [1112223333©from-trunk:3]
Gosub(“IAX2÷provider-88888”, “app-blacklist-check,s,1()”)
– Executing [s©app-blacklist-check:1]
GotoIf(“IAX2÷provider-88888”, “0?blacklisted”)
– Executing [s©app-blacklist-check:2]
Set(“IAX2÷provider-88888”, “CALLED_BLACKLIST=1”)
– Executing [s©app-blacklist-check:3]
Return(“IAX2÷provider-88888”, “”)
– Executing [1112223333©from-trunk:4]
Set(“IAX2÷provider-88888”, “CDR(did)=1112223333”)
– Executing [1112223333©from-trunk:5]
ExecIf(“IAX2÷provider-88888”, “0?Set(CALLERID(name)=4445556666)”)
– Executing [1112223333©from-trunk:6]
Set(“IAX2÷provider-88888”, “CHANNEL(musicclass)=none”)
– Executing [1112223333©from-trunk:7]
Set(“IAX2÷provider-88888”, “__MOHCLASS=none”)
– Executing [1112223333©from-trunk:8]
Set(“IAX2÷provider-88888”, “__CALLINGPRES_SV=allowed_not_screened”)
– Executing [1112223333©from-trunk:9]
Set(“IAX2÷provider-88888”, “CALLERPRES()=allowed_not_screened”)
– Executing [1112223333©from-trunk:10]
Goto(“IAX2÷provider-88888”, “from-did-direct,77777,1”)
– Goto (from-did-direct,00360,1)
– Executing [77777©from-did-direct:1]
Set(“IAX2÷provider-88888”, “__RINGTIMER=25”)
– Executing [77777©from-did-direct:2]
Macro(“IAX2÷provider-88888”, “exten-vm,77777,77777,0,0,0”)
– Executing [s©macro-exten-vm:1]
Macro(“IAX2÷provider-88888”, “user-callerid,”)
– Executing [s©macro-user-callerid:1]
Set(“IAX2÷provider-88888”, “AMPUSER=4445556666”)
– Executing [s©macro-user-callerid:2]
GotoIf(“IAX2÷provider-88888”, “0?report”)
– Executing [s©macro-user-callerid:3]
ExecIf(“IAX2÷provider-88888”, “1?Set(REALCALLERIDNUM=4445556666)”)
– Executing [s©macro-user-callerid:4]
Set(“IAX2÷provider-88888”, “AMPUSER=”)
– Executing [s©macro-user-callerid:5]
Set(“IAX2÷provider-88888”, “AMPUSERCIDNAME=”)
– Executing [s©macro-user-callerid:6]
GotoIf(“IAX2÷provider-88888”, “1?report”)
– Goto (macro-user-callerid,s,13)
– Executing [s©macro-user-callerid:13]
GotoIf(“IAX2÷provider-88888”, “0?continue”)
– Executing [s©macro-user-callerid:14]
Set(“IAX2÷provider-88888”, “__TTL=64”)
– Executing [s©macro-user-callerid:15]
GotoIf(“IAX2÷provider-88888”, “1?continue”)
– Goto (macro-user-callerid,s,26)
– Executing [s©macro-user-callerid:26]
Set(“IAX2÷provider-88888”, “CALLERID(number)=4445556666”)
– Executing [s©macro-user-callerid:27]
Set(“IAX2÷provider-88888”, “CALLERID(name)=4445556666”)
– Executing [s©macro-user-callerid:28]
Set(“IAX2÷provider-88888”, “CHANNEL(language)=fr”)
– Executing [s©macro-exten-vm:2]
Set(“IAX2÷provider-88888”, “RingGroupMethod=none”)
– Executing [s©macro-exten-vm:3]
Set(“IAX2÷provider-88888”, “__EXTTOCALL=77777”)
– Executing [s©macro-exten-vm:4]
Set(“IAX2÷provider-88888”, “__PICKUPMARK=77777”)
– Executing [s©macro-exten-vm:5]
Set(“IAX2÷provider-88888”, “RT=25”)
– Executing [s©macro-exten-vm:6]
Gosub(“IAX2÷provider-88888”, “sub-record-check,s,1(exten,77777,)”)
– Executing [s©sub-record-check:1]
GotoIf(“IAX2÷provider-88888”, “1?check”)
– Goto (sub-record-check,s,6)
– Executing [s©sub-record-check:6]
Set(“IAX2÷provider-88888”, “__MON_FMT=wav”)
– Executing [s©sub-record-check:7]
GotoIf(“IAX2÷provider-88888”, “1?next”)
– Goto (sub-record-check,s,10)
– Executing [s©sub-record-check:10]
ExecIf(“IAX2÷provider-88888”, “0?Return()”)
– Executing [s©sub-record-check:11]
GotoIf(“IAX2÷provider-88888”, “0?exten,1”)
– Executing [s©sub-record-check:12]
Set(“IAX2÷provider-88888”, “__REC_STATUS=INITIALIZED”)
– Executing [s©sub-record-check:13]
ExecIf(“IAX2÷provider-88888”, “0?Set(__REC_POLICY_MODE=)”)
– Executing [s©sub-record-check:14]
Set(“IAX2÷provider-88888”, “NOW=1405794970”)
– Executing [s©sub-record-check:15]
Set(“IAX2÷provider-88888”, “__DAY=19”)
– Executing [s©sub-record-check:16]
Set(“IAX2÷provider-88888”, “__MONTH=07”)
– Executing [s©sub-record-check:17]
Set(“IAX2÷provider-88888”, “__YEAR=2014”)
– Executing [s©sub-record-check:18]
Set(“IAX2÷provider-88888”, “__TIMESTR=20140719-143610”)
– Executing [s©sub-record-check:19]
Set(“IAX2÷provider-88888”, “__FROMEXTEN=4445556666”)
– Executing [s©sub-record-check:20]
Set(“IAX2÷provider-88888”, “__CALLFILENAME=
exten-77777-4445556666-20140719-143610-1405794970.4391”)
– Executing [s©sub-record-check:21]
Goto(“IAX2÷provider-88888”, “exten,1”)
– Goto (sub-record-check,exten,1)
– Executing [exten©sub-record-check:1]
GotoIf(“IAX2÷provider-88888”, “0?callee”)
– Executing [exten©sub-record-check:2]
Set(“IAX2÷provider-88888”, “__REC_POLICY_MODE=dontcare”)
– Executing [exten©sub-record-check:3]
GotoIf(“IAX2÷provider-88888”, “1?caller”)
– Goto (sub-record-check,exten,10)
– Executing [exten©sub-record-check:10]
Set(“IAX2÷provider-88888”, “__REC_POLICY_MODE=”)
– Executing [exten©sub-record-check:11]
GosubIf(“IAX2÷provider-88888”, “0?record,1(exten,77777,
4445556666)”)
– Executing [exten©sub-record-check:12]
Return(“IAX2÷provider-88888”, “”)
– Executing [s©macro-exten-vm:7]
Macro(“IAX2÷provider-88888”, “dial-one,25,tr,77777”)
– Executing [s©macro-dial-one:1]
Set(“IAX2÷provider-88888”, “DEXTEN=77777”)
– Executing [s©macro-dial-one:2]
Set(“IAX2÷provider-88888”, “DIALSTATUS_CW=”)
– Executing [s©macro-dial-one:3]
GosubIf(“IAX2÷provider-88888”, “0?screen,1()”)
– Executing [s©macro-dial-one:4]
GosubIf(“IAX2÷provider-88888”, “0?cf,1()”)
– Executing [s©macro-dial-one:5]
GotoIf(“IAX2÷provider-88888”, “1?skip1”)
– Goto (macro-dial-one,s,8)
– Executing [s©macro-dial-one:8]
GotoIf(“IAX2÷provider-88888”, “0?nodial”)
– Executing [s©macro-dial-one:9]
GotoIf(“IAX2÷provider-88888”, “0?continue”)
– Executing [s©macro-dial-one:10]
Set(“IAX2÷provider-88888”, “EXTHASCW=ENABLED”)
– Executing [s©macro-dial-one:11]
GotoIf(“IAX2÷provider-88888”, “0?next1:cwinusebusy”)
– Goto (macro-dial-one,s,23)
– Executing [s©macro-dial-one:23]
GotoIf(“IAX2÷provider-88888”, “1?next3:continue”)
– Goto (macro-dial-one,s,24)
– Executing [s©macro-dial-one:24]
ExecIf(“IAX2÷provider-88888”, “0?Set(DIALSTATUS_CW=BUSY)”)
– Executing [s©macro-dial-one:25]
GotoIf(“IAX2÷provider-88888”, “0?nodial”)
– Executing [s©macro-dial-one:26]
GosubIf(“IAX2÷provider-88888”, “1?dstring,1():dlocal,1()”)
– Executing [dstring©macro-dial-one:1]
Set(“IAX2÷provider-88888”, “DSTRING=”)
– Executing [dstring©macro-dial-one:2]
Set(“IAX2÷provider-88888”, “DEVICES=77777”)
– Executing [dstring©macro-dial-one:3]
ExecIf(“IAX2÷provider-88888”, “0?Return()”)
– Executing [dstring©macro-dial-one:4]
ExecIf(“IAX2÷provider-88888”, “0?Set(DEVICES=7777)”)
– Executing [dstring©macro-dial-one:5]
Set(“IAX2÷provider-88888”, “LOOPCNT=1”)
– Executing [dstring©macro-dial-one:6]
Set(“IAX2÷provider-88888”, “ITER=1”)
– Executing [dstring©macro-dial-one:7]
Set(“IAX2÷provider-88888”, “THISDIAL=SIP÷77777”)
– Executing [dstring©macro-dial-one:8]
GosubIf(“IAX2÷provider-88888”, “1?zap2dahdi,1()”)
– Executing [zap2dahdi©macro-dial-one:1]
ExecIf(“IAX2÷provider-88888”, “0?Return()”)
– Executing [zap2dahdi©macro-dial-one:2]
Set(“IAX2÷provider-88888”, “NEWDIAL=”)
– Executing [zap2dahdi©macro-dial-one:3]
Set(“IAX2÷provider-88888”, “LOOPCNT2=1”)
– Executing [zap2dahdi©macro-dial-one:4]
Set(“IAX2÷provider-88888”, “ITER2=1”)
– Executing [zap2dahdi©macro-dial-one:5]
Set(“IAX2÷provider-88888”, “THISPART2=SIP÷77777”)
– Executing [zap2dahdi©macro-dial-one:6]
ExecIf(“IAX2÷provider-88888”, “0?Set(THISPART2=DAHDI÷77777)”)
– Executing [zap2dahdi©macro-dial-one:7]
Set(“IAX2÷provider-88888”, “NEWDIAL=SIP÷77777&”)
– Executing [zap2dahdi©macro-dial-one:8]
Set(“IAX2÷provider-88888”, “ITER2=2”)
– Executing [zap2dahdi©macro-dial-one:9]
GotoIf(“IAX2÷provider-88888”, “0?begin2”)
– Executing [zap2dahdi©macro-dial-one:10]
Set(“IAX2÷provider-88888”, “THISDIAL=SIP÷77777”)
– Executing [zap2dahdi©macro-dial-one:11]
Return(“IAX2÷provider-88888”, “”)
– Executing [dstring©macro-dial-one:9]
Set(“IAX2÷provider-88888”, “DSTRING=SIP÷77777&”)
– Executing [dstring©macro-dial-one:10]
Set(“IAX2÷provider-88888”, “ITER=2”)
– Executing [dstring©macro-dial-one:11]
GotoIf(“IAX2÷provider-88888”, “0?begin”)
– Executing [dstring©macro-dial-one:12]
Set(“IAX2÷provider-88888”, “DSTRING=SIP÷77777”)
– Executing [dstring©macro-dial-one:13]
Return(“IAX2÷provider-88888”, “”)
– Executing [s©macro-dial-one:27]
GotoIf(“IAX2÷provider-88888”, “0?nodial”)
– Executing [s©macro-dial-one:28]
GotoIf(“IAX2÷provider-88888”, “0?skiptrace”)
– Executing [s©macro-dial-one:29]
GosubIf(“IAX2÷provider-88888”, “1?ctset,1():ctclear,1()”)
– Executing [ctset©macro-dial-one:1]
Set(“IAX2÷provider-88888”, “DB(CALLTRACE÷77777)=4445556666”)
– Executing [ctset©macro-dial-one:2]
Return(“IAX2÷provider-88888”, “”)
– Executing [s©macro-dial-one:30]
Set(“IAX2÷provider-88888”, “D_OPTIONS=tr”)
– Executing [s©macro-dial-one:31]
ExecIf(“IAX2÷provider-88888”, “0?SIPAddHeader(Alert-Info: )”)
– Executing [s©macro-dial-one:32]
ExecIf(“IAX2÷provider-88888”, “0?SIPAddHeader()”)
– Executing [s©macro-dial-one:33]
ExecIf(“IAX2÷provider-88888”, “1?Set(CHANNEL(musicclass)=none)”)
– Executing [s©macro-dial-one:34]
GosubIf(“IAX2÷provider-88888”, “0?qwait,1()”)
– Executing [s©macro-dial-one:35]
Set(“IAX2÷provider-88888”, “__CWIGNORE=”)
– Executing [s©macro-dial-one:36]
Set(“IAX2÷provider-88888”, “__KEEPCID=TRUE”)
– Executing [s©macro-dial-one:37]
GotoIf(“IAX2÷provider-88888”, “0?usegoto,1”)
– Executing [s©macro-dial-one:38]
GotoIf(“IAX2÷provider-88888”, “1?godial”)
– Goto (macro-dial-one,s,42)
– Executing [s©macro-dial-one:42]
Dial(“IAX2÷provider-88888”, “SIP÷77777,25,tr”)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP÷77777
– SIP÷77777-00000943 is ringing
– Executing [s©macro-dial-one:43]
ExecIf(“IAX2÷provider-88888”, “0?Set(DIALSTATUS=)”)
– Executing [s©macro-dial-one:44]
GosubIf(“IAX2÷provider-88888”, “0?s-NOANSWER,1()”)
– Executing [s©macro-dial-one:45]
MacroExit(“IAX2÷provider-88888”, “”)
– Executing [s©macro-exten-vm:8]
Set(“IAX2÷provider-88888”, “SV_DIALSTATUS=NOANSWER”)
– Executing [s©macro-exten-vm:9]
GosubIf(“IAX2÷provider-88888”, “0?docfu,1()”)
– Executing [s©macro-exten-vm:10]
GosubIf(“IAX2÷provider-88888”, “0?docfb,1()”)
– Executing [s©macro-exten-vm:11]
Set(“IAX2÷provider-88888”, “DIALSTATUS=NOANSWER”)
– Executing [s©macro-exten-vm:12]
ExecIf(“IAX2÷provider-88888”, “0?MacroExit()”)
– Executing [s©macro-exten-vm:13]
GotoIf(“IAX2÷provider-88888”, “0?s-NOANSWER,1”)
– Executing [s©macro-exten-vm:14]
Macro(“IAX2÷provider-88888”, “vm,77777,NOANSWER,”)
– Executing [s©macro-vm:1]
Macro(“IAX2÷provider-88888”, “user-callerid,SKIPTTL”)
– Executing [s©macro-user-callerid:1]
Set(“IAX2÷provider-88888”, “AMPUSER=4445556666”)
– Executing [s©macro-user-callerid:2]
GotoIf(“IAX2÷provider-88888”, “0?report”)
– Executing [s©macro-user-callerid:3]
ExecIf(“IAX2÷provider-88888”, “0?Set(REALCALLERIDNUM=4445556666)”)
– Executing [s©macro-user-callerid:4]
Set(“IAX2÷provider-88888”, “AMPUSER=”)
– Executing [s©macro-user-callerid:5]
Set(“IAX2÷provider-88888”, “AMPUSERCIDNAME=”)
– Executing [s©macro-user-callerid:6]
GotoIf(“IAX2÷provider-88888”, “1?report”)
– Goto (macro-user-callerid,s,13)
– Executing [s©macro-user-callerid:13]
GotoIf(“IAX2÷provider-88888”, “1?continue”)
– Goto (macro-user-callerid,s,26)
– Executing [s©macro-user-callerid:26]
Set(“IAX2÷provider-88888”, “CALLERID(number)=4445556666”)
– Executing [s©macro-user-callerid:27]
Set(“IAX2÷provider-88888”, “CALLERID(name)=4445556666”)
– Executing [s©macro-user-callerid:28]
Set(“IAX2÷provider-88888”, “CHANNEL(language)=fr”)
– Executing [s©macro-vm:2]
Set(“IAX2÷provider-88888”, “VMGAIN=”"")
– Executing [s©macro-vm:3]
Macro(“IAX2÷provider-88888”, “blkvm-check,”)
– Executing [s©macro-blkvm-check:1]
Set(“IAX2÷provider-88888”, “GOSUB_RETVAL=”)
– Executing [s©macro-blkvm-check:2]
ExecIf(“IAX2÷provider-88888”, “0?Set(GOSUB_RETVAL=TRUE)”)
– Executing [s©macro-blkvm-check:3]
MacroExit(“IAX2÷provider-88888”, “”)
– Executing [s©macro-vm:4]
GotoIf(“IAX2÷provider-88888”, “1?vmx,1”)
– Goto (macro-vm,vmx,1)
– Executing [vmx©macro-vm:1]
Set(“IAX2÷provider-88888”, “MEXTEN=77777”)
– Executing [vmx©macro-vm:2]
Set(“IAX2÷provider-88888”, “MMODE=NOANSWER”)
– Executing [vmx©macro-vm:3]
Set(“IAX2÷provider-88888”, “RETVM=”)
– Executing [vmx©macro-vm:4]
Set(“IAX2÷provider-88888”, “MODE=unavail”)
– Executing [vmx©macro-vm:5]
GotoIf(“IAX2÷provider-88888”, “1?chknomsg”)
– Goto (macro-vm,vmx,8)
– Executing [vmx©macro-vm:8]
GotoIf(“IAX2÷provider-88888”, “0?s-NOANSWER,1”)
– Executing [vmx©macro-vm:9]
GotoIf(“IAX2÷provider-88888”, “1?notdirect”)
– Goto (macro-vm,vmx,11)
– Executing [vmx©macro-vm:11]
NoOp(“IAX2÷provider-88888”, “Checking if ext 77777 is enabled: “)
– Executing [vmx©macro-vm:12]
GotoIf(“IAX2÷provider-88888”, “1?s-NOANSWER,1”)
– Goto (macro-vm,s-NOANSWER,1)
– Executing [s-NOANSWER©macro-vm:1]
Macro(“IAX2÷provider-88888”, “get-vmcontext,77777”)
– Executing [s©macro-get-vmcontext:1]
Set(“IAX2÷provider-88888”, “VMCONTEXT=default”)
– Executing [s©macro-get-vmcontext:2]
GotoIf(“IAX2÷provider-88888”, “0?200:300”)
– Goto (macro-get-vmcontext,s,300)
– Executing [s©macro-get-vmcontext:300]
NoOp(“IAX2÷provider-88888”, “”)
– Executing [s-NOANSWER©macro-vm:2]
VoiceMail(“IAX2÷provider-88888”, “77777©default,u”””)
– <IAX2÷provider-88888> Playing ‘vm-theperson.ulaw’ (language ‘fr’)
== Spawn extension (macro-vm, s-NOANSWER, 2)
exited non-zero on ‘IAX2÷provider-88888’ in macro ‘vm’
== Spawn extension (macro-exten-vm, s, 14)
exited non-zero on ‘IAX2÷provider-88888’ in macro ‘exten-vm’
== Spawn extension (from-did-direct, 77777, 2)
exited non-zero on ‘IAX2÷provider-88888’
– Executing [h©from-did-direct:1]
Macro(“IAX2÷provider-88888”, “hangupcall,”)
– Executing [s©macro-hangupcall:1]
GotoIf(“IAX2÷provider-88888”, “1?theend”)
– Goto (macro-hangupcall,s,3)
– Executing [s©macro-hangupcall:3]
ExecIf(“IAX2÷provider-88888”, “0?Set(CDR(recordingfile)=)”)
– Executing [s©macro-hangupcall:4]
Hangup(“IAX2÷provider-88888”, “”)
== Spawn extension (macro-hangupcall, s, 4)
exited non-zero on ‘IAX2÷provider-88888’ in macro ‘hangupcall’
== Spawn extension (from-did-direct, h, 1)
exited non-zero on ‘IAX2÷provider-88888’
– Hungup ‘IAX2÷provider-88888’