Hello everyone, Now that proxy media mode is working again I'm trying to figure out why T.38 with re-INVITE doesn't... Everything goes well until my end tries to re-INVITE to T.38: U 10.16.5.129:5060 -> 65.196.170.191:5060 INVITE sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Remote-Party-ID: fax_9186 <sip:fax_9186@65.196.170.191>;screen=yes;party=called. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. Max-Forwards: 70. Contact: fax_9186 <sip:fax_9186@10.16.5.129:5060>. Expires: 30. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 261. Content-Type: application/sdp. . v=0. o=- 57670 57670 IN IP4 10.16.5.129. s=-. c=IN IP4 10.16.5.129. t=0 0. m=image 16454 udptl t38. a=T38FaxVersion:0. a=T38MaxBitRate:14400. a=T38FaxRateManagement:transferredTCF. a=T38FaxMaxBuffer:200. a=T38FaxMaxDatagram:200. a=T38FaxUdpEC:t38UDPRedundancy. U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. User-Agent: Star2Star Media. Content-Length: 0. . U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. Contact: <sip:mod_sofia@65.196.170.191:5060>. User-Agent: Star2Star Media. Accept: application/sdp. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY, PUBLISH, SUBSCRIBE. Supported: timer, precondition, path, replaces. Content-Type: application/sdp. Content-Disposition: session. Content-Length: 242. . v=0. o=Sonus_UAC 881416742673069109 186840485790971511 IN IP4 65.196.170.129. s=SIP Media Capabilities. c=IN IP4 65.196.170.191. t=0 0. m=audio 19646 RTP/AVP 101. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=silenceSupp:off - - - -. U 10.16.5.129:5060 -> 65.196.170.191:5060 ACK sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-842177a7. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 ACK. Max-Forwards: 70. Contact: fax_9186 <sip:fax_9186@10.16.5.129:5060>. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 0. . U 10.16.5.129:5060 -> 65.196.170.191:5060 BYE sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-9e6b284b. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 102 BYE. Max-Forwards: 70. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 0. . U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-9e6b284b. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191>;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 102 BYE. User-Agent: Star2Star Media. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY, PUBLISH, SUBSCRIBE. Supported: timer, precondition, path, replaces. Content-Length: 0. . U 65.196.170.191:5080 -> 65.196.170.129:5060 BYE sip:gw+sip0@65.196.170.129:5080;transport=udp SIP/2.0. Via: SIP/2.0/UDP 65.196.170.191:5080;rport;branch=z9hG4bKpv9pFF0S5r9ca. Route: <sip:65.196.170.129;lr=on;ftag=3D535BNy2tS9e;did=699.54d14392>. Max-Forwards: 70. From: <sip:+15673861009@65.196.170.129>;tag=p4H9tpXS1Qv8m. To: "WIRELESS CALLER" <sip:+19412848354@65.196.170.129>;tag=3D535BNy2tS9e. Call-ID: 2d4c8faa-385d-122d-a69b-003018ae0bd3. CSeq: 121917605 BYE. Contact: <sip:+15673861009@65.196.170.191:5080;transport=udp>. User-Agent: Star2Star Media. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY. Supported: timer, precondition, path, replaces. Reason: Q.850;cause=16;text="NORMAL_CLEARING". Content-Length: 0. . It's bizarre because the re-INVITE never gets transmitted to the other leg and FreeSWITCH responds with an SDP that only supports RFC2833. Here is the FreeSWITCH level 7 log: 2009-10-20 20:54:15.577191 [NOTICE] switch_channel.c:613 New Channel sofia/s2s/+19412848354@65.196.170.129 [ba5b3890-bdba-11de-b004-d7a35c351f6f] 2009-10-20 20:54:15.577191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_NEW 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [received][100] 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 4.55.0.130 t=0 0 m=audio 26636 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20 2009-10-20 20:54:15.577191 [DEBUG] switch_core_state_machine.c:312 (sofia/s2s/+19412848354@65.196.170.129) State NEW 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3615 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_NEW -> CS_INIT 2009-10-20 20:54:15.577191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_INIT 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:330 (sofia/s2s/+19412848354@65.196.170.129) State INIT 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:83 sofia/s2s/+19412848354@65.196.170.129 SOFIA INIT 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:111 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_INIT -> CS_ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:330 (sofia/s2s/+19412848354@65.196.170.129) State INIT going to sleep 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:333 (sofia/s2s/+19412848354@65.196.170.129) State ROUTING 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:130 sofia/s2s/+19412848354@65.196.170.129 SOFIA ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:78 sofia/s2s/+19412848354@65.196.170.129 Standard ROUTING 2009-10-20 20:54:15.581191 [INFO] mod_dialplan_xml.c:391 Processing WIRELESS CALLER->fax_9186 in context s2s-in Dialplan: sofia/s2s/+19412848354@65.196.170.129 parsing [s2s-in->unloop] continue=false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/s2s/+19412848354@65.196.170.129 parsing [s2s-in->faxpass] continue=false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Absolute Condition [faxpass] Dialplan: sofia/s2s/+19412848354@65.196.170.129 Action bridge(sofia/rmt/fax_9186%rmt.star2star.com) 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:114 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_ROUTING -> CS_EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:333 (sofia/s2s/+19412848354@65.196.170.129) State ROUTING going to sleep 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:340 (sofia/s2s/+19412848354@65.196.170.129) State EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:173 sofia/s2s/+19412848354@65.196.170.129 SOFIA EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:151 sofia/s2s/+19412848354@65.196.170.129 Standard EXECUTE EXECUTE sofia/s2s/+19412848354@65.196.170.129 bridge(sofia/rmt/fax_9186%rmt.star2star.com) 2009-10-20 20:54:15.585206 [NOTICE] switch_channel.c:613 New Channel sofia/rmt/fax_9186 [ba5baee2-bdba-11de-b004-d7a35c351f6f] 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:2981 (sofia/rmt/fax_9186) State Change CS_NEW -> CS_INIT 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_INIT 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:330 (sofia/rmt/fax_9186) State INIT 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:83 sofia/rmt/fax_9186 SOFIA INIT 2009-10-20 20:54:15.585206 [DEBUG] sofia_glue.c:1328 sofia/rmt/fax_9186 Patched SDP --- v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 4.55.0.130 t=0 0 m=audio 26636 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20 +++ v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 65.196.170.191 t=0 0 m=audio 11842 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20 2009-10-20 20:54:15.585206 [DEBUG] sofia_glue.c:1761 sip:fax_9186@10.16.5.129:5060 Setting proxy route to sofia/rmt/fax_9186 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:111 (sofia/rmt/fax_9186) State Change CS_INIT -> CS_ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:330 (sofia/rmt/fax_9186) State INIT going to sleep 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:333 (sofia/rmt/fax_9186) State ROUTING 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:130 sofia/rmt/fax_9186 SOFIA ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_ivr_originate.c:66 (sofia/rmt/fax_9186) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:333 (sofia/rmt/fax_9186) State ROUTING going to sleep 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:352 (sofia/rmt/fax_9186) State CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:352 (sofia/rmt/fax_9186) State CONSUME_MEDIA going to sleep 2009-10-20 20:54:15.585206 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [calling][0] 2009-10-20 20:54:15.601186 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [proceeding][180] 2009-10-20 20:54:15.601186 [NOTICE] sofia.c:3557 Ring-Ready sofia/rmt/fax_9186! 2009-10-20 20:54:15.606802 [DEBUG] switch_ivr_originate.c:388 sofia/s2s/+19412848354@65.196.170.129 receive message [RINGING] 2009-10-20 20:54:15.606802 [NOTICE] mod_sofia.c:1525 Ring-Ready sofia/s2s/+19412848354@65.196.170.129! 2009-10-20 20:54:15.606802 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.606802 [NOTICE] switch_ivr_originate.c:388 Ring Ready sofia/s2s/+19412848354@65.196.170.129! 2009-10-20 20:54:15.609957 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [early][180] 2009-10-20 20:54:16.169195 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [ready][200] 2009-10-20 20:54:16.169195 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=audio 16458 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2009-10-20 20:54:16.169195 [DEBUG] switch_channel.c:2105 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.169195 [NOTICE] sofia.c:3948 Channel [sofia/rmt/fax_9186] has been answered 2009-10-20 20:54:16.169195 [DEBUG] sofia_glue.c:2102 Set Codec sofia/rmt/fax_9186 PROXY/8000 20 ms 160 samples 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:2379 PROXY AUDIO RTP [sofia/rmt/fax_9186] 65.196.170.191:11842->10.16.5.129:16458 codec: 0 ms: 20 2009-10-20 20:54:16.175057 [DEBUG] switch_rtp.c:1163 Not using a timer 2009-10-20 20:54:16.175057 [DEBUG] sofia.c:3961 sofia/s2s/+19412848354@65.196.170.129 receive message [ANSWER] 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:1328 sofia/s2s/+19412848354@65.196.170.129 Patched SDP --- v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=audio 16458 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 +++ v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 65.196.170.191 t=0 0 m=audio 11186 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:2102 Set Codec sofia/s2s/+19412848354@65.196.170.129 PROXY/8000 20 ms 160 samples 2009-10-20 20:54:16.177257 [DEBUG] sofia_glue.c:2379 PROXY AUDIO RTP [sofia/s2s/+19412848354@65.196.170.129] 65.196.170.191:11186->4.55.0.130:26636 codec: 0 ms: 20 2009-10-20 20:54:16.177257 [DEBUG] switch_rtp.c:1163 Not using a timer 2009-10-20 20:54:16.177257 [DEBUG] switch_ivr_originate.c:2324 sofia/s2s/+19412848354@65.196.170.129 receive message [ANSWER] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] sofia.c:407 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.182190 [NOTICE] sofia.c:3961 Channel [sofia/s2s/+19412848354@65.196.170.129] has been answered 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/s2s/+19412848354@65.196.170.129 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_originate.c:2368 Originate Resulted in Success: [sofia/rmt/fax_9186] 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/rmt/fax_9186 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/s2s/+19412848354@65.196.170.129 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] sofia.c:407 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.185443 [DEBUG] mod_sofia.c:1328 Not sending same id again "unknown" <fax_9186> 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:975 sofia/rmt/fax_9186 receive message [BRIDGE] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:653 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [completed][200] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:982 sofia/s2s/+19412848354@65.196.170.129 receive message [BRIDGE] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:1026 (sofia/rmt/fax_9186) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] switch_core_state_machine.c:343 (sofia/rmt/fax_9186) State EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] mod_sofia.c:436 SOFIA LOOPBACK 2009-10-20 20:54:16.242188 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [ready][200] 2009-10-20 20:54:16.310188 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.310188 [DEBUG] switch_core_session.c:712 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.310188 [DEBUG] switch_ivr_bridge.c:122 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.313084 [DEBUG] switch_ivr_bridge.c:122 sofia/s2s/+19412848354@65.196.170.129 receive message [DISPLAY] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [received][100] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=- 75318 75318 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=image 16458 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:200 a=T38FaxUdpEC:t38UDPRedundancy 2009-10-20 20:54:18.993185 [DEBUG] switch_core_session.c:861 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:18.993185 [DEBUG] switch_ivr_bridge.c:301 sofia/s2s/+19412848354@65.196.170.129 receive message [UNBRIDGE] 2009-10-20 20:54:18.993185 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [completed][200] 2009-10-20 20:54:19.005192 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [ready][200] 2009-10-20 20:54:19.005192 [NOTICE] sofia.c:328 Hangup sofia/rmt/fax_9186 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2009-10-20 20:54:19.005192 [DEBUG] switch_channel.c:1896 Send signal sofia/rmt/fax_9186 [KILL] 2009-10-20 20:54:19.005192 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.005192 [DEBUG] switch_core_state_machine.c:451 thread mismatch skipping state handler. 2009-10-20 20:54:19.009120 [DEBUG] switch_ivr_bridge.c:528 BRIDGE THREAD DONE [sofia/rmt/fax_9186] 2009-10-20 20:54:19.009120 [DEBUG] switch_ivr_bridge.c:530 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:343 (sofia/rmt/fax_9186) State EXCHANGE_MEDIA going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_HANGUP 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:478 (sofia/rmt/fax_9186) State HANGUP 2009-10-20 20:54:19.009120 [DEBUG] mod_sofia.c:344 Channel sofia/rmt/fax_9186 hanging up, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:46 sofia/rmt/fax_9186 Standard HANGUP, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:478 (sofia/rmt/fax_9186) State HANGUP going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:325 (sofia/rmt/fax_9186) State Change CS_HANGUP -> CS_REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:569 (sofia/rmt/fax_9186) State REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:53 sofia/rmt/fax_9186 Standard REPORTING, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:569 (sofia/rmt/fax_9186) State REPORTING going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:319 (sofia/rmt/fax_9186) State Change CS_REPORTING -> CS_DESTROY 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:1122 Session 16 (sofia/rmt/fax_9186) Locked, Waiting on external entities 2009-10-20 20:54:19.110187 [DEBUG] switch_ivr.c:540 sofia/s2s/+19412848354@65.196.170.129 Command Execute playback(local_stream://moh) EXECUTE sofia/s2s/+19412848354@65.196.170.129 playback(local_stream://moh) 2009-10-20 20:54:19.112927 [ERR] switch_core_file.c:116 Invalid file format [local_stream] for [moh]! 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:304 sofia/s2s/+19412848354@65.196.170.129 receive message [BRIDGE] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:306 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:502 sofia/s2s/+19412848354@65.196.170.129 receive message [UNBRIDGE] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:528 BRIDGE THREAD DONE [sofia/s2s/+19412848354@65.196.170.129] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:530 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.112927 [NOTICE] switch_core_state_machine.c:179 Hangup sofia/s2s/+19412848354@65.196.170.129 [CS_EXECUTE] [NORMAL_CLEARING] 2009-10-20 20:54:19.112927 [DEBUG] switch_channel.c:1896 Send signal sofia/s2s/+19412848354@65.196.170.129 [KILL] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:478 (sofia/s2s/+19412848354@65.196.170.129) State HANGUP 2009-10-20 20:54:19.112927 [DEBUG] mod_sofia.c:344 Channel sofia/s2s/+19412848354@65.196.170.129 hanging up, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] mod_sofia.c:382 Sending BYE to sofia/s2s/+19412848354@65.196.170.129 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:46 sofia/s2s/+19412848354@65.196.170.129 Standard HANGUP, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:478 (sofia/s2s/+19412848354@65.196.170.129) State HANGUP going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:340 (sofia/s2s/+19412848354@65.196.170.129) State EXECUTE going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_HANGUP 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:456 handler already called, skipping state handler. 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:325 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_HANGUP -> CS_REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:569 (sofia/s2s/+19412848354@65.196.170.129) State REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:53 sofia/s2s/+19412848354@65.196.170.129 Standard REPORTING, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:569 (sofia/s2s/+19412848354@65.196.170.129) State REPORTING going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:319 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_REPORTING -> CS_DESTROY 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:1122 Session 15 (sofia/s2s/+19412848354@65.196.170.129) Locked, Waiting on external entities 2009-10-20 20:54:19.242188 [NOTICE] switch_core_session.c:1140 Session 16 (sofia/rmt/fax_9186) Ended 2009-10-20 20:54:19.242188 [NOTICE] switch_core_session.c:1142 Close Channel sofia/rmt/fax_9186 [CS_DESTROY] 2009-10-20 20:54:19.242188 [DEBUG] switch_core_state_machine.c:415 (sofia/rmt/fax_9186) Running State Change CS_DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/rmt/fax_9186) State DESTROY 2009-10-20 20:54:19.245025 [DEBUG] mod_sofia.c:261 sofia/rmt/fax_9186 SOFIA DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:60 sofia/rmt/fax_9186 Standard DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/rmt/fax_9186) State DESTROY going to sleep 2009-10-20 20:54:19.245025 [NOTICE] switch_core_session.c:1140 Session 15 (sofia/s2s/+19412848354@65.196.170.129) Ended 2009-10-20 20:54:19.245025 [NOTICE] switch_core_session.c:1142 Close Channel sofia/s2s/+19412848354@65.196.170.129 [CS_DESTROY] 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:415 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/s2s/+19412848354@65.196.170.129) State DESTROY 2009-10-20 20:54:19.245025 [DEBUG] mod_sofia.c:261 sofia/s2s/+19412848354@65.196.170.129 SOFIA DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:60 sofia/s2s/+19412848354@65.196.170.129 Standard DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/s2s/+19412848354@65.196.170.129) State DESTROY going to sleep -- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
issue: console loglevel debug sofia profile internal siptrace on and put it on pastebin http://pastebin.freeswitch.org On Tue, Oct 20, 2009 at 3:57 PM, Kristian Kielhofner < kristian.kielhofner@gmail.com> wrote:
Hello everyone,
Now that proxy media mode is working again I'm trying to figure out why T.38 with re-INVITE doesn't...
Everything goes well until my end tries to re-INVITE to T.38:
U 10.16.5.129:5060 -> 65.196.170.191:5060 INVITE sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Remote-Party-ID: fax_9186 <sip:fax_9186@65.196.170.191<sip%3Afax_9186@65.196.170.191> ;screen=yes;party=called. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. Max-Forwards: 70. Contact: fax_9186 <sip:fax_9186@10.16.5.129:5060>. Expires: 30. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 261. Content-Type: application/sdp. . v=0. o=- 57670 57670 IN IP4 10.16.5.129. s=-. c=IN IP4 10.16.5.129. t=0 0. m=image 16454 udptl t38. a=T38FaxVersion:0. a=T38MaxBitRate:14400. a=T38FaxRateManagement:transferredTCF. a=T38FaxMaxBuffer:200. a=T38FaxMaxDatagram:200. a=T38FaxUdpEC:t38UDPRedundancy.
U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. User-Agent: Star2Star Media. Content-Length: 0. .
U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-2656bddb. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 INVITE. Contact: <sip:mod_sofia@65.196.170.191:5060>. User-Agent: Star2Star Media. Accept: application/sdp. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY, PUBLISH, SUBSCRIBE. Supported: timer, precondition, path, replaces. Content-Type: application/sdp. Content-Disposition: session. Content-Length: 242. . v=0. o=Sonus_UAC 881416742673069109 186840485790971511 IN IP4 65.196.170.129. s=SIP Media Capabilities. c=IN IP4 65.196.170.191. t=0 0. m=audio 19646 RTP/AVP 101. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=silenceSupp:off - - - -.
U 10.16.5.129:5060 -> 65.196.170.191:5060 ACK sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-842177a7. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 101 ACK. Max-Forwards: 70. Contact: fax_9186 <sip:fax_9186@10.16.5.129:5060>. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 0. .
U 10.16.5.129:5060 -> 65.196.170.191:5060 BYE sip:mod_sofia@65.196.170.191:5060 SIP/2.0. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-9e6b284b. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 102 BYE. Max-Forwards: 70. User-Agent: Linksys/SPA3102-5.1.10(GW). Content-Length: 0. .
U 65.196.170.191:5060 -> 10.16.5.129:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 10.16.5.129:5060;branch=z9hG4bK-9e6b284b. From: <sip:fax_9186@10.16.5.129:5060>;tag=9f75a042a3ca1f17i0. To: "WIRELESS CALLER" <sip:19412848354@65.196.170.191<sip%3A19412848354@65.196.170.191>
;tag=4eUH874j0eUZF. Call-ID: 2889ab05-385d-122d-07b2-0014221c0392. CSeq: 102 BYE. User-Agent: Star2Star Media. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY, PUBLISH, SUBSCRIBE. Supported: timer, precondition, path, replaces. Content-Length: 0. .
U 65.196.170.191:5080 -> 65.196.170.129:5060 BYE sip:gw+sip0@65.196.170.129:5080;transport=udp SIP/2.0. Via: SIP/2.0/UDP 65.196.170.191:5080;rport;branch=z9hG4bKpv9pFF0S5r9ca. Route: <sip:65.196.170.129;lr=on;ftag=3D535BNy2tS9e;did=699.54d14392>. Max-Forwards: 70. From: <sip:+15673861009@65.196.170.129<sip%3A%2B15673861009@65.196.170.129>
;tag=p4H9tpXS1Qv8m. To: "WIRELESS CALLER" <sip:+19412848354@65.196.170.129<sip%3A%2B19412848354@65.196.170.129> ;tag=3D535BNy2tS9e. Call-ID: 2d4c8faa-385d-122d-a69b-003018ae0bd3. CSeq: 121917605 BYE. Contact: <sip:+15673861009@65.196.170.191:5080;transport=udp>. User-Agent: Star2Star Media. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, UPDATE, NOTIFY. Supported: timer, precondition, path, replaces. Reason: Q.850;cause=16;text="NORMAL_CLEARING". Content-Length: 0. .
It's bizarre because the re-INVITE never gets transmitted to the other leg and FreeSWITCH responds with an SDP that only supports RFC2833. Here is the FreeSWITCH level 7 log:
2009-10-20 20:54:15.577191 [NOTICE] switch_channel.c:613 New Channel sofia/s2s/+19412848354@65.196.170.129 [ba5b3890-bdba-11de-b004-d7a35c351f6f] 2009-10-20 20:54:15.577191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_NEW 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [received][100] 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 4.55.0.130 t=0 0 m=audio 26636 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20
2009-10-20 20:54:15.577191 [DEBUG] switch_core_state_machine.c:312 (sofia/s2s/+19412848354@65.196.170.129) State NEW 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3615 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_NEW -> CS_INIT 2009-10-20 20:54:15.577191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_INIT 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:330 (sofia/s2s/+19412848354@65.196.170.129) State INIT 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:83 sofia/s2s/+19412848354@65.196.170.129 SOFIA INIT 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:111 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_INIT -> CS_ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:330 (sofia/s2s/+19412848354@65.196.170.129) State INIT going to sleep 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:333 (sofia/s2s/+19412848354@65.196.170.129) State ROUTING 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:130 sofia/s2s/+19412848354@65.196.170.129 SOFIA ROUTING 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:78 sofia/s2s/+19412848354@65.196.170.129 Standard ROUTING 2009-10-20 20:54:15.581191 [INFO] mod_dialplan_xml.c:391 Processing WIRELESS CALLER->fax_9186 in context s2s-in Dialplan: sofia/s2s/+19412848354@65.196.170.129 parsing [s2s-in->unloop] continue=false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/s2s/+19412848354@65.196.170.129 parsing [s2s-in->faxpass] continue=false Dialplan: sofia/s2s/+19412848354@65.196.170.129 Absolute Condition [faxpass] Dialplan: sofia/s2s/+19412848354@65.196.170.129 Action bridge(sofia/rmt/fax_9186%rmt.star2star.com) 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:114 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_ROUTING -> CS_EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:333 (sofia/s2s/+19412848354@65.196.170.129) State ROUTING going to sleep 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:340 (sofia/s2s/+19412848354@65.196.170.129) State EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:173 sofia/s2s/+19412848354@65.196.170.129 SOFIA EXECUTE 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:151 sofia/s2s/+19412848354@65.196.170.129 Standard EXECUTE EXECUTE sofia/s2s/+19412848354@65.196.170.129 bridge(sofia/rmt/fax_9186%rmt.star2star.com) 2009-10-20 20:54:15.585206 [NOTICE] switch_channel.c:613 New Channel sofia/rmt/fax_9186 [ba5baee2-bdba-11de-b004-d7a35c351f6f] 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:2981 (sofia/rmt/fax_9186) State Change CS_NEW -> CS_INIT 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_INIT 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:330 (sofia/rmt/fax_9186) State INIT 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:83 sofia/rmt/fax_9186 SOFIA INIT 2009-10-20 20:54:15.585206 [DEBUG] sofia_glue.c:1328 sofia/rmt/fax_9186 Patched SDP --- v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 4.55.0.130 t=0 0 m=audio 26636 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20
+++ v=0 o=Sonus_UAC 7412556365376427063 4600708733824463060 IN IP4 65.196.170.129 s=SIP Media Capabilities c=IN IP4 65.196.170.191 t=0 0 m=audio 11842 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:20
2009-10-20 20:54:15.585206 [DEBUG] sofia_glue.c:1761 sip:fax_9186@10.16.5.129:5060 Setting proxy route to sofia/rmt/fax_9186 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:111 (sofia/rmt/fax_9186) State Change CS_INIT -> CS_ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:330 (sofia/rmt/fax_9186) State INIT going to sleep 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:333 (sofia/rmt/fax_9186) State ROUTING 2009-10-20 20:54:15.585206 [DEBUG] mod_sofia.c:130 sofia/rmt/fax_9186 SOFIA ROUTING 2009-10-20 20:54:15.585206 [DEBUG] switch_ivr_originate.c:66 (sofia/rmt/fax_9186) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:333 (sofia/rmt/fax_9186) State ROUTING going to sleep 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:352 (sofia/rmt/fax_9186) State CONSUME_MEDIA 2009-10-20 20:54:15.585206 [DEBUG] switch_core_state_machine.c:352 (sofia/rmt/fax_9186) State CONSUME_MEDIA going to sleep 2009-10-20 20:54:15.585206 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [calling][0] 2009-10-20 20:54:15.601186 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [proceeding][180] 2009-10-20 20:54:15.601186 [NOTICE] sofia.c:3557 Ring-Ready sofia/rmt/fax_9186! 2009-10-20 20:54:15.606802 [DEBUG] switch_ivr_originate.c:388 sofia/s2s/+19412848354@65.196.170.129 receive message [RINGING] 2009-10-20 20:54:15.606802 [NOTICE] mod_sofia.c:1525 Ring-Ready sofia/s2s/+19412848354@65.196.170.129! 2009-10-20 20:54:15.606802 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:15.606802 [NOTICE] switch_ivr_originate.c:388 Ring Ready sofia/s2s/+19412848354@65.196.170.129! 2009-10-20 20:54:15.609957 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [early][180] 2009-10-20 20:54:16.169195 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [ready][200] 2009-10-20 20:54:16.169195 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=audio 16458 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
2009-10-20 20:54:16.169195 [DEBUG] switch_channel.c:2105 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.169195 [NOTICE] sofia.c:3948 Channel [sofia/rmt/fax_9186] has been answered 2009-10-20 20:54:16.169195 [DEBUG] sofia_glue.c:2102 Set Codec sofia/rmt/fax_9186 PROXY/8000 20 ms 160 samples 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:2379 PROXY AUDIO RTP [sofia/rmt/fax_9186] 65.196.170.191:11842->10.16.5.129:16458 codec: 0 ms: 20 2009-10-20 20:54:16.175057 [DEBUG] switch_rtp.c:1163 Not using a timer 2009-10-20 20:54:16.175057 [DEBUG] sofia.c:3961 sofia/s2s/+19412848354@65.196.170.129 receive message [ANSWER] 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:1328 sofia/s2s/+19412848354@65.196.170.129 Patched SDP --- v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=audio 16458 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
+++ v=0 o=- 74979 74979 IN IP4 10.16.5.129 s=- c=IN IP4 65.196.170.191 t=0 0 m=audio 11186 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:2102 Set Codec sofia/s2s/+19412848354@65.196.170.129 PROXY/8000 20 ms 160 samples 2009-10-20 20:54:16.177257 [DEBUG] sofia_glue.c:2379 PROXY AUDIO RTP [sofia/s2s/+19412848354@65.196.170.129] 65.196.170.191:11186->4.55.0.130:26636 codec: 0 ms: 20 2009-10-20 20:54:16.177257 [DEBUG] switch_rtp.c:1163 Not using a timer 2009-10-20 20:54:16.177257 [DEBUG] switch_ivr_originate.c:2324 sofia/s2s/+19412848354@65.196.170.129 receive message [ANSWER] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] sofia.c:407 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.182190 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.182190 [NOTICE] sofia.c:3961 Channel [sofia/s2s/+19412848354@65.196.170.129] has been answered 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/s2s/+19412848354@65.196.170.129 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_originate.c:2368 Originate Resulted in Success: [sofia/rmt/fax_9186] 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/rmt/fax_9186 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182 sofia/s2s/+19412848354@65.196.170.129 receive message [AUDIO_SYNC] 2009-10-20 20:54:16.185443 [DEBUG] sofia.c:407 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.185443 [DEBUG] mod_sofia.c:1328 Not sending same id again "unknown" <fax_9186> 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:975 sofia/rmt/fax_9186 receive message [BRIDGE] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:653 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [completed][200] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:982 sofia/s2s/+19412848354@65.196.170.129 receive message [BRIDGE] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:1026 (sofia/rmt/fax_9186) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.185443 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] switch_core_state_machine.c:343 (sofia/rmt/fax_9186) State EXCHANGE_MEDIA 2009-10-20 20:54:16.185443 [DEBUG] mod_sofia.c:436 SOFIA LOOPBACK 2009-10-20 20:54:16.242188 [DEBUG] sofia.c:3493 Channel sofia/s2s/+19412848354@65.196.170.129 entering state [ready][200] 2009-10-20 20:54:16.310188 [DEBUG] switch_core_session.c:712 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:16.310188 [DEBUG] switch_core_session.c:712 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:16.310188 [DEBUG] switch_ivr_bridge.c:122 sofia/rmt/fax_9186 receive message [DISPLAY] 2009-10-20 20:54:16.313084 [DEBUG] switch_ivr_bridge.c:122 sofia/s2s/+19412848354@65.196.170.129 receive message [DISPLAY] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [received][100] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3500 Remote SDP: v=0 o=- 75318 75318 IN IP4 10.16.5.129 s=- c=IN IP4 10.16.5.129 t=0 0 m=image 16458 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:200 a=T38FaxUdpEC:t38UDPRedundancy
2009-10-20 20:54:18.993185 [DEBUG] switch_core_session.c:861 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:18.993185 [DEBUG] switch_ivr_bridge.c:301 sofia/s2s/+19412848354@65.196.170.129 receive message [UNBRIDGE] 2009-10-20 20:54:18.993185 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:18.993185 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [completed][200] 2009-10-20 20:54:19.005192 [DEBUG] sofia.c:3493 Channel sofia/rmt/fax_9186 entering state [ready][200] 2009-10-20 20:54:19.005192 [NOTICE] sofia.c:328 Hangup sofia/rmt/fax_9186 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2009-10-20 20:54:19.005192 [DEBUG] switch_channel.c:1896 Send signal sofia/rmt/fax_9186 [KILL] 2009-10-20 20:54:19.005192 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.005192 [DEBUG] switch_core_state_machine.c:451 thread mismatch skipping state handler. 2009-10-20 20:54:19.009120 [DEBUG] switch_ivr_bridge.c:528 BRIDGE THREAD DONE [sofia/rmt/fax_9186] 2009-10-20 20:54:19.009120 [DEBUG] switch_ivr_bridge.c:530 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:343 (sofia/rmt/fax_9186) State EXCHANGE_MEDIA going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_HANGUP 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:478 (sofia/rmt/fax_9186) State HANGUP 2009-10-20 20:54:19.009120 [DEBUG] mod_sofia.c:344 Channel sofia/rmt/fax_9186 hanging up, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:46 sofia/rmt/fax_9186 Standard HANGUP, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:478 (sofia/rmt/fax_9186) State HANGUP going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:325 (sofia/rmt/fax_9186) State Change CS_HANGUP -> CS_REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:306 (sofia/rmt/fax_9186) Running State Change CS_REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:569 (sofia/rmt/fax_9186) State REPORTING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:53 sofia/rmt/fax_9186 Standard REPORTING, cause: NORMAL_CLEARING 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:569 (sofia/rmt/fax_9186) State REPORTING going to sleep 2009-10-20 20:54:19.009120 [DEBUG] switch_core_state_machine.c:319 (sofia/rmt/fax_9186) State Change CS_REPORTING -> CS_DESTROY 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:985 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.009120 [DEBUG] switch_core_session.c:1122 Session 16 (sofia/rmt/fax_9186) Locked, Waiting on external entities 2009-10-20 20:54:19.110187 [DEBUG] switch_ivr.c:540 sofia/s2s/+19412848354@65.196.170.129 Command Execute playback(local_stream://moh) EXECUTE sofia/s2s/+19412848354@65.196.170.129 playback(local_stream://moh) 2009-10-20 20:54:19.112927 [ERR] switch_core_file.c:116 Invalid file format [local_stream] for [moh]! 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:304 sofia/s2s/+19412848354@65.196.170.129 receive message [BRIDGE] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:306 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:502 sofia/s2s/+19412848354@65.196.170.129 receive message [UNBRIDGE] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:653 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:528 BRIDGE THREAD DONE [sofia/s2s/+19412848354@65.196.170.129] 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:530 Send signal sofia/rmt/fax_9186 [BREAK] 2009-10-20 20:54:19.112927 [NOTICE] switch_core_state_machine.c:179 Hangup sofia/s2s/+19412848354@65.196.170.129 [CS_EXECUTE] [NORMAL_CLEARING] 2009-10-20 20:54:19.112927 [DEBUG] switch_channel.c:1896 Send signal sofia/s2s/+19412848354@65.196.170.129 [KILL] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:478 (sofia/s2s/+19412848354@65.196.170.129) State HANGUP 2009-10-20 20:54:19.112927 [DEBUG] mod_sofia.c:344 Channel sofia/s2s/+19412848354@65.196.170.129 hanging up, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] mod_sofia.c:382 Sending BYE to sofia/s2s/+19412848354@65.196.170.129 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:46 sofia/s2s/+19412848354@65.196.170.129 Standard HANGUP, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:478 (sofia/s2s/+19412848354@65.196.170.129) State HANGUP going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:340 (sofia/s2s/+19412848354@65.196.170.129) State EXECUTE going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_HANGUP 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:456 handler already called, skipping state handler. 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:325 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_HANGUP -> CS_REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:306 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:569 (sofia/s2s/+19412848354@65.196.170.129) State REPORTING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:53 sofia/s2s/+19412848354@65.196.170.129 Standard REPORTING, cause: NORMAL_CLEARING 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:569 (sofia/s2s/+19412848354@65.196.170.129) State REPORTING going to sleep 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:319 (sofia/s2s/+19412848354@65.196.170.129) State Change CS_REPORTING -> CS_DESTROY 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send signal sofia/s2s/+19412848354@65.196.170.129 [BREAK] 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:1122 Session 15 (sofia/s2s/+19412848354@65.196.170.129) Locked, Waiting on external entities 2009-10-20 20:54:19.242188 [NOTICE] switch_core_session.c:1140 Session 16 (sofia/rmt/fax_9186) Ended 2009-10-20 20:54:19.242188 [NOTICE] switch_core_session.c:1142 Close Channel sofia/rmt/fax_9186 [CS_DESTROY] 2009-10-20 20:54:19.242188 [DEBUG] switch_core_state_machine.c:415 (sofia/rmt/fax_9186) Running State Change CS_DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/rmt/fax_9186) State DESTROY 2009-10-20 20:54:19.245025 [DEBUG] mod_sofia.c:261 sofia/rmt/fax_9186 SOFIA DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:60 sofia/rmt/fax_9186 Standard DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/rmt/fax_9186) State DESTROY going to sleep 2009-10-20 20:54:19.245025 [NOTICE] switch_core_session.c:1140 Session 15 (sofia/s2s/+19412848354@65.196.170.129) Ended 2009-10-20 20:54:19.245025 [NOTICE] switch_core_session.c:1142 Close Channel sofia/s2s/+19412848354@65.196.170.129 [CS_DESTROY] 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:415 (sofia/s2s/+19412848354@65.196.170.129) Running State Change CS_DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/s2s/+19412848354@65.196.170.129) State DESTROY 2009-10-20 20:54:19.245025 [DEBUG] mod_sofia.c:261 sofia/s2s/+19412848354@65.196.170.129 SOFIA DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:60 sofia/s2s/+19412848354@65.196.170.129 Standard DESTROY 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426 (sofia/s2s/+19412848354@65.196.170.129) State DESTROY going to sleep
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
Anthony, I will the next chance I get. Thanks! On Tue, Oct 20, 2009 at 5:34 PM, Anthony Minessale <anthony.minessale@gmail.com> wrote:
issue: console loglevel debug sofia profile internal siptrace on
and put it on pastebin http://pastebin.freeswitch.org
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
Done. On Tue, Oct 20, 2009 at 5:34 PM, Anthony Minessale <anthony.minessale@gmail.com> wrote:
issue: console loglevel debug sofia profile internal siptrace on
and put it on pastebin http://pastebin.freeswitch.org
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
can you try trunk and let me know right away, if it's still not working i may need ssh access and call you on the phone. On Tue, Oct 20, 2009 at 10:50 PM, Kristian Kielhofner < kristian.kielhofner@gmail.com> wrote:
Done.
On Tue, Oct 20, 2009 at 5:34 PM, Anthony Minessale <anthony.minessale@gmail.com> wrote:
issue: console loglevel debug sofia profile internal siptrace on
and put it on pastebin http://pastebin.freeswitch.org
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:213-799-1400
An update for Tony, Brian, Mike, and everyone on the list... I was able to get some phone time with the team yesterday. Tony worked on my machine, found the issue, and had it committed within 30 minutes. I've been testing T.38 all morning between the fax machines in the office with few issues. THANKS AGAIN GUYS! On Wed, Oct 21, 2009 at 2:54 PM, Anthony Minessale <anthony.minessale@gmail.com> wrote:
can you try trunk and let me know right away, if it's still not working i may need ssh access and call you on the phone.
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
On Thu, Oct 22, 2009 at 5:44 PM, Kristian Kielhofner < kristian.kielhofner@gmail.com> wrote:
An update for Tony, Brian, Mike, and everyone on the list...
I was able to get some phone time with the team yesterday. Tony worked on my machine, found the issue, and had it committed within 30 minutes.
I've been testing T.38 all morning between the fax machines in the office with few issues.
and what these few issues are? :P
THANKS AGAIN GUYS!
On Thu, Oct 22, 2009 at 11:58 AM, Tihomir Culjaga <tculjaga@gmail.com> wrote:
and what these few issues are? :P
One fax machine here in the office (still testing others) correctly sends all fax pages. A minute or so after the fax is marked "successful" on both sides it hangs up, redials, and resends the last page... It never did it while connected to the PSTN but then again my other fax machine isn't doing it either. I'm going to test with more fax machines to see if it's an issue with that specific machine. -- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine. Gabe Kristian Kielhofner wrote:
On Thu, Oct 22, 2009 at 11:58 AM, Tihomir Culjaga <tculjaga@gmail.com> wrote:
One fax machine here in the office (still testing others) correctly sends all fax pages. A minute or so after the fax is marked "successful" on both sides it hangs up, redials, and resends the last page... It never did it while connected to the PSTN but then again my other fax machine isn't doing it either. I'm going to test with more fax machines to see if it's an issue with that specific machine.
indeed, this looks like a "dialect" problem between your fax machine and your T.38 device. Anyhow, T.38 doesn't work well with SG3... I Always have to disable v.34 in order to have a reliable fax service. Also, cisco uses to suppress CM so that SG3 timeouts on ANSam the communication fallbacks to ordinary G3. Kristian, just for fun, what are you using to send the fax ? T. On Thu, Oct 22, 2009 at 8:16 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine.
Gabe
Kristian Kielhofner wrote:
On Thu, Oct 22, 2009 at 11:58 AM, Tihomir Culjaga <tculjaga@gmail.com> wrote:
One fax machine here in the office (still testing others) correctly sends all fax pages. A minute or so after the fax is marked "successful" on both sides it hangs up, redials, and resends the last page... It never did it while connected to the PSTN but then again my other fax machine isn't doing it either. I'm going to test with more fax machines to see if it's an issue with that specific machine.
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Gabe, I don't think any of them are plus the T.38 SDP tells me the bitrate is 14400, certainly not V.34 speed. Are you saying the machine even trying to negotiate V.34 poses a problem? On Thu, Oct 22, 2009 at 2:16 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine.
Gabe
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
AFAIK T.38 v2 supports a max speed of 14.4 anyhow, so that's the max speed you'll ever see in the SDP. T.38 v3 supposedly supports v.34 speeds, however no one that I've seen has implemented it yet - not sure it's even an official standard? Yes, in my experience, v.34 capable FAXes do not properly negotiate down to 14.4 speeds, we've always had to disable v.34 (or whatever the option is called on your particular make/model to force it down to 14.4 or slower speeds). We use the Cisco/Linksys ATAs - I've heard there's better ATAs out there that properly negotiate the FAX down to 14.4 on the T.30 side of the connection, but never had a chance to play with them. I'd certainly be interested to hear anyone's experience with T.38 reliability and various combinations of FAX machines and make/model of ATAs. Gabe Kristian Kielhofner wrote:
Gabe,
I don't think any of them are plus the T.38 SDP tells me the bitrate is 14400, certainly not V.34 speed.
Are you saying the machine even trying to negotiate V.34 poses a problem?
On Thu, Oct 22, 2009 at 2:16 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine.
Gabe
well, my experience with T.38 is that we switched it off within our network and now use passthrough instead :P. the reason: - new fax machines that defaults to v.34 and on some you cannot disable SG3 at all... just imagine what pain it is to produce a how to disable V.34 manual for every damn fax machine - a variety of T.30 <> T.38 mapping issues, broken GWs/ATAs that don't do a correct encoding/decoding expectantly when it comes to a terminating fax server that doesn't send a proper EOP... God save our souls... - our network has very low jitter - up to 40 ms , so passthrough works perfect - bandwidth become cheap :=) - and ... don't even remember any fax issues after shutdown T.38 i could go with the list... but i suppose you have better things to do :P T. On Thu, Oct 22, 2009 at 9:29 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
AFAIK T.38 v2 supports a max speed of 14.4 anyhow, so that's the max speed you'll ever see in the SDP. T.38 v3 supposedly supports v.34 speeds, however no one that I've seen has implemented it yet - not sure it's even an official standard?
Yes, in my experience, v.34 capable FAXes do not properly negotiate down to 14.4 speeds, we've always had to disable v.34 (or whatever the option is called on your particular make/model to force it down to 14.4 or slower speeds). We use the Cisco/Linksys ATAs - I've heard there's better ATAs out there that properly negotiate the FAX down to 14.4 on the T.30 side of the connection, but never had a chance to play with them.
I'd certainly be interested to hear anyone's experience with T.38 reliability and various combinations of FAX machines and make/model of ATAs.
Gabe
Kristian Kielhofner wrote:
Gabe,
I don't think any of them are plus the T.38 SDP tells me the bitrate is 14400, certainly not V.34 speed.
Are you saying the machine even trying to negotiate V.34 poses a problem?
On Thu, Oct 22, 2009 at 2:16 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine.
Gabe
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
We have probably 30-40 fax machines running T.38 between Linksys SPA-3102 and Cisco gateways. We have a pretty good success rate and we have been doing this for probably 2-3 years. We have a couple of them going thru an * 1.4 box and it seems to work ok. One of my projects is to try and get them all converted to go thru an FS box, I just haven't had time. Our biggest issues have always been error correction. Once we disable that on the fax machine, it seems to work pretty good. As a general rule, we have found that older cheaper machines work better. New fancy machines are unreliable and that could certainly be related to v.34 issues, but we haven't bothered to get that into it to find out. Peder -----Original Message----- From: freeswitch-users-bounces@lists.freeswitch.org [mailto:freeswitch-users-bounces@lists.freeswitch.org] On Behalf Of Gabriel Kuri Sent: Thursday, October 22, 2009 2:29 PM To: freeswitch-users@lists.freeswitch.org Subject: Re: [Freeswitch-users] Proxy media mode with T.38 re-invite AFAIK T.38 v2 supports a max speed of 14.4 anyhow, so that's the max speed you'll ever see in the SDP. T.38 v3 supposedly supports v.34 speeds, however no one that I've seen has implemented it yet - not sure it's even an official standard? Yes, in my experience, v.34 capable FAXes do not properly negotiate down to 14.4 speeds, we've always had to disable v.34 (or whatever the option is called on your particular make/model to force it down to 14.4 or slower speeds). We use the Cisco/Linksys ATAs - I've heard there's better ATAs out there that properly negotiate the FAX down to 14.4 on the T.30 side of the connection, but never had a chance to play with them. I'd certainly be interested to hear anyone's experience with T.38 reliability and various combinations of FAX machines and make/model of ATAs. Gabe Kristian Kielhofner wrote:
Gabe,
I don't think any of them are plus the T.38 SDP tells me the bitrate is 14400, certainly not V.34 speed.
Are you saying the machine even trying to negotiate V.34 poses a problem?
On Thu, Oct 22, 2009 at 2:16 PM, Gabriel Kuri <gkuri@ieee.org> wrote:
Out of curiosity, is it a Super G3 (ie v.34) capable FAX? We've had nothing but intermittent problems with Super G3 FAXes over T.38, unless v.34 is strictly turned off on the machine.
Gabe
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Fix this or set it to silence. /b On Oct 20, 2009, at 3:57 PM, Kristian Kielhofner wrote:
EXECUTE sofia/s2s/+19412848354@65.196.170.129 playback (local_stream://moh) 2009-10-20 20:54:19.112927 [ERR] switch_core_file.c:116 Invalid file format [local_stream] for [moh]!
Brian, It's already set to silence :). My guess here is that Sofia is mis-interpreting the re-INVITE as not having any media (a la RFC 2543 hold). I don't want to place the call on hold. I want to negotiate T.38 ;). On Tue, Oct 20, 2009 at 5:35 PM, Brian West <brian@freeswitch.org> wrote:
Fix this or set it to silence.
/b
On Oct 20, 2009, at 3:57 PM, Kristian Kielhofner wrote:
EXECUTE sofia/s2s/+19412848354@65.196.170.129 playback (local_stream://moh) 2009-10-20 20:54:19.112927 [ERR] switch_core_file.c:116 Invalid file format [local_stream] for [moh]!
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Kristian Kielhofner http://www.astlinux.org http://blog.krisk.org http://www.star2star.com http://www.submityoursip.com http://www.voalte.com
participants (6)
-
Anthony Minessale
-
Brian West
-
Gabriel Kuri
-
Kristian Kielhofner
-
Peder
-
Tihomir Culjaga