[Home]

Summary:ASTERISK-13896: early media playback doesn't work
Reporter:pj (pj)Labels:
Date Opened:2009-04-04 14:59:14Date Closed:2009-04-24 08:49:31
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 14827.diff
( 1) trace.zip
( 2) trace2.zip
( 3) trace2a.zip
( 4) trace3.zip
Description:progress messages playback during callsetup doesn't work,
previous svn trunk revision - 183107, that I used before, was worked OK

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

[Apr  4 21:45:28]     -- Executing [222111333@zamestnanci:4] Dial("SIP/324-08810670", "SIP/cube-gw/*30222111333") in new stack
[Apr  4 21:45:28]     -- Called cube-gw/*30222111333
[Apr  4 21:45:30]     -- SIP/cube-gw-0882e408 is making progress passing it to SIP/324-08810670
[Apr  4 21:45:30] Audio is at 192.168.24.148 port 17012
[Apr  4 21:45:30] Adding codec 0x100 (g729) to SDP
[Apr  4 21:45:30] Adding codec 0x400 (ilbc) to SDP
[Apr  4 21:45:30] Adding non-codec 0x1 (telephone-event) to SDP
[Apr  4 21:45:30]
<--- Transmitting (NAT) to 193.85.164.154:13731 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 193.85.164.154:13731;branch=z9hG4bKduu0un2nqlirsvjlsi41mdj;received=193.85.164.154
From: <sip:324@sip.foo.bar>;tag=ke1ada3jrdhc73g7043o
To: <sip:222111333@sip.foo.bar;user=phone>;tag=as44e56757
Call-ID: UriaACjCoIdeN047xG-km45s7Ug1Sc
CSeq: 33353 INVITE
Server: SIP PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
Contact: <sip:222111333@192.168.24.148>
Content-Type: application/sdp
Content-Length: 289

v=0
o=ipbx 1606305535 1606305535 IN IP4 192.168.24.148
s=SIP Call
c=IN IP4 192.168.24.148
t=0 0
m=audio 17012 RTP/AVP 18 97 98
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:98 telephone-event/8000
a=fmtp:98 0-16
a=ptime:20
a=sendrecv
Comments:By: Joshua C. Colp (jcolp) 2009-04-04 15:17:44

Please attach complete console output with sip debug, core debug set to go to console in logger.conf and a level of at least 3, plus rtp debug. I just tested this exact scenario here and have audio working as expected.
By: pj (pj) 2009-04-04 15:33:43

asterisk sends rtp packets to completelly wrong ip address.
in my example below, client phone has ip address 193.85.164.154, but rtp debug and tcpdump shows, that asterisk sending packets to 107.16.29.8

[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004743, ts 000320, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      3.0.0.0:13944 (type 18, seq 005864, ts 000320, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004744, ts 000480, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      107.16.29.8:13944 (type 18, seq 005865, ts 000480, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004745, ts 000640, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      107.16.29.8:13944 (type 18, seq 005866, ts 000640, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004746, ts 000800, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      107.16.29.8:13944 (type 18, seq 005867, ts 000800, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004747, ts 000960, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      107.16.29.8:13944 (type 18, seq 005868, ts 000960, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004748, ts 001120, len 000020)
[Apr  4 22:30:24] Sent RTP packet to      107.16.29.8:13944 (type 18, seq 005869, ts 001120, len 000020)
[Apr  4 22:30:24] Got  RTP packet from    192.168.249.133:19160 (type 18, seq 004749, ts 001280, len 000020)
By: pj (pj) 2009-04-04 15:36:15

as consequece of above, no other audio is hear,
so issue isn't only related to early media!
By: Joshua C. Colp (jcolp) 2009-04-04 16:09:15

Please try the attached patch.
By: pj (pj) 2009-04-05 01:43:06

after applying patch it works again, thanks!
By: pj (pj) 2009-04-05 02:44:52

... but must also tell, that latest asterisk trunk Asterisk SVN-trunk-r186537 has still major issue, probably with rtp engine,
p2p bridging not working at all,
here is console log, when trying to bridge two sip channels,
after (locally?!) bridging it immediatelly drops the call.
when reverting to revision eg. 183107 it works again,
so I have suspicion, that this issue was caused by newly added module res_rtp_asterisk.so

[Apr  5 09:34:57]     -- Executing [sw-26-324@from-bill:12] Dial("SIP/icz-gw-08f91058", "SIP/324") in new stack
[Apr  5 09:34:57]     -- Called 324
[Apr  5 09:34:57]     -- SIP/324-08fae168 is ringing
[Apr  5 09:35:01]     -- SIP/324-08fae168 connected line has changed, passing it to SIP/icz-gw-08f91058
[Apr  5 09:35:01]     -- SIP/324-08fae168 answered SIP/icz-gw-08f91058
[Apr  5 09:35:01]     -- Locally bridging SIP/icz-gw-08f91058 and SIP/324-08fae168
[Apr  5 09:35:01]   == Spawn extension (from-bill, sw-26-324, 12) exited non-zero on 'SIP/icz-gw-08f91058'


By: Digium Subversion (svnbot) 2009-04-06 08:23:14

Repository: asterisk
Revision: 186563

U   trunk/main/rtp_engine.c

------------------------------------------------------------------------
r186563 | file | 2009-04-06 08:23:13 -0500 (Mon, 06 Apr 2009) | 8 lines

Pass the correct value to sizeof when copying address information.

(issue ASTERISK-13896)
Reported by: pj
Patches:
     14827.diff uploaded by file (license 11)
Tested by: pj

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=186563
By: Joshua C. Colp (jcolp) 2009-04-06 08:24:40

Okay, glad to hear it is closer. Can you please upload the information I asked for previously for this bridging issue?
By: Digium Subversion (svnbot) 2009-04-06 08:25:27

Repository: asterisk
Revision: 186564

_U  branches/1.6.2/

------------------------------------------------------------------------
r186564 | file | 2009-04-06 08:25:27 -0500 (Mon, 06 Apr 2009) | 14 lines

Blocked revisions 186563 via svnmerge

........
 r186563 | file | 2009-04-06 10:23:12 -0300 (Mon, 06 Apr 2009) | 8 lines
 
 Pass the correct value to sizeof when copying address information.
 
 (issue ASTERISK-13896)
 Reported by: pj
 Patches:
       14827.diff uploaded by file (license 11)
 Tested by: pj
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=186564
By: pj (pj) 2009-04-06 14:50:28

required trace attached - trace.zip

here are suspicious lines:
[Apr  6 21:30:00] DEBUG[12158] res_rtp_asterisk.c: No remote address on RTP instance '0x9d96030' so dropping frame
[Apr  6 21:30:01] DEBUG[12158] rtp_engine.c: rtp-engine-local-bridge: Ooh, got a hangup
[Apr  6 21:30:01] DEBUG[12158] channel.c: Returning from native bridge, channels: SIP/icz-gw-09d87808, SIP/324-09dc7b38


By: Joshua C. Colp (jcolp) 2009-04-08 11:37:38

Please update to latest SVN and give it a go.
By: pj (pj) 2009-04-08 13:26:32

it seems, it's working now fine again!
tested Asterisk SVN-trunk-r187050
small question: packet2packet bridging is now "local bridging"?

[Apr  8 20:22:24]     -- SIP/324-0a29eb18 answered SIP/icz-gw-0a26caf0
[Apr  8 20:22:24]     -- Locally bridging SIP/icz-gw-0a26caf0 and SIP/324-0a29eb18
By: Joshua C. Colp (jcolp) 2009-04-08 13:29:02

Yes. Packet2Packet is specific to the Asterisk RTP stack, so I made the name more generic in case other underlying RTP engines appear.
By: pj (pj) 2009-04-09 05:53:57

today appears, that new rtp engine is still somehow buggy. when call is established some party can't hear other. "echo test" also doesn't work for some clients (like twinkle) - call is connected, but doesn't hear entry file playback
By: Joshua C. Colp (jcolp) 2009-04-09 07:24:31

Okay, I'll need to see the sip debug, rtp debug, and core debug for that.
By: pj (pj) 2009-04-09 12:46:08

another trace attached - trace2.zip,
call to file playback (call was connected but user hear nothing)
By: Joshua C. Colp (jcolp) 2009-04-09 12:49:34

That log doesn't actually show the SIP packets themselves I'm afraid or rtp debug.
By: pj (pj) 2009-04-09 13:12:46

yes, it's because sip debug isn't logged into asterisk messages, uploading console log, but it's hard to read, because it also contain coloring control characters.
By: Joshua C. Colp (jcolp) 2009-04-10 13:21:29

I've just made some changes to the way we handle the address. I believe that an invalid value was getting into the address causing us to not be able to send it out. Can you please update and give it a go?
By: pj (pj) 2009-04-14 16:48:32

It still doesn't work,
it seems, that asterisk is sending rtp packets to private ip address of client, instead of nated public ip, even when I have nat=yes (nat:always) in sip.conf for that peer
trace3.zip attached, it contains asterisk traces and packed dump
tested trunk revision 188019
By: pj (pj) 2009-04-20 14:37:54

feedback was given, so please change status of this bugreport from "feedback" that someone can continue solving this issue, thanks.
By: Digium Subversion (svnbot) 2009-04-24 08:49:04

Repository: asterisk
Revision: 190421

U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r190421 | file | 2009-04-24 08:49:04 -0500 (Fri, 24 Apr 2009) | 5 lines

Fix nat setting on RTP instances.

(closes issue ASTERISK-13896)
Reported by: pj

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=190421
By: Digium Subversion (svnbot) 2009-04-24 08:49:30

Repository: asterisk
Revision: 190422

_U  branches/1.6.2/

------------------------------------------------------------------------
r190422 | file | 2009-04-24 08:49:30 -0500 (Fri, 24 Apr 2009) | 11 lines

Blocked revisions 190421 via svnmerge

........
 r190421 | file | 2009-04-24 10:49:03 -0300 (Fri, 24 Apr 2009) | 5 lines
 
 Fix nat setting on RTP instances.
 
 (closes issue ASTERISK-13896)
 Reported by: pj
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=190422