Incorrect data in CDR fields (Asterisk 1.8)

Asterisk Asterisk Support
1

Hello,

I’m currently using Asterisk 1.8.12.0 and I want to make my own custom CDR database table based on information from CDR fields.

When I make normal calls between two sip phones everything is ok, disposition, duration, billsec and everything else is with correct values.

When I make calls from one Asterisk to other Asterisk through SIP trunk there are problems.

  1. If the other side rejects the call, disposition=BUSY, duration and billsec (with value 0) have correct values.
  2. If the other side accepts the call, disposition=NO ANSWER, duration and billsec are 0 which is are incorrect values.
    However, in the second case I noticed that DIALSTATUS is with correct value = ANSWERED. So at the same time DIALSTATUS=ANSWERED (which is correct) and disposition=NO ANSWER(which is incorrect).
    It’s not a NAT problem as both asterisk servers and phones are in one network.

Does anybody got similar problmes and do you know how to solve or search the source of the problem?

Thanks!

2

Hello again,

The above mentioned issue is still on the line and I really hope that someone with more experience and knowledge of me will help. If it’s necessary I’ll post some debug info and configuration files but I think that this situation where disposition != dialstatus can’t be achieved by incorrect settings.

Thanks!

3

There is no real difference between extensions and trunks in Asterisk. The distinction tends to be in the dialplan. You need to produce at least verbose level 3 CLI output.

Also note that disposition isn’t derived from DIALSTATUS, although, with a straightforward dialplan, I would expect an ANSWERED dialstatus to be associated with a ANSWERED disposition.

4

Here is the CLI output:
(there is quite routing logic, at the end are the rows where I actually insert the data in my custom cdr table)

