[Freeswitch-users] Problems with T.38
Shishko
shishko69 at gmail.com
Thu Dec 6 23:23:03 MSK 2012
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 at fs2> recv 1068 bytes from udp/[10.0.0.1]:5060 at 20:20:29.334875:
------------------------------------------------------------------------
INVITE sip:9178 at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 10.0.0.2>
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076550 INVITE
Contact: <sip:FreeSWITCH at 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 at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.350500 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.350500 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2) State INIT
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:86
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA INIT
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:126
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:454
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2) Running State Change CS_ROUTING
2012-12-06 21:20:29.522375 [DEBUG] switch_channel.c:2003
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2) State ROUTING
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:149
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA ROUTING
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:117
sofia/internal/FreeSWITCH at 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 at 10.0.0.2 parsing [public->unloop]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[public->outside_call] continue=true
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Absolute Condition [outside_call]
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action set(outside_call=true)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[public->call_debug] continue=true
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[public->public_extensions] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[public_extensions] destination_number(9178) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[public->fax_extensions] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS)
[fax_extensions] destination_number(9178) =~ /^9178/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2) State EXECUTE
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:242
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA EXECUTE
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:209
sofia/internal/FreeSWITCH at 10.0.0.2 Standard EXECUTE
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2 set(outside_call=true)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [outside_call]=[true]
EXECUTE sofia/internal/FreeSWITCH at 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 at 10.0.0.2 transfer(9178 XML default)
2012-12-06 21:20:29.522375 [DEBUG] switch_ivr.c:1773
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_session.c:830 Send
signal sofia/internal/FreeSWITCH at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [NOTICE] switch_ivr.c:1779 Transfer
sofia/internal/FreeSWITCH at 10.0.0.2 to XML[9178 at default]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:477
(sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2) State ROUTING
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:149
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA ROUTING
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:117
sofia/internal/FreeSWITCH at 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 at 10.0.0.2 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->tod_example] continue=true
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Date/TimeMatch (FAIL)
[tod_example] break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[global-intercept] destination_number(9178) =~ /^886$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[group-intercept] destination_number(9178) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->intercept-ext] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[intercept-ext] destination_number(9178) =~ /^\*\*(\d+)$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->redial]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [redial]
destination_number(9178) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->global]
continue=true
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/FreeSWITCH at 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 at 10.0.0.2 Regex (PASS) [global]
${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED
NEGOTIATION)/ break=on-f
alse
Dialplan: sofia/internal/FreeSWITCH at 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 at 10.0.0.2 Absolute Condition [global]
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->snom-demo-2] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[snom-demo-2] destination_number(9178) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->snom-demo-1] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[snom-demo-1] destination_number(9178) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [eavesdrop]
destination_number(9178) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [eavesdrop]
destination_number(9178) =~ /^779$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->call_return] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[call_return] destination_number(9178) =~ /^\*69$|^869$|^lcr$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->del-group] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [del-group]
destination_number(9178) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->add-group] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [add-group]
destination_number(9178) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[call-group-simo] destination_number(9178) =~ /^82(\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[call-group-order] destination_number(9178) =~ /^83(\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[extension-intercom] destination_number(9178) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[Local_Extension] destination_number(9178) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[Local_Extension_Skinny] destination_number(9178) =~ /^(11[01][0-9])$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->group_dial_sales] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[group_dial_sales] destination_number(9178) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->group_dial_support] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[group_dial_support] destination_number(9178) =~ /^2001$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->group_dial_billing] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[group_dial_billing] destination_number(9178) =~ /^2002$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->operator] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [operator]
destination_number(9178) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->vmain]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [vmain]
destination_number(9178) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->sip_uri] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [sip_uri]
destination_number(9178) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->nb_conferences] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[nb_conferences] destination_number(9178) =~ /^(30\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->wb_conferences] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[wb_conferences] destination_number(9178) =~ /^(31\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->uwb_conferences] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[uwb_conferences] destination_number(9178) =~ /^(32\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->cdquality_conferences] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[cdquality_conferences] destination_number(9178) =~ /^(33\d{2})$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/FreeSWITCH at 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 at 10.0.0.2 parsing
[default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[mad_boss_intercom] destination_number(9178) =~ /^0911$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[mad_boss_intercom] destination_number(9178) =~ /^0912$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->mad_boss] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [mad_boss]
destination_number(9178) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->ivr_demo] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [ivr_demo]
destination_number(9178) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->dynamic_conference] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[dynamic_conference] destination_number(9178) =~ /^5001$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL)
[rtp_multicast_page] destination_number(9178) =~ /^pagegroup$|^7243$/
break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->park]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [park]
destination_number(9178) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->unpark]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [unpark]
destination_number(9178) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->valet_park] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [valet_park]
destination_number(9178) =~ /^(6000)$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->valet_park] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [valet_park]
destination_number(9178) =~ /^(60\d[1-9])$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->park]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [park]
destination_number(9178) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->unpark]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [unpark]
destination_number(9178) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->park]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [park]
destination_number(9178) =~ /callpark/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->unpark]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [unpark]
destination_number(9178) =~ /pickup/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing [default->wait]
continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (FAIL) [wait]
destination_number(9178) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 parsing
[default->fax_receive] continue=false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Regex (PASS)
[fax_receive] destination_number(9178) =~ /^9178/ break=on-false
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action set(fax_enable_t38=true)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
set(fax_enable_t38_request=true)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
set(absolute_codec_string=PCMA)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action set(proxy_media=true)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action set(bypass_media=false)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action set(use-ecm=true)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action answer()
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action
playback(silence_stream://2000)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action rxfax(fax/rxfax.tif)
Dialplan: sofia/internal/FreeSWITCH at 10.0.0.2 Action hangup()
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:167
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:470
(sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2) State EXECUTE
2012-12-06 21:20:29.522375 [DEBUG] mod_sofia.c:242
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA EXECUTE
2012-12-06 21:20:29.522375 [DEBUG] switch_core_state_machine.c:209
sofia/internal/FreeSWITCH at 10.0.0.2 Standard EXECUTE
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2
hash(insert/0.0.0.0-spymap/1234/712d8bfe-f045-4665-8b9c-f610a4f1a438)
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2
hash(insert/0.0.0.0-last_dial/1234/9178)
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2
hash(insert/0.0.0.0-last_dial/global/712d8bfe-f045-4665-8b9c-f610a4f1a438)
EXECUTE sofia/internal/FreeSWITCH at 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 at 10.0.0.2 set(fax_enable_t38=true)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [fax_enable_t38]=[true]
EXECUTE sofia/internal/FreeSWITCH at 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 at 10.0.0.2 SET [fax_enable_t38_request]=[true]
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2 set(absolute_codec_string=PCMA)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [absolute_codec_string]=[PCMA]
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2 set(proxy_media=true)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [proxy_media]=[true]
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2 set(bypass_media=false)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [bypass_media]=[false]
EXECUTE sofia/internal/FreeSWITCH at 10.0.0.2 set(use-ecm=true)
2012-12-06 21:20:29.522375 [DEBUG] mod_dptools.c:1344
sofia/internal/FreeSWITCH at 10.0.0.2 SET [use-ecm]=[true]
EXECUTE sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 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 at 10.0.0.2!
2012-12-06 21:20:29.663000 [DEBUG] switch_channel.c:3136
(sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.663000 [DEBUG] switch_channel.c:3395
(sofia/internal/FreeSWITCH at 10.0.0.2) Callstate Change EARLY -> ACTIVE
2012-12-06 21:20:29.663000 [NOTICE] mod_dptools.c:1176 Channel
[sofia/internal/FreeSWITCH at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 10.0.0.2>;tag=em42Xtm0UDeDD
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076550 INVITE
Contact: <sip:9178 at 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 at 10.0.0.2
X-FS-Support: update_display,send_info
Remote-Party-ID: "9178"
<sip:9178 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.663000 [DEBUG] sofia.c:5603 Channel
sofia/internal/FreeSWITCH at 10.0.0.2 entering state [completed][200]
EXECUTE sofia/internal/FreeSWITCH at 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 at 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 at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 10.0.0.2>;tag=em42Xtm0UDeDD
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076550 ACK
Contact: <sip:FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.850500 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 10.0.0.2 [BREAK]
2012-12-06 21:20:29.850500 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 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 at 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 at 10.0.0.2>;tag=em42Xtm0UDeDD
To: "" <sip:FreeSWITCH at 10.0.0.2>;tag=rN8rZtevXta7S
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076552 INVITE
Contact: <sip:9178 at 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 at 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 at 10.0.0.2>;tag=em42Xtm0UDeDD
To: "" <sip:FreeSWITCH at 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 at 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 at 10.0.0.2>;tag=em42Xtm0UDeDD
To: "" <sip:FreeSWITCH at 10.0.0.2>;tag=rN8rZtevXta7S
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076552 INVITE
Contact: <sip:FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:33.116125 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 10.0.0.2 [BREAK]
2012-12-06 21:20:33.116125 [INFO] sofia.c:931
sofia/internal/FreeSWITCH at 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 at 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 at 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 at 10.0.0.2>;tag=em42Xtm0UDeDD
To: "" <sip:FreeSWITCH at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:33.272375 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 10.0.0.2 [BREAK]
2012-12-06 21:20:33.288000 [DEBUG] sofia.c:5603 Channel
sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:33.491125 [DEBUG] switch_core_session.c:975 Send
signal sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 10.0.0.2>;tag=em42Xtm0UDeDD
Call-ID: 3824cd3f-ba85-1230-1b9e-9b4137433975
CSeq: 37076551 BYE
Contact: <sip:FreeSWITCH at 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 at 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 at 10.0.0.2) Callstate Change ACTIVE -> HANGUP
2012-12-06 21:20:43.491125 [NOTICE] sofia.c:711 Hangup
sofia/internal/FreeSWITCH at 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 at 10.0.0.2 [KILL]
2012-12-06 21:20:43.491125 [DEBUG] switch_core_session.c:1283 Send
signal sofia/internal/FreeSWITCH at 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 at 10.0.0.2>;tag=rN8rZtevXta7S
To: <sip:9178 at 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 at 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 at 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 at 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 at 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 at 10.0.0.2) State HANGUP
2012-12-06 21:20:43.506750 [DEBUG] mod_sofia.c:503 Channel
sofia/internal/FreeSWITCH at 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 at 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 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:415
(sofia/internal/FreeSWITCH at 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 at 10.0.0.2) State REPORTING
2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:92
sofia/internal/FreeSWITCH at 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 at 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 at 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 at 10.0.0.2 [BREAK]
2012-12-06 21:20:43.647375 [DEBUG] switch_core_session.c:1488 Session
19 (sofia/internal/FreeSWITCH at 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 at 10.0.0.2) Ended
2012-12-06 21:20:43.647375 [NOTICE] switch_core_session.c:1510 Close
Channel sofia/internal/FreeSWITCH at 10.0.0.2 [CS_DESTROY]
2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:556
(sofia/internal/FreeSWITCH at 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 at 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 at 10.0.0.2) State DESTROY
2012-12-06 21:20:43.647375 [DEBUG] mod_sofia.c:396
sofia/internal/FreeSWITCH at 10.0.0.2 SOFIA DESTROY
2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:99
sofia/internal/FreeSWITCH at 10.0.0.2 Standard DESTROY
2012-12-06 21:20:43.647375 [DEBUG] switch_core_state_machine.c:569
(sofia/internal/FreeSWITCH at 10.0.0.2) State DESTROY going to sleep
freeswitch at fs2>
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list