0000307: Callfork rtp_forward doesn't work

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ Issue History ] [ Print ]

Category

Severity

Reproducibility

Date Submitted

Last Update

0000307

[Yate - Yet Another Telephony Engine] module

minor

always

2012-06-12 13:09

2015-02-13 20:06

Reporter

sega

View Status

public

Assigned To

Priority

normal

Resolution

open

Status

new

Product Version

SVN

Summary

0000307: Callfork rtp_forward doesn't work

Description

raw SDP isn't returning back to the originator, below is a part of forked call:

<sip:INFO> 'udp:91.204.65.68:5060' received 601 bytes SIP message from 91.204.65.10:5060 [0x18223f0]
------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 91.204.65.68:5060;rport;branch=z9hG4bK523501816
From: "Camel" <sip:37166011010@91.204.65.11>;tag=876864729
To: <sip:051037126588388@91.204.65.10>;tag=ds-2feae19d-4c24390663ade
Call-ID: 1981504573@91.204.65.11
CSeq: 3 INVITE
Content-Length: 227
Content-Type: application/sdp
Contact: <sip:CallAgent@ca.sertex.lv;transport=udp>

v=0
o=- 913851950 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
------
<INFO> SIPMessage::SIPMessage(0x7f2a14000f60,601) [0x7f2a1402d260]
------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 91.204.65.68:5060;rport;branch=z9hG4bK523501816
From: "Camel" <sip:37166011010@91.204.65.11>;tag=876864729
To: <sip:051037126588388@91.204.65.10>;tag=ds-2feae19d-4c24390663ade
Call-ID: 1981504573@91.204.65.11
CSeq: 3 INVITE
Content-Length: 227
Content-Type: application/sdp
Contact: <sip:CallAgent@ca.sertex.lv;transport=udp>

v=0
o=- 913851950 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
------
<ALL> SIPMessage::parse(0x7f2a14000f60,601) [0x7f2a1402d260]
<ALL> got answer version='SIP/2.0' code=180 reason='Ringing'
<ALL> MimeBody::build(0x7f2a140010d6,227,'application/sdp')
<ALL> MimeBody::MimeBody('Content-Type','application/sdp') [0x7f2a140319c0]
<ALL> SIPMessage::buildBody 8 header lines, body 0x7f2a140319c0
<ALL> SIPMessage::parse 8 header lines, body 0x7f2a140319c0
<sipengine:INFO> addMessage(0x7f2a1402d260) [0x181f640]
<sipengine:ALL> SIPTransaction processing answer 0x7f2a1402d260 'INVITE' 180 in [0x7f2a0c00b820]
<sipengine:ALL> SIPTransaction latest message changing from (nil) 0 to 0x7f2a1402d260 180 [0x7f2a0c00b820]
<sipengine:ALL> SIPMessage::complete(0x181f640,'(null)','(null)','ds-2feae19d-4c24390663ade',-1) ANS [0x7f2a1402d260]
<sipengine:ALL> SIPTransaction new 1 timeouts initially 176000000 usec apart [0x7f2a0c00b820]
<ALL> SIPEvent::SIPEvent(0x7f2a1402d260,0x7f2a0c00b820) [0x7f2a1402df20]
<sipengine:INFO> Got pending event 0x7f2a1402df20 (state Process) from transaction 0x7f2a0c00b820 [0x181f640]
<sip/4:INFO> YateSIPConnection::process(0x7f2a1402df20) active Process code=180 [0x7f2a0c0095d0]
<SIPDialog:ALL> callid '1981504573@91.204.65.11' local 'sip:37166011010@91.204.65.11;tag=876864729' remote 'sip:051037126588388@91.204.65.10;tag=(null)' [0x7f2a263e9a00]
<SIPDialog:ALL> callid '1981504573@91.204.65.11' local 'sip:37166011010@91.204.65.11;tag=876864729' remote 'sip:051037126588388@91.204.65.10;tag=ds-2feae19d-4c24390663ade' [0x7f2a0c009970]
<sip/4:INFO> YateSIPConnection got SDP [0x7f2a0c0095d0]
<ALL> SDPParser::parse(0x7f2a140319c0,(null),(nil),'',false)
<sip:ALL> Formats 'g729,g729b' mappings 'g729=18'
<ALL> SDPMedia::SDPMedia('audio','RTP/AVP','g729,g729b',4330,-1) [0x7f2a1c00ed30]
<sip:ALL> SDPSession::setMedia(0x7f2a1c00b070) [0x7f2a0c0097b0]
<sip/4:ALL> RTP addr '91.204.65.5' [0x7f2a0c0095d0]
<ALL> MimeSdpBody::buildBody() [0x7f2a140319c0]
<sipengine:ALL> Processing incoming event 0x7f2a1402df20 message 0x7f2a1402d260 [0x181f640]
<ALL> SIPEvent::~SIPEvent() [0x7f2a1402df20]
Sniffed 'call.ringing' time=1339495346.059516
  thread=0x1827000 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['id'] = 'sip/4'
  param['module'] = 'sip'
  param['status'] = 'ringing'
  param['address'] = '91.204.65.10:5060'
  param['targetid'] = 'fork/2/1'
  param['peerid'] = 'fork/2/1'
  param['lastpeerid'] = 'fork/2/1'
  param['answered'] = 'false'
  param['domain'] = '91.204.65.11'
  param['callid'] = 'sip/1981504573@91.204.65.11/876864729/ds-2feae19d-4c24390663ade'
  param['sip_content-type'] = 'application/sdp'
  param['sip_contact'] = '<sip:CallAgent@ca.sertex.lv;transport=udp>'
  param['media'] = 'yes'
  param['formats'] = 'g729,g729b'
  param['transport'] = 'RTP/AVP'
  param['rtp_mapping'] = 'g729=18'
  param['rtp_rfc2833'] = '101'
  param['sdp_sqn'] = ' 0'
  param['sdp_cdsc'] = ' 1 image udptl t38'
  param['rtp_forward'] = 'yes'
  param['rtp_addr'] = '91.204.65.5'
  param['rtp_port'] = '4330'
  param['rtp_rfc2833'] = '101'
  param['sdp_raw'] = 'v=0