Verbosity is at least 5 Core debug is at least 5 [Jul 16 11:37:19] == Using SIP RTP TOS bits 184 [Jul 16 11:37:19] == Using SIP RTP CoS mark 5 [Jul 16 11:37:19] -- Executing [9293@from-internal:1] Set("SIP/101-00000014", "__DYNAMIC_FEATURES=conf-join#conf-accept#conf-deny#conf-start#blind-transfer#attended-transfer") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:2] NoOp("SIP/101-00000014", "Avarii (ViK),101,SIP/101-00000014") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:3] ExecIf("SIP/101-00000014", "1?Set(target=9293)") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:4] ExecIf("SIP/101-00000014", "1?Set(caller_id="SIP/101-00000014")") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:5] Set("SIP/101-00000014", "caller_id=101-00000014") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:6] Set("SIP/101-00000014", "caller_id=101-00000014") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:7] Set("SIP/101-00000014", "caller_id=101") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:8] Set("SIP/101-00000014", "src_channel=101") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:9] Set("SIP/101-00000014", "rec_en="yes"") in new stack [Jul 16 11:37:19] > Found no rows [SELECT value FROM globals WHERE parameter='''global_blacklist_en'''] [Jul 16 11:37:19] -- Executing [9293@from-internal:10] Set("SIP/101-00000014", "global_blacklist_en=""") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:11] ExecIf("SIP/101-00000014", "0?GoSub(global-blacklist,9293,1)") in new stack [Jul 16 11:37:19] > Found no rows [SELECT 1 FROM trunks WHERE name='Avarii (ViK)'] [Jul 16 11:37:19] -- Executing [9293@from-internal:12] Set("SIP/101-00000014", "isfromexternal=") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:13] ExecIf("SIP/101-00000014", "0?Set(caller_id=Avarii (ViK))") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:14] ExecIf("SIP/101-00000014", "0?Set(isfrominternal=0):Set(isfrominternal=1)") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:15] ExecIf("SIP/101-00000014", "1?Set(exists=1)") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:16] ExecIf("SIP/101-00000014", "0?Set(caller_id=101)") in new stack [Jul 16 11:37:19] > Found no rows [SELECT 1 FROM extensions WHERE number='9293'] [Jul 16 11:37:19] -- Executing [9293@from-internal:17] Set("SIP/101-00000014", "to_internal=") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:18] Set("SIP/101-00000014", "CDR_calldate="2012-07-16 11:37:19",CDR_src_custom="101",CDR_src_trunk=" "") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:19] Set("SIP/101-00000014", "CDR(calldate)=2012-07-16 11:37:19") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:20] Set("SIP/101-00000014", "CDR_TCS_INSERT()="1342427839.20,2012-07-16 11:37:19,101,,,,,0,0,,,"Avarii (ViK)" <101>,,,1342427839.20"") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:21] ExecIf("SIP/101-00000014", "0?Set(destination=internal-to-internal):Set(destination=to-external)") in new stack [Jul 16 11:37:19] -- Executing [9293@from-internal:22] Gosub("SIP/101-00000014", "to-external,s,1(9293)") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:1] NoOp("SIP/101-00000014", "Outgoing routing, 9293,,") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:2] Set("SIP/101-00000014", "dial_target="9293",return=,rule_priority=0") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:3] ExecIf("SIP/101-00000014", "?Set(caller_id=)") in new stack [Jul 16 11:37:19] > Found no rows [SELECT or_group FROM trunks WHERE name='101'] [Jul 16 11:37:19] -- Executing [s@to-external:4] ExecIf("SIP/101-00000014", "1?Set(or_group=test):Set(or_group=)") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:5] Set("SIP/101-00000014", "ARRAY(drop_call,rule_priority)="0,1"") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:6] ExecIf("SIP/101-00000014", "0?NoOp(There is no rule for this route):Goto(check_rule_type)") in new stack [Jul 16 11:37:19] -- Goto (to-external,s,8) [Jul 16 11:37:19] -- Executing [s@to-external:8] ExecIf("SIP/101-00000014", "0?Return()") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:9] Set("SIP/101-00000014", "ARRAY(route_trunks,strip_digits_start,add_prefix,strip_digits_end,add_postfix)="tecosys_to_test,1,,0,"") in new stack [Jul 16 11:37:19] -- Executing [s@to-external:10] Goto("SIP/101-00000014", "build_routes,1") in new stack [Jul 16 11:37:19] -- Goto (to-external,build_routes,1) [Jul 16 11:37:19] -- Executing [build_routes@to-external:1] NoOp("SIP/101-00000014", "Build routes") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:2] Set("SIP/101-00000014", "end=0,count=0") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:3] While("SIP/101-00000014", "1") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:4] Set("SIP/101-00000014", "trunk="tecosys_to_test"") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:5] Set("SIP/101-00000014", "trunk_length="16"") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:6] ExecIf("SIP/101-00000014", "0?Goto(dial_number)") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:7] Set("SIP/101-00000014", "count=1") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:8] Set("SIP/101-00000014", "trunk1=SIP/tecosys_to_test") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:9] Set("SIP/101-00000014", "route_trunks=""") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:10] Set("SIP/101-00000014", "end="1"") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:11] EndWhile("SIP/101-00000014", "") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:3] While("SIP/101-00000014", "0") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:12] Set("SIP/101-00000014", "dial_target_len="4"") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:13] Set("SIP/101-00000014", "dial_target=9293") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:14] Set("SIP/101-00000014", "dial_target=293") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:15] Set("SIP/101-00000014", "dial_target=293") in new stack [Jul 16 11:37:19] -- Executing [build_routes@to-external:16] ExecIf("SIP/101-00000014", "1?Goto(dial_number,1):NoOp(There are no selected trunks for this route)") in new stack [Jul 16 11:37:19] -- Goto (to-external,dial_number,1) [Jul 16 11:37:19] -- Executing [dial_number@to-external:1] NoOp("SIP/101-00000014", "Try to dial through each trunk") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:2] ExecIf("SIP/101-00000014", "0?Return(tecosys_to_test/293)") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:3] Set("SIP/101-00000014", "i=1") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:4] While("SIP/101-00000014", "1") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:5] Set("SIP/101-00000014", "rec_en="yes"") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:6] ExecIf("SIP/101-00000014", "1?Set(rec_en="0")") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:7] ExecIf("SIP/101-00000014", "1?Set(rec_en="0")") in new stack [Jul 16 11:37:19] -- Executing [dial_number@to-external:8] Gosub("SIP/101-00000014", "dial-to-external,s,1,(SIP/tecosys_to_test)") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:1] NoOp("SIP/101-00000014", "Try to dial through trunk and get status") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:2] Set("SIP/101-00000014", "trunk_to=SIP/tecosys_to_test") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:3] Set("SIP/101-00000014", "CALLERID(name)=101") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:4] Set("SIP/101-00000014", "CDR_dst_trunk="tecosys_to_test"") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:5] Set("SIP/101-00000014", "CDR_calldate="2012-07-16 11:37:19",CDR_dst_custom="293"") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:6] Set("SIP/101-00000014", "recording_filename="/var/spool/asterisk/monitor/2012-07-16 11-37-19 101 293.wav"") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:7] ExecIf("SIP/101-00000014", "0?MixMonitor(/var/spool/asterisk/monitor/2012-07-16 11-37-19 101 293.wav,b):Goto(put_cdr)") in new stack [Jul 16 11:37:19] -- Goto (dial-to-external,s,9) [Jul 16 11:37:19] -- Executing [s@dial-to-external:9] Set("SIP/101-00000014", "CDR(src_custom)="101",CDR(src_trunk)=" ",CDR(dst_custom)="293",CDR(dst_trunk)="tecosys_to_test",CDR(calldate)="2012-07-16 11:37:19",CDR(recorded)=""") in new stack [Jul 16 11:37:19] -- Executing [s@dial-to-external:10] Dial("SIP/101-00000014", "SIP/tecosys_to_test/293,,Ttg") in new stack [Jul 16 11:37:19] == Using SIP RTP TOS bits 184 [Jul 16 11:37:19] == Using SIP RTP CoS mark 5 [Jul 16 11:37:19] -- Called SIP/tecosys_to_test/293 [Jul 16 11:37:19] -- SIP/tecosys_to_test-00000015 is ringing [Jul 16 11:37:21] -- SIP/tecosys_to_test-00000015 answered SIP/101-00000014 [Jul 16 11:37:23] == Spawn extension (dial-to-external, s, 10) exited non-zero on 'SIP/101-00000014' [Jul 16 11:37:23] -- Executing [h@dial-to-external:1] NoOp("SIP/101-00000014", "HANGUPCAUSE=16") in new stack [Jul 16 11:37:23] -- Executing [h@dial-to-external:2] ExecIf("SIP/101-00000014", "1?Set(count=0,end=1)") in new stack [Jul 16 11:37:23] -- Executing [h@dial-to-external:3] Return("SIP/101-00000014", "") in new stack [Jul 16 11:37:23] -- Executing [dial_number@to-external:9] Set("SIP/101-00000014", "i=2") in new stack [Jul 16 11:37:23] -- Executing [dial_number@to-external:10] EndWhile("SIP/101-00000014", "") in new stack [Jul 16 11:37:23] -- Executing [dial_number@to-external:4] While("SIP/101-00000014", "0") in new stack [Jul 16 11:37:23] -- Executing [dial_number@to-external:11] GotoIf("SIP/101-00000014", "0?s,find_rule:h,1") in new stack [Jul 16 11:37:23] -- Goto (to-external,h,1) [Jul 16 11:37:23] -- Executing [h@to-external:1] Return("SIP/101-00000014", "") in new stack [Jul 16 11:37:23] -- Executing [9293@from-internal:23] Goto("SIP/101-00000014", "h,1") in new stack [Jul 16 11:37:23] -- Goto (from-internal,h,1) [Jul 16 11:37:23] -- Executing [h@from-internal:1] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,dst)=293") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:2] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,dst_trunk)=tecosys_to_test") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:3] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,record_filename)="/var/spool/asterisk/monitor/2012-07-16 11-37-19 101 293.wav"") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:4] ExecIf("SIP/101-00000014", "1?Set(CDR_TCS_UPDATE(1342427839.20,dst_all)="tecosys_to_test/293"):Set(CDR_TCS_UPDATE(,dst_all)="")") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:5] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,ring_duration)=0") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:6] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,talk_duration)=0") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:7] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,disposition)="NO ANSWER"") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:8] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,last_app)="Dial"") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:9] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,last_data)="SIP/tecosys_to_test/293,,Ttg"") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:10] Set("SIP/101-00000014", "CDR_TCS_UPDATE(1342427839.20,linked_id)="1342427839.20"") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:11] NoOp("SIP/101-00000014", "start=2012-07-16 11:37:23,answer=,end=") in new stack [Jul 16 11:37:23] -- Executing [h@from-internal:12] Return("SIP/101-00000014", "") in new stack [Jul 16 11:37:23] == Spawn extension (from-internal, h, 12) exited non-zero on 'SIP/101-00000014'

