ASTERISK-17100: forkCDR - variables mismatch

[Home]

Summary: ASTERISK-17100: forkCDR - variables mismatch

Reporter: Maciej Krajewski (jamicque) Labels:

Date Opened: 2010-12-13 08:47:51.000-0600 Date Closed: 2012-05-18 04:03:27

Priority: Minor Regression?

Status: Closed/Complete Components: Applications/app_forkcdr

Versions: Frequency of
Occurrence Constant

Related
Issues:

Environment: Attachments:

Description: Beneath I paste the log from connection, where on the first glance everything is ok.
However two CDR variables named "accountcode", are misplaced in CDR's (test001 is where test005 should be).

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

-- Remote UNIX connection
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
== Using SIP VRTP TOS bits 136
== Using SIP VRTP CoS mark 4
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
[2010-12-13 15:26:22] WARNING[12816]: chan_sip.c:12302 __set_address_from_contact: Invalid contact uri spts051...3:10isac=09667e5d (missing sip: or sips:), attempting to use anyway
[2010-12-13 15:26:22] WARNING[12816]: chan_sip.c:12321 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'spts051...3'
-- Got SIP response 500 "Server Internal Error" back from 10.0.0.239
-- Executing [11@CALLEX:1] DumpChan("SIP/test005-00000000", "1") in new stack

Dumping Info For Channel: SIP/test005-00000000:
================================================================================
Info:
Name= SIP/test005-00000000
Type= SIP
UniqueID= 1292250382.0
CallerIDNum= *
CallerIDName= test001
DNIDDigits= 11
RDNIS= (N/A)
Parkinglot=
Language= en
State= Ring (4)
Rings= 0
NativeFormat= 0x4 (ulaw)
WriteFormat= 0x4 (ulaw)
ReadFormat= 0x4 (ulaw)
RawWriteFormat= 0x4 (ulaw)
RawReadFormat= 0x4 (ulaw)
1stFileDescriptor= 24
Framesin= 0
Framesout= 0
TimetoHangup= 0
ElapsedTime= 0h0m0s
Context= CALLEX
Extension= 11
Priority= 1
CallGroup=
PickupGroup=
Application= DumpChan
Data= 1
Blocking_in= (Not Blocking)

