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@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@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@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@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@qsc.de>. From: "+4921653258007" <sip:+4921653258007@qsc.de
;tag=SD24vi901-88lt6slg-CC-35. CSeq: 1 INVITE. Max-Forwards: 65. P-Asserted-Identity: <sip:+4921653258007@qsc.de>. Contact: <sip:021653258007@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@qsc.de. X-ORIGINAL-DDI-URI: sip:+4921173062190950@qsc.de. X-CID: mrg5ml6g71ggh5tty7yh7hc5osy5os8y@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@qsc.de
;tag=SD24vi901-88lt6slg-CC-35. To: <sip:+4921173062190950@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@qsc.de
;tag=SD24vi901-88lt6slg-CC-35. To: <sip:+4921173062190950@qsc.de>;tag=ejS9yr5v3a6Qj. Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3. CSeq: 1 INVITE. Contact: <sip:+4921173062190950@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@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@qsc.de) Running State Change CS_NEW 2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5494 Channel sofia/external/+ 4921653258007@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@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@8000h@20i 2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:2919 Set Codec sofia/external/+4921653258007@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@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@qsc.de [BREAK] 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+4921653258007@qsc.de) Running State Change CS_INIT 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401 (sofia/external/+4921653258007@qsc.de) State INIT 2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:85 sofia/external/+ 4921653258007@qsc.de SOFIA INIT 2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:125 (sofia/external/+ 4921653258007@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@qsc.de [BREAK] 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401 (sofia/external/+4921653258007@qsc.de) State INIT going to sleep 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+4921653258007@qsc.de) Running State Change CS_ROUTING 2012-01-20 17:01:04.324734 [DEBUG] switch_channel.c:1890 (sofia/external/+ 4921653258007@qsc.de) Callstate Change DOWN -> RINGING 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410 (sofia/external/+4921653258007@qsc.de) State ROUTING 2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:148 sofia/external/+ 4921653258007@qsc.de SOFIA ROUTING 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:104 sofia/external/+4921653258007@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@qsc.de parsing [default->default] continue=false Dialplan: sofia/external/+4921653258007@qsc.de Absolute Condition [default] Dialplan: sofia/external/+4921653258007@qsc.de Action park() 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:154 (sofia/external/+4921653258007@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@qsc.de [BREAK] 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410 (sofia/external/+4921653258007@qsc.de) State ROUTING going to sleep 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+4921653258007@qsc.de) Running State Change CS_EXECUTE 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:417 (sofia/external/+4921653258007@qsc.de) State EXECUTE 2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:241 sofia/external/+ 4921653258007@qsc.de SOFIA EXECUTE 2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:192 sofia/external/+4921653258007@qsc.de Standard EXECUTE EXECUTE sofia/external/+4921653258007@qsc.de park() 2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.344716 [DEBUG] switch_ivr.c:591 sofia/external/+ 4921653258007@qsc.de Command Execute answer() EXECUTE sofia/external/+4921653258007@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@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@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@qsc.de [BREAK] 2012-01-20 17:01:04.344716 [DEBUG] switch_channel.c:3194 (sofia/external/+ 4921653258007@qsc.de) Callstate Change RINGING -> ACTIVE 2012-01-20 17:01:04.344716 [NOTICE] mod_dptools.c:1135 Channel [sofia/external/+4921653258007@qsc.de] has been answered 2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.344716 [DEBUG] sofia.c:5494 Channel sofia/external/+ 4921653258007@qsc.de entering state [completed][200] 2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.364714 [DEBUG] switch_ivr.c:591 sofia/external/+ 4921653258007@qsc.de Command Execute playback(silence_stream://100) EXECUTE sofia/external/+4921653258007@qsc.de playback(silence_stream://100) 2012-01-20 17:01:04.364714 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16@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@qsc.de [BREAK] 2012-01-20 17:01:04.484715 [DEBUG] switch_ivr.c:591 sofia/external/+ 4921653258007@qsc.de Command Execute sleep(900) EXECUTE sofia/external/+4921653258007@qsc.de sleep(900) 2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.644728 [DEBUG] sofia.c:5494 Channel sofia/external/+ 4921653258007@qsc.de entering state [ready][200] 2012-01-20 17:01:04.664735 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2852 (sofia/external/+ 4921653258007@qsc.de) Callstate Change ACTIVE -> HANGUP 2012-01-20 17:01:04.684730 [NOTICE] sofia.c:623 Hangup sofia/external/+ 4921653258007@qsc.de [CS_EXECUTE] [NORMAL_CLEARING] 2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2875 Send signal sofia/external/+4921653258007@qsc.de [KILL] 2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+4921653258007@qsc.de [BREAK] 2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:2285 sofia/external/+4921653258007@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@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@qsc.de) State EXECUTE going to sleep 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+4921653258007@qsc.de) Running State Change CS_HANGUP 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602 (sofia/external/+4921653258007@qsc.de) State HANGUP 2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:463 sofia/external/+ 4921653258007@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@qsc.de hanging up, cause: NORMAL_CLEARING 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:47 sofia/external/+4921653258007@qsc.de Standard HANGUP, cause: NORMAL_CLEARING 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602 (sofia/external/+4921653258007@qsc.de) State HANGUP going to sleep 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:393 (sofia/external/+4921653258007@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@qsc.de [BREAK] 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+4921653258007@qsc.de) Running State Change CS_REPORTING 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662 (sofia/external/+4921653258007@qsc.de) State REPORTING 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:79 sofia/external/+4921653258007@qsc.de Standard REPORTING, cause: NORMAL_CLEARING 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662 (sofia/external/+4921653258007@qsc.de) State REPORTING going to sleep 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:387 (sofia/external/+4921653258007@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@qsc.de [BREAK] 2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1380 Session 3 (sofia/external/+4921653258007@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@qsc.de) Ended 2012-01-20 17:01:04.684730 [NOTICE] switch_core_session.c:1400 Close Channel sofia/external/+4921653258007@qsc.de [CS_DESTROY] 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:491 (sofia/external/+4921653258007@qsc.de) Callstate Change HANGUP -> DOWN 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:494 (sofia/external/+4921653258007@qsc.de) Running State Change CS_DESTROY 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504 (sofia/external/+4921653258007@qsc.de) State DESTROY 2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:374 sofia/external/+ 4921653258007@qsc.de SOFIA DESTROY 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:86 sofia/external/+4921653258007@qsc.de Standard DESTROY 2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504 (sofia/external/+4921653258007@qsc.de) State DESTROY going to sleep