This is the code from extensions.conf which fills the table:

exten => h,1,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},dst)=${CDR_dst_custom})
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},dst_trunk)=${CDR_dst_trunk})
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},record_filename)="${recording_filename}")
exten => h,n,ExecIf($[${LEN(${or_group})}>0]?Set(CDR_TCS_UPDATE(${CDR(uniqueid)},dst_all)="${CDR_dst_trunk}/${CDR_dst_custom}"):Set(CDR_TCS_UPDATE(${cdr_id},dst_all)="${checked_targets_raw}"))
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},ring_duration)=$[${CDR(duration)}-${CDR(billsec)}])
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},talk_duration)=${CDR(billsec,r)})
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},disposition)="${CDR(disposition,r)}")
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},last_app)="${CDR(lastapp)}")
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},last_data)="${CDR(lastdata)}")
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},linked_id)="${CDR(linkedid)}")
exten => h,n,NoOP(start=${CDR(start)},answer=${CDR(answer)},end=${CDR(end)})

exten => h,n,Return()

And this is what is actually inserted in the PostgreSQL table:

[id] = ‘1342427839.20’
[calldate] = 2012-07-16 11:37:19;101
[src] = ‘101’
[src_trunk] = ‘’
[dst] = 293
[dst_trunk] = ‘tecosys_to_test’
[dst_all] = ‘tecosys_to_test/293’
[ring_duraion] = 0
[talk_duration] = 0
[disposition] = ‘NO ANSWER’
[record_filename] = ‘/var/spool/asterisk/monitor/2012-07-16 11-37-19 101 293.wav’
[caller_id] = ‘Avarii (ViK) <101>’
[last_app] = ‘Dial’
[last_data] = ‘SIP/tecosys_to_test/293’
[linked_id] = ‘1342427839.20’
[etax_date] =

