[Freeswitch-users] Ringtone on multiple destinations
Christian Benke
benkokakao at gmail.com
Fri Feb 17 18:02:30 MSK 2012
On 17 February 2012 01:57, Anthony Minessale
<anthony.minessale at gmail.com> wrote:
> try changing:
>
> <ignore_early_media=true>
>
> to
>
> <ignore_early_media=ring_ready>
Should this actually react to 180 RINGING too? No luck though(see logs) :-/
Regards
Christian
-------------- next part --------------
2012-02-17 15:56:22.698914 [INFO] ftmod_sangoma_isdn_stack_rcv.c:75 [s1c1][1:1] Received SETUP (suId:1 suInstId:0 spInstId:2)
2012-02-17 15:56:22.698914 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:57 [s1c1][1:1] Processing SETUP (suId:1 suInstId:0 spInstId:2)
2012-02-17 15:56:22.698914 [INFO] ftmod_sangoma_isdn_stack_hndl.c:140 [s1c1][1:1] Incoming call: Called No:[809] Calling No:[5XXXXXXX3]
2012-02-17 15:56:22.698914 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:194 [s1c1][1:1] Changed state from DOWN to COLLECT
2012-02-17 15:56:22.698914 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for COLLECT
2012-02-17 15:56:22.698914 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to COLLECT
2012-02-17 15:56:22.698914 [INFO] ftmod_sangoma_isdn_stack_out.c:106 [s1c1][1:1] Sending SETUP ACK (suId:1 suInstId:2 spInstId:2 dchan:1 ces:0)
2012-02-17 15:56:22.698914 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from DOWN to COLLECT in 0ms
2012-02-17 15:56:26.198932 [INFO] ftmod_sangoma_isdn_stack_rcv.c:519 [s1c1][1:1] Received STATUS CONFIRM (suId:1 suInstId:2 spInstId:2)
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:897 [s1c1][1:1] Processing STATUS CONFIRM (suId:1 suInstId:2 spInstId:2)
2012-02-17 15:56:26.198932 [WARNING] ftmod_sangoma_isdn_stack_hndl.c:918 [s1c1][1:1] Recovery on timer expire (call_state:25 channel-state:COLLECT cause:102) (suId:1 suInstId:2 spInstId:2)
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:1069 [s1c1][1:1] T302 Timer expired, proceeding with call
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:1070 [s1c1][1:1] Changed state from COLLECT to RING
2012-02-17 15:56:26.198932 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for RING
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to RING
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn.c:677 [s1c1][1:1] Sending incoming call from 5XXXXXXX3 to 809 to FTDM core
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from COLLECT to RING in 0ms
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:2416 got clear channel sig [START]
2012-02-17 15:56:26.198932 [DEBUG] ftdm_io.c:3133 [s1c1][1:1] Enabled software DTMF detector
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:407 Set codec PCMA 20ms
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:1740 Connect inbound channel FreeTDM/1:1/809
2012-02-17 15:56:26.198932 [NOTICE] switch_channel.c:930 New Channel FreeTDM/1:1/809 [90bb4d30-5977-11e1-8ab9-95378f428adb]
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:1846 (FreeTDM/1:1/809) State Change CS_NEW -> CS_INIT
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_INIT
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/809) State INIT
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:435 (FreeTDM/1:1/809) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/809) State INIT going to sleep
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_ROUTING
2012-02-17 15:56:26.198932 [DEBUG] switch_channel.c:1890 (FreeTDM/1:1/809) Callstate Change DOWN -> RINGING
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/809 CHANNEL ROUTING
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state RING
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Changed state from RING to PROCEED
2012-02-17 15:56:26.198932 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROCEED
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to PROCEED
2012-02-17 15:56:26.198932 [INFO] ftmod_sangoma_isdn_stack_out.c:174 [s1c1][1:1] Sending PROCEED (suId:1 suInstId:2 spInstId:2 dchan:1 ces:0)
2012-02-17 15:56:26.198932 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from RING to PROCEED in 0ms
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/809 Standard ROUTING
2012-02-17 15:56:26.198932 [INFO] mod_dialplan_xml.c:481 Processing <5XXXXXXX3>->809 in context public
Dialplan: FreeTDM/1:1/809 parsing [public->unloop] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [public->outside_call] continue=true
Dialplan: FreeTDM/1:1/809 Absolute Condition [outside_call]
Dialplan: FreeTDM/1:1/809 Action set(outside_call=true)
Dialplan: FreeTDM/1:1/809 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: FreeTDM/1:1/809 parsing [public->call_debug] continue=true
Dialplan: FreeTDM/1:1/809 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never
Dialplan: FreeTDM/1:1/809 Action info()
Dialplan: FreeTDM/1:1/809 parsing [public->reception_extension0] continue=true
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [reception_extension0] destination_number(809) =~ /^$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [public->public_did] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [public_did] destination_number(809) =~ /^(\d{2,5})$/ break=on-false
Dialplan: FreeTDM/1:1/809 Action set(accountcode=inbound_call)
Dialplan: FreeTDM/1:1/809 Action set(originator_number_cdr=00${caller_id_number)
Dialplan: FreeTDM/1:1/809 Action set(domain_name=10.3.0.4)
Dialplan: FreeTDM/1:1/809 Action transfer(809 XML default)
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/809) State Change CS_ROUTING -> CS_EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING going to sleep
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/809 CHANNEL EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/809 Standard EXECUTE
EXECUTE FreeTDM/1:1/809 set(outside_call=true)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [outside_call]=[true]
EXECUTE FreeTDM/1:1/809 set(RFC2822_DATE=Fri, 17 Feb 2012 15:56:26 +0100)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [RFC2822_DATE]=[Fri, 17 Feb 2012 15:56:26 +0100]
EXECUTE FreeTDM/1:1/809 info()
2012-02-17 15:56:26.198932 [INFO] mod_dptools.c:1439 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [FreeTDM/1:1/809]
Unique-ID: [90bb4d30-5977-11e1-8ab9-95378f428adb]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Call-UUID: [90bb4d30-5977-11e1-8ab9-95378f428adb]
Answer-State: [ringing]
Channel-Read-Codec-Name: [PCMA]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [64000]
Channel-Write-Codec-Name: [PCMA]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [64000]
Caller-Direction: [inbound]
Caller-Username: [FreeTDM]
Caller-Dialplan: [XML]
Caller-Caller-ID-Number: [5XXXXXXX3]
Caller-ANI: [5XXXXXXX3]
Caller-Destination-Number: [809]
Caller-Unique-ID: [90bb4d30-5977-11e1-8ab9-95378f428adb]
Caller-Source: [mod_freetdm]
Caller-Context: [public]
Caller-Channel-Name: [FreeTDM/1:1/809]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1329490586198932]
Caller-Channel-Created-Time: [1329490586198932]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [90bb4d30-5977-11e1-8ab9-95378f428adb]
variable_session_id: [4]
variable_read_codec: [PCMA]
variable_read_rate: [8000]
variable_write_codec: [PCMA]
variable_write_rate: [8000]
variable_channel_name: [FreeTDM/1:1/809]
variable_freetdm_span_name: [wp1]
variable_freetdm_span_number: [1]
variable_freetdm_chan_number: [1]
variable_freetdm_bearer_capability: [0]
variable_freetdm_bearer_layer1: [3]
variable_freetdm_calling_party_category: [unknown]
variable_screening_ind: [user-provided-not-screened]
variable_presentation_ind: [presentation-allowed]
variable_DP_MATCH: [ARRAY::809|:809]
variable_call_uuid: [90bb4d30-5977-11e1-8ab9-95378f428adb]
variable_outside_call: [true]
variable_RFC2822_DATE: [Fri, 17 Feb 2012 15:56:26 +0100]
variable_current_application: [info]
EXECUTE FreeTDM/1:1/809 set(accountcode=inbound_call)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [accountcode]=[inbound_call]
EXECUTE FreeTDM/1:1/809 set(originator_number_cdr=005XXXXXXX3)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [originator_number_cdr]=[005XXXXXXX3]
EXECUTE FreeTDM/1:1/809 set(domain_name=10.3.0.4)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [domain_name]=[10.3.0.4]
EXECUTE FreeTDM/1:1/809 transfer(809 XML default)
2012-02-17 15:56:26.198932 [DEBUG] switch_ivr.c:1711 (FreeTDM/1:1/809) State Change CS_EXECUTE -> CS_ROUTING
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [NOTICE] switch_ivr.c:1717 Transfer FreeTDM/1:1/809 to XML[809 at default]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE going to sleep
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_ROUTING
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/809 CHANNEL ROUTING
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state PROCEED
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/809 Standard ROUTING
2012-02-17 15:56:26.198932 [INFO] mod_dialplan_xml.c:481 Processing <5XXXXXXX3>->809 in context default
Dialplan: FreeTDM/1:1/809 parsing [default->unloop] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_enable_chefsec] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_enable_chefsec] destination_number(809) =~ /^\*95(\d{0,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->group-intercept] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [group-intercept] destination_number(809) =~ /^\*82$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->intercept-ext] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [intercept-ext] destination_number(809) =~ /^\*81(\d+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_single_intercom_with_two_way_audio] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_single_intercom_with_two_way_audio] destination_number(809) =~ /^\*01(\d{2,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_group_intercom] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_group_intercom] destination_number(809) =~ /^\*02(\d{0,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->Outbound to PSTN 11 Digits] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [Outbound to PSTN 11 Digits] destination_number(809) =~ /^(1[2-9][0-9]{2}[2-9]{7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->del-group] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [del-group] destination_number(809) =~ /^\*\*50(\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->add-group] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [add-group] destination_number(809) =~ /^\*\*51(\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call-group-simo] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call-group-simo] destination_number(809) =~ /^\*52(\d{2,4})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call-group-order] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call-group-order] destination_number(809) =~ /^\*53(\d{2,4})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nb_conferences] destination_number(809) =~ /^\*(30\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->wb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [wb_conferences] destination_number(809) =~ /^\*(31\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->uwb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [uwb_conferences] destination_number(809) =~ /^\*(32\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->cdquality_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [cdquality_conferences] destination_number(809) =~ /^\*(33\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->global_directory] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [global_directory] destination_number(809) =~ /^\*77(\d{1,3})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_now] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_now] destination_number(809) =~ /^\*21(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_timeout] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_timeout] destination_number(809) =~ /^\*22(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_busy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_busy] destination_number(809) =~ /^\*23(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call_privacy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call_privacy] destination_number(809) =~ /^\*67(\d+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call_privacy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call_privacy] destination_number(809) =~ /^\*60$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->send_to_voicemail] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [send_to_voicemail] destination_number(809) =~ /^\*99(\d{2,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain] destination_number(809) =~ /^vmain$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain1] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain1] destination_number(809) =~ /^vmain1$|^\*97$|^97$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain2] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain2] destination_number(809) =~ /^vmain2$|^\*98$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_now] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_now] destination_number(809) =~ /^\*35$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->local] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [local] ${toll_allow}() =~ /local/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->domestic] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [domestic] destination_number(809) =~ /^0(0[1-9]\d{3,}+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->international] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [international] ${toll_allow}() =~ /international/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->test] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [test] destination_number(809) =~ /809/ break=on-false
Dialplan: FreeTDM/1:1/809 Action set(ignore_early_media=ring_ready)
Dialplan: FreeTDM/1:1/809 Action set(ringback=${rs-ring})
Dialplan: FreeTDM/1:1/809 Action bridge([leg_timeout=0][origination_caller_id_number=30]user/24@${domain_name}:_:[leg_timeout=0][origination_caller_id_number=30]user/10@${domain_name})
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/809) State Change CS_ROUTING -> CS_EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING going to sleep
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/809 CHANNEL EXECUTE
2012-02-17 15:56:26.198932 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/809 Standard EXECUTE
EXECUTE FreeTDM/1:1/809 set(ignore_early_media=ring_ready)
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [ignore_early_media]=[ring_ready]
EXECUTE FreeTDM/1:1/809 set(ringback=%(1000, 4000, 425.0, 0.0))
2012-02-17 15:56:26.198932 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [ringback]=[%(1000, 4000, 425.0, 0.0)]
EXECUTE FreeTDM/1:1/809 bridge([leg_timeout=0][origination_caller_id_number=30]user/24 at 10.3.0.4:_:[leg_timeout=0][origination_caller_id_number=30]user/10 at 10.3.0.4)
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:1413 Parsing ultra-global variables
2012-02-17 15:56:26.219879 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Indicating PROGRESS_MEDIA in state PROCEED
2012-02-17 15:56:26.219879 [DEBUG] mod_freetdm.c:970 [s1c1][1:1] Changed state from PROCEED to PROGRESS_MEDIA
2012-02-17 15:56:26.219879 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROGRESS_MEDIA
2012-02-17 15:56:26.219879 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to PROGRESS_MEDIA
2012-02-17 15:56:26.219879 [INFO] ftmod_sangoma_isdn_stack_out.c:206 [s1c1][1:1] Sending PROGRESS (suId:1 suInstId:2 spInstId:2 dchan:1 ces:0)
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-02-17 15:56:26.219879 [DEBUG] switch_event.c:1521 Parsing variable [leg_timeout]=[0]
2012-02-17 15:56:26.219879 [DEBUG] switch_event.c:1521 Parsing variable [origination_caller_id_number]=[30]
2012-02-17 15:56:26.219879 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from PROCEED to PROGRESS_MEDIA in 0ms
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-02-17 15:56:26.219879 [DEBUG] switch_event.c:1521 Parsing variable [leg_timeout]=[0]
2012-02-17 15:56:26.219879 [DEBUG] switch_event.c:1521 Parsing variable [origination_caller_id_number]=[30]
2012-02-17 15:56:26.219879 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:56:26.219879 [NOTICE] switch_ivr_originate.c:1478 Pre-Answer FreeTDM/1:1/809!
2012-02-17 15:56:26.219879 [DEBUG] switch_channel.c:2936 (FreeTDM/1:1/809) Callstate Change RINGING -> EARLY
2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:56:26.219879 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[24 at 10.3.0.4]
2012-02-17 15:56:26.219879 [NOTICE] switch_channel.c:930 New Channel sofia/internal/sip:24 at 10.3.0.39 [90bffe20-5977-11e1-8ac3-95378f428adb]
2012-02-17 15:56:26.219879 [DEBUG] mod_sofia.c:4670 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_NEW -> CS_INIT
2012-02-17 15:56:26.219879 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_INIT
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:24 at 10.3.0.39) State INIT
2012-02-17 15:56:26.219879 [DEBUG] mod_sofia.c:85 sofia/internal/sip:24 at 10.3.0.39 SOFIA INIT
2012-02-17 15:56:26.219879 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:56:26.219879 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:24 at 10.3.0.39) State INIT going to sleep
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_ROUTING
2012-02-17 15:56:26.219879 [DEBUG] switch_channel.c:1890 (sofia/internal/sip:24 at 10.3.0.39) Callstate Change DOWN -> RINGING
send 1238 bytes to udp/[10.3.0.39]:5060 at 14:56:26.233973:
------------------------------------------------------------------------
INVITE sip:24 at 10.3.0.39 SIP/2.0
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKNB7KZZBH3j3Ne
Max-Forwards: 70
From: "" <sip:30 at 10.3.0.4>;tag=NK7a7yjNUcrFK
To: <sip:24 at 10.3.0.39>
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:24 at 10.3.0.39) State ROUTING
Call-ID: 681ea940-d41a-122f-28b4-00900b1be530
CSeq: 24409229 INVITE
Contact: <sip:mod_sofia at 10.3.0.4:5060>2012-02-17 15:56:26.219879 [DEBUG] mod_sofia.c:148 sofia/internal/sip:24 at 10.3.0.39 SOFIA ROUTING
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-a9c10f8 2012-01-30 18-32-05 -0500
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE2012-02-17 15:56:26.219879 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_ROUTING -> CS_CONSUME_MEDIA
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer2012-02-17 15:56:26.219879 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
Content-Type: application/sdp
Content-Disposition: session
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:24 at 10.3.0.39) State ROUTING going to sleep
Content-Length: 369
X-FS-Support: update_display,send_info
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_CONSUME_MEDIA
Remote-Party-ID: <sip:30 at 10.3.0.4>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1329474140 1329474141 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16446 RTP/AVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
m=video 16440 RTP/AVP 98 99 100 34 31
2012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:24 at 10.3.0.39) State CONSUME_MEDIA
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/900002012-02-17 15:56:26.219879 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:24 at 10.3.0.39) State CONSUME_MEDIA going to sleep
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
------------------------------------------------------------------------
2012-02-17 15:56:26.219879 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:56:26.219879 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:24 at 10.3.0.39 entering state [calling][0]
2012-02-17 15:56:26.238951 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:56:26.238951 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[10 at 10.3.0.4]
2012-02-17 15:56:26.238951 [NOTICE] switch_channel.c:930 New Channel sofia/internal/sip:10 at 10.3.0.24 [90c18d58-5977-11e1-8ac7-95378f428adb]
2012-02-17 15:56:26.238951 [DEBUG] mod_sofia.c:4670 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_NEW -> CS_INIT
2012-02-17 15:56:26.238951 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_INIT
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:10 at 10.3.0.24) State INIT
2012-02-17 15:56:26.238951 [DEBUG] mod_sofia.c:85 sofia/internal/sip:10 at 10.3.0.24 SOFIA INIT
2012-02-17 15:56:26.238951 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:56:26.238951 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:10 at 10.3.0.24) State INIT going to sleep
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_ROUTING
2012-02-17 15:56:26.238951 [DEBUG] switch_channel.c:1890 (sofia/internal/sip:10 at 10.3.0.24) Callstate Change DOWN -> RINGING
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:10 at 10.3.0.24) State ROUTING
2012-02-17 15:56:26.238951 [DEBUG] mod_sofia.c:148 sofia/internal/sip:10 at 10.3.0.24 SOFIA ROUTING
2012-02-17 15:56:26.238951 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-02-17 15:56:26.238951 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
send 1238 bytes to udp/[10.3.0.24]:5060 at 14:56:26.244152:
------------------------------------------------------------------------
INVITE sip:10 at 10.3.0.24 SIP/2.0
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKpm0c1tvm0US8S2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:10 at 10.3.0.24) State ROUTING going to sleep
Max-Forwards: 70
From: "" <sip:30 at 10.3.0.4>;tag=pv038S3rrNe2e2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_CONSUME_MEDIA
To: <sip:10 at 10.3.0.24>
Call-ID: 68203759-d41a-122f-28b4-00900b1be530
CSeq: 24409229 INVITE
Contact: <sip:mod_sofia at 10.3.0.4:5060>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-a9c10f8 2012-01-30 18-32-05 -0500
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:10 at 10.3.0.24) State CONSUME_MEDIA
Content-Length: 369
X-FS-Support: update_display,send_info
2012-02-17 15:56:26.238951 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:10 at 10.3.0.24) State CONSUME_MEDIA going to sleep
Remote-Party-ID: <sip:30 at 10.3.0.4>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1329474144 1329474145 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16442 RTP/AVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
m=video 16388 RTP/AVP 98 99 100 34 31
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/90000
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
------------------------------------------------------------------------
2012-02-17 15:56:26.238951 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:56:26.238951 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:10 at 10.3.0.24 entering state [calling][0]
2012-02-17 15:56:26.238951 [DEBUG] ftmod_wanpipe.c:945 [s1c1][1:1] Rx Queue length exceeded 80% hreshold (9/10)
2012-02-17 15:56:26.238951 [DEBUG] ftmod_wanpipe.c:965 [s1c1][1:1] First packet read stats: Rx queue len: 9, Rx queue size: 10
2012-02-17 15:56:26.238951 [DEBUG] ftmod_wanpipe.c:949 [s1c1][1:1] Rx Queue length reduced 80% hreshold (8/10)
recv 396 bytes from udp/[10.3.0.39]:5060 at 14:56:26.247195:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKNB7KZZBH3j3Ne
From: <sip:30 at 10.3.0.4>;tag=NK7a7yjNUcrFK
To: "Braun" <sip:24 at 10.3.0.39>;tag=475B2CBE-C63B9C09
CSeq: 24409229 INVITE
Call-ID: 681ea940-d41a-122f-28b4-00900b1be530
Contact: <sip:24 at 10.3.0.39>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
recv 396 bytes from udp/[10.3.0.24]:5060 at 14:56:26.255971:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKpm0c1tvm0US8S
From: <sip:30 at 10.3.0.4>;tag=pv038S3rrNe2e
To: "Knaus" <sip:10 at 10.3.0.24>;tag=A392816D-37CE9790
CSeq: 24409229 INVITE
Call-ID: 68203759-d41a-122f-28b4-00900b1be530
Contact: <sip:10 at 10.3.0.24>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
recv 433 bytes from udp/[10.3.0.39]:5060 at 14:56:26.288363:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKNB7KZZBH3j3Ne
From: <sip:30 at 10.3.0.4>;tag=NK7a7yjNUcrFK
To: "Braun" <sip:24 at 10.3.0.39>;tag=475B2CBE-C63B9C09
CSeq: 24409229 INVITE
Call-ID: 681ea940-d41a-122f-28b4-00900b1be530
Contact: <sip:24 at 10.3.0.39>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Allow-Events: talk,hold,conference
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
2012-02-17 15:56:26.278917 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:56:26.278917 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
recv 433 bytes from udp/[10.3.0.24]:5060 at 14:56:26.294498:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKpm0c1tvm0US8S
From: <sip:30 at 10.3.0.4>;tag=pv038S3rrNe2e
To: "Knaus" <sip:10 at 10.3.0.24>;tag=A392816D-37CE9790
CSeq: 24409229 INVITE
Call-ID: 68203759-d41a-122f-28b4-00900b1be530
Contact: <sip:10 at 10.3.0.24>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Allow-Events: talk,hold,conference
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
2012-02-17 15:56:26.278917 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:56:26.278917 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:56:26.278917 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:24 at 10.3.0.39 entering state [proceeding][180]
2012-02-17 15:56:26.278917 [NOTICE] sofia.c:5600 Ring-Ready sofia/internal/sip:24 at 10.3.0.39!
2012-02-17 15:56:26.299213 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:10 at 10.3.0.24 entering state [proceeding][180]
2012-02-17 15:56:26.299213 [NOTICE] sofia.c:5600 Ring-Ready sofia/internal/sip:10 at 10.3.0.24!
-------------- next part --------------
2012-02-17 15:55:47.638933 [INFO] ftmod_sangoma_isdn_stack_rcv.c:75 [s1c1][1:1] Received SETUP (suId:1 suInstId:0 spInstId:1)
2012-02-17 15:55:47.638933 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:57 [s1c1][1:1] Processing SETUP (suId:1 suInstId:0 spInstId:1)
2012-02-17 15:55:47.638933 [INFO] ftmod_sangoma_isdn_stack_hndl.c:140 [s1c1][1:1] Incoming call: Called No:[809] Calling No:[5XXXXXXX3]
2012-02-17 15:55:47.638933 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:194 [s1c1][1:1] Changed state from DOWN to COLLECT
2012-02-17 15:55:47.638933 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for COLLECT
2012-02-17 15:55:47.638933 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to COLLECT
2012-02-17 15:55:47.638933 [INFO] ftmod_sangoma_isdn_stack_out.c:106 [s1c1][1:1] Sending SETUP ACK (suId:1 suInstId:1 spInstId:1 dchan:1 ces:0)
2012-02-17 15:55:47.638933 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from DOWN to COLLECT in 0ms
2012-02-17 15:55:51.198935 [INFO] ftmod_sangoma_isdn_stack_rcv.c:519 [s1c1][1:1] Received STATUS CONFIRM (suId:1 suInstId:1 spInstId:1)
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:897 [s1c1][1:1] Processing STATUS CONFIRM (suId:1 suInstId:1 spInstId:1)
2012-02-17 15:55:51.198935 [WARNING] ftmod_sangoma_isdn_stack_hndl.c:918 [s1c1][1:1] Recovery on timer expire (call_state:25 channel-state:COLLECT cause:102) (suId:1 suInstId:1 spInstId:1)
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:1069 [s1c1][1:1] T302 Timer expired, proceeding with call
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:1070 [s1c1][1:1] Changed state from COLLECT to RING
2012-02-17 15:55:51.198935 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for RING
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to RING
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn.c:677 [s1c1][1:1] Sending incoming call from 5XXXXXXX3 to 809 to FTDM core
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from COLLECT to RING in 0ms
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:2416 got clear channel sig [START]
2012-02-17 15:55:51.198935 [DEBUG] ftdm_io.c:3133 [s1c1][1:1] Enabled software DTMF detector
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:407 Set codec PCMA 20ms
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:1740 Connect inbound channel FreeTDM/1:1/809
2012-02-17 15:55:51.198935 [NOTICE] switch_channel.c:930 New Channel FreeTDM/1:1/809 [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:1846 (FreeTDM/1:1/809) State Change CS_NEW -> CS_INIT
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_INIT
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/809) State INIT
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:435 (FreeTDM/1:1/809) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:401 (FreeTDM/1:1/809) State INIT going to sleep
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_ROUTING
2012-02-17 15:55:51.198935 [DEBUG] switch_channel.c:1890 (FreeTDM/1:1/809) Callstate Change DOWN -> RINGING
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/809 CHANNEL ROUTING
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state RING
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Changed state from RING to PROCEED
2012-02-17 15:55:51.198935 [DEBUG] ftdm_state.c:511 [s1c1][1:1] Executing state processor for PROCEED
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn.c:656 [s1c1][1:1] processing state change to PROCEED
2012-02-17 15:55:51.198935 [INFO] ftmod_sangoma_isdn_stack_out.c:174 [s1c1][1:1] Sending PROCEED (suId:1 suInstId:1 spInstId:1 dchan:1 ces:0)
2012-02-17 15:55:51.198935 [DEBUG] ftmod_sangoma_isdn.c:914 [s1c1][1:1] Completed state change from RING to PROCEED in 0ms
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/809 Standard ROUTING
2012-02-17 15:55:51.198935 [INFO] mod_dialplan_xml.c:481 Processing <5XXXXXXX3>->809 in context public
Dialplan: FreeTDM/1:1/809 parsing [public->unloop] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [public->outside_call] continue=true
Dialplan: FreeTDM/1:1/809 Absolute Condition [outside_call]
Dialplan: FreeTDM/1:1/809 Action set(outside_call=true)
Dialplan: FreeTDM/1:1/809 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: FreeTDM/1:1/809 parsing [public->call_debug] continue=true
Dialplan: FreeTDM/1:1/809 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never
Dialplan: FreeTDM/1:1/809 Action info()
Dialplan: FreeTDM/1:1/809 parsing [public->reception_extension0] continue=true
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [reception_extension0] destination_number(809) =~ /^$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [public->public_did] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [public_did] destination_number(809) =~ /^(\d{2,5})$/ break=on-false
Dialplan: FreeTDM/1:1/809 Action set(accountcode=inbound_call)
Dialplan: FreeTDM/1:1/809 Action set(originator_number_cdr=00${caller_id_number)
Dialplan: FreeTDM/1:1/809 Action set(domain_name=10.3.0.4)
Dialplan: FreeTDM/1:1/809 Action transfer(809 XML default)
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/809) State Change CS_ROUTING -> CS_EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING going to sleep
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/809 CHANNEL EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/809 Standard EXECUTE
EXECUTE FreeTDM/1:1/809 set(outside_call=true)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [outside_call]=[true]
EXECUTE FreeTDM/1:1/809 set(RFC2822_DATE=Fri, 17 Feb 2012 15:55:51 +0100)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [RFC2822_DATE]=[Fri, 17 Feb 2012 15:55:51 +0100]
EXECUTE FreeTDM/1:1/809 info()
2012-02-17 15:55:51.198935 [INFO] mod_dptools.c:1439 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [FreeTDM/1:1/809]
Unique-ID: [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Call-UUID: [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
Answer-State: [ringing]
Channel-Read-Codec-Name: [PCMA]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [64000]
Channel-Write-Codec-Name: [PCMA]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [64000]
Caller-Direction: [inbound]
Caller-Username: [FreeTDM]
Caller-Dialplan: [XML]
Caller-Caller-ID-Number: [5XXXXXXX3]
Caller-ANI: [5XXXXXXX3]
Caller-Destination-Number: [809]
Caller-Unique-ID: [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
Caller-Source: [mod_freetdm]
Caller-Context: [public]
Caller-Channel-Name: [FreeTDM/1:1/809]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1329490551198935]
Caller-Channel-Created-Time: [1329490551198935]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
variable_session_id: [1]
variable_read_codec: [PCMA]
variable_read_rate: [8000]
variable_write_codec: [PCMA]
variable_write_rate: [8000]
variable_channel_name: [FreeTDM/1:1/809]
variable_freetdm_span_name: [wp1]
variable_freetdm_span_number: [1]
variable_freetdm_chan_number: [1]
variable_freetdm_bearer_capability: [0]
variable_freetdm_bearer_layer1: [3]
variable_freetdm_calling_party_category: [unknown]
variable_screening_ind: [user-provided-not-screened]
variable_presentation_ind: [presentation-allowed]
variable_DP_MATCH: [ARRAY::809|:809]
variable_call_uuid: [7bdeb0fa-5977-11e1-8aa9-95378f428adb]
variable_outside_call: [true]
variable_RFC2822_DATE: [Fri, 17 Feb 2012 15:55:51 +0100]
variable_current_application: [info]
EXECUTE FreeTDM/1:1/809 set(accountcode=inbound_call)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [accountcode]=[inbound_call]
EXECUTE FreeTDM/1:1/809 set(originator_number_cdr=005XXXXXXX3)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [originator_number_cdr]=[005XXXXXXX3]
EXECUTE FreeTDM/1:1/809 set(domain_name=10.3.0.4)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [domain_name]=[10.3.0.4]
EXECUTE FreeTDM/1:1/809 transfer(809 XML default)
2012-02-17 15:55:51.198935 [DEBUG] switch_ivr.c:1711 (FreeTDM/1:1/809) State Change CS_EXECUTE -> CS_ROUTING
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:729 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [NOTICE] switch_ivr.c:1717 Transfer FreeTDM/1:1/809 to XML[809 at default]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE going to sleep
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_ROUTING
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:458 FreeTDM/1:1/809 CHANNEL ROUTING
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:461 [s1c1][1:1] Indicating PROCEED in state PROCEED
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:104 FreeTDM/1:1/809 Standard ROUTING
2012-02-17 15:55:51.198935 [INFO] mod_dialplan_xml.c:481 Processing <5XXXXXXX3>->809 in context default
Dialplan: FreeTDM/1:1/809 parsing [default->unloop] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_enable_chefsec] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_enable_chefsec] destination_number(809) =~ /^\*95(\d{0,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->group-intercept] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [group-intercept] destination_number(809) =~ /^\*82$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->intercept-ext] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [intercept-ext] destination_number(809) =~ /^\*81(\d+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_single_intercom_with_two_way_audio] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_single_intercom_with_two_way_audio] destination_number(809) =~ /^\*01(\d{2,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nxo_group_intercom] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nxo_group_intercom] destination_number(809) =~ /^\*02(\d{0,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->Outbound to PSTN 11 Digits] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [Outbound to PSTN 11 Digits] destination_number(809) =~ /^(1[2-9][0-9]{2}[2-9]{7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->del-group] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [del-group] destination_number(809) =~ /^\*\*50(\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->add-group] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [add-group] destination_number(809) =~ /^\*\*51(\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call-group-simo] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call-group-simo] destination_number(809) =~ /^\*52(\d{2,4})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call-group-order] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call-group-order] destination_number(809) =~ /^\*53(\d{2,4})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->nb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [nb_conferences] destination_number(809) =~ /^\*(30\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->wb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [wb_conferences] destination_number(809) =~ /^\*(31\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->uwb_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [uwb_conferences] destination_number(809) =~ /^\*(32\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->cdquality_conferences] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [cdquality_conferences] destination_number(809) =~ /^\*(33\d{2})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->global_directory] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [global_directory] destination_number(809) =~ /^\*77(\d{1,3})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_now] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_now] destination_number(809) =~ /^\*21(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_timeout] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_timeout] destination_number(809) =~ /^\*22(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_busy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_busy] destination_number(809) =~ /^\*23(\d{0,20})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call_privacy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call_privacy] destination_number(809) =~ /^\*67(\d+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->call_privacy] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [call_privacy] destination_number(809) =~ /^\*60$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->send_to_voicemail] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [send_to_voicemail] destination_number(809) =~ /^\*99(\d{2,7})$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain] destination_number(809) =~ /^vmain$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain1] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain1] destination_number(809) =~ /^vmain1$|^\*97$|^97$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->vmain2] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [vmain2] destination_number(809) =~ /^vmain2$|^\*98$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->redirect_now] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [redirect_now] destination_number(809) =~ /^\*35$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->local] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [local] ${toll_allow}() =~ /local/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->domestic] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [domestic] destination_number(809) =~ /^0(0[1-9]\d{3,}+)$/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->international] continue=false
Dialplan: FreeTDM/1:1/809 Regex (FAIL) [international] ${toll_allow}() =~ /international/ break=on-false
Dialplan: FreeTDM/1:1/809 parsing [default->test] continue=false
Dialplan: FreeTDM/1:1/809 Regex (PASS) [test] destination_number(809) =~ /809/ break=on-false
Dialplan: FreeTDM/1:1/809 Action set(ignore_early_media=ring_ready)
Dialplan: FreeTDM/1:1/809 Action set(ringback=)
Dialplan: FreeTDM/1:1/809 Action bridge([leg_timeout=0][origination_caller_id_number=30]user/24@${domain_name}:_:[leg_timeout=0][origination_caller_id_number=30]user/10@${domain_name})
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:154 (FreeTDM/1:1/809) State Change CS_ROUTING -> CS_EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/1:1/809 [BREAK]
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:410 (FreeTDM/1:1/809) State ROUTING going to sleep
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:362 (FreeTDM/1:1/809) Running State Change CS_EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:417 (FreeTDM/1:1/809) State EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] mod_freetdm.c:478 FreeTDM/1:1/809 CHANNEL EXECUTE
2012-02-17 15:55:51.198935 [DEBUG] switch_core_state_machine.c:192 FreeTDM/1:1/809 Standard EXECUTE
EXECUTE FreeTDM/1:1/809 set(ignore_early_media=ring_ready)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [ignore_early_media]=[ring_ready]
EXECUTE FreeTDM/1:1/809 set(ringback=)
2012-02-17 15:55:51.198935 [DEBUG] mod_dptools.c:1281 FreeTDM/1:1/809 SET [ringback]=[UNDEF]
EXECUTE FreeTDM/1:1/809 bridge([leg_timeout=0][origination_caller_id_number=30]user/24 at 10.3.0.4:_:[leg_timeout=0][origination_caller_id_number=30]user/10 at 10.3.0.4)
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:1413 Parsing ultra-global variables
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [leg_timeout]=[0]
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [origination_caller_id_number]=[30]
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [leg_timeout]=[0]
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [origination_caller_id_number]=[30]
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[24 at 10.3.0.4]
2012-02-17 15:55:51.218979 [NOTICE] switch_channel.c:930 New Channel sofia/internal/sip:24 at 10.3.0.39 [7be2d7f2-5977-11e1-8ab3-95378f428adb]
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:4670 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_NEW -> CS_INIT
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_INIT
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:24 at 10.3.0.39) State INIT
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:85 sofia/internal/sip:24 at 10.3.0.39 SOFIA INIT
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:24 at 10.3.0.39) State INIT going to sleep
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_ROUTING
2012-02-17 15:55:51.218979 [DEBUG] switch_channel.c:1890 (sofia/internal/sip:24 at 10.3.0.39) Callstate Change DOWN -> RINGING
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:24 at 10.3.0.39) State ROUTING
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:148 sofia/internal/sip:24 at 10.3.0.39 SOFIA ROUTING
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:24 at 10.3.0.39) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:24 at 10.3.0.39) State ROUTING going to sleep
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:24 at 10.3.0.39) Running State Change CS_CONSUME_MEDIA
send 1238 bytes to udp/[10.3.0.39]:5060 at 14:55:51.231136:
------------------------------------------------------------------------
INVITE sip:24 at 10.3.0.39 SIP/2.0
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKKSm2U99980pgQ
Max-Forwards: 70
From: "" <sip:30 at 10.3.0.4>;tag=K1mS38ge1tBac
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:24 at 10.3.0.39) State CONSUME_MEDIA
To: <sip:24 at 10.3.0.39>
Call-ID: 5341a632-d41a-122f-28b4-00900b1be530
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:24 at 10.3.0.39) State CONSUME_MEDIA going to sleep
CSeq: 24409211 INVITE
Contact: <sip:mod_sofia at 10.3.0.4:5060>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-a9c10f8 2012-01-30 18-32-05 -0500
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 369
X-FS-Support: update_display,send_info
Remote-Party-ID: <sip:30 at 10.3.0.4>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1329474121 1329474122 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16430 RTP/AVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
m=video 16390 RTP/AVP 98 99 100 34 31
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/90000
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
------------------------------------------------------------------------
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:24 at 10.3.0.39 entering state [calling][0]
2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-02-17 15:55:51.218979 [DEBUG] switch_event.c:1521 Parsing variable [presence_id]=[10 at 10.3.0.4]
2012-02-17 15:55:51.218979 [NOTICE] switch_channel.c:930 New Channel sofia/internal/sip:10 at 10.3.0.24 [7be451ae-5977-11e1-8ab7-95378f428adb]
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:4670 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_NEW -> CS_INIT
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_INIT
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:10 at 10.3.0.24) State INIT
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:85 sofia/internal/sip:10 at 10.3.0.24 SOFIA INIT
2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_INIT -> CS_ROUTING
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:10 at 10.3.0.24) State INIT going to sleep
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_ROUTING
2012-02-17 15:55:51.218979 [DEBUG] switch_channel.c:1890 (sofia/internal/sip:10 at 10.3.0.24) Callstate Change DOWN -> RINGING
send 1238 bytes to udp/[10.3.0.24]:5060 at 14:55:51.239708:
------------------------------------------------------------------------
INVITE sip:10 at 10.3.0.24 SIP/2.0
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKm2DUX4tD69c3j
Max-Forwards: 70
From: "" <sip:30 at 10.3.0.4>;tag=maej531Hy31vQ
To: <sip:10 at 10.3.0.24>
Call-ID: 5342f5b6-d41a-122f-28b4-00900b1be530
CSeq: 24409211 INVITE
Contact: <sip:mod_sofia at 10.3.0.4:5060>
User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-a9c10f8 2012-01-30 18-32-05 -0500
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:10 at 10.3.0.24) State ROUTING
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE2012-02-17 15:55:51.218979 [DEBUG] mod_sofia.c:148 sofia/internal/sip:10 at 10.3.0.24 SOFIA ROUTING
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer2012-02-17 15:55:51.218979 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:10 at 10.3.0.24) State Change CS_ROUTING -> CS_CONSUME_MEDIA
Content-Type: application/sdp
Content-Disposition: session
2012-02-17 15:55:51.218979 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
Content-Length: 369
X-FS-Support: update_display,send_info
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:10 at 10.3.0.24) State ROUTING going to sleep
Remote-Party-ID: <sip:30 at 10.3.0.4>;party=calling;screen=yes;privacy=off
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:10 at 10.3.0.24) Running State Change CS_CONSUME_MEDIA
v=0
o=FreeSWITCH 1329474135 1329474136 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16416 RTP/AVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
m=video 16396 RTP/AVP 98 99 100 34 31
2012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:10 at 10.3.0.24) State CONSUME_MEDIA
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/900002012-02-17 15:55:51.218979 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:10 at 10.3.0.24) State CONSUME_MEDIA going to sleep
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
------------------------------------------------------------------------
2012-02-17 15:55:51.240318 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:55:51.240318 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:10 at 10.3.0.24 entering state [calling][0]
recv 395 bytes from udp/[10.3.0.39]:5060 at 14:55:51.242848:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKKSm2U99980pgQ
From: <sip:30 at 10.3.0.4>;tag=K1mS38ge1tBac
To: "Braun" <sip:24 at 10.3.0.39>;tag=52904DDD-89045A8
CSeq: 24409211 INVITE
Call-ID: 5341a632-d41a-122f-28b4-00900b1be530
Contact: <sip:24 at 10.3.0.39>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
recv 396 bytes from udp/[10.3.0.24]:5060 at 14:55:51.251445:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKm2DUX4tD69c3j
From: <sip:30 at 10.3.0.4>;tag=maej531Hy31vQ
To: "Knaus" <sip:10 at 10.3.0.24>;tag=1D7DCFF4-E471855F
CSeq: 24409211 INVITE
Call-ID: 5342f5b6-d41a-122f-28b4-00900b1be530
Contact: <sip:10 at 10.3.0.24>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
recv 432 bytes from udp/[10.3.0.39]:5060 at 14:55:51.287148:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKKSm2U99980pgQ
From: <sip:30 at 10.3.0.4>;tag=K1mS38ge1tBac
To: "Braun" <sip:24 at 10.3.0.39>;tag=52904DDD-89045A8
CSeq: 24409211 INVITE
Call-ID: 5341a632-d41a-122f-28b4-00900b1be530
Contact: <sip:24 at 10.3.0.39>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Allow-Events: talk,hold,conference
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
2012-02-17 15:55:51.278910 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
2012-02-17 15:55:51.278910 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:24 at 10.3.0.39 [BREAK]
recv 433 bytes from udp/[10.3.0.24]:5060 at 14:55:51.292014:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKm2DUX4tD69c3j
From: <sip:30 at 10.3.0.4>;tag=maej531Hy31vQ
To: "Knaus" <sip:10 at 10.3.0.24>;tag=1D7DCFF4-E471855F
CSeq: 24409211 INVITE
Call-ID: 5342f5b6-d41a-122f-28b4-00900b1be530
Contact: <sip:10 at 10.3.0.24>
User-Agent: PolycomSoundPointIP-SPIP_321-UA/3.3.1.0933
Allow-Events: talk,hold,conference
Accept-Language: de-de,de;q=0.9,en;q=0.8
Content-Length: 0
------------------------------------------------------------------------
2012-02-17 15:55:51.278910 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:55:51.278910 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:10 at 10.3.0.24 [BREAK]
2012-02-17 15:55:51.298968 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:24 at 10.3.0.39 entering state [proceeding][180]
2012-02-17 15:55:51.298968 [NOTICE] sofia.c:5600 Ring-Ready sofia/internal/sip:24 at 10.3.0.39!
2012-02-17 15:55:51.358930 [DEBUG] sofia.c:5508 Channel sofia/internal/sip:10 at 10.3.0.24 entering state [proceeding][180]
2012-02-17 15:55:51.358930 [NOTICE] sofia.c:5600 Ring-Ready sofia/internal/sip:10 at 10.3.0.24!
Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users
mailing list