Dear all,

I am tring skypopen with latest git-head. 
There are just 1 skype instance. When forward skype call to 5000, it works fine. It also works fine with originate skypopen/interface1/***** &bridge(user/1001)

 But when I try to forward skype to 1001 with the following dial plan, call hang up imediately when answered.

  <extension name="skypetest">
    <condition field="destination_number" expression="^(5100)$">
      <action application="bridge" data="user/1001"/>
    </condition>
  </extension>

I am working on l ubuntu 10.10 server edition and skype static 2.0.0.72

here is the skype configure
=============full mod_skypopen.conf.xml=====================
<configuration name="skypopen.conf" description="Skypopen Configuration">
  <global_settings>
    <param name="debug" value="8"/>
    <param name="dialplan" value="XML"/>
    <param name="context" value="default"/>
    <param name="destination" value="5100"/>
    <param name="skype_user" value="user1"/>
    <param name="report_incoming_chatmessages" value="true"/>
    <param name="silent_mode" value="false"/>
    <param name="write_silence_when_idle" value="true"/>
  </global_settings>
  <!-- one entry here per each skypopen interface -->
  <per_interface_settings>
    <interface id="1" name="interface1">
        <param name="X11-display" value="localhost:10.0"/>
        <param name="skype_user" value="niqizhi"/>
    </interface>
  </per_interface_settings>
</configuration>




the debug message of the call is listed below. May I ask what is the possiable cause? Thanks.



2011-03-05 03:15:13.353532 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 CONF_ID 0|||
2011-03-05 03:15:13.438727 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 STATUS RINGING|||
2011-03-05 03:15:13.438727 [DEBUG] skypopen_protocol.c:595     [32b8f10|9350fb9] [DEBUG_SKYPE  595  ][interface1     ][IDLE,IDLE] NO ACTIVE calls in this moment, skype_call 142 is RINGING, to ask PARTNER_DISPNAME and PARTNER_HANDLE
2011-03-05 03:15:13.438727 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][IDLE,IDLE] SENDING: |||GET CALL 142 PARTNER_DISPNAME||||
2011-03-05 03:15:13.438727 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][IDLE,IDLE] SENDING: |||GET CALL 142 PARTNER_HANDLE||||
2011-03-05 03:15:13.576818 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 PARTNER_DISPNAME Eric Ni|||
2011-03-05 03:15:13.609592 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 PARTNER_HANDLE eric.nqz|||
2011-03-05 03:15:13.609592 [DEBUG] skypopen_protocol.c:506     [32b8f10|9350fb9] [DEBUG_SKYPE  506  ][interface1     ][IDLE,IDLE] Call 142 go to skypopen_partner_handle_ring
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:2626         [32b8f10|9350fb9] [DEBUG_SKYPE  2626 ][interface1     ][IDLE,IDLE] NOT FOUND
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:2244         [32b8f10|9350fb9] [DEBUG_SKYPE  2244 ][interface1     ][PRERING,IDLE] 2 SESSION_REQUEST c958d9be-46d6-11e0-bb71-d9b9e6428344
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:244          [32b8f10|9350fb9] [DEBUG_SKYPE  244  ][interface1     ][PRERING,IDLE] codecs UP
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:273          [32b8f10|9350fb9] [DEBUG_SKYPE  273  ][interface1     ][PRERING,IDLE] skypopen_tech_init SUCCESS
2011-03-05 03:15:13.609592 [NOTICE] switch_channel.c:812 New Channel skypopen/interface1 [c958d9be-46d6-11e0-bb71-d9b9e6428344]
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:2268 (skypopen/interface1) State Change CS_NEW -> CS_INIT
2011-03-05 03:15:13.609592 [DEBUG] switch_core_session.c:1116 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:13.609592 [DEBUG] mod_skypopen.c:2280         [32b8f10|9350fb9] [DEBUG_SKYPE  2280 ][interface1     ][PRERING,IDLE] new_inbound_channel
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:320 (skypopen/interface1) Running State Change CS_INIT
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:356 (skypopen/interface1) State INIT
2011-03-05 03:15:13.610977 [DEBUG] mod_skypopen.c:463 (skypopen/interface1) State Change CS_INIT -> CS_ROUTING
2011-03-05 03:15:13.610977 [DEBUG] switch_core_session.c:1116 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:13.610977 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:13.610977 [DEBUG] mod_skypopen.c:464          [32b8f10|9350fb9] [DEBUG_SKYPE  464  ][interface1     ][PRERING,IDLE] interface1 CHANNEL INIT c958d9be-46d6-11e0-bb71-d9b9e6428344
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:356 (skypopen/interface1) State INIT going to sleep
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:320 (skypopen/interface1) Running State Change CS_ROUTING
2011-03-05 03:15:13.610977 [DEBUG] switch_channel.c:1664 (skypopen/interface1) Callstate Change DOWN -> RINGING
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:359 (skypopen/interface1) State ROUTING
2011-03-05 03:15:13.610977 [DEBUG] mod_skypopen.c:664          [32b8f10|9350fb9] [DEBUG_SKYPE  664  ][interface1     ][PRERING,IDLE] interface1 CHANNEL ROUTING
2011-03-05 03:15:13.610977 [DEBUG] switch_core_state_machine.c:77 skypopen/interface1 Standard ROUTING
2011-03-05 03:15:13.610977 [INFO] mod_dialplan_xml.c:331 Processing Eric Ni <eric.nqz>->5100 in context default
Dialplan: skypopen/interface1 parsing [default->unloop] continue=false
Dialplan: skypopen/interface1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: skypopen/interface1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->tod_example] continue=true
Dialplan: skypopen/interface1 Date/Time Match (FAIL) [tod_example] break=on-false
Dialplan: skypopen/interface1 parsing [default->holiday_example] continue=true
Dialplan: skypopen/interface1 Date/Time Match (FAIL) [holiday_example] break=on-false
Dialplan: skypopen/interface1 parsing [default->global-intercept] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [global-intercept] destination_number(5100) =~ /^886$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->group-intercept] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [group-intercept] destination_number(5100) =~ /^\*8$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->intercept-ext] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [intercept-ext] destination_number(5100) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->redial] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [redial] destination_number(5100) =~ /^(redial|870)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->global] continue=true
Dialplan: skypopen/interface1 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: skypopen/interface1 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: skypopen/interface1 Absolute Condition [global]
Dialplan: skypopen/interface1 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: skypopen/interface1 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: skypopen/interface1 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: skypopen/interface1 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: skypopen/interface1 parsing [default->snom-demo-2] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [snom-demo-2] destination_number(5100) =~ /^9001$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->snom-demo-1] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [snom-demo-1] destination_number(5100) =~ /^9000$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->eavesdrop] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [eavesdrop] destination_number(5100) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->eavesdrop] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [eavesdrop] destination_number(5100) =~ /^779$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->call_return] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [call_return] destination_number(5100) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->del-group] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [del-group] destination_number(5100) =~ /^80(\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->add-group] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [add-group] destination_number(5100) =~ /^81(\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->call-group-simo] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [call-group-simo] destination_number(5100) =~ /^82(\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->call-group-order] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [call-group-order] destination_number(5100) =~ /^83(\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->extension-intercom] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [extension-intercom] destination_number(5100) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->Local_Extension] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [Local_Extension] destination_number(5100) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [Local_Extension_Skinny] destination_number(5100) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->group_dial_sales] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [group_dial_sales] destination_number(5100) =~ /^2000$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->group_dial_support] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [group_dial_support] destination_number(5100) =~ /^2001$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->group_dial_billing] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [group_dial_billing] destination_number(5100) =~ /^2002$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->operator] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [operator] destination_number(5100) =~ /^(operator|0)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->vmain] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [vmain] destination_number(5100) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->sip_uri] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [sip_uri] destination_number(5100) =~ /^sip:(.*)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->nb_conferences] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [nb_conferences] destination_number(5100) =~ /^(30\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->wb_conferences] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [wb_conferences] destination_number(5100) =~ /^(31\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->uwb_conferences] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [uwb_conferences] destination_number(5100) =~ /^(32\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->cdquality_conferences] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [cdquality_conferences] destination_number(5100) =~ /^(33\d{2})$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->freeswitch_public_conf_via_sip] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(5100) =~ /^9(888|8888|1616|3232)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->mad_boss_intercom] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [mad_boss_intercom] destination_number(5100) =~ /^0911$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->mad_boss_intercom] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [mad_boss_intercom] destination_number(5100) =~ /^0912$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->mad_boss] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [mad_boss] destination_number(5100) =~ /^0913$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ivr_demo] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ivr_demo] destination_number(5100) =~ /^5000$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->dynamic_conference] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [dynamic_conference] destination_number(5100) =~ /^5001$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->rtp_multicast_page] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [rtp_multicast_page] destination_number(5100) =~ /^pagegroup$|^7243$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->park] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [park] destination_number(5100) =~ /^5900$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->unpark] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [unpark] destination_number(5100) =~ /^5901$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->valet_park] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [valet_park] destination_number(5100) =~ /^(6000)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->valet_park] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [valet_park] destination_number(5100) =~ /^(60\d[1-9])$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->park] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [park] source(mod_skypopen) =~ /mod_sofia/ break=on-false
Dialplan: skypopen/interface1 parsing [default->unpark] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [unpark] source(mod_skypopen) =~ /mod_sofia/ break=on-false
Dialplan: skypopen/interface1 parsing [default->park] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [park] source(mod_skypopen) =~ /mod_sofia/ break=on-false
Dialplan: skypopen/interface1 parsing [default->unpark] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [unpark] source(mod_skypopen) =~ /mod_sofia/ break=on-false
Dialplan: skypopen/interface1 parsing [default->wait] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [wait] destination_number(5100) =~ /^wait$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->fax_receive] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [fax_receive] destination_number(5100) =~ /^9178$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->fax_transmit] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [fax_transmit] destination_number(5100) =~ /^9179$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ringback_180] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ringback_180] destination_number(5100) =~ /^9180$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ringback_183_uk_ring] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ringback_183_uk_ring] destination_number(5100) =~ /^9181$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ringback_183_music_ring] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ringback_183_music_ring] destination_number(5100) =~ /^9182$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ringback_post_answer_uk_ring] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(5100) =~ /^9183$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ringback_post_answer_music] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ringback_post_answer_music] destination_number(5100) =~ /^9184$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->ClueCon] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [ClueCon] destination_number(5100) =~ /^9191$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->show_info] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [show_info] destination_number(5100) =~ /^9192$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->video_record] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [video_record] destination_number(5100) =~ /^9193$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->video_playback] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [video_playback] destination_number(5100) =~ /^9194$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->delay_echo] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [delay_echo] destination_number(5100) =~ /^9195$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->echo] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [echo] destination_number(5100) =~ /^9196$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->milliwatt] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [milliwatt] destination_number(5100) =~ /^9197$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->tone_stream] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [tone_stream] destination_number(5100) =~ /^9198$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->zrtp_enrollement] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [zrtp_enrollement] destination_number(5100) =~ /^9787$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->hold_music] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [hold_music] destination_number(5100) =~ /^9664$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->pizza_demo] continue=false
Dialplan: skypopen/interface1 Regex (FAIL) [pizza_demo] destination_number(5100) =~ /^(pizza|74992)$/ break=on-false
Dialplan: skypopen/interface1 parsing [default->skypetest] continue=false
Dialplan: skypopen/interface1 Regex (PASS) [skypetest] destination_number(5100) =~ /^(5100)$/ break=on-false
Dialplan: skypopen/interface1 Action bridge(user/1001)
2011-03-05 03:15:13.612058 [DEBUG] switch_core_state_machine.c:119 (skypopen/interface1) State Change CS_ROUTING -> CS_EXECUTE
2011-03-05 03:15:13.612058 [DEBUG] switch_core_session.c:1116 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:13.612058 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:13.612058 [DEBUG] switch_core_state_machine.c:359 (skypopen/interface1) State ROUTING going to sleep
2011-03-05 03:15:13.612058 [DEBUG] switch_core_state_machine.c:320 (skypopen/interface1) Running State Change CS_EXECUTE
2011-03-05 03:15:13.612058 [DEBUG] switch_core_state_machine.c:366 (skypopen/interface1) State EXECUTE
2011-03-05 03:15:13.612058 [DEBUG] mod_skypopen.c:681          [32b8f10|9350fb9] [DEBUG_SKYPE  681  ][interface1     ][PRERING,IDLE] interface1 CHANNEL EXECUTE
2011-03-05 03:15:13.612058 [DEBUG] switch_core_state_machine.c:157 skypopen/interface1 Standard EXECUTE
EXECUTE skypopen/interface1 hash(insert/178.79.156.136-spymap/eric.nqz/c958d9be-46d6-11e0-bb71-d9b9e6428344)
2011-03-05 03:15:13.612058 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=26
2011-03-05 03:15:13.612058 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=27
EXECUTE skypopen/interface1 hash(insert/178.79.156.136-last_dial/eric.nqz/5100)
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=26
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=27
EXECUTE skypopen/interface1 hash(insert/178.79.156.136-last_dial/global/c958d9be-46d6-11e0-bb71-d9b9e6428344)
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=26
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=27
EXECUTE skypopen/interface1 set(RFC2822_DATE=Sat, 05 Mar 2011 03:15:13 +0000)
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=26
2011-03-05 03:15:13.613142 [DEBUG] mod_dptools.c:1059 skypopen/interface1 SET [RFC2822_DATE]=[Sat, 05 Mar 2011 03:15:13 +0000]
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=27
EXECUTE skypopen/interface1 bridge(user/1001)
2011-03-05 03:15:13.613142 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=26
2011-03-05 03:15:13.614232 [DEBUG] switch_ivr_originate.c:1971 variable string 0 = [sip_invite_domain=178.79.156.136]
2011-03-05 03:15:13.614232 [DEBUG] switch_ivr_originate.c:1971 variable string 1 = [presence_id=1001@178.79.156.136]
2011-03-05 03:15:13.614232 [NOTICE] switch_channel.c:812 New Channel sofia/internal/sip:1001@90.198.86.129:62954 [c959849a-46d6-11e0-bb72-d9b9e6428344]
2011-03-05 03:15:13.614232 [DEBUG] mod_sofia.c:4151 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_NEW -> CS_INIT
2011-03-05 03:15:13.614232 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:13.614232 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_INIT
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:1001@90.198.86.129:62954) State INIT
2011-03-05 03:15:13.615308 [DEBUG] mod_sofia.c:84 sofia/internal/sip:1001@90.198.86.129:62954 SOFIA INIT
2011-03-05 03:15:13.615308 [DEBUG] mod_sofia.c:124 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_INIT -> CS_ROUTING
2011-03-05 03:15:13.615308 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:1001@90.198.86.129:62954) State INIT going to sleep
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_ROUTING
2011-03-05 03:15:13.615308 [DEBUG] switch_channel.c:1664 (sofia/internal/sip:1001@90.198.86.129:62954) Callstate Change DOWN -> RINGING
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:1001@90.198.86.129:62954) State ROUTING
2011-03-05 03:15:13.615308 [DEBUG] mod_sofia.c:147 sofia/internal/sip:1001@90.198.86.129:62954 SOFIA ROUTING
2011-03-05 03:15:13.615308 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-03-05 03:15:13.615308 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:1001@90.198.86.129:62954) State ROUTING going to sleep
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_CONSUME_MEDIA
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:1001@90.198.86.129:62954) State CONSUME_MEDIA
2011-03-05 03:15:13.615308 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1001@90.198.86.129:62954 entering state [calling][0]
2011-03-05 03:15:13.615308 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:1001@90.198.86.129:62954) State CONSUME_MEDIA going to sleep
2011-03-05 03:15:13.758128 [INFO] sofia.c:729 sofia/internal/sip:1001@90.198.86.129:62954 Update Callee ID to "Outbound Call" <1001>
2011-03-05 03:15:13.759171 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1001@90.198.86.129:62954 entering state [proceeding][180]
2011-03-05 03:15:13.759171 [NOTICE] sofia.c:4761 Ring-Ready sofia/internal/sip:1001@90.198.86.129:62954!
2011-03-05 03:15:13.759171 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PRERING,IDLE] MSG_ID=7
2011-03-05 03:15:13.759171 [DEBUG] switch_core_session.c:709 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:13.759171 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:13.759171 [NOTICE] switch_ivr_originate.c:479 Ring Ready skypopen/interface1!
2011-03-05 03:15:13.759171 [NOTICE] switch_ivr_originate.c:479 Ring-Ready skypopen/interface1!
2011-03-05 03:15:15.372653 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1001@90.198.86.129:62954 entering state [completing][200]
2011-03-05 03:15:15.372653 [DEBUG] sofia.c:4694 Remote SDP:
v=0
o=- 1 2 IN IP4 90.198.86.129
s=CounterPath eyeBeam 1.5
c=IN IP4 90.198.86.129
t=0 0
m=audio 56446 RTP/AVP 8 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2011-03-05 03:15:15.373722 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1001@90.198.86.129:62954 entering state [ready][200]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[L16:10:16000:20:256000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4529 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:2760 Set Codec sofia/internal/sip:1001@90.198.86.129:62954 PCMA/8000 20 ms 160 samples 64000 bits
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:4635 Set 2833 dtmf send payload to 101
2011-03-05 03:15:15.373722 [DEBUG] sofia_glue.c:2990 AUDIO RTP [sofia/internal/sip:1001@90.198.86.129:62954] 178.79.156.136 port 32054 -> 90.198.86.129 port 56446 codec: 8 ms: 20
2011-03-05 03:15:15.373722 [DEBUG] switch_rtp.c:1621 Starting timer [soft] 160 bytes per 20ms
2011-03-05 03:15:15.374777 [DEBUG] sofia_glue.c:3235 Set 2833 dtmf send payload to 101
2011-03-05 03:15:15.374777 [DEBUG] sofia_glue.c:3240 Set 2833 dtmf receive payload to 101
2011-03-05 03:15:15.374777 [DEBUG] switch_channel.c:2795 (sofia/internal/sip:1001@90.198.86.129:62954) Callstate Change RINGING -> ACTIVE
2011-03-05 03:15:15.374777 [DEBUG] switch_channel.c:2807 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.374777 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.374777 [NOTICE] sofia.c:5267 Channel [sofia/internal/sip:1001@90.198.86.129:62954] has been answered
2011-03-05 03:15:15.375852 [DEBUG] mod_skypopen.c:1115         [32b8f10|9350fb9] [DEBUG_SKYPE  1115 ][interface1     ][PRERING,IDLE] skypopen/interface1 CHANNEL got SWITCH_MESSAGE_INDICATE_ANSWER
2011-03-05 03:15:15.375852 [DEBUG] mod_skypopen.c:2723         [32b8f10|9350fb9] [DEBUG_SKYPE  2723 ][interface1     ][PRERING,IDLE] NOT FOUND
2011-03-05 03:15:15.375852 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][PREANSW,IDLE] SENDING: |||ALTER CALL 142 ANSWER||||
2011-03-05 03:15:15.375852 [DEBUG] mod_skypopen.c:2734         [32b8f10|9350fb9] [DEBUG_SKYPE  2734 ][interface1     ][PREANSW,IDLE] We answered a Skype RING on skype_call 142
2011-03-05 03:15:15.375852 [DEBUG] mod_skypopen.c:2742         [32b8f10|9350fb9] [DEBUG_SKYPE  2742 ][interface1     ][PREANSW,IDLE] NEW!  name: interface1, state: 11, value=eric.nqz, tech_pvt->callid_number=eric.nqz, tech_pvt->skype_user=niqizhi
2011-03-05 03:15:15.472676 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][PREANSW,IDLE] READING: |||ALTER CALL 142 ANSWER|||
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:1142         [32b8f10|9350fb9] [DEBUG_SKYPE  1142 ][interface1     ][PREANSW,IDLE] Synching audio
2011-03-05 03:15:15.884213 [DEBUG] switch_core_session.c:709 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.884213 [DEBUG] switch_channel.c:2795 (skypopen/interface1) Callstate Change RINGING -> ACTIVE
2011-03-05 03:15:15.884213 [NOTICE] switch_ivr_originate.c:3363 Channel [skypopen/interface1] has been answered
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:1148         [32b8f10|9350fb9] [DEBUG_SKYPE  1148 ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:1170         [32b8f10|9350fb9] [DEBUG_SKYPE  1170 ][interface1     ][PREANSW,IDLE] Synching audio
2011-03-05 03:15:15.884213 [DEBUG] switch_ivr_originate.c:3408 Originate Resulted in Success: [sofia/internal/sip:1001@90.198.86.129:62954]
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:1148         [32b8f10|9350fb9] [DEBUG_SKYPE  1148 ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
2011-03-05 03:15:15.884213 [DEBUG] mod_skypopen.c:1170         [32b8f10|9350fb9] [DEBUG_SKYPE  1170 ][interface1     ][PREANSW,IDLE] Synching audio
2011-03-05 03:15:15.885293 [DEBUG] switch_ivr_originate.c:3408 Originate Resulted in Success: [sofia/internal/sip:1001@90.198.86.129:62954]
2011-03-05 03:15:15.885293 [DEBUG] mod_skypopen.c:1148         [32b8f10|9350fb9] [DEBUG_SKYPE  1148 ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_MESSAGE_INDICATE_AUDIO_SYNC
2011-03-05 03:15:15.885293 [DEBUG] mod_skypopen.c:1170         [32b8f10|9350fb9] [DEBUG_SKYPE  1170 ][interface1     ][PREANSW,IDLE] Synching audio
2011-03-05 03:15:15.885293 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.885293 [DEBUG] mod_skypopen.c:1173         [32b8f10|9350fb9] [DEBUG_SKYPE  1173 ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_MESSAGE_INDICATE_BRIDGE
2011-03-05 03:15:15.885293 [DEBUG] mod_skypopen.c:1195         [32b8f10|9350fb9] [DEBUG_SKYPE  1195 ][interface1     ][PREANSW,IDLE] Synching audio
2011-03-05 03:15:15.885293 [DEBUG] switch_core_session.c:709 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.885293 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.885293 [DEBUG] switch_ivr_bridge.c:1234 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2011-03-05 03:15:15.885293 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.885293 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_EXCHANGE_MEDIA
2011-03-05 03:15:15.885293 [DEBUG] switch_core_state_machine.c:369 (sofia/internal/sip:1001@90.198.86.129:62954) State EXCHANGE_MEDIA
2011-03-05 03:15:15.885293 [DEBUG] mod_sofia.c:552 SOFIA EXCHANGE_MEDIA
2011-03-05 03:15:15.886388 [DEBUG] switch_core_session.c:771 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.886388 [DEBUG] switch_core_session.c:771 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.886388 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.906103 [DEBUG] switch_ivr_bridge.c:500 skypopen/interface1 ending bridge by request from read function
2011-03-05 03:15:15.906103 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [skypopen/interface1]
2011-03-05 03:15:15.906103 [DEBUG] switch_ivr_bridge.c:601 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.909404 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [sofia/internal/sip:1001@90.198.86.129:62954]
2011-03-05 03:15:15.909404 [DEBUG] switch_ivr_bridge.c:601 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.909404 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.909404 [DEBUG] switch_channel.c:2545 (sofia/internal/sip:1001@90.198.86.129:62954) Callstate Change ACTIVE -> HANGUP
2011-03-05 03:15:15.909404 [NOTICE] switch_ivr_bridge.c:653 Hangup sofia/internal/sip:1001@90.198.86.129:62954 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2011-03-05 03:15:15.909404 [DEBUG] switch_channel.c:2561 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [KILL]
2011-03-05 03:15:15.909404 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.909404 [DEBUG] switch_core_state_machine.c:369 (sofia/internal/sip:1001@90.198.86.129:62954) State EXCHANGE_MEDIA going to sleep
2011-03-05 03:15:15.909404 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_HANGUP
2011-03-05 03:15:15.910537 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:1001@90.198.86.129:62954) State HANGUP
2011-03-05 03:15:15.910537 [DEBUG] mod_sofia.c:457 Channel sofia/internal/sip:1001@90.198.86.129:62954 hanging up, cause: NORMAL_CLEARING
2011-03-05 03:15:15.910537 [DEBUG] switch_ivr_bridge.c:1305 sofia/internal/sip:1001@90.198.86.129:62954 skip receive message [UNBRIDGE] (channel is hungup already)
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PREANSW,IDLE] MSG_ID=5
2011-03-05 03:15:15.910537 [DEBUG] switch_core_session.c:709 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:1201         [32b8f10|9350fb9] [DEBUG_SKYPE  1201 ][interface1     ][PREANSW,IDLE] MSG_ID=27
2011-03-05 03:15:15.910537 [NOTICE] switch_core_state_machine.c:189 skypopen/interface1 has executed the last dialplan instruction, hanging up.
2011-03-05 03:15:15.910537 [DEBUG] switch_channel.c:2545 (skypopen/interface1) Callstate Change ACTIVE -> HANGUP
2011-03-05 03:15:15.910537 [NOTICE] switch_core_state_machine.c:191 Hangup skypopen/interface1 [CS_EXECUTE] [NORMAL_CLEARING]
2011-03-05 03:15:15.910537 [DEBUG] switch_channel.c:2561 Send signal skypopen/interface1 [KILL]
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:700          [32b8f10|9350fb9] [DEBUG_SKYPE  700  ][interface1     ][PREANSW,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_KILL
2011-03-05 03:15:15.910537 [DEBUG] switch_core_session.c:1116 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][HANG_RQ,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.910537 [DEBUG] switch_core_state_machine.c:366 (skypopen/interface1) State EXECUTE going to sleep
2011-03-05 03:15:15.910537 [DEBUG] mod_sofia.c:500 Sending BYE to sofia/internal/sip:1001@90.198.86.129:62954
2011-03-05 03:15:15.910537 [DEBUG] switch_core_state_machine.c:320 (skypopen/interface1) Running State Change CS_HANGUP
2011-03-05 03:15:15.910537 [DEBUG] switch_core_state_machine.c:560 (skypopen/interface1) State HANGUP
2011-03-05 03:15:15.910537 [DEBUG] mod_skypopen.c:623          [32b8f10|9350fb9] [DEBUG_SKYPE  623  ][interface1     ][HANG_RQ,IDLE] hanging up skype call: 142
2011-03-05 03:15:15.911571 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][HANG_RQ,IDLE] SENDING: |||ALTER CALL 142 END HANGUP||||
2011-03-05 03:15:15.911571 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][HANG_RQ,IDLE] SENDING: |||ALTER CALL 142 HANGUP||||
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:629          [32b8f10|9350fb9] [DEBUG_SKYPE  629  ][interface1     ][HANG_RQ,IDLE] interface1 CHANNEL HANGUP
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:648 (skypopen/interface1) State Change CS_HANGUP -> CS_DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_session.c:1116 Send signal skypopen/interface1 [BREAK]
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:727          [32b8f10|9350fb9] [DEBUG_SKYPE  727  ][interface1     ][DOWN,IDLE] skypopen/interface1 CHANNEL got SWITCH_SIG_BREAK
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:560 (skypopen/interface1) State HANGUP going to sleep
2011-03-05 03:15:15.911571 [DEBUG] switch_core_session.c:1288 Session 24 (skypopen/interface1) Locked, Waiting on external entities
2011-03-05 03:15:15.911571 [NOTICE] switch_core_session.c:1306 Session 24 (skypopen/interface1) Ended
2011-03-05 03:15:15.911571 [NOTICE] switch_core_session.c:1308 Close Channel skypopen/interface1 [CS_DESTROY]
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1001@90.198.86.129:62954 Standard HANGUP, cause: NORMAL_CLEARING
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:1001@90.198.86.129:62954) State HANGUP going to sleep
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_HANGUP -> CS_REPORTING
2011-03-05 03:15:15.911571 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_REPORTING
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:1001@90.198.86.129:62954) State REPORTING
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1001@90.198.86.129:62954 Standard REPORTING, cause: NORMAL_CLEARING
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:1001@90.198.86.129:62954) State REPORTING going to sleep
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:449 (skypopen/interface1) Callstate Change HANGUP -> DOWN
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:452 (skypopen/interface1) Running State Change CS_DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:462 (skypopen/interface1) State DESTROY
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:479          [32b8f10|9350fb9] [DEBUG_SKYPE  479  ][interface1     ][DOWN,IDLE] interface1 CHANNEL DESTROY c958d9be-46d6-11e0-bb71-d9b9e6428344
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:493          [32b8f10|9350fb9] [DEBUG_SKYPE  493  ][interface1     ][DOWN,IDLE] audio tcp threads to DIE
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:503          [32b8f10|9350fb9] [DEBUG_SKYPE  503  ][interface1     ][DOWN,IDLE] audio tcp srv thread DEAD 0
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:513          [32b8f10|9350fb9] [DEBUG_SKYPE  513  ][interface1     ][DOWN,IDLE] audio tcp cli thread DEAD 0
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/sip:1001@90.198.86.129:62954) State Change CS_REPORTING -> CS_DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1001@90.198.86.129:62954 [BREAK]
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:524          [32b8f10|9350fb9] [DEBUG_SKYPE  524  ][interface1     ][DOWN,IDLE] codecs DOWN
2011-03-05 03:15:15.911571 [DEBUG] switch_core_session.c:1288 Session 25 (sofia/internal/sip:1001@90.198.86.129:62954) Locked, Waiting on external entities
2011-03-05 03:15:15.911571 [DEBUG] mod_skypopen.c:579          [32b8f10|9350fb9] [DEBUG_SKYPE  579  ][interface1     ][IDLE,IDLE] CHANNEL DESTROYED c958d9be-46d6-11e0-bb71-d9b9e6428344
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:60 skypopen/interface1 Standard DESTROY
2011-03-05 03:15:15.911571 [NOTICE] switch_core_session.c:1306 Session 25 (sofia/internal/sip:1001@90.198.86.129:62954) Ended
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:462 (skypopen/interface1) State DESTROY going to sleep
2011-03-05 03:15:15.911571 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/sip:1001@90.198.86.129:62954 [CS_DESTROY]
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/sip:1001@90.198.86.129:62954) Callstate Change HANGUP -> DOWN
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:1001@90.198.86.129:62954) Running State Change CS_DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:1001@90.198.86.129:62954) State DESTROY
2011-03-05 03:15:15.911571 [DEBUG] mod_sofia.c:362 sofia/internal/sip:1001@90.198.86.129:62954 SOFIA DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1001@90.198.86.129:62954 Standard DESTROY
2011-03-05 03:15:15.911571 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:1001@90.198.86.129:62954) State DESTROY going to sleep
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 STATUS INPROGRESS|||
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:719     [32b8f10|9350fb9] [DEBUG_SKYPE  719  ][interface1     ][IDLE,IDLE] no tech_pvt->session_uuid_str
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:725     [32b8f10|9350fb9] [DEBUG_SKYPE  725  ][interface1     ][IDLE,IDLE] skype_call: 142 is now active
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:732     [32b8f10|9350fb9] [DEBUG_SKYPE  732  ][interface1     ][UP,INPROGRS] START start_audio_threads
2011-03-05 03:15:16.149772 [DEBUG] mod_skypopen.c:2203         [32b8f10|9350fb9] [DEBUG_SKYPE  2203 ][interface1     ][UP,INPROGRS] started tcp_srv_thread thread.
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:89      [32b8f10|9350fb9] [DEBUG_SKYPE  89   ][interface1     ][UP,INPROGRS] Binded! *which_port=32783, tech_pvt->tcp_cli_port=32782, tech_pvt->tcp_srv_port=32783
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:94      [32b8f10|9350fb9] [DEBUG_SKYPE  94   ][interface1     ][UP,INPROGRS] 1 SO_RCVBUF is 87380, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:98      [32b8f10|9350fb9] [DEBUG_SKYPE  98   ][interface1     ][UP,INPROGRS] 1 SO_SNDBUF is 16384, size is 4
2011-03-05 03:15:16.149772 [DEBUG] mod_skypopen.c:2219         [32b8f10|9350fb9] [DEBUG_SKYPE  2219 ][interface1     ][UP,INPROGRS] started tcp_cli_thread thread.
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:115     [32b8f10|9350fb9] [DEBUG_SKYPE  115  ][interface1     ][UP,INPROGRS] 2 SO_RCVBUF is 87380, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:130     [32b8f10|9350fb9] [DEBUG_SKYPE  130  ][interface1     ][UP,INPROGRS] 2 SO_SNDBUF is 16384, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:89      [32b8f10|9350fb9] [DEBUG_SKYPE  89   ][interface1     ][UP,INPROGRS] Binded! *which_port=32784, tech_pvt->tcp_cli_port=32784, tech_pvt->tcp_srv_port=32783
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:134     [32b8f10|9350fb9] [DEBUG_SKYPE  134  ][interface1     ][UP,INPROGRS] TCP_NODELAY is 0
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:94      [32b8f10|9350fb9] [DEBUG_SKYPE  94   ][interface1     ][UP,INPROGRS] 1 SO_RCVBUF is 87380, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:141     [32b8f10|9350fb9] [DEBUG_SKYPE  141  ][interface1     ][UP,INPROGRS] TCP_NODELAY is 0
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:98      [32b8f10|9350fb9] [DEBUG_SKYPE  98   ][interface1     ][UP,INPROGRS] 1 SO_SNDBUF is 16384, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:833     [32b8f10|9350fb9] [DEBUG_SKYPE  833  ][interface1     ][UP,INPROGRS] started tcp_srv_thread thread.
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:115     [32b8f10|9350fb9] [DEBUG_SKYPE  115  ][interface1     ][UP,INPROGRS] 2 SO_RCVBUF is 87380, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:130     [32b8f10|9350fb9] [DEBUG_SKYPE  130  ][interface1     ][UP,INPROGRS] 2 SO_SNDBUF is 16384, size is 4
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:134     [32b8f10|9350fb9] [DEBUG_SKYPE  134  ][interface1     ][UP,INPROGRS] TCP_NODELAY is 0
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:141     [32b8f10|9350fb9] [DEBUG_SKYPE  141  ][interface1     ][UP,INPROGRS] TCP_NODELAY is 0
2011-03-05 03:15:16.149772 [DEBUG] skypopen_protocol.c:997     [32b8f10|9350fb9] [DEBUG_SKYPE  997  ][interface1     ][UP,INPROGRS] started tcp_cli_thread thread.
2011-03-05 03:15:16.250297 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][UP,INPROGRS] SENDING: |||ALTER CALL 142 SET_INPUT PORT="32784"||||
2011-03-05 03:15:16.250297 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][UP,INPROGRS] SENDING: |||#output ALTER CALL 142 SET_OUTPUT PORT="32783"||||
2011-03-05 03:15:16.250297 [WARNING] skypopen_protocol.c:2036  [32b8f10|9350fb9] [WARNINGA     2036 ][interface1     ][UP,INPROGRS] no tech_pvt->session_uuid_str after INPROGRESS, let's hangup
2011-03-05 03:15:16.250297 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][UP,INPROGRS] SENDING: |||ALTER CALL 142 HANGUP||||
2011-03-05 03:15:16.250297 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||CALL 142 VIDEO_SEND_STATUS AVAILABLE|||
2011-03-05 03:15:16.290473 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||CALL 142 VIDEO_STATUS VIDEO_BOTH_ENABLED|||
2011-03-05 03:15:16.363839 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||CALL 142 DURATION 1|||
2011-03-05 03:15:16.432605 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||ALTER CALL 142 END HANGUP|||
2011-03-05 03:15:16.494506 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.495584 [DEBUG] skypopen_protocol.c:228     [32b8f10|9350fb9] [DEBUG_SKYPE  228  ][interface1     ][UP,INPROGRS] Skype got ERROR about a failed action (probably TRYING to HANGUP A CALL), no problem: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.710271 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][UP,INPROGRS] READING: |||ERROR 589 ALTER CALL: unable to alter input/output|||
2011-03-05 03:15:16.711346 [DEBUG] skypopen_protocol.c:247     [32b8f10|9350fb9] [DEBUG_SKYPE  247  ][interface1     ][UP,INPROGRS] Skype client was not able to correctly manage tcp audio sockets, probably got a local or remote hangup: |||ERROR 589 ALTER CALL: unable to alter input/output|||
2011-03-05 03:15:16.711346 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][UP,INPROGRS] SENDING: |||ALTER CALL 142 HANGUP||||
2011-03-05 03:15:16.711346 [DEBUG] skypopen_protocol.c:1619    [32b8f10|9350fb9] [DEBUG_SKYPE  1619 ][interface1     ][UP,INPROGRS] SENDING: |||ALTER CALL 142 END HANGUP||||
2011-03-05 03:15:16.711346 [DEBUG] mod_skypopen.c:1413         [32b8f10|9350fb9] [DEBUG_SKYPE  1413 ][interface1     ][DOWN,INPROGRS] skype call ended
2011-03-05 03:15:16.711346 [DEBUG] mod_skypopen.c:1433         [32b8f10|9350fb9] [DEBUG_SKYPE  1433 ][interface1     ][DOWN,INPROGRS] no session
2011-03-05 03:15:16.711346 [DEBUG] mod_skypopen.c:1436         [32b8f10|9350fb9] [DEBUG_SKYPE  1436 ][interface1     ][DOWN,INPROGRS] audio tcp threads to DIE
2011-03-05 03:15:16.712434 [DEBUG] skypopen_protocol.c:960     [32b8f10|9350fb9] [DEBUG_SKYPE  960  ][interface1     ][DOWN,INPROGRS] incoming audio (read) server (I am it) EXITING
2011-03-05 03:15:16.715692 [DEBUG] mod_skypopen.c:1446         [32b8f10|9350fb9] [DEBUG_SKYPE  1446 ][interface1     ][DOWN,INPROGRS] audio tcp srv thread DEAD 1
2011-03-05 03:15:16.750763 [DEBUG] skypopen_protocol.c:1112    [32b8f10|9350fb9] [DEBUG_SKYPE  1112 ][interface1     ][DOWN,INPROGRS] outbound audio server (I am it) EXITING
2011-03-05 03:15:16.751849 [DEBUG] mod_skypopen.c:1456         [32b8f10|9350fb9] [DEBUG_SKYPE  1456 ][interface1     ][DOWN,INPROGRS] audio tcp cli thread DEAD 7
2011-03-05 03:15:16.751849 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||#output ERROR 589 ALTER CALL: unable to alter input/output|||
2011-03-05 03:15:16.779660 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.780762 [DEBUG] skypopen_protocol.c:228     [32b8f10|9350fb9] [DEBUG_SKYPE  228  ][interface1     ][IDLE,IDLE] Skype got ERROR about a failed action (probably TRYING to HANGUP A CALL), no problem: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.828877 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.828877 [DEBUG] skypopen_protocol.c:228     [32b8f10|9350fb9] [DEBUG_SKYPE  228  ][interface1     ][IDLE,IDLE] Skype got ERROR about a failed action (probably TRYING to HANGUP A CALL), no problem: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.869183 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.869183 [DEBUG] skypopen_protocol.c:228     [32b8f10|9350fb9] [DEBUG_SKYPE  228  ][interface1     ][IDLE,IDLE] Skype got ERROR about a failed action (probably TRYING to HANGUP A CALL), no problem: |||ERROR 559 CALL: Action failed|||
2011-03-05 03:15:16.911668 [DEBUG] skypopen_protocol.c:173     [32b8f10|9350fb9] [DEBUG_SKYPE  173  ][interface1     ][IDLE,IDLE] READING: |||CALL 142 STATUS FINISHED|||
2011-03-05 03:15:16.911668 [DEBUG] skypopen_protocol.c:661     [32b8f10|9350fb9] [DEBUG_SKYPE  661  ][interface1     ][IDLE,IDLE] skype_call 142 is MY call, now I'm going DOWN
2011-03-05 03:15:16.911668 [DEBUG] mod_skypopen.c:1413         [32b8f10|9350fb9] [DEBUG_SKYPE  1413 ][interface1     ][IDLE,IDLE] skype call ended
2011-03-05 03:15:16.911668 [DEBUG] mod_skypopen.c:1433         [32b8f10|9350fb9] [DEBUG_SKYPE  1433 ][interface1     ][IDLE,IDLE] no session
2011-03-05 03:15:16.911668 [DEBUG] mod_skypopen.c:1436         [32b8f10|9350fb9] [DEBUG_SKYPE  1436 ][interface1     ][DOWN,IDLE] audio tcp threads to DIE
2011-03-05 03:15:16.911668 [DEBUG] mod_skypopen.c:1446         [32b8f10|9350fb9] [DEBUG_SKYPE  1446 ][interface1     ][DOWN,IDLE] audio tcp srv thread DEAD 0
2011-03-05 03:15:16.911668 [DEBUG] mod_skypopen.c:1456         [32b8f10|9350fb9] [DEBUG_SKYPE  1456 ][interface1     ][DOWN,IDLE] audio tcp cli thread DEAD 0