[Freeswitch-users] G.722 negotiation issue with AVM Fritzbox

Fri Jan 20 19:28:09 MSK 2012

Hi,

It seems that FreeSwitch cannot negotiate G.722 with an AVM Fritzbox device
(*the* most popular VoIP box/router in Germany) because of what seems to be
a concatenation of several bugs.

First of all, the FritzBox sends this SDP in the INVITE:

INVITE sip:+4921173062190950 at 192.168.232.164:6060;transport=udp;gw=duro
SIP/2.0.
[...]
v=0.
o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222.
s=Sip Call.
c=IN IP4 213.148.136.222.
t=0 0.
m=audio 28800 RTP/AVP 9 8 0 102 100 99 97.
*a=rtpmap:9 G722/16000.*
a=rtpmap:8 PCMA/8000.
a=rtpmap:0 PCMU/8000.
a=rtpmap:102 G726-32/8000.
a=rtpmap:100 G726-40/8000.
a=rtpmap:99 G726-24/8000.
a=rtpmap:97 iLBC/8000.
a=ptime:30.
a=fmtp:97 mode=30.

which is wrong since RFC 3551, Section 4.5.2 clearly states that the RTP
clock is 8kHz.

We could all blame it on AVM here, but when taking a look at the "200 OK"
from FreeSwitch, that's really not what should happen:

SIP/2.0 200 OK.
[...]
v=0.
o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164.
s=FreeSWITCH.
c=IN IP4 192.168.232.164.
t=0 0.
m=audio *0* RTP/AVP 96.
*a=rtpmap:96 G722/8000.*

So FreeSwitch announces G.722/8000 (correct), but as RTP/AVP ID 96 (9 was
requested) and with *UDP Port 0*.

The FritzBox BYE's the call when it receives that.

What's even more funny is that in the FreeSwitch debugging, it says about
the local SDP:

[...]
2012-01-20 17:01:04.344716 [DEBUG] sofia_glue.c:3171 AUDIO RTP
[sofia/external/+4921653258007 at qsc.de] 192.168.232.164 port 23418 ->
213.148.136.222 port 28800 codec: 9 ms: 20
2012-01-20 17:01:04.344716 [DEBUG] switch_rtp.c:1659 Starting timer [soft]
160 bytes per 20ms
2012-01-20 17:01:04.344716 [DEBUG] mod_sofia.c:750 Local SDP
sofia/external/+4921653258007 at qsc.de:
v=0
o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164
s=FreeSWITCH
c=IN IP4 192.168.232.164
t=0 0
*m=audio 23418 RTP/AVP 9*
*a=rtpmap:9 G722/8000*
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

So there, everything is correct.

Does anyone have an idea about this one? Actually, I have taken a look at
the source but I was not able to find the point where the UDP port gets
lost...

The full debugging trace and packet capture ist attached.

Greetings,
Roland

#
U 2012/01/20 17:01:04.323112 213.148.136.222:5060 -> 192.168.232.164:6060
INVITE sip:+4921173062190950 at 192.168.232.164:6060;transport=udp;gw=duro
SIP/2.0.
Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.
Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.
To: <sip:+4921173062190950 at qsc.de>.
From: "+4921653258007" <sip:+4921653258007 at qsc.de
>;tag=SD24vi901-88lt6slg-CC-35.
CSeq: 1 INVITE.
Max-Forwards: 65.
P-Asserted-Identity: <sip:+4921653258007 at qsc.de>.
Contact: <sip:021653258007 at 213.148.136.222:5060;transport=udp>.
Allow:
INVITE,ACK,OPTIONS,BYE,CANCEL,REGISTER,INFO,PRACK,SUBSCRIBE,NOTIFY,UPDATE,MESSAGE,REFER.
User-Agent: Huawei SoftX3000 V300R010.
Supported: 100rel.
Content-Length: 352.
Content-Type: application/sdp.
P-Called-Party-ID: sip:+4921173062190950 at qsc.de.
X-ORIGINAL-DDI-URI: sip:+4921173062190950 at qsc.de.
X-CID: mrg5ml6g71ggh5tty7yh7hc5osy5os8y at SoftX3000.
.
v=0.
o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222.
s=Sip Call.
c=IN IP4 213.148.136.222.
t=0 0.
m=audio 28800 RTP/AVP 9 8 0 102 100 99 97.
a=rtpmap:9 G722/16000.
a=rtpmap:8 PCMA/8000.
a=rtpmap:0 PCMU/8000.
a=rtpmap:102 G726-32/8000.
a=rtpmap:100 G726-40/8000.
a=rtpmap:99 G726-24/8000.
a=rtpmap:97 iLBC/8000.
a=ptime:30.
a=fmtp:97 mode=30.

