[Home]

Summary:ASTERISK-17296: Calls didn't appear in CDR
Reporter:Kirill Nikitin (dj kill)Labels:
Date Opened:2011-01-27 10:21:15.000-0600Date Closed:2013-01-25 15:11:26.000-0600
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:CDR/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) debug.log
Description:From time to time few calls from queue (about 2% of total calls about 20% of all unanswered calls) didn't appear in CDR.
Tested on PGSQL CDR database and CVS CDR.
This happened only for unanswered calls.
In queue.log this calls presents.

****** STEPS TO REPRODUCE ******

After enter the queue or after periodic announcement caller hangup the call.  

****** ADDITIONAL INFORMATION ******

Dialplan:

[call-centre-queue]
exten => que,1,Playback(DGKrecorded)
exten => que,n,Queue(DGK-queue,,,,540)
exten => que,n,Playback(DGKEnd)
exten => que,n,Hangup()

exten => h,1,GotoIf($[${ISNULL(${BRIDGEPEER})} = 1 ]?unavail)
exten => h,n,DeadAGI(agent_by_clid_queue.agi,${BRIDGEPEER})
exten => h,n,Set(CDR(userfield)=${USRFLD})
exten => h,n(unavail),NoOp(${CDR(userfield)})
Comments:By: Leif Madsen (lmadsen) 2011-01-31 14:10:59.000-0600

I think you'll need to provide the same console output with debug level logging (enable 'debug' in logger.conf).

Also I'd be curious what (if anything) is being written to postgresql. Sometimes the SQL can just get rejected from the database due to table misconfiguration so I'd want to see if that is happening.

Other than that I'm not sure what else to ask for.
By: Kirill Nikitin (dj kill) 2011-02-01 09:59:23.000-0600

debug in logger.conf enabled:
[general]
event_log = no
[logfiles]
console => notice,warning,error,debug,verbose
messages => notice,warning,error,debug,verbose
syslog.local0 => notice

cdr.conf looks like:
[general]
endbeforehexten=yes

Changing endbeforehexten to NO didn't affected on this misses.

cdr_pgsql.conf looks like
[global]
hostname=localhost
port=5432
dbname=asterisk
password=geirby
user=secret
spool=pgsql.spool

This situation not only with PGSQL but in cvs and mysql everything looks the same.

Tomorrow I'll try to find all calls missed in CDR.

How can I debug this error more detailed?
By: Kirill Nikitin (dj kill) 2011-02-03 06:12:43.000-0600

We made some addition test.

So, all of these lost calls appeared only then the "h extension" processed.
AGI and DeadADI didn't affected.
By: Kirill Nikitin (dj kill) 2011-02-08 03:24:47.000-0600

So, the h extension removed.
Here is the full diaplan:

[incoming]
exten => 78003339100,1,NoOp(${CALLERID(num)})
exten => 78003339100,n,Goto(call-centre,8800,1)
exten => 78003339100,n,Hangup()

exten => 74959559100,1,NoOp(${CALLERID(num)})
exten => 74959559100,n,Goto(call-centre,8800,1)
exten => 74959559100,n,Hangup()

[call-centre]
exten => 8800,1,Answer
exten => 8800,n,Ringing()
exten => 8800,n,Wait(2)
exten => 8800,n,NoOp(${AGENTUPDATECDR})
exten => 8800,n,Playback(DGKHello)
exten => 8800,n,Playback(DGKStay)
exten => 8800,n,Background(DGKPress1)
exten => 8800,n,Background(DGKPress2)
exten => 8800,n,StartMusicOnHold
exten => 8800,n,WaitExten(5)
exten => 1,1,Set(testvar='1')
exten => 1,n,Set(CDR(accountcode)=${testvar})
exten => 1,n,Set(QUEUE_PRIO=10)
exten => 1,n,Goto(call-centre-queue,que,1)
exten => 2,1,Set(testvar='2')
exten => 2,n,Set(CDR(accountcode)=${testvar})
exten => 2,n,Playback(DGKPayment)
exten => 2,n,Background(DGKPress0)
exten => 2,n,StartMusicOnHold
exten => 2,n,WaitExten(5)
exten => 2,n,Playback(DGKThanks)
exten => 2,n,Hangup()
exten => 0,1,Set(testvar=${testvar}'0')
exten => 0,n,Set(CDR(accountcode)=${testvar})
exten => 0,n,Set(QUEUE_PRIO=1)
exten => 0,n,Goto(call-centre-queue,que,1)
exten => t,1,Goto(call-centre,0,1)
exten => i,1,Goto(call-centre,0,1)

[call-centre-queue]
exten => que,1,Playback(DGKrecorded)
exten => que,n,Queue(DGK-queue,,,,540)
exten => que,n,Playback(DGKEnd)
exten => que,n,Hangup()

And here is the missed in CDR call debug:

