[Freeswitch-dev] Getting CHANNEL_ANSWER Event before call is answered with 'api originate <dialstring> conference:conf_uuid-TEST_CONF inline'

Thu Mar 11 12:17:54 PST 2010

Testing with version 16963M

Problem:

When using

 * api originate sofia/internal/+18014712100 at 172.30.110.225:5060
conference: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: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 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=506
0

   f:""<sip:0000000000 at 10.50.48.232>;tag=Bgv1HtFKD6UUK

t:<sip:+18014712100 at 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 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.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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20100311/efc1ab67/attachment-0001.html 