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: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=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

 

 


_______________________________________________
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
GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com
IRC: irc.freenode.net #freeswitch

FreeSWITCH Developer Conference
sip:888@conference.freeswitch.org
iax:guest@conference.freeswitch.org/888
googletalk:conf+888@conference.freeswitch.org
pstn:+19193869900