[asterisk-dev] The Trouble with CDR's...!

Mon Dec 18 14:06:10 MST 2006

To He/She Who Cares about CDR's in Asterisk:

Now is the time to review CDR problems, and complaints; that is, if you
want them fixed. If you like your problems to stay that way, you can
stop reading this now...

I'm trying to work on 8221, the somethings-not-quite-right-with-CDRs
bug;

I've been fighting with the CDR code to help with more obtuse cases, and
have made some progress, and will continue to fight with it until Kevin
says stop or the community begs me to leave the poor mess alone.

Every experiment I try keeps pointing to more problems.

I've been able to straighten out some problems, tho. But on others, I
just have to scratch my head, and ask, what SHOULD this be doing?

I need some community input and proposals.

Let me describe what currently is being produced, and what my changes
thus far have done, and you can see what needs to further be done...

It could be you have other scenarios; I need to know how to reproduce
them on my test machine. There has been some mention of scenarios I
cannot at this moment reproduce, like H323, etc. They will be tough to
debug. I may have to use you as a test agent to try out changes, etc...!

======
CASE 1: "normal, simple case"

Right now, For "normal", simple cases, CDRs are generated, and are
pretty correct. A simple, normal, case would be something like: A picks
up extension,
calls B, on or off off site, B answers, they talk, then hang up.

In this case you, get a single CDR generated, that might look like this:

"","ext3","917777661684","homeext","ext3","Zap/3-1","Zap/1-1","Dial","Zap/1/17777661684|30|TW","2006-12-17 18:56:33","2006-12-17 18:56:36","2006-12-17 19:34:43",2290,2287,"ANSWERED","DOCUMENTATION","1166406981.1010",""

My changes, so far, have not changed this behavior.

From the above, we can guess the other party picked up pretty quick,
only 3 seconds, and the two parties conversed for 2287 seconds after
that.

Commentary:

Not much.

======
CASE 2: A calls B, who does not answer:

in 1.4:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 09:39:12","","2006-12-18 09:39:44","32","0","NO
ANSWER","DOCUMENTATION","","1166459948.0",""

in my 8221 branch:

"","","","","Zap/52-1","Zap/50-1","Dial","Zap/50|30|tw","2006-12-18
08:28:12","","2006-12-18 08:28:46","34","0","NO
ANSWER","DOCUMENTATION","","1166455692.0",""

I see no change in behavior here. (extension and priority are blank,...
I don't know why... I'll investigate).

Commentary:

not much.

======
CASE 3: A calls B;  B parks the call via #700;  C picks up the parked
call. They converse and hang up.

in 1.4:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 09:42:02","2006-12-18 09:42:05","2006-12-18
09:42:41","39","36","ANSWERED","DOCUMENTATION","","1166460119.2",""

"","","701","extension","Zap/51-1","","ParkedCall","701","2006-12-18
09:42:26","2006-12-18 09:42:26","2006-12-18
09:42:41","15","15","ANSWERED","DOCUMENTATION","","1166460138.4",""

in my 8221 branch:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 08:41:31","2006-12-18 08:41:40","2006-12-18
08:41:50","19","10","ANSWERED","DOCUMENTATION","","1166456491.2",""

"","","701","extension","Zap/51-1","Zap/52-1","ParkedCall","701","2006-12-18 08:41:55","2006-12-18 08:42:04","2006-12-18 08:42:24","29","20","ANSWERED","DOCUMENTATION","","1166456515.4",""

Commentary:

In the 8221 branch: By supplying the missing dstchannel name, you can
now link the two CDR's. The first CDR ends when 150(Zap/50) hangs up.
The second begins when 151(Zap/51) dials 701 to retrieve the caller from
the parking lot.

In 1.4, both CDRS ended at the same time; the parked CDR begins at the
time of pickup; there is no way to tell how long the call was parked.

