First, you should not post issues on the list use JIRA http://jira.freeswitch.org Second, you should paste logs into the body of messages, attach them to the ticket or email. On Thu, Dec 5, 2013 at 9:01 AM, Germán Ruiz <chmp99@gmail.com> wrote:
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@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@172.16.0.216 in context default
Execute bride: EXECUTE rtmp/default/sip:user1002@172.16.0.216 bridge(user/user1002@172.16.0.216 ,rtmp/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@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@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@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@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@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@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@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@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@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@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@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@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@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@172.16.0.216 CHANNEL ROUTING 2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:117 rtmp/default/sip:user1002@172.16.0.216 Standard ROUTING 2013-12-05 11:23:20.418092 [INFO] mod_dialplan_xml.c:558 Processing <user1001>->sip:user1002@172.16.0.216 in context default Dialplan: rtmp/default/sip:user1002@172.16.0.216 parsing [default->global] continue=true Dialplan: rtmp/default/sip:user1002@172.16.0.216 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: rtmp/default/sip:user1002@172.16.0.216 Absolute Condition [global] Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: rtmp/default/sip:user1002@172.16.0.216 parsing [default->conferencias web] continue=false Dialplan: rtmp/default/sip:user1002@172.16.0.216 Regex (FAIL) [conferencias web] destination_number(sip:user1002@172.16.0.216) =~ /^(_conf_.*)$/ break=on-false
Dialplan: rtmp/default/sip:user1002@172.16.0.216 parsing [default->show_info] continue=false Dialplan: rtmp/default/sip:user1002@172.16.0.216 Regex (FAIL) [show_info] destination_number(sip:user1002@172.16.0.216) =~ /^(sip:)?(9192+)(@172.16.0.216)?/ break=on-false
Dialplan: rtmp/default/sip:user1002@172.16.0.216 parsing [default->transf_both_legs] continue=false Dialplan: rtmp/default/sip:user1002@172.16.0.216 Regex (FAIL) [transf_both_legs] destination_number(sip:user1002@172.16.0.216) =~ /^transf_both_(.*)_(.*)_(.*)$/ break=on-false
Dialplan: rtmp/default/sip:user1002@172.16.0.216 parsing [default->autenticado] continue=false Dialplan: rtmp/default/sip:user1002@172.16.0.216 Regex (PASS) [autenticado] destination_number(sip:user1002@172.16.0.216) =~ /^(sip:)?([a-z]([a-z0-9])+)(@172.16.0.216)?/ break=on-false
Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action export(dialed=user1002) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action export(processed=true) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action set(ringback=${us-ring}) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action set(call_timeout=30) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action set(hangup_after_bridge=true) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action set(fail_on_single_reject=false) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action set(ignore_early_media=true) Dialplan: rtmp/default/sip:user1002@172.16.0.216 Action info() Dialplan: rtmp/default/sip:user1002@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@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@172.16.0.216 [BREAK] 2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:470 (rtmp/default/sip:user1002@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@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@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@172.16.0.216 CHANNEL EXECUTE 2013-12-05 11:23:20.418092 [DEBUG] switch_core_state_machine.c:209 rtmp/default/sip:user1002@172.16.0.216 Standard EXECUTE EXECUTE rtmp/default/sip:user1002@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@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@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@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@172.16.0.216 SET [ringback]=[%(2000,4000,440,480)] EXECUTE rtmp/default/sip:user1002@172.16.0.216 set(call_timeout=30) 2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402 rtmp/default/sip:user1002@172.16.0.216 SET [call_timeout]=[30] EXECUTE rtmp/default/sip:user1002@172.16.0.216set(hangup_after_bridge=true) 2013-12-05 11:23:20.418092 [DEBUG] mod_dptools.c:1402 rtmp/default/sip:user1002@172.16.0.216 SET [hangup_after_bridge]=[true] EXECUTE rtmp/default/sip:user1002@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@172.16.0.216 SET [fail_on_single_reject]=[false] EXECUTE rtmp/default/sip:user1002@172.16.0.216set(ignore_early_media=true) 2013-12-05 11:23:20.447790 [DEBUG] mod_dptools.c:1402 rtmp/default/sip:user1002@172.16.0.216 SET [ignore_early_media]=[true] EXECUTE rtmp/default/sip:user1002@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@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@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@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@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@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@172.16.0.216 bridge(user/user1002@172.16.0.216 ,rtmp/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216) 2013-12-05 11:23:20.447790 [DEBUG] switch_channel.c:1198 rtmp/default/sip:user1002@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@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@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@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@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@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@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@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@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@172.16.0.216! 2013-12-05 11:23:20.487852 [DEBUG] switch_channel.c:3238 (rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@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@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@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@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@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@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@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@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@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@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@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@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@172.16.0.216 in context default
Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@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@172.16.0.216! Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Absolute Condition [global] Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 parsing [default->conferencias web] continue=false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Regex (FAIL) [conferencias web] destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/ user1002@172.16.0.216) =~ /^(_conf_.*)$/ break=on-false
Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 parsing [default->show_info] continue=false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Regex (FAIL) [show_info] destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/ user1002@172.16.0.216) =~ /^(sip:)?(9192+)(@172.16.0.216)?/ break=on-false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 parsing [default->transf_both_legs] continue=false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Regex (FAIL) [transf_both_legs] destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/ user1002@172.16.0.216) =~ /^transf_both_(.*)_(.*)_(.*)$/ break=on-false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 parsing [default->autenticado] continue=false Dialplan: rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@172.16.0.216 Regex (FAIL) [autenticado] destination_number(99e9f39c-5db8-11e3-8fd2-8518b7899937/ user1002@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@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@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@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@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@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@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@172.16.0.216 Standard EXECUTE
EXECUTE rtmp/default/99e9f39c-5db8-11e3-8fd2-8518b7899937/user1002@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@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@172.16.0.216 [BREAK] 2013-12-05 11:23:20.487852 [DEBUG] switch_ivr_originate.c:1248 Raw Codec Activation Success L16@16000hz 1 channel 20ms 2013-12-05 11:23:20.487852 [DEBUG] switch_core_codec.c:219 rtmp/default/sip:user1002@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@172.16.0.216 [KILL] 2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1351 Send signal rtmp/default/sip:user1002@172.16.0.216 [BREAK] 2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:2810 rtmp/default/sip:user1002@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@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@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@172.16.0.216) State HANGUP 2013-12-05 11:23:20.507798 [DEBUG] mod_rtmp.c:273 rtmp/default/sip:user1002@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@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@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@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@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@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@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@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@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@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@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@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@172.16.0.216 [BREAK] 2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:415 (rtmp/default/sip:user1002@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@172.16.0.216) State REPORTING 2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:92 rtmp/default/sip:user1002@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@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@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@172.16.0.216 [BREAK] 2013-12-05 11:23:20.507798 [DEBUG] switch_core_session.c:1559 Session 56 (rtmp/default/sip:user1002@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@172.16.0.216) Ended 2013-12-05 11:23:20.507798 [NOTICE] switch_core_session.c:1581 Close Channel rtmp/default/sip:user1002@172.16.0.216 [CS_DESTROY] 2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:565 (rtmp/default/sip:user1002@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@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@172.16.0.216) State DESTROY 2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:99 rtmp/default/sip:user1002@172.16.0.216 Standard DESTROY 2013-12-05 11:23:20.507798 [DEBUG] switch_core_state_machine.c:578 (rtmp/default/sip:user1002@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
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users 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 googletalk:conf+888@conference.freeswitch.org pstn:+19193869900