Problems with repetitive calls in rtmp
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.216 set(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.216 set(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
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
Anthony, Sorry, but I did not want to create a Jira issue if it was an already known situation or a configuration error. About the log, I included it in the mail to clarify my situation. Thanks. Germán
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 <mailto: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 (!)
...................
No biggie, Jira issues are not expensive and are just as easy to use as email. On Fri, Dec 6, 2013 at 1:34 PM, Germán Ruiz <chmp99@gmail.com> wrote:
Anthony, Sorry, but I did not want to create a Jira issue if it was an already known situation or a configuration error. About the log, I included it in the mail to clarify my situation.
Thanks. Germán
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 (!)
...................
_________________________________________________________________________ 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
participants (2)
-
Anthony Minessale
-
Germán Ruiz