======
CASE 4: (blind transfer) A calls B;  B transfers call to C (via e.g.,
#151) C answers; A and C converse; the call is hung up.

in 1.4:

"","","151","extension","Zap/52-1","Zap/51-1","Dial","Zap/51|30|
tw","2006-12-18 09:44:59","2006-12-18 09:45:01","2006-12-18
09:45:39","40","38","ANSWERED","DOCUMENTATION","","1166460296.5",""

in my 8221 branch:

"","150","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 08:44:01","2006-12-18 08:44:08","2006-12-18
08:44:12","11","4","ANSWERED","DOCUMENTATION","","1166456641.5",""

"151","151","151","extension","Zap/51-1","Zap/52-1","","","2006-12-18
08:44:12","2006-12-18 08:44:17","2006-12-18
08:44:31","19","14","ANSWERED","DOCUMENTATION","","1166456652.7",""

Commentary:

In 1.4, with only 1 merged CDR, you cannot even tell that Zap/50 (150)
was involved in the call. According to that CDR, A called C directly,
and spent the whole time talking there.

In the 8221 branch, you can see the call to Zap/50, when it was
answered, and when it ended (when the #151 was completely dialed). The
second CDR begins at that instant. For all practical intents, they are
two separate calls; first Zap/52 calls Zap/50, then Zap/52 calls Zap/51.
The only difference: the second CDR has no app/data recorded; I have
been trying to put BLINDXFER there, but it's not trivial to do so...

======
CASE 5: (attended blind transfer) A calls B; B transfers call to C (via
e.g.: flash-hook, 151), B hangs up before C answers;  C answers, A and C
converse.

in 1.4:

"","","151","extension","Zap/50-2","Zap/51-1","Dial","Zap/51|30|
tw","2006-12-18 09:52:00","2006-12-18 09:52:07","2006-12-18
09:52:20","20","13","ANSWERED","DOCUMENTATION","","1166460717.10",""

"","","151","extension","Zap/52-1","Zap/51-1","Dial","Zap/50|30|
tw","2006-12-18 09:51:40","2006-12-18 09:51:46","2006-12-18
09:52:20","40","34","ANSWERED","DOCUMENTATION","","1166460694.8",""

in my 8221 branch:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 08:46:13","2006-12-18 08:46:20","2006-12-18
08:46:38","25","18","ANSWERED","DOCUMENTATION","","1166456773.8",""

"151","151","151","extension","Zap/51-1","Zap/52-1","","","2006-12-18
08:46:27","2006-12-18 08:46:40","2006-12-18
08:47:20","53","40","ANSWERED","DOCUMENTATION","","1166456787.11",""

Commentary:

In 1.4, both calls CDR's end at the same time. You cannot tell that
Zap/52(Party A)  talked to Zap/50(Party B) at all; Indeed, it looks more
like B and C talked, when they did not. Are folks using the common
end-times to tie the two halves together?

In the 8221 branch, Zap/52 (A) is involved in both legs. The lack of
App/Data in the second leg is a clue of a transfer. I hope to one day
stick something in the APP field like "ATXFER". It shows that the first
call ended 2 seconds before the 
second call answered. 

======
CASE 6: (attended transfer) A calls B; B transfers call to C (via e.g.:
flash-hook, 151), C answers, B and C converse; B flashes hook, now
A,B,and C converse; B hangs up, A and C converse; A and C then hang up.

in 1.4:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 09:59:31","2006-12-18 09:59:34","2006-12-18
09:59:46","15","12","ANSWERED","DOCUMENTATION","","1166461167.12",""

"","","151","extension","Zap/50-2","Zap/51-1","Dial","Zap/51|30|
tw","2006-12-18 10:00:22","2006-12-18 10:00:31","2006-12-18
10:01:14","52","43","ANSWERED","DOCUMENTATION","","1166461218.17",""

"","","151","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 10:00:09","2006-12-18 10:00:11","2006-12-18
10:01:14","65","63","ANSWERED","DOCUMENTATION","","1166461206.15",""

in my 8221 branch:

"","","150","extension","Zap/52-1","Zap/50-1","Dial","Zap/50|30|
tw","2006-12-18 08:48:07","2006-12-18 08:48:12","2006-12-18
08:49:42","95","90","ANSWERED","DOCUMENTATION","","1166456887.12",""

"","","151","extension","Zap/50-2","Zap/51-1","Dial","Zap/51|30|
tw","2006-12-18 08:48:21","2006-12-18 08:48:31","2006-12-18
08:51:49","208","198","ANSWERED","DOCUMENTATION","","1166456901.14",""

Commentary:

In 1.4, this sequence generates 3 CDR's. The first is the call from
Zap/52 (A) to Zap/50 (B). It appears to end when B flashes hook and
dials 151 (C). The last pair of CDR's end at the same time. The second
CDR apparently records the call from Zap/50 to Zap/51, but the times
bother me; CDR 3 has an earlier start time. So, it might be documenting
the time of the 3-way call between the 3 parties instead. The third  CDR
apparently starts When Zap/50 flashes the first time.

In the 8221 branch, the first CDR records the first call, where Zap/52
(A) calls Zap/50 (B). The start time records when Zap/52 began the dial,
and the answer time is when (B) answered. The end time appears to be
when Zap/50 hangs up from the merged call. The second CDR documents the
call from Zap/50 (B) to Zap/51 (C),
it starts when Zap/50 flashes hook and dials Zap/51, and the answer time
looks like when Zap/51 (C) picks up the phone. It appears to end when
(A) and (C) hang up. I'd have to run some carefully stop-watched tests
to verify these times. As you can tell, I am only just starting my
analysis of the ATX scenarios!

======
CASE 7:  a call file is submitted that dials an extension, and hooks you
up to the DISA app. Answer the extension, get dialtone, dial another
extension, converse, both sides hang up.

in 1.4:

"150","150","100","callbackmenu","Local/150 at income1-ef0b,1","","DISA","no-password|callbackdialout","2006-12-18 12:31:27","","2006-12-18 12:31:36","9","0","ANSWERED","DOCUMENTATION","","1166470284.30",""

"150","150","150","income1","Local/150 at income1-ef0b,2","Zap/50-1","Dial","Zap/50|20|m","2006-12-18 12:31:24","2006-12-18 12:31:27","2006-12-18 12:32:13","49","46","ANSWERED","DOCUMENTATION","","1166470284.31",""

"150","150","151","callbackdialout","Local/150 at income1-ef0b,1","Zap/51-1","Dial","Zap/51|20|w","2006-12-18 12:31:36","","2006-12-18 12:32:13","37","0","NO ANSWER","DOCUMENTATION","","1166470284.30",""

in my 8221 branch:

"","","","","Local/150 at income1-2fdd,1","","DISA","no-password|
callbackdialout","2006-12-18 09:16:50","2006-12-18 09:16:57","2006-12-18
09:17:08","18","11","ANSWERED","DOCUMENTATION","","1166458610.21",""

"150","150","150","income1","Local/150 at income1-2fdd,2","Zap/50-1","Dial","Zap/50|20|m","2006-12-18 09:16:50","2006-12-18 09:16:57","2006-12-18 09:17:28","38","31","ANSWERED","DOCUMENTATION","","1166458610.22",""

"150","150","1151","callbackdialout","Local/150 at income1-2fdd,1","Zap/51-1","Dial","Zap/51|20|w","2006-12-18 09:17:08","2006-12-18 09:17:16","2006-12-18 09:17:28","20","12","ANSWERED","DOCUMENTATION","","1166458610.21",""

Commentary:

In the 1.4, as per bug 8221, The first CDR is marked "ANSWER", but no
answer time is present, for the DISA app. This is conflicting info. The
beginning of the process is recorded in the second CDR, where extension
150 is dialed, and 3 seconds later, it is picked up; then the first
CDR's start time begins, and apparently ends when the extension number
is obtained from the user. The 3rd CDR records the call to Zap/51. Both
2nd and 3rd CDRs end at the same time. We don't know when the user
picked up the phone for the DISA app.

in the 8221 branch, the DISA app begins at the same time the Dial to
Zap/50; both the first and second CDR's share the same start and answer
time. The DISA cdr end time appears to be when the user finishes typing
in his response to the dialtone,
and coincides with the start of the dial to Zap/51 in the 3rd CDR. The
ends times are common to the 2nd and 3rd CDR, because when either end
hangs up, the call is over. It looks like all the fields are correct and
reasonable to me.

Question: What SHOULD this scenario produce in the way of CDR's?

======
CASE 8:   An extension is taken off-hook; dial tone is generated. The
extension is then hung up.

in 1.4

-- no CDR is generated.

in my 8221 branch:

"","","","","","","","","2006-12-15 12:52:18","","2006-12-15
12:52:26","8","0","NO ANSWER","DOCUMENTATION","","",""

Commentary:

my new branch will attach a CDR to a channel at creation time, so in
this case a cdr is generated. I'm highly tempted to simply remove a CDR
that has no destination channel, no app, no data, no answer. The channel
name SHOULD have been there, showing the Zap/50 or whatever... but, this
sort of thing may also end up deleting wanted or needed CDRs, we shall
see.

-- 
Steve Murphy
Software Developer
Digium
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/x-pkcs7-signature
Size: 3227 bytes
Desc: not available
Url : http://lists.digium.com/pipermail/asterisk-dev/attachments/20061218/e292bd69/smime.bin