2017-05-25 12:54:15.508375 [NOTICE] switch_channel.c:1104 New Channel sofia/default/95878797@127.0.0.1:5060 [59fe0ca5-958e-4801-9c69-3ef056fb102f] 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_NEW 2017-05-25 12:54:15.508375 [DEBUG] sofia.c:9376 sofia/default/95878797@127.0.0.1:5060 receiving invite from 127.0.0.1:5060 version: 1.6.8 64bit 2017-05-25 12:54:15.508375 [DEBUG] sofia.c:9488 IP 127.0.0.1 Approved by acl "default[]". Access Granted. 2017-05-25 12:54:15.508375 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [received][100] 2017-05-25 12:54:15.508375 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=Z 0 0 IN IP4 127.0.0.2 s=Z c=IN IP4 127.0.0.2 t=0 0 m=audio 8000 RTP/AVP 8 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2017-05-25 12:54:15.508375 [DEBUG] sofia.c:7227 (sofia/default/95878797@127.0.0.1:5060) State Change CS_NEW -> CS_INIT 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:562 (sofia/default/95878797@127.0.0.1:5060) State NEW 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_INIT 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:586 (sofia/default/95878797@127.0.0.1:5060) State INIT 2017-05-25 12:54:15.508375 [DEBUG] mod_sofia.c:89 sofia/default/95878797@127.0.0.1:5060 SOFIA INIT 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:40 sofia/default/95878797@127.0.0.1:5060 Standard INIT 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:48 (sofia/default/95878797@127.0.0.1:5060) State Change CS_INIT -> CS_ROUTING 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:586 (sofia/default/95878797@127.0.0.1:5060) State INIT going to sleep 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_ROUTING 2017-05-25 12:54:15.508375 [DEBUG] switch_channel.c:2249 (sofia/default/95878797@127.0.0.1:5060) Callstate Change DOWN -> RINGING 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:602 (sofia/default/95878797@127.0.0.1:5060) State ROUTING 2017-05-25 12:54:15.508375 [DEBUG] mod_sofia.c:142 sofia/default/95878797@127.0.0.1:5060 SOFIA ROUTING 2017-05-25 12:54:15.508375 [DEBUG] switch_core_state_machine.c:236 sofia/default/95878797@127.0.0.1:5060 Standard ROUTING 2017-05-25 12:54:15.508375 [INFO] mod_dialplan_xml.c:637 Processing 95878797 <95878797>->123456789 in context default 2017-05-25 12:54:15.508375 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f0b80072ff0 Connected. 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [xml_REQUEST] key_name: 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [xml_REQUEST] key_value: 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [xml_REQUEST] tag_name: 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [xml_REQUEST] section: dialplan 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [Dialplan] Dialed number : 123456789 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [Dialplan] Dialed number : 123456789 Voicemail Number 7777 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,A.number as did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="123456789" LIMIT 1 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [Dialplan] Call direction : inbound 2017-05-25 12:54:15.508375 [NOTICE] switch_cpp.cpp:1360 [TEST_FAX] [Accountcode : 9213634206] 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "9213634206" OR id="9213634206") AND status=0 AND deleted=0 AND (expiry >= '2017-05-25 10:54:15' OR expiry = '0000-00-00 00:00:00') limit 1 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [GET_PACKAGE_INFO] Query :SELECT * FROM packages as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns ='^123456789.*' OR patterns ='^9476518391.*' OR patterns ='^947651839.*' OR patterns ='^94765183.*' OR patterns ='^9476518.*' OR patterns ='^947651.*' OR patterns ='^94765.*' OR patterns ='^9476.*' OR patterns ='^947.*' OR patterns ='^94.*' OR patterns ='^9.*' OR patterns ='--') AND status = 0 AND pricelist_id = 22 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] =============== Account Information =================== 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] User id : 64 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Account code : 9213634206 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Balance : 4.9046 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Type : 0 [0:prepaid,1:postpaid] 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Ratecard id : 22 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] ======================================================== 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 22 AND status = 0 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,A.number as did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="123456789" LIMIT 1 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] =============== Rates Information =================== 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] ID : 23 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Connectcost : 0.00000 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Includedseconds : 0 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Cost : 0.00000 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] comment : 123456789 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Accid : 64 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] ================================================================ 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [FIND_MAXLENGTH] Your balance is to dial 4.9046 !!! 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 100 2017-05-25 12:54:15.508375 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Call Max length duration : 100 minutes 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "35" OR id="35") AND status=0 AND deleted=0 AND (expiry >= '2017-05-25 10:54:15' OR expiry = '0000-00-00 00:00:00') limit 1 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 22 AND status = 0 2017-05-25 12:54:15.508375 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern ='^123456789.*' OR pattern ='^9476518391.*' OR pattern ='^947651839.*' OR pattern ='^94765183.*' OR pattern ='^9476518.*' OR pattern ='^947651.*' OR pattern ='^94765.*' OR pattern ='^9476.*' OR pattern ='^947.*' OR pattern ='^94.*' OR pattern ='^9.*' OR pattern ='--') AND status = 0 AND pricelist_id = 22 ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] =============== Rates Information =================== 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] ID : 41 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Connectcost : 0.00000 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Includedseconds : 0 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Cost : 0.00370 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] comment : España Fijo 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] Accid : 64 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] ================================================================ 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [FIND_MAXLENGTH] Your balance is to dial 4.9046 !!! 2017-05-25 12:54:15.548289 [INFO] switch_cpp.cpp:1360 [TEST_FAX] [userinfo] Userinfo XML:64 2017-05-25 12:54:15.548289 [DEBUG] switch_cpp.cpp:1360 [TEST_FAX] [Dialplan] Generated XML:
2017-05-25 12:54:15.548289 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f0b80072ff0 released. Dialplan: sofia/default/95878797@127.0.0.1:5060 parsing [default->123456789] continue=false Dialplan: sofia/default/95878797@127.0.0.1:5060 Regex (PASS) [123456789] destination_number(123456789) =~ /123456789/ break=on-false Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(effective_destination_number=123456789) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action sched_hangup(+6000 normal_clearing) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(callstart=2017-05-25 10:54:15) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(continue_on_fail=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(account_id=64) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(parent_id=0) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(entity_id=0) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(call_processed=internal) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(call_direction=inbound) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(accountname=default) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(origination_rates_did=ID:23|CODE:^.123456789.*|DESTINATION:123456789|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:35) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(origination_rates=ID:41|CODE:^9.*|DESTINATION:España Fijo|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00370|INC:0|INITIALBLOCK:0|RATEGROUP:22|MARKUP:0|ACCID:64) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(receiver_accid=35) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(calltype=FAX) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action answer() Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(callfax=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action playback(silence_stream://2000) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(ignore_early_media=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(fax_enable_t38_request=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(fax_use_ecm=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(fax_enable_t38=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(fax_verbose=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(session_in_hangup_hook=true) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action set(api_hangup_hook=system /var/www/html/FAX/scripts/emailfax.sh /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.tif 64 Sip6_tarifa+coste test@test.com /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.pdf) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action rxfax(/tmp/123-FAX.tif) Dialplan: sofia/default/95878797@127.0.0.1:5060 Action hangup() 2017-05-25 12:54:15.548289 [DEBUG] switch_core_state_machine.c:286 (sofia/default/95878797@127.0.0.1:5060) State Change CS_ROUTING -> CS_EXECUTE 2017-05-25 12:54:15.548289 [DEBUG] switch_core_state_machine.c:602 (sofia/default/95878797@127.0.0.1:5060) State ROUTING going to sleep 2017-05-25 12:54:15.548289 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_EXECUTE 2017-05-25 12:54:15.548289 [DEBUG] switch_core_state_machine.c:609 (sofia/default/95878797@127.0.0.1:5060) State EXECUTE 2017-05-25 12:54:15.548289 [DEBUG] mod_sofia.c:197 sofia/default/95878797@127.0.0.1:5060 SOFIA EXECUTE 2017-05-25 12:54:15.548289 [DEBUG] switch_core_state_machine.c:328 sofia/default/95878797@127.0.0.1:5060 Standard EXECUTE EXECUTE sofia/default/95878797@127.0.0.1:5060 set(effective_destination_number=123456789) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [effective_destination_number]=[123456789] EXECUTE sofia/default/95878797@127.0.0.1:5060 sched_hangup(+6000 normal_clearing) 2017-05-25 12:54:15.548289 [DEBUG] switch_scheduler.c:249 Added task 7 switch_ivr_schedule_hangup (59fe0ca5-958e-4801-9c69-3ef056fb102f) to run at 1495715655 EXECUTE sofia/default/95878797@127.0.0.1:5060 set(callstart=2017-05-25 10:54:15) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [callstart]=[2017-05-25 10:54:15] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(hangup_after_bridge=true) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [hangup_after_bridge]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(continue_on_fail=true) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [continue_on_fail]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(account_id=64) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [account_id]=[64] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(parent_id=0) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [parent_id]=[0] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(entity_id=0) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [entity_id]=[0] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(call_processed=internal) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [call_processed]=[internal] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(call_direction=inbound) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [call_direction]=[inbound] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(accountname=default) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [accountname]=[default] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(origination_rates_did=ID:23|CODE:^.123456789.*|DESTINATION:123456789|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:35) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [origination_rates_did]=[ID:23|CODE:^.123456789.*|DESTINATION:123456789|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:35] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(origination_rates=ID:41|CODE:^9.*|DESTINATION:España Fijo|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00370|INC:0|INITIALBLOCK:0|RATEGROUP:22|MARKUP:0|ACCID:64) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [origination_rates]=[ID:41|CODE:^9.*|DESTINATION:España Fijo|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00370|INC:0|INITIALBLOCK:0|RATEGROUP:22|MARKUP:0|ACCID:64] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(receiver_accid=35) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [receiver_accid]=[35] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(calltype=FAX) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [calltype]=[FAX] EXECUTE sofia/default/95878797@127.0.0.1:5060 answer() 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/95878797@127.0.0.1:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2017-05-25 12:54:15.548289 [DEBUG] switch_core_codec.c:111 sofia/default/95878797@127.0.0.1:5060 Original read codec set to PCMA:8 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:4681 sofia/default/95878797@127.0.0.1:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/95878797@127.0.0.1:5060] 127.0.0.3 port 25770 -> 127.0.0.2 port 8000 codec: 8 ms: 20 2017-05-25 12:54:15.548289 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:6763 sofia/default/95878797@127.0.0.1:5060 Set 2833 dtmf send payload to 101 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:6770 sofia/default/95878797@127.0.0.1:5060 Set 2833 dtmf receive payload to 101 2017-05-25 12:54:15.548289 [DEBUG] switch_core_media.c:6793 sofia/default/95878797@127.0.0.1:5060 Set rtp dtmf delay to 40 2017-05-25 12:54:15.548289 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/95878797@127.0.0.1:5060! 2017-05-25 12:54:15.548289 [DEBUG] switch_channel.c:3471 (sofia/default/95878797@127.0.0.1:5060) Callstate Change RINGING -> EARLY 2017-05-25 12:54:15.548289 [DEBUG] mod_sofia.c:814 Local SDP sofia/default/95878797@127.0.0.1:5060: v=0 o=FreeSWITCH 1495683885 1495683886 IN IP4 127.0.0.3 s=FreeSWITCH c=IN IP4 127.0.0.3 t=0 0 m=audio 25770 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2017-05-25 12:54:15.548289 [NOTICE] mod_dptools.c:1309 Channel [sofia/default/95878797@127.0.0.1:5060] has been answered send 1021 bytes to udp/[127.0.0.1]:5060 at 12:54:15.555337: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6aab.be435b72.1 Via: SIP/2.0/UDP 127.0.0.2:36676;branch=z9hG4bK-d8754z-39f7e02283df1ba2-1---d8754z- Record-Route: From: ;tag=a1e83108 To: ;tag=gUB5yNB70camp Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 2 INVITE Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 224 v=0 o=FreeSWITCH 1495683885 1495683886 IN IP4 127.0.0.3 s=FreeSWITCH c=IN IP4 127.0.0.3 t=0 0 m=audio 25770 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-05-25 12:54:15.548289 [DEBUG] switch_channel.c:3770 (sofia/default/95878797@127.0.0.1:5060) Callstate Change EARLY -> ACTIVE 2017-05-25 12:54:15.548289 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [completed][200] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(callfax=true) 2017-05-25 12:54:15.548289 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [callfax]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 playback(silence_stream://2000) 2017-05-25 12:54:15.548289 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms recv 939 bytes from udp/[127.0.0.1]:5060 at 12:54:15.769974: ------------------------------------------------------------------------ ACK sip:123456789@127.0.0.3:7777;transport=udp SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6aab.be435b72.3 Via: SIP/2.0/UDP 127.0.0.2:36676;branch=z9hG4bK-d8754z-7d9646c55b1fa2ff-1---d8754z- Max-Forwards: 30 Contact: To: ;tag=gUB5yNB70camp From: ;tag=a1e83108 Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 2 ACK Proxy-Authorization: Digest username="95878797",realm="127.0.0.1",nonce="5926b7f400001de81b704f6044ebbf3fcc509038f7b7efa4",uri="sip:123456789@127.0.0.1;transport=UDP",response="b81f6beb76103b488863ffafa71feec8",algorithm=MD5 User-Agent: Z 3.3.25608 r25552 Content-Length: 0 P-hint: rr-enforced X-AUTH-IP: 127.0.0.2 P-Accountcode: 4118807230 P-effective_caller_id_name: P-effective_caller_id_number: ------------------------------------------------------------------------ 2017-05-25 12:54:15.748366 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [ready][200] recv 345 bytes from udp/[127.0.0.1]:7000 at 12:54:16.371165: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK3ffc.b9334371.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-f156 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0c08-3294@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 541 bytes to udp/[127.0.0.1]:7000 at 12:54:16.371439: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK3ffc.b9334371.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-f156 To: ;tag=H44X0gvayN06H Call-ID: 2a3b058977bb0c08-3294@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 345 bytes from udp/[127.0.0.1]:7000 at 12:54:17.373476: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK8d06.4a5e35b7.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-7a90 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0d34-3302@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 541 bytes to udp/[127.0.0.1]:7000 at 12:54:17.373725: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK8d06.4a5e35b7.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-7a90 To: ;tag=jDyp2BDeUypSD Call-ID: 2a3b058977bb0d34-3302@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:17.548427 [DEBUG] switch_ivr_play_say.c:1910 done playing file silence_stream://2000 EXECUTE sofia/default/95878797@127.0.0.1:5060 set(ignore_early_media=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [ignore_early_media]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(fax_enable_t38_request=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [fax_enable_t38_request]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(fax_use_ecm=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [fax_use_ecm]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(fax_enable_t38=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [fax_enable_t38]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(fax_verbose=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [fax_verbose]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(session_in_hangup_hook=true) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [session_in_hangup_hook]=[true] EXECUTE sofia/default/95878797@127.0.0.1:5060 set(api_hangup_hook=system /var/www/html/FAX/scripts/emailfax.sh /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.tif 64 Sip6_tarifa+coste test@test.com /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.pdf) 2017-05-25 12:54:17.548427 [DEBUG] mod_dptools.c:1519 SET sofia/default/95878797@127.0.0.1:5060 [api_hangup_hook]=[system /var/www/html/FAX/scripts/emailfax.sh /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.tif 64 Sip6_tarifa+coste test@test.com /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.pdf] EXECUTE sofia/default/95878797@127.0.0.1:5060 rxfax(/tmp/123-FAX.tif) 2017-05-25 12:54:17.548427 [DEBUG] mod_spandsp_fax.c:1440 Raw read codec activation Success L16 20000 2017-05-25 12:54:17.548427 [DEBUG] switch_core_codec.c:221 sofia/default/95878797@127.0.0.1:5060 Push codec L16:100 2017-05-25 12:54:17.548427 [DEBUG] mod_spandsp_fax.c:1458 Raw write codec activation Success L16 recv 343 bytes from udp/[127.0.0.4]:7000 at 12:54:18.376658: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKd3f.1399208.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-4bc1 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0cd8-3330@127.0.0.4 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 563 bytes to udp/[127.0.0.4]:7000 at 12:54:18.376855: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKd3f.1399208.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-4bc1 To: ;tag=KpQF46XHr7ccS Call-ID: 2a3b058977bb0cd8-3330@127.0.0.4 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:18.808383 [DEBUG] switch_core_media.c:8901 sofia/default/95878797@127.0.0.1:5060 image media sdp: v=0 o=FreeSWITCH 1495683885 1495683887 IN IP4 127.0.0.3 s=FreeSWITCH c=IN IP4 127.0.0.3 t=0 0 m=image 25770 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2017-05-25 12:54:18.808383 [DEBUG] sofia_glue.c:1257 sofia/default/95878797@127.0.0.1:5060 sending invite version: 1.6.8 64bit Local SDP: v=0 o=FreeSWITCH 1495683885 1495683887 IN IP4 127.0.0.3 s=FreeSWITCH c=IN IP4 127.0.0.3 t=0 0 m=image 25770 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy send 1081 bytes to udp/[127.0.0.1]:5060 at 12:54:18.813525: ------------------------------------------------------------------------ INVITE sip:95878797@127.0.0.2:36676;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.3:7777;rport;branch=z9hG4bK06QmrpUmDry9B Route: Max-Forwards: 30 From: ;tag=gUB5yNB70camp To: ;tag=a1e83108 Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518765 INVITE Contact: User-Agent: TEST_FAX Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Content-Type: application/sdp Content-Length: 320 P-Accountcode: 9213634206 X-AUTH-IP: 127.0.0.2 P-Accountcode-1: 4118807230 v=0 o=FreeSWITCH 1495683885 1495683887 IN IP4 127.0.0.3 s=FreeSWITCH c=IN IP4 127.0.0.3 t=0 0 m=image 25770 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ recv 386 bytes from udp/[127.0.0.1]:5060 at 12:54:18.814212: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 127.0.0.3:7777;received=127.0.0.3;rport=7777;branch=z9hG4bK06QmrpUmDry9B From: ;tag=gUB5yNB70camp To: ;tag=a1e83108 Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518765 INVITE server: SBC02 Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:18.808383 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [calling][0] recv 1056 bytes from udp/[127.0.0.1]:5060 at 12:54:19.045470: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.3:7777;received=127.0.0.3;rport=7777;branch=z9hG4bK06QmrpUmDry9B Contact: To: ;tag=a1e83108 From: ;tag=gUB5yNB70camp Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518765 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Z 3.3.25608 r25552 Allow-Events: presence, kpml Content-Length: 381 v=0 o=Z 0 1 IN IP4 127.0.0.2 s=Z c=IN IP4 127.0.0.2 t=0 0 m=image 8000 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy a=oldoip:172.16.16.2 a=oldcip:172.16.16.2 ------------------------------------------------------------------------ 2017-05-25 12:54:19.028379 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [completing][200] 2017-05-25 12:54:19.028379 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=Z 0 1 IN IP4 127.0.0.2 s=Z c=IN IP4 127.0.0.2 t=0 0 m=image 8000 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy a=oldoip:172.16.16.2 a=oldcip:172.16.16.2 send 441 bytes to udp/[127.0.0.1]:5060 at 12:54:19.066530: ------------------------------------------------------------------------ ACK sip:95878797@127.0.0.2:36676;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.3:7777;rport;branch=z9hG4bK1FHDtHcra1mvQ Route: Max-Forwards: 70 From: ;tag=gUB5yNB70camp To: ;tag=a1e83108 Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518765 ACK Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:19.068308 [DEBUG] sofia.c:6858 Channel sofia/default/95878797@127.0.0.1:5060 entering state [ready][200] 2017-05-25 12:54:19.068308 [DEBUG] switch_core_media.c:9262 Remote address:port [127.0.0.2:8000] has not changed. 2017-05-25 12:54:19.068308 [DEBUG] switch_core_media.c:9262 Remote address:port [127.0.0.2:8000] has not changed. recv 338 bytes from udp/[127.0.0.4]:7000 at 12:54:19.379153: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKb068.b13494f2.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-9e25 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0c16-3360@0.0.0.0 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 558 bytes to udp/[127.0.0.4]:7000 at 12:54:19.379399: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKb068.b13494f2.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-9e25 To: ;tag=mZg851eNNg3ym Call-ID: 2a3b058977bb0c16-3360@0.0.0.0 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:19.848399 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed. 2017-05-25 12:54:19.848399 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present 2017-05-25 12:54:19.848399 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 CED tone is present 2017-05-25 12:54:19.848399 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state ANSWERING 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state ANSWERING 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CED to B_RX 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 4 2017-05-25 12:54:20.008389 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0 recv 338 bytes from udp/[127.0.0.4]:5060 at 12:54:20.382278: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6165.eafc8852.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-ed56 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0d2e-3354@0.0.0.0 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 558 bytes to udp/[127.0.0.4]:5060 at 12:54:20.382542: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6165.eafc8852.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-ed56 To: ;tag=N8907vZrjSSHg Call-ID: 2a3b058977bb0d2e-3354@0.0.0.0 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:20.728420 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type CSI - CRC OK (clean) 2017-05-25 12:54:20.728420 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-05-25 12:54:20.728420 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: CSI without final frame tag 2017-05-25 12:54:20.728420 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 03 40 31 31 31 31 30 30 30 30 20 20 20 20 20 20 20 20 20 20 20 20 2017-05-25 12:54:20.728420 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave CSI as: "00001111" 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type DIS - CRC OK, sig end (clean) 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: DIS with final frame tag 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx: ff 13 80 04 ee fa 80 80 9f 80 80 80 80 80 80 80 1f 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state ANSWERING 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS/DTC before DIS 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= Real-time Internet fax (T.38): Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= 3G mobile network: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= V.8 capabilities: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Preferred octets: 256 octets 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= Can receive fax: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= 2-D coding: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..10= Recording width: 215mm +- 1%, 255mm +- 1% and 303mm +- 1% 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 10..= Recording length: Unlimited 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .111 ....= Receiver's minimum scan line time: 0ms at 3.85 l/mm; T7.7 = T3.85 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Error correction mode (ECM): Non-ECM 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= T.6 coding: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= "Field not valid" supported: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Multiple selective polling: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Polled sub-address: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= T.43 coding: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Plane interleave: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= R8x15.4lines/mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= 300x300pels/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= Inch-based resolution preferred: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= Metric-based resolution preferred: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Selective polling: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Sub-addressing: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Password: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Character mode: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Digital network capability: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Duplex capability: Half only 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= JPEG coding: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Full colour mode: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= 12bits/pel component: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= No subsampling (1:1:1): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Custom illuminant: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Custom gamut range: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= North American Letter (215.9mm x 279.4mm): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= North American Legal (215.9mm x 355.6mm): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= HKM key management: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= RSA key management: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Override: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= HFX40 cipher: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Alternative cipher number 2: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Alternative cipher number 3: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= HFX40-I hashing: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Alternative hashing system 2: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= Alternative hashing system 3: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Reserved for future security features: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..00 0...= T.44 (Mixed Raster Content): 0 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Page length maximum stripe size for T.44 (Mixed Raster Content): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...0= Colour/gray-scale 300pels/25.4mm x 300lines/25.4mm or 400pels/25.4mm x 400lines/25.4mm resolution: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..0.= 100pels/25.4mm x 100lines/25.4mm for colour/gray scale: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .0..= Simple phase C BFT negotiations: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 0...= Extended BFT Negotiations capable: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...0 ....= Internet Selective Polling address (ISP): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Internet Routing Address (IRA): Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 1... ....= Extension indicator: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ...1= 600pels/25.4mm x 600lines/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... ..1.= 1200pels/25.4mm x 1200lines/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... .1..= 300pels/25.4mm x 600lines/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .... 1...= 400pels/25.4mm x 800lines/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ...1 ....= 600pels/25.4mm x 1200lines/25.4mm: Set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 ..0. ....= Colour/gray scale 600pels/25.4mm x 600lines/25.4mm: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 .0.. ....= Colour/gray scale 1200pels/25.4mm x 1200lines/25.4mm: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 0... ....= Extension indicator: Not set 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result ======================================================= 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:318 Remote station id: 00001111 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:319 Local station id: TEST_FAX 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate: 14400 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:322 ECM status off 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:323 remote country: 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:324 remote vendor: 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:325 remote model: 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:327 ============================================================================== 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS - nothing to send 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trying to receive file '/tmp/123-FAX.tif' 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS far end cannot transmit 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Status changing to 'Far end is not able to transmit' 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Flushing queued phase B_TX 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state ANSWERING to C 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: DCN with final frame tag 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx: ff 13 fb 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state C 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to D_TX 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4 2017-05-25 12:54:20.988379 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present recv 344 bytes from udp/[127.0.0.1]:5060 at 12:54:21.385787: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK10f7.7e633b7.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-e776 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0a7c-3288@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 540 bytes to udp/[127.0.0.1]:5060 at 12:54:21.386050: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK10f7.7e633b7.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-e776 To: ;tag=pH3S9QgvF2F4B Call-ID: 2a3b058977bb0a7c-3288@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 338 bytes from udp/[127.0.0.4]:5060 at 12:54:22.388596: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6f3e.1e8653a4.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-9de2 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0cce-3342@0.0.0.0 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 558 bytes to udp/[127.0.0.4]:5060 at 12:54:22.388954: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK6f3e.1e8653a4.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-9de2 To: ;tag=QtvjBK1ZcB6pQ Call-ID: 2a3b058977bb0cce-3342@0.0.0.0 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 345 bytes from udp/[127.0.0.1]:7000 at 12:54:23.391417: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK9cdd.c3786c52.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-193f CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0d9e-3306@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 541 bytes to udp/[127.0.0.1]:7000 at 12:54:23.391659: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK9cdd.c3786c52.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-193f To: ;tag=r3NBDej39Kv9j Call-ID: 2a3b058977bb0d9e-3306@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting final pause before disconnecting 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to E 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 1 2017-05-25 12:54:23.408383 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state C to B recv 344 bytes from udp/[127.0.0.4]:7000 at 12:54:24.394321: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKb6f.dbf2aa56.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-7854 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0cda-3330@127.0.0.4 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 564 bytes to udp/[127.0.0.4]:7000 at 12:54:24.394564: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKb6f.dbf2aa56.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-7854 To: ;tag=ScF4e9266vjve Call-ID: 2a3b058977bb0cda-3330@127.0.0.4 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase E, state B 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:496 ============================================================================== 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:508 Fax processing not successful - result (10) Far end is not able to transmit. 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:513 Remote station id: 00001111 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:514 Local station id: TEST_FAX 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 0 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 0 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 0x0 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 14400 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:521 ECM status off 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:522 remote country: 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:523 remote vendor: 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:524 remote model: 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:526 ============================================================================== 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state B to CALL_FINISHED 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase E to CALL_FINISHED 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 9 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 9 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T FAX exchange complete 2017-05-25 12:54:24.728348 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed recv 344 bytes from udp/[127.0.0.1]:7000 at 12:54:25.406040: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKd9c.59b22373.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-f7e6 CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0da0-3306@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 540 bytes to udp/[127.0.0.1]:7000 at 12:54:25.406332: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bKd9c.59b22373.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-f7e6 To: ;tag=tN8vg4Ka458ea Call-ID: 2a3b058977bb0da0-3306@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:26.028382 [DEBUG] switch_core_codec.c:246 sofia/default/95878797@127.0.0.1:5060 Restore previous codec PCMA:8. EXECUTE sofia/default/95878797@127.0.0.1:5060 hangup() 2017-05-25 12:54:26.028382 [NOTICE] mod_dptools.c:1283 Hangup sofia/default/95878797@127.0.0.1:5060 [CS_EXECUTE] [NORMAL_CLEARING] 2017-05-25 12:54:26.028382 [DEBUG] switch_core_session.c:2796 sofia/default/95878797@127.0.0.1:5060 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:609 (sofia/default/95878797@127.0.0.1:5060) State EXECUTE going to sleep 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_HANGUP 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:809 (sofia/default/95878797@127.0.0.1:5060) Callstate Change ACTIVE -> HANGUP 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:811 (sofia/default/95878797@127.0.0.1:5060) State HANGUP 2017-05-25 12:54:26.028382 [DEBUG] mod_sofia.c:437 Channel sofia/default/95878797@127.0.0.1:5060 hanging up, cause: NORMAL_CLEARING 2017-05-25 12:54:26.028382 [DEBUG] mod_sofia.c:490 Sending BYE to sofia/default/95878797@127.0.0.1:5060 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:60 sofia/default/95878797@127.0.0.1:5060 Standard HANGUP, cause: NORMAL_CLEARING 2017-05-25 12:54:26.028382 [DEBUG] switch_core_state_machine.c:811 (sofia/default/95878797@127.0.0.1:5060) State HANGUP going to sleep send 624 bytes to udp/[127.0.0.1]:5060 at 12:54:26.036918: ------------------------------------------------------------------------ BYE sip:95878797@127.0.0.2:36676;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 127.0.0.3:7777;rport;branch=z9hG4bK2ra6UcXU79aFK Route: Max-Forwards: 70 From: ;tag=gUB5yNB70camp To: ;tag=a1e83108 Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518766 BYE User-Agent: TEST_FAX Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ recv 450 bytes from udp/[127.0.0.1]:5060 at 12:54:26.224966: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.3:7777;received=127.0.0.3;rport=7777;branch=z9hG4bK2ra6UcXU79aFK Contact: To: ;tag=a1e83108 From: ;tag=gUB5yNB70camp Call-ID: MThhMDhmZGZlNTY3MjdjZmRhNTJhOGFkNTE1MzgzZjc. CSeq: 107518766 BYE User-Agent: Z 3.3.25608 r25552 Content-Length: 0 ------------------------------------------------------------------------ recv 345 bytes from udp/[127.0.0.1]:7000 at 12:54:26.408789: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK7ead.8e302c77.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-2dbe CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0bc8-3292@127.0.0.1 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 541 bytes to udp/[127.0.0.1]:7000 at 12:54:26.409107: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK7ead.8e302c77.0 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-2dbe To: ;tag=Uy1NjZ4D1eZ1N Call-ID: 2a3b058977bb0bc8-3292@127.0.0.1 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:27.328401 [DEBUG] switch_core_state_machine.c:742 Hangup Command with Session system(/var/www/html/FAX/scripts/emailfax.sh /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.tif 64 Sip6_tarifa+coste test@test.com /var/www/html/FAX/receive_fax_files/59fe0ca5-958e-4801-9c69-3ef056fb102f-FAX.pdf): SMTP -> FROM SERVER: 220 smtp.gmail.com ESMTP s5sm6864160wra.60 - gsmtp SMTP -> FROM SERVER: 250-smtp.gmail.com at your service, [127.0.0.3] 250-SIZE 35882577 250-8BITMIME 250-AUTH LOGIN PLAIN XOAUTH2 PLAIN-CLIENTTOKEN OAUTHBEARER XOAUTH 250-ENHANCEDSTATUSCODES 250-PIPELINING 250-CHUNKING 250 SMTPUTF8 SMTP -> FROM SERVER: 250 2.1.0 OK s5sm6864160wra.60 - gsmtp SMTP -> FROM SERVER: 250 2.1.5 OK s5sm6864160wra.60 - gsmtp SMTP -> FROM SERVER: 354 Go ahead s5sm6864160wra.60 - gsmtp SMTP -> FROM SERVER: 250 2.0.0 OK 1495709667 s5sm6864160wra.60 - gsmtp 2017-05-25 12:54:27.328401 [DEBUG] switch_core_state_machine.c:578 (sofia/default/95878797@127.0.0.1:5060) State Change CS_HANGUP -> CS_REPORTING 2017-05-25 12:54:27.328401 [DEBUG] switch_core_state_machine.c:543 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_REPORTING 2017-05-25 12:54:27.328401 [DEBUG] switch_core_state_machine.c:897 (sofia/default/95878797@127.0.0.1:5060) State REPORTING 2017-05-25 12:54:27.328401 [INFO] mod_json_cdr.c:271 Process [59fe0ca5-958e-4801-9c69-3ef056fb102f.cdr.json] recv 345 bytes from udp/[127.0.0.4]:7000 at 12:54:27.412257: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK3996.faf8db94.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-776c CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0d92-3332@127.0.0.4 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 565 bytes to udp/[127.0.0.4]:7000 at 12:54:27.412519: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:7000;branch=z9hG4bK3996.faf8db94.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-776c To: ;tag=v7temtNHyQNmH Call-ID: 2a3b058977bb0d92-3332@127.0.0.4 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:174 sofia/default/95878797@127.0.0.1:5060 Standard REPORTING, cause: NORMAL_CLEARING 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:897 (sofia/default/95878797@127.0.0.1:5060) State REPORTING going to sleep 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:569 (sofia/default/95878797@127.0.0.1:5060) State Change CS_REPORTING -> CS_DESTROY 2017-05-25 12:54:27.468387 [DEBUG] switch_core_session.c:1646 Session 5 (sofia/default/95878797@127.0.0.1:5060) Locked, Waiting on external entities 2017-05-25 12:54:27.468387 [NOTICE] switch_core_session.c:1664 Session 5 (sofia/default/95878797@127.0.0.1:5060) Ended 2017-05-25 12:54:27.468387 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/95878797@127.0.0.1:5060 [CS_DESTROY] 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:700 (sofia/default/95878797@127.0.0.1:5060) Running State Change CS_DESTROY 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:710 (sofia/default/95878797@127.0.0.1:5060) State DESTROY 2017-05-25 12:54:27.468387 [DEBUG] mod_sofia.c:342 sofia/default/95878797@127.0.0.1:5060 SOFIA DESTROY 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:181 sofia/default/95878797@127.0.0.1:5060 Standard DESTROY 2017-05-25 12:54:27.468387 [DEBUG] switch_core_state_machine.c:710 (sofia/default/95878797@127.0.0.1:5060) State DESTROY going to sleep 2017-05-25 12:54:27.548389 [DEBUG] switch_scheduler.c:144 Deleting task 7 switch_ivr_schedule_hangup (59fe0ca5-958e-4801-9c69-3ef056fb102f) recv 338 bytes from udp/[127.0.0.4]:5060 at 12:54:28.415321: ------------------------------------------------------------------------ OPTIONS sip:127.0.0.3:7777 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK2add.abfe7083.0 To: sip:127.0.0.3:7777 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-5f6c CSeq: 14 OPTIONS Call-ID: 2a3b058977bb0cd0-3342@0.0.0.0 Max-Forwards: 70 Content-Length: 0 User-Agent: SIP Proxy ------------------------------------------------------------------------ send 558 bytes to udp/[127.0.0.4]:5060 at 12:54:28.415600: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK2add.abfe7083.0;received=127.0.0.4 From: ;tag=df56c3a3d84e6efb9ab79966da869d5e-5f6c To: ;tag=Xgm7NN6mU0B7c Call-ID: 2a3b058977bb0cd0-3342@0.0.0.0 CSeq: 14 OPTIONS Contact: User-Agent: TEST_FAX Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------