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 SOFIA INIT 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 SOFIA ROUTING 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=506 0 f:""<sip:0000000000@10.50.48.232>;tag=Bgv1HtFKD6UUK t:<sip:+18014712100@172.30.110.225:5060>;tag=887148b37ae7121417289eefaa3 40e22 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.2 32%0As%3DFreeSWITCH%0Ac%3DIN%20IP4%2010.50.48.232%0At%3D0%200%0Am%3Daudi o%2032646%20RTP/AVP%200%20101%2013%0Aa%3Drtpmap%3A0%20PCMU/8000%0Aa%3Drt pmap%3A101%20telephone-event/8000%0Aa%3Dfmtp%3A101%200-16%0Aa%3Drtpmap%3 A13%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%3D 10.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%3D887148b37ae71 21417289eefaa340e22 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%3Dfm tp%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