Ticket #3310 (reopened Bugs)

Opened 2 years ago

Last modified 2 years ago

Ring strategy firstavailable does not work as expected

Reported by: stintel Assigned to: p_lindheimer
Priority: minor Milestone: 2.5
Component: Ring Groups Version: 2.5-branch
Keywords: Cc:
Confirmation: Unreviewed SVN Revision (if applicable):
Backend Engine: Asterisk 1.4.x Backend Engine Version: 1.4.22

Description (Last modified by wiseoldowl)

The description of the ring strategy "firstavailable", says that it should ring only the first available channel. If I understand it correctly, this means that if the first channel is unavailable (e.g. not logged in when running in deviceanduser mode), it should try the next channel, but this doesn't happen. When the first extension in the ringgroup is not available, the other extensions will never be called.

Configuration for the ring group, taken from extensions_additional.conf: 

exten => 8054,1,Macro(user-callerid,)
exten => 8054,n,GotoIf($["foo${BLKVM_OVERRIDE}" = "foo"]?skipdb)
exten => 8054,n,GotoIf($["${DB(${BLKVM_OVERRIDE})}" = "TRUE"]?skipov)
exten => 8054,n(skipdb),Set(__NODEST=)
exten => 8054,n,Set(__BLKVM_OVERRIDE=BLKVM/${EXTEN}/${CHANNEL})
exten => 8054,n,Set(__BLKVM_BASE=${EXTEN})
exten => 8054,n,Set(DB(${BLKVM_OVERRIDE})=TRUE)
exten => 8054,n(skipov),Set(RRNODEST=${NODEST})
exten => 8054,n(skipvmblk),Set(__NODEST=${EXTEN})
exten => 8054,n,Set(__CWIGNORE=TRUE)
exten => 8054,n,Set(_CFIGNORE=TRUE)
exten => 8054,n,Set(_FORWARD_CONTEXT=block-cf)
exten => 8054,n,Set(RecordMethod=Group)
exten => 8054,n,Macro(record-enable,1011#-1012#-1013#-1050#-1069#,${RecordMethod})
exten => 8054,n,Set(RingGroupMethod=ringall)
exten => 8054,n(DIALGRP),Macro(dial,60,${DIAL_OPTIONS},1011#-1012#-1013#-1050#-1069#)
exten => 8054,n,Set(RingGroupMethod=)
exten => 8054,n,GotoIf($["foo${RRNODEST}" != "foo"]?nodest)
exten => 8054,n,Set(__NODEST=)
exten => 8054,n,dbDel(${BLKVM_OVERRIDE})
exten => 8054,n,Goto(ext-queues,7054,1)
exten => 8054,n(nodest),Noop(SKIPPING DEST, CALL CAME FROM Q/RG: ${RRNODEST})

Configuration for the ring group, taken from mysql: 

mysql> select * from ringgroups where grpnum = 8002 \G
*************************** 1. row ***************************
        grpnum: 8002
      strategy: firstavailable
       grptime: 60
        grppre: Accounting: 
       grplist: 1014-1010
     annmsg_id: 0
      postdest: 
   description: Accounting
     alertinfo: 
remotealert_id: 0
     needsconf: 
    toolate_id: 0
       ringing: Ring
      cwignore: 
      cfignore:

Asterisk log when calling the ring group, with 1010 logged in, 1014 not logged in: 

[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:1] Macro("SIP/2011-15ac3d00", "user-callerid|") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/2011-15ac3d00", "AMPUSER=2011") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/2011-15ac3d00", "0?report") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/2011-15ac3d00", "1|Set|REALCALLERIDNUM=2011") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: ExecIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/2011-15ac3d00", "AMPUSER=1050") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/2011-15ac3d00", "AMPUSERCIDNAME=Stijn Tintel") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/2011-15ac3d00", "0?report") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/2011-15ac3d00", "AMPUSERCID=1050") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/2011-15ac3d00", "CALLERID(all)="Stijn Tintel" <1050>") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:9] Set("SIP/2011-15ac3d00", "REALCALLERIDNUM=1050") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:10] ExecIf("SIP/2011-15ac3d00", "0|Set|CHANNEL(language)=") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: ExecIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:11] GotoIf("SIP/2011-15ac3d00", "0?continue") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:12] Set("SIP/2011-15ac3d00", "__TTL=64") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:13] GotoIf("SIP/2011-15ac3d00", "1?continue") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-user-callerid,s,20)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-user-callerid:20] NoOp("SIP/2011-15ac3d00", "Using CallerID "Stijn Tintel" <1050>") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Noop
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:2] GotoIf("SIP/2011-15ac3d00", "1?skipdb") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (from-internal,8002,4)
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:4] Set("SIP/2011-15ac3d00", "__NODEST=") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:5] Set("SIP/2011-15ac3d00", "__BLKVM_OVERRIDE=BLKVM/8002/SIP/2011-15ac3d00") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:6] Set("SIP/2011-15ac3d00", "__BLKVM_BASE=8002") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:7] Set("SIP/2011-15ac3d00", "DB(BLKVM/8002/SIP/2011-15ac3d00)=TRUE") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:8] Set("SIP/2011-15ac3d00", "RRNODEST=") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:9] Set("SIP/2011-15ac3d00", "__NODEST=8002") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:10] Set("SIP/2011-15ac3d00", "RecordMethod=Group") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:11] Macro("SIP/2011-15ac3d00", "record-enable|1014#-1010#|Group") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/2011-15ac3d00", "1?check") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-record-enable,s,4)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/2011-15ac3d00", "recordingcheck|20081021-131145|1224587505.27") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   recordingcheck|20081021-131145|1224587505.27: No DB Entry AMPUSER/1014#/recording - Not Recording for 1014#, checking for others
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   recordingcheck|20081021-131145|1224587505.27: No DB Entry AMPUSER/1010#/recording - Not Recording for 1010#, checking for others
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- AGI Script recordingcheck completed, returning 0
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: AGI
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/2011-15ac3d00", "") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:12] Set("SIP/2011-15ac3d00", "RingGroupMethod=firstavailable") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:13] Macro("SIP/2011-15ac3d00", "dial|60|tr|1014#-1010#") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/2011-15ac3d00", "1?dial") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,3)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/2011-15ac3d00", "dialparties.agi") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   dialparties.agi: Starting New Dialparties.agi
[Oct 21 13:11:45] VERBOSE[5085] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Oct 21 13:11:45] VERBOSE[5085] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5085] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Oct 21 13:11:45] VERBOSE[5085] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5085] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Oct 21 13:11:45] VERBOSE[5085] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5085] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   dialparties.agi: Caller ID name is 'Stijn Tintel' number is '1050'
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   dialparties.agi: Methodology of ring is  'firstavailable'
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     --  dialparties.agi: Added extension 1014# to extension map
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     --  dialparties.agi: Added extension 1010# to extension map
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     --  dialparties.agi: Extension 1014# cf is disabled
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     --  dialparties.agi: Extension 1010# cf is disabled
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     --  dialparties.agi: Filtered ARG3: 1014-1010
[Oct 21 13:11:45] VERBOSE[5085] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- AGI Script dialparties.agi completed, returning 0
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: AGI
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:20] NoOp("SIP/2011-15ac3d00", "Returned from dialparties with hunt groups to dial ") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: NoOp
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:21] Set("SIP/2011-15ac3d00", "HuntLoop=0") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:22] GotoIf("SIP/2011-15ac3d00", "1?a30") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,26)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:26] Set("SIP/2011-15ac3d00", "HuntMember=HuntMember0") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:27] GotoIf("SIP/2011-15ac3d00", "0?a32:a35") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,31)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:31] GotoIf("SIP/2011-15ac3d00", "0?a36:a50") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,44)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:44] DBdel("SIP/2011-15ac3d00", "CALLTRACE/") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- DBdel: family=CALLTRACE, key=
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- DBdel: Error deleting key from database.
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: DBdel


