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

Tue Oct 20 13:57:41 PDT 2009

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>;tag=4eUH874j0eUZF.
Remote-Party-ID: fax_9186 <sip:fax_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>;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>;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>;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>;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>;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>;tag=p4H9tpXS1Qv8m.
To: "WIRELESS CALLER" <sip:+19412848354 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