[Home]

Summary:ASTERISK-13742: [patch] Lost info in CDR when transfering call via AMI's Redirect
Reporter:caspy (caspy)Labels:
Date Opened:2009-03-13 09:11:05Date Closed:2011-07-26 15:13:28
Priority:MajorRegression?No
Status:Closed/CompleteComponents:CDR/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) app_answer-cdr-fix1.diff
( 1) backtrace1.txt
( 2) backtrace2.txt
( 3) manager-redirect-cdr-fix1.diff
( 4) manager-redirect-cdr-fix2.diff
( 5) manager-redirect-cdr-fix3.diff
( 6) manager-redirect-cdr-fix4.diff
( 7) manager-redirect-cdr-fix5.diff
( 8) manager-redirect-cdr-fix6.diff
Description:- SIP/1344 call SIP/1340
- SIP/1340 answers, and they are speaking
- man-in-a-middle do a Redirect of SIP/1344 leg of this call to SIP/1341
- SIP/1341 answers, and 1344 speaks with 1341 successfuly.

The probles is in CDR.
For the first call (1344 to 1340) asterisk lost just all important fields:


"","","s","fromoffice","","SIP/1340-08c6dce8","","","","2009-03-13 16:37:44","2009-03-13 16:37:47","2009-03-13 16:37:54",10,7,"ANSWERED","DOCUMENTATION","1236951464.550476",""