[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:45] Goto("SIP/2011-15ac3d00", "s|a42") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,38)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Goto
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:38] Dial("SIP/2011-15ac3d00", "Local/1014@from-internal/n|60|trM(auto-blkvm)") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Called 1014@from-internal/n
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [1014@from-internal:1] GotoIf("Local/1014@from-internal-ffc6,2", "1?ext-local|1014|1") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (ext-local,1014,1)
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [1014@ext-local:1] Macro("Local/1014@from-internal-ffc6,2", "exten-vm|1014|1014") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("Local/1014@from-internal-ffc6,2", "user-callerid") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:1] Set("Local/1014@from-internal-ffc6,2", "AMPUSER=1050") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("Local/1014@from-internal-ffc6,2", "1?report") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-user-callerid,s,11)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:11] GotoIf("Local/1014@from-internal-ffc6,2", "0?continue") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:12] Set("Local/1014@from-internal-ffc6,2", "__TTL=63") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:13] GotoIf("Local/1014@from-internal-ffc6,2", "1?continue") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-user-callerid,s,20)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:20] NoOp("Local/1014@from-internal-ffc6,2", "Using CallerID "Stijn Tintel" <1050>") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Noop
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Macro
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:2] Set("Local/1014@from-internal-ffc6,2", "RingGroupMethod=none") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:3] Set("Local/1014@from-internal-ffc6,2", "VMBOX=1014") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:4] Set("Local/1014@from-internal-ffc6,2", "EXTTOCALL=1014") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] DEBUG[5086] func_db.c: DB: CFU/1014 not found in database.
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:5] Set("Local/1014@from-internal-ffc6,2", "CFUEXT=") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] DEBUG[5086] func_db.c: DB: CFB/1014 not found in database.
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:6] Set("Local/1014@from-internal-ffc6,2", "CFBEXT=") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:7] Set("Local/1014@from-internal-ffc6,2", "RT=30") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set