[Feb  8 07:01:57] VERBOSE[82622] logger.c:     -- Executing [74959559100@incoming:1] NoOp("SIP/zebra2-000107ea", "9831071817") in new stack
[Feb  8 07:01:57] VERBOSE[82622] logger.c:     -- Executing [74959559100@incoming:2] Goto("SIP/zebra2-000107ea", "call-centre|8800|1") in new stack
[Feb  8 07:01:57] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:1] Answer("SIP/zebra2-000107ea", "") in new stack
[Feb  8 07:01:57] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:2] Ringing("SIP/zebra2-000107ea", "") in new stack
[Feb  8 07:01:57] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:3] Wait("SIP/zebra2-000107ea", "2") in new stack
[Feb  8 07:01:59] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:4] NoOp("SIP/zebra2-000107ea", "") in new stack
[Feb  8 07:01:59] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:5] Playback("SIP/zebra2-000107ea", "DGKHello") in new stack
[Feb  8 07:01:59] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKHello' (language 'ru')
[Feb  8 07:02:04] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:6] Playback("SIP/zebra2-000107ea", "DGKStay") in new stack
[Feb  8 07:02:04] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKStay' (language 'ru')
[Feb  8 07:02:07] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:7] BackGround("SIP/zebra2-000107ea", "DGKPress1") in new stack
[Feb  8 07:02:07] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKPress1' (language 'ru')
[Feb  8 07:02:11] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:8] BackGround("SIP/zebra2-000107ea", "DGKPress2") in new stack
[Feb  8 07:02:11] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKPress2' (language 'ru')
[Feb  8 07:02:17] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:9] StartMusicOnHold("SIP/zebra2-000107ea", "") in new stack
[Feb  8 07:02:17] VERBOSE[82622] logger.c:     -- Started music on hold, class 'default', on SIP/zebra2-000107ea
[Feb  8 07:02:17] VERBOSE[82622] logger.c:     -- Executing [8800@call-centre:10] WaitExten("SIP/zebra2-000107ea", "5") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Timeout on SIP/zebra2-000107ea, going to 't'
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [t@call-centre:1] Goto("SIP/zebra2-000107ea", "call-centre|0|1") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [0@call-centre:1] Set("SIP/zebra2-000107ea", "testvar=0") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [0@call-centre:2] Set("SIP/zebra2-000107ea", "CDR(accountcode)=0") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [0@call-centre:3] Set("SIP/zebra2-000107ea", "QUEUE_PRIO=1") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [0@call-centre:4] Goto("SIP/zebra2-000107ea", "call-centre-queue|que|1") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Executing [que@call-centre-queue:1] Playback("SIP/zebra2-000107ea", "DGKrecorded") in new stack
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- Stopped music on hold on SIP/zebra2-000107ea
[Feb  8 07:02:22] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKrecorded' (language 'ru')
[Feb  8 07:02:30] VERBOSE[82622] logger.c:     -- Executing [que@call-centre-queue:2] Queue("SIP/zebra2-000107ea", "DGK-queue||||540") in new stack
[Feb  8 07:02:30] VERBOSE[82622] logger.c:     -- Started music on hold, class 'default', on SIP/zebra2-000107ea
[Feb  8 07:03:08] VERBOSE[82622] logger.c:     -- Stopped music on hold on SIP/zebra2-000107ea
[Feb  8 07:03:08] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKMid' (language 'ru')
[Feb  8 07:03:15] VERBOSE[82622] logger.c:     -- Started music on hold, class 'default', on SIP/zebra2-000107ea
[Feb  8 07:03:46] VERBOSE[82622] logger.c:     -- Stopped music on hold on SIP/zebra2-000107ea
[Feb  8 07:03:46] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKMid' (language 'ru')
[Feb  8 07:03:53] VERBOSE[82622] logger.c:     -- Started music on hold, class 'default', on SIP/zebra2-000107ea
[Feb  8 07:04:24] VERBOSE[82622] logger.c:     -- Stopped music on hold on SIP/zebra2-000107ea
[Feb  8 07:04:24] VERBOSE[82622] logger.c:     -- <SIP/zebra2-000107ea> Playing 'DGKMid' (language 'ru')
[Feb  8 07:04:31] VERBOSE[82622] logger.c:     -- Started music on hold, class 'default', on SIP/zebra2-000107ea
[Feb  8 07:05:00] VERBOSE[82622] logger.c:     -- Stopped music on hold on SIP/zebra2-000107ea
[Feb  8 07:05:00] VERBOSE[82622] logger.c:   == Spawn extension (call-centre-queue, que, 2) exited non-zero on 'SIP/zebra2-000107ea'

It is still about 20 calls per day.


By: dimitripietro (dimitripietro) 2011-02-28 10:06:36.000-0600

To add more information, I have exactly the same problem. In my case I have no "h" extension. I'm unable to reproduce it but all the missing cdr are call that are unanswered in the queue. The reason why I'm able to track this is because the event are written into the queue_log. So I can see the call in the queue_log but not in the cdr. Anything you would like me to submit ?
By: Kirill Nikitin (dj kill) 2011-03-22 09:35:55

The same problem in 1.4.40
Unanswered calls in queue still disappears from CDR.
By: Attila Megyeri (amegyeri) 2011-05-02 06:52:34

Can you please check issue 19207?

It is probably the same issue, but I can reproduce that one with 100% certanity.
It happens if a call is disconnected while waiting in the queue, while the member is "BUSY". If the member is ringing, CDR is written properly.

Thanks.
By: Jeff Hoppe (jhoppebugs) 2011-11-08 11:22:01.422-0600

I believe this is my situation as well.   About 20 - 30% of all calls that leave a queue due to TRANSFER, ABANDON, EXITWITHKEY, EXITWITHTIMEOUT will not have a CDR created; however, a queue log is created which allows me to identify this issue.

All of my COMPLETEAGENT and COMPLETECALLER event calls have a CDR recorded, its just the events that leave a queue.

I am logging CDRs to an ODBC database.  I get no sql errors in console display or full log file regarding CDR inserts.

I also log CDR's into the Master.CSV file and they don't exist there as well.
By: Matt Jordan (mjordan) 2013-01-25 15:11:26.199-0600

This is a duplicate of ASTERISK-17776.

This behavior was fixed in SVN trunk, which will be released in Asterisk 12. Due to the volatile nature of CDRs, a fix was determined not to be a candidate for inclusion in release branches.