CUBE Help please! VOIP dial peer to Lync

[rrobles007]

Hello,

i'm having inbound call setup issues and hoping someone might be able to point me in the right direction.. its been a while since i worked on a Cube.

I have a 4 port FXO card on CUBE with VOIP dial peers pointing to a Microsoft Lync 2013

Any help would be HUGELY APPRECIATED. right now i don't believe i'm sending the call towards the lync server..

I can make outbound calls no problem, on inbound I get a fast busy. During the debug ccsip for inbound calls  i see the following:

(this is a dev environment so i don't mind sharing config)

The Call Setup Information is:
Call Control Block (CCB) : 0x23D03C8
State of The Call        : STATE_DEAD
TCP Sockets Used         : YES
Calling Number           : 
Called Number            : 8409
Source IP Address (Sig  ): 0.0.0.0
Destn SIP Req Addr:Port  : :0
Destn SIP Resp Addr:Port : :0
Destination Name         : 

I see that i match 2 dial peers on the inbound call: Matching Dial peer 10 for inbound and dial-peer 7 for outgoing:

ccsip_target_is_busied: SIP Dialpeer 7 busied out due to options-keepalive failure

dial-peer voice 7 voip
 translation-profile outgoing toLync
 huntstop
 destination-pattern ....
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 voice-class codec 1
 voice-class sip localhost dns:GoPro_CUBE.test.lcl 
 no voice-class sip early-offer forced
 voice-class sip block 183 sdp absent
 voice-class sip options-keepalive
 dtmf-relay rtp-nte

dial-peer voice 10 pots
 description outbound_to_FXO
 destination-pattern .T
 direct-inward-dial
 port 0/0/1
 forward-digits all

*Nov 26 18:31:17.481: //25003/36D36F9EA3E9/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x21290A8, Tag=0x0, Call Id=25003,
   Call Entry(Disconnect Cause=3, Voice Class Cause Code=0, Retry Count=0)
*Nov 26 18:31:17.481: //25003/36D36F9EA3E9/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Nov 26 18:31:17.481: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:17.481: :cc_free_feature_vsa freeing 259C1D0
*Nov 26 18:31:17.481: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:17.481:  vsacount in free is 0
*Nov 26 18:31:21.977: //-1/4141B85CA3EE/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=8409
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-lastrdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=0
   cisco-rdnsi=0
   cisco-redirectreason=0   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

*Nov 26 18:31:21.977: //-1/4141B85CA3EE/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x21290A8, Call Info(
   Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=8409(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=10, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
*Nov 26 18:31:21.977: //-1/4141B85CA3EE/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Nov 26 18:31:21.977: //-1/4141B85CA3EE/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Nov 26 18:31:21.977: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.977: :cc_get_feature_vsa malloc success
*Nov 26 18:31:21.977: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.977:  cc_get_feature_vsa count is 1
*Nov 26 18:31:21.977: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.977: :FEATURE_VSA attributes are: feature_name:0,feature_time:39436760,feature_id:288
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=8409(TON=Unknown, NPI=Unknown))
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/cc_process_call_setup_ind:
   Event=0x135E87D8
*Nov 26 18:31:21.977: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 8409
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCallSetContext:
   Context=0x11B14348
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 25005 with tag 10 to app "_ManagedAppProcess_Default"
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
*Nov 26 18:31:21.977: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 8409
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=FALSE, Mode=0,
   Outgoing Dial-peer=7, Params=0x11B1A2C0, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCallSetupRequest:
   Destination Pattern=...., Called Number=8409, Digit Strip=FALSE
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/ccCallSetupRequest:
   Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=8409(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=, Final Destination Flag=TRUE,
   Guid=4141B85C-74D1-11E4-A3EE-80FA62F158C4, Outgoing Dial-peer=7
*Nov 26 18:31:21.977: //25005/4141B85CA3EE/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=8409
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-lastrdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=0
   cisco-rdnsi=0
   cisco-redirectreason=0   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

*Nov 26 18:31:21.981: //25005/4141B85CA3EE/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x1979710, Interface Type=3, Destination=, Mode=0x0,
   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=8409(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=7, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
*Nov 26 18:31:21.981: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.981: :cc_get_feature_vsa malloc success
*Nov 26 18:31:21.981: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.981:  cc_get_feature_vsa count is 2
*Nov 26 18:31:21.981: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
*Nov 26 18:31:21.981: :FEATURE_VSA attributes are: feature_name:0,feature_time:39436536,feature_id:289
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=3, FlowMode=1
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/ccCallSetContext:
   Context=0x11B1A270
*Nov 26 18:31:21.981: //25005/4141B85CA3EE/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=7
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/cc_api_call_disconnected:
   Cause Value=3, Interface=0x1979710, Call Id=25006
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=3, Retry Count=0)
*Nov 26 18:31:21.981: //25005/xxxxxxxxxxxx/CCAPI/ccCallReleaseResources:
   release reserved xcoding resource.
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/ccCallSetAAA_Accounting:
   Accounting=0, Call Id=25006
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/ccCallDisconnect:
   Cause Value=3, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=3)
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/ccCallDisconnect:
   Cause Value=3, Call Entry(Responsed=TRUE, Cause Value=3)
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/cc_api_call_disconnect_done:
   Disposition=-11, Interface=0x1979710, Tag=0x0, Call Id=25006,
   Call Entry(Disconnect Cause=3, Voice Class Cause Code=0, Retry Count=0)
*Nov 26 18:31:21.981: //25006/4141B85CA3EE/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Nov 26 18:31:21.981: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:21.981: :cc_free_feature_vsa freeing 259C0F0
*Nov 26 18:31:21.981: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:21.981:  vsacount in free is 1
*Nov 26 18:31:21.981: //25005/4141B85CA3EE/CCAPI/ccCallDisconnect:
   Cause Value=3, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Nov 26 18:31:21.981: //25005/4141B85CA3EE/CCAPI/ccCallDisconnect:
   Cause Value=3, Call Entry(Responsed=TRUE, Cause Value=3)
*Nov 26 18:31:21.981: //25005/4141B85CA3EE/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
*Nov 26 18:31:34.901: //25005/4141B85CA3EE/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x21290A8, Tag=0x0, Call Id=25005,
   Call Entry(Disconnect Cause=3, Voice Class Cause Code=0, Retry Count=0)
*Nov 26 18:31:34.901: //25005/4141B85CA3EE/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Nov 26 18:31:34.901: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:34.901: :cc_free_feature_vsa freeing 259C1D0
*Nov 26 18:31:34.901: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
*Nov 26 18:31:34.901:  vsacount in free is 0

aaa new-model
!
!
!
!
!
!
!
aaa session-id common
!
!
!
!
!
!
no ipv6 cef
ip source-route
ip cef
!
!
!
!
no ip domain lookup
ip domain name test.lcl
ip name-server 172.16.12.10
ip name-server 172.16.12.11
!
multilink bundle-name authenticated
!
!
!
!
!
voice-card 0
!
!
!
voice service voip
 allow-connections sip to sip
 no supplementary-service sip refer
 supplementary-service media-renegotiate
 fax protocol t38 ls-redundancy 0 hs-redundancy 0 fallback none
 sip
  min-se 600 
  asserted-id pai
  midcall-signaling passthru
  privacy-policy passthru
  privacy-policy send-always
  sip-profiles 1
!
voice class codec 1
 codec preference 1 g711ulaw
 codec preference 2 g711alaw
!
voice class sip-profiles 1
 request INVITE sip-header Expires remove 
 request INVITE sip-header Session-Expires add "Session-expires: 600" 
!
!
!
voice translation-rule 1
 rule 1 /\(..........\)/ /+1\1/
!
voice translation-rule 2
 rule 1 /\+1\(..........\)/ /\1/
!
voice translation-rule 3
 rule 1 /\(..........\)/ /+\1/
!
!
voice translation-profile toAnalog
 translate called 3
!
voice translation-profile toLync
 translate called 1
!
voice translation-profile toPRI
 translate called 2
!
!
!
application
 service dsapp
  param dialpeer 7
  param callHold TRUE
 !
!
license udi pid C3900-SPE100/K9 sn FOC16216VXU
license boot module c3900 technology-package securityk9
license boot module c3900 technology-package uck9
license boot module c3900 technology-package datak9
hw-module pvdm 0/0
!
!
!

!
redundancy
!
!
ip ssh time-out 60
! 
!
!
!
!
!
!
interface GigabitEthernet0/0
 no ip address
 shutdown
 duplex auto
 speed auto
 !
!
interface GigabitEthernet0/1
 no ip address
 shutdown
 duplex auto
 speed auto
 !
!
interface GigabitEthernet0/2
 ip address 172.16.12.6 255.255.255.0
 duplex auto
 speed auto
 !
!
!
ip default-gateway 172.16.12.1
ip forward-protocol nd
!
no ip http server
no ip http secure-server
!
ip route 0.0.0.0 0.0.0.0 172.16.12.1
!
!
!
!
!
nls resp-timeout 1
cpd cr-id 1
!
!
control-plane
 !
!
!
voice-port 0/0/0
!
voice-port 0/0/1
 connection plar 8409
!
voice-port 0/0/2
!
voice-port 0/0/3
!
!
!
!
dial-peer voice 2 pots
 destination-pattern 5206803
 direct-inward-dial
 port 0/0/0
!
dial-peer voice 3 pots
 destination-pattern 6505206803
 direct-inward-dial
 port 0/0/2
!
dial-peer voice 1 voip
 description outgoing to Lync
 translation-profile outgoing toLync
 huntstop
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 incoming called-number .
 voice-class codec 1
 voice-class sip localhost dns:GOPRO_CUBE.test.lcl 
 no voice-class sip early-offer forced
 no voice-class sip block 183
 voice-class sip options-keepalive
 dtmf-relay rtp-nte
!
dial-peer voice 4 voip
 description outgoint toAnalog
 huntstop
 destination-pattern 9728522617
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 incoming called-number .
 voice-class codec 1
 voice-class sip localhost dns:GOPRO_CUBE.test.lcl 
 no voice-class sip early-offer forced
 no voice-class sip block 183
 voice-class sip options-keepalive
 dtmf-relay rtp-nte sip-notify sip-kpml
!
dial-peer voice 6 voip
 description outgoint toAnalog
 huntstop
 destination-pattern ..........
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 incoming called-number .
 voice-class codec 1
 voice-class sip localhost dns:GOPRO_CUBE.test.lcl 
 no voice-class sip early-offer forced
 no voice-class sip block 183
 voice-class sip options-keepalive
 dtmf-relay rtp-nte sip-notify sip-kpml
!
dial-peer voice 7 voip
 translation-profile outgoing toLync
 huntstop
 destination-pattern ....
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 voice-class codec 1
 voice-class sip localhost dns:GOPRO_CUBE.test.lcl 
 no voice-class sip early-offer forced
 voice-class sip block 183 sdp absent
 voice-class sip options-keepalive
 dtmf-relay rtp-nte
!
dial-peer voice 8 voip
 description toPSTN
 translation-profile outgoing fromAnalog
 shutdown
 destination-pattern 1..........
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.test.lcl
 session transport tcp
 incoming called-number .
 voice-class codec 1
 voice-class sip localhost dns:GOPRO_CUBE.test.lcl 
 no voice-class sip early-offer forced
 no voice-class sip block 183
 voice-class sip options-keepalive
 dtmf-relay rtp-nte sip-notify sip-kpml
!
dial-peer voice 5 pots
 destination-pattern T
 incoming called-number .
 forward-digits all
!         
dial-peer voice 10 pots
 description outbound_to_FXO
 destination-pattern .T
 direct-inward-dial
 port 0/0/1
 forward-digits all
!
dial-peer voice 11 pots
 shutdown
 destination-pattern 1..........
 direct-inward-dial
 port 0/0/3
 forward-digits 0
!
dial-peer voice 8409 pots
 destination-pattern .T
 port 0/0/1
!
!
sip-ua 
 set pstn-cause 31 sip-status 480
 timers expires 1800000
!
!
!
gatekeeper
 shutdown
!
!

!
scheduler allocate 20000 1000
end

CCSIP DEBUG:

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x23D03C8) with key=[24907] to table
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetSipProfilesTag: voice class SIP Profiles tag is set : 1
*Nov 26 18:43:09.685: //25117/000000000000/SIP/State/sipSPIChangeState: 0x23D03C8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x23D56B8) with key=[24908] to table
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetSipProfilesTag: voice class SIP Profiles tag is set : 1
*Nov 26 18:43:09.685: //25118/000000000000/SIP/State/sipSPIChangeState: 0x23D56B8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 621D to table
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE
*Nov 26 18:43:09.685: //25117/000000000000/SIP/State/sipSPIChangeState: 0x23D03C8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.685: //25117/000000000000/SIP/State/sipSPIChangeState: 0x23D03C8 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 621E to table
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE
*Nov 26 18:43:09.685: //25118/000000000000/SIP/State/sipSPIChangeState: 0x23D56B8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.685: //25118/000000000000/SIP/State/sipSPIChangeState: 0x23D56B8 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_srv_query: TYPE SRV query for _sip._tcp.dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: DNS query for dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_query: TYPE A query successful for dev-lync-01v.test.lcl
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: IP Address of dev-lync-01v.test.lcl is:

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: 172.16.12.28

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_srv_query: TYPE SRV query for _sip._tcp.dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43
*Nov 26 18:43:09.685: //25117/000000000000/SIP/State/sipSPIChangeState: 0x23D03C8 : State change from (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x23D03C8 key=E715629F-74D211E4-A46A80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Info/sipSPISendOptionsRequest: Associated container=0x138CA8B8 to Options
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x11A7429C, addr=172.16.12.28, port=5060, sentBy_port=0, is_req=1, transport=2, switch=0, callBack=0x7A03A18
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Nov 26 18:43:09.685: //25117/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x11A7429C
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x11A7429C, addr=172.16.12.28, port=5060, connId=2 for TCP
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent: 
OPTIONS sip:dev-lync-01v.test.lcl:5060 SIP/2.0
Via: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5ACE1D7E
From: <sip:GOPRO_CUBE.test.lcl>;tag=978AB0C-1C3E
To: <sip:dev-lync-01v.test.lcl>
Date: Wed, 26 Nov 2014 18:43:09 GMT
Call-ID: E715629F-74D211E4-A46A80FA-62F158C4@GOPRO_CUBE.test.lcl
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
CSeq: 101 OPTIONS
Contact: <sip:172.16.12.6:5060;transport=tcp>
Content-Length: 0

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: DNS query for dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_query: TYPE A query successful for dev-lync-01v.test.lcl
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: IP Address of dev-lync-01v.test.lcl is:

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: 172.16.12.28