[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:8] Macro("Local/1014@from-internal-ffc6,2", "record-enable|1014|IN") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/1014@from-internal-ffc6,2", "1?check") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-record-enable,s,4)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-record-enable:4] AGI("Local/1014@from-internal-ffc6,2", "recordingcheck|20081021-131145|1224587505.29") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   recordingcheck|20081021-131145|1224587505.29: Inbound recording not enabled
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- AGI Script recordingcheck completed, returning 0
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: AGI
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("Local/1014@from-internal-ffc6,2", "") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Macro
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:9] Macro("Local/1014@from-internal-ffc6,2", "dial|30|tr|1014") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-dial:1] GotoIf("Local/1014@from-internal-ffc6,2", "1?dial") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-dial,s,3)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-dial:3] AGI("Local/1014@from-internal-ffc6,2", "dialparties.agi") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   dialparties.agi: Starting New Dialparties.agi
[Oct 21 13:11:45] VERBOSE[5089] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Oct 21 13:11:45] VERBOSE[5089] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5089] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Oct 21 13:11:45] VERBOSE[5089] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5089] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Oct 21 13:11:45] VERBOSE[5089] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5089] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   dialparties.agi: Caller ID name is 'Stijn Tintel' number is '1050'
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   dialparties.agi: Methodology of ring is  'none'
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     --  dialparties.agi: Added extension 1014 to extension map
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     --  dialparties.agi: Extension 1014 cf is disabled
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     --  dialparties.agi: Extension 1014 do not disturb is disabled
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     --  dialparties.agi: dbset CALLTRACE/1014 to 1050
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     --  dialparties.agi: Filtered ARG3: 1014
[Oct 21 13:11:45] VERBOSE[5089] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- AGI Script dialparties.agi completed, returning 0
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: AGI
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-dial:7] Dial("Local/1014@from-internal-ffc6,2", "SIP/1014|30|trM(auto-blkvm)") in new stack
[Oct 21 13:11:45] WARNING[5086] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Dial
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-dial:8] Set("Local/1014@from-internal-ffc6,2", "DIALSTATUS=CHANUNAVAIL") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-dial:9] GosubIf("Local/1014@from-internal-ffc6,2", "0?CHANUNAVAIL|1") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GosubIf
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Macro
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:10] GotoIf("Local/1014@from-internal-ffc6,2", "0?exit|return") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:11] Set("Local/1014@from-internal-ffc6,2", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:12] GosubIf("Local/1014@from-internal-ffc6,2", "0?docfu|1") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GosubIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:13] GosubIf("Local/1014@from-internal-ffc6,2", "0?docfb|1") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GosubIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:14] Set("Local/1014@from-internal-ffc6,2", "DIALSTATUS=CHANUNAVAIL") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:15] NoOp("Local/1014@from-internal-ffc6,2", "Voicemail is 1014") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: NoOp
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:16] GotoIf("Local/1014@from-internal-ffc6,2", "0?s-CHANUNAVAIL|1") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:17] NoOp("Local/1014@from-internal-ffc6,2", "Sending to Voicemail box 1014") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: NoOp
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-exten-vm:18] Macro("Local/1014@from-internal-ffc6,2", "vm|1014|CHANUNAVAIL|") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-vm:1] Macro("Local/1014@from-internal-ffc6,2", "user-callerid|SKIPTTL") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:1] Set("Local/1014@from-internal-ffc6,2", "AMPUSER=1050") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("Local/1014@from-internal-ffc6,2", "1?report") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-user-callerid,s,11)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:11] GotoIf("Local/1014@from-internal-ffc6,2", "1?continue") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (macro-user-callerid,s,20)
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-user-callerid:20] NoOp("Local/1014@from-internal-ffc6,2", "Using CallerID "Stijn Tintel" <1050>") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Noop
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Macro
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-vm:2] Set("Local/1014@from-internal-ffc6,2", "VMGAIN=""") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-vm:3] GotoIf("Local/1014@from-internal-ffc6,2", "0?vmx|1") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] WARNING[5086] func_db.c: DB requires an argument, DB(<family>/<key>)
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [s@macro-vm:4] NoOp("Local/1014@from-internal-ffc6,2", "CAME FROM: 8002 - Blocking VM cause of key: ") in new stack
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Noop
[Oct 21 13:11:45] DEBUG[5086] app_macro.c: Executed application: Macro
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [1014@ext-local:2] Goto("Local/1014@from-internal-ffc6,2", "vmret|1") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Goto (ext-local,vmret,1)
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [vmret@ext-local:1] GotoIf("Local/1014@from-internal-ffc6,2", "0?playret") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:     -- Executing [vmret@ext-local:2] Hangup("Local/1014@from-internal-ffc6,2", "") in new stack
[Oct 21 13:11:45] VERBOSE[5086] logger.c:   == Spawn extension (ext-local, vmret, 2) exited non-zero on 'Local/1014@from-internal-ffc6,2'
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Dial
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:39] Set("SIP/2011-15ac3d00", "HuntLoop=1") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:40] GotoIf("SIP/2011-15ac3d00", "0?a46") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:41] Set("SIP/2011-15ac3d00", "HuntMembers=0") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:42] Set("SIP/2011-15ac3d00", "HuntMembers=-1") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Set
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:43] Goto("SIP/2011-15ac3d00", "s|a22") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-dial,s,22)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Goto
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:22] GotoIf("SIP/2011-15ac3d00", "0?a30") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-dial:23] NoOp("SIP/2011-15ac3d00", "Returning there are no members left in the hunt group to ring") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: NoOp
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:14] Set("SIP/2011-15ac3d00", "RingGroupMethod=") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:15] GotoIf("SIP/2011-15ac3d00", "0?nodest") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:16] Set("SIP/2011-15ac3d00", "__NODEST=") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:17] DBdel("SIP/2011-15ac3d00", "BLKVM/8002/SIP/2011-15ac3d00") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- DBdel: family=BLKVM, key=8002/SIP/2011-15ac3d00
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [8002@from-internal:18] Hangup("SIP/2011-15ac3d00", "") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   == Spawn extension (from-internal, 8002, 18) exited non-zero on 'SIP/2011-15ac3d00'
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/2011-15ac3d00", "hangupcall") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/2011-15ac3d00", "w") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: ResetCDR
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/2011-15ac3d00", "") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: NoCDR
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/2011-15ac3d00", "1?skiprg") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-hangupcall,s,6)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/2011-15ac3d00", "0?skipblkvm") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:7] NoOp("SIP/2011-15ac3d00", "Cleaning Up Block VM Flag: BLKVM/8002/SIP/2011-15ac3d00") in new stack
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: Noop
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:8] DBdel("SIP/2011-15ac3d00", "BLKVM/8002/SIP/2011-15ac3d00") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- DBdel: family=BLKVM, key=8002/SIP/2011-15ac3d00
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- DBdel: Error deleting key from database.
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: DBDel
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/2011-15ac3d00", "1?theend") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Goto (macro-hangupcall,s,11)
[Oct 21 13:11:45] DEBUG[5080] app_macro.c: Executed application: GotoIf
[Oct 21 13:11:45] VERBOSE[5080] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/2011-15ac3d00", "") in new stack
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/2011-15ac3d00' in macro 'hangupcall'
[Oct 21 13:11:45] VERBOSE[5080] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/2011-15ac3d00'
[Oct 21 13:11:45] VERBOSE[5082] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Oct 21 13:11:45] VERBOSE[5082] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5082] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Oct 21 13:11:45] VERBOSE[5082] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5082] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Oct 21 13:11:45] VERBOSE[5082] logger.c: Found
[Oct 21 13:11:45] VERBOSE[5082] logger.c:   == Manager 'admin' logged on from 127.0.0.1

