[Freeswitch-users] Problems with repetitive calls in rtmp
Germán Ruiz
chmp99 at gmail.com
Thu Dec 5 18:01:22 MSK 2013
Hi !
I have problems when I call twice a client conected to rtmp endpoint.
The first one is ok and ring. But when I retry few seconds ago (less
than 15 sec), I get a abort error.
Looking in the log, I can see that is executing two times my dialplan.
The first time with the dialed number and the second with the rtmp
connection uuid (!)
In the example below, I call from user "user1001" to user
"user1002 at 172.16.0.216".
First execute for dialplan:
2013-12-05 11:23:20.418092 [INFO] mod_dialplan_xml.c:558 Processing
<user1001>->sip:user1002 at 172.16.0.216 in context default
Execute bride:
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216
bridge(user/user1002 at 172.16.0.216,rtmp/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
And next re-execute the dialplan, taking the dialed string as the uuid leg.
2013-12-05 11:23:20.487852 [INFO] mod_dialplan_xml.c:558 Processing Abel
Valencia
<user1001>->99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
in context default
I only see this behavior in RTMP. Users connected with SIP don't have
this problem. Is it a bug in rtmp module or I have a wrong configuration ?
Thanks in advance!
The extension "autenticado" is
<extension name="autenticado">
<condition field="destination_number"
expression="^(sip:)?([a-z]([a-z0-9])+)(@${domain})?">
<action application="export" data="dialed=$2"/>
<action application="export" data="processed=true"/>
<action application="set" data="ringback=${us-ring}"/>
<action application="set" data="call_timeout=30"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="fail_on_single_reject=false" />
<action application="set" data="ignore_early_media=true" />
<action application="info"/>
<action application="bridge"
data="user/${dialed}@172.16.0.216,${rtmp_contact(default/${dialed}@172.16.0.216)}"/>
</condition>
</extension>
FS version:
FreeSWITCH Version 1.2.15+git~20131205T011841Z~cb244aea1d~64bit (git
cb244ae 2013-12-05 01:18:41Z 64bit)
Full log from second call (the first was ok!)
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:905 [chunk_stream=2 type=0x4
ts=7649694 stream_id=0x0] len=10
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:77 Control (3): 00 00 00 00 00
00 00 c8
2013-12-05 11:23:20.387941 [WARNING] rtmp.c:101 [amfnumber=2] Unhandled
control packet (type=0x3)
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:905 [chunk_stream=3 type=0x14
ts=76296 stream_id=0x0] len=25
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:171 [amfnumber=3] Got INVOKE
for createStream
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=29
2013-12-05 11:23:20.387941 [INFO] rtmp_sig.c:136 Replied to createStream
(17)
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:905 [chunk_stream=3 type=0x14
ts=76296 stream_id=0x0] len=25
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:171 [amfnumber=3] Got INVOKE
for createStream
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=29
2013-12-05 11:23:20.387941 [INFO] rtmp_sig.c:136 Replied to createStream
(18)
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:905 [chunk_stream=3 type=0x14
ts=76296 stream_id=0x0] len=81
2013-12-05 11:23:20.387941 [DEBUG] rtmp.c:171 [amfnumber=3] Got INVOKE
for makeCall
2013-12-05 11:23:20.387941 [INFO] mod_rtmp.c:953 New FreeSWITCH session
created: ca7f1924-5db8-11e3-90b2-8518b7899937
2013-12-05 11:23:20.387941 [NOTICE] switch_channel.c:1052 New Channel
rtmp/default/sip:user1002 at 172.16.0.216
[ca7f1924-5db8-11e3-90b2-8518b7899937]
2013-12-05 11:23:20.418092 [DEBUG] mod_rtmp.c:1007
(rtmp/default/sip:user1002 at 172.16.0.216) State Change CS_NEW -> CS_INIT
2013-12-05 11:23:20.418092 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=114
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_INIT
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=60
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:454
(rtmp/default/sip:user1002 at 172.16.0.216) State INIT
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=68
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:905 [chunk_stream=2 type=0x4
ts=7649694 stream_id=0x0] len=10
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:77 Control (3): 00 00 00 11 00
00 00 c8
2013-12-05 11:23:20.418092 [WARNING] rtmp.c:101 [amfnumber=2] Unhandled
control packet (type=0x3)
2013-12-05 11:23:20.418092 [DEBUG] mod_rtmp.c:171
(rtmp/default/sip:user1002 at 172.16.0.216) State Change CS_INIT -> CS_ROUTING
2013-12-05 11:23:20.418092 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:905 [chunk_stream=8 type=0x14
ts=76296 stream_id=0x11] len=24
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:454
(rtmp/default/sip:user1002 at 172.16.0.216) State INIT going to sleep
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:171 [amfnumber=8] Got INVOKE
for play
2013-12-05 11:23:20.418092 [DEBUG] rtmp_sig.c:188 Got play for play on
stream 17
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=2 type=0x4
stream_id=0x0] len=6
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=2 type=0x4
stream_id=0x0] len=10
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=5 type=0x14
stream_id=0x11] len=135
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=5 type=0x14
stream_id=0x11] len=135
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=5 type=0x12
stream_id=0x11] len=44
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=5 type=0x12
stream_id=0x11] len=24
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:905 [chunk_stream=14 type=0x14
ts=76296 stream_id=0x12] len=37
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_ROUTING
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:171 [amfnumber=14] Got INVOKE
for publish
2013-12-05 11:23:20.418092 [DEBUG] switch_channel.c:2164
(rtmp/default/sip:user1002 at 172.16.0.216) Callstate Change DOWN -> RINGING
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=2 type=0x4
stream_id=0x0] len=6
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=14 type=0x14
stream_id=0x0] len=21
2013-12-05 11:23:20.418092 [INFO] rtmp_sig.c:274 Got publish on stream 18.
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:905 [chunk_stream=8 type=0x14
ts=76296 stream_id=0x11] len=27
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:171 [amfnumber=8] Got INVOKE
for receiveAudio
2013-12-05 11:23:20.418092 [INFO] rtmp_sig.c:159 Sending audio
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:470
(rtmp/default/sip:user1002 at 172.16.0.216) State ROUTING
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.418092 [DEBUG] mod_rtmp.c:197
rtmp/default/sip:user1002 at 172.16.0.216 CHANNEL ROUTING
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:117
rtmp/default/sip:user1002 at 172.16.0.216 Standard ROUTING
2013-12-05 11:23:20.418092 [INFO] mod_dialplan_xml.c:558 Processing
<user1001>->sip:user1002 at 172.16.0.216 in context default
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 parsing
[default->global] continue=true
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Absolute Condition [global]
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 parsing
[default->conferencias web] continue=false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Regex (FAIL)
[conferencias web] destination_number(sip:user1002 at 172.16.0.216) =~
/^(_conf_.*)$/
break=on-false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 parsing
[default->show_info] continue=false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Regex (FAIL)
[show_info] destination_number(sip:user1002 at 172.16.0.216) =~
/^(sip:)?(9192+)(@172.16.0.216)?/
break=on-false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 parsing
[default->transf_both_legs] continue=false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Regex (FAIL)
[transf_both_legs] destination_number(sip:user1002 at 172.16.0.216) =~
/^transf_both_(.*)_(.*)_(.*)$/
break=on-false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 parsing
[default->autenticado] continue=false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Regex (PASS)
[autenticado] destination_number(sip:user1002 at 172.16.0.216) =~
/^(sip:)?([a-z]([a-z0-9])+)(@172.16.0.216)?/
break=on-false
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
export(dialed=user1002)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
export(processed=true)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
set(ringback=${us-ring})
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
set(call_timeout=30)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
set(hangup_after_bridge=true)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
set(fail_on_single_reject=false)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
set(ignore_early_media=true)
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action info()
Dialplan: rtmp/default/sip:user1002 at 172.16.0.216 Action
bridge(user/${dialed}@172.16.0.216,${rtmp_contact(default/${dialed}@172.16.0.216)})
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:167
(rtmp/default/sip:user1002 at 172.16.0.216) State Change CS_ROUTING ->
CS_EXECUTE
2013-12-05 11:23:20.418092 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:470
(rtmp/default/sip:user1002 at 172.16.0.216) State ROUTING going to sleep
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_EXECUTE
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:477
(rtmp/default/sip:user1002 at 172.16.0.216) State EXECUTE
2013-12-05 11:23:20.418092 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.418092 [DEBUG] mod_rtmp.c:215
rtmp/default/sip:user1002 at 172.16.0.216 CHANNEL EXECUTE
2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:209
rtmp/default/sip:user1002 at 172.16.0.216 Standard EXECUTE
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 export(RFC2822_DATE=Thu,
05 Dec 2013 11:23:20 -0300)
2013-12-05 11:23:20.418092 [DEBUG] switch_channel.c:1244 EXPORT
(export_vars) [RFC2822_DATE]=[Thu, 05 Dec 2013 11:23:20 -0300]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 export(dialed=user1002)
2013-12-05 11:23:20.418092 [DEBUG] switch_channel.c:1244 EXPORT
(export_vars) [dialed]=[user1002]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 export(processed=true)
2013-12-05 11:23:20.418092 [DEBUG] switch_channel.c:1244 EXPORT
(export_vars) [processed]=[true]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216
set(ringback=%(2000,4000,440,480))
2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402
rtmp/default/sip:user1002 at 172.16.0.216 SET [ringback]=[%(2000,4000,440,480)]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 set(call_timeout=30)
2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402
rtmp/default/sip:user1002 at 172.16.0.216 SET [call_timeout]=[30]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 set(hangup_after_bridge=true)
2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402
rtmp/default/sip:user1002 at 172.16.0.216 SET [hangup_after_bridge]=[true]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216
set(fail_on_single_reject=false)
2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402
rtmp/default/sip:user1002 at 172.16.0.216 SET [fail_on_single_reject]=[false]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 set(ignore_early_media=true)
2013-12-05 11:23:20.447790 [DEBUG] mod_dptools.c:1402
rtmp/default/sip:user1002 at 172.16.0.216 SET [ignore_early_media]=[true]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216 info()
2013-12-05 11:23:20.447790 [INFO] mod_dptools.c:1614 CHANNEL_DATA:
Channel-State:
[CS_EXECUTE]
Channel-Call-State:
[RINGING]
Channel-State-Number:
[4]
Channel-Name:
[rtmp/default/sip:user1002 at 172.16.0.216]
Unique-ID:
[ca7f1924-5db8-11e3-90b2-8518b7899937]
Call-Direction:
[inbound]
Presence-Call-Direction:
[inbound]
Channel-HIT-Dialplan:
[true]
Channel-Call-UUID:
[ca7f1924-5db8-11e3-90b2-8518b7899937]
Answer-State:
[ringing]
Channel-Read-Codec-Name:
[SPEEX]
Channel-Read-Codec-Rate:
[16000]
Channel-Read-Codec-Bit-Rate:
[42200]
Channel-Write-Codec-Name:
[SPEEX]
Channel-Write-Codec-Rate:
[16000]
Channel-Write-Codec-Bit-Rate:
[42200]
Caller-Direction:
[inbound]
Caller-Username:
[user1001]
Caller-Dialplan:
[XML]
Caller-Caller-ID-Number:
[user1001]
Caller-Orig-Caller-ID-Number:
[user1001]
Caller-Network-Addr:
[192.168.0.156]
Caller-Destination-Number:
[sip:user1002 at 172.16.0.216]
Caller-Unique-ID:
[ca7f1924-5db8-11e3-90b2-8518b7899937]
Caller-Source:
[mod_rtmp]
Caller-Context:
[default]
Caller-Channel-Name:
[rtmp/default/sip:user1002 at 172.16.0.216]
Caller-Profile-Index:
[1]
Caller-Profile-Created-Time:
[1386253400418092]
Caller-Channel-Created-Time:
[1386253400418092]
Caller-Channel-Answered-Time:
[0]
Caller-Channel-Progress-Time:
[0]
Caller-Channel-Progress-Media-Time:
[0]
Caller-Channel-Hangup-Time:
[0]
Caller-Channel-Transfer-Time:
[0]
Caller-Channel-Resurrect-Time:
[0]
Caller-Channel-Bridged-Time:
[0]
Caller-Channel-Last-Hold:
[0]
Caller-Channel-Hold-Accum:
[0]
Caller-Screen-Bit:
[true]
Caller-Privacy-Hide-Name:
[false]
Caller-Privacy-Hide-Number:
[false]
variable_direction:
[inbound]
variable_uuid:
[ca7f1924-5db8-11e3-90b2-8518b7899937]
variable_session_id:
[56]
variable_channel_name:
[rtmp/default/sip:user1002 at 172.16.0.216]
variable_user_context:
[default]
variable_effective_caller_id_name: [Abel
Valencia]
variable_user_name:
[user1001]
variable_domain_name:
[172.16.0.216]
variable_rtmp_authorized:
[true]
variable_read_codec:
[SPEEX]
variable_read_rate:
[16000]
variable_write_codec:
[SPEEX]
variable_write_rate:
[16000]
variable_rtmp_profile:
[default]
variable_rtmp_session:
[9d04d178-5db8-11e3-8fd7-8518b7899937]
variable_rtmp_flash_version: [LNX
11,2,202,310]
variable_rtmp_swf_url:
[https://172.16.0.216/flash/phone.swf]
variable_rtmp_tc_url:
[rtmp://172.16.0.216:1935]
variable_rtmp_page_url:
[https://172.16.0.216]
variable_rtmp_remote_address:
[192.168.0.156]
variable_rtmp_remote_port:
[44345]
variable_DP_MATCH:
[ARRAY::sip:user1002 at 172.16.0.216|:sip:|:user1002|:2|:@172.16.0.216]
variable_call_uuid:
[ca7f1924-5db8-11e3-90b2-8518b7899937]
variable_RFC2822_DATE: [Thu, 05 Dec 2013 11:23:20
-0300]
variable_dialed:
[user1002]
variable_processed:
[true]
variable_export_vars:
[RFC2822_DATE,dialed,processed]
variable_ringback:
[%(2000,4000,440,480)]
variable_call_timeout:
[30]
variable_hangup_after_bridge:
[true]
variable_fail_on_single_reject:
[false]
variable_ignore_early_media:
[true]
variable_current_application:
[info]
EXECUTE rtmp/default/sip:user1002 at 172.16.0.216
bridge(user/user1002 at 172.16.0.216,rtmp/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
2013-12-05 11:23:20.447790 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[RFC2822_DATE]=[Thu, 05 Dec 2013 11:23:20 -0300] to
event
2013-12-05 11:23:20.447790 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[dialed]=[user1002] to event
2013-12-05 11:23:20.447790 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[processed]=[true] to event
2013-12-05 11:23:20.447790 [DEBUG] switch_ivr_originate.c:2061 Parsing
global variables
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[RFC2822_DATE]=[Thu, 05 Dec 2013 11:23:20 -0300] to
event
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[dialed]=[user1002] to event
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:1198
rtmp/default/sip:user1002 at 172.16.0.216 EXPORTING[export_vars]
[processed]=[true] to event
2013-12-05 11:23:20.487852 [DEBUG] switch_ivr_originate.c:2061 Parsing
global variables
2013-12-05 11:23:20.487852 [DEBUG] switch_event.c:1654 Parsing variable
[presence_id]=[user1002 at 172.16.0.216]
2013-12-05 11:23:20.487852 [NOTICE] switch_ivr_originate.c:2662 Cannot
create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2013-12-05 11:23:20.487852 [DEBUG] switch_ivr_originate.c:3639 Originate
Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2013-12-05 11:23:20.487852 [NOTICE] switch_ivr_originate.c:2662 Cannot
create outgoing channel of type [user] cause: [USER_NOT_REGISTERED]
2013-12-05 11:23:20.487852 [NOTICE] switch_channel.c:1052 New Channel
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[ca8dfa2a-5db8-11e3-90c8-8518b7899937]
2013-12-05 11:23:20.487852 [NOTICE] mod_rtmp.c:670 Ring Ready
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216!
2013-12-05 11:23:20.487852 [NOTICE] mod_rtmp.c:670 Ring-Ready
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216!
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:3238
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Callstate
Change DOWN ->
RINGING
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=119
2013-12-05 11:23:20.487852 [DEBUG] mod_rtmp.c:673
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
Change CS_NEW ->
CS_INIT
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change
CS_INIT
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:454
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
INIT
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.487852 [DEBUG] mod_rtmp.c:171
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
Change CS_INIT ->
CS_ROUTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:454
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
INIT going to
sleep
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change
CS_ROUTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:470
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
ROUTING
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.487852 [DEBUG] mod_rtmp.c:197
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
CHANNEL ROUTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:117
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Standard
ROUTING
2013-12-05 11:23:20.487852 [INFO] mod_dialplan_xml.c:558 Processing Abel
Valencia
<user1001>->99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
in context
default
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
parsing [default->global] continue=true
2013-12-05 11:23:20.487852 [NOTICE] mod_rtmp.c:549 Pre-Answer
rtmp/default/sip:user1002 at 172.16.0.216!
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/
break=never
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Absolute Condition [global]
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
parsing [default->conferencias web] continue=false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Regex (FAIL) [conferencias web]
destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
=~ /^(_conf_.*)$/
break=on-false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
parsing [default->show_info] continue=false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Regex (FAIL) [show_info]
destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
=~ /^(sip:)?(9192+)(@172.16.0.216)?/
break=on-false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
parsing [default->transf_both_legs] continue=false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Regex (FAIL) [transf_both_legs]
destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
=~ /^transf_both_(.*)_(.*)_(.*)$/
break=on-false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
parsing [default->autenticado] continue=false
Dialplan:
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Regex (FAIL) [autenticado]
destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216)
=~ /^(sip:)?([a-z]([a-z0-9])+)(@172.16.0.216)?/
break=on-false
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:167
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
Change CS_ROUTING ->
CS_EXECUTE
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:470
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
ROUTING going to
sleep
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change
CS_EXECUTE
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:477
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
EXECUTE
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.487852 [DEBUG] mod_rtmp.c:215
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
CHANNEL EXECUTE
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:209
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Standard
EXECUTE
EXECUTE
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
export(RFC2822_DATE=Thu, 05 Dec 2013 11:23:20 -0300)
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:3364
(rtmp/default/sip:user1002 at 172.16.0.216) Callstate Change RINGING -> EARLY
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:1244 EXPORT
(export_vars) [RFC2822_DATE]=[Thu, 05 Dec 2013 11:23:20 -0300]
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=69
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:871 Send signal
rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_ivr_originate.c:1248 Raw Codec
Activation Success L16 at 16000hz 1 channel 20ms
2013-12-05 11:23:20.487852 [DEBUG] switch_core_codec.c:219
rtmp/default/sip:user1002 at 172.16.0.216 Push codec L16:70
2013-12-05 11:23:20.487852 [NOTICE] switch_core_state_machine.c:262
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
has executed the last dialplan instruction, hanging
up.
2013-12-05 11:23:20.487852 [NOTICE] switch_core_state_machine.c:264
Hangup
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[CS_EXECUTE]
[NORMAL_CLEARING]
2013-12-05 11:23:20.487852 [DEBUG] switch_ivr_originate.c:1316 Play
Ringback Tone [%(2000,4000,440,480)]
2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:3183 Send signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[KILL]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:477
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
EXECUTE going to
sleep
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change
CS_HANGUP
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:678
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
HANGUP
2013-12-05 11:23:20.487852 [DEBUG] mod_rtmp.c:273
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
CHANNEL HANGUP
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=71
2013-12-05 11:23:20.487852 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=78
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:48
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Standard HANGUP, cause:
NORMAL_CLEARING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:678
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
HANGUP going to
sleep
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:689
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Callstate
Change RINGING ->
HANGUP
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:446
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
Change CS_HANGUP ->
CS_REPORTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change
CS_REPORTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:761
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
REPORTING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:92
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Standard REPORTING, cause:
NORMAL_CLEARING
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:761
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
REPORTING going to
sleep
2013-12-05 11:23:20.487852 [DEBUG] switch_core_state_machine.c:440
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
Change CS_REPORTING ->
CS_DESTROY
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1351 Send
signal
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[BREAK]
2013-12-05 11:23:20.487852 [DEBUG] switch_core_session.c:1559 Session 57
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Locked,
Waiting on external
entities
2013-12-05 11:23:20.507798 [DEBUG] switch_core_codec.c:244
rtmp/default/sip:user1002 at 172.16.0.216 Restore previous codec SPEEX:99.
2013-12-05 11:23:20.507798 [DEBUG] switch_ivr_originate.c:3639 Originate
Resulted in Error Cause: 16 [NORMAL_CLEARING]
2013-12-05 11:23:20.507798 [INFO] mod_dptools.c:3201 Originate Failed.
Cause: NORMAL_CLEARING
2013-12-05 11:23:20.507798 [NOTICE] switch_channel.c:4643 Hangup
rtmp/default/sip:user1002 at 172.16.0.216 [CS_EXECUTE] [NORMAL_CLEARING]
2013-12-05 11:23:20.507798 [DEBUG] switch_channel.c:3183 Send signal
rtmp/default/sip:user1002 at 172.16.0.216 [KILL]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:2810
rtmp/default/sip:user1002 at 172.16.0.216 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup
already)
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:477
(rtmp/default/sip:user1002 at 172.16.0.216) State EXECUTE going to sleep
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_HANGUP
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:678
(rtmp/default/sip:user1002 at 172.16.0.216) State HANGUP
2013-12-05 11:23:20.507798 [DEBUG] mod_rtmp.c:273
rtmp/default/sip:user1002 at 172.16.0.216 CHANNEL HANGUP
2013-12-05 11:23:20.507798 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=24
2013-12-05 11:23:20.507798 [NOTICE] switch_core_session.c:1577 Session
57
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Ended
2013-12-05 11:23:20.507798 [NOTICE] switch_core_session.c:1581 Close
Channel
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
[CS_DESTROY]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:565
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Callstate
Change HANGUP ->
DOWN
2013-12-05 11:23:20.507798 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=69
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:568
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) Running
State Change CS_DESTROY
2013-12-05 11:23:20.507798 [DEBUG] rtmp.c:572 [amfnumber=3 type=0x14
stream_id=0x0] len=78
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:48
rtmp/default/sip:user1002 at 172.16.0.216 Standard HANGUP, cause:
NORMAL_CLEARING
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:678
(rtmp/default/sip:user1002 at 172.16.0.216) State HANGUP going to sleep
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:689
(rtmp/default/sip:user1002 at 172.16.0.216) Callstate Change EARLY -> HANGUP
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:578
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:99
rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216
Standard DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:578
(rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002 at 172.16.0.216) State
DESTROY going to sleep
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:446
(rtmp/default/sip:user1002 at 172.16.0.216) State Change CS_HANGUP ->
CS_REPORTING
2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:415
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_REPORTING
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:761
(rtmp/default/sip:user1002 at 172.16.0.216) State REPORTING
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:92
rtmp/default/sip:user1002 at 172.16.0.216 Standard REPORTING, cause:
NORMAL_CLEARING
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:761
(rtmp/default/sip:user1002 at 172.16.0.216) State REPORTING going to sleep
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:440
(rtmp/default/sip:user1002 at 172.16.0.216) State Change CS_REPORTING ->
CS_DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1351 Send
signal rtmp/default/sip:user1002 at 172.16.0.216 [BREAK]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1559 Session 56
(rtmp/default/sip:user1002 at 172.16.0.216) Locked, Waiting on external
entities
2013-12-05 11:23:20.507798 [NOTICE] switch_core_session.c:1577 Session
56 (rtmp/default/sip:user1002 at 172.16.0.216) Ended
2013-12-05 11:23:20.507798 [NOTICE] switch_core_session.c:1581 Close
Channel rtmp/default/sip:user1002 at 172.16.0.216 [CS_DESTROY]
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:565
(rtmp/default/sip:user1002 at 172.16.0.216) Callstate Change HANGUP -> DOWN
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:568
(rtmp/default/sip:user1002 at 172.16.0.216) Running State Change CS_DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:578
(rtmp/default/sip:user1002 at 172.16.0.216) State DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:99
rtmp/default/sip:user1002 at 172.16.0.216 Standard DESTROY
2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:578
(rtmp/default/sip:user1002 at 172.16.0.216) State DESTROY going to sleep
2013-12-05 11:23:20.747829 [DEBUG] rtmp.c:905 [chunk_stream=14 type=0x14
ts=76656 stream_id=0x12] len=24
2013-12-05 11:23:20.747829 [DEBUG] rtmp.c:171 [amfnumber=14] Got INVOKE
for closeStream
2013-12-05 11:23:20.747829 [DEBUG] rtmp.c:905 [chunk_stream=8 type=0x14
ts=76656 stream_id=0x11] len=24
2013-12-05 11:23:20.747829 [DEBUG] rtmp.c:171 [amfnumber=8] Got INVOKE
for closeStream
2013-12-05 11:23:20.807853 [DEBUG] rtmp.c:905 [chunk_stream=3 type=0x14
ts=76727 stream_id=0x0] len=34
2013-12-05 11:23:20.807853 [DEBUG] rtmp.c:171 [amfnumber=3] Got INVOKE
for deleteStream
2013-12-05 11:23:20.807853 [DEBUG] rtmp.c:905 [chunk_stream=3 type=0x14
ts=76727 stream_id=0x0] len=34
2013-12-05 11:23:20.807853 [DEBUG] rtmp.c:171 [amfnumber=3] Got INVOKE
for deleteStream
Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users
mailing list