*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43
*Nov 26 18:43:09.685: //25118/000000000000/SIP/State/sipSPIChangeState: 0x23D56B8 : State change from (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x23D56B8 key=E715629F-74D211E4-A46B80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Info/sipSPISendOptionsRequest: Associated container=0x138CA5F8 to Options
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x11A4F654, addr=172.16.12.28, port=5060, sentBy_port=0, is_req=1, transport=2, switch=0, callBack=0x7A03A18
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Nov 26 18:43:09.685: //25118/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x11A4F654
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x11A4F654, addr=172.16.12.28, port=5060, connId=2 for TCP
*Nov 26 18:43:09.685: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent: 
OPTIONS sip:dev-lync-01v.test.lcl:5060 SIP/2.0
Via: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5ACF12E0
From: <sip:GOPRO_CUBE.test.lcl>;tag=978AB0C-2045
To: <sip:dev-lync-01v.test.lcl>
Date: Wed, 26 Nov 2014 18:43:09 GMT
Call-ID: E715629F-74D211E4-A46B80FA-62F158C4@GOPRO_CUBE.test.lcl
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
CSeq: 101 OPTIONS
Contact: <sip:172.16.12.6:5060;transport=tcp>
Content-Length: 0

*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x133503FC
*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x133503FC, addr=172.16.12.28, port=5060, connid=2, transport=TCP
*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Nov 26 18:43:09.689: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header tags
*Nov 26 18:43:09.689: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 200 OK
FROM: <sip:GOPRO_CUBE.test.lcl>;tag=978AB0C-1C3E
TO: <sip:dev-lync-01v.test.lcl>;tag=14f067e6da
CSEQ: 101 OPTIONS
CALL-ID: E715629F-74D211E4-A46A80FA-62F158C4@GOPRO_CUBE.test.lcl
VIA: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5ACE1D7E
ACCEPT: application/sdp
CONTENT-LENGTH: 0
ACCEPT-ENCODING: gzip
ACCEPT-LANGUAGE: en
ALLOW: NOTIFY
ALLOW: BENOTIFY
SERVER: RTCC/5.0.0.0 MediationServer

