[Home]

Summary:ASTERISK-16330: No CDRs after AMI Redirect
Reporter:postkonform (postkonform)Labels:
Date Opened:2010-07-07 16:08:29Date Closed:2015-02-26 09:14:13.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:CDR/General
Versions:Frequency of
Occurrence
Related
Issues:
duplicatesASTERISK-16537 No CDR with originate from manager and then an redirect to a dial from manager
Environment:Attachments:( 0) ZipZoneAsteriskDebugLog
Description:When using the Goto app no CDR is written if the call was answered.
If the call fails or is not answered a CDR is written.

We use the AMI to check a self made prepaid deposit if enough credit is left. If so we use the Redirect action to redirect the channel to another context named initCall where a Dial app establishes the call, so we can not use the Gosub app where this problem does not occur (The Redirect action seems to use Goto).

We tested it without the AMI. In this case we used the Goto directly to send incoming calls to the initCall context and the same error occurs. If we use Gosub it does not occur.

Another interesting thing could be, that if we redirect to another context where a Playback app will be started a CDR is written (in our case this will happen if no credit is left)

The CDR is neither written to CSV nor to MySQL.

*ADDITIONAL INFORMATION*

{{extensions.conf:}}
...
{noformat}
[Sip-Out]
exten => _.,1,Set(NR=${EXTEN})
exten => _.,2,Wait(100)
;A Java program which listens on the AMI redirects to initCall if credit is
;left on the user deposit, otherwise it redirects to noCredit

[initCall]
exten => s,1,Dial(SIP/${NR},,M(Timeout))

[macro-Timeout]
exten => s,1,Set(TIMEOUT(absolute)=16)

[noCredit]
exten => s,1,Playback(demo-nogo)
{noformat}
...

We only modified sip.conf, extensions.conf, manager.conf and cdr_mysql.conf

We are using asterisk-1.6.2.9, asterisk-addons-1.6.2.1 on centos-release-5-5.el5.centos.

rpm -q centos-release uname -a:
Linux voip 2.6.24-11-pve #1 SMP PREEMPT Fri May 14 09:28:08 CEST 2010 i686 i686 i386 GNU/Linux

We also corresponded with a user in the german asterisk irc channel, which could easily reproduce the problem and agreed that this seems to be a bug in the Goto app.
Comments:By: postkonform (postkonform) 2010-07-07 16:14:35

I just saw a post made one day before, it seems the problem relates to a similar problem, but I am not quite sure. https://issues.asterisk.org/view.php?id=17592
By: Leif Madsen (lmadsen) 2010-07-08 09:52:16

The other issue is using Originate, so I'm not sure they are related.
By: Leif Madsen (lmadsen) 2010-07-08 09:53:32

Please provide the complete dialplan that can easily reproduce this -- I'm not seeing any Goto() in your example.

Also please provide examples of the CDR records which are wrong and are correct with descriptions pointing out what you are missing and expect to see.
By: postkonform (postkonform) 2010-07-08 10:09:38

As I said we use the Redirect action of the AMI to redirect incoming calls from Sip-out to initCall (I just said that we tried it with the Goto app also and that does not solve the issue, but if we use the Gosub in this case it worked). My conclusion is that the Redirect action uses the Goto app. The dial plan above is the full dialplan we use, except the redirection with the Java AMI API.

