[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