*Nov 26 18:43:09.689: //-1/xxxxxxxxxxxx/SIP/Info/sipSPILocateInviteDialogCCB: Could not find matching transaction for this response, Dropping it
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x23C0AF8) with key=[24909] to table
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetSipProfilesTag: voice class SIP Profiles tag is set : 1
*Nov 26 18:43:09.697: //25119/000000000000/SIP/State/sipSPIChangeState: 0x23C0AF8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x23C5DE8) with key=[24910] to table
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetSipProfilesTag: voice class SIP Profiles tag is set : 1
*Nov 26 18:43:09.697: //25120/000000000000/SIP/State/sipSPIChangeState: 0x23C5DE8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 621F to table
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE
*Nov 26 18:43:09.697: //25119/000000000000/SIP/State/sipSPIChangeState: 0x23C0AF8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.697: //25119/000000000000/SIP/State/sipSPIChangeState: 0x23C0AF8 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 6220 to table
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE
*Nov 26 18:43:09.697: //25120/000000000000/SIP/State/sipSPIChangeState: 0x23C5DE8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.697: //25120/000000000000/SIP/State/sipSPIChangeState: 0x23C5DE8 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_srv_query: TYPE SRV query for _sip._tcp.dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: DNS query for dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_query: TYPE A query successful for dev-lync-01v.test.lcl
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: IP Address of dev-lync-01v.test.lcl is:

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: 172.16.12.28

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_srv_query: TYPE SRV query for _sip._tcp.dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43
*Nov 26 18:43:09.697: //25119/000000000000/SIP/State/sipSPIChangeState: 0x23C0AF8 : State change from (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x23C0AF8 key=E7173716-74D211E4-A46C80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Info/sipSPISendOptionsRequest: Associated container=0x138CA548 to Options
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x11A700A4, addr=172.16.12.28, port=5060, sentBy_port=0, is_req=1, transport=2, switch=0, callBack=0x7A03A18
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Nov 26 18:43:09.697: //25119/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x11A700A4
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x11A700A4, addr=172.16.12.28, port=5060, connId=2 for TCP
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent: 
OPTIONS sip:dev-lync-01v.test.lcl:5060 SIP/2.0
Via: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5AD02446
From: <sip:GOPRO_CUBE.test.lcl>;tag=978AB18-197A
To: <sip:dev-lync-01v.test.lcl>
Date: Wed, 26 Nov 2014 18:43:09 GMT
Call-ID: E7173716-74D211E4-A46C80FA-62F158C4@GOPRO_CUBE.test.lcl
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
CSeq: 101 OPTIONS
Contact: <sip:172.16.12.6:5060;transport=tcp>
Content-Length: 0

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x133503FC
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x133503FC, addr=172.16.12.28, port=5060, connid=2, transport=TCP
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Nov 26 18:43:09.697: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header tags
*Nov 26 18:43:09.697: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 200 OK
FROM: <sip:GOPRO_CUBE.test.lcl>;tag=978AB0C-2045
TO: <sip:dev-lync-01v.test.lcl>;tag=8358923a7
CSEQ: 101 OPTIONS
CALL-ID: E715629F-74D211E4-A46B80FA-62F158C4@GOPRO_CUBE.test.lcl
VIA: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5ACF12E0
ACCEPT: application/sdp
CONTENT-LENGTH: 0
ACCEPT-ENCODING: gzip
ACCEPT-LANGUAGE: en
ALLOW: NOTIFY
ALLOW: BENOTIFY
SERVER: RTCC/5.0.0.0 MediationServer

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPILocateInviteDialogCCB: Could not find matching transaction for this response, Dropping it
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: DNS query for dev-lync-01v.test.lcl and type:1
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_query: TYPE A query successful for dev-lync-01v.test.lcl
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: IP Address of dev-lync-01v.test.lcl is:

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: 172.16.12.28