Core version: 2.5.0.4 Ring Group version : 2.5.1.6

Change History

10/21/08 07:38:47 changed by stintel

Ehr, config from extensions_additional is for the wrong ring group, this should be better: 

exten => 8002,1,Macro(user-callerid,)
exten => 8002,n,GotoIf($["foo${BLKVM_OVERRIDE}" = "foo"]?skipdb)
exten => 8002,n,GotoIf($["${DB(${BLKVM_OVERRIDE})}" = "TRUE"]?skipov)
exten => 8002,n(skipdb),Set(__NODEST=)
exten => 8002,n,Set(__BLKVM_OVERRIDE=BLKVM/${EXTEN}/${CHANNEL})
exten => 8002,n,Set(__BLKVM_BASE=${EXTEN})
exten => 8002,n,Set(DB(${BLKVM_OVERRIDE})=TRUE)
exten => 8002,n(skipov),Set(RRNODEST=${NODEST})
exten => 8002,n(skipvmblk),Set(__NODEST=${EXTEN})
exten => 8002,n,GotoIf($["foo${RGPREFIX}" = "foo"]?REPCID)
exten => 8002,n,GotoIf($["${RGPREFIX}" != "${CALLERID(name):0:${LEN(${RGPREFIX})}}"]?REPCID)
exten => 8002,n,Noop(Current RGPREFIX is ${RGPREFIX}....stripping from Caller ID)
exten => 8002,n,Set(CALLERID(name)=${CALLERID(name):${LEN(${RGPREFIX})}})
exten => 8002,n,Set(_RGPREFIX=)
exten => 8002,n(REPCID),Noop(CALLERID(name) is ${CALLERID(name)})
exten => 8002,n,Set(_RGPREFIX=Accounting: )
exten => 8002,n,Set(CALLERID(name)=${RGPREFIX}${CALLERID(name)})
exten => 8002,n,Set(RecordMethod=Group)
exten => 8002,n,Macro(record-enable,1014-1010,${RecordMethod})
exten => 8002,n,Set(RingGroupMethod=firstavailable)
exten => 8002,n(DIALGRP),Macro(dial,60,${DIAL_OPTIONS},1014-1010)
exten => 8002,n,Set(RingGroupMethod=)
exten => 8002,n,GotoIf($["foo${RRNODEST}" != "foo"]?nodest)
exten => 8002,n,Set(__NODEST=) 
exten => 8002,n,dbDel(${BLKVM_OVERRIDE})
exten => 8002,n,Hangup
exten => 8002,n(nodest),Noop(SKIPPING DEST, CALL CAME FROM Q/RG: ${RRNODEST})

