[Freeswitch-users] Problem of FreeSwitch and T.38 Test
chi zhang
sanms.zhang at gmail.com
Thu Jul 1 18:23:30 PDT 2010
hi,brian
log as below:
------------------------ start ---------------------------
[ 2010-07-01 14:15:16.287030 [DEBUG] sofia.c:5928 IP 192.168.26.39 Approved
by acl "192.168.26.0/24[]". Access Granted.
[36m2010-07-01 14:15:16.289031 [NOTICE] switch_channel.c:776 New Channel
sofia/internal/1000 at 192.168.26.39:15060[d8dc7307-efd6-48ed-8d85-d5f2d52deb10]
[ 2010-07-01 14:15:16.289031 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_NEW
[ 2010-07-01 14:15:16.289031 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/1000 at 192.168.26.39:15060) State NEW
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia.c:4297 Channel sofia/internal/
1000 at 192.168.26.39:15060 entering state [received][100]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia.c:4308 Remote SDP:
v=0
o=user1 3748 3748 IN IP4 192.168.26.39
s=-
c=IN IP4 192.168.26.39
t=0 0
m=audio 6000 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11,16
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3859 Audio Codec Compare
[PCMA:8:8000:20]/[G7221:115:32000:20]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3859 Audio Codec Compare
[PCMA:8:8000:20]/[G7221:107:16000:20]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3859 Audio Codec Compare
[PCMA:8:8000:20]/[G722:9:8000:20]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3859 Audio Codec Compare
[PCMA:8:8000:20]/[PCMU:0:8000:20]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3859 Audio Codec Compare
[PCMA:8:8000:20]/[PCMA:8:8000:20]
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:2442 Set Codec
sofia/internal/1000 at 192.168.26.39:15060 PCMA/8000 20 ms 160 samples
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia_glue.c:3798 Set 2833 dtmf
send/recv payload to 101
[ 2010-07-01 14:15:16.331035 [DEBUG] sofia.c:4455 (sofia/internal/
1000 at 192.168.26.39:15060) State Change CS_NEW -> CS_INIT
[ 2010-07-01 14:15:16.331035 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_INIT
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/1000 at 192.168.26.39:15060) State INIT
[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:83 sofia/internal/
1000 at 192.168.26.39:15060 SOFIA INIT
[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:119 (sofia/internal/
1000 at 192.168.26.39:15060) State Change CS_INIT -> CS_ROUTING
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/1000 at 192.168.26.39:15060) State INIT going to sleep
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_ROUTING
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_channel.c:1471 (sofia/internal/
1000 at 192.168.26.39:15060) Callstate Change DOWN -> RINGING
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/1000 at 192.168.26.39:15060) State ROUTING
[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:142 sofia/internal/
1000 at 192.168.26.39:15060 SOFIA ROUTING
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:77
sofia/internal/1000 at 192.168.26.39:15060 Standard ROUTING
[32m2010-07-01 14:15:16.333036 [INFO] mod_dialplan_xml.c:331 Processing
1000->666666 in context public
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 parsing [public->fax]
continue=false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Regex (FAIL) [fax]
destination_number(666666) =~ /^fax$/ break=on-false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 parsing [public->4444]
continue=false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Regex (FAIL) [4444]
destination_number(666666) =~ /^(4444)$/ break=on-false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 parsing [public->fax]
continue=false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Regex (FAIL) [fax]
destination_number(666666) =~ /^fax$/ break=on-false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 parsing
[public->666666] continue=false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Regex (PASS) [666666]
destination_number(666666) =~ /^(666666)$/ break=on-false
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Action answer()
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Action
playback(silence_stream://2000)
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Action
rxfax(/tmp/999.tiff)
[ Dialplan: sofia/internal/1000 at 192.168.26.39:15060 Action hangup()
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:119
(sofia/internal/1000 at 192.168.26.39:15060) State Change CS_ROUTING ->
CS_EXECUTE
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/1000 at 192.168.26.39:15060) State ROUTING going to sleep
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_EXECUTE
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/1000 at 192.168.26.39:15060) State EXECUTE
[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:235 sofia/internal/
1000 at 192.168.26.39:15060 SOFIA EXECUTE
[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:157
sofia/internal/1000 at 192.168.26.39:15060 Standard EXECUTE
[ EXECUTE sofia/internal/1000 at 192.168.26.39:15060 answer()
[ 2010-07-01 14:15:16.367038 [DEBUG] sofia_glue.c:2682 AUDIO RTP
[sofia/internal/1000 at 192.168.26.39:15060] 192.168.26.39 port 30734 ->
192.168.26.39 port 6000 codec: 8 ms: 20
[ 2010-07-01 14:15:16.369048 [DEBUG] switch_rtp.c:1413 Starting timer
[soft] 160 bytes per 20ms
[ 2010-07-01 14:15:16.371038 [DEBUG] sofia_glue.c:2892 Set 2833 dtmf send
payload to 101
[ 2010-07-01 14:15:16.371038 [DEBUG] sofia_glue.c:2897 Set 2833 dtmf
receive payload to 101
[ 2010-07-01 14:15:16.371038 [DEBUG] mod_sofia.c:669 Local SDP
sofia/internal/1000 at 192.168.26.39:15060:
v=0
o=FreeSWITCH 1277934182 1277934183 IN IP4 192.168.26.39
s=FreeSWITCH
c=IN IP4 192.168.26.39
t=0 0
m=audio 30734 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
[ 2010-07-01 14:15:16.371038 [DEBUG] switch_core_session.c:647 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:16.371038 [DEBUG] switch_channel.c:2494 (sofia/internal/
1000 at 192.168.26.39:15060) Callstate Change RINGING -> ACTIVE
[36m2010-07-01 14:15:16.371038 [NOTICE] mod_dptools.c:746 Channel
[sofia/internal/1000 at 192.168.26.39:15060] has been answered
[ 2010-07-01 14:15:16.371038 [DEBUG] sofia.c:4297 Channel sofia/internal/
1000 at 192.168.26.39:15060 entering state [completed][200]
[ 2010-07-01 14:15:16.371038 [DEBUG] sofia.c:4297 Channel sofia/internal/
1000 at 192.168.26.39:15060 entering state [ready][200]
[ EXECUTE sofia/internal/1000 at 192.168.26.39:15060playback(silence_stream://2000)
[ 2010-07-01 14:15:16.371038 [DEBUG] switch_ivr_play_say.c:1161 Codec
Activated L16 at 8000hz 1 channels 20ms
[ 2010-07-01 14:15:18.364218 [DEBUG] switch_ivr_play_say.c:1468 done
playing file
[ EXECUTE sofia/internal/1000 at 192.168.26.39:15060 rxfax(/tmp/999.tiff)
[ 2010-07-01 14:15:18.364218 [ERR] mod_spandsp.c:64 This is for fax test:
receive fax
[ 2010-07-01 14:15:18.364218 [ERR] mod_spandsp_fax.c:445 trans mode = 1
[ 2010-07-01 14:15:18.364218 [ERR] mod_spandsp_fax.c:591 This is for fax
test: prag go to here!!!
[ 2010-07-01 14:15:18.364218 [DEBUG] mod_spandsp_fax.c:1064 Raw read codec
activation Success L16 20000
[ 2010-07-01 14:15:18.364218 [DEBUG] switch_core_codec.c:122
sofia/internal/1000 at 192.168.26.39:15060 Push codec L16:10
[ 2010-07-01 14:15:18.364218 [DEBUG] mod_spandsp_fax.c:1080 Raw write codec
activation Success L16
[ 2010-07-01 14:15:18.645238 [ERR] mod_spandsp_fax.c:1119 pvt->t38_mode = 0
[ 2010-07-01 14:15:26.374918 [DEBUG] sofia.c:4297 Channel sofia/internal/
1000 at 192.168.26.39:15060 entering state [received][100]
[ 2010-07-01 14:15:26.374918 [DEBUG] sofia.c:4308 Remote SDP:
v=0
o=root 0 0 IN IP4 192.168.26.39
s=Session SDP
c=IN IP4 192.168.26.39
t=0 0
m=image 49172 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxUdpEC:t38UDPRedundancy
[ 2010-07-01 14:15:26.382925 [ERR] mod_spandsp_fax.c:1119 pvt->t38_mode = 0
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:744 T38FaxVersion =
0
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:745 T38MaxBitRate =
9600
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:746
T38FaxFillBitRemoval = 1
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:747
T38FaxTranscodingMMR = 1
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:748
T38FaxTranscodingJBIG = 1
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:749
T38FaxRateManagement = 'transferredTCF'
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:750 T38FaxMaxBuffer
= 200
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:751
T38FaxMaxDatagram = 72
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:752 T38FaxUdpEC =
't38UDPRedundancy'
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:753 T38VendorInfo =
''
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:754 ip =
'192.168.26.39'
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_spandsp_fax.c:756 port = 49172
[ 2010-07-01 14:15:26.382925 [DEBUG] mod_sofia.c:1232 IMAGE UDPTL CHANGING
DEST TO: [192.168.26.39:49172]
[ 2010-07-01 14:15:26.382925 [DEBUG] sofia_glue.c:122 sofia/internal/
1000 at 192.168.26.39:15060 image media sdp:
v=0
o=FreeSWITCH 1277934182 1277934184 IN IP4 192.168.26.39
s=FreeSWITCH
c=IN IP4 192.168.26.39
t=0 0
m=image 30734 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxFillBitRemoval
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38VendorInfo:0 0 0
[ 2010-07-01 14:15:26.382925 [ERR] mod_spandsp_fax.c:445 trans mode = 0
[ 2010-07-01 14:15:26.382925 [DEBUG] sofia.c:4297 Channel sofia/internal/
1000 at 192.168.26.39:15060 entering state [completed][200]
[ 2010-07-01 14:15:46.390709 [ERR] mod_spandsp_fax.c:1119 pvt->t38_mode = 1
This is for fax test : s->state= 17
This is for fax test: command exceed max
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:302 result = 48
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:304
==============================================================================
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:316 Fax processing
not successful - result (48) Disconnected after permitted retries.
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:321 Remote station
id:
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:322 Local station
id: SpanDSP Fax Ident
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:323 Pages
transferred: 0
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:325 Total fax pages:
0
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:326 Image
resolution: 0x0
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:327 Transfer Rate:
14400
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:329 ECM status
off
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:330 remote country:
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:331 remote vendor:
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:332 remote model:
[ 2010-07-01 14:15:49.052963 [DEBUG] mod_spandsp_fax.c:334
==============================================================================
[ 2010-07-01 14:15:51.388172 [DEBUG] switch_core_codec.c:146
sofia/internal/1000 at 192.168.26.39:15060 Restore previous codec PCMA:8.
[ EXECUTE sofia/internal/1000 at 192.168.26.39:15060 hangup()
[ 2010-07-01 14:15:51.388172 [DEBUG] switch_channel.c:2261 (sofia/internal/
1000 at 192.168.26.39:15060) Callstate Change ACTIVE -> HANGUP
[36m2010-07-01 14:15:51.388172 [NOTICE] mod_dptools.c:732 Hangup
sofia/internal/1000 at 192.168.26.39:15060 [CS_EXECUTE] [NORMAL_CLEARING]
[ 2010-07-01 14:15:51.388172 [DEBUG] switch_channel.c:2277 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [KILL]
[ 2010-07-01 14:15:51.388172 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:51.388172 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/1000 at 192.168.26.39:15060) State EXECUTE going to sleep
[ 2010-07-01 14:15:51.391171 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_HANGUP
[ 2010-07-01 14:15:51.391171 [DEBUG] switch_core_state_machine.c:500
(sofia/internal/1000 at 192.168.26.39:15060) State HANGUP
[ 2010-07-01 14:15:51.391171 [DEBUG] mod_sofia.c:447 Channel
sofia/internal/1000 at 192.168.26.39:15060 hanging up, cause: NORMAL_CLEARING
[ 2010-07-01 14:15:51.433177 [DEBUG] mod_sofia.c:490 Sending BYE to
sofia/internal/1000 at 192.168.26.39:15060
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:46
sofia/internal/1000 at 192.168.26.39:15060 Standard HANGUP, cause:
NORMAL_CLEARING
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:500
(sofia/internal/1000 at 192.168.26.39:15060) State HANGUP going to sleep
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/1000 at 192.168.26.39:15060) State Change CS_HANGUP ->
CS_REPORTING
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_REPORTING
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:591
(sofia/internal/1000 at 192.168.26.39:15060) State REPORTING
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:53
sofia/internal/1000 at 192.168.26.39:15060 Standard REPORTING, cause:
NORMAL_CLEARING
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:591
(sofia/internal/1000 at 192.168.26.39:15060) State REPORTING going to sleep
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:327
(sofia/internal/1000 at 192.168.26.39:15060) State Change CS_REPORTING ->
CS_DESTROY
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_session.c:1027 Send signal
sofia/internal/1000 at 192.168.26.39:15060 [BREAK]
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_session.c:1175 Session 1
(sofia/internal/1000 at 192.168.26.39:15060) Locked, Waiting on external
entities
[36m2010-07-01 14:15:51.433177 [NOTICE] switch_core_session.c:1193 Session
1 (sofia/internal/1000 at 192.168.26.39:15060) Ended
[36m2010-07-01 14:15:51.433177 [NOTICE] switch_core_session.c:1195 Close
Channel sofia/internal/1000 at 192.168.26.39:15060 [CS_DESTROY]
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:427
(sofia/internal/1000 at 192.168.26.39:15060) Callstate Change HANGUP -> DOWN
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:430
(sofia/internal/1000 at 192.168.26.39:15060) Running State Change CS_DESTROY
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/1000 at 192.168.26.39:15060) State DESTROY
[ 2010-07-01 14:15:51.433177 [DEBUG] mod_sofia.c:352 sofia/internal/
1000 at 192.168.26.39:15060 SOFIA DESTROY
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:60
sofia/internal/1000 at 192.168.26.39:15060 Standard DESTROY
[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/1000 at 192.168.26.39:15060) State DESTROY going to sleep
------------------------ end -------------------------
regards
sammy
2010/7/1 Brian West <brian at freeswitch.org>
> You'll need to provide the sip trace and full debug logs.
>
> /b
>
> On Jul 1, 2010, at 3:30 AM, chi zhang wrote:
>
> > Does anyone know the reason?
> > Where is the span_log of spandsp lib ? i cannt find it...
> >
>
>
> _______________________________________________
> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100702/dd90556c/attachment-0001.html
More information about the FreeSWITCH-users
mailing list