*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43
*Nov 26 18:43:09.697: //25120/000000000000/SIP/State/sipSPIChangeState: 0x23C5DE8 : State change from (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x23C5DE8 key=E7173716-74D211E4-A46D80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Info/sipSPISendOptionsRequest: Associated container=0x138CA5A0 to Options
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x1396E6D8, addr=172.16.12.28, port=5060, sentBy_port=0, is_req=1, transport=2, switch=0, callBack=0x7A03A18
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Nov 26 18:43:09.697: //25120/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x1396E6D8
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x1396E6D8, addr=172.16.12.28, port=5060, connId=2 for TCP
*Nov 26 18:43:09.697: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent: 
OPTIONS sip:dev-lync-01v.test.lcl:5060 SIP/2.0
Via: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5AD15AA
From: <sip:GOPRO_CUBE.test.lcl>;tag=978AB18-139B
To: <sip:dev-lync-01v.test.lcl>
Date: Wed, 26 Nov 2014 18:43:09 GMT
Call-ID: E7173716-74D211E4-A46D80FA-62F158C4@GOPRO_CUBE.test.lcl
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
CSeq: 101 OPTIONS
Contact: <sip:172.16.12.6:5060;transport=tcp>
Content-Length: 0

*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x133503FC
*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x133503FC, addr=172.16.12.28, port=5060, connid=2, transport=TCP
*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Nov 26 18:43:09.701: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header tags
*Nov 26 18:43:09.701: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 200 OK
FROM: <sip:GOPRO_CUBE.test.lcl>;tag=978AB18-197A
TO: <sip:dev-lync-01v.test.lcl>;tag=7292bc3259
CSEQ: 101 OPTIONS
CALL-ID: E7173716-74D211E4-A46C80FA-62F158C4@GOPRO_CUBE.test.lcl
VIA: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5AD02446
ACCEPT: application/sdp
CONTENT-LENGTH: 0
ACCEPT-ENCODING: gzip
ACCEPT-LANGUAGE: en
ALLOW: NOTIFY
ALLOW: BENOTIFY
SERVER: RTCC/5.0.0.0 MediationServer