In the test case the Sip-out looked like this:
exten => _.,1,Goto(initCall) (or Goto (initCall,s,1) I am not sure, but it was set up right and did not work


By: Leif Madsen (lmadsen) 2010-07-08 10:29:46

OK thanks. The CDRs you expect to see and the incorrect CDRs pointing out what is wrong or not wrong would also be useful for a developer to review.
By: David Woolley (davidw) 2010-07-08 12:30:52

What is answering the call?

Do you have unanswered call logging turned on?

AMI Redirect does end up calling code in common to GoTo, but it can also do channel masquerades if the call is bridged.  It doesn't call the GoTo application, but both may call the same low level code in the "PBX".

I wouldn't expect GoTo to have any effect, except in terms of the context and extension logged, but masquerading can have big effects.  I wonder if GoTo is a red herring here, in which case this is probably a support question, not a bug.
By: postkonform (postkonform) 2010-07-08 17:00:37

An answered call is, if the bridge between two channels was established. So if for example I call an extension and the other side accepts the call, the connection is established and then the CDR normally is saved with disposition ANSWERED, otherwise if the call was not accepted it is NO ANSWER, if the call was rejected it is FAILED and if the other extension is busy its BUSY.

Yes, unanswered calls are also logged. All calls should be logged. But the CDR is only written in case of NO ANSWER and FAILED (BUSY was not tested yet). If a bridge was established the CDR is not written.

This is a CDR what is written if disposition is NO ANSWER
calldate 2010-07-08 22:23:02
clid  
src  2
dst  s
dcontext initCall  
channel  SIP/222-00000003
dstchannel  SIP/111-00000004
lastapp  Dial
lastdata  SIP/111,,M(Timeout)
duration  4
billsec  0
disposition NO ANSWER
amaflags 3
accountcode  222
uniqueid  1278613382.3
userfield  

Expected would be the same for an answered call, except disposition = ANSWERED and billsec > 0 > duration

I am not 100% deep into asterisk, maybe you are right and it is not a bug, but I am missing something. Would be great to know what to do to actually get the CDR we want

Ah, and we tested to apply the patch of the post noted earlier. It does not solve the issue, just that you know.


By: postkonform (postkonform) 2010-07-08 17:10:43

Additionally the CDR that is written if the incoming call is redirected to the noCredit context(what maybe is interesting, that this one is written)

calldate 2010-07-08 01:38:12
clid
src 2
dst s
dcontext noCredit
channel SIP/222-00000013
dstchannel
lastapp Playback
lastdata demo-nogo
duration 9
billsec 9
disposition ANSWERED
amaflags 3
accountcode 222
uniqueid 1278538692.19
userfield


By: David Woolley (davidw) 2010-07-09 05:47:06

To be more specific, I think your problem is that you have failed to set this parameter to yes, which is a support issue, and nothing to do with goto:

; Define whether or not to log unanswered calls. Setting this to "yes" will
; report every attempt to ring a phone in dialing attempts, when it was not
; answered. For example, if you try to dial 3 extensions, and this option is "yes",
; you will get 3 CDR's, one for each phone that was rung. Default is "no". Some
; find this information horribly useless. Others find it very valuable. Note, in "yes"
; mode, you will see one CDR, with one of the call targets on one side, and the originating
; channel on the other, and then one CDR for each channel attempted. This may seem
; redundant, but cannot be helped.
;unanswered = no


I was also trying to establish whether you were really redirecting a call on wait, or whether you actually tried to connect it and then aborted it before or after answer.
By: postkonform (postkonform) 2010-07-09 14:30:09

But the problem is not, that unanswered calls are not logged. Actually the answered calls are not logged.
By: postkonform (postkonform) 2010-08-11 13:59:23

I checked my config and the unanswered option was set to yes. So it's not the problem (Like I suggested - the unanswered calls were logged, the problem really is that the answered calls are not logged)

Note: I also tried updating to 1.6.2.11, nothing changed.


By: Paul Belanger (pabelanger) 2010-09-04 14:26:40

We require a complete debug log to help triage the issue.

This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue:

http://svn.digium.com/svn/asterisk/trunk/doc/HOWTO_collect_debug_information.txt
By: postkonform (postkonform) 2010-09-28 13:34:27

I attached the log
By: Matt Jordan (mjordan) 2015-02-26 09:13:57.820-0600

I've confirmed that this is still a problem in Asterisk 11 using the AMI Redirect Action. Using the following dialplan:

{noformat}
[ Context 'contextB' created by 'pbx_config' ]
 's' =>            1. NoOp(I'm contextB)                         [pbx_config]
                   2. Set(CDR(accountcode)=B)                    [pbx_config]
                   3. Wait(3)                                    [pbx_config]
                   4. Answer()                                   [pbx_config]
                   5. PlayBack(silence/3)                        [pbx_config]
                   6. Hangup()                                   [pbx_config]

[ Context 'contextA' created by 'pbx_config' ]
 's' =>            1. NoOp(I'm contextA)                         [pbx_config]
                   2. Dial(Local/s@contextB/n)                   [pbx_config]

[ Context 'wait' created by 'pbx_config' ]
 's' =>            1. NoOp()                                     [pbx_config]
                   2. Wait(50000)                                [pbx_config]
{noformat}

I originated a Local channel into {{Local/s@wait}}, then performed an AMI Redirect on the resulting {{;2}} of the channel pair to {{s@contextA}}. This resulted in the following CDRs:

{noformat}
"","","s","wait","","Local/s@wait-00000000;1","","Echo","","2015-02-26 15:05:52","2015-02-26 15:06:16","2015-02-26 15:06:17",25,1,"ANSWERED","DOCUMENTATION","1424963152.0",""
"B","","s","contextB","","Local/s@contextB-00000001;2","","Hangup","","2015-02-26 15:06:13","2015-02-26 15:06:16","2015-02-26 15:06:20",7,4,"ANSWERED","DOCUMENTATION","1424963173.3",""
{noformat}

Note that there is no CDR for the {{Local/s@wait-00000000;2}} that Dialled {{Local/s@contextB-00000001;1}}.

Testing with Asterisk 13, however, this is no longer a problem. Using the same setup, I get the following CDRs:

{noformat}
"B","","s","contextB",""""" <>","Local/s@contextB-00000002;2","","Hangup","","2015-02-26 15:04:05","2015-02-26 15:04:08","2015-02-26 15:04:12",6,3,"ANSWERED","DOCUMENTATION","1424963045.5",""
"","","s","wait",""""" <>","Local/s@wait-00000001;1","","Echo","","2015-02-26 15:03:46","2015-02-26 15:04:08","2015-02-26 15:04:12",25,3,"ANSWERED","DOCUMENTATION","1424963026.2",""
"","","s","contextA",""""" <>","Local/s@wait-00000001;2","Local/s@contextB-00000002;1","Dial","Local/s@contextB/n","2015-02-26 15:03:46","2015-02-26 15:04:08","2015-02-26 15:04:12",25,3,"ANSWERED","DOCUMENTATION","1424963026.3",""
{noformat}

Note that here, we see the relationship between {{Local/s@wait-00000001;2}} and {{Local/s@contextB-00000002;1}}.

While this is a bug in Asterisk 11, CDRs - particularly in the interaction with channel masquerades (which is what occurs when the Redirect happens) - are *extremely* temperamental and prone to failure. Attempting to fix this code in 11 would certainly break CDRs in other masquerade scenarios, such as SIP initiated blind/attended transfers. The risk is extremely high that attempting to fix this issue in that branch would only cause additional problems.

Since this was fixed by the great CDR re-write in Asterisk 12, I'm going to close this issue out as Fixed in that version.