o=- 913851950 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
'
<callfork:NOTE> Call 'sip/3' going on 'fork/2/1' to 'sip/4'
<cdrbuild:ALL> Emit 'update' for 'sip/4' status 'ringing'
<cdrbuild:ALL> Emit 'update' for 'sip/3' status 'ringing'
<ALL> SIPMessage::SIPMessage(0x7f2a14002fb0,180,'(null)') [0x7f2a180024a0]
<sipengine:ALL> SIPTransaction latest message changing from 0x7f2a0c000fa0 183 to 0x7f2a180024a0 180 [0x7f2a14023280]
<ALL> SIPMessage::~SIPMessage() [0x7f2a0c000fa0]
<sipengine:ALL> SIPMessage::complete(0x181f640,'(null)','(null)','1216339402',-1) OUT ANS [0x7f2a180024a0]
<sipengine:ALL> SIPTransaction new 1 timeouts initially 180000000 usec apart [0x7f2a14023280]
Returned true 'call.ringing' delay=0.003556
  thread=0x1827000 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['id'] = 'sip/4'
  param['module'] = 'sip'
  param['status'] = 'ringing'
  param['address'] = '91.204.65.10:5060'
  param['targetid'] = 'sip/3'
  param['peerid'] = 'sip/3'
  param['lastpeerid'] = 'fork/2/1'
  param['answered'] = 'false'
  param['domain'] = '91.204.65.11'
  param['callid'] = 'sip/1981504573@91.204.65.11/876864729/ds-2feae19d-4c24390663ade'
  param['sip_content-type'] = 'application/sdp'
  param['sip_contact'] = '<sip:CallAgent@ca.sertex.lv;transport=udp>'
  param['media'] = 'yes'
  param['formats'] = 'g729,g729b'
  param['transport'] = 'RTP/AVP'
  param['rtp_mapping'] = 'g729=18'
  param['rtp_rfc2833'] = '101'
  param['sdp_sqn'] = ' 0'
  param['sdp_cdsc'] = ' 1 image udptl t38'
  param['rtp_forward'] = 'yes'
  param['rtp_addr'] = '91.204.65.5'
  param['rtp_port'] = '4330'
  param['rtp_rfc2833'] = '101'
  param['sdp_raw'] = 'v=0
