[asterisk-users] Problem with callfile and CDR

Wed Aug 1 13:36:56 CDT 2012

Not a "bug" but a "feature"; when you use the local channel, the CDR is
recorded "incorrectly" because you are doing a 2-leg call.

From: asterisk-users-bounces at lists.digium.com
[mailto:asterisk-users-bounces at lists.digium.com] On Behalf Of Rodrigo Lang
Sent: Wednesday, August 01, 2012 1:31 PM
To: Asterisk Users Mailing List - Non-Commercial Discussion
Subject: Re: [asterisk-users] Problem with callfile and CDR

Hey, with the "SIP" works fine. Good tip.

But is this a bug with Local?

Thanks!

Rodrigo Lang.

2012/8/1 Danny Nicholas <danny at debsinc.com>

Just a WAG, but could the "local" channel be causing some kind of problem?
Perhaps if you  changed local to SIP or DAHDI?

From: asterisk-users-bounces at lists.digium.com
[mailto:asterisk-users-bounces at lists.digium.com] On Behalf Of Rodrigo Lang
Sent: Wednesday, August 01, 2012 12:45 PM
To: Asterisk Users Mailing List - Non-Commercial Discussion
Subject: [asterisk-users] Problem with callfile and CDR

Good afternoon list.

I am experiencing a problem with the CDR and callfiles. What is happening is
this: When generating a call with a callfile, everything works perfectly,
but the CDR is recorded in the table when they answer the call destination.
The field disposition is being recorded correctly, but the duration field is
marked with the ring time and billsec is marked with 0. This just happens to
connections through callfiles. Yes, the call is working usually remains. I
did several tests with durations from seconds to 20 minutes.

I tested in two servers. With an Asterisk 1.4.44 (debian 5 64bits), and
another with Asterisk 1.8.14.0 (debian 6 64bits). In both occurs the same
problem. AND I tried using ForkCDR and ResetCDR and both did not help.

I'm doing something wrong? Has anyone experienced something similar? Any
tips? 

The callfile:

Channel: local/21411615 at test_outgoing
CallerID: "ELCO Test" <123456789>
MaxRetries: 1
RetryTime: 30
WaitTime: 25
Context: test_ivr
Extension: 21411615
Priority: 1
AlwaysDelete: Yes
Archive: Yes

The extensions.conf

[test_outgoingsaida]
exten => _X.,1,Dial(khomp/gpstn/${EXTEN},120,Ttr)
exten => _X.,2,Hangup()
[test_ivr]
exten => _X.,1,Answer()
exten => _X.,n,Wait(20)
exten => _X.,n,Hangup()

Example, console:

Log first channel:

[2012-08-01 14:29:44] DEBUG[6679] pbx.c: Launching 'Dial'

[2012-08-01 14:29:44] VERBOSE[6679] pbx.c:     -- Executing
[21411615 at test_outgoing:1] Dial("Local/21411615 at test_outgoing-cb92;2",
"khomp/gpstn/21411615,120,Ttr") in new stack

[2012-08-01 14:29:44] DEBUG[6679] devicestate.c: device 'Khomp/B1C0' state
'1'

[2012-08-01 14:29:44] DEBUG[6679] rtp_engine.c: Can't find native functions
for channel 'Khomp/B1C0-0.0'

[2012-08-01 14:29:44] DEBUG[6679] rtp_engine.c: Seeded SDP of
'Khomp/B1C0-0.0' with that of 'Local/21411615 at test_outgoing-cb92;2'

[2012-08-01 14:29:44] DEBUG[6679] channel.c: Not copying variable
DIALEDTIME.

[2012-08-01 14:29:44] DEBUG[6679] channel.c: Not copying variable
ANSWEREDTIME.

[2012-08-01 14:29:44] DEBUG[6679] channel.c: Not copying variable
DIALEDPEERNAME.

[2012-08-01 14:29:44] DEBUG[6679] channel.c: Not copying variable
DIALEDPEERNUMBER.

[2012-08-01 14:29:44] DEBUG[6679] channel.c: Not copying variable
DIALSTATUS.

[2012-08-01 14:29:44] VERBOSE[6679] app_dial.c:     -- Called
khomp/gpstn/21411615

[2012-08-01 14:29:52] VERBOSE[6679] app_dial.c:     -- Khomp/B1C0-0.0 is
ringing

[2012-08-01 14:29:53] VERBOSE[6679] app_dial.c:     -- Khomp/B1C0-0.0 is
making progress passing it to Local/21411615 at test_outgoing-cb92;2

[2012-08-01 14:30:02] VERBOSE[6679] app_dial.c:     -- Khomp/B1C0-0.0
answered Local/21411615 at test_outgoing-cb92;2

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Set channel Khomp/B1C0-0.0 to
write format slin

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Set channel Khomp/B1C0-0.0 to
read format slin

[2012-08-01 14:30:02] DEBUG[6679] features.c: Removing dialed interfaces
datastore on Khomp/B1C0-0.0 since we're bridging

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Planning to masquerade channel
Khomp/B1C0-0.0 into the structure of Local/21411615 at test_outgoing-cb92;1

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Done planning to masquerade
channel Khomp/B1C0-0.0 into the structure of
Local/21411615 at test_outgoing-cb92;1

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Set channel Khomp/B1C0-0.0 to
write format slin

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Set channel Khomp/B1C0-0.0 to
read format slin

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Putting channel Khomp/B1C0-0.0
in slin/slin formats

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Done Masquerading
Khomp/B1C0-0.0 (6)