*Nov 26 18:43:09.701: //-1/xxxxxxxxxxxx/SIP/Info/sipSPILocateInviteDialogCCB: Could not find matching transaction for this response, Dropping it
*Nov 26 18:43:09.853: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_send_ood_options_ping: Dialpeer is down; not sending ood options ping
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x133503FC
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x133503FC, addr=172.16.12.28, port=5060, connid=2, transport=TCP
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Nov 26 18:43:09.901: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header tags
*Nov 26 18:43:09.901: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 200 OK
FROM: <sip:GOPRO_CUBE.test.lcl>;tag=978AB18-139B
TO: <sip:dev-lync-01v.test.lcl>;tag=eff2ad64f6
CSEQ: 101 OPTIONS
CALL-ID: E7173716-74D211E4-A46D80FA-62F158C4@GOPRO_CUBE.test.lcl
VIA: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK5AD15AA
ACCEPT: application/sdp
CONTENT-LENGTH: 0
ACCEPT-ENCODING: gzip
ACCEPT-LANGUAGE: en
ALLOW: NOTIFY
ALLOW: BENOTIFY
SERVER: RTCC/5.0.0.0 MediationServer

*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Info/sipSPILocateInviteDialogCCB: Could not find matching transaction for this response, Dropping it
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Error/act_sent_OODoptions_wait_response: Out of retries
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 621D
*Nov 26 18:43:10.185: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[24907] removed.
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x23D03C8 key=E715629F-74D211E4-A46A80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/ccsip_qos_cleanup: Entry
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Nov 26 18:43:10.185: //25117/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 23D03C8
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Error/act_sent_OODoptions_wait_response: Out of retries
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 621E
*Nov 26 18:43:10.185: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[24908] removed.
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x23D56B8 key=E715629F-74D211E4-A46B80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/ccsip_qos_cleanup: Entry
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Nov 26 18:43:10.185: //25118/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 23D56B8
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Error/act_sent_OODoptions_wait_response: Out of retries
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 621F
*Nov 26 18:43:10.197: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[24909] removed.
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x23C0AF8 key=E7173716-74D211E4-A46C80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/ccsip_qos_cleanup: Entry
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Nov 26 18:43:10.197: //25119/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 23C0AF8
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Error/act_sent_OODoptions_wait_response: Out of retries
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 6220
*Nov 26 18:43:10.197: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[24910] removed.
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x23C5DE8 key=E7173716-74D211E4-A46D80FA-62F158C4@GOPRO_CUBE.test.lcl
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/ccsip_qos_cleanup: Entry
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Nov 26 18:43:10.197: //25120/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 23C5DE8
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x23C5DE8) with key=[24911] to table
*Nov 26 18:43:10.477: //25122/000000000000/SIP/State/sipSPIChangeState: 0x23C5DE8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Nov 26 18:43:10.477: //25122/000000000000/SIP/Info/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200
*Nov 26 18:43:10.477: //25122/000000000000/SIP/Info/ccsip_call_setup_request: This is a TDM-IP call: callID= 25122, peer_callID = 25121
*Nov 26 18:43:10.477: //25122/000000000000/SIP/Info/ccsip_call_setup_request: This is a TDM-IP call: callID= 25122, peer_callID = 25121
*Nov 26 18:43:10.477: //25122/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : dev-lync-01v.test.lcl target_port : 5060

