VoIP Mailing List Archives

[kristian.kielhofner at...]

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

_______________________________________________
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

[brian at freeswitch.org]

Fix this or set it to silence.

/b

On Oct 20, 2009, at 3:57 PM, Kristian Kielhofner wrote:

[anthony.minessale at g...]

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 (kristian.kielhofner@gmail.com)> wrote:

[kristian.kielhofner at...]

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:

[kristian.kielhofner at...]

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:

[kristian.kielhofner at...]

Done.

On Tue, Oct 20, 2009 at 5:34 PM, Anthony Minessale
<anthony.minessale@gmail.com> wrote:

[anthony.minessale at g...]

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 (kristian.kielhofner@gmail.com)> wrote:

[kristian.kielhofner at...]

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:

[tculjaga at gmail.com]

On Thu, Oct 22, 2009 at 5:44 PM, Kristian Kielhofner <kristian.kielhofner@gmail.com (kristian.kielhofner@gmail.com)> wrote:

[kristian.kielhofner at...]

On Thu, Oct 22, 2009 at 11:58 AM, Tihomir Culjaga <tculjaga@gmail.com> wrote:

[gkuri at ieee.org]

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:

[tculjaga at gmail.com]

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 (gkuri@ieee.org)> wrote:

[kristian.kielhofner at...]

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:

[gkuri at ieee.org]

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:

[tculjaga at gmail.com]

well, my experience with T.38 is that we switched it off within our network and now use passthrough instead .

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 


T.

On Thu, Oct 22, 2009 at 9:29 PM, Gabriel Kuri <gkuri@ieee.org (gkuri@ieee.org)> wrote: