[Freeswitch-users] mod_skypopen Refusing Skype Calls Once a Call is Answered Via a Desktop Skype Client
Giovanni Maruzzelli
gmaruzz at gmail.com
Tue Sep 28 11:48:43 PDT 2010
Please open a Jira on this one, and attach a complete debug session to
it (as a text file attachment).
-giovanni
On Tue, Sep 28, 2010 at 8:14 PM, Jason Jeffords <jason at cloudtree.net> wrote:
> We have found another failure case, this time without any extra Skype
> instances.
>
> 1) Call a Skype userid on FreeSWITCH which bridges to a SIP endpoint
> 2) Hang up the Skype Client before the far end answers
> 3) The far end will keep ringing for a while, wait until it finishes
> 4) Now call the same Skype userid on FreeSWITCH
> 5) Answer the far end - there is no audio
> 6) Hang up either end
> 7) Now call the same Skype userid on FreeSWITCH - This time the Skype
> client will be rejected
>
> That Skype instance is now broken no matter where you call it from
> until FreeSWITCH is restarted.
>
> This is exactly the same behavior as occurs with multiple Skype
> clients. The problem appears to be mod_skypopen is not handling
> hangups/cancels before the B leg answers.
>
> Jason
>
> On Tue, Sep 28, 2010 at 1:36 PM, Jason Jeffords <jason at cloudtree.net> wrote:
>> We are seeing a "STATUS FINISHED" indication from Skype when a call
>> is answered remotely. When this occurs, mod_skypopen says:
>>
>> 2010-09-28 17:22:55.741952 [DEBUG] skypopen_protocol.c:635 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 635
>> ][interface2][-1, 7, 0] skype_call 74 is NOT MY call, ignoring
>>
>> In this example (see below) call 74 is in progress and the SIP messages
>> are already sent. When the FINISHED indication is received, could the
>> call be canceled (e.g. this is equivalent to the Skype caller hanging up
>> on their end).
>>
>> Jason
>>
>> 2010-09-28 17:22:47.962165 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 0, 0] READING: |||CALL 74 CONF_ID 0|||
>> 2010-09-28 17:22:47.991943 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 0, 0] READING: |||CALL 74 STATUS RINGING|||
>> 2010-09-28 17:22:47.991943 [DEBUG] skypopen_protocol.c:579 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 579
>> ][interface2][-1, 0, 0] NO ACTIVE calls in this moment, skype_call 74
>> is RINGING, to ask PARTNER_DISPNAME and PARTNER_HANDLE
>> 2010-09-28 17:22:47.991943 [DEBUG] skypopen_protocol.c:1541 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>> ][interface2][-1, 0, 0] SENDING: |||GET CALL 74 PARTNER_DISPNAME||||
>> 2010-09-28 17:22:48.002019 [DEBUG] skypopen_protocol.c:1541 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>> ][interface2][-1, 0, 0] SENDING: |||GET CALL 74 PARTNER_HANDLE||||
>> 2010-09-28 17:22:48.041940 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 0, 0] READING: |||CALL 74 PARTNER_DISPNAME Thomas
>> Hazel|||
>> 2010-09-28 17:22:48.041940 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 0, 0] READING: |||CALL 74 PARTNER_HANDLE
>> stratusware|||
>> 2010-09-28 17:22:48.041940 [DEBUG] skypopen_protocol.c:496 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 496
>> ][interface2][-1, 0, 0] Call 74 go to skypopen_partner_handle_ring
>> 2010-09-28 17:22:48.041940 [DEBUG] mod_skypopen.c:2437 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2437
>> ][interface2][-1, 0, 0] NOT FOUND
>> 2010-09-28 17:22:48.041940 [DEBUG] mod_skypopen.c:2049 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2049
>> ][interface2][-1, 7, 0] 2 SESSION_REQUEST
>> 03aeed34-cb25-11df-a2b6-3dee1bbd18ba
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:272 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 272
>> ][interface2][-1, 7, 0] skypopen_tech_init SUCCESS
>> 2010-09-28 17:22:48.061934 [NOTICE] switch_channel.c:779 New Channel
>> skypopen/interface2 [03aeed34-cb25-11df-a2b6-3dee1bbd18ba]
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:2073
>> (skypopen/interface2) State Change CS_NEW -> CS_INIT
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_session.c:1039 Send
>> signal skypopen/interface2 [BREAK]
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:2085 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2085
>> ][interface2][-1, 7, 0] new_inbound_channel
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:314
>> (skypopen/interface2) Running State Change CS_INIT
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:338
>> (skypopen/interface2) State INIT
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:450
>> (skypopen/interface2) State Change CS_INIT -> CS_ROUTING
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_session.c:1039 Send
>> signal skypopen/interface2 [BREAK]
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:451 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 451
>> ][interface2][-1, 7, 0] interface2 CHANNEL INIT
>> 03aeed34-cb25-11df-a2b6-3dee1bbd18ba
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:338
>> (skypopen/interface2) State INIT going to sleep
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:314
>> (skypopen/interface2) Running State Change CS_ROUTING
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_channel.c:1512
>> (skypopen/interface2) Callstate Change DOWN -> RINGING
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:341
>> (skypopen/interface2) State ROUTING
>> 2010-09-28 17:22:48.061934 [DEBUG] mod_skypopen.c:568 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 568
>> ][interface2][-1, 7, 0] interface2 CHANNEL ROUTING
>> 2010-09-28 17:22:48.061934 [DEBUG] switch_core_state_machine.c:77
>> skypopen/interface2 Standard ROUTING
>> 2010-09-28 17:22:48.061934 [INFO] mod_dialplan_xml.c:331 Processing
>> Thomas Hazel <stratusware>->skype_inbound in context default
>> Dialplan: skypopen/interface2 parsing [default->SkypeInbound] continue=false
>> Dialplan: skypopen/interface2 Regex (PASS) [SkypeInbound]
>> destination_number(skype_inbound) =~ /^skype_inbound$/ break=on-false
>> Dialplan: skypopen/interface2 Action set(ignore_early_media=true)
>> Dialplan: skypopen/interface2 Action
>> set(toll_allow=domestic,international,local)
>> Dialplan: skypopen/interface2 Action set(default_gateway=bandwidth.com)
>> Dialplan: skypopen/interface2 Action
>> set(effective_caller_id_name=${skype_user})
>> Dialplan: skypopen/interface2 Action
>> set(effective_caller_id_number=+18574883540)
>> Dialplan: skypopen/interface2 Action
>> bridge(sofia/gateway/${default_gateway}/+16037141687)
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:119
>> (skypopen/interface2) State Change CS_ROUTING -> CS_EXECUTE
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_session.c:1039 Send
>> signal skypopen/interface2 [BREAK]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:341
>> (skypopen/interface2) State ROUTING going to sleep
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:314
>> (skypopen/interface2) Running State Change CS_EXECUTE
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:348
>> (skypopen/interface2) State EXECUTE
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:585 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 585
>> ][interface2][-1, 7, 0] interface2 CHANNEL EXECUTE
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:157
>> skypopen/interface2 Standard EXECUTE
>> EXECUTE skypopen/interface2 set(ignore_early_media=true)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_dptools.c:854
>> skypopen/interface2 SET [ignore_early_media]=[true]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=27
>> EXECUTE skypopen/interface2 set(toll_allow=domestic,international,local)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_dptools.c:854
>> skypopen/interface2 SET [toll_allow]=[domestic,international,local]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=27
>> EXECUTE skypopen/interface2 set(default_gateway=bandwidth.com)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_dptools.c:854
>> skypopen/interface2 SET [default_gateway]=[bandwidth.com]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=27
>> EXECUTE skypopen/interface2 set(effective_caller_id_name=ct-user4)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_dptools.c:854
>> skypopen/interface2 SET [effective_caller_id_name]=[ct-user4]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=27
>> EXECUTE skypopen/interface2 set(effective_caller_id_number=+18574883540)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_dptools.c:854
>> skypopen/interface2 SET [effective_caller_id_number]=[+18574883540]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=27
>> EXECUTE skypopen/interface2 bridge(sofia/gateway/bandwidth.com/+16037141687)
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_skypopen.c:1061 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>> ][interface2][-1, 7, 0] MSG_ID=26
>> 2010-09-28 17:22:48.091944 [NOTICE] switch_channel.c:779 New Channel
>> sofia/external/+16037141687 [03b7082a-cb25-11df-a2b8-3dee1bbd18ba]
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_sofia.c:3899
>> (sofia/external/+16037141687) State Change CS_NEW -> CS_INIT
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:314
>> (sofia/external/+16037141687) Running State Change CS_INIT
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:338
>> (sofia/external/+16037141687) State INIT
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_sofia.c:83
>> sofia/external/+16037141687 SOFIA INIT
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_sofia.c:119
>> (sofia/external/+16037141687) State Change CS_INIT -> CS_ROUTING
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:338
>> (sofia/external/+16037141687) State INIT going to sleep
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:314
>> (sofia/external/+16037141687) Running State Change CS_ROUTING
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_channel.c:1512
>> (sofia/external/+16037141687) Callstate Change DOWN -> RINGING
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:341
>> (sofia/external/+16037141687) State ROUTING
>> 2010-09-28 17:22:48.091944 [DEBUG] mod_sofia.c:142
>> sofia/external/+16037141687 SOFIA ROUTING
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_ivr_originate.c:66
>> (sofia/external/+16037141687) State Change CS_ROUTING ->
>> CS_CONSUME_MEDIA
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:341
>> (sofia/external/+16037141687) State ROUTING going to sleep
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:314
>> (sofia/external/+16037141687) Running State Change CS_CONSUME_MEDIA
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:360
>> (sofia/external/+16037141687) State CONSUME_MEDIA
>> 2010-09-28 17:22:48.091944 [DEBUG] switch_core_state_machine.c:360
>> (sofia/external/+16037141687) State CONSUME_MEDIA going to sleep
>> 2010-09-28 17:22:48.091944 [DEBUG] sofia.c:4399 Channel
>> sofia/external/+16037141687 entering state [calling][0]
>> 2010-09-28 17:22:49.701942 [INFO] sofia.c:703
>> sofia/external/+16037141687 Update Callee ID to "+16037141687"
>> <+16037141687>
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia.c:4399 Channel
>> sofia/external/+16037141687 entering state [proceeding][183]
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia.c:4410 Remote SDP:
>> v=0
>> o=- 1285694568 1285694569 IN IP4 209.247.5.148
>> s=-
>> c=IN IP4 209.247.5.148
>> t=0 0
>> m=audio 63944 RTP/AVP 0 101
>> a=rtpmap:101 telephone-event/8000
>> a=fmtp:101 0-16
>> a=ptime:20
>>
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia_glue.c:3851 Audio Codec
>> Compare [PCMU:0:8000:20]/[L16:10:16000:20]
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia_glue.c:3851 Audio Codec
>> Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia_glue.c:2446 Set Codec
>> sofia/external/+16037141687 PCMU/8000 20 ms 160 samples
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf
>> send payload to 101
>> 2010-09-28 17:22:49.701942 [DEBUG] sofia_glue.c:2686 AUDIO RTP
>> [sofia/external/+16037141687] 173.203.197.16 port 16694 ->
>> 209.247.5.148 port 63944 codec: 0 ms: 20
>> 2010-09-28 17:22:49.701942 [DEBUG] switch_rtp.c:1413 Starting timer
>> [soft] 160 bytes per 20ms
>> 2010-09-28 17:22:49.711951 [DEBUG] sofia_glue.c:2896 Set 2833 dtmf
>> send payload to 101
>> 2010-09-28 17:22:49.711951 [DEBUG] sofia_glue.c:2901 Set 2833 dtmf
>> receive payload to 101
>> 2010-09-28 17:22:49.711951 [NOTICE] sofia_glue.c:3294 Pre-Answer
>> sofia/external/+16037141687!
>> 2010-09-28 17:22:49.711951 [DEBUG] switch_channel.c:2409
>> (sofia/external/+16037141687) Callstate Change RINGING -> EARLY
>> 2010-09-28 17:22:49.711951 [DEBUG] switch_channel.c:2449 Send signal
>> skypopen/interface2 [BREAK]
>> 2010-09-28 17:22:49.711951 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:22:50.412029 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface3][-1, 0, 0] READING: |||USER cloud-tree-admin
>> NROF_AUTHED_BUDDIES 8|||
>> 2010-09-28 17:22:50.441981 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface3][-1, 0, 0] READING: |||USER cloud-tree-admin
>> NROF_AUTHED_BUDDIES 7|||
>> 2010-09-28 17:22:53.692056 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface3][-1, 0, 0] READING: |||USER ct-user4 TIMEZONE 72000|||
>> 2010-09-28 17:22:55.741952 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 7, 0] READING: |||CALL 74 STATUS FINISHED|||
>> 2010-09-28 17:22:55.741952 [DEBUG] skypopen_protocol.c:635 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 635
>> ][interface2][-1, 7, 0] skype_call 74 is NOT MY call, ignoring
>> 2010-09-28 17:23:15.982024 [DEBUG] sofia.c:4399 Channel
>> sofia/external/+16037141687 entering state [completing][200]
>> 2010-09-28 17:23:15.982024 [DEBUG] sofia.c:4407 Duplicate SDP
>> v=0
>> o=- 1285694568 1285694569 IN IP4 209.247.5.148
>> s=-
>> c=IN IP4 209.247.5.148
>> t=0 0
>> m=audio 63944 RTP/AVP 0 101
>> a=rtpmap:101 telephone-event/8000
>> a=fmtp:101 0-16
>> a=ptime:20
>>
>> 2010-09-28 17:23:15.992544 [DEBUG] sofia.c:4399 Channel
>> sofia/external/+16037141687 entering state [ready][200]
>> 2010-09-28 17:23:15.992544 [DEBUG] switch_channel.c:2555
>> (sofia/external/+16037141687) Callstate Change EARLY -> ACTIVE
>> 2010-09-28 17:23:15.992544 [DEBUG] switch_channel.c:2567 Send signal
>> skypopen/interface2 [BREAK]
>> 2010-09-28 17:23:15.992544 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:23:15.992544 [NOTICE] sofia.c:4908 Channel
>> [sofia/external/+16037141687] has been answered
>> 2010-09-28 17:23:15.992544 [DEBUG] mod_skypopen.c:985 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 985
>> ][interface2][-1, 7, 0] skypopen/interface2 CHANNEL got
>> SWITCH_MESSAGE_INDICATE_ANSWER
>> 2010-09-28 17:23:15.992544 [DEBUG] mod_skypopen.c:2546 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2546
>> ][interface2][-1, 7, 0] NOT FOUND
>> 2010-09-28 17:23:15.992544 [DEBUG] skypopen_protocol.c:1541 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>> ][interface2][-1,11, 0] SENDING: |||ALTER CALL 74 ANSWER||||
>> 2010-09-28 17:23:16.011969 [DEBUG] mod_skypopen.c:2556 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2556
>> ][interface2][-1,11, 0] We answered a Skype RING on skype_call 74
>> 2010-09-28 17:23:16.011969 [DEBUG] mod_skypopen.c:2564 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2564
>> ][interface2][-1,11, 0] NEW! name: interface2, state: 11,
>> value=stratusware, tech_pvt->callid_number=stratusware,
>> tech_pvt->skype_user=ct-user4
>> 2010-09-28 17:23:16.042127 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1,11, 0] READING: |||ERROR 559 CALL: Action failed|||
>> 2010-09-28 17:23:16.042127 [DEBUG] skypopen_protocol.c:236 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 236
>> ][interface2][-1,11, 0] Skype got ERROR about a failed action
>> (probably TRYING to ANSWER A CALL), let's go down: |||ERROR 559 CALL:
>> Action failed|||
>> 2010-09-28 17:23:16.042127 [DEBUG] skypopen_protocol.c:238 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 238
>> ][interface2][-1,11,16] skype_call now is DOWN
>> 2010-09-28 17:23:16.042127 [DEBUG] mod_skypopen.c:1271 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1271
>> ][interface2][-1, 1,16] skype call ended
>> 2010-09-28 17:23:16.042127 [DEBUG] switch_channel.c:2322
>> (skypopen/interface2) Callstate Change RINGING -> HANGUP
>> 2010-09-28 17:23:16.042127 [NOTICE] mod_skypopen.c:1282 Hangup
>> skypopen/interface2 [CS_EXECUTE] [NORMAL_CLEARING]
>> 2010-09-28 17:23:16.042127 [DEBUG] switch_channel.c:2338 Send signal
>> skypopen/interface2 [KILL]
>> 2010-09-28 17:23:16.042127 [DEBUG] mod_skypopen.c:606 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 606
>> ][interface2][-1, 1,16] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_KILL
>> 2010-09-28 17:23:16.042127 [DEBUG] skypopen_protocol.c:1541 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>> ][interface2][-1, 1,16] SENDING: |||ALTER CALL 74 END HANGUP||||
>> 2010-09-28 17:23:16.061968 [DEBUG] switch_core_session.c:1039 Send
>> signal skypopen/interface2 [BREAK]
>> 2010-09-28 17:23:16.061968 [DEBUG] mod_skypopen.c:627 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>> ][interface2][-1, 1,16] skypopen/interface2 CHANNEL got
>> SWITCH_SIG_BREAK
>> 2010-09-28 17:23:16.371973 [DEBUG] skypopen_protocol.c:189 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>> ][interface2][-1, 0, 0] READING: |||ERROR 559 CALL: Action failed|||
>> 2010-09-28 17:23:16.371973 [DEBUG] skypopen_protocol.c:245 rev
>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 245
>> ][interface2][-1, 0, 0] Skype got ERROR about a failed action
>> (probably TRYING to HANGUP A CALL), no problem: |||ERROR 559 CALL:
>> Action failed|||
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_channel.c:2322
>> (sofia/external/+16037141687) Callstate Change ACTIVE -> HANGUP
>> 2010-09-28 17:23:29.121962 [NOTICE] sofia.c:522 Hangup
>> sofia/external/+16037141687 [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_channel.c:2338 Send signal
>> sofia/external/+16037141687 [KILL]
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:314
>> (sofia/external/+16037141687) Running State Change CS_HANGUP
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:535
>> (sofia/external/+16037141687) State HANGUP
>> 2010-09-28 17:23:29.121962 [DEBUG] mod_sofia.c:447
>> sofia/external/+16037141687 Overriding SIP cause 480 with 200 from the
>> other leg
>> 2010-09-28 17:23:29.121962 [DEBUG] mod_sofia.c:453 Channel
>> sofia/external/+16037141687 hanging up, cause: NORMAL_CLEARING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:46
>> sofia/external/+16037141687 Standard HANGUP, cause: NORMAL_CLEARING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:535
>> (sofia/external/+16037141687) State HANGUP going to sleep
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:333
>> (sofia/external/+16037141687) State Change CS_HANGUP -> CS_REPORTING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:314
>> (sofia/external/+16037141687) Running State Change CS_REPORTING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:595
>> (sofia/external/+16037141687) State REPORTING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:53
>> sofia/external/+16037141687 Standard REPORTING, cause: NORMAL_CLEARING
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:595
>> (sofia/external/+16037141687) State REPORTING going to sleep
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_state_machine.c:327
>> (sofia/external/+16037141687) State Change CS_REPORTING -> CS_DESTROY
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_session.c:1039 Send
>> signal sofia/external/+16037141687 [BREAK]
>> 2010-09-28 17:23:29.121962 [DEBUG] switch_core_session.c:1202 Session
>> 24 (sofia/external/+16037141687) Locked, Waiting on external entities
>>
>>
>>
>> On Tue, Sep 28, 2010 at 12:01 PM, Giovanni Maruzzelli <gmaruzz at gmail.com> wrote:
>>> On Tue, Sep 28, 2010 at 5:26 PM, Jason Jeffords <jason at cloudtree.net> wrote:
>>>> We did not realize this case is not supported, and it does indeed
>>>> break mod_skypopen
>>>> (specifically, it looks like mod_skypopen is ignoring the "answered"
>>>> message from
>>>> the Skype client indicating another client answered the call).
>>>>
>>>> Is there any way we could add this support?
>>>
>>> Only modifiying the mod_skypopen sources, and I'm not sure it's
>>> feasible at all (ie: if the external skype clients notify the FS skype
>>> clients they've answered), but maybe yes.
>>>
>>> -giovanni
>>>
>>>>
>>>> Thanks in advance,
>>>>
>>>> Jason
>>>>
>>>> PS> Our use case is to have multiple instances with the same user ID on multiple
>>>> servers and desktop clients. So this is a show stopper for us.
>>>>
>>>> On Tue, Sep 28, 2010 at 11:08 AM, Giovanni Maruzzelli <gmaruzz at gmail.com> wrote:
>>>>> Hi Jason,
>>>>>
>>>>> Maybe I've not understood, so I ask explicitly: you have the same
>>>>> skypeuserid running on the freeswitch server AND on the desktops?
>>>>>
>>>>> This is not supported, and will break the inner working of mod_skypopen.
>>>>>
>>>>> -giovanni
>>>>>
>>>>> On Tue, Sep 28, 2010 at 4:47 PM, Jason Jeffords <jason at cloudtree.net> wrote:
>>>>>> 1) Call a Skype user on Freeswitch which then bridges to
>>>>>> 1 or more SIP endpoints - this will simultaneous ring SIP
>>>>>> and any desktop Skype instances you have open - it works
>>>>>> every time as long as you answer the SIP endpoints
>>>>>>
>>>>>> 2) Answer the call with one of your desktop Skype instances
>>>>>>
>>>>>> 3) Call a Skype user again as in step 1 - this will now fail on both
>>>>>> FreeSWITCH and your desktop clients
>>>>>>
>>>>>> mod_skypopen/FreeSWITCH is rejecting all subsequent calls,
>>>>>> which forces a reject on the Skype network as well. It appears
>>>>>> the call answering by the desktop Skype instance is not
>>>>>> handled by mod_skypopen (it should probably cancel the
>>>>>> outbound call request when it sees an external answer,
>>>>>> perhaps by hangup?).
>>>>>>
>>>>>> The only way to fix the problem is a complete restart of the
>>>>>> Skype instances on FreeSWITCH and FreeSWITCH itself.
>>>>>>
>>>>>> I have included a small portion of the failing log below (once
>>>>>> mod_skypopen/FreeSWITCH system is wedged).
>>>>>>
>>>>>> Any help would be greatly appreciated.
>>>>>>
>>>>>> Thanks in advance,
>>>>>>
>>>>>> Jason
>>>>>>
>>>>>> 2010-09-28 14:38:14.797954 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 0, 0] READING: |||CALL 227 CONF_ID 0|||
>>>>>> 2010-09-28 14:38:14.867970 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 0, 0] READING: |||CALL 227 STATUS RINGING|||
>>>>>> 2010-09-28 14:38:14.867970 [DEBUG] skypopen_protocol.c:579 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 579
>>>>>> ][interface4][-1, 0, 0] NO ACTIVE calls in this moment, skype_call 227
>>>>>> is RINGING, to ask PARTNER_DISPNAME and PARTNER_HANDLE
>>>>>> 2010-09-28 14:38:14.867970 [DEBUG] skypopen_protocol.c:1541 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>>>>>> ][interface4][-1, 0, 0] SENDING: |||GET CALL 227 PARTNER_DISPNAME||||
>>>>>> 2010-09-28 14:38:14.917964 [DEBUG] skypopen_protocol.c:1541 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>>>>>> ][interface4][-1, 0, 0] SENDING: |||GET CALL 227 PARTNER_HANDLE||||
>>>>>> 2010-09-28 14:38:15.247962 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 0, 0] READING: |||CALL 227 PARTNER_DISPNAME Thomas
>>>>>> Hazel|||
>>>>>> 2010-09-28 14:38:15.277958 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 0, 0] READING: |||CALL 227 PARTNER_HANDLE
>>>>>> stratusware|||
>>>>>> 2010-09-28 14:38:15.277958 [DEBUG] skypopen_protocol.c:496 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 496
>>>>>> ][interface4][-1, 0, 0] Call 227 go to skypopen_partner_handle_ring
>>>>>> 2010-09-28 14:38:15.707985 [DEBUG] mod_skypopen.c:2437 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2437
>>>>>> ][interface4][-1, 0, 0] NOT FOUND
>>>>>> 2010-09-28 14:38:15.838037 [DEBUG] mod_skypopen.c:2049 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2049
>>>>>> ][interface4][-1, 7, 0] 2 SESSION_REQUEST
>>>>>> 07602acc-cb0e-11df-ada1-018a94d3f22d
>>>>>> 2010-09-28 14:38:15.898008 [DEBUG] mod_skypopen.c:272 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 272
>>>>>> ][interface4][-1, 7, 0] skypopen_tech_init SUCCESS
>>>>>> 2010-09-28 14:38:15.898008 [NOTICE] switch_channel.c:779 New Channel
>>>>>> skypopen/interface4 [07602acc-cb0e-11df-ada1-018a94d3f22d]
>>>>>> 2010-09-28 14:38:15.898008 [DEBUG] mod_skypopen.c:2073
>>>>>> (skypopen/interface4) State Change CS_NEW -> CS_INIT
>>>>>> 2010-09-28 14:38:15.898008 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:15.898008 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] mod_skypopen.c:2085 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2085
>>>>>> ][interface4][-1, 7, 0] new_inbound_channel
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_core_state_machine.c:314
>>>>>> (skypopen/interface4) Running State Change CS_INIT
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_core_state_machine.c:338
>>>>>> (skypopen/interface4) State INIT
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] mod_skypopen.c:450
>>>>>> (skypopen/interface4) State Change CS_INIT -> CS_ROUTING
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] mod_skypopen.c:451 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 451
>>>>>> ][interface4][-1, 7, 0] interface4 CHANNEL INIT
>>>>>> 07602acc-cb0e-11df-ada1-018a94d3f22d
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_core_state_machine.c:338
>>>>>> (skypopen/interface4) State INIT going to sleep
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_core_state_machine.c:314
>>>>>> (skypopen/interface4) Running State Change CS_ROUTING
>>>>>> 2010-09-28 14:38:15.937986 [DEBUG] switch_channel.c:1512
>>>>>> (skypopen/interface4) Callstate Change DOWN -> RINGING
>>>>>> 2010-09-28 14:38:15.947959 [DEBUG] switch_core_state_machine.c:341
>>>>>> (skypopen/interface4) State ROUTING
>>>>>> 2010-09-28 14:38:15.967968 [DEBUG] mod_skypopen.c:568 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 568
>>>>>> ][interface4][-1, 7, 0] interface4 CHANNEL ROUTING
>>>>>> 2010-09-28 14:38:15.967968 [DEBUG] switch_core_state_machine.c:77
>>>>>> skypopen/interface4 Standard ROUTING
>>>>>> 2010-09-28 14:38:15.947959 [DEBUG] mod_skypopen.c:942 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 942
>>>>>> ][interface4][-1, 7, 0] interface4 CHANNEL ANSWER
>>>>>> bb88b0c2-cb0a-11df-ad99-018a94d3f22d
>>>>>> 2010-09-28 14:38:15.977964 [DEBUG] mod_skypopen.c:947 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 947
>>>>>> ][interface4][-1, 7, 0] ANSWERED!
>>>>>> 2010-09-28 14:38:15.977964 [DEBUG] mod_skypopen.c:1008 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1008
>>>>>> ][interface4][-1, 7, 0] Synching audio
>>>>>> 2010-09-28 14:38:15.997965 [DEBUG] switch_core_session.c:658 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:15.997965 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:15.997965 [DEBUG] switch_channel.c:2555
>>>>>> (skypopen/interface4) Callstate Change RINGING -> ACTIVE
>>>>>> 2010-09-28 14:38:16.007958 [INFO] mod_dialplan_xml.c:331 Processing
>>>>>> Thomas Hazel <stratusware>->skype_inbound in context default
>>>>>> 2010-09-28 14:38:16.048001 [NOTICE] switch_ivr_originate.c:3315
>>>>>> Channel [skypopen/interface4] has been answered
>>>>>> 2010-09-28 14:38:16.048001 [DEBUG] mod_skypopen.c:1014 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1014
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
>>>>>> 2010-09-28 14:38:16.048001 [DEBUG] mod_skypopen.c:1033 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1033
>>>>>> ][interface4][-1, 7, 0] Synching audio
>>>>>> 2010-09-28 14:38:16.097966 [DEBUG] switch_ivr_originate.c:3360
>>>>>> Originate Resulted in Success: [sofia/external/+16037141687]
>>>>>> 2010-09-28 14:38:16.179398 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface1][-1, 0, 0] READING: |||USER ct-user2 NROF_AUTHED_BUDDIES
>>>>>> 3|||
>>>>>> 2010-09-28 14:38:16.187965 [DEBUG] mod_skypopen.c:1014 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1014
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
>>>>>> 2010-09-28 14:38:16.187965 [DEBUG] mod_skypopen.c:1033 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1033
>>>>>> ][interface4][-1, 7, 0] Synching audio
>>>>>> 2010-09-28 14:38:16.297970 [WARNING] switch_ivr_bridge.c:1241 Bridge
>>>>>> Failed skypopen/interface4->sofia/external/+16037141687
>>>>>> 2010-09-28 14:38:16.337946 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 7, 0] MSG_ID=5
>>>>>> 2010-09-28 14:38:16.337946 [DEBUG] switch_core_session.c:658 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:16.337946 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:16.347942 [DEBUG] switch_channel.c:2322
>>>>>> (skypopen/interface4) Callstate Change ACTIVE -> HANGUP
>>>>>> 2010-09-28 14:38:16.358103 [NOTICE] switch_ivr_bridge.c:1280 Hangup
>>>>>> skypopen/interface4 [CS_EXECUTE] [NORMAL_CLEARING]
>>>>>> 2010-09-28 14:38:16.358103 [DEBUG] switch_channel.c:2338 Send signal
>>>>>> skypopen/interface4 [KILL]
>>>>>> 2010-09-28 14:38:16.358103 [DEBUG] mod_skypopen.c:606 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 606
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_KILL
>>>>>> 2010-09-28 14:38:16.358103 [DEBUG] skypopen_protocol.c:1541 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>>>>>> ][interface4][-1, 7, 0] SENDING: |||ALTER CALL 227 END HANGUP||||
>>>>>> 2010-09-28 14:38:16.377945 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:16.377945 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 7, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:16.377945 [NOTICE] switch_core_session.c:1220 Session
>>>>>> 18 (sofia/external/+16037141687) Ended
>>>>>> 2010-09-28 14:38:16.377945 [NOTICE] switch_core_session.c:1222 Close
>>>>>> Channel sofia/external/+16037141687 [CS_DESTROY]
>>>>>> 2010-09-28 14:38:16.387943 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 7, 0] READING: |||ALTER CALL 227 END HANGUP|||
>>>>>> 2010-09-28 14:38:16.387943 [DEBUG] switch_core_session.c:1909
>>>>>> skypopen/interface4 skip receive message [APPLICATION_EXEC_COMPLETE]
>>>>>> (channel is hungup already)
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:427
>>>>>> (sofia/external/+16037141687) Callstate Change HANGUP -> DOWN
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:348
>>>>>> (skypopen/interface4) State EXECUTE going to sleep
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:314
>>>>>> (skypopen/interface4) Running State Change CS_HANGUP
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:535
>>>>>> (skypopen/interface4) State HANGUP
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] mod_skypopen.c:541 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 541
>>>>>> ][interface4][-1,10, 0] interface4 CHANNEL HANGUP
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:46
>>>>>> skypopen/interface4 Standard HANGUP, cause: NORMAL_CLEARING
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:535
>>>>>> (skypopen/interface4) State HANGUP going to sleep
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:333
>>>>>> (skypopen/interface4) State Change CS_HANGUP -> CS_REPORTING
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:314
>>>>>> (skypopen/interface4) Running State Change CS_REPORTING
>>>>>> 2010-09-28 14:38:16.428193 [DEBUG] switch_core_state_machine.c:595
>>>>>> (skypopen/interface4) State REPORTING
>>>>>> 2010-09-28 14:38:16.507974 [DEBUG] switch_core_state_machine.c:53
>>>>>> skypopen/interface4 Standard REPORTING, cause: NORMAL_CLEARING
>>>>>> 2010-09-28 14:38:16.507974 [DEBUG] switch_core_state_machine.c:595
>>>>>> (skypopen/interface4) State REPORTING going to sleep
>>>>>> 2010-09-28 14:38:16.507974 [DEBUG] switch_core_state_machine.c:327
>>>>>> (skypopen/interface4) State Change CS_REPORTING -> CS_DESTROY
>>>>>> 2010-09-28 14:38:16.507974 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:16.507974 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:16.517965 [DEBUG] switch_core_session.c:1202 Session
>>>>>> 17 (skypopen/interface4) Locked, Waiting on external entities
>>>>>> 2010-09-28 14:38:16.517965 [NOTICE] switch_core_session.c:1220 Session
>>>>>> 17 (skypopen/interface4) Ended
>>>>>> 2010-09-28 14:38:16.517965 [NOTICE] switch_core_session.c:1222 Close
>>>>>> Channel skypopen/interface4 [CS_DESTROY]
>>>>>> 2010-09-28 14:38:16.517965 [DEBUG] switch_core_state_machine.c:427
>>>>>> (skypopen/interface4) Callstate Change HANGUP -> DOWN
>>>>>> 2010-09-28 14:38:16.517965 [DEBUG] switch_core_state_machine.c:430
>>>>>> (skypopen/interface4) Running State Change CS_DESTROY
>>>>>> 2010-09-28 14:38:16.517965 [DEBUG] switch_core_state_machine.c:440
>>>>>> (skypopen/interface4) State DESTROY
>>>>>> 2010-09-28 14:38:16.517965 [DEBUG] mod_skypopen.c:464 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 464
>>>>>> ][interface4][-1, 0, 0] interface4 CHANNEL DESTROY
>>>>>> bb88b0c2-cb0a-11df-ad99-018a94d3f22d
>>>>>> 2010-09-28 14:38:16.547962 [DEBUG] switch_core_state_machine.c:60
>>>>>> skypopen/interface4 Standard DESTROY
>>>>>> 2010-09-28 14:38:16.547962 [DEBUG] switch_core_state_machine.c:440
>>>>>> (skypopen/interface4) State DESTROY going to sleep
>>>>>> 2010-09-28 14:38:16.577977 [DEBUG] switch_core_state_machine.c:430
>>>>>> (sofia/external/+16037141687) Running State Change CS_DESTROY
>>>>>> 2010-09-28 14:38:16.597962 [DEBUG] switch_core_state_machine.c:440
>>>>>> (sofia/external/+16037141687) State DESTROY
>>>>>> 2010-09-28 14:38:16.597962 [DEBUG] mod_sofia.c:358
>>>>>> sofia/external/+16037141687 SOFIA DESTROY
>>>>>> 2010-09-28 14:38:16.637965 [DEBUG] switch_core_state_machine.c:60
>>>>>> sofia/external/+16037141687 Standard DESTROY
>>>>>> 2010-09-28 14:38:16.637965 [DEBUG] switch_core_state_machine.c:440
>>>>>> (sofia/external/+16037141687) State DESTROY going to sleep
>>>>>> 2010-09-28 14:38:17.381259 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1, 0, 0] READING: |||CALL 227 STATUS REFUSED|||
>>>>>> 2010-09-28 14:38:17.390474 [DEBUG] skypopen_protocol.c:666 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 666
>>>>>> ][interface4][-1, 0, 0] we REFUSED skype_call 227
>>>>>> Dialplan: skypopen/interface4 parsing [default->SkypeInbound] continue=false
>>>>>> Dialplan: skypopen/interface4 Regex (PASS) [SkypeInbound]
>>>>>> destination_number(skype_inbound) =~ /^skype_inbound$/ break=on-false
>>>>>> Dialplan: skypopen/interface4 Action set(ignore_early_media=true)
>>>>>> Dialplan: skypopen/interface4 Action
>>>>>> set(toll_allow=domestic,international,local)
>>>>>> Dialplan: skypopen/interface4 Action set(default_gateway=bandwidth.com)
>>>>>> Dialplan: skypopen/interface4 Action set(effective_caller_id_name=Thomas Hazel)
>>>>>> Dialplan: skypopen/interface4 Action
>>>>>> set(effective_caller_id_number=+16174190921)
>>>>>> Dialplan: skypopen/interface4 Action ring_ready()
>>>>>> Dialplan: skypopen/interface4 Action set(hangup_after_bridge=true)
>>>>>> Dialplan: skypopen/interface4 Action
>>>>>> bridge(sofia/gateway/${default_gateway}/+16037141687)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_state_machine.c:119
>>>>>> (skypopen/interface4) State Change CS_ROUTING -> CS_EXECUTE
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_state_machine.c:341
>>>>>> (skypopen/interface4) State ROUTING going to sleep
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_state_machine.c:314
>>>>>> (skypopen/interface4) Running State Change CS_EXECUTE
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_state_machine.c:348
>>>>>> (skypopen/interface4) State EXECUTE
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:585 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 585
>>>>>> ][interface4][-1, 0, 0] interface4 CHANNEL EXECUTE
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] switch_core_state_machine.c:157
>>>>>> skypopen/interface4 Standard EXECUTE
>>>>>> EXECUTE skypopen/interface4 set(ignore_early_media=true)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [ignore_early_media]=[true]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 set(toll_allow=domestic,international,local)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [toll_allow]=[domestic,international,local]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 set(default_gateway=bandwidth.com)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [default_gateway]=[bandwidth.com]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 set(effective_caller_id_name=Thomas Hazel)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [effective_caller_id_name]=[Thomas Hazel]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 set(effective_caller_id_number=+16174190921)
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [effective_caller_id_number]=[+16174190921]
>>>>>> 2010-09-28 14:38:17.967960 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 ring_ready()
>>>>>> 2010-09-28 14:38:18.007957 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:18.007957 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=7
>>>>>> 2010-09-28 14:38:18.007957 [DEBUG] switch_core_session.c:658 Send
>>>>>> signal skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:18.007957 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:18.007957 [NOTICE] mod_dptools.c:514 Ring Ready
>>>>>> skypopen/interface4!
>>>>>> 2010-09-28 14:38:18.007957 [NOTICE] mod_dptools.c:514 Ring-Ready
>>>>>> skypopen/interface4!
>>>>>> 2010-09-28 14:38:18.037964 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 set(hangup_after_bridge=true)
>>>>>> 2010-09-28 14:38:18.047977 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:18.047977 [DEBUG] mod_dptools.c:854
>>>>>> skypopen/interface4 SET [hangup_after_bridge]=[true]
>>>>>> 2010-09-28 14:38:18.069062 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=27
>>>>>> EXECUTE skypopen/interface4 bridge(sofia/gateway/bandwidth.com/+16037141687)
>>>>>> 2010-09-28 14:38:18.069062 [DEBUG] mod_skypopen.c:1061 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1061
>>>>>> ][interface4][-1, 0, 0] MSG_ID=26
>>>>>> 2010-09-28 14:38:18.117977 [NOTICE] switch_channel.c:779 New Channel
>>>>>> sofia/external/+16037141687 [08bcfb02-cb0e-11df-ada3-018a94d3f22d]
>>>>>> 2010-09-28 14:38:18.137885 [DEBUG] mod_sofia.c:3899
>>>>>> (sofia/external/+16037141687) State Change CS_NEW -> CS_INIT
>>>>>> 2010-09-28 14:38:18.137885 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:18.147956 [DEBUG] switch_core_state_machine.c:314
>>>>>> (sofia/external/+16037141687) Running State Change CS_INIT
>>>>>> 2010-09-28 14:38:18.147956 [DEBUG] switch_core_state_machine.c:338
>>>>>> (sofia/external/+16037141687) State INIT
>>>>>> 2010-09-28 14:38:18.147956 [DEBUG] mod_sofia.c:83
>>>>>> sofia/external/+16037141687 SOFIA INIT
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] mod_sofia.c:119
>>>>>> (sofia/external/+16037141687) State Change CS_INIT -> CS_ROUTING
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:338
>>>>>> (sofia/external/+16037141687) State INIT going to sleep
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:314
>>>>>> (sofia/external/+16037141687) Running State Change CS_ROUTING
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_channel.c:1512
>>>>>> (sofia/external/+16037141687) Callstate Change DOWN -> RINGING
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:341
>>>>>> (sofia/external/+16037141687) State ROUTING
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] mod_sofia.c:142
>>>>>> sofia/external/+16037141687 SOFIA ROUTING
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_ivr_originate.c:66
>>>>>> (sofia/external/+16037141687) State Change CS_ROUTING ->
>>>>>> CS_CONSUME_MEDIA
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:341
>>>>>> (sofia/external/+16037141687) State ROUTING going to sleep
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:314
>>>>>> (sofia/external/+16037141687) Running State Change CS_CONSUME_MEDIA
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:360
>>>>>> (sofia/external/+16037141687) State CONSUME_MEDIA
>>>>>> 2010-09-28 14:38:18.267973 [DEBUG] switch_core_state_machine.c:360
>>>>>> (sofia/external/+16037141687) State CONSUME_MEDIA going to sleep
>>>>>> 2010-09-28 14:38:18.347964 [DEBUG] sofia.c:4399 Channel
>>>>>> sofia/external/+16037141687 entering state [calling][0]
>>>>>> 2010-09-28 14:38:20.068043 [INFO] sofia.c:703
>>>>>> sofia/external/+16037141687 Update Callee ID to "+16037141687"
>>>>>> <+16037141687>
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia.c:4399 Channel
>>>>>> sofia/external/+16037141687 entering state [proceeding][183]
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia.c:4410 Remote SDP:
>>>>>> v=0
>>>>>> o=- 1285684698 1285684699 IN IP4 63.215.27.71
>>>>>> s=-
>>>>>> c=IN IP4 63.215.27.71
>>>>>> t=0 0
>>>>>> m=audio 64508 RTP/AVP 0 101
>>>>>> a=rtpmap:101 telephone-event/8000
>>>>>> a=fmtp:101 0-16
>>>>>> a=ptime:20
>>>>>>
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia_glue.c:3851 Audio Codec
>>>>>> Compare [PCMU:0:8000:20]/[PCMU:0:8000:20]
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia_glue.c:2446 Set Codec
>>>>>> sofia/external/+16037141687 PCMU/8000 20 ms 160 samples
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf
>>>>>> send payload to 101
>>>>>> 2010-09-28 14:38:20.068043 [DEBUG] sofia_glue.c:2686 AUDIO RTP
>>>>>> [sofia/external/+16037141687] 173.203.197.16 port 29798 ->
>>>>>> 63.215.27.71 port 64508 codec: 0 ms: 20
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] switch_rtp.c:1413 Starting timer
>>>>>> [soft] 160 bytes per 20ms
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] sofia_glue.c:2896 Set 2833 dtmf
>>>>>> send payload to 101
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] sofia_glue.c:2901 Set 2833 dtmf
>>>>>> receive payload to 101
>>>>>> 2010-09-28 14:38:20.147938 [NOTICE] sofia_glue.c:3294 Pre-Answer
>>>>>> sofia/external/+16037141687!
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] switch_channel.c:2409
>>>>>> (sofia/external/+16037141687) Callstate Change RINGING -> EARLY
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] switch_channel.c:2449 Send signal
>>>>>> skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:20.147938 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:40.417986 [DEBUG] sofia.c:4399 Channel
>>>>>> sofia/external/+16037141687 entering state [completing][200]
>>>>>> 2010-09-28 14:38:40.417986 [DEBUG] sofia.c:4407 Duplicate SDP
>>>>>> v=0
>>>>>> o=- 1285684698 1285684699 IN IP4 63.215.27.71
>>>>>> s=-
>>>>>> c=IN IP4 63.215.27.71
>>>>>> t=0 0
>>>>>> m=audio 64508 RTP/AVP 0 101
>>>>>> a=rtpmap:101 telephone-event/8000
>>>>>> a=fmtp:101 0-16
>>>>>> a=ptime:20
>>>>>>
>>>>>> 2010-09-28 14:38:40.417986 [DEBUG] sofia.c:4399 Channel
>>>>>> sofia/external/+16037141687 entering state [ready][200]
>>>>>> 2010-09-28 14:38:40.417986 [DEBUG] switch_channel.c:2555
>>>>>> (sofia/external/+16037141687) Callstate Change EARLY -> ACTIVE
>>>>>> 2010-09-28 14:38:40.417986 [DEBUG] switch_channel.c:2567 Send signal
>>>>>> skypopen/interface4 [BREAK]
>>>>>> 2010-09-28 14:38:40.437977 [DEBUG] mod_skypopen.c:627 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 627
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_SIG_BREAK
>>>>>> 2010-09-28 14:38:40.437977 [NOTICE] sofia.c:4908 Channel
>>>>>> [sofia/external/+16037141687] has been answered
>>>>>> 2010-09-28 14:38:40.437977 [DEBUG] mod_skypopen.c:985 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 985
>>>>>> ][interface4][-1, 0, 0] skypopen/interface4 CHANNEL got
>>>>>> SWITCH_MESSAGE_INDICATE_ANSWER
>>>>>> 2010-09-28 14:38:40.458166 [DEBUG] mod_skypopen.c:2546 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2546
>>>>>> ][interface4][-1, 0, 0] NOT FOUND
>>>>>> 2010-09-28 14:38:40.458166 [DEBUG] skypopen_protocol.c:1541 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1541
>>>>>> ][interface4][-1,11, 0] SENDING: |||ALTER CALL 227 ANSWER||||
>>>>>> 2010-09-28 14:38:40.467976 [DEBUG] mod_skypopen.c:2556 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2556
>>>>>> ][interface4][-1,11, 0] We answered a Skype RING on skype_call 227
>>>>>> 2010-09-28 14:38:40.467976 [DEBUG] mod_skypopen.c:2564 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 2564
>>>>>> ][interface4][-1,11, 0] NEW! name: interface4, state: 11,
>>>>>> value=stratusware, tech_pvt->callid_number=stratusware,
>>>>>> tech_pvt->skype_user=jjeffords.com
>>>>>> 2010-09-28 14:38:40.487975 [DEBUG] skypopen_protocol.c:189 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 189
>>>>>> ][interface4][-1,11, 0] READING: |||ERROR 559 CALL: Action failed|||
>>>>>> 2010-09-28 14:38:40.487975 [DEBUG] skypopen_protocol.c:236 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 236
>>>>>> ][interface4][-1,11, 0] Skype got ERROR about a failed action
>>>>>> (probably TRYING to ANSWER A CALL), let's go down: |||ERROR 559 CALL:
>>>>>> Action failed|||
>>>>>> 2010-09-28 14:38:40.487975 [DEBUG] skypopen_protocol.c:238 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 238
>>>>>> ][interface4][-1,11,16] skype_call now is DOWN
>>>>>> 2010-09-28 14:38:40.487975 [DEBUG] mod_skypopen.c:1271 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1271
>>>>>> ][interface4][-1, 1,16] skype call ended
>>>>>> 2010-09-28 14:38:40.487975 [DEBUG] mod_skypopen.c:1288 rev
>>>>>> git2svn-syncpoint-master-372-gce352bc[(nil)|37 ][DEBUG_SKYPE 1288
>>>>>> ][interface4][-1, 1,16] no session
>>>>>> 2010-09-28 14:38:47.227969 [DEBUG] switch_channel.c:2322
>>>>>> (sofia/external/+16037141687) Callstate Change ACTIVE -> HANGUP
>>>>>> 2010-09-28 14:38:47.227969 [NOTICE] sofia.c:522 Hangup
>>>>>> sofia/external/+16037141687 [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
>>>>>> 2010-09-28 14:38:47.227969 [DEBUG] switch_channel.c:2338 Send signal
>>>>>> sofia/external/+16037141687 [KILL]
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:314
>>>>>> (sofia/external/+16037141687) Running State Change CS_HANGUP
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:535
>>>>>> (sofia/external/+16037141687) State HANGUP
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] mod_sofia.c:447
>>>>>> sofia/external/+16037141687 Overriding SIP cause 480 with 200 from the
>>>>>> other leg
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] mod_sofia.c:453 Channel
>>>>>> sofia/external/+16037141687 hanging up, cause: NORMAL_CLEARING
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:46
>>>>>> sofia/external/+16037141687 Standard HANGUP, cause: NORMAL_CLEARING
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:535
>>>>>> (sofia/external/+16037141687) State HANGUP going to sleep
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:333
>>>>>> (sofia/external/+16037141687) State Change CS_HANGUP -> CS_REPORTING
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:314
>>>>>> (sofia/external/+16037141687) Running State Change CS_REPORTING
>>>>>> 2010-09-28 14:38:47.238185 [DEBUG] switch_core_state_machine.c:595
>>>>>> (sofia/external/+16037141687) State REPORTING
>>>>>> 2010-09-28 14:38:47.258201 [DEBUG] switch_core_state_machine.c:53
>>>>>> sofia/external/+16037141687 Standard REPORTING, cause: NORMAL_CLEARING
>>>>>> 2010-09-28 14:38:47.258201 [DEBUG] switch_core_state_machine.c:595
>>>>>> (sofia/external/+16037141687) State REPORTING going to sleep
>>>>>> 2010-09-28 14:38:47.258201 [DEBUG] switch_core_state_machine.c:327
>>>>>> (sofia/external/+16037141687) State Change CS_REPORTING -> CS_DESTROY
>>>>>> 2010-09-28 14:38:47.258201 [DEBUG] switch_core_session.c:1039 Send
>>>>>> signal sofia/external/+16037141687 [BREAK]
>>>>>> 2010-09-28 14:38:47.258201 [DEBUG] switch_core_session.c:1202 Session
>>>>>> 20 (sofia/external/+16037141687) Locked, Waiting on external entities
>>>>>>
>>>>>> _______________________________________________
>>>>>> FreeSWITCH-users mailing list
>>>>>> FreeSWITCH-users at lists.freeswitch.org
>>>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>>>> http://www.freeswitch.org
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Sincerely,
>>>>>
>>>>> Giovanni Maruzzelli
>>>>> Cell : +39-347-2665618
>>>>>
>>>>> _______________________________________________
>>>>> FreeSWITCH-users mailing list
>>>>> FreeSWITCH-users at lists.freeswitch.org
>>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>>> http://www.freeswitch.org
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> jason jeffords | founder & cto cloudtree
>>>> c | +1 617 299 6242
>>>> 850 winter street I waltham ma 02451
>>>> jason at cloudtree.net
>>>>
>>>> _______________________________________________
>>>> FreeSWITCH-users mailing list
>>>> FreeSWITCH-users at lists.freeswitch.org
>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>> http://www.freeswitch.org
>>>>
>>>
>>>
>>>
>>> --
>>> Sincerely,
>>>
>>> Giovanni Maruzzelli
>>> Cell : +39-347-2665618
>>>
>>> _______________________________________________
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>>
>>
>>
>>
>> --
>> jason jeffords | founder & cto cloudtree
>> c | +1 617 299 6242
>> 850 winter street I waltham ma 02451
>> jason at cloudtree.net
>>
>
>
>
> --
> jason jeffords | founder & cto cloudtree
> c | +1 617 299 6242
> 850 winter street I waltham ma 02451
> jason at cloudtree.net
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
--
Sincerely,
Giovanni Maruzzelli
Cell : +39-347-2665618
More information about the FreeSWITCH-users
mailing list