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@gmail.com> wrote:
On Tue, Sep 28, 2010 at 5:26 PM, Jason Jeffords <jason@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@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@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@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@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@cloudtree.net
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Sincerely,
Giovanni Maruzzelli Cell : +39-347-2665618
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- jason jeffords | founder & cto cloudtree c | +1 617 299 6242 850 winter street I waltham ma 02451 jason@cloudtree.net