Variables:
SIPCALLID=NGJjZGE4NTE2ZDkwZDg4MGIxMzc1MGZiNTAwOTNjM2Y.
SIPDOMAIN=10.0.0.239
SIPURI=sip:test005@10.0.0.239:61201
================================================================================
-- Executing [11@CALLEX:2] GotoIf("SIP/test005-00000000", "0?3") in new stack
-- Executing [11@CALLEX:3] Set("SIP/test005-00000000", "__ORGDEST=11") in new stack
-- Executing [11@CALLEX:4] AGI("SIP/test005-00000000", "agi://127.0.0.1/script.agi") in new stack
-- AGI Script Executing Application: (Set) Options: (CHANNEL(language)=pl)
-- AGI Script Executing Application: (Set) Options: (CALLERID(all)="test005"<-15>)
-- AGI Script Executing Application: (Set) Options: (CALLERPRES()=ALLOWED_PASSED_SCREEN)
-- AGI Script Executing Application: (Set) Options: (GROUP(in)=user7)
-- AGI Script Executing Application: (Set) Options: (GROUP(out)=user2)
-- AGI Script Executing Application: (Set) Options: (_CFWD_ACCOUNT=test001)
-- AGI Script Executing Application: (Set) Options: (CDR(is_inbound)=true)
-- AGI Script Executing Application: (Set) Options: (CDR(is_outbound)=true)
-- AGI Script Executing Application: (Set) Options: (CDR(number_a)=Unknown)
-- AGI Script Executing Application: (Set) Options: (CDR(number_b)=-11)
-- AGI Script Executing Application: (Set) Options: (CDR(src_interface)=CALLEX/test005)
-- AGI Script Executing Application: (Set) Options: (CDR(dst_interface)=CALLEX/test001)
-- AGI Script Executing Application: (Set) Options: (CDR(src_account)=test005)
-- AGI Script Executing Application: (Set) Options: (CDR(dst_account)=test001)
-- AGI Script Executing Application: (Set) Options: (CDR(accountcode)=test005)
-- AGI Script Executing Application: (Set) Options: (CDR(acd)=test005)
-- AGI Script Executing Application: (Set) Options: (CDR(userfield)=UID:1292250382.0;CRG:1;ACD:test005;)
-- AGI Script Executing Application: (ForkCDR) Options: ()
-- AGI Script Executing Application: (Set) Options: (CALLERID(all)="test001"<+48583509012>)
-- AGI Script Executing Application: (Set) Options: (CALLERPRES()=ALLOWED_PASSED_SCREEN)
-- AGI Script Executing Application: (Set) Options: (GROUP(in)=user2)
-- AGI Script Executing Application: (Set) Options: (GROUP(out)=sip11)
-- AGI Script Executing Application: (Set) Options: (TIMEOUT(absolute)=438)
Channel will hangup at 2010-12-13 15:33:40.870 CET.
-- AGI Script Executing Application: (Set) Options: (CDR(is_inbound)=false)
-- AGI Script Executing Application: (Set) Options: (CDR(is_outbound)=true)
-- AGI Script Executing Application: (Set) Options: (CDR(number_a)=+48583509012)
-- AGI Script Executing Application: (Set) Options: (CDR(number_b)=+48605188514)
-- AGI Script Executing Application: (Set) Options: (CDR(src_interface)=CALLEX/test001)
-- AGI Script Executing Application: (Set) Options: (CDR(dst_interface)=SIP/jankow)
-- AGI Script Executing Application: (Set) Options: (CDR(src_account)=test001)
-- AGI Script Executing Application: (Set) Options: (CDR(sip_proxy_host)=sip.freeconet.pl)
-- AGI Script Executing Application: (Set) Options: (CDR(accountcode)=test001)
-- AGI Script Executing Application: (Set) Options: (CDR(acd)=test001)
-- AGI Script Executing Application: (Set) Options: (CDR(userfield)=UID:1292250382.0;CRG:1;ACD:test001;)
-- AGI Script Executing Application: (Set) Options: (_CALLUNIQUEID=1292250382.0)
-- AGI Script Executing Application: (Set) Options: (_NUMBER_A=15)
-- AGI Script Executing Application: (Set) Options: (_NUMBER_B=48605188514)
-- AGI Script Executing Application: (Monitor) Options: (wav,2010-12-13_15-26-22_15_48605188514,mb)
-- AGI Script Executing Application: (Set) Options: (__CALLRECORDER_RECORDID=545)
-- AGI Script Executing Application: (Dial) Options: (SIP/+48605188514@jankow,45,wW)
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
== Using SIP VRTP TOS bits 136
== Using SIP VRTP CoS mark 4
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
> doing dnsmgr_lookup for 'sip.freeconet.pl'
-- Called +48605188514@jankow
-- SIP/jankow-00000001 is making progress passing it to SIP/test005-00000000
-- SIP/jankow-00000001 is ringing
-- <SIP/test005-00000000>AGI Script agi://127.0.0.1/script.agi completed, returning -1
-- Executing [h@CALLEX:1] NoOp("SIP/test005-00000000", ""po AGI ===================="h" "11"") in new stack
-- Executing [h@CALLEX:2] Hangup("SIP/test005-00000000", "") in new stack
== Spawn extension (CALLEX, h, 2) exited non-zero on 'SIP/test005-00000000'
> [INSERT INTO cdr (clid,src,dst,dcontext,channel,lastapp,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,number_a,number_b,src_interface,dst_interface,is_outbound,is_inbound,src_account,sip_proxy_host,acd) VALUES ('"test005" <15>','15','11','CALLEX','SIP/test005-00000000','ForkCDR',5,0,'NO ANSWER',3,'test005','1292250382.0','UID:1292250382.0;CRG:1;ACD:test005;','+48583509012','+48605188514','CALLEX/test001','SIP/jankow','t','f','test001','sip.freeconet.pl','test001')]
> [INSERT INTO cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,number_a,number_b,src_interface,dst_interface,is_outbound,is_inbound,src_account,dst_account,acd) VALUES ('"test001" <+48583509012>','+48583509012','11','CALLEX','SIP/test005-00000000','SIP/jankow-00000001','Dial','SIP/+48605188514@jankow,45,wW',5,0,'NO ANSWER',3,'test001','1292250382.0','UID:1292250382.0;CRG:1;ACD:test001;','Unknown','-11','CALLEX/test005','CALLEX/test001','t','t','test005','test001','test005')]

