[Freeswitch-users] Proxy media mode with T.38 re-invite

Tue Oct 20 14:34:38 PDT 2009

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 at 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 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 65.196.170.191>
> >;tag=4eUH874j0eUZF.
> Remote-Party-ID: fax_9186 <sip:fax_9186 at 65.196.170.191<sip%3Afax_9186 at 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 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 65.196.170.191>
> >;tag=4eUH874j0eUZF.
> Call-ID: 2889ab05-385d-122d-07b2-0014221c0392.
> CSeq: 101 INVITE.
> Contact: <sip:mod_sofia at 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 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 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 at 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 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 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 at 10.16.5.129:5060>;tag=9f75a042a3ca1f17i0.
> To: "WIRELESS CALLER" <sip:19412848354 at 65.196.170.191<sip%3A19412848354 at 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 at 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 at 65.196.170.129<sip%3A%2B15673861009 at 65.196.170.129>
> >;tag=p4H9tpXS1Qv8m.
> To: "WIRELESS CALLER" <sip:+19412848354 at 65.196.170.129<sip%3A%2B19412848354 at 65.196.170.129>
> >;tag=3D535BNy2tS9e.
> Call-ID: 2d4c8faa-385d-122d-a69b-003018ae0bd3.
> CSeq: 121917605 BYE.
> Contact: <sip:+15673861009 at 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 at 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 at 65.196.170.129) Running State Change CS_NEW
> 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3493 Channel
> sofia/s2s/+19412848354 at 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 at 65.196.170.129) State NEW
> 2009-10-20 20:54:15.577191 [DEBUG] sofia.c:3615
> (sofia/s2s/+19412848354 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:306
> (sofia/s2s/+19412848354 at 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 at 65.196.170.129) State INIT
> 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:83
> sofia/s2s/+19412848354 at 65.196.170.129 SOFIA INIT
> 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:111
> (sofia/s2s/+19412848354 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:330
> (sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129) State ROUTING
> 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:130
> sofia/s2s/+19412848354 at 65.196.170.129 SOFIA ROUTING
> 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:78
> sofia/s2s/+19412848354 at 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 at 65.196.170.129 parsing
> [s2s-in->unloop] continue=false
> Dialplan: sofia/s2s/+19412848354 at 65.196.170.129 Regex (PASS) [unloop]
> ${unroll_loops}(true) =~ /^true$/ break=on-false
> Dialplan: sofia/s2s/+19412848354 at 65.196.170.129 Regex (FAIL) [unloop]
> ${sip_looped_call}() =~ /^true$/ break=on-false
> Dialplan: sofia/s2s/+19412848354 at 65.196.170.129 parsing
> [s2s-in->faxpass] continue=false
> Dialplan: sofia/s2s/+19412848354 at 65.196.170.129 Absolute Condition
> [faxpass]
> Dialplan: sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:333
> (sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129) State EXECUTE
> 2009-10-20 20:54:15.581191 [DEBUG] mod_sofia.c:173
> sofia/s2s/+19412848354 at 65.196.170.129 SOFIA EXECUTE
> 2009-10-20 20:54:15.581191 [DEBUG] switch_core_state_machine.c:151
> sofia/s2s/+19412848354 at 65.196.170.129 Standard EXECUTE
> EXECUTE sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129 receive message [RINGING]
> 2009-10-20 20:54:15.606802 [NOTICE] mod_sofia.c:1525 Ring-Ready
> sofia/s2s/+19412848354 at 65.196.170.129!
> 2009-10-20 20:54:15.606802 [DEBUG] switch_core_session.c:653 Send
> signal sofia/s2s/+19412848354 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:15.606802 [NOTICE] switch_ivr_originate.c:388 Ring
> Ready sofia/s2s/+19412848354 at 65.196.170.129!
> 2009-10-20 20:54:15.609957 [DEBUG] sofia.c:3493 Channel
> sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129 receive message [ANSWER]
> 2009-10-20 20:54:16.175057 [DEBUG] sofia_glue.c:1328
> sofia/s2s/+19412848354 at 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 at 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 at 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 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:16.182190 [NOTICE] sofia.c:3961 Channel
> [sofia/s2s/+19412848354 at 65.196.170.129] has been answered
> 2009-10-20 20:54:16.185443 [DEBUG] switch_channel.c:182
> sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129 entering state [completed][200]
> 2009-10-20 20:54:16.185443 [DEBUG] switch_ivr_bridge.c:982
> sofia/s2s/+19412848354 at 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 at 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 at 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 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:18.993185 [DEBUG] switch_ivr_bridge.c:301
> sofia/s2s/+19412848354 at 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 at 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 at 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 at 65.196.170.129 Command Execute
> playback(local_stream://moh)
> EXECUTE sofia/s2s/+19412848354 at 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 at 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 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:19.112927 [DEBUG] switch_ivr_bridge.c:528 BRIDGE
> THREAD DONE [sofia/s2s/+19412848354 at 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 at 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 at 65.196.170.129 [KILL]
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:985 Send
> signal sofia/s2s/+19412848354 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:478
> (sofia/s2s/+19412848354 at 65.196.170.129) State HANGUP
> 2009-10-20 20:54:19.112927 [DEBUG] mod_sofia.c:344 Channel
> sofia/s2s/+19412848354 at 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 at 65.196.170.129
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:46
> sofia/s2s/+19412848354 at 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 at 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 at 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 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:306
> (sofia/s2s/+19412848354 at 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 at 65.196.170.129) State REPORTING
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_state_machine.c:53
> sofia/s2s/+19412848354 at 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 at 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 at 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 at 65.196.170.129 [BREAK]
> 2009-10-20 20:54:19.112927 [DEBUG] switch_core_session.c:1122 Session
> 15 (sofia/s2s/+19412848354 at 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 at 65.196.170.129) Ended
> 2009-10-20 20:54:19.245025 [NOTICE] switch_core_session.c:1142 Close
> Channel sofia/s2s/+19412848354 at 65.196.170.129 [CS_DESTROY]
> 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:415
> (sofia/s2s/+19412848354 at 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 at 65.196.170.129) State DESTROY
> 2009-10-20 20:54:19.245025 [DEBUG] mod_sofia.c:261
> sofia/s2s/+19412848354 at 65.196.170.129 SOFIA DESTROY
> 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:60
> sofia/s2s/+19412848354 at 65.196.170.129 Standard DESTROY
> 2009-10-20 20:54:19.245025 [DEBUG] switch_core_state_machine.c:426
> (sofia/s2s/+19412848354 at 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 at 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 at hotmail.com <MSN%3Aanthony_minessale at hotmail.com>
GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com<PAYPAL%3Aanthony.minessale at gmail.com>
IRC: irc.freenode.net #freeswitch

FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org <sip%3A888 at conference.freeswitch.org>
iax:guest at conference.freeswitch.org/888
googletalk:conf+888 at conference.freeswitch.org<googletalk%3Aconf%2B888 at conference.freeswitch.org>
pstn:213-799-1400
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20091020/1b41c9cd/attachment-0002.html 