o=- 913851950 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
'
Sniffed 'call.cdr' time=1339495346.063002 (broadcast)
  thread=0x1827000 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['time'] = '1339495341.222'
  param['chan'] = 'sip/4'
  param['cdrid'] = '4'
  param['runid'] = '1339495244'
  param['operation'] = 'update'
  param['direction'] = 'outgoing'
  param['duration'] = '4.841'
  param['billtime'] = '0.000'
  param['ringtime'] = '0.003'
  param['status'] = 'ringing'
  param['external'] = '1000#0037126588388'
  param['cdrwrite'] = 'true'
  param['address'] = '91.204.65.10:5060'

Additional Information

And standard regex routing:

<sip:INFO> 'udp:91.204.65.68:5060' received 604 bytes SIP message from 91.204.65.10:5060 [0x24ba560]
------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 91.204.65.68:5060;rport;branch=z9hG4bK2060656246
From: "Camel" <sip:37166011010@91.204.65.68>;tag=1703178318
To: <sip:051037126588388@91.204.65.10>;tag=ds-68e895ab-4c24291c8efb2
Call-ID: 1073147275@91.204.65.68
CSeq: 3 INVITE
Content-Length: 228
Content-Type: application/sdp
Contact: <sip:CallAgent@ca.sertex.lv;transport=udp>

v=0
o=- 1099652297 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
------
<INFO> SIPMessage::SIPMessage(0x7ff03c000f60,604) [0x7ff03c02dc60]
------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 91.204.65.68:5060;rport;branch=z9hG4bK2060656246
From: "Camel" <sip:37166011010@91.204.65.68>;tag=1703178318
To: <sip:051037126588388@91.204.65.10>;tag=ds-68e895ab-4c24291c8efb2
Call-ID: 1073147275@91.204.65.68
CSeq: 3 INVITE
Content-Length: 228
Content-Type: application/sdp
Contact: <sip:CallAgent@ca.sertex.lv;transport=udp>

