Ticket #3439 (closed Bugs: fixed)

Opened 4 years ago

Last modified 4 years ago

Call Trace/Callback seems to have stopped working when follow-me is in use

Reported by: wiseoldowl Assigned to:
Priority: minor Milestone: 2.6
Component: Callback Version: 2.4.0
Keywords: Cc:
Confirmation: Need Feedback Distro:
Backend Engine: All Distro Ver:
Backend Ver: SVN Revision (if applicable):

Description

I'm using Elastix with FreePBX 2.4 so don't know if this may have been fixed in 2.5, but I am observing that *69 no longer returns valid information on the last call. This is true whether the call is from another extension or from an outside caller. All of my extensions have follow-me's set up (firstnotonphone treatment so calls will roll over from a busy extension to a non-busy one) but that should not affect callback, should it? In any case, ever time I call *69 it says the call came from extension 255 which is REALLY strange, because 255 is a dedicated extension that can only call a ring group with two extensions on it, neither of which are the extensions I use, and furthermore 255 is on a VoIP adapter that's set up to "hot dial" its destination whenever the phone is taken off hook (and to further eliminate possibilities, the dial doesn't even work on the phone connected to that adapter!). So I don't see how I could have received a call from extension 255 in the first place, but in any case it seems that's now permanently set as the "last call" number when *69 is called. This used to work in previous versions so I don't know what changed, but something is not right there! By the way, CallerID is delivered normally and correctly.

Change History

12/12/08 16:39:13 changed by mickecarlsson

  • confirmation changed from Unreviewed to Need Feedback.

Start asterisk console (asterisk -r) and type 'database show calltrace' You will see something like /CALLTRACE/1234 : 555123456

Do you see anything abnormal there?

The best thing to trace this is to type 'set verbose 5' and the do test call from one extension to another. Stop trace with 'set verbose 0' and post the log to this ticket.

12/22/08 02:55:00 changed by wiseoldowl

Sorry for not responding sooner, I did not see that there had been a reply. It turns out that the issue only occurs on extensions that have a follow-me set up. If you don't have a follow-me then the calling extension gets recorded (shown in the 'database show calltrace' display). But if you do have a follow me, this appears not to be the case. However, I should explain that my follow-mes are just a bit atypical in that I will group two or three extensions together and then use follow-mes with a Ring Strategy of firstnotonphone. My Follow-Me List would then look like this (this is for extension 250):

****250#
250
251
252

Now you are probably wondering what that first entry is - well that is a hack to fire off a Caller ID popup. It always returns busy so the call then falls through to the next extension on the list. There are two lines for it in extensions_custom.conf:

exten => ****250,1,Notify(${CALLERID(num)}|${CALLERID(name)}|250/192.168.1.2)
exten => ****250,n,Busy

(More info on what I'm accomplishing by doing that is here: How to set up notification (Caller ID popup) on Mac OS X, Linux and other systems)

Anyway, even with the follow-me in use, I would still expect whichever extension(s) ultimately ring should have the calling number stored in the database, or failing that, perhaps at least it should be stored for the extension that was actually called. But when I have the follow-me in operation, I can call 250, and 250 rings (because it's not in use) but still the calling number doesn't seem to get recorded for 250, and never will as long as the follow-me is in operation.

12/22/08 03:12:27 changed by wiseoldowl

Here is the log you asked for - call from 251 to 250:

    -- Executing [250@from-internal:1] GotoIf("SIP/251-08d12880", "0?ext-local|250|1") in new stack
    -- Executing [250@from-internal:2] Macro("SIP/251-08d12880", "user-callerid|") in new stack
    -- Executing [s@macro-user-callerid:1] NoOp("SIP/251-08d12880", "user-callerid: device 251") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/251-08d12880", "AMPUSER=251") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/251-08d12880", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/251-08d12880", "1|Set|REALCALLERIDNUM=251") in new stack
    -- Executing [s@macro-user-callerid:5] 6;40mNoOp("SIP/251-08d12880", "REALCALLERIDNUM is 251") in new stack
    -- Executing [s@macro-user-callerid:6] Set("SIP/251-08d12880", "AMPUSER=251") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/251-08d12880", "AMPUSERCIDNAME=John Smith") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf;40m("SIP/251-08d12880", "0?report") in new stack
    -- Executing [s@macro-user-callerid:9] Set("SIP/251-08d12880", "AMPUSERCID=251") in new stack
    -- Executing [s@macro-user-callerid:10] Set("SIP/251-08d12880", "CALLERID(all)="John Smith" <251>") in new stack
    -- Executing [s@macro-user-callerid:11] Set("SIP/251-08d12880", "REALCALLERIDNUM=251") in new stack
    -- Executing [s@macro-user-callerid:12] ExecIf("SIP/251-08d12880", "0|Set|CHANNEL(language)=") in new stack
    -- Executing [s@macro-user-callerid:13] NoOp("SIP/251-08d12880", "TTL:  ARG1: ") in new stack
    -- Executing [s@macro-user-callerid:14] GotoIf("SIP/251-08d12880", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:15] Set("SIP/251-08d12880", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/251-08d12880", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,23)
    -- Executing [s@macro-user-callerid:23] NoOp("SIP/251-08d128800;37;40m", "Using CallerID "John Smith" <251>") in new stack
    -- Executing [250@from-internal:3] GotoIf("SIP/251-08d12880", "1?skipdb") in new stack
    -- Goto (from-internal,250,5)
    -- Executing [250@from-internal:5] Set("SIP/251-08d12880", "__NODEST=") in new stack
    -- Executing [250@from-internal:6] Set("SIP/251-08d128800;37;40m", "__BLKVM_OVERRIDE=BLKVM/250/SIP/251-08d12880") in new stack
    -- Executing [250@from-internal:7] Set("SIP/251-08d12880", "__BLKVM_BASE=250") in new stack
    -- Executing [250@from-internal:8] Set("SIP/251-08d12880", "DB(BLKVM/250/SIP/251-08d12880)=TRUE") in new stack
    -- Executing [250@from-internal:9] Set("SIP/251-08d12880", "RRNODEST=") in new stack
    -- Executing [250@from-internal:10] Set("SIP/251-08d12880", "__NODEST=250") in new stack
    -- Executing [250@from-internal:11] GotoIf("SIP/251-08d12880", "1 ?skipsimple") in new stack
    -- Goto (from-internal,250,13)
    -- Executing [250@from-internal:13] Set("SIP/251-08d12880", "RecordMethod=Group") in new stack
    -- Executing [250@from-internal:14] Macro("SIP/251-08d12880", "record-enable|****250#-250-251-252|Group") in new stack
    -- Executing [s@macro-record-enable:1] GotoIf("SIP/251-08d12880", "0?2:4") in new stack
    -- Goto (macro-record-enable,s,4)
    -- Executing [s@macro-record-enable:4] AGI("SIP/251-08d12880", "recordingcheck|20081222-025923|1229932763.335") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
  recordingcheck|20081222-025923|1229932763.335: No DB Entry AMPUSER/****250#/recording - Not Recording for ****250#, checking for others
    -- AGI Script recordingcheck completed, returning 0
    -- Executing [s@macro-record-enable:5] NoOp("SIP/251-08d12880", "No recording needed") in new stack
    -- Executing [250@from-internal:15] Set("SIP/251-08d12880", "RingGroupMethod=firstnotonphone") in new stack
    -- Executing [250@from-internal:16] Set("SIP/251-08d12880", "_FMGRP=250") in new stack
    -- Executing [250@from-internal:17] GotoIf("SIP/251-08d12880", "0?doconfirm") in new stack
    -- Executing [250@from-internal:18] Macro("SIP/251-08d12880", "dial|32|m(special-ringing)tTwW|****250#-250-251-252") in new stack
    -- Executing [s@macro-dial:1] GotoIf("SIP/251-08d12880", "1?dial") in new stack
    -- Goto (macro-dial,s,3)
    -- Executing [s@macro-dial:3] AGI("SIP/251-08d12880", "dialparties.agi") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
  dialparties.agi: Starting New Dialparties.agi
  == 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
  dialparties.agi: Caller ID name is 'John Smith' number is '251'
  dialparties.agi: USE_CONFIRMATION:  'FALSE'
  dialparties.agi: RINGGROUP_INDEX:   ''
  dialparties.agi: Methodology of ring is  'firstnotonphone'
    --  dialparties.agi: Added extension ****250# to extension map
    --  dialparties.agi: Added extension 250 to extension map
    --  dialparties.agi: Added extension 251 to extension map
    --  dialparties.agi: Added extension 252 to extension map
    --  dialparties.agi: Extension ****250# cf is disabled
    --  dialparties.agi: Extension 250 cf is disabled
    --  dialparties.agi: Extension 251 cf is disabled
    --  dialparties.agi: Extension 252 cf is disabled
    --  dialparties.agi: Extension 250 do not disturb is disabled
    --  dialparties.agi: Extension 251 do not disturb is disabled
    --  dialparties.agi: Extension 252 do not disturb is disabled
       >  dialparties.agi: extnum ****250# has:  cw: 0; hascfb: 0 [] hascfu: 0 []
       >  dialparties.agi: Built External dialstring component for ****250: Local/****250@from-internal/n
       >  dialparties.agi: extnum 250 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
       >  dialparties.agi: ExtensionState: 0
  dialparties.agi: Extension 250 has ExtensionState: 0
    --  dialparties.agi: Checking CW and CFB status for extension 250
       >  dialparties.agi: extnum 251 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
       >  dialparties.agi: ExtensionState: 1
  dialparties.agi: Extension 251 has ExtensionState: 1
    --  dialparties.agi: Checking CW and CFB status for extension 251
  dialparties.agi: Extension 251 is not available to be called
  dialparties.agi: Extension 251 has call waiting disabled
       >  dialparties.agi: extnum 252 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
       >  dialparties.agi: ExtensionState: 0
  dialparties.agi: Extension 252 has ExtensionState: 0
    --  dialparties.agi: Checking CW and CFB status for extension 252
    --  dialparties.agi: Filtered ARG3: ****250-250-252
       >  dialparties.agi: NODEST: 250 adding M(auto-blkvm) to dialopts: m(special-ringing)tTwWM(auto-blkvm)
       >  dialparties.agi: NODEST: 250 blkvm enabled macro already in dialopts: m(special-ringing)tTwWM(auto-blkvm)
  == Manager 'admin' logged off from 127.0.0.1
    -- AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:20] NoOp("SIP/251-08d12880", "Returned from dialparties with hunt groups to dial ") in new stack
    -- Executing [s@macro-dial:21] Set("SIP/251-08d12880", "HuntLoop=0") in new stack
    -- Executing [s@macro-dial:22] GotoIf("SIP/251-08d12880", "1?a30") in new stack
    -- Goto (macro-dial,s,26)
    -- Executing [s@macro-dial:26] Set("SIP/251-08d12880", "HuntMember=HuntMember0") in new stack
    -- Executing [s@macro-dial:27] GotoIf("SIP/251-08d12880", "0?a32:a35") in new stack
    -- Goto (macro-dial,s,31)
    -- Executing [s@macro-dial:31] GotoIf("SIP/251-08d12880", "0?a36:a50") in new stack
    -- Goto (macro-dial,s,44)
    -- Executing [s@macro-dial:44] DBdel("SIP/251-08d12880", "CALLTRACE/") in new stack
    -- DBdel: family=CALLTRACE, key=
    -- DBdel: Error deleting key from database.
    -- Executing [s@macro-dial:45] Goto("SIP/251-08d12880", "s|a42") in new stack
    -- Goto (macro-dial,s,38)
    -- Executing [s@macro-dial:38] Dial("SIP/251-08d12880", "Local/****250@from-internal/n|32|m(special-ringing)tTwWM(auto-blkvm)") in new stack
    -- Called ****250@from-internal/n
    -- Started music on hold, class 'special-ringing', on SIP/251-08d12880
    -- Executing [****250@from-internal:1] Notify("Local/****250@from-internal-41c4,2", "251|John Smith|250/192.168.1.2") in new stack
    -- Notify: sending '251|John Smith|250' to 192.168.1.2:40000 
    -- Executing [****250@from-internal:2] Busy("Local/****250@from-internal-41c4,2", "") in new stack
    -- Local/****250@from-internal-41c4,1 is busy
  == Everyone is busy/congested at this time (1:1/0/0)
    -- Stopped music on hold on SIP/251-08d12880
    -- Executing [s@macro-dial:39] Set("SIP/251-08d12880", "HuntLoop=1") in new stack
    -- Executing [s@macro-dial:40] GotoIf("SIP/251-08d12880", "1?a46") in new stack
    -- Goto (macro-dial,s,42)
    -- Executing [s@macro-dial:42] Set("SIP/251-08d12880", "HuntMembers=2") in new stack
    -- Executing [s@macro-dial:43] Goto("SIP/251-08d12880", "s|a22") in new stack
    -- Goto (macro-dial,s,22)
    -- Executing [s@macro-dial:22] GotoIf("SIP/251-08d12880", "1?a30") in new stack
    -- Goto (macro-dial,s,26)
    -- Executing [s@macro-dial:26] Set("SIP/251-08d12880", "HuntMember=HuntMember1") in new stack
    -- Executing [s@macro-dial:27] GotoIf("SIP/251-08d12880", "0?a32:a35") in new stack
    -- Goto (macro-dial,s,31)
    -- Executing [s@macro-dial:31] GotoIf("SIP/251-08d12880", "0?a36:a50") in new stack
    -- Goto (macro-dial,s,44)
    -- Executing [s@macro-dial:44] DBdel("SIP/251-08d12880", "CALLTRACE/") in new stack
    -- DBdel: family=CALLTRACE, key=
    -- DBdel: Error deleting key from database.
    -- Executing [s@macro-dial:45] Goto("SIP/251-08d12880", "s|a42") in new stack
    -- Goto (macro-dial,s,38)
    -- Executing [s@macro-dial:38] Dial("SIP/251-08d12880", "SIP/250|32|m(special-ringing)tTwWM(auto-blkvm)") in new stack
    -- Called 250
    -- Started music on hold, class 'special-ringing', on SIP/251-08d12880
  == Spawn extension (from-internal, ****250, 2) exited non-zero on 'Local/****250@from-internal-41c4,2'
    -- Executing [h@from-internal:1] Macro("Local/****250@from-internal-41c4,2", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] ResetCDR("Local/****250@from-internal-41c4,2", "w") in new stack
    -- Executing [s@macro-hangupcall:2] NoCDR("Local/****250@from-internal-41c4,2", "") in new stack
    -- Executing [s@macro-hangupcall:3] GotoIf("Local/****250@from-internal-41c4,2", "1?skiprg") in new stack
    -- Goto (macro-hangupcall,s,6)
    -- Executing [s@macro-hangupcall:6] GotoIf("Local/****250@from-internal-41c4,2", "1?skipblkvm") in new stack
    -- Goto (macro-hangupcall,s,9)
    -- Executing [s@macro-hangupcall:9] GotoIf("Local/****250@from-internal-41c4,2", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,11)
    -- Executing [s@macro-hangupcall:11] Hangup("Local/****250@from-internal-41c4,2", "") in new stack
  == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Local/****250@from-internal-41c4,2' in macro 'hangupcall'
  == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Local/****250@from-internal-41c4,2'
    -- SIP/250-086e98c8 is ringing
    -- Stopped music on hold on SIP/251-08d12880
  == Spawn extension (macro-dial, s, 38) exited non-zero on 'SIP/251-08d12880' in macro 'dial'
  == Spawn extension (macro-dial, s, 38) exited non-zero on 'SIP/251-08d12880'
    -- Executing [h@macro-dial:1] Macro("SIP/251-08d12880", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/251-08d12880", "w") in new stack
    -- Executing [s@macro-hangupcall:2] NoCDR("SIP/251-08d12880", "") in new stack
    -- Executing [s@macro-hangupcall:3] GotoIf("SIP/251-08d12880", "1?skiprg") in new stack
    -- Goto (macro-hangupcall,s,6)
    -- Executing [s@macro-hangupcall:6] GotoIf("SIP/251-08d12880", "0?skipblkvm") in new stack
    -- Executing [s@macro-hangupcall:7] NoOp("SIP/251-08d12880", "Cleaning Up Block VM Flag: BLKVM/250/SIP/251-08d12880") in new stack
    -- Executing [s@macro-hangupcall:8] DBdel("SIP/251-08d12880", "BLKVM/250/SIP/251-08d12880") in new stack
    -- DBdel: family=BLKVM, key=250/SIP/251-08d12880
    -- Executing [s@macro-hangupcall:9] GotoIf("SIP/251-08d12880", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,11)
    -- Executing [s@macro-hangupcall:11] Hangup("SIP/251-08d12880", "") in new stack
  == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/251-08d12880' in macro 'hangupcall'
  == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/251-08d12880'

12/22/08 03:13:28 changed by wiseoldowl

  • summary changed from Call Trace/Callback seems to have stopped working to Call Trace/Callback seems to have stopped working when follow-me is in use.

12/26/08 16:31:25 changed by wiseoldowl

It appears there is a fix for this, at least it seems to fix the problem on my system. But since I'm not the person who figured it out, I want to hold off on posting it until I see if he is able to submit it. If not, then I'll post the fix here later tonight or tomorrow (it's a single line change in extensions.conf).

12/26/08 16:33:43 changed by wiseoldowl

Oops, make that Sunday.

12/27/08 05:12:08 changed by mickecarlsson

Thank you wiseoldowl, I have verified that there is something not right with the current implementation and are talking with other developers about the issue. Awaiting your suggestion.

12/27/08 22:06:39 changed by naftali5

Thanks wiseoldowl for pointing it out. Actually pointed out in #1850, by wiseoldowl, but then it had only been in trunk, not released yet.

Anyhow, here is the patch, against /modules/branches/2.5/

Index: core/etc/extensions.conf
===================================================================
--- core/etc/extensions.conf    (revision 7339)
+++ core/etc/extensions.conf    (working copy)
@@ -94,7 +94,7 @@
 ; and The total number in HuntMembers. So for each iteration, we will update the CALLTRACE Data.
 ;
 exten => s,n+2(a30),Set(HuntMember=HuntMember${HuntLoop})
-exten => s,n,GotoIf($[$["${CALLTRACE_HUNT}" != "" ] & $["${RingGroupMethod}" = "hunt" ]]?a32:a35)
+exten => s,n,GotoIf($[$["${CALLTRACE_HUNT}" != "" ] & $[$["${RingGroupMethod}" = "hunt" ] | $["${RingGroupMethod}" = "firstavailable"] | $["${RingGroupMethod}" = "firstnotonphone"]]]?a32:a35)
 exten => s,n(a32),Set(CT_EXTEN=${CUT(FILTERED_DIAL,,$[${HuntLoop} + 1])})
 exten => s,n,Set(DB(CALLTRACE/${CT_EXTEN})=${CALLTRACE_HUNT})
 exten => s,n,Goto(s,a42)

...and the commit message which I couldn't commit as it seems I lost svn access somewhere during my absence :(

probably due to this change

Closes #3439 - re #1671 - re #1850 - fixed calltrace function for ringgroup with firstnotonphone or firstavailable modes

but i am not closing this one - until the change is committed.

12/28/08 08:04:00 changed by wiseoldowl

Thank you naftali5 for posting the fix, which also works in FreePBX 2.4.0 (I show line 85 of extensions.conf as the line to change in that version, although with the caveat that the text editor I use doesn't always seem to number lines in the same manner as used in patch files).

01/07/09 14:07:28 changed by mickecarlsson

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

(In [7411]) Closes #3439 fixes calltrace function for ringgroup with firstnotonphone or firstavailable modes. Thank you naftali5

03/13/09 20:15:38 changed by p_lindheimer

(In [7524]) Merged revisions 7411,7413,7415-7416,7419-7420,7423-7434,7438-7439,7441-7442,7444-7446,7458-7469 via svnmerge from http://svn.freepbx.org/modules/branches/2.6

........

r7411 | mickecarlsson | 2009-01-07 11:07:27 -0800 (Wed, 07 Jan 2009) | 1 line

Closes #3439 fixes calltrace function for ringgroup with firstnotonphone or firstavailable modes. Thank you naftali5

........

r7442 | mickecarlsson | 2009-02-03 10:33:30 -0800 (Tue, 03 Feb 2009) | 1 line

Closes #3510 add missing echo in code. Thank you jsarrel

........

r7462 | p_lindheimer | 2009-02-17 13:07:28 -0800 (Tue, 17 Feb 2009) | 1 line

add webserver as acceptable AUTHTYPE so admin module does not complain

........

r7464 | mickecarlsson | 2009-03-01 11:03:55 -0800 (Sun, 01 Mar 2009) | 1 line

Closes #3557, fixes typo in code. Thank you zultron.

........

r7469 | mbrevda | 2009-03-07 14:15:25 -0800 (Sat, 07 Mar 2009) | 1 line

cosmetic and security settings updated; updated applet to latest version

........