[Freeswitch-dev] Getting CHANNEL_ANSWER Event before call is answered with 'api originate <dialstring> conference:conf_uuid-TEST_CONF inline'
Anthony Minessale
anthony.minessale at gmail.com
Thu Mar 11 12:42:56 PST 2010
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 at sipstorm.com> wrote:
> Testing with version *16963M*
>
>
>
> *Problem:*
>
>
>
> When using
>
> * api originate sofia/internal/+18014712100 at 172.30.110.225:5060conference:conf_uuid-TEST_CONF inline or
>
> * api originate sofia/internal/+18014712100 at 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 at 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 at 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 at 172.30.110.225:5060 [BREAK]
>
> 2010-03-11 14:30:44.785190 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/+18014712100 at 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 at 172.30.110.225:5060) State INIT
>
> 2010-03-11 14:30:44.785190 [DEBUG] mod_sofia.c:83 sofia/internal/+
> 18014712100 at 172.30.110.225:5060 SOFIA INIT
>
> 2010-03-11 14:30:44.785190 [DEBUG] mod_sofia.c:117 (sofia/internal/+
> 18014712100 at 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 at 172.30.110.225:5060 [BREAK]
>
> 2010-03-11 14:30:44.785190 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/+18014712100 at 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 at 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 at 172.30.110.225:5060) State ROUTING
>
> 2010-03-11 14:30:44.785190 [DEBUG] mod_sofia.c:140 sofia/internal/+
> 18014712100 at 172.30.110.225:5060 SOFIA ROUTING
>
> 2010-03-11 14:30:44.785190 [DEBUG] switch_ivr_originate.c:66
> (sofia/internal/+18014712100 at 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 at 172.30.110.225:5060 [BREAK]
>
> 2010-03-11 14:30:44.785190 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/+18014712100 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 172.30.110.225:5060]
>
> 2010-03-11 14:30:45.730985 [DEBUG] switch_ivr.c:1441 (sofia/internal/+
> 18014712100 at 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 at 172.30.110.225:5060 SOFIA EXECUTE
>
> 2010-03-11 14:30:45.730985 [DEBUG] switch_core_state_machine.c:157
> sofia/internal/+18014712100 at 172.30.110.225:5060 Standard EXECUTE
>
> *EXECUTE sofia/internal/+18014712100 at 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 at 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 at 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 at 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 at 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 at 10.50.48.232 <sip%3A0000000000 at 10.50.48.232>
> >;tag=Bgv1HtFKD6UUK
>
> t:<sip:+18014712100 at 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 at 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 at 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 at hotmail.com <MSN%3Aanthony_minessale at hotmail.com>
GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com<PAYPAL%3Aanthony.minessale at gmail.com>
IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org <sip%3A888 at conference.freeswitch.org>
iax:guest at conference.freeswitch.org/888
googletalk:conf+888 at conference.freeswitch.org<googletalk%3Aconf%2B888 at conference.freeswitch.org>
pstn:+19193869900
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20100311/5522234c/attachment-0001.html
More information about the FreeSWITCH-dev
mailing list