And this is what is inserted for the same call in the “original” cdr table using cdr_adaptive_odbc:

[clid] = ‘“101” <101>’
[src] = ‘101’
[dst] = ‘s’
[dcontext] = ‘dial-to-external’
[channel] = ‘SIP/101-00000014’
[dstchannel] = ‘SIP/tecosys_to_test-00000015’
[lastapp] = ‘Dial’
[lastdata] = ‘SIP/tecosys_to_test/293,Ttg’
[duration] = 4
[billsec] = 2
[disposition] = ‘ANSWERED’
[amaflags] = 3
[accountcode] = ‘’
[uniqueid] = ‘1342427839.20’
[userfield] = ‘’
[src_custom] = ‘101’
[src_trunk] = ’ '
[dst_custom] = ‘293’
[dst_trunk] = ‘tecosys_to_test’
[recorded] = 0
[calldate] = ‘2012-07-16 11:37:19’

Also there aren’t any suspicious messages in asterisk’s logs

5
6

David,

This is the row which executes what you quoted:
exten => h,n,Set(CDR_TCS_UPDATE(${CDR(uniqueid)},disposition)="${CDR(disposition,r)}")

This is exactly the problem - why disposition is with value “NO ANSWER” when the call is answerd, also why duration and billsec are 0.

7

That dialplan seems to be using h extensions in non-standard ways. It would take me too long to work out whether, in particular, the return from one h extension is legitimate. I wonder if it has got the CDR for the outgoing leg confused with that for the incoming one.

8

I’ve just tested that the first time the call enters h extension (without the routing afterwards) the data is incorrect, so I guess it’s not from the way I’m using the h extension (with returns through different contexts etc).