#
U 2012/01/20 17:01:04.323965 192.168.232.164:6060 -> 213.148.136.222:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.
From: "+4921653258007" <sip:+4921653258007 at qsc.de
>;tag=SD24vi901-88lt6slg-CC-35.
To: <sip:+4921173062190950 at qsc.de>.
Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.
CSeq: 1 INVITE.
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-cfa926d 2012-01-10 17-33-40
-0600.
Content-Length: 0.
.

#
U 2012/01/20 17:01:04.354937 192.168.232.164:6060 -> 213.148.136.222:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.
From: "+4921653258007" <sip:+4921653258007 at qsc.de
>;tag=SD24vi901-88lt6slg-CC-35.
To: <sip:+4921173062190950 at qsc.de>;tag=ejS9yr5v3a6Qj.
Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.
CSeq: 1 INVITE.
Contact: <sip:+4921173062190950 at 192.168.232.164:6060;transport=udp>.
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-cfa926d 2012-01-10 17-33-40
-0600.
Accept: application/sdp.
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER,
REFER, NOTIFY.
Supported: timer, precondition, path, replaces.
Allow-Events: talk, hold, refer.
Content-Type: application/sdp.
Content-Disposition: session.
Content-Length: 156.
P-Asserted-Identity: "+4921173062190950" <sip:+4921173062190950 at qsc.de>.
.
v=0.
o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164.
s=FreeSWITCH.
c=IN IP4 192.168.232.164.
t=0 0.
m=audio 0 RTP/AVP 96.
a=rtpmap:96 G722/8000.

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

2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_NEW
2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5494 Channel sofia/external/+
4921653258007 at qsc.de entering state [received][100]
2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5505 Remote SDP:
v=0
o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222
s=Sip Call
c=IN IP4 213.148.136.222
t=0 0
m=audio 28800 RTP/AVP 9 8 0 102 100 99 97
a=rtpmap:9 G722/16000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:102 G726-32/8000
a=rtpmap:100 G726-40/8000
a=rtpmap:99 G726-24/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=ptime:30

2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:380
(sofia/external/+4921653258007 at qsc.de) State NEW
2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:4798 Audio Codec Compare
[G722:9:16000:30:64000]/[G722:9:8000:20:64000]
2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:4814 Bah HUMBUG! Sticking
with G722 at 8000h@20i
2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:2919 Set Codec
sofia/external/+4921653258007 at qsc.de G722/8000 20 ms 160 samples 64000 bits
2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:4930 No 2833 in SDP.
 Disable 2833 dtmf and switch to INFO
