[ 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@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@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@192.168.26.39:15060) State NEW

[ 2010-07-01 14:15:16.331035 [DEBUG] sofia.c:4297 Channel sofia/internal/1000@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@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@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@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@192.168.26.39:15060) State INIT

[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:83 sofia/internal/1000@192.168.26.39:15060 SOFIA INIT

[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:119 (sofia/internal/1000@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/1000@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@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@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@192.168.26.39:15060) State ROUTING

[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:142 sofia/internal/1000@192.168.26.39:15060 SOFIA ROUTING

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1000@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@192.168.26.39:15060 parsing [public->fax] continue=false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Regex (FAIL) [fax] destination_number(666666) =~ /^fax$/ break=on-false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 parsing [public->4444] continue=false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Regex (FAIL) [4444] destination_number(666666) =~ /^(4444)$/ break=on-false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 parsing [public->fax] continue=false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Regex (FAIL) [fax] destination_number(666666) =~ /^fax$/ break=on-false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 parsing [public->666666] continue=false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Regex (PASS) [666666] destination_number(666666) =~ /^(666666)$/ break=on-false

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Action answer()

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Action playback(silence_stream://2000)

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Action rxfax(/tmp/999.tiff)

[ Dialplan: sofia/internal/1000@192.168.26.39:15060 Action hangup()

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1000@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:341 (sofia/internal/1000@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@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@192.168.26.39:15060) State EXECUTE

[ 2010-07-01 14:15:16.333036 [DEBUG] mod_sofia.c:235 sofia/internal/1000@192.168.26.39:15060 SOFIA EXECUTE

[ 2010-07-01 14:15:16.333036 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1000@192.168.26.39:15060 Standard EXECUTE

[ EXECUTE sofia/internal/1000@192.168.26.39:15060 answer()

[ 2010-07-01 14:15:16.367038 [DEBUG] sofia_glue.c:2682 AUDIO RTP [sofia/internal/1000@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@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:16.371038 [DEBUG] switch_channel.c:2494 (sofia/internal/1000@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@192.168.26.39:15060] has been answered

[ 2010-07-01 14:15:16.371038 [DEBUG] sofia.c:4297 Channel sofia/internal/1000@192.168.26.39:15060 entering state [completed][200]

[ 2010-07-01 14:15:16.371038 [DEBUG] sofia.c:4297 Channel sofia/internal/1000@192.168.26.39:15060 entering state [ready][200]

[ EXECUTE sofia/internal/1000@192.168.26.39:15060 playback(silence_stream://2000)

[ 2010-07-01 14:15:16.371038 [DEBUG] switch_ivr_play_say.c:1161 Codec Activated L16@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@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@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@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@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@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@192.168.26.39:15060 Restore previous codec PCMA:8.

[ EXECUTE sofia/internal/1000@192.168.26.39:15060 hangup()

[ 2010-07-01 14:15:51.388172 [DEBUG] switch_channel.c:2261 (sofia/internal/1000@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@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@192.168.26.39:15060 [KILL]

[ 2010-07-01 14:15:51.388172 [DEBUG] switch_core_session.c:1027 Send signal sofia/internal/1000@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:51.388172 [DEBUG] switch_core_state_machine.c:348 (sofia/internal/1000@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@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@192.168.26.39:15060) State HANGUP

[ 2010-07-01 14:15:51.391171 [DEBUG] mod_sofia.c:447 Channel sofia/internal/1000@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@192.168.26.39:15060

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1000@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@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@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1000@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@192.168.26.39:15060) State REPORTING

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1000@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@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@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@192.168.26.39:15060 [BREAK]

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_session.c:1175 Session 1 (sofia/internal/1000@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@192.168.26.39:15060) Ended

[36m2010-07-01 14:15:51.433177 [NOTICE] switch_core_session.c:1195 Close Channel sofia/internal/1000@192.168.26.39:15060 [CS_DESTROY]

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:427 (sofia/internal/1000@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@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@192.168.26.39:15060) State DESTROY

[ 2010-07-01 14:15:51.433177 [DEBUG] mod_sofia.c:352 sofia/internal/1000@192.168.26.39:15060 SOFIA DESTROY

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@192.168.26.39:15060 Standard DESTROY

[ 2010-07-01 14:15:51.433177 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/1000@192.168.26.39:15060) State DESTROY going to sleep