Hi people! I've setup two Windows boxes with FS 1.3.8b and started testing T.38 functionality between them. First FS box should send fax and second one should receive it, hopefully. On receiving side I've setup following dialplan <extension name="fax_receive"> <condition field="destination_number" expression="^9178"> <action application="set" data="fax_enable_t38=true"/> <action application="set" data="fax_enable_t38_request=true"/> <action application="set" data="absolute_codec_string=PCMA"/> <action application="set" data="proxy_media=true"/> <action application="set" data="bypass_media=false"/> <action application="set" data="use-ecm=true"/> <action application="answer" /> <action application="playback" data="silence_stream://2000"/> <action application="rxfax" data="fax/rxfax.tif"/> <action application="hangup"/> </condition> </extension> On sending side I use command originate {origination_caller_id_number=1234}sofia/gateway/fs2/9178 &txfax(fax.tif) But I always get error "Fax processing not successful - result (49) The call dropped prematurely." or "Fax processing not successful - result (17) Received a DCN while waiting for a DIS". Any hint for me? Thanks ------------------------------------------------------------------------------------------------------------------------- freeswitch@fs2> recv 1068 bytes from udp/[10.0.0.1]:5060 at 20:20:29.334875: ------------------------------------------------------------------------ INVITE sip:9178@10.0.0.2 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.1;rport;branch=z9hG4bKry6g7U1QDer3g Max-Forwards: 70 From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2> Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076550 INVITE Contact: <sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2> User-Agent: FreeSWITCH-mod_sofia/1.3.8b Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, r efer Content-Type: application/sdp Content-Disposition: session Content-Length: 193 X-FS-Support: update_display,send_info Remote-Party-ID: <sip:1234@10.0.0.2>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1354798433 1354798434 IN IP4 10.0.0.1 s=FreeSWITCH c=IN IP4 10.0.0.1 t=0 0 m=audio 26796 RTP/AVP 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ send 297 bytes to udp/[10.0.0.1]:5060 at 20:20:29.334875: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.1;rport=5060;branch=z9hG4bKry6g7U1QDer3g From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2> Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076550 INVITE User-Agent: FreeSWITCH-mod_sofia/1.3.8b Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:29.334875 [NOTICE] switch_channel.c:968 New Channel sofia/internal/FreeSWITCH@10.0.0.2 [712d8bfe-f045-4665-8b9c-f610a4f1a438] 2012-12-06 21:20:29.350500 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.350500 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.350500 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_NEW 2012-12-06 21:20:29.350500 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/FreeSWITCH@10.0.0.2) State NEW 2012-12-06 21:20:29.350500 [DEBUG] sofia.c:7678 IP 10.0.0.1 Approved by acl "domains[]". Access Granted. 2012-12-06 21:20:29.522375 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [received][100] 2012-12-06 21:20:29.522375 [DEBUG] sofia.c:5614 Remote SDP: v=0 o=FreeSWITCH 1354798433 1354798434 IN IP4 10.0.0.1 s=FreeSWITCH c=IN IP4 10.0.0.1 t=0 0 m=audio 26796 RTP/AVP 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2012-12-06 21:20:29.522375 [DEBUG] sofia.c:5811 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_NEW -> CS_INIT 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_INIT 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/FreeSWITCH@10.0.0.2) State INIT 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:86 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA INIT 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:126 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_INIT -> CS_ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/FreeSWITCH@10.0.0.2) State INIT going to sleep 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_channel.c:2003 (sofia/internal/FreeSWITCH@10.0.0.2) Callstate Change DOWN -> RINGING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/FreeSWITCH@10.0.0.2) State ROUTING 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:149 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:117 sofia/internal/FreeSWITCH@10.0.0.2 Standard ROUTING 2012-12-06 21:20:29.522375 [INFO] mod_dialplan_xml.c:498 Processing <1234>->9178 in context public Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [public->unloop] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [public->outside_call] continue=true Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Absolute Condition [outside_call] Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(outside_call=true) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [public->call_debug] continue=true Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [public_extensions] destination_number(9178) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [public->fax_extensions] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [fax_extensions] destination_number(9178) =~ /^9178/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action transfer(9178 XML default) 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_ROUTING -> CS_EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/FreeSWITCH@10.0.0.2) State ROUTING going to sleep 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/FreeSWITCH@10.0.0.2) State EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:242 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:209 sofia/internal/FreeSWITCH@10.0.0.2 Standard EXECUTE EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(outside_call=true) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [outside_call]=[true] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 export(RFC2822_DATE=Thu, 06 Dec 2012 21:20:29 Central European Standard Time) 2012-12-06 21:20:29.522375 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 06 Dec 2012 21:20:29 Central European Standard Time ] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 transfer(9178 XML default) 2012-12-06 21:20:29.522375 [DEBUG] switch_ivr.c:1773 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_EXECUTE -> CS_ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [NOTICE] switch_ivr.c:1779 Transfer sofia/internal/FreeSWITCH@10.0.0.2 to XML[9178@default] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/FreeSWITCH@10.0.0.2) State EXECUTE going to sleep 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/FreeSWITCH@10.0.0.2) State ROUTING 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:149 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA ROUTING 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:117 sofia/internal/FreeSWITCH@10.0.0.2 Standard ROUTING 2012-12-06 21:20:29.522375 [INFO] mod_dialplan_xml.c:498 Processing <1234>->9178 in context default Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->unloop] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->tod_example] continue=true Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [global-intercept] destination_number(9178) =~ /^886$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [group-intercept] destination_number(9178) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [intercept-ext] destination_number(9178) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->redial] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [redial] destination_number(9178) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->global] continue=true Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break= never Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-f alse Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=FreeSWITCH 1354798433 1354798434 IN IP4 10.0.0.1 s=FreeSWITCH c=IN IP4 10.0.0.1 t=0 0 m=audio 26796 RTP/AVP 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Absolute Condition [global] Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [snom-demo-2] destination_number(9178) =~ /^9001$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [snom-demo-1] destination_number(9178) =~ /^9000$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [eavesdrop] destination_number(9178) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [eavesdrop] destination_number(9178) =~ /^779$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->call_return] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [call_return] destination_number(9178) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->del-group] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [del-group] destination_number(9178) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->add-group] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [add-group] destination_number(9178) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [call-group-simo] destination_number(9178) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [call-group-order] destination_number(9178) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [extension-intercom] destination_number(9178) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [Local_Extension] destination_number(9178) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->Local_Extension_Skinny] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [Local_Extension_Skinny] destination_number(9178) =~ /^(11[01][0-9])$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->group_dial_sales] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [group_dial_sales] destination_number(9178) =~ /^2000$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->group_dial_support] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [group_dial_support] destination_number(9178) =~ /^2001$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->group_dial_billing] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [group_dial_billing] destination_number(9178) =~ /^2002$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->operator] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [operator] destination_number(9178) =~ /^(operator|0)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->vmain] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [vmain] destination_number(9178) =~ /^vmain$|^4000$|^\*98$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->sip_uri] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [sip_uri] destination_number(9178) =~ /^sip:(.*)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->nb_conferences] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [nb_conferences] destination_number(9178) =~ /^(30\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->wb_conferences] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [wb_conferences] destination_number(9178) =~ /^(31\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->uwb_conferences] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [uwb_conferences] destination_number(9178) =~ /^(32\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [cdquality_conferences] destination_number(9178) =~ /^(33\d{2})$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->freeswitch_public_conf_via_sip] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(9178) =~ /^9(888|8888|1616|3232)$/ break =on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [mad_boss_intercom] destination_number(9178) =~ /^0911$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [mad_boss_intercom] destination_number(9178) =~ /^0912$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->mad_boss] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [mad_boss] destination_number(9178) =~ /^0913$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->ivr_demo] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [ivr_demo] destination_number(9178) =~ /^5000$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->dynamic_conference] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [dynamic_conference] destination_number(9178) =~ /^5001$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->rtp_multicast_page] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [rtp_multicast_page] destination_number(9178) =~ /^pagegroup$|^7243$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->park] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [park] destination_number(9178) =~ /^5900$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->unpark] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [unpark] destination_number(9178) =~ /^5901$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->valet_park] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [valet_park] destination_number(9178) =~ /^(6000)$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->valet_park] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [valet_park] destination_number(9178) =~ /^(60\d[1-9])$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->park] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [park] destination_number(9178) =~ /park\+(\d+)/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->unpark] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [unpark] destination_number(9178) =~ /^parking$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->park] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [park] destination_number(9178) =~ /callpark/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->unpark] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [unpark] destination_number(9178) =~ /pickup/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->wait] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (FAIL) [wait] destination_number(9178) =~ /^wait$/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 parsing [default->fax_receive] continue=false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Regex (PASS) [fax_receive] destination_number(9178) =~ /^9178/ break=on-false Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(fax_enable_t38=true) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(fax_enable_t38_request=true) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(absolute_codec_string=PCMA) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(proxy_media=true) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(bypass_media=false) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action set(use-ecm=true) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action answer() Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action playback(silence_stream://2000) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action rxfax(fax/rxfax.tif) Dialplan: sofia/internal/FreeSWITCH@10.0.0.2 Action hangup() 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_ROUTING -> CS_EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/FreeSWITCH@10.0.0.2) State ROUTING going to sleep 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/FreeSWITCH@10.0.0.2) State EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:242 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA EXECUTE 2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:209 sofia/internal/FreeSWITCH@10.0.0.2 Standard EXECUTE EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 hash(insert/0.0.0.0-spymap/1234/712d8bfe-f045-4665-8b9c-f610a4f1a438) EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 hash(insert/0.0.0.0-last_dial/1234/9178) EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 hash(insert/0.0.0.0-last_dial/global/712d8bfe-f045-4665-8b9c-f610a4f1a438) EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 export(RFC2822_DATE=Thu, 06 Dec 2012 21:20:29 Central European Standard Time) 2012-12-06 21:20:29.522375 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 06 Dec 2012 21:20:29 Central European Standard Time ] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(fax_enable_t38=true) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [fax_enable_t38]=[true] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(fax_enable_t38_request=true) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [fax_enable_t38_request]=[true] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(absolute_codec_string=PCMA) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [absolute_codec_string]=[PCMA] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(proxy_media=true) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [proxy_media]=[true] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(bypass_media=false) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [bypass_media]=[false] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 set(use-ecm=true) 2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344 sofia/internal/FreeSWITCH@10.0.0.2 SET [use-ecm]=[true] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 answer() 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:5134 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3093 Set Codec sofia/internal/FreeSWITCH@10.0.0.2 PCMA/8000 20 ms 160 samples 64000 bits 2012-12-06 21:20:29.663000 [DEBUG] switch_core_codec.c:111 sofia/internal/FreeSWITCH@10.0.0.2 Original read codec set to PCMA:8 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:5263 Set 2833 dtmf send/recv payload to 101 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3348 AUDIO RTP [sofia/internal/FreeSWITCH@10.0.0.2] 10.0.0.2 port 16666 -> 10.0.0.1 port 26796 codec: 8 ms: 20 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:1928 Starting timer [soft] 160 bytes per 20ms 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: START SESSION INITIALIZATION. sID=43. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ZID=303030303030303030393363. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Loading User's profile: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: allowclear: OFF 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: autosecure: ON 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: disclose_bit: OFF 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: signal. role: Unknown 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: TTL: 4294967295 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: SAS schemes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 B256 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 B32 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Ciphers: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 AES3 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 AES1 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: PK schemes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 DH3k 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 DH2k 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 Mult 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp .c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATL: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 HS32 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Hashes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 S256 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Session initialization - DONE. sID=43. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM to sID=43: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Empty slot was found - initializing new stream with ID=43. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM - DONE. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp engine]: START STREAM ID=43 mode=CLEAR state=ACTIVE. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=43 CLEAR switching <ACTIVE> ---> <START>. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22463 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3612 Set 2833 dtmf send payload to 101 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3618 Set 2833 dtmf receive payload to 101 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3645 sofia/internal/FreeSWITCH@10.0.0.2 Set rtp dtmf delay to 40 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3651 Set comfort noise payload to 13 2012-12-06 21:20:29.663000 [NOTICE] sofia_glue.c:4256 Pre-Answer sofia/internal/FreeSWITCH@10.0.0.2! 2012-12-06 21:20:29.663000 [DEBUG] switch_channel.c:3136 (sofia/internal/FreeSWITCH@10.0.0.2) Callstate Change RINGING -> EARLY 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3348 AUDIO RTP [sofia/internal/FreeSWITCH@10.0.0.2] 10.0.0.2 port 16666 -> 10.0.0.1 port 26796 codec: 8 ms: 20 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:1928 Starting timer [soft] 160 bytes per 20ms 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: START SESSION INITIALIZATION. sID=44. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ZID=303030303030303030393363. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Loading User's profile: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: allowclear: OFF 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: autosecure: ON 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: disclose_bit: OFF 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: signal. role: Unknown 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: TTL: 4294967295 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: SAS schemes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 B256 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 B32 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Ciphers: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 AES3 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 AES1 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: PK schemes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 DH3k 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 DH2k 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 Mult 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp .c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATL: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 HS32 2012-12-0 6 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Hashes: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 S256 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Session initialization - DONE. sID=44. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM to sID=44: 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Empty slot was found - initializing new stream with ID=44. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM - DONE. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp engine]: START STREAM ID=44 mode=CLEAR state=ACTIVE. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=44 CLEAR switching <ACTIVE> ---> <START>. 2012-12-06 21:20:29.663000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445208357 seq=9178 size=140. Stream 44:CLEAR:START 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3612 Set 2833 dtmf send payload to 101 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3618 Set 2833 dtmf receive payload to 101 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3645 sofia/internal/FreeSWITCH@10.0.0.2 Set rtp dtmf delay to 40 2012-12-06 21:20:29.663000 [DEBUG] sofia_glue.c:3651 Set comfort noise payload to 13 2012-12-06 21:20:29.663000 [DEBUG] mod_sofia.c:856 Local SDP sofia/internal/FreeSWITCH@10.0.0.2: v=0 o=FreeSWITCH 1354808563 1354808564 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=audio 16666 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv 2012-12-06 21:20:29.663000 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.663000 [DEBUG] switch_channel.c:3395 (sofia/internal/FreeSWITCH@10.0.0.2) Callstate Change EARLY -> ACTIVE 2012-12-06 21:20:29.663000 [NOTICE] mod_dptools.c:1176 Channel [sofia/internal/FreeSWITCH@10.0.0.2] has been answered send 1181 bytes to udp/[10.0.0.1]:5060 at 20:20:29.678625: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.1;rport=5060;branch=z9hG4bKry6g7U1QDer3g From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076550 INVITE Contact: <sip:9178@10.0.0.2:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.3.8b Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, r efer Content-Type: application/sdp Content-Disposition: session Content-Length: 236 X-FS-Display-Name: 9178 X-FS-Display-Number: sip:9178@10.0.0.2 X-FS-Support: update_display,send_info Remote-Party-ID: "9178" <sip:9178@10.0.0.2>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1354808563 1354808564 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=audio 16666 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ 2012-12-06 21:20:29.663000 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.663000 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [completed][200] EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 playback(silence_stream://2000) 2012-12-06 21:20:29.663000 [DEBUG] switch_ivr_play_say.c:1309 Codec Activated L16@8000hz 1 channels 20ms 2012-12-06 21:20:29.741125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445208357 seq=9179 size=140. Stream 44:CLEAR:START 2012-12-06 21:20:29.741125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22464 size=140. Stream 43:CLEAR:START recv 376 bytes from udp/[10.0.0.1]:5060 at 20:20:29.850500: ------------------------------------------------------------------------ ACK sip:9178@10.0.0.2:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.1;rport;branch=z9hG4bKS7Z98pjUaQepc Max-Forwards: 70 From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076550 ACK Contact: <sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2> Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:29.850500 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.850500 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.850500 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:29.850500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445208357 seq=9180 size=140. Stream 44:CLEAR:START 2012-12-06 21:20:29.866125 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [ready][200] 2012-12-06 21:20:29.881750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22465 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:30.053625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445208357 seq=9181 size=140. Stream 44:CLEAR:START 2012-12-06 21:20:30.084875 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22466 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Received <Hello > packet with ssrc=1413688741 seq=4776/4776 size=140. Stream44: CLEAR:START. 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: Processing HELLO from FreeSWITCH V=1.10, P=0, M=1. 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: ac=1 cc=2 sc=2 kc=3 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: S256AES3AES1HS32DH3kDH2kMultB256B32 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: Received HELLO had the same protocol V. 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: Received a ZRTP_HELLO packet with the same ZRTP ID that we have. This is likely due to a bug in the software. Ignoring the ZRTP_HELLO packet, therefore this call cannot be encrypted. 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: Enter InitiatingError State with ERROR:<Equal ZIDs in Hello>, notification Ena bled. ID=44 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=44 CLEAR switching <START> ---> <INITERROR>. 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <ERROR> ssrc=1445208357 seq=9182 size=32. Stream 44:CLEAR:INITERROR 2012-12-06 21:20:30.131750 [DEBUG] switch_rtp.c:916 [ zrtp engine]: ERROR! _zrtp_machine_process_hello() failed with status=1. ID=44 2012-12-06 21:20:30.147375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Received <Error > packet with ssrc=1413688741 seq=4777/4777 size=32. Stream44:C LEAR:INITERROR. 2012-12-06 21:20:30.147375 [DEBUG] switch_rtp.c:916 [ zrtp engine]: Enter PendingError State with ERROR:<Equal ZIDs in Hello>. ID=44 2012-12-06 21:20:30.147375 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=44 CLEAR switching <INITERROR> ---> <PENDERROR>. 2012-12-06 21:20:30.147375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <ERRORACK> ssrc=1445208357 seq=9183 size=28. Stream 44:CLEAR:PENDERROR 2012-12-06 21:20:30.194250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Received <ErrorACK> packet with ssrc=1413688741 seq=4778/4778 size=28. Stream44:C LEAR:PENDERROR. 2012-12-06 21:20:30.288000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <ERRORACK> ssrc=1445208357 seq=9184 size=28. Stream 44:CLEAR:PENDERROR 2012-12-06 21:20:30.303625 [DEBUG] switch_rtp.c:3622 Correct ip/port confirmed. 2012-12-06 21:20:30.303625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22467 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:30.350500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Received <ErrorACK> packet with ssrc=1413688741 seq=4779/4779 size=28. Stream44:C LEAR:PENDERROR. 2012-12-06 21:20:30.444250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <ERRORACK> ssrc=1445208357 seq=9185 size=28. Stream 44:CLEAR:PENDERROR 2012-12-06 21:20:30.522375 [DEBUG] switch_rtp.c:916 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO _ZRTP_QUICK event. ID=43 2012-12-06 21:20:30.522375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22468 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:30.553625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Received <ErrorACK> packet with ssrc=1413688741 seq=4780/4780 size=28. Stream44:C LEAR:PENDERROR. 2012-12-06 21:20:30.616125 [DEBUG] switch_rtp.c:916 [ zrtp engine]: WARNING! ERRORACK Max retransmissions count reached. ID=44 2012-12-06 21:20:30.616125 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=44 CLEAR switching <PENDERROR> ---> <ERROR>. 2012-12-06 21:20:30.725500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22469 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:30.928625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22470 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:31.131750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22471 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:31.350500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22472 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:31.553625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22473 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:31.741125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22474 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:31.834875 [DEBUG] switch_ivr_play_say.c:1682 done playing file silence_stream://2000 EXECUTE sofia/internal/FreeSWITCH@10.0.0.2 rxfax(fax/rxfax.tif) 2012-12-06 21:20:31.834875 [DEBUG] mod_spandsp_fax.c:1363 Raw read codec activation Success L16 20000 2012-12-06 21:20:31.834875 [DEBUG] switch_core_codec.c:219 sofia/internal/FreeSWITCH@10.0.0.2 Push codec L16:70 2012-12-06 21:20:31.834875 [DEBUG] mod_spandsp_fax.c:1379 Raw write codec activation Success L16 2012-12-06 21:20:31.944250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22475 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:32.163000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22476 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:32.366125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22477 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:32.569250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22478 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:32.772375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22479 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:32.975500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22480 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:33.084875 [DEBUG] sofia_glue.c:173 sofia/internal/FreeSWITCH@10.0.0.2 image media sdp: v=0 o=FreeSWITCH 1354808563 1354808565 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=image 16666 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2012-12-06 21:20:33.084875 [DEBUG] sofia_glue.c:2647 Local SDP: v=0 o=FreeSWITCH 1354808563 1354808565 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=image 16666 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy send 992 bytes to udp/[10.0.0.1]:5060 at 20:20:33.084875: ------------------------------------------------------------------------ INVITE sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.2;rport;branch=z9hG4bKj8736jSrDv4ZB Max-Forwards: 69 From: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD To: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076552 INVITE Contact: <sip:9178@10.0.0.2:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.3.8b Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 308 X-FS-Support: update_display,send_info v=0 o=FreeSWITCH 1354808563 1354808565 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=image 16666 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ 2012-12-06 21:20:33.084875 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] recv 315 bytes from udp/[10.0.0.1]:5060 at 20:20:33.084875: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.2;rport=5060;branch=z9hG4bKj8736jSrDv4ZB From: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD To: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076552 INVITE User-Agent: FreeSWITCH-mod_sofia/1.3.8b Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:33.084875 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [calling][0] recv 927 bytes from udp/[10.0.0.1]:5060 at 20:20:33.116125: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.2;rport=5060;branch=z9hG4bKj8736jSrDv4ZB From: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD To: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076552 INVITE Contact: <sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2> User-Agent: FreeSWITCH-mod_sofia/1.3.8b Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 308 v=0 o=FreeSWITCH 1354798433 1354798435 IN IP4 10.0.0.1 s=FreeSWITCH c=IN IP4 10.0.0.1 t=0 0 m=image 26796 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ 2012-12-06 21:20:33.116125 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.116125 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.116125 [INFO] sofia.c:931 sofia/internal/FreeSWITCH@10.0.0.2 Update Callee ID to "FreeSWITCH" <FreeSWITCH> 2012-12-06 21:20:33.194250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22481 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:33.272375 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [completing][200] 2012-12-06 21:20:33.272375 [DEBUG] sofia.c:5614 Remote SDP: v=0 o=FreeSWITCH 1354798433 1354798435 IN IP4 10.0.0.1 s=FreeSWITCH c=IN IP4 10.0.0.1 t=0 0 m=image 26796 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy send 327 bytes to udp/[10.0.0.1]:5060 at 20:20:33.288000: ------------------------------------------------------------------------ ACK sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.2;rport;branch=z9hG4bKKH1v8Dava5tjQ Max-Forwards: 70 From: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD To: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076552 ACK Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:33.272375 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.272375 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.288000 [DEBUG] sofia.c:5603 Channel sofia/internal/FreeSWITCH@10.0.0.2 entering state [ready][200] 2012-12-06 21:20:33.366125 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 6 bytes. 2012-12-06 21:20:33.381750 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 6 bytes. 2012-12-06 21:20:33.381750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1445101237 seq=22482 size=140. Stream 43:CLEAR:START 2012-12-06 21:20:33.413000 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 6 bytes. 2012-12-06 21:20:33.428625 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 8 bytes. 2012-12-06 21:20:33.444250 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 8 bytes. 2012-12-06 21:20:33.444250 [DEBUG] sofia_glue.c:3348 AUDIO RTP [sofia/internal/FreeSWITCH@10.0.0.2] 10.0.0.2 port 16666 -> 10.0.0.1 port 26796 codec: 8 ms: 20 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:1928 Starting timer [soft] 160 bytes per 20ms 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: START SESSION INITIALIZATION. sID=45. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: ZID=303030303030303030393363. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Loading User's profile: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: allowclear: OFF 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: autosecure: ON 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: disclose_bit: OFF 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: signal. role: Unknown 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: TTL: 4294967295 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: SAS schemes: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 B256 2012-12-0 6 21:20:33.444250 [DEBUG] switch_rtp.c:916 B32 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Ciphers: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 AES3 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 AES1 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: PK schemes: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 DH3k 2012-12-0 6 21:20:33.444250 [DEBUG] switch_rtp.c:916 DH2k 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 Mult 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp .c:916 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATL: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 HS32 2012-12-0 6 21:20:33.444250 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Hashes: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 S256 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Session initialization - DONE. sID=45. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM to sID=45: 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Empty slot was found - initializing new stream with ID=45. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp main]: ATTACH NEW STREAM - DONE. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp engine]: START STREAM ID=45 mode=CLEAR state=ACTIVE. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=45 CLEAR switching <ACTIVE> ---> <START>. 2012-12-06 21:20:33.444250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63418 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:33.444250 [ERR] sofia_glue.c:3549 Invalid Jitterbuffer spec [0] must be between 20 and 10000 2012-12-06 21:20:33.444250 [DEBUG] sofia_glue.c:3612 Set 2833 dtmf send payload to 101 2012-12-06 21:20:33.444250 [DEBUG] sofia_glue.c:3618 Set 2833 dtmf receive payload to 101 2012-12-06 21:20:33.444250 [DEBUG] sofia_glue.c:3645 sofia/internal/FreeSWITCH@10.0.0.2 Set rtp dtmf delay to 40 2012-12-06 21:20:33.475500 [WARNING] switch_rtp.c:3652 Ignoring invalid RTP packet size of 8 bytes. 2012-12-06 21:20:33.491125 [DEBUG] mod_sofia.c:1487 Remote address:port [10.0.0.1:26796] has not changed. 2012-12-06 21:20:33.491125 [DEBUG] mod_sofia.c:1487 Remote address:port [10.0.0.1:26796] has not changed. 2012-12-06 21:20:33.491125 [DEBUG] sofia_glue.c:173 sofia/internal/FreeSWITCH@10.0.0.2 image media sdp: v=0 o=FreeSWITCH 1354808563 1354808566 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=image 16666 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2012-12-06 21:20:33.491125 [DEBUG] mod_sofia.c:1487 Remote address:port [10.0.0.1:26796] has not changed. 2012-12-06 21:20:33.491125 [DEBUG] mod_sofia.c:1487 Remote address:port [10.0.0.1:26796] has not changed. 2012-12-06 21:20:33.491125 [DEBUG] sofia_glue.c:173 sofia/internal/FreeSWITCH@10.0.0.2 image media sdp: v=0 o=FreeSWITCH 1354808563 1354808567 IN IP4 10.0.0.2 s=FreeSWITCH c=IN IP4 10.0.0.2 t=0 0 m=image 16666 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2012-12-06 21:20:33.491125 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.491125 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:33.522375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63419 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:33.584875 [DEBUG] switch_rtp.c:916 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=43 2012-12-06 21:20:33.584875 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=43 CLEAR switching <START> ---> <NOZRTP>. 2012-12-06 21:20:33.631750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63420 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:33.850500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63421 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:34.053625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63422 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:34.241125 [DEBUG] switch_rtp.c:916 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO _ZRTP_QUICK event. ID=45 2012-12-06 21:20:34.241125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63423 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:34.444250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63424 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:34.663000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63425 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:34.866125 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63426 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:35.069250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63427 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:35.272375 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63428 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:35.475500 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63429 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:35.694250 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63430 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:35.881750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63431 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:36.084875 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63432 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:36.303625 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63433 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:36.506750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63434 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:36.709875 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63435 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:36.913000 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63436 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:37.131750 [DEBUG] switch_rtp.c:916 [ zrtp utils]: Send <HELLO> ssrc=1447881465 seq=63437 size=140. Stream 45:CLEAR:START 2012-12-06 21:20:37.334875 [DEBUG] switch_rtp.c:916 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=45 2012-12-06 21:20:37.334875 [DEBUG] switch_rtp.c:916 [ zrtp]: Stream ID=45 CLEAR switching <START> ---> <NOZRTP>. recv 622 bytes from udp/[10.0.0.1]:5060 at 20:20:42.600500: ------------------------------------------------------------------------ BYE sip:9178@10.0.0.2:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.1;rport;branch=z9hG4bKtgS2aj3y7Z48Q Max-Forwards: 70 From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076551 BYE Contact: <sip:FreeSWITCH@10.0.0.1:5060;transport=udp;gw=fs2> User-Agent: FreeSWITCH-mod_sofia/1.3.8b Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:42.584875 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:43.491125 [ERR] mod_spandsp_fax.c:641 INVALID WRITE: 22:1 2012-12-06 21:20:43.491125 [ERR] mod_spandsp_fax.c:653 TERMINATING T30 STATE 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:487 ============================================================================== 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:500 Fax processing not successful - result (49) The call dropped prematurely. 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:505 Remote station id: 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:506 Local station id: SpanDSP Fax Ident 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:507 Pages transferred: 0 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:509 Total fax pages: 0 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:510 Image resolution: 0x0 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:511 Transfer Rate: 14400 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:513 ECM status off 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:514 remote country: 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:515 remote vendor: 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:516 remote model: 2012-12-06 21:20:43.491125 [DEBUG] mod_spandsp_fax.c:518 ============================================================================== 2012-12-06 21:20:43.491125 [DEBUG] switch_channel.c:2994 (sofia/internal/FreeSWITCH@10.0.0.2) Callstate Change ACTIVE -> HANGUP 2012-12-06 21:20:43.491125 [NOTICE] sofia.c:711 Hangup sofia/internal/FreeSWITCH@10.0.0.2 [CS_EXECUTE] [NORMAL_CLEARING] 2012-12-06 21:20:43.491125 [DEBUG] switch_channel.c:3017 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [KILL] 2012-12-06 21:20:43.491125 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] send 466 bytes to udp/[10.0.0.1]:5060 at 20:20:43.491125: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.1;rport=5060;branch=z9hG4bKtgS2aj3y7Z48Q From: "" <sip:FreeSWITCH@10.0.0.2>;tag=rN8rZtevXta7S To: <sip:9178@10.0.0.2>;tag=em42Xtm0UDeDD Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975 CSeq: 37076551 BYE User-Agent: FreeSWITCH-mod_sofia/1.3.8b Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2012-12-06 21:20:43.506750 [DEBUG] switch_core_codec.c:244 sofia/internal/FreeSWITCH@10.0.0.2 Restore previous codec PCMA:8. 2012-12-06 21:20:43.506750 [DEBUG] switch_core_session.c:2687 sofia/internal/FreeSWITCH@10.0.0.2 skip receive message [APPLICATION_EXEC_COMPLETE] (cha nnel is hungup already) 2012-12-06 21:20:43.506750 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/FreeSWITCH@10.0.0.2) State EXECUTE going to sleep 2012-12-06 21:20:43.506750 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_HANGUP 2012-12-06 21:20:43.506750 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/FreeSWITCH@10.0.0.2) State HANGUP 2012-12-06 21:20:43.506750 [DEBUG] mod_sofia.c:503 Channel sofia/internal/FreeSWITCH@10.0.0.2 hanging up, cause: NORMAL_CLEARING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:48 sofia/internal/FreeSWITCH@10.0.0.2 Standard HANGUP, cause: NORMAL_CLEARING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/FreeSWITCH@10.0.0.2) State HANGUP going to sleep 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_HANGUP -> CS_REPORTING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_REPORTING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/FreeSWITCH@10.0.0.2) State REPORTING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:92 sofia/internal/FreeSWITCH@10.0.0.2 Standard REPORTING, cause: NORMAL_CLEARING 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/FreeSWITCH@10.0.0.2) State REPORTING going to sleep 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/FreeSWITCH@10.0.0.2) State Change CS_REPORTING -> CS_DESTROY 2012-12-06 21:20:43.647375 [DEBUG] switch_core_session.c:1283 Send signal sofia/internal/FreeSWITCH@10.0.0.2 [BREAK] 2012-12-06 21:20:43.647375 [DEBUG] switch_core_session.c:1488 Session 19 (sofia/internal/FreeSWITCH@10.0.0.2) Locked, Waiting on external entities 2012-12-06 21:20:43.647375 [NOTICE] switch_core_session.c:1506 Session 19 (sofia/internal/FreeSWITCH@10.0.0.2) Ended 2012-12-06 21:20:43.647375 [NOTICE] switch_core_session.c:1510 Close Channel sofia/internal/FreeSWITCH@10.0.0.2 [CS_DESTROY] 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:556 (sofia/internal/FreeSWITCH@10.0.0.2) Callstate Change HANGUP -> DOWN 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:559 (sofia/internal/FreeSWITCH@10.0.0.2) Running State Change CS_DESTROY 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/FreeSWITCH@10.0.0.2) State DESTROY 2012-12-06 21:20:43.647375 [DEBUG] mod_sofia.c:396 sofia/internal/FreeSWITCH@10.0.0.2 SOFIA DESTROY 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:99 sofia/internal/FreeSWITCH@10.0.0.2 Standard DESTROY 2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/FreeSWITCH@10.0.0.2) State DESTROY going to sleep freeswitch@fs2>