v=0
o=- 1099652297 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
------
<ALL> SIPMessage::parse(0x7ff03c000f60,604) [0x7ff03c02dc60]
<ALL> got answer version='SIP/2.0' code=180 reason='Ringing'
<ALL> MimeBody::build(0x7ff03c0010d8,228,'application/sdp')
<ALL> MimeBody::MimeBody('Content-Type','application/sdp') [0x7ff03c02c420]
<ALL> SIPMessage::buildBody 8 header lines, body 0x7ff03c02c420
<ALL> SIPMessage::parse 8 header lines, body 0x7ff03c02c420
<sipengine:INFO> addMessage(0x7ff03c02dc60) [0x24b77b0]
<sipengine:ALL> SIPTransaction processing answer 0x7ff03c02dc60 'INVITE' 180 in [0x7ff03400cba0]
<sipengine:ALL> SIPTransaction latest message changing from (nil) 0 to 0x7ff03c02dc60 180 [0x7ff03400cba0]
<sipengine:ALL> SIPMessage::complete(0x24b77b0,'(null)','(null)','ds-68e895ab-4c24291c8efb2',-1) ANS [0x7ff03c02dc60]
<sipengine:ALL> SIPTransaction new 1 timeouts initially 176000000 usec apart [0x7ff03400cba0]
<ALL> SIPEvent::SIPEvent(0x7ff03c02dc60,0x7ff03400cba0) [0x7ff03c02e0e0]
<sipengine:INFO> Got pending event 0x7ff03c02e0e0 (state Process) from transaction 0x7ff03400cba0 [0x24b77b0]
<sip/4:INFO> YateSIPConnection::process(0x7ff03c02e0e0) active Process code=180 [0x7ff0340082c0]
<SIPDialog:ALL> callid '1073147275@91.204.65.68' local 'sip:37166011010@91.204.65.68;tag=1703178318' remote 'sip:051037126588388@91.204.65.10;tag=(null)' [0x7ff04b452a00]
<SIPDialog:ALL> callid '1073147275@91.204.65.68' local 'sip:37166011010@91.204.65.68;tag=1703178318' remote 'sip:051037126588388@91.204.65.10;tag=ds-68e895ab-4c24291c8efb2' [0x7ff034008660]
<sip/4:INFO> YateSIPConnection got SDP [0x7ff0340082c0]
<ALL> SDPParser::parse(0x7ff03c02c420,(null),(nil),'',false)
<sip:ALL> Formats 'g729,g729b' mappings 'g729=18'
<ALL> SDPMedia::SDPMedia('audio','RTP/AVP','g729,g729b',4330,-1) [0x7ff04400b0e0]
<sip:ALL> SDPSession::setMedia(0x7ff04400e5f0) [0x7ff0340084a0]
<sip/4:ALL> RTP addr '91.204.65.5' [0x7ff0340082c0]
<ALL> MimeSdpBody::buildBody() [0x7ff03c02c420]
<sipengine:ALL> Processing incoming event 0x7ff03c02e0e0 message 0x7ff03c02dc60 [0x24b77b0]
<ALL> SIPEvent::~SIPEvent() [0x7ff03c02e0e0]
Sniffed 'call.ringing' time=1339491074.378806
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['id'] = 'sip/4'
  param['module'] = 'sip'
  param['status'] = 'ringing'
  param['address'] = '91.204.65.10:5060'
  param['targetid'] = 'sip/3'
  param['billid'] = '1339491049-2'
  param['peerid'] = 'sip/3'
  param['lastpeerid'] = 'sip/3'
  param['answered'] = 'false'
  param['callid'] = 'sip/1073147275@91.204.65.68/1703178318/ds-68e895ab-4c24291c8efb2'
  param['sip_content-type'] = 'application/sdp'
  param['sip_contact'] = '<sip:CallAgent@ca.sertex.lv;transport=udp>'
  param['media'] = 'yes'
  param['formats'] = 'g729,g729b'
  param['transport'] = 'RTP/AVP'
  param['rtp_mapping'] = 'g729=18'
  param['rtp_rfc2833'] = '101'
  param['sdp_sqn'] = ' 0'
  param['sdp_cdsc'] = ' 1 image udptl t38'
  param['rtp_forward'] = 'yes'
  param['rtp_addr'] = '91.204.65.5'
  param['rtp_port'] = '4330'
  param['rtp_rfc2833'] = '101'
  param['sdp_raw'] = 'v=0
o=- 1099652297 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
'
<cdrbuild:ALL> Emit 'update' for 'sip/4' status 'ringing'
<cdrbuild:ALL> Emit 'update' for 'sip/3' status 'ringing'
<ALL> SIPMessage::SIPMessage(0x7ff03c002fb0,180,'(null)') [0x7ff040005550]
<ALL> MimeBody::MimeBody('application/sdp') [0x7ff040001900]
<sipengine:ALL> SIPTransaction latest message changing from 0x7ff034000c70 183 to 0x7ff040005550 180 [0x7ff03c0110f0]
<ALL> SIPMessage::~SIPMessage() [0x7ff034000c70]
<sipengine:ALL> SIPMessage::complete(0x24b77b0,'(null)','(null)','2049387441',-1) OUT ANS [0x7ff040005550]
<sipengine:ALL> SIPTransaction new 1 timeouts initially 180000000 usec apart [0x7ff03c0110f0]
Returned true 'call.ringing' delay=0.005364
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['id'] = 'sip/4'
  param['module'] = 'sip'
  param['status'] = 'ringing'
  param['address'] = '91.204.65.10:5060'
  param['targetid'] = 'sip/3'
  param['billid'] = '1339491049-2'
  param['peerid'] = 'sip/3'
  param['lastpeerid'] = 'sip/3'
  param['answered'] = 'false'
  param['callid'] = 'sip/1073147275@91.204.65.68/1703178318/ds-68e895ab-4c24291c8efb2'
  param['sip_content-type'] = 'application/sdp'
  param['sip_contact'] = '<sip:CallAgent@ca.sertex.lv;transport=udp>'
  param['media'] = 'yes'
  param['formats'] = 'g729,g729b'
  param['transport'] = 'RTP/AVP'
  param['rtp_mapping'] = 'g729=18'
  param['rtp_rfc2833'] = '101'
  param['sdp_sqn'] = ' 0'
  param['sdp_cdsc'] = ' 1 image udptl t38'
  param['rtp_addr'] = '91.204.65.5'
  param['rtp_port'] = '4330'
  param['rtp_rfc2833'] = '101'
  param['sdp_raw'] = 'v=0