*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/ccsip_call_setup_request: Incrementing call counter in dial-peer [7]
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 6222 to table
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec    bytes: 0 
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: Media forking disabled
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetSipProfilesTag: voice class SIP Profiles tag is set : 1
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: Using Voice Class Codec, tag = 1
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: xcoder high-density disabled
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: Flow Mode set to FLOW_THROUGH
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIGetCallConfig: Media forking disabled
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/preprocessSetup: 
 This is a not a SIGO Call -, could be DM call 
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[24911] removed.
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/ccsip_qos_cleanup: Entry
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Nov 26 18:43:10.477: //25122/E78DA014A46E/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 23C5DE8
*Nov 26 18:43:10.477: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[24911]u all
All possible debugging has been turned off
GOPRO_CUBE#

[Anas Abueideh · Accepted solution]

Hi,

what is your router and IOS versions ?

can you describe your setup? what is the purpose of this integration ?

Regards

Anas

[rrobles007]

Hello Anas,

router is a cisco 3925 CUBE.

ROM: System Bootstrap, Version 15.0(1r)M13, RELEASE SOFTWARE (fc1)

i'm just using it as the PSTN gateway for a Lync Enterprise voice deployment. 
The VOIP dialpeers point to the Lync server. it works ok for outbound, and on inbound it looks like i might be having issues with the dial peer.

