Testing with version 16963M
Problem:
When using
* api originate sofia/internal/+18014712100@172.30.110.225:5060 conference:conf_uuid-TEST_CONF inline or
* api originate sofia/internal/+18014712100@172.30.110.225:5060 &conference(conf_uuid-TEST_CONF)
I am getting the CHANNEL_ANSWER event
before the channel is actually answered. I have included console logs
(with SIP messages) as well as the EVENT from ESL in the enclosed log files [Early_CHANNEL_ANSWER_EVENTS.txt
& Early_CHANNEL_ANSWER_CLI_LOG.txt]
Is
there a work-around or something else I need to do/set, or should I log this in
Jira?
To give
an overview:
2010-03-11
14:30:44.785190 [NOTICE] switch_channel.c:669 New
Channel sofia/internal/+18014712100@172.30.110.225:5060
[8a0782ef-fb06-4fa7-9441-ddcc65f08b4a]
2010-03-11
14:30:44.785190 [DEBUG] mod_sofia.c:3375
(sofia/internal/+18014712100@172.30.110.225:5060) State Change CS_NEW ->
CS_INIT
2010-03-11
14:30:44.785190 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/+18014712100@172.30.110.225:5060 [BREAK]
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/+18014712100@172.30.110.225:5060)
Running State Change CS_INIT
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/+18014712100@172.30.110.225:5060) State INIT
2010-03-11
14:30:44.785190 [DEBUG] mod_sofia.c:83 sofia/internal/+18014712100@172.30.110.225:5060
2010-03-11
14:30:44.785190 [DEBUG] mod_sofia.c:117
(sofia/internal/+18014712100@172.30.110.225:5060) State Change CS_INIT ->
CS_ROUTING
2010-03-11
14:30:44.785190 [DEBUG] switch_core_session.c:1018 Send signal sofia/internal/+18014712100@172.30.110.225:5060
[BREAK]
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/+18014712100@172.30.110.225:5060) State INIT going to sleep
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/+18014712100@172.30.110.225:5060) Running State Change
CS_ROUTING
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/+18014712100@172.30.110.225:5060) State ROUTING
2010-03-11
14:30:44.785190 [DEBUG] mod_sofia.c:140
sofia/internal/+18014712100@172.30.110.225:5060
2010-03-11
14:30:44.785190 [DEBUG] switch_ivr_originate.c:66
(sofia/internal/+18014712100@172.30.110.225:5060) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2010-03-11
14:30:44.785190 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/+18014712100@172.30.110.225:5060 [BREAK]
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/+18014712100@172.30.110.225:5060) State ROUTING going to sleep
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/+18014712100@172.30.110.225:5060) Running State Change
CS_CONSUME_MEDIA
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:360
(sofia/internal/+18014712100@172.30.110.225:5060) State CONSUME_MEDIA
2010-03-11
14:30:44.785190 [DEBUG] switch_core_state_machine.c:360
(sofia/internal/+18014712100@172.30.110.225:5060) State CONSUME_MEDIA going to
sleep
send 1140 bytes to
udp/[172.30.110.225]:5060 at 19:30:44.787327:
------------------------------------------------------------------------
INVITE sip:+18014712100@172.30.110.225:5060 SIP/2.0
<<< Deleted here for shorter version – full log in enclosed
file>>>
------------------------------------------------------------------------
2010-03-11
14:30:44.787361 [DEBUG] sofia.c:4152 Channel
sofia/internal/+18014712100@172.30.110.225:5060 entering state [calling][0]
recv 739 bytes
from udp/[172.30.110.225]:5060 at 19:30:44.817367:
------------------------------------------------------------------------
SIP/2.0 100 Trying
<<< Deleted here for shorter version – full log in enclosed
file>>>
------------------------------------------------------------------------
recv 732 bytes
from udp/[172.30.110.225]:5060 at 19:30:45.667133:
------------------------------------------------------------------------
SIP/2.0 180 Ringing [NOTE: This is a 180 WITH SDP – causing Early Media –
Yes this is a Sonus!]]
<<< Deleted here for shorter version – full log in enclosed
file>>>
------------------------------------------------------------------------
2010-03-11
14:30:45.666976 [INFO] sofia.c:662 Update Callee ID to "+18014712100"
<+18014712100>
2010-03-11
14:30:45.724981 [DEBUG] sofia.c:4152 Channel
sofia/internal/+18014712100@172.30.110.225:5060 entering state
[proceeding][180]
2010-03-11
14:30:45.724981 [DEBUG] sofia.c:4163 Remote SDP:
v=0
<<< Deleted here for shorter version – full log in enclosed
file>>>
2010-03-11
14:30:45.724981 [DEBUG] sofia_glue.c:3570 Audio Codec Compare
[PCMU:0:8000:20]/[PCMU:0:8000:20]
2010-03-11
14:30:45.724981 [DEBUG] sofia_glue.c:2354 Set Codec
sofia/internal/+18014712100@172.30.110.225:5060 PCMU/8000 20 ms 160 samples
2010-03-11
14:30:45.727007 [DEBUG] sofia_glue.c:3511 Set 2833 dtmf payload to 101
2010-03-11
14:30:45.727007 [DEBUG] sofia_glue.c:2594 AUDIO RTP
[sofia/internal/+18014712100@172.30.110.225:5060] 10.50.48.232 port 32646 ->
65.59.218.161 port 59838 codec: 0 ms: 20
2010-03-11
14:30:45.727007 [DEBUG] switch_rtp.c:1181 Starting timer [soft] 160 bytes per
20ms
2010-03-11 14:30:45.729007
[NOTICE] sofia_glue.c:3149 Pre-Answer
sofia/internal/+18014712100@172.30.110.225:5060!
2010-03-11
14:30:45.730985 [DEBUG] switch_ivr_originate.c:3107 Originate Resulted in
Success: [sofia/internal/+18014712100@172.30.110.225:5060]
2010-03-11 14:30:45.730985
[DEBUG] switch_ivr.c:1441 (sofia/internal/+18014712100@172.30.110.225:5060)
State Change CS_CONSUME_MEDIA -> CS_ROUTING
<<< Deleted here for shorter version – full log in enclosed
file>>>
2010-03-11
14:30:45.730985 [DEBUG] mod_sofia.c:226
sofia/internal/+18014712100@172.30.110.225:5060 SOFIA EXECUTE
2010-03-11
14:30:45.730985 [DEBUG] switch_core_state_machine.c:157
sofia/internal/+18014712100@172.30.110.225:5060 Standard EXECUTE
EXECUTE
sofia/internal/+18014712100@172.30.110.225:5060 conference(conf_uuid-TEST_CON)
2010-03-11
14:30:45.730985 [DEBUG] mod_conference.c:5671 Installing default caller control
action 'mute' bound to '0'.
2010-03-11
14:30:45.730985 [DEBUG] switch_ivr.c:1616 max len 1
2010-03-11
14:30:45.730985 [DEBUG] switch_ivr.c:1620 min len 1
<<< Deleted here for shorter version – full log in enclosed
file>>>
2010-03-11
14:30:45.733291 [DEBUG] switch_core_codec.c:122
sofia/internal/+18014712100@172.30.110.225:5060 Push codec L16:10
2010-03-11
14:30:45.733291 [DEBUG] switch_core_session.c:638 Send signal
sofia/internal/+18014712100@172.30.110.225:5060 [BREAK]
2010-03-11
14:30:45.733291 [DEBUG] mod_conference.c:2202 Setup timer soft success
interval: 20 samples: 160
2010-03-11
14:30:45.733291 [NOTICE] mod_conference.c:2213 Channel
[sofia/internal/+18014712100@172.30.110.225:5060] has been answered
NOTE: The above line is where CHANNEL_ANSWER event gets
generated, but the call is not answered until about 10 seconds later (in this
case). See below.
2010-03-11
14:30:45.733291 [DEBUG] mod_conference.c:2316 Outbound conference channel
answered, setting CFLAG_ANSWERED
2010-03-11
14:30:45.735363 [DEBUG] mod_conference.c:994 Setup timer success interval:
20 samples: 160
2010-03-11
14:30:46.232841 [DEBUG] switch_rtp.c:2055 Correct ip/port confirmed.
2010-03-11
14:30:48.494337 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/8000] 8000hz
NOTE: The 200 OK came ~10 seconds after the above “Channel
[sofia/internal/+18014712100@172.30.110.225:5060] has been answered” message
recv 830 bytes
from udp/[172.30.110.225]:5060 at 19:30:55.520491:
------------------------------------------------------------------------
SIP/2.0 200 OK
v:SIP/2.0/UDP
10.50.48.232;branch=z9hG4bKXQaS3DB27ypra;received=10.50.48.232;rport=5060
f:""<sip:0000000000@10.50.48.232>;tag=Bgv1HtFKD6UUK
t:<sip:+18014712100@172.30.110.225:5060>;tag=887148b37ae7121417289eefaa340e22
i:6db7a397-a7e7-122d-84b6-001279948854
<<< Deleted here for shorter version – full log in enclosed
file>>>
From
the enclosed Event logs [Early_CHANNEL_ANSWER_EVENTS.txt]
loop = 17
Event-Name: CHANNEL_ANSWER
Core-UUID:
3920497f-8c61-401e-85b2-8693bcf0a428
FreeSWITCH-Hostname:
tpa-es-rh-232.dev.sipstorm.com
FreeSWITCH-IPv4:
10.50.48.232
FreeSWITCH-IPv6:
%3A%3A1
Event-Date-Local: 2010-03-11 14:30:45
[NOTE: 14:30:45] – time of the 2010-03-11
14:30:45.733291 [NOTICE] mod_conference.c:2213 Channel
[sofia/internal/+18014712100@172.30.110.225:5060] has been answered
Event-Date-GMT:
Thu,%2011%20Mar%202010%2019%3A30%3A45%20GMT
Event-Date-Timestamp:
1268335845733291
Event-Calling-File:
switch_channel.c
Event-Calling-Function:
switch_channel_perform_mark_answered
Event-Calling-Line-Number:
2283
Channel-State:
CS_EXECUTE
Channel-State-Number:
4
Channel-Name:
sofia/internal/%2B18014712100%40172.30.110.225%3A5060
Unique-ID:
8a0782ef-fb06-4fa7-9441-ddcc65f08b4a
Call-Direction:
outbound
Presence-Call-Direction:
outbound
Answer-State:
answered
Channel-Read-Codec-Name:
L16
Channel-Read-Codec-Rate:
8000
Channel-Write-Codec-Name:
PCMU
Channel-Write-Codec-Rate:
8000
Caller-Dialplan:
inline
Caller-Caller-ID-Number:
0000000000
Caller-Network-Addr:
172.30.110.225
Caller-Destination-Number:
%2B18014712100
Caller-Unique-ID:
8a0782ef-fb06-4fa7-9441-ddcc65f08b4a
Caller-Source:
src/switch_ivr_originate.c
Caller-Context:
default
Caller-Channel-Name:
sofia/internal/%2B18014712100%40172.30.110.225%3A5060
Caller-Profile-Index:
2
Caller-Profile-Created-Time:
1268335845730985
Caller-Channel-Created-Time:
1268335844785190
Caller-Channel-Answered-Time:
1268335845733291
Caller-Channel-Progress-Time:
0
Caller-Channel-Progress-Media-Time:
1268335845729007
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_is_outbound:
true
variable_uuid:
8a0782ef-fb06-4fa7-9441-ddcc65f08b4a
variable_sip_profile_name:
10.50.48.232
variable_channel_name:
sofia/internal/%2B18014712100%40172.30.110.225%3A5060
variable_sip_destination_url:
sip%3A%2B18014712100%40172.30.110.225%3A5060
variable_originate_early_media:
true
variable_sip_local_sdp_str:
v%3D0%0Ao%3DFreeSWITCH%201268303198%201268303199%20IN%20IP4%2010.50.48.232%0As%3DFreeSWITCH%0Ac%3DIN%20IP4%2010.50.48.232%0At%3D0%200%0Am%3Daudio%2032646%20RTP/AVP%200%20101%2013%0Aa%3Drtpmap%3A0%20PCMU/8000%0Aa%3Drtpmap%3A101%20telephone-event/8000%0Aa%3Dfmtp%3A101%200-16%0Aa%3Drtpmap%3A13%20CN/8000%0Aa%3Dptime%3A20%0Aa%3Dsendrecv%0A
variable_sip_outgoing_contact_uri:
%3Csip%3Amod_sofia%4010.50.48.232%3A5060%3E
variable_sip_req_uri:
%2B18014712100%40172.30.110.225%3A5060
variable_sofia_profile_name:
internal
variable_sip_reply_host:
172.30.110.225
variable_sip_reply_port:
5060
variable_sip_network_ip:
172.30.110.225
variable_sip_network_port:
5060
variable_sip_full_via:
SIP/2.0/UDP%2010.50.48.232%3Bbranch%3Dz9hG4bKXQaS3DB27ypra%3Breceived%3D10.50.48.232%3Brport%3D5060
variable_sip_full_from:
%22%22%20%3Csip%3A0000000000%4010.50.48.232%3E%3Btag%3DBgv1HtFKD6UUK
variable_sip_full_to:
%3Csip%3A%2B18014712100%40172.30.110.225%3A5060%3E%3Btag%3D887148b37ae7121417289eefaa340e22
variable_sip_from_user:
0000000000
variable_sip_from_uri:
0000000000%4010.50.48.232
variable_sip_from_host:
10.50.48.232
variable_sip_to_user:
%2B18014712100
variable_sip_to_port:
5060
variable_sip_to_uri:
%2B18014712100%40172.30.110.225%3A5060
variable_sip_to_host:
172.30.110.225
variable_sip_contact_params:
transport%3Dudp
variable_sip_contact_user:
0-04370ee113c407043dff
variable_sip_contact_port:
5060
variable_sip_contact_uri:
0-04370ee113c407043dff%40172.30.110.225%3A5060
variable_sip_contact_host:
172.30.110.225
variable_sip_to_tag:
887148b37ae7121417289eefaa340e22
variable_sip_from_tag:
Bgv1HtFKD6UUK
variable_sip_cseq:
128049586
variable_sip_call_id:
6db7a397-a7e7-122d-84b6-001279948854
variable_switch_r_sdp:
v%3D0%0D%0Ao%3DSonus_UAC%20536801%2053680100%20IN%20IP4%2065.59.218.161%0D%0As%3DSIP%20Media%20Capabilities%0D%0Ac%3DIN%20IP4%2065.59.218.161%0D%0At%3D0%200%0D%0Am%3Daudio%2059838%20RTP/AVP%200%20101%0D%0Aa%3Drtpmap%3A0%20PCMU/8000%0D%0Aa%3Drtpmap%3A101%20telephone-event/8000%0D%0Aa%3Dfmtp%3A101%200-15%0D%0Aa%3Dmaxptime%3A20%0D%0A
variable_sip_use_codec_name:
PCMU
variable_sip_use_codec_rate:
8000
variable_sip_use_codec_ptime:
20
variable_write_codec:
PCMU
variable_write_rate:
8000
variable_local_media_ip:
10.50.48.232
variable_local_media_port:
32646
variable_sip_use_pt:
0
variable_rtp_use_ssrc:
2908074324
variable_remote_media_ip:
65.59.218.161
variable_remote_media_port:
59838
variable_endpoint_disposition:
EARLY%20MEDIA
variable_max_forwards:
70
variable_current_application_data:
conf_uuid-TEST_CON
variable_current_application:
conference
variable_conference_name:
conf_uuid-TEST_CON
variable_read_codec:
L16
variable_read_rate:
8000