Comments: By: Leif Madsen (lmadsen) 2010-12-16 10:29:09.000-0600

Please show the dialplan you're using along with the console output leading up to the DumpChan(). What you've shown us makes it impossible to reproduce and see what is going on.
By: Maciej Krajewski (jamicque) 2010-12-16 13:57:40.000-0600

Yes you are right sorry,here are more details. I've simplified the dialplan:

exten => 11,1,Set(CDR(number_a)=1)
exten => 11,n,Set(CDR(number_b)=2)
exten => 11,n,Set(CDR(accountcode)=test001)
exten => 11,n,ForkCDR()
exten => 11,n,Set(CDR(number_a)=3)
exten => 11,n,Set(CDR(number_b)=4)
exten => 11,n,Set(CDR(accountcode)=test002)
exten => 11,n,Dial(SIP/692161736@jamicque)

and here are the logs:
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
== Using SIP VRTP TOS bits 136
== Using SIP VRTP CoS mark 4
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
-- Executing [11@CALLEX:1] Set("SIP/test001-00000003", "CDR(number_a)=1") in new stack
-- Executing [11@CALLEX:2] Set("SIP/test001-00000003", "CDR(number_b)=2") in new stack
-- Executing [11@CALLEX:3] Set("SIP/test001-00000003", "CDR(accountcode)=test001") in new stack
-- Executing [11@CALLEX:4] ForkCDR("SIP/test001-00000003", "") in new stack
-- Executing [11@CALLEX:5] Set("SIP/test001-00000003", "CDR(number_a)=3") in new stack
-- Executing [11@CALLEX:6] Set("SIP/test001-00000003", "CDR(number_b)=4") in new stack
-- Executing [11@CALLEX:7] Set("SIP/test001-00000003", "CDR(accountcode)=test002") in new stack
-- Executing [11@CALLEX:8] Dial("SIP/test001-00000003", "SIP/692161736@jamicque") in new stack
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
== Using SIP VRTP TOS bits 136
== Using SIP VRTP CoS mark 4
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
-- Called 692161736@jamicque
-- SIP/jamicque-00000004 is making progress passing it to SIP/test001-00000003
== Spawn extension (CALLEX, 11, 8) exited non-zero on 'SIP/test001-00000003'
-- Executing [h@CALLEX:1] NoOp("SIP/test001-00000003", ""po AGI ===================="h" """) in new stack
-- Executing [h@CALLEX:2] Hangup("SIP/test001-00000003", "") in new stack
== Spawn extension (CALLEX, h, 2) exited non-zero on 'SIP/test001-00000003'
> [INSERT INTO cdr (clid,src,dst,dcontext,channel,lastapp,duration,billsec,disposition,amaflags,accountcode,uniqueid,number_a,number_b) VALUES ('*','*','11','CALLEX','SIP/test001-00000003','ForkCDR',1,0,'NO ANSWER',3,'test001','1292529315.3','3','4')]
> [INSERT INTO cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,number_a,number_b) VALUES ('*','*','11','CALLEX','SIP/test001-00000003','SIP/jamicque-00000004','Dial','SIP/692161736@jamicque',1,0,'NO ANSWER',3,'test002','1292529315.3','1','2')]

You can see clearly here that the variable accountcode is misplaced.
By: Maciej Krajewski (jamicque) 2011-06-07 12:51:28.338-0500

this bug still exists in 1.8.4.2
By: Maciej Krajewski (jamicque) 2012-05-17 04:09:54.702-0500

The problem still exists in newest vesrion of asterisk.
The problem occurs also in different call scenario:
ORIGINATE via AMI to test001 setting 2 variables: CDR(number_a)=1,CDR(number_b)=2
{code}
Action: Originate
Channel: SIP/test001
Context: TEST
Exten: 11
Priority: 1
Variable: CDR(number_a)=1,CDR(number_b)=2
{code}

the dialplan
{code}
exten => 11,n,ForkCDR()
exten => 11,n,Set(CDR(number_a)=3)
exten => 11,n,Set(CDR(number_b)=4)
exten => 11,n,Dial(SIP/test002,5)
{code}
After the has been picked up by test001 and no answered byc test002 (timeout)the log in the console is as followed:
{code}
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
> Channel SIP/test001-0000000a was answered.
-- Executing [11@TEST:1] GotoIf("SIP/test001-0000000a", "0?3") in new stack
-- Executing [11@TEST:2] ForkCDR("SIP/test001-0000000a", "") in new stack
-- Executing [11@TEST:3] Set("SIP/test001-0000000a", "CDR(number_a)=3") in new stack
-- Executing [11@TEST:4] Set("SIP/test001-0000000a", "CDR(number_b)=4") in new stack
-- Executing [11@TEST:5] Dial("SIP/test001-0000000a", "SIP/test002,5") in new stack
== Using UDPTL TOS bits 136
== Using UDPTL CoS mark 4
== Using SIP RTP TOS bits 136
== Using SIP RTP CoS mark 4
-- Called SIP/test002
-- SIP/test002-0000000b is ringing
-- Nobody picked up in 5000 ms
-- Auto fallthrough, channel 'SIP/test001-0000000a' status is 'NOANSWER'
-- Executing [h@TEST:1] Hangup("SIP/test001-0000000a", "") in new stack
== Spawn extension (TEST, h, 1) exited non-zero on 'SIP/test001-0000000a'
> [INSERT INTO cdr (dst,dcontext,channel,lastapp,duration,billsec,disposition,amaflags,uniqueid,number_a,number_b) VALUES ('11','TEST','SIP/test001-0000000a','ForkCDR',8,5,'ANSWERED',3,'1337244941.10','3','4')]
> [INSERT INTO cdr (dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,number_a,number_b) VALUES ('11','TEST','SIP/test001-0000000a','SIP/test002-0000000b','Dial','SIP/test002,5',5,0,'NO ANSWER',3,'1337244941.10','1','2')]
{code}

Please look at the variables CDR(number_a) & CDR(number_b) they are misplaced - in CDR here the call was answered there should be CDR(number_a)=1 and CDR(number_b)=2
and in NO ANSWER 3 and 4. And they are opposite.
By: Maciej Krajewski (jamicque) 2012-05-17 06:34:40.195-0500

The problem i probably caused by t locking the wrong CDR.
According to the documentation the original CDR should be locked, however as far as I can see the child CDR is locked - the new variables are set on original channel not the child channel.
By: Maciej Krajewski (jamicque) 2012-05-18 04:03:14.702-0500

Using fork with option "v", and setting CDR with option 'l' seems to fix the problem - the ticket can be closed.

{code}
exten => 11,n,ForkCDR(v)
exten => 11,n,Set(CDR(number_a,l)=3)
exten => 11,n,Set(CDR(number_b,l)=4)
exten => 11,n,Dial(SIP/test002,5)
{code}