I'm basically trying to ring ext 8409 that is reachable behind dial peer 7.

It works for outbound but accoriding to debugs it looks like its not finding a matching dial peer to send 8409 down to lync server. The lync server is not receiving the digits from the PSTN gateway (CUBE)

[Ayodeji Okanlawon · Accepted solution]

From the logs the dial-peer 7 is matched...However we can see this in the logs..

Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x133503FC, addr=172.16.12.28, port=5060, connid=2, transport=TCP
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Nov 26 18:43:09.901: Parse Error: url_parseSipUrl: Received Bad Host
*Nov 26 18:43:09.901: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header

Can you remove this command from dial-peer 7 and test again

voice-class sip localhost dns:GOPRO_CUBE.test.lcl 

If it fails again please do the ff:

service sequence-numbers
service timestamps debug datetime localtime msec
logging buffered 10000000 debug
no logging console
no logging monitor
default logging rate-limit
default logging queue-limit

Then..

<Enable debugs, then test again.>

debug ccsip all

<Enable session capture to txt file in terminal program.> (such as Putty)

then do the ff:

terminal length 0
show logging

[rrobles007]

Hello Oyodeji,

thank you for your help.. i tried your suggestion and same result. i've capture the debug and attached as requested. Again, thank you for your time, your help is much appreciated. I'm rustier than I thought :)

[rrobles007]

this debug looks much different than it did before.. i think were getting closer thank you Oyodeji!! Now it looks like its complianing about a codec and maybe no originating number is being passed which might be a problem too.. (all the addressing was blank before, i attached a debug from when the command you had me remove was still in there, they look much different now)

Calling Number           : 
Called Number            : 8409
Source IP Address (Sig  ): 172.16.12.6
Destn SIP Req Addr:Port  : 172.16.12.28:5060
Destn SIP Resp Addr:Port : 172.16.12.28:5060
Destination Name         : dev-lync-01v.test.lcl