10/21/08 08:04:38 changed by p_lindheimer

  • status changed from new to closed.
  • resolution set to invalid.

You have provided 3 sets of inconsistent information in this trace. First a ring group which was not the same as the log trace, and then a "correction" that was still not the same as what you tested. When providing configuration data and log traces, please make sure that you provide what you tested. When you don't, you end up taking a lot of time for developers trying to understand what is going on when that data provided is not correct.

Your last configuration claims you had the following for your ringgroup: 

1014
1010

but the trace you provided shows you had: 

1014#
1010#

The latter is very different, it dials as if you were calling an outside number (even though it will reach the extension and run it through their follow-me if they have one). However, because it is "just a dialed number" (because of the #) it is not treated like an extension and thus there is not state information on it. That means it is available (because we don't know what the followme list might dial).

Marking this as invalid due to the conflicting nature of configuration data and logs that are not related. It works if you remove the "#".

10/21/08 08:20:32 changed by stintel

Hmmm. It seems that I accidentally copied the wrong trace from the log. I tried to add the # at the end, to see if that would make a difference. Here is a log trace with configuration as attached to this ticket. Apologies for the confustion. 

[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:1] Macro("SIP/2011-1d31f6b0", "user-callerid|") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/2011-1d31f6b0", "AMPUSER=2011") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/2011-1d31f6b0", "0?report") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/2011-1d31f6b0", "1|Set|REALCALLERIDNUM=2011") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: ExecIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/2011-1d31f6b0", "AMPUSER=1050") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/2011-1d31f6b0", "AMPUSERCIDNAME=Stijn Tintel") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/2011-1d31f6b0", "0?report") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/2011-1d31f6b0", "AMPUSERCID=1050") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/2011-1d31f6b0", "CALLERID(all)="Stijn Tintel" <1050>") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:9] Set("SIP/2011-1d31f6b0", "REALCALLERIDNUM=1050") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:10] ExecIf("SIP/2011-1d31f6b0", "0|Set|CHANNEL(language)=") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: ExecIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:11] GotoIf("SIP/2011-1d31f6b0", "0?continue") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:12] Set("SIP/2011-1d31f6b0", "__TTL=64") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:13] GotoIf("SIP/2011-1d31f6b0", "1?continue") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-user-callerid,s,20)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-user-callerid:20] NoOp("SIP/2011-1d31f6b0", "Using CallerID "Stijn Tintel" <1050>") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Noop
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:2] GotoIf("SIP/2011-1d31f6b0", "1?skipdb") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (from-internal,8002,4)
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:4] Set("SIP/2011-1d31f6b0", "__NODEST=") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:5] Set("SIP/2011-1d31f6b0", "__BLKVM_OVERRIDE=BLKVM/8002/SIP/2011-1d31f6b0") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:6] Set("SIP/2011-1d31f6b0", "__BLKVM_BASE=8002") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:7] Set("SIP/2011-1d31f6b0", "DB(BLKVM/8002/SIP/2011-1d31f6b0)=TRUE") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:8] Set("SIP/2011-1d31f6b0", "RRNODEST=") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:9] Set("SIP/2011-1d31f6b0", "__NODEST=8002") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:10] GotoIf("SIP/2011-1d31f6b0", "1?REPCID") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (from-internal,8002,15)
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:15] NoOp("SIP/2011-1d31f6b0", "CALLERID(name) is Stijn Tintel") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:16] Set("SIP/2011-1d31f6b0", "_RGPREFIX=Accounting: ") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:17] Set("SIP/2011-1d31f6b0", "CALLERID(name)=Accounting: Stijn Tintel") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:18] Set("SIP/2011-1d31f6b0", "RecordMethod=Group") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:19] Macro("SIP/2011-1d31f6b0", "record-enable|1014-1010|Group") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/2011-1d31f6b0", "1?check") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-record-enable,s,4)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/2011-1d31f6b0", "recordingcheck|20081021-171626|1224602186.3") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- AGI Script recordingcheck completed, returning 0
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: AGI
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/2011-1d31f6b0", "") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:20] Set("SIP/2011-1d31f6b0", "RingGroupMethod=firstavailable") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:21] Macro("SIP/2011-1d31f6b0", "dial|60|tr|1014-1010") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/2011-1d31f6b0", "1?dial") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,3)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/2011-1d31f6b0", "dialparties.agi") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   dialparties.agi: Starting New Dialparties.agi
[Oct 21 17:16:26] VERBOSE[7792] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Oct 21 17:16:26] VERBOSE[7792] logger.c: Found
[Oct 21 17:16:26] VERBOSE[7792] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Oct 21 17:16:26] VERBOSE[7792] logger.c: Found
[Oct 21 17:16:26] VERBOSE[7792] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Oct 21 17:16:26] VERBOSE[7792] logger.c: Found
[Oct 21 17:16:26] VERBOSE[7792] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   dialparties.agi: Caller ID name is 'Accounting: Stijn Tintel' number is '1050'
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   dialparties.agi: Methodology of ring is  'firstavailable'
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Added extension 1014 to extension map
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Added extension 1010 to extension map
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Extension 1014 cf is disabled
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Extension 1010 cf is disabled
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Extension 1014 do not disturb is disabled
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Extension 1010 do not disturb is disabled
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     --  dialparties.agi: Filtered ARG3: 1014-1010
[Oct 21 17:16:26] VERBOSE[7792] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- AGI Script dialparties.agi completed, returning 0
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: AGI
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:20] NoOp("SIP/2011-1d31f6b0", "Returned from dialparties with hunt groups to dial ") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: NoOp
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:21] Set("SIP/2011-1d31f6b0", "HuntLoop=0") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:22] GotoIf("SIP/2011-1d31f6b0", "1?a30") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,26)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:26] Set("SIP/2011-1d31f6b0", "HuntMember=HuntMember0") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:27] GotoIf("SIP/2011-1d31f6b0", "0?a32:a35") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,31)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:31] GotoIf("SIP/2011-1d31f6b0", "0?a36:a50") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,44)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:44] DBdel("SIP/2011-1d31f6b0", "CALLTRACE/") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- DBdel: family=CALLTRACE, key=
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- DBdel: Error deleting key from database.
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: DBdel
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:45] Goto("SIP/2011-1d31f6b0", "s|a42") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,38)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Goto
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:38] Dial("SIP/2011-1d31f6b0", "SIP/1014|60|trM(auto-blkvm)") in new stack
[Oct 21 17:16:26] WARNING[7789] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Dial
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:39] Set("SIP/2011-1d31f6b0", "HuntLoop=1") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:40] GotoIf("SIP/2011-1d31f6b0", "0?a46") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:41] Set("SIP/2011-1d31f6b0", "HuntMembers=0") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:42] Set("SIP/2011-1d31f6b0", "HuntMembers=-1") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Set
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:43] Goto("SIP/2011-1d31f6b0", "s|a22") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-dial,s,22)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Goto
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:22] GotoIf("SIP/2011-1d31f6b0", "0?a30") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-dial:23] NoOp("SIP/2011-1d31f6b0", "Returning there are no members left in the hunt group to ring") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: NoOp
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:22] Set("SIP/2011-1d31f6b0", "RingGroupMethod=") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:23] GotoIf("SIP/2011-1d31f6b0", "0?nodest") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:24] Set("SIP/2011-1d31f6b0", "__NODEST=") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:25] DBdel("SIP/2011-1d31f6b0", "BLKVM/8002/SIP/2011-1d31f6b0") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- DBdel: family=BLKVM, key=8002/SIP/2011-1d31f6b0
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [8002@from-internal:26] Hangup("SIP/2011-1d31f6b0", "") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   == Spawn extension (from-internal, 8002, 26) exited non-zero on 'SIP/2011-1d31f6b0'
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/2011-1d31f6b0", "hangupcall") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/2011-1d31f6b0", "w") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: ResetCDR
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/2011-1d31f6b0", "") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: NoCDR
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/2011-1d31f6b0", "1?skiprg") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-hangupcall,s,6)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/2011-1d31f6b0", "0?skipblkvm") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:7] NoOp("SIP/2011-1d31f6b0", "Cleaning Up Block VM Flag: BLKVM/8002/SIP/2011-1d31f6b0") in new stack
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: Noop
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:8] DBdel("SIP/2011-1d31f6b0", "BLKVM/8002/SIP/2011-1d31f6b0") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- DBdel: family=BLKVM, key=8002/SIP/2011-1d31f6b0
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- DBdel: Error deleting key from database.
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: DBDel
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/2011-1d31f6b0", "1?theend") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Goto (macro-hangupcall,s,11)
[Oct 21 17:16:26] DEBUG[7789] app_macro.c: Executed application: GotoIf
[Oct 21 17:16:26] VERBOSE[7789] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/2011-1d31f6b0", "") in new stack
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/2011-1d31f6b0' in macro 'hangupcall'
[Oct 21 17:16:26] VERBOSE[7789] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/2011-1d31f6b0'

