That was a very obscure bug becuse most people to not send unanswered calls to something who might call answer on them. its fixed in r16970 but if you have any more bugs, please report them to http://jira.freeswitch.org not here. On Thu, Mar 11, 2010 at 2:17 PM, Gledhill, James < james.gledhill@sipstorm.com> wrote:
Testing with version *16963M*
*Problem:*
When using
* api originate sofia/internal/+18014712100@172.30.110.225:5060conference: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:5060conference(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 <sip%3A0000000000@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
_______________________________________________ FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com <MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com<PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <sip%3A888@conference.freeswitch.org> iax:guest@conference.freeswitch.org/888 googletalk:conf+888@conference.freeswitch.org<googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:+19193869900