Summary:	ASTERISK-08000: [branch] Error in CDRs involving bridges and Local/ channels (call files)
Reporter:	flot (flot)	Labels:
Date Opened:	2006-10-25 04:15:38	Date Closed:	2007-03-30 10:07:48
Priority:	Minor	Regression?	No
Status:	Closed/Complete	Components:	Core/General
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) app_dial_noaswer_bug.diff
Description:	Some calls in cdr have status 'NO ANSWER' though they are definitly  'ANSWER'. :( Extracts from extension.conf [local] exten =100,1,goto(callback-menu,100,1) exten =103,1,Dial(sip/...) exten =101,1,Dial(sip/...) [callback-menu] exten => _X.,1,Answer exten => _X.,2,Wait(1) exten => _X.,3,Set(TIMEOUT(digit)=5) exten => _X.,4,Set(TIMEOUT(response)=30) exten => _X.,5,DISA,no-password|callback-dialout [callback-dialout] include => msk exten => _X.,102,noop exten => _X.,n,Answer exten => _X.,n,Playback(rus/busy) exten => _X.,n,Goto(callback-menu,100,2) exten => i,1,Answer exten => i,2,Playback(rus/incorrect) exten => i,3,Goto(callback-menu,100,2) [msk] include => local Dial 100 from tel. 100 and then dial 103. Answer the call from 103. View CDR: ""flot" <flot-phone>","flot-phone","100","callback-menu","SIP/flot-phone-b610bcc8","","DISA","no-password|callback-dialout","2006-10-24 16:26:27","2006-10-24 16:26:27","2006-10-24 16:26:35","8","8","ANSWERED","DOCUMENTATION","","1161692787.139","" ""flot" <flot-phone>","flot-phone","103","callback-dialout","SIP/flot-phone-b610bcc8","SIP/flot-08214170","Dial","SIP/flot||Tto","2006-10-24 16:26:35","2006-10-24 16:26:41","2006-10-24 16:26:46","11","5","ANSWERED","DOCUMENTATION","","1161692787.139","" Now everything's ok. Now access call file Channel: Local/101@local Callerid: 100 Context: callback-menu Extension: 100 MaxRetries: 4 Retrytime: 10 WaitTime: 10 Priority: 1 Tel.101 receives a call. We pick up the phone and dial 103 and answer the call at tel. 103. "100","100","101","local","Local/101@local-ca09,2","SIP/flot-phone-08214170","Dial","SIP/flot-phone|10|Tt","2006-10-24 16:27:05","2006-10-24 16:27:06","2006-10-24 16:27:06","1","0","ANSWERED","DOCUMENTATION","","1161692825.142","" "100","100","100","callback-menu","Local/101@local-ca09,1","","DISA","no-password|callback-dialout","2006-10-24 16:27:06","","2006-10-24 16:27:14","8","0","ANSWERED","DOCUMENTATION","","1161692825.141","" "100","100","103","callback-dialout","Local/101@local-ca09,1","SIP/flot-082180b0","Dial","SIP/flot||Tto","2006-10-24 16:27:14","","2006-10-24 16:27:23","9","0","NO ANSWER","DOCUMENTATION","","1161692825.141","" All three entries are not correct. Even though for the first one the status is ANSWERED, call duration is 0. Same thing with the second. The third one is 'NO ANSWER' whereas it must by ANSWERED.
Comments:	By: Steve Murphy (murf) 2006-11-18 06:53:13.000-0600 Question:  This **JUST** hit me: I see the 'bad' cdrs involve SIP devices. If you set call_limit on those devices to some non-zero number, does this problem go away? By: flot (flot) 2006-11-20 04:23:53.000-0600 The problem concerns not only SIP channels. Setting up of "call-limit" doesn't change anything. The same problem with the version SVN  trunk (I am testing it  now) By: Steve Murphy (murf) 2006-11-20 12:32:24.000-0600 OK, I'll try to reproduce this... I see you use a callfile with a Local/ channel. What happens if you say: Channel: Local/101@local/n in your callfile? Any difference. Hopefully, I have the first part reproduced, where there's no problem, but because of the call file, and my dialplan being a little different, I have to play with the callfile a bit. By: Steve Murphy (murf) 2006-11-20 14:40:55.000-0600 Ah-hah! I think I have it now. I get the same results. But... Some of it I can explain, I think: 1. The first cdr is posted the moment you pick up the ringing phone. It has a zero  duration because the moment you pick up the phone, that leg of the call is finished. The ring time is the only significant number. 2. The second cdr is posted the moment the other extension starts ringing, which is the moment the DISA triggers the Dial to the other extension. It posted a start and end time, but no answer time, as theoretically, no-one had any opportunity to answer this leg of the call. It got handed to Dial.  Since no post-answer time is accumulated, it's correctly reporting 0. It took 8 seconds from the time you picked up your ringing extension, to the time you dialed 103, and DISA fired the DIAL. What is incorrect with the second cdr post is that it bears the "ANSWER". That call was never answered. 3. The final leg follows the DISA commanded DIAL. It also has no "ANSWER" timestamp, and has the NO_ANSWER disposition. This is clearly not correct. However, the end-time appears to be reasonable. 9 seconds after the phone rang, you hung up. NOW, if I add a "/n" to the end of the Local/ spec in the call file, as in: Channel: Local/150@income1/n Then, I get output that looks like this: "150","150","100","callbackmenu","Local/150@income1-050e,1","","DISA","no-password|callbackdialout","2006-11-20 13:02:19","","2006-11-20 13:02:32","13","0","ANSWERED","DOCUMENTATION","","1164052931.37","" "150","150","100","callbackdialout","Local/150@income1-050e,1","Zap/51-1","Dial","Zap/51|20|w","2006-11-20 13:02:32","","2006-11-20 13:03:37","65","0","NO ANSWER","DOCUMENTATION","","1164052931.37","" "150","150","150","income1","Local/150@income1-050e,2","Zap/50-1","Dial","Zap/50|20|m","2006-11-20 13:02:11","2006-11-20 13:02:19","2006-11-20 13:03:37","86","78","ANSWERED","DOCUMENTATION","","1164052931.38","" To me, the above is a subtle mix of times. I've sorted it out into the following: 1. at 13:02:11, the call file is submitted into the queue, and the first dial is executed, and the first phone starts ringing. 2. at 13:02:19, the user picked up that ringing phone. At this very moment, the   DISA app was executed. 3. the user took some time to dial in the "103" or whatever. 4. at 13:02:32, the user finished pressing keys, and DISA app initiated the Dial to the last extension (Zap/51 in my case). The second phone starts ringing at this point in time. 5. at some unspecified moment (not recorded in the cdrs), the user picks up the second ringing phone, and the second dial cmd bridges the two together. 6. at 13:03:37, one or both ends of the bridged channel hang/hung up. The call is terminated, and two dial cdr's are posted. So, it looks like the bug is that the second dial command, initiated at 13:02:32, has no ANSWER posted to the CDR mechanism. I shall investigate. By: Steve Murphy (murf) 2006-11-23 20:50:01.000-0600 OK, I think I'm **close** to having a handle on this. I have code in place that generates these CDRs: "150","150","s","income1","Local/150@income1-b376,1","","DISA","no-password|callbackdialout","2006-11-23 19:09:16","2006-11-23 19:09:16","2006-11-23 19:09:25","9","9","ANSWERED","DOCUMENTATION","","1164334153.0","" "150","150","103","callbackdialout","Local/150@income1-b376,1","Zap/51-1","Dial","Zap/51|20|w","2006-11-23 19:09:25","2006-11-23 19:09:29","2006-11-23 19:09:39","14","10","ANSWERED","DOCUMENTATION","","1164334153.0","" "150","150","150","income1","Local/150@income1-b376,2","Zap/50-1","Dial","Zap/50|20|m","2006-11-23 19:09:13","2006-11-23 19:09:16","2006-11-23 19:09:39","26","23","ANSWERED","DOCUMENTATION","","1164334153.1","" All 3 are marked "ANSWERED", and all 3 are truthful. All 3 have the correct answer times, and all 3 have correct start and end times. But the implementation was a bit 'intrusive', and may cause extraneous CDRs to be generated. I can handle these on a case by case basis. Initial testing doesn't show that they are, but in my heart, I know that they are possible. The trouble: right now, a CDR is attached to usually only one of the two channels involved in a bridge (ast_bridge_call). In this case, because there's no CDR attached to the channels involved in the extensions being used, the ANSWER updates are thrown away. And, of course, the two Local/ channels have the CDR's, and where back-to-back to events take place, the CDR updates are folded over each other, and it gets grim, especially when two Bridges are formed in parallel, and overlap. To solve the lack of answer data, I include code to attach CDR's to channels that are getting ANSWER events, but have no cdr to record them in. I then added code in the bridging routines to create a CDR stored in the bridge itself. The bridging code pulls the data out of the channel CDRs and then destroys the channel CDR's as it finishes, and it posts the CDR it built instead. In most cases, where an ANSWER event is generated, a bridge is involved, which will clean out the extra CDR's that might be generated. It is possible that apps that make a phone ring, but don't use Dial (bridging) to do it, could generate extra nonsense CDRs. If you see one, report it, and I'll see if I can generically stop all such nonsense. I need testers. I have created two branches: one for 1.4 and one for trunk. http://svn.digium.com/svn/asterisk/team/murf/bug8221    (trunk) http://svn.digium.com/svn/asterisk/team/murf/bug8221-1.4   (1.4) It's not polished code yet. Contains a small boatload of debug messages. If you have a problem, send me the logs. When things calm down, I'll generate a 'clean' branch, with no debug messages in it. By: Steve Murphy (murf) 2006-11-23 21:02:53.000-0600 Give me some feedback. By: John Martin (jfp_martin) 2006-11-25 17:43:47.000-0600 Murf,  bear with me for a while... I've been having some problems with cdrs in CLI and manager originates, both extension and application versions. The extension version also using Local channels. I'd been digging into the code for the last day or so when I noticed this bug report.  My problem was that the answer cdr entry was always zero. So I put some debug into my 1.4svn code base and could see the problem being that ast_pbx_outgoing_app/exten calls ast_request_and_dial() _then_ creates a CDR.  Now ast_request_and_dial calls ast_request() then ast_call(), and for a SIP channel ast_call will result in an answered call _before_ ast_call returns, at least thats how it looked to me. So there is a call to ast_cdr_answer before ast_pbx_outgoing_app/exten has had a chance to create the cdr.  I fixed this by adding: if (!chan->cdr) { chan->cdr=ast_cdr_alloc(); ast_cdr_init(chan->cdr, chan);  /* initilize our channel's cdr */ ast_cdr_start(chan->cdr); } in between ast_request and ast_call code in ast_request_and_dial. I also tried your 1.4 patch to see if this might fix my problem, but it didn't. I know the original issue was to do with NOANSWER but there's also an implicit requirement to fix the zero answer field in the cdr. If you feel I'm onto a different problem then I'll create a new bug, but it seemed to be relevant enough to this bug to warrant my not keeping quiet. John By: Steve Murphy (murf) 2006-11-25 23:17:07.000-0600 John-- This is interesting. I think these problems could easily be related. My changes will always make sure that a call to ast_cdr_answer will always have a non-null arg. I thought I covered all possibilities. Let me review the ramifications of what you had done. Also, I need to recreate the same steps you see when you see the problem. Tell me exactly what sequence of steps are executed, any relevent dialplan entries, etc. If I can reproduce the problem here, believe me, the debug will go a lot quicker. By: John Martin (jfp_martin) 2006-11-26 02:35:32.000-0600 Hi Murf,  I can recreate the problem from the command line on any SIP extension, i.e.: CLI> originate SIP/1000 application echo The zero answer field can be seen in a csv that supports answer. I'll check a few more scenarios later today.  I should also mention that even though the echo example I just gave is trivial and not very likely to be used a great deal, I see the same issues bringing extensions in to conferences, with more complex dialplans, and which are key to applications we use. John By: Steve Murphy (murf) 2006-11-27 07:05:39.000-0600 John-- With my patch in place, I get the following CDR for a CLI originate, as you described: "","","s","extension","Zap/50-1","","Echo","","2006-11-26 13:49:17","2006-11-26 13:49:17","2006-11-26 13:49:51","34","34","ANSWERED","DOCUMENTATION","","1164574153.0","" The CDR was started the moment the phone was picked up (the ANSWER is what triggered the existence of the CDR), so you'll never know how long it rang before answering. Besides that, everything's working... So, perhaps you made an error in building/installing/running and weren't really running my patched version? By: John Martin (jfp_martin) 2006-11-27 14:46:45.000-0600 Hi Murf,  I checked my test of your patch1.4 and I do see the answer field as non zero, but having the start field set to the answer field doesn't get us much further.  I also checked your patch against a common call flow we use... H.323 -> IVR -> Queue -> SIP/Agent -> Conference (via Manager generated Redirect of both channels) -> Manager Originate to bring in 3rd caller. This would normally generate 4 CDRs and a QueueLog entry. With your patch some of the start and answer times were inconsistent and the H.323 call's end time  became the point at which it got connected to the Agent and not when it got hung up.  I can provide the CDRs if it will help, but this call flow is obviously quite difficult to debug... I'm also trying to figure out how to make this work for me.  Let me know if there's anything I can do. John By: Steve Murphy (murf) 2006-11-27 20:22:42.000-0600 John, I've implemented the fix you suggested, in request_and_dial, between the request and call, setting the cdr; and it isn't even called when you use the originate CLI command. Exactly in what situation did this addition solve a problem? As to your 4-legged CDR, please include some more info, as to how I can reproduce the problem, and the 4 cdr's you get, and what fields are wrong, so I can calculate a solution. By: Steve Murphy (murf) 2006-11-28 09:00:46.000-0600 John-- My apologies! I added that code to the wrong file!!! (I've got too many "brands in the fire", I guess. Anyway, I got that code inserted in the correct channel.c, and viola! it does help with the DISA in the 3-legged test, and in the originate case from the CLI. Sorry about that! So, I'll make this a part of the fix; Now, for the 4-legged case. I'll commit the change to the 8221-1.4 branch, and make sure it's updated. Try using these changes on your 4-legged (H.323 -> IVR -> Queue -> SIP/Agent -> Conference (via Manager generated Redirect of both channels) -> Manager Originate to bring in 3rd caller) case. By: John Martin (jfp_martin) 2006-11-28 09:09:10.000-0600 Thanks Murf, I'll try your updated branch later... I was starting to worry about my suggested patch, I couldn't see how it wouldn't fire where I'd suggested it was put... hey ho! I'm looking into why cdr->start and cdr->answer always seem to get set to cdr->start when handing calls off to other apps/transfer/conf etc. I think there's a problem with Masquerading ignoring cdrs but whenever I try to masquerade the CDR too I get a stale CDR at call tear down and a therefore a seg fault. I'll let you know if I get anywhere. John By: Steve Murphy (murf) 2006-11-28 11:39:26.000-0600 I can easily imagine coredumps if you copy the cdr pointers. When a cdr is posted, it's freed also. So, copy the pointer, and you'll be freeing something twice. I've been cdr_alloc()'ing and using a cdr_merge() call to do 2->1 mappings in the dial() stuff. By: John Martin (jfp_martin) 2006-12-01 06:36:20.000-0600 Hi Murf,  I tried you modified 8221 1.4 patch with the following results... You can see that the events I would expect to be tracked are getting overwritten. For instance the H.323 call should really end around 12:20:05 not 12:19:31. All the other CDRs are not really tracking real events either. John CREATE TABLE `cdr` (  `calldate` datetime NOT NULL default '0000-00-00 00:00:00',  `answerdate` datetime NOT NULL default '0000-00-00 00:00:00',  `enddate` datetime NOT NULL default '0000-00-00 00:00:00',  `clid` varchar(80) NOT NULL default '',  `src` varchar(80) NOT NULL default '',  `dst` varchar(80) NOT NULL default '',  `dcontext` varchar(80) NOT NULL default '',  `channel` varchar(80) NOT NULL default '',  `dstchannel` varchar(80) NOT NULL default '',  `lastapp` varchar(80) NOT NULL default '',  `lastdata` varchar(80) NOT NULL default '',  `duration` int(11) NOT NULL default '0',  `billsec` int(11) NOT NULL default '0',  `disposition` varchar(45) NOT NULL default '',  `amaflags` int(11) NOT NULL default '0',  `accountcode` varchar(20) NOT NULL default '',  `uniqueid` varchar(32) NOT NULL default '',  `userfield` varchar(255) NOT NULL default '' ) ENGINE=MyISAM DEFAULT CHARSET=latin1; 1: '2006-12-01 12:19:00', '2006-12-01 12:19:00', '2006-12-01 12:19:31', '"Tandberg-00814122" <aa.bb.cc.dd>', 'aa.bb.cc.dd', '1', 'ext-queues', 'H323/ip$aa.bb.cc.dd:5555/10387', 'SIP/3062-0860b9a0', 'Queue', '1|t|||1200', 31, 31, 'ANSWERED', 3, '', '1164975540.6', '1164975540.6' 2: '2006-12-01 12:19:32', '2006-12-01 12:19:32', '2006-12-01 12:19:56', '2000', '2000', 's', 'macro-dial', 'Local/2000@conferences-20a3,1', 'SIP/3060-0868f500', 'Dial', 'SIP/3060|60|tr', 24, 24, 'ANSWERED', 3, '', '1164975572.9', '1164975540.6' 3: '2006-12-01 12:19:32', '2006-12-01 12:19:32', '2006-12-01 12:19:56', '2000', '2000', '2000', 'conferences', 'Local/2000@conferences-20a3,2', '', 'Videoswitch', '2000/9', 24, 24, 'ANSWERED', 3, '', '1164975572.10', '1164975540.6' 4: '2006-12-01 12:19:31', '2006-12-01 12:19:31', '2006-12-01 12:20:06', '"Tandberg-00814122" <aa.bb.cc.dd>', 'aa.bb.cc.dd', '2000', 'conferences', 'SIP/3062-0860b9a0', '', 'Videoswitch', '2000/M09', 35, 35, 'ANSWERED', 3, '', '1164975571.8', '1164975540.6' Events should have been: Enter IVR             : 2006-12-01 12:19:00 Enter Q (agent rings) : 2006-12-01 12:19:11 Agent Ans             : 2006-12-01 12:19:20 Agent Calls 3way      : 2006-12-01 12:19:33 3way Answer           : 2006-12-01 12:19:40 3way Hangup           : 2006-12-01 12:19:56 Agent Hangup          : 2006-12-01 12:20:05 Caller Hangup         : 2006-12-01 12:20:05 Where 1: is the caller into the system on an H.323 channel 2 and 3: are Local channels created by an originate extension connecting the conference to a SIP extension 4: is the Agent on SIP/3062 By: John Martin (jfp_martin) 2006-12-01 18:49:27.000-0600 BTW Murf,  I can get nearly all of the events right in the previous example (without your patch) by: a) taking the small code change I proposed between ast_request and ast_call and inserting it directly into ast_request(). This is so we make sure a CDR has been   started before ast_request has exited. b) adding cdr's to the do_masquerade function (copying pointers around). What that leaves my test case with is the answer field of the two local channels being set to the start of the call (beginning of ringing) and not when the SIP/3060 extension they are bridging starts to ring. I'm going to work on that next week. The weird thing about my test case is that there are actually 5 channels existing during the conferenced 3 way call: The H.323/aa.bb.cc.dd channel, the SIP/3062 agent channel, the two LOCAL/conf... channels (all of which have CDRs as detailed above) and a fifth SIP channel for the bridged endpoint, SIP/3060 in the example above. I need to investigate why the fifth channel has no CDR and I guess also why connecting this fifth channel to the conference requires two bridged LOCAL channels to get there... I'm sure it's to do with media negotiation (because they don't exist if I do a canreinvite=yes) but I'm bu****ed if I can see why at the moment. John By: Steve Murphy (murf) 2006-12-05 22:35:17.000-0600 OK, I've put a cdr_alloc() call in the channel_alloc() in the bug8221-1.4 branch... the reason is that in about the third of the problems, a missing cdr is the root problem. There's code to create CDR's sprinkled thruout the source. My wild-eyed, scary idea is to create a CDR on every channel. If we hit cases where a CDR is really not wanted, we can try to figure out where and why and kill it before it hits the logs. It appears, however, that such cases are in the minority. The results of this are that in the 3-legged call case, the times for "start" are the real times, not the answer times. So far, in simple bridged calls, no unwanted cdrs generated. And in the 3 legged case, no unwanted CDR's. Let's see about the 5-legged call case...! I've added some more debug to the bug8221-1.4 branch. I haven't touched the trunk branch, so don't play there yet. So... please, all you CDR officianados, run the bug8221-1.4 branch and tell me what problems you see. Later I'll go back over the code, and remove the now unnecessary cdr_alloc() calls, if this idea pans out. John-- I'm curious as to whether the bug8221-1.4 branch will give you your 5th leg now; if not, I can trace down a good place to post the cdr; if you supply both the logs and the generated CDRs, and show me what's wrong, I hope to get this all straightened out somehow. And, I'm watching very closely what you're doing. Occams Razor can and should always be applied where it can be! You might try moving your cdr_alloc to the channel_alloc() func, and see if that clears up the start times. If that's all you need, then I'll yank out all the bridgeing mess and call it quits. By: Steve Murphy (murf) 2006-12-07 07:19:48.000-0600 Any news on the latest branch? By: John Martin (jfp_martin) 2006-12-07 15:44:47.000-0600 Hi Murf, I'm gonna get some time to look at this in the morning... I tried your suggestion of putting the cdr_alloc into channel_alloc and all seemed to work ok for my derivative 1.4. I'll try your branch in the morning. John By: John Martin (jfp_martin) 2006-12-09 13:19:51.000-0600 Hi Murf,  I did have a look at your patch again yesterday. It raised more quesions than it solved. I was looking through the chan_local code and realised that it matters what direction a call is being made for the masquerade to be attempted. I switched my orginate channels/extensions around and I find that the local channels now get bridged and I loose a couple of CDRs - down to a reasonable 3 CDRs for three calls - seems to make sense. With your patch in place too I find that one of the CDRs comes back because after I redirect my initial two channels (you'll remember I do a redirect of two channels then an originate to get three people in a conf) the breaking of the original two channel bridge, by the redirect, dumps out a CDR... which could be considered correct behaviour. I still get problems with the start and answer times of the originate(d) channels though. When I get some time I'll detail the new CDR bahaviour... John By: Steve Murphy (murf) 2006-12-14 16:26:40.000-0600 OK, it just hit me the last two mornings, as I was waking up, that the merge algorithm wasn't doing the "end" time merging right. The start and answer times need to be the earlier of the two, if they conflict, but the end time probably should be the later of the two. I've made this change in the team/murf/bug8221-1.4 branch... Don't know if it'll help, but... By: Loic Didelot (voipgate) 2007-01-10 03:03:32.000-0600 When using Local channels the CDR variables like CDR(accountcode) are no longer available when the first (Local) channel has been answered. Tested on SVN-murf-bug8221-1.4-r50306: My commando for originating the call through the asterisk manager: Action: Originate Channel: Local/+352621209047@CALLBACK-STEP1 Context: CALLBACK-STEP2 Exten: +352091600422 Priority: 1 Account: 4966 Callerid: "Privat" <+352621209047> Timeout: 10000 Variable: IPADDRESS=192.168.2.77|CALLMEBACK=1 ActionID: 9e736de81166721483eb948a62364610 By: dimka (dimka) 2007-01-12 15:01:12.000-0600 was tryed on bug8221-1.4 branch Revision: 50673 === first example === callfile: Channel: local/7xxxxxxxxxx@back/n MaxRetries: 2 RetryTime: 3 WaitTime: 60 Context: call Extension: 8xxxxxxxxxx Account: 00000079 extensions: [back] exten => _X.,n,Dial(H323/${EXTEN}@gate,60) [call] exten => _X.,n,Dial(H323/${EXTEN}@gate,60) Master.csv: "","","","","H323/gate-8","","","","2007-01-12 22:40:18","2007-01-12 22:40:45","2007-01-12 22:40:59","41","14","ANSWERED","DOCUMENTATION","","1168630818.15","" ""7xxxxxxxxxx" <7xxxxxxxxxx>","7xxxxxxxxxx","8xxxxxxxxxx","call","Local/7xxxxxxxxxx@back-8fee,1","H323/gate-8","Dial","H323/8xxxxxxxxxx@gate|60|h","2007-01-12 22:39:59","2007-01-12 22:40:18","2007-01-12 22:40:59","60","41","ANSWERED","DOCUMENTATION","00000079","1168630799.12","06E3ACBD408B0BCC4C04BD456510B1FC" "","","","","H323/gate-7","","","","2007-01-12 22:39:59","2007-01-12 22:40:18","2007-01-12 22:40:59","60","41","ANSWERED","DOCUMENTATION","","1168630799.14","" ""7xxxxxxxxxx" <7xxxxxxxxxx>","7xxxxxxxxxx","7xxxxxxxxxx","back","Local/7xxxxxxxxxx@back-8fee,2","H323/gate-7","Dial","H323/7xxxxxxxxxx@gate|60|hS(1000)","2007-01-12 22:39:59","2007-01-12 22:40:18","2007-01-12 22:40:59","60","41","ANSWERED","DOCUMENTATION","00000079","1168630799.13","06E3ACBD408B0BCC4C04BD456510B1FC" === second example === callfile: Channel: H323/7xxxxxxxxxx@gate MaxRetries: 2 RetryTime: 3 WaitTime: 60 Context: call Extension: 8xxxxxxxxxx Account: 00000079 Callerid: 7xxxxxxxxxx" <7xxxxxxxxxx> [call] exten => _X.,n,Dial(H323/${EXTEN}@gate,60) "","","","","H323/gate-13","","","","2007-01-12 23:17:55","2007-01-12 23:18:07","2007-01-12 23:18:24","29","17","ANSWERED","DOCUMENTATION","","1168633075.26","" ""7xxxxxxxxxx" <7xxxxxxxxxx>","7xxxxxxxxxx","8xxxxxxxxxx","call","H323/gate-12","H323/gate-13","Dial","H323/8xxxxxxxxxx@gate|60","2007-01-12 23:17:37","2007-01-12 23:17:55","2007-01-12 23:18:24","47","29","ANSWERED","DOCUMENTATION","00000079","1168633057.25","0C77009950B96187DE053093DA606582" === results === call sequences for both examples: 1. make call file, then asterisk do make call to 7xxxxxxxxxx     2. 7xxxxxxxxxx phone ringing... time passed... then answer. 3. after answering asterisk do call to 8xxxxxxxxxx 4. 8xxxxxxxxxx phone ringing... time passed... then answer. 5. time passed... Hangup comments and bugs: -- first call clid/dst/src/account/dcontext/dstchannel/lastapp/lastdata is null, i.e. call file information was ignored. -- start time is not right for second call, because second call start after first call was answered. -- answer time, duration and billsec seems ok in second example, but wrong in first example for "second call" record from local channel (answer time must be 2007-01-12 22:40:45. By: dimka (dimka) 2007-01-12 19:01:21.000-0600 I think this case something about CDR design in asterisk: "One CDR for action". Before 1.4 (in 1.2.1) I was used local channel with "/n" suffix (modified local channel + radius support with start/stop and _keepalive_ accounting packets) for doubling CDR records. 1.4 have broken billsec and disposition, all other seems have compatible behaviour. I think we need "fixing" only this problem and nothing more. For future design I will recommend "one per leg CDR" scheme, because this can be more correct way to explain how call was made. We create channel - we need cdr, some of them will be ingress type, some egress. Each channel/leg _can_ have a cost... and problem will be aggregate "one" call from a lot CDRs for some billing systems (maybe we need conf_id like cisco does). :) Just my 2c. ps. dst/src/account is null (see previous note) because channel.c->ast_channel_alloc have /* Experiment: under what conditions do we NOT want to track cdrs on channels? */ in murf/bug8221-1.4 By: dimka (dimka) 2007-01-15 14:21:27.000-0600 Double bug... 1. ast_cdr_answer() not called after second channel was answered (in case callfile/manager). Diff have same behaviour like before, for callfiles and manager. But, maybe this should be fixed some other way, i.e. not in app_dial. 2. Don't try test with CLI originate command, because it buggy. Runned from CLI it have no own thread and blocked all (I think we need to open res_clioriginate case for fixing this). ps. did anyone tried my patch (app_dial_noaswer_bug.diff) on fresh 1.4? any success? By: rayjay (rayjay) 2007-01-17 23:05:50.000-0600 We recently installed Asterisk 1.4.0 and the broken CDR's related to this bug are a major show stopper for us at the moment.  I have tried the 8221 branch and from my tests so far all the CDR is correct which is great!  However, there are a few other bugs that have *come back* since they were resolved after this fork was done.  Is there any chance these fixes could be put back into the main trunk?  If not, could you explain the changes you have made to resolve the issue, so I can apply these to the 1.4.0 branch? Many thanks for your hard work on this. By: Steve Murphy (murf) 2007-01-18 00:27:31.000-0600 I've been concentrating on 1.4, as the set of changes are highly experimental, and are subject to a lot of change/etc., and it's hard enough just dealing with one set of code, let alone 2. I'll see if I can extract a clean "patch", and I'm using the term "clean" VERY loosely! I've got debugs all over the place! And they are going to get worse! By: Afshin Mashayekhi (afshin) 2007-01-30 19:57:53.000-0600 I checked your branch bug8221-1.4 and I tried to park call and pick up the call and transfer from 1 phone to another phone number. In first case the billsec and channels are correct but I'm setting CDR(userfield) in h extension but it doesn't effect the CDR in this revision. In second case which is transferring a phone to a normal mobile number or something like that. I called from A to B and B was forwarded to XXXXXX. as soon as I picked up the mobile it writes a CDR record from B to XXXXX with billsec 0 and after I hanged up the mobile it writes the second CDR from A to B with correct information.  I think u write cdr before processing the h extension, this causes a problem for billing purposes... I can see the execution of h extension but it doesn't effect the CDR... By: Afshin Mashayekhi (afshin) 2007-03-30 00:32:41 Hi murf, I've tried your 1.4 branch and I've tried to merge your branch with 1.4.2 but still the same problem exist and I'm getting 0 bill sec for one of records which is the main cdr... By: Steve Murphy (murf) 2007-03-30 07:50:00 I assume this is about 8927, let's continue discussions there, then. By: Steve Murphy (murf) 2007-03-30 10:07:45 At last, I built up the courage to commit this stuff to 1.4 (59486) and trunk (59500). It doesn't solve all the CDR probs, but it got a few; I hope that at the least, it's an improvement.