"","1344","1341","fromoffice","""Akzhan Test"" <1344>","SIP/1344-b4b3e758","SIP/1341-b51deec0","Dial","SIP/1341,60,twTWL(5400000)","2009-03-13 16:37:44","2009-03-13 16:38:00","2009-03-13 16:38:05",21,5,"ANSWERED","DOCUMENTATION","1236951464.550474",""


Also, mention that uniqueid is very strange: first part (time) is the same, but second is decreesed for two. Why?
Comments:By: caspy (caspy) 2009-03-13 09:14:19

"man-in-a-middle do a Redirect" == tranfer is done via Redirect command in Manager Interface.
By: caspy (caspy) 2009-03-13 09:34:24

i've looked for code of blindtransfer in main/features.c,
there are some manipulations with cdr just before ast_async_goto() call.

in manager.c there is nothing done with cdr before goto.

may be this is a reason? ;)
By: caspy (caspy) 2009-03-17 07:35:23

may be i was wrong with category, and it should be 'Core/ManagerInterface'?
can someone look and change if needed?
By: Leif Madsen (lmadsen) 2009-03-18 08:27:41

I'll leave this as a CDR issue for now since that is what is being affected. Thanks!
By: caspy (caspy) 2009-03-20 03:35:13

i've made some researches in code.

Scenario ONE:
- A call to B, and they are speaking;
- B makes a blind transfer (via res_features) of A to C;
- A speaking to C.
here swaping cdr is needed and done (cause B was a callee party, and need cdr info for his call).

ALL OK here.



Scenario TWO:
- A call to B, and they are speaking;
- A makes a blind transfer (via res_features) of B to C;
- B speaking to C.
here swaping cdr is NOT needed, but done.
NOT OK. we are making CDR for B-to-C call incorrect.
(Also, channel A did not hanged up, and recalls to B. May be i should report another one bug?)


Scenario THREE:
- A call to B;
- some one else make an AMI's Redirect of A (or B) to C.
- and if we transfering A (to C), we should swap cdrs. but in action_redirect() in manager.c we have only trasfeered channel structure.
By: caspy (caspy) 2009-06-25 11:09:31

can i help smth else, to solve this issue?
By: Matthew Nicholson (mnicholson) 2009-07-21 13:01:00

What is the current state of this bug?  Is this still a problem with asterisk trunk?
By: caspy (caspy) 2009-07-27 01:15:12

i run 1.6.0.9 now. here problem exists.
By: Matthew Nicholson (mnicholson) 2009-07-28 10:51:08

I have identified a problem with CDRs related to the manager redirect command.  I am working on a fix for that.  Some aspects of this problem cannot be fixed within the current CDR architecture and can only be solved using CEL.
By: Matthew Nicholson (mnicholson) 2009-07-28 17:26:08

Please test with the patch I just uploaded (manager-redirect-cdr-fix1.diff) and let me know if it resolves this issue.
By: caspy (caspy) 2009-07-31 09:38:32

no, it does not.
with this patch, transfer action creates 4 (four) records in cdr log instead two. without patch these two records are created, but they contain incorrect values.
for this reason, in feature's blind_tranfer procedure swaping of cdrs is done.
By: Matthew Nicholson (mnicholson) 2009-07-31 09:44:18

Please describe how you are testing this patch.  Include the type of devices you are using (sip/zap/dahdi/iax), the call path (sip->asterisk->sip, sip->asterisk->zap), and the method you are using to transfer (# transfer, flash, sip blind/attended transfer).
By: caspy (caspy) 2009-07-31 09:54:52

All calls are sip calls from sip-devices via asterisk (canreinvite=no).

Here is a log for blind transfer done from device.
1340 calling to 1342, then 1342 blind_tranfering caller to 1341

"","1340","1342","fromoffice","1340 <1340>","SIP/1340-b691e618","SIP/1342-09e32ff8","Dial","SIP/1342,60,twTWL(5400000)","2009-07-31 16:04:51","2009-07-31 16:04:52","2009-07-31 16:04:57",6,5,"ANSWERED","DOCUMENTATION","1249041891.90747","int:1340:1342"
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b691e618","SIP/1341-09c5ef48","Dial","SIP/1341,60,twTWL(5400000)","2009-07-31 16:04:57","2009-07-31 16:05:01","2009-07-31 16:05:07",10,6,"ANSWERED","DOCUMENTATION","1249041891.90747","int:1340:1342"



Here you can see the same scenario, but transfer is done via AMI:

"","","s","fromoffice","","SIP/1342-09053cf8","","","","2009-07-30 10:15:42","2009-07-30 10:15:42","2009-07-30 10:15:59",17,17,"ANSWERED","DOCUMENTATION","1248934542.149608",""
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b6c9a258","SIP/1341-08e62f18","Dial","SIP/1341,60,twTWL(5400000)","2009-07-30 10:15:42","2009-07-30 10:16:02","2009-07-30 10:16:16",34,14,"ANSWERED","DOCUMENTATION","1248934542.149606","int:1340:1342"

you can see, that for the first record information is lost.

In first case information was saved cause a swapping of CDR's were done.
In second case - most of data were lost for initial call.



And here how log looks after patch (transfering via AMI):

"","","s","fromoffice","","SIP/1342-09c131c0","","","","2009-07-30 10:27:31","2009-07-30 10:27:32","2009-07-30 10:27:41",10,9,"ANSWERED","DOCUMENTATION","1248935251.358",""
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b6741c00","SIP/1341-09c26b20","Dial","SIP/1341,60,twTWL(5400000)","2009-07-30 10:27:41","2009-07-30 10:27:48","2009-07-30 10:27:54",13,6,"ANSWERED","DOCUMENTATION","1248935251.356",""
"","1340","1342","fromoffice","1340 <1340>","SIP/1340-b6741c00","SIP/1342-09c131c0","Monitor",",int-20090730-102731-1340-1342-1248935251-356,mX","2009-07-30 10:27:31","2009-07-30 10:27:32","2009-07-30 10:27:41",10,9,"ANSWERED","DOCUMENTATION","1248935251.356","int:1340:1342"
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b6741c00","SIP/1341-09c26b20","Monitor",",int-20090730-102731-1340-1342-1248935251-356,mX","2009-07-30 10:27:54",,"2009-07-30 10:27:54",0,0,"NO ANSWER","DOCUMENTATION","1248935251.356",""
By: Matthew Nicholson (mnicholson) 2009-07-31 10:05:21

Which version of asterisk are you testing with?
By: caspy (caspy) 2009-07-31 10:10:06

1.6.0.9
By: Matthew Nicholson (mnicholson) 2009-07-31 10:11:36

Please re-do your test with the 1.4 svn branch and post your results.


By: Jay Reeder (escape2mtns) 2009-08-11 21:30:28

We're wrestling with the same issue and were pleased to find this patch.  I've installed on 1.4.25.1 and it appears to work as designed.  We will know more tomorrow after a higher call volume has been put through the system.

In our case we have a call center app that agents use to place the inbound call on hold using AMI to redirect the channel to a music on hold context, make an outbound call with AMI's originate, and then redirect the inbound/outbound legs to a meetme conference to patch the call.

The only curiosity noticed so far is when redirecting that answered call to the music on hold context (for example) the disposition for that next leg of the call shows as "FAILED" even though the first CDR item had a disposition of "ANSWERED".  In the limited testing I've done, it looks like all associated records after that first one show a "FAILED" disposition.
By: Jay Reeder (escape2mtns) 2009-08-12 10:19:50

Example of cdrs when using AMI redirect with this patch.  The caller #is replaced with 1111111111 and the DID number is replaced with 2222222222 and the extension in queue 777 that took the call was 170.  The outbound number that the inbound call is ultimately connected to is replaced with 3333333333.

In this example an inbound call from 1111111111 to DID 2222222222 was routed to queue 777 and delivered to static  member sip/170.  The operator at sip/170 answers the call and uses the call center app to place the call on hold.  When this happens, an AMI redirect sends both channels (caller and agent) to a music on hold context.  The agent then dials an outside party using the call center app ... which results in an AMI originate to the outside number from a temp meetmeroom accessed using context qvcallpickup.  Meanwhile, the operator is placed in this same room using a redirect through context qvpickup.  When the outbound call is answered the operator patches the outbound caller with the original inbound channel with an AMI redirect of both the inbound channel and the outbound channel to a meetme through context qvmeetme.  The operator channel is disconnected.

Note that we use the inbound channel's uniqueid as the unique meetme conf #.

From what I can figure out.  The 1st two CDR's represent the extension that receives that call from queue and is at first put on hold with the caller.  It's odd that both have a disposition of "NO ANSWER"

The next two CDRs represent the inbound call from queue and it being first put on hold.  The first of these two events has the correct disposition "ANSWERED" but then the next one shows "FAILED".  The fourth cdr entry represents when the inbound channel is redirected from the extension who received the queue call to the music on hold context but for some reason shows details from the final redirect to a meetme conference (when the inbound call is bridged with the outbound call).

The fifth cdr is where we generate an outbound call from the meetme conference to the person we're transferring the call to (using Local channel) and the sixth cdr entry is the other side of that Local channel connecting to the meetme conference.

The seventh cdr is the channel of the original inbound call recipient being redirected to the meetme conference with the outbound call.

The last cdr entry is the original inbound channel being redirected from the music on hold context to the meetme conference with the outbound call.

"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield"
"2009-08-12 10:02:52";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b74281d0";"SIP/170-093ee708";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"6";"0";"NO ANSWER";"3";"2222222222";"1250085772.5027";
"2009-08-12 10:02:52";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b74281d0";"SIP/170-093ee708";"MusicOnHold";;"15";"0";"NO ANSWER";"3";"2222222222";"1250085772.5027";
"2009-08-12 10:02:52";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b74281d0";"SIP/170-093ee708";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"6";"6";"ANSWERED";"3";"2222222222";"1250085772.5026";
"2009-08-12 10:02:58";"\"CALLER NAME\" <1111111111>";"1111111111";"12500857725026";"qvmeetme";"SIP/SIP1-b74281d0";;"MeetMe";"12500857725026|1dFqx";"14";"0";"FAILED";"3";"2222222222";"1250085772.5026";
"2009-08-12 10:03:07";"2222222222";"2222222222";"3333333333";"from-internal";"Local/12500857725026@qvcallpickup-b2ee,1";"SIP/SIP1-09400980";"ResetCDR";"vw";"5";"3";"ANSWERED";"3";"2222222222";"1250085787.5029";"3"
"2009-08-12 10:03:07";"2222222222";"2222222222";"12500857725026";"qvcallpickup";"Local/12500857725026@qvcallpickup-b2ee,2";;"MeetMe";"12500857725026|1dFqx";"5";"5";"ANSWERED";"3";"2222222222";"1250085787.5030";
"2009-08-12 10:03:07";"\"CALLER NAME\" <1111111111>";"1111111111";"12500857725026";"qvpickup";"SIP/170-093ee708";;"MeetMe";"12500857725026|1dFqAx";"5";"0";"FAILED";"3";;"1250085778.5028";
"2009-08-12 10:03:12";"\"CALLER NAME\" <1111111111>";"1111111111";"12500857725026";"qvmeetme";"SIP/SIP1-b74281d0";;"MeetMe";"12500857725026|1dFqx";"7";"0";"FAILED";"3";"2222222222";"1250085772.5026";


The one part that I can't understand is ... when the original inbound channel is redirected to hold music and then redirected to the meetme conference (final patch with outbound call) ... the relevant cdr entries from this list are numbers 3,4, and 8 ... why does the first redirect to hold music (#4) use details from the final redirect to the meetme conference (# 8) when it should look like the agent phone that was also redirected to hold music (#2)?

I notice that the inbound call maintains it's uniqueid for the duration, even though it's redirected.  While the Agent phone gets a new uniqueid each time it's redirected (it may be that I'm seeing the local channels show up as new uniqueid's).


By: Jay Reeder (escape2mtns) 2009-08-12 12:19:17

One other question... would this patch negatively affect the ability to store values in the userfield?  It looks like I'm losing the cdr's userfield value.
By: Matthew Nicholson (mnicholson) 2009-08-13 12:17:51

Yes, this patch loses the uniqueid.  I can modify it so that it preserves the uniqueid.
By: Matthew Nicholson (mnicholson) 2009-08-13 13:19:52

Some of these errors in the CDR records may be caused by unrelated bugs in the way CDRs for originated calls are generated.
By: Matthew Nicholson (mnicholson) 2009-08-13 13:23:03

Test the new patch I uploaded (fix2.diff).  It should cause the userfield to be preserved.
By: Jay Reeder (escape2mtns) 2009-08-13 14:13:19

OK - I'll put it on when things get quieter this afternoon or evening.

One more question - after the redirect, all billsecs are 0.  How do we turn billsecs on after a redirect?
By: Matthew Nicholson (mnicholson) 2009-08-13 14:36:29

That is a tricky problem to solve.  The answer time value is reset during the redirect.  I actually think the behavior is correct the way it is currently implemented in the patch.  If there is a 'Dial' after the redirect, that will populate answer time and generate a proper value for billsec.  If there is no dial, answer time will not be filled in unless the 'Answer' application is called in the dialplan.  If answer time was populated during the redirect and then 'dial' was called, billsec would be incorrect because answer time would record when the redirect occurred, not when the new call was actually answered.

Both of these situations cannot be fixed within the current CDR framework.  CEL should not have this issue. It should also be possible to work around some of these limitations within your billing software.  We need to determine which one of these two behaviors is the optimal one and then document it and leave it at that.  Personally, I think the proper behavior is to not set answer time in the redirect to allow for 'Dial' to set the answer time later on.
By: Jay Reeder (escape2mtns) 2009-08-13 16:38:13

I understand.  In our case we're redirecting the channel to a hold music context and then a meetme room.  It would be 'application-appropriate' to enable billsecs while in the meetme room.  Can we call the Answer application in the dialplan just before entering the meetme room?  Will that give us the desired effect?
By: Matthew Nicholson (mnicholson) 2009-08-13 16:43:49

Yes that might work.  Although after looking at the code, I am not so sure.  It looks like the ast_answer, which is called by the Answer application, does not call ast_cdr_answer() unless the channel is in state AST_STATE_RINGING or AST_STATE_RING.  Calling ast_cdr_answer() multiple times on a cdr record should not cause any problems.  Test it out by calling Answer, if that does not work I will post another patch to fix that.
By: Jay Reeder (escape2mtns) 2009-08-13 16:58:14

It looks like I already had 'Answer' on each of these contexts....
By: Matthew Nicholson (mnicholson) 2009-08-13 17:01:35

Test with the patch I just uploaded (ast_answer-cdr-fix1.diff).
By: Jay Reeder (escape2mtns) 2009-08-13 20:41:33

After application of all patches, some things work and some still don't seem right but I have to study some more to make sure unrelated issues aren't clouding the picture.

This test is identical to the one above, with the exception that the queue 777 also rings SIP/111 (but it doesn't answer).  The records seemed out of order so I sorted them by calldate before exporting from MySQL.

Roughly 23 seconds after answering the call I put the caller and agent on "hold" (redirect to music on hold context).  I left that until around 34 seconds into the call when the agent was placed in a meetme (qvpickup) with the originated outbound call (qvcallpickup).  40 seconds into the call the original inbound channel was redirected into the meetme with the outbound call and the agent was disconnected.

Notes/Points of concern:
* Item #2 is one I can't explain

1) The second cdr entry is the event where the call is answered by extension 170 and the 3rd entry is when that extension goes to "hold" with the inbound caller.
 
2) The 4th cdr entry is the inbound call being answered but it's duplicated entirely in the 5th cdr entry.

3) The outbound call sent originated to 3333333333@from-internal from Local/<meetme #>@qvcallpickup shows a duration of 8 seconds when that channel was in the meetme for 30+ seconds.  I might know what's causing this though.  We originate from the meetme but then when we patch the inbound caller with the outbound call, we do another redirect for both the inbound channel and the outbound channel into the same meetme (this was done so we don't have to check logic on who was in the meetme beforehand.. the agent could have had either leg on hold and be speaking with the other when the patch command was sent).  The 8 seconds does correlate with the duration of the originate before that leg is redirected back to the same meetme conference.

"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield";"agent"
"2009-08-13 20:07:09";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7610870";"SIP/111-09f531d8";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"2";"0";"NO ANSWER";"3";"2222222222";"1250208429.589";;
"2009-08-13 20:07:09";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7610870";"SIP/170-09e798f0";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"24";"0";"NO ANSWER";"3";"2222222222";"1250208429.588";;
"2009-08-13 20:07:09";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7610870";"SIP/170-09e798f0";"MusicOnHold";;"33";"0";"NO ANSWER";"3";"2222222222";"1250208429.588";;
"2009-08-13 20:07:09";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7610870";"SIP/170-09e798f0";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"24";"24";"ANSWERED";"3";"2222222222";"1250208429.587";;
"2009-08-13 20:07:09";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7610870";"SIP/170-09e798f0";"Queue";"777|tr||custom/Txfr-From-Auto-Att";"24";"24";"ANSWERED";"3";"2222222222";"1250208429.587";;
"2009-08-13 20:07:33";"\"CALLER NAME \" <1111111111>";"1111111111";"1250208429587";"qvmeetme";"SIP/SIP1-b7610870";"SIP/170-09e798f0";"MeetMe";"1250208429587|1dFqAx";"17";"17";"ANSWERED";"2";"2222222222";"1250208429.587";;
"2009-08-13 20:07:42";"2222222222";"2222222222";"3333333333";"from-internal";"Local/1250208429587@qvcallpickup-e2b9,1";"SIP/SIP1-09f03ed0";"ResetCDR";"vw";"8";"6";"ANSWERED";"3";"2222222222";"1250208462.591";"3";
"2009-08-13 20:07:42";"\"CALLER NAME \" <1111111111>";"1111111111";"1250208429587";"qvpickup";"SIP/170-09e798f0";"SIP/170-09e798f0";"MeetMe";"1250208429587|1dFqAx";"8";"0";"FAILED";"2";;"1250208453.590";;
"2009-08-13 20:07:42";"2222222222";"2222222222";"1250208429587";"qvcallpickup";"Local/1250208429587@qvcallpickup-e2b9,2";;"MeetMe";"1250208429587|1dFqx";"8";"8";"ANSWERED";"3";"2222222222";"1250208462.592";;
By: Matthew Nicholson (mnicholson) 2009-08-14 12:48:58

Is it possible for you to construct a minimal test case to just test the redirection portions of this test?  I am going to try to build a test bed here as well.
By: Jay Reeder (escape2mtns) 2009-08-14 16:13:02

Sort of... I could have an inbound route that rings directly to my extension and then test what happens when I put the calls on hold.

Separately I could place an outbound call and put it on hold.

Let me see what I can come up with.
By: Jay Reeder (escape2mtns) 2009-08-16 18:27:24

OK, I just upgraded to the latest 1.4.26.1 (prev. on 1.4.25.1) and applied the patches to test against the latest.

I called from 1111111111 into DID 2222222222 that routes to queue 777.  The call was answered by Sip/172.  Then I did a manager redirect to send both the inbound channel and the call recipient channel to a music on hold context.  

The inbound channel looks pretty good.

The call recipient channel that was sent to music on hold didn't get a cdr entry (which isn't a huge deal for me but might be for others).


"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield";"agent"
"2009-08-16 19:03:20";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7700b48";"SIP/172-08fbb7a0";"Queue";"777|tr||";"18";"18";"ANSWERED";"3";"2222222222";"1250463800.49";;
"2009-08-16 19:03:38";"\"CALLER NAME\" <1111111111>";"1111111111";"172";"qvmusiconhold";"SIP/SIP1-b7700b48";"SIP/172-08fbb7a0";"MusicOnHold";;"18";"18";"ANSWERED";"3";"2222222222";"1250463800.49";;


By: Jay Reeder (escape2mtns) 2009-08-16 18:58:23

I just ran the more complicated scenario - the one we're using - and I think I might have figured out the issue with duplicate CDR records.

Just like the last test, I called from 1111111111 into DID 2222222222 that routes to queue 777. The call was answered by Sip/172. Then I did a manager redirect to send both the inbound channel and the call recipient channel to a music on hold context.

The channel for Sip/172 that had received the call was redirected from the MOH context to a meetme room.

An outbound call to 3333333333 was originated from that same meetme room.

I then redirected the original inbound call channel from MOH to the meetme room and the original call recipient dropped off.

This is a manager-controlled supervised transfer.

I think what's going on is that when the inbound call channel is redirected to the MOH context it forks the original cdr entry but the new action (MOH context) doesn't generate a CDR event.  So when it is subsequently redirected to the Meetme room, we're duplicating based on the original 'call received from queue' cdr record and therefore duplicating the original event.


"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield";"agent"
"2009-08-16 19:27:23";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b774cea8";"SIP/172-08fb9cd8";"Queue";"777|tr||";"20";"20";"ANSWERED";"3";"2222222222";"1250465243.226";"3";
"2009-08-16 19:27:23";"\"CALLER NAME\" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b774cea8";"SIP/172-08fb9cd8";"Queue";"777|tr||";"20";"20";"ANSWERED";"3";"2222222222";"1250465243.226";"3";
"2009-08-16 19:27:43";"\"CALLER NAME\" <1111111111>";"1111111111";"1250465243226";"qvmeetme";"SIP/SIP1-b774cea8";"SIP/172-08fb9cd8";"MeetMe";"1250465243226|1dFqAx";"17";"17";"ANSWERED";"2";"2222222222";"1250465243.226";"3";
"2009-08-16 19:27:56";"\"CALLER NAME\" <1111111111>";"1111111111";"1250465243226";"qvpickup";"SIP/172-08fb9cd8";"SIP/172-08fb9cd8";"MeetMe";"1250465243226|1dFqAx";"5";"0";"FAILED";"2";;"1250465263.230";"3";
"2009-08-16 19:27:57";"2222222222";"2222222222";"3333333333";"from-internal";"Local/1250465243226@qvcallpickup-808d,1";"SIP/SIP1-08fbb7a0";"ResetCDR";"vw";"3";"2";"ANSWERED";"3";"2222222222";"1250465277.231";"3";
"2009-08-16 19:27:57";"2222222222";"2222222222";"1250465243226";"qvcallpickup";"Local/1250465243226@qvcallpickup-808d,2";;"MeetMe";"1250465243226|1dFqx";"3";"3";"ANSWERED";"3";"2222222222";"1250465277.232";;
By: Jay Reeder (escape2mtns) 2009-08-17 11:39:26

There were positive effects in each of the two patches.  Maybe we need a combination of the two.

Should this line (dropped from the 2nd patch) be put back in:

                       ast_cdr_start(cdr);

I can't do any more testing until things die down a bit.


By: Matthew Nicholson (mnicholson) 2009-08-17 11:45:38

ast_cdr_reset() function calls ast_cdr_start().
By: Jay Reeder (escape2mtns) 2009-08-17 11:57:45

gotcha... it looks like an ast_cdr_update just before the ast_cdr_dup might fix the issue of duplicate cdrs caused by a double redirect... first to a music on hold context and second to a meetme room.  Would that work?
By: Matthew Nicholson (mnicholson) 2009-08-17 12:00:05

I am not sure.  I have not set up this scenario in my lab yet.  I plan to do it later today, although it may get pushed back to tomorrow.
By: Jay Reeder (escape2mtns) 2009-08-17 21:13:47

The ast_cdr_update didn't fix the duplicate cdrs caused by the double redirect.  I just tried that and got the following cdr's.

In this test I did a supervised transfer where the inbound caller was received by the agent from queue 777 right away and after 25 seconds both the inbound caller and the agent were redirected to hold.

After another 30 seconds or so (1 minute into the call) the agent was redirected to a meetme room and the outbound call was originated from that room .

After another 30 seconds or so (1:30 into the call) the original inbound call was redirected from hold music to the meetme room and the agent dropped off.

That meetme conference continued for another 1:30 before both legs disconnected.

"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield";"agent";"queue_duration"
"2009-08-17 21:41:00";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7600468";"SIP/172-085e2538";"AGI";"VERBOSE";"23";"23";"ANSWERED";"3";"2222222222";"1250559660.16";"3";"172";"1"
"2009-08-17 21:41:00";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7600468";"SIP/172-085e2538";"AGI";"VERBOSE";"23";"23";"ANSWERED";"3";"2222222222";"1250559660.16";"3";"172";"1"
"2009-08-17 21:41:23";"\"CALLER NAME \" <1111111111>";"1111111111";"125055966016";"qvmeetme";"SIP/SIP1-b7600468";"SIP/172-085e2538";"MeetMe";"125055966016|1dFqAx";"67";"67";"ANSWERED";"2";"2222222222";"1250559660.16";"3";;"0"
"2009-08-17 21:41:59";"\"CALLER NAME \" <1111111111>";"1111111111";"125055966016";"qvpickup";"SIP/172-085e2538";"SIP/172-085e2538";"MeetMe";"125055966016|1dFqAx";"32";"0";"FAILED";"2";;"1250559683.20";"3";;"0"
"2009-08-17 21:42:00";"2222222222";"2222222222";"3333333333";"from-internal";"Local/125055966016@qvcallpickup-5ea9,1";"SIP/SIP1-085fa2b0";"ResetCDR";"vw";"30";"28";"ANSWERED";"3";"2222222222";"1250559720.21";"3";"172";"0"
"2009-08-17 21:42:00";"2222222222";"2222222222";"125055966016";"qvcallpickup";"Local/125055966016@qvcallpickup-5ea9,2";;"MeetMe";"125055966016|1dFqx";"30";"30";"ANSWERED";"3";"2222222222";"1250559720.22";;"172";"0"

* In these cdrs the 'last application' for the first queue event is now AGI because we're now passing the Queue command a connect-time agi script to run.

The double CDR entry for the first inbound call is still there.  It would almost make sense if the uniqueid was different for the 2 events because each could represent the two channels of that first inbound call (that are both redirected to a hold music context).
By: Matthew Nicholson (mnicholson) 2009-08-18 13:49:43

I just ran the same test you did (redirecting both channels to MOH).  I am seeing missing CDR records.  Let me investigate this further.  I did not test redirecting both channels during my initial testing.
By: caspy (caspy) 2009-08-18 14:29:39

mnicholson,
you can also run my initial scenario. it is much more clear and easy.
By: Matthew Nicholson (mnicholson) 2009-08-18 14:31:25

I will set that up once I get the basic scenario working reasonably.  I think I have worked out what should happen, I just need to implement it.
By: Matthew Nicholson (mnicholson) 2009-08-19 14:22:56

I just uploaded the manager-redirect-cdr-fix3.diff patch.  This patch should work properly when redirecting two channels.  Please test it and let me know if it works.  This patch is intended to be used with the app_answer-cdr-fix1.diff patch.
By: Jay Reeder (escape2mtns) 2009-08-19 22:36:14

That first redirect of both channels to hold music works beautifully!

But when I perform the last step of my attended transfer (using AMI) where two channels from separate calls are both redirected together (using redirect with extrachannel) into a meetme room, I get a Segmentation fault.  That's new.

I tried connecting an inbound call to the agent phone and redirecting both to hold music and then redirecting both of those back to a meetme (take off hold) and put back on hold and take off hold (redirects happening each time) and there was no issue... no matter how many times I did that.

I then tried placing two outbound calls where I place the first call and then it goes on hold via redirects... then I place a second call and try to bridge the two outbound channels together in a meetme room using redirect and I get the same Segmentation fault.  

Finally, I tried just placing an outbound call and putting it on hold with the redirects.  I got the segmentation fault right there. Without the patch it works functionally.  With the patch I get the segmentation fault.

So when I originate a call from SIP/172 to an outside number on context from-internal and then place both legs of that call on hold with a redirect to MOH, I get the segmentation fault.

/usr/sbin/safe_asterisk: line 125:  4296 Segmentation fault      (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} >&/dev/${TTY} < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.
Automatically restarting Asterisk.
mpg123: no process killed


By: Matthew Nicholson (mnicholson) 2009-08-20 09:09:25

I am going to try and reproduce this crash.  When you say "placing an outbound call" are you doing an originate from asterisk with the manager interface (or a call file)?
By: Jay Reeder (escape2mtns) 2009-08-20 09:59:52

In that context, I'm doing an AMI originate (no call files):

Channel: "SIP/172"
Context: "from-internal"
Exten: "3333333333"
Priority: "1"
Timeout: "15000"

Then I redirect the SIP/172 channel and the outbound SIP channel (on ours it's SIP/SIP1...) to hold music and I get the segmentation fault.
By: Matthew Nicholson (mnicholson) 2009-08-20 10:13:07

I tested this exact scenario and was not able to reproduce the crash.

My test is as follows:
Originate (from the cli) to sip/1, which then goes into the dialplan and dials sip/2
Wait 5 seconds after answer and redirect sip/1 and sip/2 to MOH (although moh is not working right on this system, I don't suspect that would cause a crash).

Please post a backtrace as described in doc/backtrace.txt.
By: Jay Reeder (escape2mtns) 2009-08-20 12:59:59

Will do.  It will be later tonight but I can do it.

Our commands are going over the AJAM (not that it should matter).  The outbound call goes out over a sip trunk to a landline (not that it should matter either).

I'll let you know how it goes....  I may even try your test and see how it works.

BTW, this server started life as AsteriskNOW 1.5 (now has upgraded Asterisk, etc) and would have the FreePBX dialplan setup.


By: Jay Reeder (escape2mtns) 2009-08-20 21:55:05

Tonight I put the patch back on, recompiled without optimizations, and when I placed the outbound call and put on hold and took off hold, it didn't crash.  But when I placed the second call and did the final redirect to patch the two outbound calls, it did.  I've attached the backtrace as backtrace1.txt

I then placed an inbound call, answered it and redirected both channels to hold, and then placed an outbound call and finally redirected the inbound channel and the outbound channel (both SIP/SIP1 channels) to a meetme room to patch them together and the crash occurred there too.  I've attached the backtrace as backtrace2.txt

In both cases, I'm taking the two channels from different calls and redirecting them with a single redirect call to a meetme room.  It works without the patch but crashes with it.


By: Matthew Nicholson (mnicholson) 2009-08-21 15:06:19

Test with the patch I just uploaded.  It should fix the problem.
By: Jay Reeder (escape2mtns) 2009-08-21 23:18:48

Thanks!  That last patch did the trick.  There were no crashes and the cdr's appear to be a much better representation of what occurred.  We'll do more testing next week but here's what I got from the test I ran:

Inbound call from 1111111111 to 22222222222 is routed to queue 777 and answered by sip/172.  

After 20 seconds both channels are redirected to music on hold.  

At 50 seconds, sip/172 is redirected to a meetme room and we originate an outbound call from that same meetme room.

At 60 seconds both the original inbound channel and the outbound channel are redirected to a meetme room as their calls are patched and sip/172 disconnects.

They stay patched for about a minute and 10 seconds or so.

"calldate";"clid";"src";"dst";"dcontext";"channel";"dstchannel";"lastapp";"lastdata";"duration";"billsec";"disposition";"amaflags";"accountcode";"uniqueid";"userfield";"agent";"queue_duration"
"2009-08-21 23:41:31";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7d47728";"SIP/172-09a0aa00";"AGI";"VERBOSE";"21";"21";"ANSWERED";"3";"2222222222";"1250912491.42";"3";"172";"2"
"2009-08-21 23:41:52";"\"CALLER NAME \" <1111111111>";"1111111111";"777";"from-internal";"SIP/172-09a0aa00";"SIP/172-09a0aa00";"MusicOnHold";;"30";"30";"ANSWERED";"3";;"1250912491.44";"3";;"0"
"2009-08-21 23:41:52";"\"SCHURKE ERIC K \" <1111111111>";"1111111111";"777";"ext-queues";"SIP/SIP1-b7d47728";"SIP/172-09a0aa00";"MusicOnHold";;"40";"40";"ANSWERED";"3";"2222222222";"1250912491.42";"3";;"0"
"2009-08-21 23:42:22";"2222222222";"2222222222";"3333333333";"from-internal";"Local/125091249142@qvcallpickup-ba5b,1";"SIP/SIP1-b7d6dc08";"ResetCDR";"vw";"10";"8";"ANSWERED";"3";"2222222222";"1250912542.63";"3";"172";"0"
"2009-08-21 23:42:22";"2222222222";"2222222222";"125091249142";"qvcallpickup";"Local/125091249142@qvcallpickup-ba5b,2";;"MeetMe";"125091249142|1dFqx";"10";"10";"ANSWERED";"3";"2222222222";"1250912542.64";;"172";"0"
"2009-08-21 23:42:22";;;"s";"default";"DAHDI/pseudo-56698133";;;;"11";"0";"NO ANSWER";"3";;"1250912542.65";;;"0"
"2009-08-21 23:42:22";"\"CALLER NAME \" <1111111111>";"1111111111";"125091249142";"qvpickup";"SIP/172-09a0aa00";"SIP/172-09a0aa00";"MeetMe";"125091249142|1dFqAx";"11";"11";"ANSWERED";"2";;"1250912512.46";"3";;"0"
"2009-08-21 23:42:32";"\"CALLER NAME \" <1111111111>";"1111111111";"125091249142";"qvmeetme";"SIP/SIP1-b7d47728";"SIP/172-09a0aa00";"MeetMe";"125091249142|1dFqAx";"70";"70";"ANSWERED";"2";"2222222222";"1250912491.42";"3";;"0"

For our application it's not a big deal but looking at that last cdr entry for the 70 second patch between the original inbound channel and the outbound channel, it looks like it's using the dstchannel from when the call first came in.  We'd have to do more testing to confirm...  It might also be missing the cdr for the other channel that was in that final conference.

Either way, this is so much better than where we were.  Thanks!


By: caspy (caspy) 2009-08-26 08:45:20

Effect of last patch (fix4) is rather strange. In my scenario (one call, and one direct transfer) it produces 3 (three!) records in CDR with fields filled incorrectly.

Scenario is the same:
1340 calls to 1342,
then 1340 is transfered to 1341 via AMI.


"","1340","1341","fromoffice","1340 <1340>","SIP/1340-08b5bd30","SIP/1341-08b12138","Dial","SIP/1341,60,twTWL(5400000)","2009-08-26 14:59:21","2009-08-26 14:59:25","2009-08-26 14:59:36",15,11,"ANSWERED","DOCUMENTATION","1251284279.35433","int:1340:1342"
"","1340","1342","fromoffice","1340 <1340>","SIP/1340-08b5bd30","SIP/1342-08adc4c8","Monitor",",rec-20090826-145759-1340-1342,mX","2009-08-26 14:57:59","2009-08-26 14:57:59","2009-08-26 14:59:21",82,82,"ANSWERED","DOCUMENTATION","1251284279.35433","int:1340:1342"
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-08b5bd30","SIP/1341-08b12138","Monitor",",rec-20090826-145759-1340-1342,mX","2009-08-26 14:59:36",,"2009-08-26 14:59:36",0,0,"NO ANSWER","DOCUMENTATION","1251284279.35433","int:1340:1342"


in first part of comment 0108465 is correct CDR for this scenario, where transfer done from device.
By: Matthew Nicholson (mnicholson) 2009-08-26 13:57:28

caspy,

What happens to 1341 when 1340 is transfered?
By: caspy (caspy) 2009-08-26 14:05:22

1341 starts to ring, and then answered.

a real situation is:
- client call to company number and is picked up by first-line-support/callcenter engineer,
- callcenter's man simply (blind-)transfering call any another department.
By: Matthew Nicholson (mnicholson) 2009-08-26 14:10:58

I'll test this senario in my lab and see what I come up with. You should only be seeing two CDR records in that senario.
By: Matthew Nicholson (mnicholson) 2009-09-03 17:03:35

Ok, I could not reproduce the bug using your scenario, but I was able to reproduce your issue.

My testing:
- client call to company number.  Call picked up by support.
- redirect support to another department.

If I redirect the caller to another department, everything works fine.  I'll work on fixing this.
By: Matthew Nicholson (mnicholson) 2009-09-03 17:23:44

caspy,

The latest patch (fix5) should fix the duplicate CDR issue.
By: Matthew Nicholson (mnicholson) 2009-09-03 17:41:34

fix5 causes a regression from fix4.  Working on a fix.
By: Matthew Nicholson (mnicholson) 2009-09-04 10:52:34

caspy,

It looks like I am using the method you described to reproduce the problem.  I was mistaken.  Still working on a fix.
By: Matthew Nicholson (mnicholson) 2009-09-04 15:52:14

Ok.  I just uploaded manager-redirect-cdr-fix6.diff.  Please test it.
By: caspy (caspy) 2009-09-08 06:46:53

seems to be the same:

"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b5a46878","SIP/1341-0a399d98","Dial","SIP/1341,60,twTWL(5400000)","2009-09-08 15:32:21","2009-09-08 15:32:23","2009-09-08 15:32:41",20,18,"ANSWERED","DOCUMENTATION","1252409517.154205","int:1340:1342"
"","1340","1342","fromoffice","1340 <1340>","SIP/1340-b5a46878","SIP/1342-0a46cbb8","Monitor",",int-20090908-153157-1340-1342-1252409517-154205,mX","2009-09-08 15:31:57","2009-09-08 15:31:58","2009-09-08 15:32:21",24,23,"ANSWERED","DOCUMENTATION","1252409517.154205","int:1340:1342"
"","1340","1341","fromoffice","1340 <1340>","SIP/1340-b5a46878","SIP/1341-0a399d98","Monitor",",int-20090908-153157-1340-1342-1252409517-154205,mX","2009-09-08 15:32:41",,"2009-09-08 15:32:41",0,0,"NO ANSWER","DOCUMENTATION","1252409517.154205","int:1340:1342"
By: Matthew Nicholson (mnicholson) 2009-09-08 10:08:28

caspy,

What version of asterisk are you testing with?
By: caspy (caspy) 2009-09-08 10:10:15

1.6.0.9
By: Matthew Nicholson (mnicholson) 2009-09-08 11:36:55

Ok.  I am using 1.4 SVN.  I'll test this with 1.6. I suspect that is the problem.
By: caspy (caspy) 2009-09-22 02:37:19

mnicholson,
any news about 1.6? can i help anything more?
By: Matthew Nicholson (mnicholson) 2009-09-22 08:24:26

Nothing new, some higher priority items have taken precedence on my todo list.
By: Daniel Stefanus (shinichi85) 2009-11-10 04:06:23.000-0600

Is there a way to solve the same problem on Asterisk 1.4.26.2? Really get stuck on here. Please help. Thank you very much.
By: Jay Reeder (escape2mtns) 2010-01-20 13:01:33.000-0600

Report after ~5 months of usage:

app_answer-cdr-fix1.diff with manager-redirect-cdr-fix4.diff has worked great for us since the update was posted.  We have the ability to know what happens on redirected calls and bill for each leg of the call.  Our billing and call review systems were written around this solution and are working perfectly.  We're on 1.4.26.1 (latest when posted) and probably won't upgrade until a perm solution is in place.

Thanks again!
By: Matthew Nicholson (mnicholson) 2010-01-21 11:51:38.000-0600

This issue is not ready for review, the patches here only work for asterisk 1.4.  Asterisk 1.6 still has this problem.
By: Leif Madsen (lmadsen) 2010-01-21 14:44:44.000-0600

Oops, I see that now :)
By: Russell Bryant (russell) 2011-07-26 15:11:25.977-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

If this is still an issue, please open a new issue so it can be re-triaged appropriately. Thanks!