Hi,<div><br></div><div>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.</div><div><br>
</div><div>First of all, the FritzBox sends this SDP in the INVITE:</div><div><br></div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div><div><font face="&#39;courier new&#39;, monospace">INVITE sip:+4921173062190950@192.168.232.164:6060;transport=udp;gw=duro SIP/2.0.</font></div>
<div><font face="&#39;courier new&#39;, monospace">[...]</font></div><div><font face="&#39;courier new&#39;, monospace">v=0.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">s=Sip Call.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">c=IN IP4 213.148.136.222.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">t=0 0.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">m=audio 28800 RTP/AVP 9 8 0 102 100 99 97.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace"><b>a=rtpmap:9 G722/16000.</b></font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:8 PCMA/8000.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:0 PCMU/8000.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:102 G726-32/8000.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:100 G726-40/8000.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:99 G726-24/8000.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">a=rtpmap:97 iLBC/8000.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">a=ptime:30.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">a=fmtp:97 mode=30.</font></div></div></blockquote><div><br></div><div>which is wrong since RFC 3551, Section 4.5.2 clearly states that the RTP clock is 8kHz.</div>
<div><br></div><div>We could all blame it on AVM here, but when taking a look at the &quot;200 OK&quot; from FreeSwitch, that&#39;s really not what should happen:</div><div><br></div><blockquote style="margin:0 0 0 40px;border:none;padding:0px">
<div><div><font face="&#39;courier new&#39;, monospace">SIP/2.0 200 OK.</font></div><div><font face="&#39;courier new&#39;, monospace">[...]</font></div><div><font face="&#39;courier new&#39;, monospace">v=0.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">s=FreeSWITCH.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace">c=IN IP4 192.168.232.164.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">t=0 0.</font></div></div><div><div><font face="&#39;courier new&#39;, monospace">m=audio <b><font color="#990000" size="4">0</font></b> RTP/AVP 96.</font></div>
</div><div><div><font face="&#39;courier new&#39;, monospace"><b>a=rtpmap:96 G722/8000.</b></font></div></div></blockquote><div><br></div><div>So FreeSwitch announces G.722/8000 (correct), but as RTP/AVP ID 96 (9 was requested) and with <b>UDP Port 0</b>.</div>
<div><br></div><div>The FritzBox BYE&#39;s the call when it receives that.</div><div><br></div><div>What&#39;s even more funny is that in the FreeSwitch debugging, it says about the local SDP:</div><div><br></div><div><br>
</div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div><div><div><font face="&#39;courier new&#39;, monospace"><div>[...]</div><div>2012-01-20 17:01:04.344716 [DEBUG] sofia_glue.c:3171 AUDIO RTP [sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>] 192.168.232.164 port 23418 -&gt; 213.148.136.222 port 28800 codec: 9 ms: 20</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_rtp.c:1659 Starting timer [soft] 160 bytes per 20ms</div></font></div><div><font face="&#39;courier new&#39;, monospace">2012-01-20 17:01:04.344716 [DEBUG] mod_sofia.c:750 Local SDP sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>:</font></div>
</div></div><div><div><div><font face="&#39;courier new&#39;, monospace">v=0</font></div></div></div><div><div><div><font face="&#39;courier new&#39;, monospace">o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164</font></div>
</div></div><div><div><div><font face="&#39;courier new&#39;, monospace">s=FreeSWITCH</font></div></div></div><div><div><div><font face="&#39;courier new&#39;, monospace">c=IN IP4 192.168.232.164</font></div></div></div><div>
<div><div><font face="&#39;courier new&#39;, monospace">t=0 0</font></div></div></div><div><div><div><font face="&#39;courier new&#39;, monospace"><b>m=audio 23418 RTP/AVP 9</b></font></div></div></div><div><div><div><font face="&#39;courier new&#39;, monospace"><b>a=rtpmap:9 G722/8000</b></font></div>
</div></div><div><div><div><font face="&#39;courier new&#39;, monospace">a=silenceSupp:off - - - -</font></div></div></div><div><div><div><font face="&#39;courier new&#39;, monospace">a=ptime:20</font></div></div></div><div>
<div><div><font face="&#39;courier new&#39;, monospace">a=sendrecv</font></div></div></div></blockquote><div><div><br></div><div>So there, everything is correct.</div><div><br></div><div>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...</div>
<div><br></div><div>The full debugging trace and packet capture ist attached.</div><div><br></div><div>Greetings,</div><div>Roland</div><div><br></div><div><br></div><div><br></div><div><br></div><div><br></div><div><br></div>
<div><div>#</div><div>U 2012/01/20 17:01:04.323112 <a href="http://213.148.136.222:5060">213.148.136.222:5060</a> -&gt; <a href="http://192.168.232.164:6060">192.168.232.164:6060</a></div><div>INVITE sip:+4921173062190950@192.168.232.164:6060;transport=udp;gw=duro SIP/2.0.</div>
<div>Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.</div><div>Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.</div><div>To: &lt;<a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>&gt;.</div>
<div>From: &quot;+4921653258007&quot; &lt;<a href="mailto:sip%3A%2B4921653258007@qsc.de">sip:+4921653258007@qsc.de</a>&gt;;tag=SD24vi901-88lt6slg-CC-35.</div><div>CSeq: 1 INVITE.</div><div>Max-Forwards: 65.</div><div>P-Asserted-Identity: &lt;<a href="mailto:sip%3A%2B4921653258007@qsc.de">sip:+4921653258007@qsc.de</a>&gt;.</div>
<div>Contact: &lt;sip:021653258007@213.148.136.222:5060;transport=udp&gt;.</div><div>Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,REGISTER,INFO,PRACK,SUBSCRIBE,NOTIFY,UPDATE,MESSAGE,REFER.</div><div>User-Agent: Huawei SoftX3000 V300R010.</div>
<div>Supported: 100rel.</div><div>Content-Length: 352.</div><div>Content-Type: application/sdp.</div><div>P-Called-Party-ID: <a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>.</div><div>X-ORIGINAL-DDI-URI: <a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>.</div>
<div>X-CID: mrg5ml6g71ggh5tty7yh7hc5osy5os8y@SoftX3000.</div><div>.</div><div>v=0.</div><div>o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222.</div><div>s=Sip Call.</div><div>c=IN IP4 213.148.136.222.</div><div>t=0 0.</div>
<div>m=audio 28800 RTP/AVP 9 8 0 102 100 99 97.</div><div>a=rtpmap:9 G722/16000.</div><div>a=rtpmap:8 PCMA/8000.</div><div>a=rtpmap:0 PCMU/8000.</div><div>a=rtpmap:102 G726-32/8000.</div><div>a=rtpmap:100 G726-40/8000.</div>
<div>a=rtpmap:99 G726-24/8000.</div><div>a=rtpmap:97 iLBC/8000.</div><div>a=ptime:30.</div><div>a=fmtp:97 mode=30.</div><div><br></div><div>#</div><div>U 2012/01/20 17:01:04.323965 <a href="http://192.168.232.164:6060">192.168.232.164:6060</a> -&gt; <a href="http://213.148.136.222:5060">213.148.136.222:5060</a></div>
<div>SIP/2.0 100 Trying.</div><div>Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.</div><div>From: &quot;+4921653258007&quot; &lt;<a href="mailto:sip%3A%2B4921653258007@qsc.de">sip:+4921653258007@qsc.de</a>&gt;;tag=SD24vi901-88lt6slg-CC-35.</div>
<div>To: &lt;<a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>&gt;.</div><div>Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.</div><div>CSeq: 1 INVITE.</div><div>User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-cfa926d 2012-01-10 17-33-40 -0600.</div>
<div>Content-Length: 0.</div><div>.</div><div><br></div><div>#</div><div>U 2012/01/20 17:01:04.354937 <a href="http://192.168.232.164:6060">192.168.232.164:6060</a> -&gt; <a href="http://213.148.136.222:5060">213.148.136.222:5060</a></div>
<div>SIP/2.0 200 OK.</div><div>Via: SIP/2.0/UDP 213.148.136.222:5060;branch=z9hG4bK7u3e5920b061csoit5d0.1.</div><div>From: &quot;+4921653258007&quot; &lt;<a href="mailto:sip%3A%2B4921653258007@qsc.de">sip:+4921653258007@qsc.de</a>&gt;;tag=SD24vi901-88lt6slg-CC-35.</div>
<div>To: &lt;<a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>&gt;;tag=ejS9yr5v3a6Qj.</div><div>Call-ID: SD24vi901-73c7d5e35e297c6dd1cbccbf5ab175ee-l65h8l3.</div><div>CSeq: 1 INVITE.</div>
<div>Contact: &lt;sip:+4921173062190950@192.168.232.164:6060;transport=udp&gt;.</div><div>User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-cfa926d 2012-01-10 17-33-40 -0600.</div><div>Accept: application/sdp.</div><div>Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY.</div>
<div>Supported: timer, precondition, path, replaces.</div><div>Allow-Events: talk, hold, refer.</div><div>Content-Type: application/sdp.</div><div>Content-Disposition: session.</div><div>Content-Length: 156.</div><div>P-Asserted-Identity: &quot;+4921173062190950&quot; &lt;<a href="mailto:sip%3A%2B4921173062190950@qsc.de">sip:+4921173062190950@qsc.de</a>&gt;.</div>
<div>.</div><div>v=0.</div><div>o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164.</div><div>s=FreeSWITCH.</div><div>c=IN IP4 192.168.232.164.</div><div>t=0 0.</div><div>m=audio 0 RTP/AVP 96.</div><div>a=rtpmap:96 G722/8000.</div>
</div><div><br></div><div><br></div><div><br></div><div><br></div><div><br></div><div>------------------------</div><div><br></div><div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_NEW</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5494 Channel sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> entering state [received][100]</div><div>2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5505 Remote SDP:</div>
<div>v=0</div><div>o=HuaweiSoftX3000 8451448 8451448 IN IP4 213.148.136.222</div><div>s=Sip Call</div><div>c=IN IP4 213.148.136.222</div><div>t=0 0</div><div>m=audio 28800 RTP/AVP 9 8 0 102 100 99 97</div><div>a=rtpmap:9 G722/16000</div>
<div>a=rtpmap:8 PCMA/8000</div><div>a=rtpmap:0 PCMU/8000</div><div>a=rtpmap:102 G726-32/8000</div><div>a=rtpmap:100 G726-40/8000</div><div>a=rtpmap:99 G726-24/8000</div><div>a=rtpmap:97 iLBC/8000</div><div>a=fmtp:97 mode=30</div>
<div>a=ptime:30</div><div><br></div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:380 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State NEW</div><div>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]</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:4814 Bah HUMBUG! Sticking with G722@8000h@20i</div><div>2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:2919 Set Codec sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> G722/8000 20 ms 160 samples 64000 bits</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] sofia_glue.c:4930 No 2833 in SDP.  Disable 2833 dtmf and switch to INFO</div><div>2012-01-20 17:01:04.324734 [DEBUG] sofia.c:5717 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State Change CS_NEW -&gt; CS_INIT</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_INIT</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State INIT</div><div>2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:85 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> SOFIA INIT</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:125 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State Change CS_INIT -&gt; CS_ROUTING</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:401 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State INIT going to sleep</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_ROUTING</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_channel.c:1890 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Callstate Change DOWN -&gt; RINGING</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State ROUTING</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:148 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> SOFIA ROUTING</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:104 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Standard ROUTING</div>
<div>2012-01-20 17:01:04.324734 [INFO] mod_dialplan_xml.c:481 Processing +4921653258007 &lt;+4921653258007&gt;-&gt;+4921173062190950 in context default</div><div>Dialplan: sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> parsing [default-&gt;default] continue=false</div>
<div>Dialplan: sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Absolute Condition [default]</div><div>Dialplan: sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Action park() </div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:154 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State Change CS_ROUTING -&gt; CS_EXECUTE</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:410 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State ROUTING going to sleep</div><div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_EXECUTE</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:417 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State EXECUTE</div><div>2012-01-20 17:01:04.324734 [DEBUG] mod_sofia.c:241 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> SOFIA EXECUTE</div>
<div>2012-01-20 17:01:04.324734 [DEBUG] switch_core_state_machine.c:192 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Standard EXECUTE</div><div>EXECUTE sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> park()</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.344716 [DEBUG] switch_ivr.c:591 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Command Execute answer()</div>
<div>EXECUTE sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> answer()</div><div>2012-01-20 17:01:04.344716 [INFO] switch_nat.c:590 NAT port mapping disabled</div><div>2012-01-20 17:01:04.344716 [INFO] switch_nat.c:590 NAT port mapping disabled</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] sofia_glue.c:3171 AUDIO RTP [sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>] 192.168.232.164 port 23418 -&gt; 213.148.136.222 port 28800 codec: 9 ms: 20</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_rtp.c:1659 Starting timer [soft] 160 bytes per 20ms</div><div>2012-01-20 17:01:04.344716 [DEBUG] mod_sofia.c:750 Local SDP sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>:</div>
<div>v=0</div><div>o=FreeSWITCH 1327051846 1327051847 IN IP4 192.168.232.164</div><div>s=FreeSWITCH</div><div>c=IN IP4 192.168.232.164</div><div>t=0 0</div><div>m=audio 23418 RTP/AVP 9</div><div>a=rtpmap:9 G722/8000</div>
<div>a=silenceSupp:off - - - -</div><div>a=ptime:20</div><div>a=sendrecv</div><div><br></div><div>2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:729 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_channel.c:3194 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Callstate Change RINGING -&gt; ACTIVE</div><div>2012-01-20 17:01:04.344716 [NOTICE] mod_dptools.c:1135 Channel [sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>] has been answered</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.344716 [DEBUG] sofia.c:5494 Channel sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> entering state [completed][200]</div>
<div>2012-01-20 17:01:04.344716 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.364714 [DEBUG] switch_ivr.c:591 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Command Execute playback(silence_stream://100)</div>
<div>EXECUTE sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> playback(silence_stream://100)</div><div>2012-01-20 17:01:04.364714 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16@16000hz 1 channels 20ms</div>
<div>2012-01-20 17:01:04.464734 [DEBUG] switch_ivr_play_say.c:1678 done playing file silence_stream://100</div><div>2012-01-20 17:01:04.464734 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div>
<div>2012-01-20 17:01:04.484715 [DEBUG] switch_ivr.c:591 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Command Execute sleep(900)</div><div>EXECUTE sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> sleep(900)</div>
<div>2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div>
<div>2012-01-20 17:01:04.624743 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.644728 [DEBUG] sofia.c:5494 Channel sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> entering state [ready][200]</div>
<div>2012-01-20 17:01:04.664735 [DEBUG] switch_core_session.c:875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2852 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Callstate Change ACTIVE -&gt; HANGUP</div>
<div>2012-01-20 17:01:04.684730 [NOTICE] sofia.c:623 Hangup sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [CS_EXECUTE] [NORMAL_CLEARING]</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_channel.c:2875 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [KILL]</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:2285 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:2285 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:417 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State EXECUTE going to sleep</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_HANGUP</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State HANGUP</div><div>2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:463 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Overriding SIP cause 480 with 200 from the other leg</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:469 Channel sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> hanging up, cause: NORMAL_CLEARING</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:47 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Standard HANGUP, cause: NORMAL_CLEARING</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:602 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State HANGUP going to sleep</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:393 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State Change CS_HANGUP -&gt; CS_REPORTING</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:362 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_REPORTING</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State REPORTING</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:79 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Standard REPORTING, cause: NORMAL_CLEARING</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:662 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State REPORTING going to sleep</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:387 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State Change CS_REPORTING -&gt; CS_DESTROY</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1180 Send signal sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [BREAK]</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_session.c:1380 Session 3 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Locked, Waiting on external entities</div>
<div>2012-01-20 17:01:04.684730 [NOTICE] switch_core_session.c:1398 Session 3 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Ended</div><div>2012-01-20 17:01:04.684730 [NOTICE] switch_core_session.c:1400 Close Channel sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> [CS_DESTROY]</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:491 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Callstate Change HANGUP -&gt; DOWN</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:494 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) Running State Change CS_DESTROY</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State DESTROY</div><div>2012-01-20 17:01:04.684730 [DEBUG] mod_sofia.c:374 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> SOFIA DESTROY</div>
<div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:86 sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a> Standard DESTROY</div><div>2012-01-20 17:01:04.684730 [DEBUG] switch_core_state_machine.c:504 (sofia/external/+<a href="mailto:4921653258007@qsc.de">4921653258007@qsc.de</a>) State DESTROY going to sleep</div>
</div><br>
</div>