386886: *Nov 27 04:10:10.702: //30159/1D10F7D3B851/SIP/Call/sipSPIMediaCallInfo: 
Number of Media Streams: 1
Media Stream             : 1
Negotiated Codec         : No Codec   
Negotiated Codec Bytes   : 0
Nego. Codec payload      : 255 (tx), 255 (rx)
Negotiated Dtmf-relay    : 0
Dtmf-relay Payload       : 0 (tx), 0 (rx)
Source IP Address (Media): 172.16.12.6
Source IP Port    (Media): 31276
Destn  IP Address (Media):  - 
Destn  IP Port    (Media): 0
Orig Destn IP Address:Port (Media): [ - ]:0

386887: *Nov 27 04:10:10.702: //30159/1D10F7D3B851/SIP/Call/sipSPICallInfo: 
Disconnect Cause (CC)    : 127
Disconnect Cause (SIP)   : 400

[Ayodeji Okanlawon]

The lync server is complaining about your INVITE/request..

Received:
SIP/2.0 400 Bad Request
FROM: <sip:172.16.12.6>;tag=B7FC8DC-1AC1
TO: <sip:8409@dev-lync-01v.test.lcl>;tag=d749528d34
CSEQ: 101 INVITE
CALL-ID: 1D10F7D3-752211E4-B85680FA-62F158C4@172.16.12.6
VIA: SIP/2.0/TCP 172.16.12.6:5060;branch=z9hG4bK6C3C2345
CONTENT-LENGTH: 0
SERVER: RTCC/5.0.0.0 MediationServer

Is the domain dev-lync-01v.test.lcl configured on the lync Mediation server?

[rrobles007]

[rrobles007]

[rrobles007]

Thank you again for your reply Ayodeji,

I think that is where my mistake is.. the sip domain is actually gopro-test.com

I will adjust the dial peer to point to the sip domain.. i'm assuming i just modify dial peer 7 and change the sesssion target to the right sip domain? i will try this now.. thank you again.

[rrobles007]

this is what the outbound addressing looks like on a successfully made outbound call from lync client:

SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.16.12.28:53098;branch=z9hG4bKbae15049
From: "u1"<sip:6503128409;ext=8409@gopro-test.com;user=phone>;epid=96A38471D0;tag=4a061c922
To: <sip:16505206803@172.16.12.6;user=phone>;tag=E9F783C-60B
Date: Thu, 27 Nov 2014 18:43:38 GMT
Call-ID: 69304c44-c115-4ec6-b6ee-053636df78fb
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 1320 PRACK
Content-Length: 0

[Ayodeji Okanlawon]

Please send us a debug ccsip messages after changing your dial-peer to gopro-test.com, ensure your DNS can resolve this domain

[rrobles007]

Here you go Oyodeji,

i've changed the dial peer and i can ping the domain:

!
dial-peer voice 7 voip
 translation-profile outgoing toLync
 huntstop
 destination-pattern ....
 rtp payload-type comfort-noise 13
 session protocol sipv2
 session target dns:dev-lync-01v.gopro-test.com
 session transport tcp
 voice-class codec 1
 no voice-class sip localhost
 no voice-class sip early-offer forced
 voice-class sip block 183 sdp absent
 voice-class sip options-keepalive
 dtmf-relay rtp-nte

GOPRO_CUBE#            ping dev-lync-01v.gopro-test.com
Translating "dev-lync-01v.gopro-test.com"...domain server (172.16.12.10)

Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 172.16.12.28, timeout is 2 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 1/1/1 ms
GOPRO_CUBE#

according to the debug it looks like its sending it to test.lcl still?

[rrobles007]

actually it looks like i'm sending it to the correct domain now.. looks like i'm trying to send 4 digits successfully now?

To: <sip:8409@dev-lync-01v.gopro-test.com>;tag=f9a118d9eb

Date: Fri, 28 Nov 2014 00:48:28 GMT

[Suresh Subramanian]

It seems something is still wrong with the INVITE sent to Lync. Why are you removing EXPIRES header in the invite message? 

voice class sip-profiles 1
request INVITE sip-header Expires remove -----> try removing this line with NO command and check. 

​if that doesn't help, you better check with Lync technician on why it is not accepting the invite. 

the mediation server show should show something about it