[Freeswitch-users] mod_skypopen Refusing Skype Calls Once a Call is Answered Via a Desktop Skype Client

28 Sep 2010

      All,

We have found an issue under the following scenario:

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] mod_skypopen Refusing Skype Calls Once a Call is Answered Via a Desktop Skype Client

Jason Jeffords