[2012-08-01 14:30:02] DEBUG[6679] chan_local.c: Not posting to
'Local/21411615 at test_outgoing-cb92;2' queue since already masqueraded out

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Bridge stops because we're
zombie or need a soft hangup: c0=Local/21411615 at test_outgoing-cb92;2,
c1=Local/21411615 at test_outgoing-cb92;1<ZOMBIE>, flags: No,Yes,Yes,Yes

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Bridge stops bridging channels
Local/21411615 at test_outgoing-cb92;2 and
Local/21411615 at test_outgoing-cb92;1<ZOMBIE>

[2012-08-01 14:30:02] DEBUG[6679] cdr_mysql.c: Inserting a CDR record.

[2012-08-01 14:30:02] DEBUG[6679] cdr_mysql.c: SQL command as follows:
INSERT INTO cdr
(`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`
lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES
('2012-08-01 14:29:44','\"ELCO Test\"
<123456789>','123456789','21411615','test_outgoing','Local/21411615 at test_out
going-cb92;2','Khomp/B1C0-0.0','Dial','khomp/gpstn/21411615,120,Ttr','18','0
','ANSWERED','3','1343842184.19303')

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Hanging up zombie
'Local/21411615 at test_outgoing-cb92;1<ZOMBIE>'

[2012-08-01 14:30:02] DEBUG[6679] app_dial.c: Exiting with
DIALSTATUS=ANSWER.

[2012-08-01 14:30:02] DEBUG[6679] pbx.c: Spawn extension
(test_outgoing,21411615,1) exited non-zero on
'Local/21411615 at test_outgoing-cb92;2'

[2012-08-01 14:30:02] VERBOSE[6679] pbx.c:   == Spawn extension
(test_outgoing, 21411615, 1) exited non-zero on
'Local/21411615 at test_outgoing-cb92;2'

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Soft-Hanging up channel
'Local/21411615 at test_outgoing-cb92;2'

[2012-08-01 14:30:02] DEBUG[6679] channel.c: Hanging up channel
'Local/21411615 at test_outgoing-cb92;2'

Log second channel:

[2012-08-01 14:29:44] VERBOSE[6678] pbx_spool.c:     -- Attempting call on
local/21411615 at test_outgoing for 21411615 at test_ivr:1 (Retry 1)

[2012-08-01 14:30:02] DEBUG[6678] pbx.c: Launching 'Answer'

[2012-08-01 14:30:02] VERBOSE[6678] pbx.c:     -- Executing
[21411615 at test_ivr:1] Answer("Local/21411615 at test_outgoing-cb92;1", "") in
new stack

[2012-08-01 14:30:02] DEBUG[6678] pbx.c: Launching 'Wait'

[2012-08-01 14:30:02] VERBOSE[6678] pbx.c:     -- Executing
[21411615 at test_ivr:2] Wait("Local/21411615 at test_outgoing-cb92;1", "30") in
new stack

[2012-08-01 14:30:02] DEBUG[6678] channel.c: Scheduling timer at (50
requested / 50 actual) timer ticks per second

[2012-08-01 14:30:02] DEBUG[6678] channel.c: Started silence generator on
'Local/21411615 at test_outgoing-cb92;1'

[2012-08-01 14:30:34] DEBUG[6678] channel.c: Scheduling timer at (0
requested / 0 actual) timer ticks per second

[2012-08-01 14:30:34] DEBUG[6678] channel.c: Stopped silence generator on
'Khomp/B1C0-0.0'

[2012-08-01 14:30:34] DEBUG[6678] pbx.c: Launching 'Hangup'

[2012-08-01 14:30:34] VERBOSE[6678] pbx.c:     -- Executing
[21411615 at test_ivr:3] Hangup("Khomp/B1C0-0.0", "") in new stack

[2012-08-01 14:30:34] DEBUG[6678] pbx.c: Spawn extension
(test_ivr,21411615,3) exited non-zero on 'Khomp/B1C0-0.0'

[2012-08-01 14:30:34] VERBOSE[6678] pbx.c:   == Spawn extension (test_ivr,
21411615, 3) exited non-zero on 'Khomp/B1C0-0.0'

[2012-08-01 14:30:34] DEBUG[6678] channel.c: Soft-Hanging up channel
'Khomp/B1C0-0.0'

[2012-08-01 14:30:34] DEBUG[6678] channel.c: Hanging up channel
'Khomp/B1C0-0.0'

[2012-08-01 14:30:34] NOTICE[6678] pbx_spool.c: Call completed to
local/21411615 at test_outgoing

Example, table cdr (MySQL):

*************************** 46. row ***************************

     calldate: 2012-08-01 14:29:44

         clid: "ELCO Test" <123456789>

          src: 123456789

          dst: 21411615

     dcontext: test_outgoing

      channel: Local/21411615 at test_outgoing-cb92;2

   dstchannel: Khomp/B1C0-0.0

      lastapp: Dial

     lastdata: khomp/gpstn/21411615,120,Ttr

     duration: 18

      billsec: 0

  disposition: ANSWERED

     amaflags: 3

  accountcode:

     uniqueid: 1343842184.19303

    userfield:

          did:

recordingfile:

Best Regards,

-- 
Rodrigo Lang

--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
New to Asterisk? Join us for a live introductory webinar every Thurs:
               http://www.asterisk.org/hello

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

-- 
Rodrigo Lang

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20120801/554e5f69/attachment.htm>