[Freeswitch-users] mod_skypopen Refusing Skype Calls Once a Call is Answered Via a Desktop Skype Client
Jason Jeffords
jason at cloudtree.net
Tue Sep 28 12:12:48 PDT 2010
Thanks Giovanni,
We will do that ASAP.
Jason
On Tue, Sep 28, 2010 at 2:48 PM, Giovanni Maruzzelli <gmaruzz at gmail.com> wrote:
> 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
>
> _______________________________________________
> 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
More information about the FreeSWITCH-users
mailing list