2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5717 (sofia/external/+
4921653258007 at qsc.de) State Change CS_NEW -> CS_INIT
2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_INIT
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401
(sofia/external/+4921653258007 at qsc.de) State INIT
2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:85 sofia/external/+
4921653258007 at qsc.de SOFIA INIT
2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:125 (sofia/external/+
4921653258007 at qsc.de) State Change CS_INIT -> CS_ROUTING
2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401
(sofia/external/+4921653258007 at qsc.de) State INIT going to sleep
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_ROUTING
2012-01-20 17:01:04.324734 [DEBUG] switch_channel.c:1890 (sofia/external/+
4921653258007 at qsc.de) Callstate Change DOWN -> RINGING
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410
(sofia/external/+4921653258007 at qsc.de) State ROUTING
2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:148 sofia/external/+
4921653258007 at qsc.de SOFIA ROUTING
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:104
sofia/external/+4921653258007 at qsc.de Standard ROUTING
2012-01-20 17:01:04.324734 [INFO] mod_dialplan_xml.c:481 Processing
+4921653258007 <+4921653258007>->+4921173062190950 in context default
Dialplan: sofia/external/+4921653258007 at qsc.de parsing [default->default]
continue=false
Dialplan: sofia/external/+4921653258007 at qsc.de Absolute Condition [default]
Dialplan: sofia/external/+4921653258007 at qsc.de Action park()
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:154
(sofia/external/+4921653258007 at qsc.de) State Change CS_ROUTING -> CS_EXECUTE
2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410
(sofia/external/+4921653258007 at qsc.de) State ROUTING going to sleep
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_EXECUTE
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:417
(sofia/external/+4921653258007 at qsc.de) State EXECUTE
2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:241 sofia/external/+
4921653258007 at qsc.de SOFIA EXECUTE
2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:192
sofia/external/+4921653258007 at qsc.de Standard EXECUTE
EXECUTE sofia/external/+4921653258007 at qsc.de park()
2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.344716 [DEBUG] switch_ivr.c:591 sofia/external/+
4921653258007 at qsc.de Command Execute answer()
EXECUTE sofia/external/+4921653258007 at qsc.de answer()
2012-01-20 17:01:04.344716 [INFO] switch_nat.c:590 NAT port mapping disabled
2012-01-20 17:01:04.344716 [INFO] switch_nat.c:590 NAT port mapping disabled
2012-01-20 17:01:04.344716 [DEBUG] sofia_glue.c:3171 AUDIO RTP
[sofia/external/+4921653258007 at qsc.de] 192.168.232.164 port 23418 ->
213.148.136.222 port 28800 codec: 9 ms: 20
2012-01-20 17:01:04.344716 [DEBUG] switch_rtp.c:1659 Starting timer [soft]
160 bytes per 20ms
2012-01-20 17:01:04.344716 [DEBUG] mod_sofia.c:750 Local SDP
sofia/external/+4921653258007 at qsc.de:
v=0
o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164
s=FreeSWITCH
c=IN IP4 192.168.232.164
t=0 0
m=audio 23418 RTP/AVP 9
a=rtpmap:9 G722/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:729 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.344716 [DEBUG] switch_channel.c:3194 (sofia/external/+
4921653258007 at qsc.de) Callstate Change RINGING -> ACTIVE
2012-01-20 17:01:04.344716 [NOTICE] mod_dptools.c:1135 Channel
[sofia/external/+4921653258007 at qsc.de] has been answered
2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:875 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.344716 [DEBUG] sofia.c:5494 Channel sofia/external/+
4921653258007 at qsc.de entering state [completed][200]
2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.364714 [DEBUG] switch_ivr.c:591 sofia/external/+
4921653258007 at qsc.de Command Execute playback(silence_stream://100)
EXECUTE sofia/external/+4921653258007 at qsc.de playback(silence_stream://100)
2012-01-20 17:01:04.364714 [DEBUG] switch_ivr_play_say.c:1306 Codec
Activated L16 at 16000hz 1 channels 20ms
2012-01-20 17:01:04.464734 [DEBUG] switch_ivr_play_say.c:1678 done playing
file silence_stream://100
2012-01-20 17:01:04.464734 [DEBUG] switch_core_session.c:1012 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.484715 [DEBUG] switch_ivr.c:591 sofia/external/+
4921653258007 at qsc.de Command Execute sleep(900)
EXECUTE sofia/external/+4921653258007 at qsc.de sleep(900)
2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.644728 [DEBUG] sofia.c:5494 Channel sofia/external/+
4921653258007 at qsc.de entering state [ready][200]
2012-01-20 17:01:04.664735 [DEBUG] switch_core_session.c:875 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2852 (sofia/external/+
4921653258007 at qsc.de) Callstate Change ACTIVE -> HANGUP
2012-01-20 17:01:04.684730 [NOTICE] sofia.c:623 Hangup sofia/external/+
4921653258007 at qsc.de [CS_EXECUTE] [NORMAL_CLEARING]
2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2875 Send signal
sofia/external/+4921653258007 at qsc.de [KILL]
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:2285
sofia/external/+4921653258007 at qsc.de skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:2285
sofia/external/+4921653258007 at qsc.de skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:417
(sofia/external/+4921653258007 at qsc.de) State EXECUTE going to sleep
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_HANGUP
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602
(sofia/external/+4921653258007 at qsc.de) State HANGUP
2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:463 sofia/external/+
4921653258007 at qsc.de Overriding SIP cause 480 with 200 from the other leg
2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:469 Channel sofia/external/+
4921653258007 at qsc.de hanging up, cause: NORMAL_CLEARING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:47
sofia/external/+4921653258007 at qsc.de Standard HANGUP, cause: NORMAL_CLEARING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602
(sofia/external/+4921653258007 at qsc.de) State HANGUP going to sleep
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:393
(sofia/external/+4921653258007 at qsc.de) State Change CS_HANGUP ->
CS_REPORTING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_REPORTING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662
(sofia/external/+4921653258007 at qsc.de) State REPORTING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:79
sofia/external/+4921653258007 at qsc.de Standard REPORTING, cause:
NORMAL_CLEARING
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662
(sofia/external/+4921653258007 at qsc.de) State REPORTING going to sleep
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:387
(sofia/external/+4921653258007 at qsc.de) State Change CS_REPORTING ->
CS_DESTROY
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal
sofia/external/+4921653258007 at qsc.de [BREAK]
2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1380 Session 3
(sofia/external/+4921653258007 at qsc.de) Locked, Waiting on external entities
2012-01-20 17:01:04.684730 [NOTICE] switch_core_session.c:1398 Session 3
(sofia/external/+4921653258007 at qsc.de) Ended
2012-01-20 17:01:04.684730 [NOTICE] switch_core_session.c:1400 Close
Channel sofia/external/+4921653258007 at qsc.de [CS_DESTROY]
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:491
(sofia/external/+4921653258007 at qsc.de) Callstate Change HANGUP -> DOWN
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:494
(sofia/external/+4921653258007 at qsc.de) Running State Change CS_DESTROY
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504
(sofia/external/+4921653258007 at qsc.de) State DESTROY
2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:374 sofia/external/+
4921653258007 at qsc.de SOFIA DESTROY
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:86
sofia/external/+4921653258007 at qsc.de Standard DESTROY
2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504
(sofia/external/+4921653258007 at qsc.de) State DESTROY going to sleep
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120120/28e1e3ad/attachment-0001.html 