o=- 1099652297 0 IN IP4 91.204.65.5
s=-
c=IN IP4 91.204.65.5
t=0 0
m=audio 4330 RTP/AVP 18 101
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 image udptl t38
'
  param['rtp_forward'] = 'accepted'
Sniffed 'call.cdr' time=1339491074.383946 (broadcast)
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['time'] = '1339491069.550'
  param['chan'] = 'sip/4'
  param['cdrid'] = '4'
  param['runid'] = '1339491049'
  param['operation'] = 'update'
  param['direction'] = 'outgoing'
  param['duration'] = '4.833'
  param['billtime'] = '0.000'
  param['ringtime'] = '0.005'
  param['status'] = 'ringing'
  param['external'] = '1000#0037126588388'
  param['cdrwrite'] = 'true'
  param['address'] = '91.204.65.10:5060'
  param['caller'] = '37166011010'
  param['called'] = '1000#0037126588388'
  param['billid'] = '1339491049-2'
  param['calledfull'] = '051037126588388'
Returned false 'call.cdr' delay=0.000326 (broadcast)
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['time'] = '1339491069.550'
  param['chan'] = 'sip/4'
  param['cdrid'] = '4'
  param['runid'] = '1339491049'
  param['operation'] = 'update'
  param['direction'] = 'outgoing'
  param['duration'] = '4.833'
  param['billtime'] = '0.000'
  param['ringtime'] = '0.005'
  param['status'] = 'ringing'
  param['external'] = '1000#0037126588388'
  param['cdrwrite'] = 'true'
  param['address'] = '91.204.65.10:5060'
  param['caller'] = '37166011010'
  param['called'] = '1000#0037126588388'
  param['billid'] = '1339491049-2'
  param['calledfull'] = '051037126588388'
Sniffed 'call.cdr' time=1339491074.384020 (broadcast)
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['time'] = '1339491069.549'
  param['chan'] = 'sip/3'
  param['cdrid'] = '3'
  param['runid'] = '1339491049'
  param['operation'] = 'update'
  param['direction'] = 'incoming'
  param['duration'] = '4.835'
  param['billtime'] = '0.000'
  param['ringtime'] = '0.005'
  param['status'] = 'ringing'
  param['external'] = '37166011010'
  param['cdrwrite'] = 'true'
  param['address'] = '91.204.65.11:5060'
  param['billid'] = '1339491049-2'
  param['caller'] = '37166011010'
  param['called'] = '1000#0037126588388'
Returned false 'call.cdr' delay=0.000318 (broadcast)
  thread=0x24bb7d0 'Engine Worker'
  data=(nil)
  retval='(null)'
  param['time'] = '1339491069.549'
  param['chan'] = 'sip/3'
  param['cdrid'] = '3'
  param['runid'] = '1339491049'
  param['operation'] = 'update'
  param['direction'] = 'incoming'
  param['duration'] = '4.835'
  param['billtime'] = '0.000'
  param['ringtime'] = '0.005'
  param['status'] = 'ringing'
  param['external'] = '37166011010'

Notes
(0000460) sega (reporter) 2012-06-12 13:11	<ALL> MimeBody::MimeBody('application/sdp') is missing in forked call

(0000568) schorpp (reporter) 2015-02-13 20:03	Steps and config for reproducing? I would try to confirm the issue. Maybe http://yate.null.ro/mantis/view.php?id=381 [^] is duplicate in 1.) .

(0000569) schorpp (reporter) 2015-02-13 20:06	No such log here from my fork "experiments" with SVN rev. HEAD: $ grep -i "missing in forked call" /var/log/yate $

Issue History
Date Modified	Username	Field	Change
2012-06-12 13:09	sega	New Issue
2012-06-12 13:11	sega	Note Added: 0000460
2015-02-13 20:03	schorpp	Note Added: 0000568
2015-02-13 20:06	schorpp	Note Added: 0000569

Relationships