10/21/08 09:18:25 changed by stintel

In extension.conf, I added a check for CHANUNAVAIL, by changing this line:

exten => s,n,GotoIf($[$[$["foo${RingGroupMethod}" != "foofirstavailable"] & $["foo${RingGroupMethod}" != "foofirstnotonphone"]] | $["foo${DialStatus}" = "fooBUSY"]]?a46)

into: exten => s,n,GotoIf($[$[$["foo${RingGroupMethod}" != "foofirstavailable"] & $["foo${RingGroupMethod}" != "foofirstnotonphone"]] | $["foo${DialStatus}" = "fooBUSY"] | $["foo${DialStatus}" = "fooCHANUNAVAIL"]]?a46)

After this change, it does work as expected.

10/21/08 12:11:34 changed by p_lindheimer

something is broken on your system: 

[Oct 21 17:16:26] WARNING[7789] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)

It looks like you may not have chan_sip.so properly loaded. Such issues are going to have un-desired consequences. FreePBX expects the system to be behaving normally and I don't think that is normal behavior.

12/27/08 19:36:28 changed by naftali5

I am the one who added the BUSY check in #1671, and did not think it possible for a call to get past dialparties.agi with an extension to ring if it was CHANUNAVAIL. Actually most people will never hit the BUSY line either, as dialparties.agi filters those out. The only way is a zap channel offhook, but not in a call, or a SIP phone with the phone having DND set (not in freepbx).

The changes proposed above will only affect these modes (firstavailable and firstnotonphone) and regardless of how CHANUNAVAIL happened, if it returns CHANUNAVAIL, the desired behavior is to ring another phone, so stintel proposed, and posted the exact correct solution.

But seems like I lost trac_admin privileges along with svn access during my absence so I cannot reopen the ticket - or fix it :(

12/28/08 23:05:57 changed by wiseoldowl

  • status changed from closed to reopened.
  • resolution deleted.
  • description changed.

I'm going to go out on a limb (isn't that where owls belong?) :-) and reopen this ticket, because even if the OP might have made some mistake when posting the details (something any of us could have done, especially if we are tired - I know I've made mistakes like that), there nevertheless is a bona fide bug AND A FIX in this ticket, and until such time as the fix is incorporated into FreePBX I would think that the bug report should remain open. Sorry if this steps on anyone's toes, but let's not lose sight of the fact that we should not let personality clashes or whatever prevent a bug from being fixed, especially when the solution is offered to us on the proverbial silver platter. I, for one, would like to thank stintel for his effort in tracking this down and providing the fix.