'SIP/2.0 500 Internal Server Error' incoming call (CUCM8)

[mamkreutz01]

Hello all,

I'm having some difficulties trying to get incoming calls from a Microsoft Lync 2010 server to work. I have two of somewhat the same environments, one at home (for testing purposes) and one at work. These environments are not exactly the same, because I used a non default CSS and non default partition at work (where I get the above error).

To give some more insights, I configured a Microsoft Lync 2010 server next to both CallManagers (version 8) and created a Trunk between the CUCMs and the Lync servers.

At home I didn't use Calling Search Spaces, I just used the default <none> CSS. I followed some guides I found on the internet and made my own modifications to get it to work. Next I tried configuring exactly the same at my work environment (apart from the CSS settings, used the right CSS because the <none> CSS is empty at my work environment because of the usage of the custom CSS).

I even built a VPN between both environments and crossed both CUCMs with the Lync Servers on the other side of the VPN. This way I made sure the problem was on the CUCM side, because the CUCM at work was still failing with the Lync from my home environment.

I don't know if the CSS have something to do with the problem I'm having on my work environment, but as far as I know this is the only difference between the two environments (build them at the same time, reflected the changes on my work environment to my home environment every day).

When trying to call from my Lync server to my CUCM at work (with the custom CSS), I get the 'SIP/2.0 500 Internal Server Error'. These are the loggings I pulled from the CUCM's with RTMT:

Tracelog succesful environment without custom CSS:

22:42:35.182 |EnvProcessUdpPort - EnvProcessUdpHandler::fireSignal() varId = 0|1,100,213,1.2446^192.168.10.31^*
22:42:35.182 |EnvProcessUdpHandler::fireSignal - SEND: index = 0, handler = 0xb3f8c320|*^*^*
22:42:35.182 |EnvProcessUdpPort::fireSignal - SEND, destination = 192.168.10.31:5060|*^*^*
22:42:35.182 |EnvProcessUdpPort - EnvProcessUdpHandler::send(buff, 405, 192.168.10.31:5060)|*^*^*
22:42:47.472 |//SIP/SIPTcp/wait_SdlConnectionInd: Connection Indication - Listen Port = 5066, Peer Port = 64128|0,0,0,0.0^*^*
22:42:47.472 |//SIP/SIPTcp/wait_SdlConnectionInd: New Connection - Index = 1996, Listen Port = 5066, Peer Port = 64128|0,0,0,0.0^*^*
22:42:47.473 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 56|0,0,0,0.0^*^*
22:42:47.473 |//SIP/Stack/Transport/0x0/context=(nil)|0,0,0,0.0^*^*
22:42:47.473 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.10.42, port=64128, connid=1996, transport=TCP|0,0,0,0.0^*^*
22:42:47.473 |//SIP/Stack/Transport/0x0/Created new accptd conn=0xb4112e40, connid=1996, addr=192.168.10.42, port=64128, transport=TCP|0,0,0,0.0^*^*
22:42:47.473 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=955|1,100,56,1.2035^192.168.10.42^*
22:42:47.473 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.10.42 on port 64128 index 1996 with 955 bytes:
INVITE sip:1001@192.168.10.70;user=phone SIP/2.0
FROM: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;epid=BF36377560;tag=d7fd21965
TO: <sip:1001@192.168.10.70;user=phone>
CSEQ: 4294 INVITE
CALL-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
CONTACT: <sip:DP16-LYNC.domain.local:5068;transport=Tcp;maddr=192.168.10.42;ms-opaque=66c32182d5ff7e5c>
CONTENT-LENGTH: 342
SUPPORTED: 100rel
USER-AGENT: RTCC/4.0.0.0 MediationServer
CONTENT-TYPE: application/sdp
ALLOW: ACK
Allow: CANCEL,BYE,INVITE,PRACK,UPDATE

v=0
o=- 59 1 IN IP4 192.168.10.42
s=session
c=IN IP4 192.168.10.42
b=CT:1000
t=0 0
m=audio 51204 RTP/AVP 97 101 13 0 8
c=IN IP4 192.168.10.42
a=rtcp:51205
a=label:Audio
a=sendrecv
a=rtpmap:97 RED/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=ptime:20
|1,100,56,1.2035^192.168.10.42^*
22:42:47.473 |//SIP/SIPTcp/wait_SdlReadRsp: SignalCounter = 2033|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.10.42, port=64128, connid=1996, transport=TCP|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0x0/Added context(0xb4001de8) with key=[4425] to table|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.10.42,Port 64128, Transport 2, SentBy Port 64128|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/States/0xb4001de8/0xb4001de8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.10.42,Port 64128, Transport 2, SentBy Port 5060|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.10.42,Port 64128, Transport 2, SentBy Port 64128|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0x0/No GTD found in inbound container|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0xb4001de8/****Adding to UAS Request table.|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0xb4001de8/Added to table. ccb=0xb4001de8 key=7736608e-8acd-4dca-b6ef-0de8f2454e461001|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0xb4001de8/Calling name Lync User, number 2002, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 1001, o|1,100,56,1.2035^192.168.10.42^*
22:42:47.663 |//SIP/Stack/Info/0xb4001de8/Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/SIPHandler/ccbId=0/scbId=0/sipSPIGetCallExtensionSupported: SIPRel1xxEnabledServiceParamSetting=0 , ccb->pld.outboundRel1xx=1|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_EXPIRES value=1800000 retries=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_EXPIRES value=1800000 retries=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo: parseResult[1]|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/SIPHandler/ccbId=0/scbId=0/getCodecAndFramesFromSDP: -- Error!!!!! Cannot convert SDP pt=13 to CM payload type.|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Info/0xb4001de8/ccsip_api_call_setup_ind returned: SIP_SUCCESS|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Info/0xb4001de8/Adding call id 1152 to table|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Transport/0xb4001de8/msg=0xb7b3d8a8, addr=192.168.10.42, port=64128, sentBy_port=64128, is_req=0, transport=2, switch=0, callBack=(nil)|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Transport/0xb4001de8/Proceedable for sending msg immediately|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Transport/0xb4001de8/switch transport is 0|1,100,56,1.2035^192.168.10.42^*
22:42:47.664 |//SIP/Stack/Transport/0xb4001de8/Trying to send resp=0xb7b3d8a8 to default port=64128|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/Stack/Transport/0xb4001de8/Connection obtained...sending msg=0xb7b3d8a8|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb7b3d8a8, addr=192.168.10.42, port=64128, connId=1996 for TCP|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/Stack/States/0xb4001de8/0xb4001de8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_RECD_INVITE, SUBSTATE_NONE)|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/Stack/Info/0xb4001de8/Previous Hop 192.168.10.42:5068|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/SIPD(1,65,8)/ccbId=4434/scbId=0/restart0_SIPSetupInd: mTsp.deviceName[LyncServer]|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/SIPD(1,65,8)/ccbId=4434/scbId=0/restart0_SIPSetupInd: mTsp.deviceName[LyncServer], transformDn 1001|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/SIPD(1,65,8)/ccbId=4434/scbId=0/updateSrtpFallbackSupport: mTsp.deviceName[LyncServer] - sRTP fallback supported = False|1,100,56,1.2035^192.168.10.42^*
22:42:47.665 |//SIP/SIPCdpc(0,0,0)/ci=0/ccbId=0/scbId=0/globalize: Performing stripAndPrependDigits --- Prefix data = , Strip Data = 0|*^*^*
22:42:47.665 |//SIP/SIPCdpc(0,0,0)/ci=0/ccbId=0/scbId=0/globalize: CallingNumber after stripAndPrependDigits 2002|*^*^*
22:42:47.665 |SPROC  getCtrlPid - callingNum=2002, inputCtrlPid=(1,100,195,1)|*^*^*
22:42:47.665 |DbMobility: getMatchedRemDest starts: cnumber = 2002|*^*^*
22:42:47.665 |DbMobility: getMatchedRemDest: full match case|*^*^*
22:42:47.666 |DbMobility: can't find remdest 2002 in map|*^*^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/getDefAe: SIPCdpc=20, nodeId=1, processNumber=65  ci=0, branch=0|1,100,66,20.1^*^*
22:42:47.666 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.10.42 on port 64128 index 1996
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
From: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;epid=BF36377560;tag=d7fd21965
To: <sip:1001@192.168.10.70;user=phone>
Date: Sun, 07 Nov 2010 21:42:47 GMT
Call-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
CSeq: 4294 INVITE
Allow-Events: presence
Content-Length: 0

|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/handleSIPUASSessionExpires: isMidCall[0], method[102]|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/handleSIPUASSessionExpires: supported NULL|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/handleSIPUASPeriodicSessionRefresh: Failed session timers, switch to periodic refresh, method [102]|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/setPeriodicReInviteTimer: interval[900] secs|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/processIncomingGeolocationInfo: no Geolocation support|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/preProcessOffer: audiomLines[0]: rtp=1,srtp=0,deviceNOTSrtpCapable=1,numCrypto=0,isOfferFromCCM=0,sipEndpointCanRcvSrtpOffers=0,deviceSupportsSrtpFB=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.666 |DbMobility: getMatchedRemDest starts: cnumber = 2002|*^*^*
22:42:47.666 |DbMobility: getMatchedRemDest: full match case|*^*^*
22:42:47.666 |DbMobility: can't find remdest 2002 in map|*^*^*
22:42:47.667 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPD(1,65,8)/ccbId=4434/scbId=0/restart0_CcCiRes: Adding Cdpc Pid (1,100,66,20) with  mapKey 22544754 and branch 0 to mCiToPid table|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/isMidCallFallbackSupported:  getXCiscoViPRFallbackID returned false, proceed without PSTN fallback|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getDefAe: SIPCdpc=20, nodeId=1, processNumber=65  ci=22544754, branch=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/sendPolicyAndRSVPRegisterReq: capCount[2], videoCap[0], dataCap[2], earlyOffer[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/sendPolicyAndRSVPRegisterReq: preconditions: Not using preconditions, rsvpStatus[34]|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/updateAllowedMethods: mEndpointAllowedMethods=00f9|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |setEndpointsDtmfCaps: Detected inband DTMF support.|*^*^*
22:42:47.667 |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=0, Inband=0(0) mEndppointsDtmfCaps...UNSOL=0, KPML=0, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=3, mMtpAllocated=0|*^*^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getDefAe: SIPCdpc=20, nodeId=1, processNumber=65  ci=22544754, branch=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getIdentityIncomingSIPMsg: fIdParseRes=[1], fRemoteNum[2002], fRemoteNam[Lync User], fRemoteNumPi[1], fRemoteNamPi[1], fRemoteSi[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/preProcessOffer: audiomLines[0]: rtp=1,srtp=0,deviceNOTSrtpCapable=1,numCrypto=0,isOfferFromCCM=0,sipEndpointCanRcvSrtpOffers=0,deviceSupportsSrtpFB=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getDefCcRegister: Secure status=1, mSrtpPresent=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.667 |//SIP/SIPCdpc(0,0,0)/ci=0/ccbId=0/scbId=0/globalize: Performing stripAndPrependDigits --- Prefix data = , Strip Data = 0|*^*^*
22:42:47.668 |//SIP/SIPCdpc(0,0,0)/ci=0/ccbId=0/scbId=0/globalize: CallingNumber after stripAndPrependDigits 2002|*^*^*
22:42:47.668 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getDefCcSetupInd: No Replaces header is Present|1,100,56,1.2035^192.168.10.42^*
22:42:47.668 |CMSIPUtility::decodeRPHdr - no RP Header found, defaulting to to -000000.0|*^*^*
22:42:47.668 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/extractGuidHeader: guid Header = F4B0EB00CD711D5700000014460AA8C0|1,100,56,1.2035^192.168.10.42^*
22:42:47.668 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/inCall_waitRSVPRes_PolicyAndRSVPRegisterRes: offAns: sip/cm=1/-1|1,100,56,1.2035^192.168.10.42^*
22:42:47.668 |Cdcc - (0000014) - storeDchanCrp - secure capability on side 0 is (1,1)|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Cdcc::preliminaryProcessCcSetupInd(0000014): precLvl=5|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit Analysis: star_DaReq: daReq.partitionSearchSpace(), filteredPartitionSearchSpaceString(), partitionSearchSpaceString()|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit Analysis: Host Address=192.168.10.70 MATCHES this node's IPv4 address.|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit Analysis: star_DaReq: Matching SIP URL, Numeric User, user=1001|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit Analysis: getDaRes data: daRes.ssType=[0] Intercept DAMR.sstype=[16777222], TPcount=[0], DAMR.NotifyCount=[1], DaRes.NotifyCount=[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit analysis: match(pi="2", fqcn="", cn="2002",plv="5", pss="", TodFilteredPss="", dd="1001",dac="0")|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 |Digit analysis: analysis results|1,100,56,1.2035^192.168.10.42^*
22:42:47.669 ||PretransformCallingPartyNumber=2002
|CallingPartyNumber=2002
|DialingPartition=
|DialingPattern=1001
|FullyQualifiedCalledPartyNumber=1001
|DialingPatternRegularExpression=(1001)
|DialingWhere=
|PatternType=Enterprise
|PotentialMatches=NoPotentialMatchesExist
|DialingSdlProcessId=(0,0,0)
|PretransformDigitString=1001
|PretransformTagsList=SUBSCRIBER
|PretransformPositionalMatchList=1001
|CollectedDigits=1001
|UnconsumedDigits=
|TagsList=SUBSCRIBER
|PositionalMatchList=1001
|VoiceMailbox=
|VoiceMailCallingSearchSpace=
|VoiceMailPilotNumber=8800
|RouteBlockFlag=RouteThisPattern
|RouteBlockCause=0
|AlertingName=Wesley Levels
|UnicodeDisplayName=Wesley Levels
|DisplayNameLocale=8
|InterceptPartition=
|InterceptPattern=1001
|InterceptWhere=
|InterceptSdlProcessId=(0,0,0)
|InterceptSsType=16777222
|InterceptSsKey=0
|InterceptSsNotifyType=1
|OverlapSendingFlagEnabled=0
|WithTags=
|WithValues=
|CallingPartyNumberPi=NotSelected
|ConnectedPartyNumberPi=NotSelected
|CallingPartyNamePi=NotSelected
|ConnectedPartyNamePi=NotSelected
|CallManagerDeviceType=NoDeviceType
|PatternPrecedenceLevel=Routine
|CallableEndPointName=[e83b03bb-6a64-2cfb-6840-38465169dd87]
|PatternNodeId=[e83b03bb-6a64-2cfb-6840-38465169dd87]
|AARNeighborhood=[]
|AARDestinationMask=[]
|AARKeepCallHistory=true
|AARVoiceMailEnabled=false
|NetworkLocation=OnNet
|Calling Party Number Type=Cisco Unified CallManager
|Calling Party Numbering Plan=Cisco Unified CallManager
|Called Party Number Type=Cisco Unified CallManager
|Called Party Numbering Plan=Cisco Unified CallManager
|ProvideOutsideDialtone=false
|AllowDeviceOverride=false
|AlternateMatches= Information Not Available
|TranslationPatternDetails= Information Not Available
|ResourcePriorityNamespace=
|PatternRouteClass=RouteClassDefault|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |SMDMSharedData::findAliasRegInfo - AliasName = e83b03bb-6a64-2cfb-6840-38465169dd87 not in AliasInfo hashmap|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |DeviceManager::star_DmPidReq - RequestedName=e83b03bb-6a64-2cfb-6840-38465169dd87 LookupName=e83b03bb-6a64-2cfb-6840-38465169dd87|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |SMDMSharedData::findLocalDevice - Name=1001: Key=e83b03bb-6a64-2cfb-6840-38465169dd87 isActvie=1 Pid=(1,154,1) found|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |Digit analysis: wait_DmPidRes- Partition=[] Pattern=[1001] Where=[],cmDeviceType=[UserDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=LineControl(1,100,154,1)|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |processCCMFeatureData: operationIeIdd=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.670 |findUnfiredInterceptOnPattern numOfPatterns = 1|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |ForwardManager - findCallBySsParty - mPartyToActiveCallIndexMap entry NOT found for party= 22544754 |1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |ForwardManager - findActivationEntryBySsParty - mPartyToActivationIndexMap - Entry NOT found for party= 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |ForwardManager - addActiveCallTableEntry - Added entry for party= 22544754 callkey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - Created! - callKey= 0x8|1,100,177,8.1^*^*
22:42:47.671 |Forwarding - getInterceptTableEntry - Successful for nppkid e83b03bb-6a64-2cfb-6840-38465169dd87|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - logInterceptTableEntry
{
  callKey= 0x8,
  ssKey = 0, recordStatus 0,
  dnPattern =  1001, dnPartition = , dnPartitionSearchSpace = ,
  cfa     = , cfaToVM     = 0, cfaCss     = ,
  cfb     = , cfbToVM     = 1, cfbCss     = ,
  cfbInt  = , cfbIntToVM  = 1, cfbIntCss  = ,
  cfna    = , cfnaToVM    = 1, cfnaCss = , cfnaTimer = 18,
  cfnaInt = , cfnaIntToVM = 1, cfnaIntCss = ,
  cfur    = , cfurToVM    = 1, cfurCss    = ,
  cfurInt = , cfurIntToVM = 1, cfurIntCss = ,
  cfap    = , cfapToVM    = 0, cfapCss = , cfapTimer = 0,
  pff     = , pffToVM     = 1, pffCss     = ,
  pffInt  = , pffIntToVM  = 1, pffIntCss  = ,
  pffCfna = 0, pffCfb      = 0,
  fullyQualifiedDirectoryNumberMask = ,
  patternUsage = 2,
  pffCfnaEnabled = 0, pffCfbEnabled=0
}
|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - awaitForwardInitiation_SsInterceptInd - New CFAP destination - :, duration= 0, callKey= 0x8, internal-call=false, hunt-pilot= false|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - sendExtendCallReq - callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - registerRelRejInterceptRequest - callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - unregisterRelRejInterceptRequest - callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - registerRelRejInterceptRequest - Registered RelRej Intercept- party= 22544754, callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.671 |Forwarding - sendExtendCallReq - Extended Call to party= 22544754, callKey= 0x8 |1,100,56,1.2035^192.168.10.42^*
22:42:47.672 |add an entry into release intercept queue|1,100,56,1.2035^192.168.10.42^*
22:42:47.672 |release intercept entry, ssType = 16777222, ssKey = 8, handler = 22544756|1,100,56,1.2035^192.168.10.42^*
22:42:47.672 |isItSafeToExtendCall dchanPid = (1 100 154 1)|1,100,56,1.2035^192.168.10.42^*
22:42:47.672 |findUnfiredInterceptOnPattern numOfPatterns = 1|1,100,56,1.2035^192.168.10.42^*
22:42:47.672 |Cdcc::sendCcSetupReq: precLvl=5|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |ForwardManager - wait_SsDataInd - Key= 0x0, party= 22544754, BCC= 1|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |ForwardManager - findCallBySsParty - Found entry for party= 22544754, callkey= 0x8 |1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |ForwardManager - wait_SsDataInd (SETUP) - mPartyToActiveCallIndexMap Added Entry for Destparty= 22544755, callkey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |LineControl(1) - 0 calls, 0 CiReq, busyTrigger=2, maxCall=4|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |LineControl(1) - Get call instance=1 for CI=22544755|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |LineControl(1): restart0_CcSetupReq update State of cdpc (18) to receive7|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |Forwarding - awaitingCallResponse_SsDataInd - SETUP - Updating precLvl to 5|1,100,56,1.2035^192.168.10.42^*
22:42:47.673 |LineCdpc(18): -dispatchToAllDevices-, sigName=CcSetupReq, device=0611913828:Wesley_RDP|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |LineCdpc(18): -dispatchToAllDevices-, sigName=CcSetupReq, device=2001:Wesley_RDP|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |LineCdpc(18): -dispatchToAllDevices-, sigName=CcSetupReq, device=SEP0006D744732C|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |SNRD::wait_CcSetupReq    (0000001) SendingDchan[1], ci(22544755), featureCallType[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |SNRD::wait_CcSetupReq    (0000001) SNR not enabled|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |SNRD::wait_CcSetupReq    (0000002) SendingDchan[1], ci(22544755), featureCallType[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |SNRD::wait_CcSetupReq    (0000002) SNR not enabled|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |StationD:    (0000002) DEBUG whatToDo: line=1 calls=0 limit=4, busy=2. GCI=(1, 17022), PL=(5, 0).|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |StationD:    (0000002) DEBUG  whatToDo: busy trigger not hit... send to open appearance|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |StationD:    (0000002) DEBUG- getLineRingSetting: retVal=4.|1,100,56,1.2035^192.168.10.42^*
22:42:47.674 |StationD:    (0000002) DEBUG- saveRinger for: ci=22544755, line=1, mode=3, precedence=5, callPhase=5.|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) DEBUG- saveRinger: ci=22544755, line=1, mode=3, precedence=5, callPhase=5, modifier=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) INFO  sendCallAcceptReq: Try to send StationLineCallAccept to cdpc=18 .|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) playRinger for: ci=22544755.|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) DEBUG- getLineRingSetting: retVal=4.|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) DEBUG- getLineRingSetting: retVal=4.|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |StationD:    (0000002) DEBUG- getLineRingSetting: retVal=4.|1,100,56,1.2035^192.168.10.42^*
22:42:47.675 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
22:42:47.675 |Locations_reserveBandwidth -- cdccPID=(1.194.14) Orig=0=Dest=0 no need to reserve bw.|*^*^*
22:42:47.675 |StationD:    (0000002) DEBUG- star_DSetCallState(0) State of cdpc(18) is 0.|1,100,51,18.1^*^*
22:42:47.676 |StationD:    (0000002) DEBUG- star_DSetCallState(2) State of cdpc(18) is 0.|1,100,56,1.2035^192.168.10.42^*
22:42:47.676 | LocalizeCgpnAndSendOutpulsedNumber: StationCdpc on device SEP0006D744732C , CSS = ,useDevicePoolCgpnCss =1 AlternateCgpn(global)=2002 cgpn=2002|1,100,56,1.2035^192.168.10.42^*
22:42:47.676 |StationCdpc:    CcSetupReq - unicodeConnectedUnicodeDisplayName='' asciiConnectedDisplayName='Lync User'|1,100,56,1.2035^192.168.10.42^*
22:42:47.676 |StationCdpc:    CcSetupReq - unicodeCallingPartyName='' asciiCallingPartyName='Lync User' callingParty='2002' unicodeCalledPartyName='Wesley Levels' asciiCalledPartyName='Wesley Levels' calledParty='1001' cgIP=IpAddr.type:0 ipv4Addr:0xc0a80a2a(192.168.10.42) |1,100,56,1.2035^192.168.10.42^*
22:42:47.676 |StationD:    (0000002) DEBUG- star_DSetCallState(0) State of cdpc(18) is 2.|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) CallState callState=4 lineInstance=1 callReference=22544755 privacy=0 precedenceLv=4 precedenceDm=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) SelectSoftKeys instance=1 reference=22544755 softKeySetIndex=3 validKeyMask=ffffffff.|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) DisplayPromptStatus timeOut=0 Status='€ 2002' content='From 2002' line=1 CI=22544755 ver=8560000b.|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) DisplayPriNotify timeOutValue=10 pri=5 notify='€ 2002' content='From 2002' ver=8560000b.|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) (1,100,9,759) CallInfo callingPartyName='Lync User' callingParty=2002 cgpnVoiceMailbox=    alternateCallingParty= 2002    calledPartyName='Wesley Levels' calledParty=1001 cdpnVoiceMailbox=    originalCalledPartyName='Wesley Levels' originalCalledParty=1001 originalCdpnVoiceMailbox= originalCdpnRedirectReason=0    lastRedirectingPartyName='Wesley Levels' lastRedirectingParty=1001 lastRedirectingVoiceMailbox= lastRedirectingReason=0    callType=1(InBound) lineInstance=1 callReference=22544755. version: 8560000b|1,100,56,1.2035^192.168.10.42^*
22:42:47.677 |StationD:    (0000002) SetLamp mode=5, stim=9 stimInst=1.|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |StationD:    (0000002) DEBUG- star_DSetCallPhase updateACall=22544755 from Phase=5 to  callPhase=5.|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |LineControl::sendSNFNotifyIndForPresenceWithAlerting mPrecenceWithAlertingChangeNotifySubscribed=0, calllist#=1|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |StationD:    (0000002) DEBUG- star_DSetCallState(8) State of cdpc(18) is 0.|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |StationD:    (0000002) SetRinger ringMode=3(OutsideRing).|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |LineCdpc(18)call_received7_CcRegisterPartyB - # device responsed = 1, mPartyBSent = 0|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |LineControl(1): star_DSetCallState(2), State of cdpc (18) is 2|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |Cdcc - (0000014) - updateDchanCrp - secure capability on side 1 is (1,1)|1,100,56,1.2035^192.168.10.42^*
22:42:47.678 |processCCMFeatureData: operationIeIdd=0|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |ForwardManager - wait_SsExtendCallRes - mPartyToActiveCallIndexMap - Added Entry for Destparty= 22544755, callkey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |ForwardManager - findCallBySsParty - Found entry for party= 22544754, callkey= 0x8 |1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |ForwardManager - wait_SsDataInd - Key= 0x0, party= 22544755, BCC= 4|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |ForwardManager - findCallBySsParty - Found entry for party= 22544755, callkey= 0x8 |1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |Forwarding - awaitingCallResponse_SsExtendCallRes - DestParty= 22544755, callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |Forwarding - awaitingCallResponse_SsDataInd, BASIC_CALL_ALERTING, precLvl=5|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |Forwarding - startCFNATimer (18000) for line entry 1001 - callKey= 0x8|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/transformConnectedNumber: device LyncServer , CSS = , useDPCss[cg=1, conn=1], connPartyNum=1001|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/getCcSignalCnNameAndNumberInfo: identityFlag=0xff|1,100,56,1.2035^192.168.10.42^*
22:42:47.679 |GeolocInfo -getGeolocDetailAndFilter|*^*^*
22:42:47.680 |GeolocInfo -readGeolocationRecord: Unspecified |*^*^*
22:42:47.680 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/processGeolocationInfoFromCC: result of compareGeolocations complete[4], filter[4]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/setCnNameAndNumber: connectedData - Name Wesley Levels Number 1001 NumberPi 1 NamePi 1 Si 1, LocalData - NumberPi 1 NamePi 0|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/setIdentityOutgoingSIPMsg: identityFlag=[PAI;RPID;], privacyType[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=0/scbId=0/setPresentationIndication: namePi[1], numPi[1]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=0/scbId=0/setScreeningIndication: si[1], oct3a[81]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=0/scbId=0/setIdentityHeaders: ccb[b4001de8], currLocalNum[1001], currLocalNam[Wesley Levels], callbackNumber[], localNumPi[1], localNamPi[1], id.flag[10], id.privacy[0]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=0/scbId=0/setRpidHeader: rpidHdrStr["Wesley Levels" <sip:1001@192.168.10.70>;party=called;screen=yes;privacy=off]|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 3 for event 5|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Info/0xb4001de8/****Adding to UAS Response table.|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Info/0xb4001de8/Added to table. ccb=0xb4001de8 key=7736608e-8acd-4dca-b6ef-0de8f2454e466106E09B-4B79-4114-9C11-A954B3A049BA-22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=4434/scbId=0/findDevicePID: Routed to SIPD by ccbId/scbId|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Info/0xb4001de8/Associated container=0xb3c8cb10 to Invite Response 180|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/Sending 180 Response to the Transport Layer|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/msg=0xb7b3dc00, addr=192.168.10.42, port=64128, sentBy_port=64128, is_req=0, transport=2, switch=0, callBack=0xa101560|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/Proceedable for sending msg immediately|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/switch transport is 0|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/Trying to send resp=0xb7b3dc00 to default port=64128|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0xb4001de8/Connection obtained...sending msg=0xb7b3dc00|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb7b3dc00, addr=192.168.10.42, port=64128, connId=1996 for TCP|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/Info/0xb4001de8/Sent a 18x Response|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/SIPHandler/ccbId=4434/scbId=0/findDevicePID: Routed to SIPD by ccbId/scbId|1,100,56,1.2035^192.168.10.42^*
22:42:47.680 |//SIP/Stack/States/0xb4001de8/0xb4001de8 : State change from (STATE_RECD_INVITE, SUBSTATE_NONE)  to (STATE_SENT_ALERTING, SUBSTATE_NONE)|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPidGivenCcbidAndCi: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.10.42 on port 64128 index 1996
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
From: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;epid=BF36377560;tag=d7fd21965
To: <sip:1001@192.168.10.70;user=phone>;tag=6106e09b-4b79-4114-9c11-a954b3a049ba-22544754
Date: Sun, 07 Nov 2010 21:42:47 GMT
Call-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
CSeq: 4294 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence
Contact: <sip:1001@192.168.10.70:5066;transport=tcp>
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Wesley Levels" <sip:1001@192.168.10.70>
Remote-Party-ID: "Wesley Levels" <sip:1001@192.168.10.70>;party=called;screen=yes;privacy=off
Content-Length: 0

|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPidGivenCcbidAndCi: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2035^192.168.10.42^*
22:42:47.681 |//SIP/SIPCdpc(1,66,20)/ci=22544754/ccbId=4434/scbId=0/star_SIPUpdateAllowed: mIsUpdateForSignalingAllowed = 1  mIsUpdateForMediaAllowed = 0  mPendingOutgoingUpdate = 0|1,100,56,1.2035^192.168.10.42^*
22:42:48.202 |//SIP/SIPTcp/wait_SdlConnectionInd: Connection Indication - Listen Port = 5066, Peer Port = 64129|0,0,0,0.0^*^*
22:42:48.202 |//SIP/SIPTcp/wait_SdlConnectionInd: New Connection - Index = 1997, Listen Port = 5066, Peer Port = 64129|0,0,0,0.0^*^*
22:42:48.202 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 56|0,0,0,0.0^*^*
22:42:48.202 |//SIP/Stack/Transport/0x0/context=(nil)|0,0,0,0.0^*^*
22:42:48.202 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.10.42, port=64129, connid=1997, transport=TCP|0,0,0,0.0^*^*
22:42:48.202 |//SIP/Stack/Transport/0x0/Created new accptd conn=0xb4112fd8, connid=1997, addr=192.168.10.42, port=64129, transport=TCP|0,0,0,0.0^*^*
22:42:48.205 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=461|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.10.42 on port 64129 index 1997 with 461 bytes:
OPTIONS sip:192.168.10.70 SIP/2.0
FROM: <sip:dp16-lync.domain.local:5068;transport=Tcp;ms-opaque=66c32182d5ff7e5c>;epid=BF36377560;tag=36b3b6454
TO: <sip:192.168.10.70>
CSEQ: 4295 OPTIONS
CALL-ID: 5f518788a58a498aad1198863f9886a1
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.10.42:64129;branch=z9hG4bK66b2455d
CONTACT: <sip:DP16-LYNC.domain.local:5068;transport=Tcp;maddr=192.168.10.42>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/4.0.0.0 MediationServer

|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/SIPTcp/wait_SdlReadRsp: SignalCounter = 2034|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.10.42, port=64129, connid=1997, transport=TCP|1,100,56,1.2036^192.168.10.42^*
22:42:48.205 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0x0/Added context(0xb66e67f0) with key=[4426] to table|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.10.42,Port 64129, Transport 2, SentBy Port 64129|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/States/0xb66e67f0/0xb66e67f0 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.10.42,Port 64129, Transport 2, SentBy Port 5060|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.10.42,Port 64129, Transport 2, SentBy Port 64129|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/SIPHandler/ccbId=4435/scbId=0/findDevicePID: Routed to SIPD by sipAddr|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/ccsip_api_options_ind returned: SIP_SUCCESS|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/States/0xb66e67f0/0xb66e67f0 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/****Adding to UAS Request table.|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/Added to table. ccb=0xb66e67f0 key=5f518788a58a498aad1198863f9886a1|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/Adding call id 1153 to table|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 3 for event 39|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/Associated container=0xb3c8dd10 to Options Response|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0xb66e67f0/msg=0xb400d138, addr=192.168.10.42, port=64129, sentBy_port=64129, is_req=0, transport=2, switch=0, callBack=0xa1036f4|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0xb66e67f0/Proceedable for sending msg immediately|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0xb66e67f0/switch transport is 0|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0xb66e67f0/Trying to send resp=0xb400d138 to default port=64129|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0xb66e67f0/Connection obtained...sending msg=0xb400d138|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb400d138, addr=192.168.10.42, port=64129, connId=1997 for TCP|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0xb66e67f0/Removing call id 1153|1,100,56,1.2036^192.168.10.42^*
22:42:48.206 |//SIP/Stack/Info/0x0/Context for key=[4426] removed.|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0xb66e67f0/****Deleting from UAS Request table.|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0xb66e67f0/Deleting from table. ccb=0xb66e67f0 key=5f518788a58a498aad1198863f9886a1|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0xb66e67f0/****Deleting from UAS Response table.|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0xb66e67f0/There are 0 events on the internal queue that are going to be free'd|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0xb66e67f0/Freeing ccb b66e67f0|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Info/0x0/NO context for key[4426]|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/Stack/Transport/0x0/gcb has cleanedup, Done with send operations for this context|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2036^192.168.10.42^*
22:42:48.207 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.10.42 on port 64129 index 1997
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.10.42:64129;branch=z9hG4bK66b2455d
From: <sip:dp16-lync.domain.local:5068;transport=Tcp;ms-opaque=66c32182d5ff7e5c>;epid=BF36377560;tag=36b3b6454
To: <sip:192.168.10.70>;tag=345591966
Date: Sun, 07 Nov 2010 21:42:48 GMT
Call-ID: 5f518788a58a498aad1198863f9886a1
CSeq: 4295 OPTIONS
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0

|1,100,56,1.2036^192.168.10.42^*
22:42:49.215 |//SIP/SIPTcp/wait_SdlConnectionInd: Connection Indication - Listen Port = 5066, Peer Port = 64390|0,0,0,0.0^*^*
22:42:49.215 |//SIP/SIPTcp/wait_SdlConnectionInd: New Connection - Index = 1998, Listen Port = 5066, Peer Port = 64390|0,0,0,0.0^*^*
22:42:49.215 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 56|0,0,0,0.0^*^*
22:42:49.215 |//SIP/Stack/Transport/0x0/context=(nil)|0,0,0,0.0^*^*
22:42:49.215 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.20.20, port=64390, connid=1998, transport=TCP|0,0,0,0.0^*^*
22:42:49.215 |//SIP/Stack/Transport/0x0/Created new accptd conn=0xb4112f50, connid=1998, addr=192.168.20.20, port=64390, transport=TCP|0,0,0,0.0^*^*
22:42:49.221 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=447|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.20.20 on port 64390 index 1998 with 447 bytes:
OPTIONS sip:192.168.10.70 SIP/2.0
FROM: <sip:el24-lync.uc.local:5068;transport=Tcp;ms-opaque=d6e734c4ed1323e8>;epid=625504215D;tag=67653232c8
TO: <sip:192.168.10.70>
CSEQ: 959 OPTIONS
CALL-ID: 1f008ccab7a74262a5e48dcfd2e07424
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.20.20:64390;branch=z9hG4bKe747b84d
CONTACT: <sip:EL24-LYNC.uc.local:5068;transport=Tcp;maddr=192.168.20.20>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/4.0.0.0 MediationServer

|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/SIPTcp/wait_SdlReadRsp: SignalCounter = 2035|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.20.20, port=64390, connid=1998, transport=TCP|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Info/0x0/Added context(0xb4000018) with key=[4427] to table|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.20.20,Port 64390, Transport 2, SentBy Port 64390|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/States/0xb4000018/0xb4000018 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.20.20,Port 64390, Transport 2, SentBy Port 5060|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.20.20,Port 64390, Transport 2, SentBy Port 64390|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/SIPHandler/ccbId=4436/scbId=0/findDevicePID: Routed to SIPD by sipAddr|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/Info/0xb4000018/ccsip_api_options_ind returned: SIP_SUCCESS|1,100,56,1.2037^192.168.20.20^*
22:42:49.221 |//SIP/Stack/States/0xb4000018/0xb4000018 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/****Adding to UAS Request table.|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Added to table. ccb=0xb4000018 key=1f008ccab7a74262a5e48dcfd2e07424|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Adding call id 1154 to table|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 3 for event 39|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Associated container=0xb3c932d8 to Options Response|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0xb4000018/msg=0xb400d138, addr=192.168.20.20, port=64390, sentBy_port=64390, is_req=0, transport=2, switch=0, callBack=0xa1036f4|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0xb4000018/Proceedable for sending msg immediately|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0xb4000018/switch transport is 0|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0xb4000018/Trying to send resp=0xb400d138 to default port=64390|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0xb4000018/Connection obtained...sending msg=0xb400d138|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb400d138, addr=192.168.20.20, port=64390, connId=1998 for TCP|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Removing call id 1154|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0x0/Context for key=[4427] removed.|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/****Deleting from UAS Request table.|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Deleting from table. ccb=0xb4000018 key=1f008ccab7a74262a5e48dcfd2e07424|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/****Deleting from UAS Response table.|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/There are 0 events on the internal queue that are going to be free'd|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0xb4000018/Freeing ccb b4000018|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Info/0x0/NO context for key[4427]|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/Stack/Transport/0x0/gcb has cleanedup, Done with send operations for this context|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2037^192.168.20.20^*
22:42:49.222 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.20.20 on port 64390 index 1998
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.20.20:64390;branch=z9hG4bKe747b84d
From: <sip:el24-lync.uc.local:5068;transport=Tcp;ms-opaque=d6e734c4ed1323e8>;epid=625504215D;tag=67653232c8
To: <sip:192.168.10.70>;tag=217680798
Date: Sun, 07 Nov 2010 21:42:49 GMT
Call-ID: 1f008ccab7a74262a5e48dcfd2e07424
CSeq: 959 OPTIONS
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0

|1,100,56,1.2037^192.168.20.20^*
22:42:58.596 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=546|1,100,56,1.2038^192.168.10.42^*
22:42:58.596 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.10.42 on port 64128 index 1996 with 546 bytes:
CANCEL sip:1001@192.168.10.70;user=phone SIP/2.0
FROM: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;tag=d7fd21965;epid=BF36377560
TO: <sip:1001@192.168.10.70;user=phone>
CSEQ: 4294 CANCEL
CALL-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
CONTACT: <sip:DP16-LYNC.domain.local:5068;transport=Tcp;maddr=192.168.10.42>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/4.0.0.0 MediationServer
Reason: SIP;cause=487;text="Request Terminated";source=client

|1,100,56,1.2038^192.168.10.42^*
22:42:58.596 |//SIP/SIPTcp/wait_SdlReadRsp: SignalCounter = 2036|1,100,56,1.2038^192.168.10.42^*
22:42:58.596 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0x0/gConnTab=0xb4110db0, addr=192.168.10.42, port=64128, connid=1996, transport=TCP|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Info/0xb4001de8/*****CCB found in UAS Request table. ccb=0xb4001de8|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.10.42,Port 64128, Transport 2, SentBy Port 5060|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 192.168.10.42,Port 64128, Transport 2, SentBy Port 64128|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/SIPHandler/ccbId=0/scbId=0/parseReasonHeaderField: Reason Header: SIP Cause: 487, mapped Q.850 Cause: 16|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_EXPIRES value=1800000 retries=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/States/0xb4001de8/0xb4001de8 : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE)  to (STATE_DISCONNECTING, SUBSTATE_NONE)|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/Sending CANCEL Response to the transport layer|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/msg=0xb400d138, addr=192.168.10.42, port=64128, sentBy_port=64128, is_req=0, transport=2, switch=0, callBack=(nil)|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/Proceedable for sending msg immediately|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/switch transport is 0|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/Trying to send resp=0xb400d138 to default port=64128|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0xb4001de8/Connection obtained...sending msg=0xb400d138|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb400d138, addr=192.168.10.42, port=64128, connId=1996 for TCP|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.10.42 on port 64128 index 1996
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
From: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;epid=BF36377560;tag=d7fd21965
To: <sip:1001@192.168.10.70;user=phone>
Date: Sun, 07 Nov 2010 21:42:58 GMT
Call-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
CSeq: 4294 CANCEL
Content-Length: 0

|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Info/0x0/No GTD found in inbound container|1,100,56,1.2038^192.168.10.42^*
22:42:58.597 |//SIP/Stack/Info/0xb4001de8/Initiate call disconnect(16) for incoming call|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |//SIP/SIPHandler/ccbId=4434/scbId=0/findDevicePID: Routed to SIPD by ccbId/scbId|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPidGivenCcbidAndCi: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |cdrWrite PER RR, orig = 0, lrn = 0, current = 0|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |Cdcc::isStaticTransactionApplicable |1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |processCCMFeatureData: operationIeIdd=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |ForwardManager - wait_SsDataInd - Key= 0x0, party= 22544754, BCC= 6|1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |ForwardManager - findCallBySsParty - Found entry for party= 22544754, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.598 |ConnectionManager - wait_AuDisconnectRequest ERROR:NO ENTRY FOUND IN TABLE,CI(22544754,22544755),dcType=1,IFCreated(0,0),PID(0-0,0-0),IFHandling(0,0),MCNode(0,0)|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |MatrixControl:updatePartyMediaCoordinatorNodeId: party1 videoCapable=0, party 2 videocapable=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |Cdcc - (0000014) - resetMediaSecurity|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 22544754  mapKey is 22544754|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |//SIP/SIPD(1,65,8)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (1,100,66,20) for mapKey 22544754|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |LineCdpc(18): -dispatchToAllDevices-, sigName=CcDisconnReq, device=SEP0006D744732C|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |ViprUtils::uploadVCRifRequired VcrUploadNeeded[0] FeatureData NOT added|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |//SIP/SIPCdpc(1,66,20)/ci=0/ccbId=4434/scbId=0/uploadVCRifRequired: VcrUploadNeeded 0|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |processCCMFeatureData: operationIeIdd=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |LineControl TEST DEBUGS: Number of entries in CallTable is =  1
|1,100,56,1.2038^192.168.10.42^*
22:42:58.599 |StationD:    (0000002) DEBUG- star_DSetCallPhase updateACall=22544755 from Phase=5 to  callPhase=3.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) DEBUG- star_DSetCallState(15) State of cdpc(18) is 8.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) SetLamp mode=1, stim=9 stimInst=1.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) ClearPromptStatus lineInstance=1 callReference=22544755.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) CallState callState=2 lineInstance=1 callReference=22544755 privacy=0 precedenceLv=4 precedenceDm=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) SelectSoftKeys instance=0 reference=0 softKeySetIndex=0 validKeyMask=ffffffff.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) DefineTimeDate timeDateInfo=11/7/2010 22:42:58,0 systemTime=1289166178.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) restart0_DStopInd: No Linked StationCdpc.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) INFO  restart0_DStopInd: Enable NewCall on line=1 limit=4 listSize=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) restart0_DStopInd: DEBUG: StationCdpc(18) removed. Calltable contains 0 calls.|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |ForwardManager - wait_SsDataInd - Key= 0x0, party= 22544754, BCC= 7|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |ForwardManager - findCallBySsParty - Found entry for party= 22544754, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |ForwardManager - wait_SsDataInd mInterceptTable - ERROR - No entry found for ForwardKey= 0x3508820, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |LineCdpc(18)dispatchKeyReleaseReq - mDevicePid(0, 0, 0); mSelectedDPid(0, 0, 0), mOnBehalfOf(Device), rfr(0)|1,100,56,1.2038^192.168.10.42^*
22:42:58.600 |StationD:    (0000002) SetRinger ringMode=1(RingOff).|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |Forwarding - awaitingCallResponse_SsDataInd - BASIC_CALL_RELEASE - Origination Release. party= 22544754, callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |deleteCi: Unable to find the device that owns the call with CI=|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |LineControl(1) - Release call instance=1 for CI=22544755|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |LineControl::sendSNFNotifyIndForPresenceWithAlerting mPrecenceWithAlertingChangeNotifySubscribed=0, calllist#=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |LineControl (1) - DStopInd - Line become idle|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |LineControl(1) - 0 calls, 0 CiReq, busyTrigger=2, maxCall=4|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |processCCMFeatureData: operationIeIdd=0|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |Locations_releaseBandwidth -- cdccPID=(1.194.14) no entry.|*^*^*
22:42:58.601 |ForwardManager - wait_SsDataInd - Key= 0x0, party= 22544755, BCC= 7|1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |ForwardManager - findCallBySsParty - Found entry for party= 22544755, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.601 |ForwardManager - wait_SsDataInd - BASIC_CALL_RELEASE - mPartyToActiveCallIndexMap - Removed entry Destparty= 22544755, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |Forwarding - awaitingCallResponse_SsDataInd - BASIC_CALL_RELEASE - Stopping Forwarding on destination Release. party= 22544755, callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |Forwarding - stopCFNATimer - callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |ForwardManager - wait_ForwardStopInd - Stop Forwarding - Pid=(1,177,8), callkey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |ForwardManager - removeActiveCallTableEntry - mPartyToActiveCallIndexMap - Removed entry Origparty= 22544754, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |ForwardManager - removeActiveCallTableEntry - mForwardActiveCallTable - Removed call entry for Origparty= 22544754, Destparty= 0, callkey= 0x8 |1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |Forwarding - awaitingStopConfirmation_ForwardStopConf - callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |Forwarding - unregisterRelRejInterceptRequest - callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |Forwarding - unregisterRelRejInterceptRequest - Unregistered RelRej Intercept- party= 22544754, callKey= 0x8|1,100,56,1.2038^192.168.10.42^*
22:42:58.602 |remove an entry from release intercept queue given ssType|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/States/0xb4001de8/0xb4001de8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE)  to (STATE_DISCONNECTING, SUBSTATE_NONE)|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |EnvProcessCdr::wait_DbCdrReq|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |EnvProcessCdr::wait_DbCdrReq DETAILED Entries 14, Inserts 1,                                             ZeroCalls 13, StartRecords 0, Default 0|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 3 for event 8|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0xb4001de8/msg=0xb400d138, addr=192.168.10.42, port=64128, sentBy_port=64128, is_req=0, transport=2, switch=0, callBack=0xa101476|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0xb4001de8/Proceedable for sending msg immediately|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0xb4001de8/switch transport is 0|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0xb4001de8/Trying to send resp=0xb400d138 to default port=64128|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0xb4001de8/Connection obtained...sending msg=0xb400d138|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb400d138, addr=192.168.10.42, port=64128, connId=1996 for TCP|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/Stack/Info/0xb4001de8/Sent a 487 Request Cancelled|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_CONNECT value=500 retries=6|1,100,56,1.2038^192.168.10.42^*
22:42:58.603 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_CONNECT value=500 retries=6|1,100,56,1.2038^192.168.10.42^*
22:42:58.604 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.2038^192.168.10.42^*
22:42:58.604 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.10.42 on port 64128 index 1996
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
From: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;epid=BF36377560;tag=d7fd21965
To: <sip:1001@192.168.10.70;user=phone>;tag=6106e09b-4b79-4114-9c11-a954b3a049ba-22544754
Date: Sun, 07 Nov 2010 21:42:58 GMT
Call-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
CSeq: 4294 INVITE
Allow-Events: presence
Content-Length: 0

|1,100,56,1.2038^192.168.10.42^*
22:42:58.605 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=404|1,100,56,1.2039^192.168.10.42^*
22:42:58.605 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.10.42 on port 64128 index 1996 with 404 bytes:
ACK sip:1001@192.168.10.70;user=phone SIP/2.0
FROM: "Lync User"<sip:2002@dp16-lync.domain.local;user=phone>;tag=d7fd21965;epid=BF36377560
TO: <sip:1001@192.168.10.70;user=phone>;tag=6106e09b-4b79-4114-9c11-a954b3a049ba-22544754
CSEQ: 4294 ACK
CALL-ID: 7736608e-8acd-4dca-b6ef-0de8f2454e46
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.10.42:64128;branch=z9hG4bKb72c7d88
CONTENT-LENGTH: 0

Here's the trace log of the environment where incoming calls from Lync are failing:

16:22:56.576 |EnvProcessUdpPort - EnvProcessUdpHandler::fireSignal() varId = 0|1,100,213,1.33413^192.168.30.30^*
16:22:56.576 |EnvProcessUdpHandler::fireSignal - SEND: index = 0, handler = 0xb451ca10|*^*^*
16:22:56.576 |EnvProcessUdpPort::fireSignal - SEND, destination = 192.168.30.30:5060|*^*^*
16:22:56.576 |EnvProcessUdpPort - EnvProcessUdpHandler::send(buff, 405, 192.168.30.30:5060)|*^*^*
16:22:57.671 |//SIP/SIPTcp/wait_SdlConnectionInd: Connection Indication - Listen Port = 5066, Peer Port = 60883|0,0,0,0.0^*^*
16:22:57.671 |//SIP/SIPTcp/wait_SdlConnectionInd: New Connection - Index = 12823, Listen Port = 5066, Peer Port = 60883|0,0,0,0.0^*^*
16:22:57.671 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 56|0,0,0,0.0^*^*
16:22:57.671 |//SIP/Stack/Transport/0x0/context=(nil)|0,0,0,0.0^*^*
16:22:57.671 |//SIP/Stack/Transport/0x0/gConnTab=0xb45042c8, addr=192.168.30.1, port=60883, connid=12823, transport=TCP|0,0,0,0.0^*^*
16:22:57.671 |//SIP/Stack/Transport/0x0/Created new accptd conn=0xb4301490, connid=12823, addr=192.168.30.1, port=60883, transport=TCP|0,0,0,0.0^*^*
16:22:57.691 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=937|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.30.1 on port 60883 index 12823 with 937 bytes:
INVITE sip:1001@192.168.30.35;user=phone SIP/2.0
FROM: "Lync User"<sip:2001@el24-lync.uc.local;user=phone>;epid=625504215D;tag=591dd5a74d
TO: <sip:1001@192.168.30.35;user=phone>
CSEQ: 388 INVITE
CALL-ID: ac5efce9-64be-4fe9-9fac-918747781af5
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.20.20:64859;branch=z9hG4bKfb77143
CONTACT: <sip:EL24-LYNC.uc.local:5068;transport=Tcp;maddr=192.168.20.20;ms-opaque=d6e734c4ed1323e8>
CONTENT-LENGTH: 342
SUPPORTED: 100rel
USER-AGENT: RTCC/4.0.0.0 MediationServer
CONTENT-TYPE: application/sdp
ALLOW: ACK
Allow: CANCEL,BYE,INVITE,PRACK,UPDATE

v=0
o=- 17 1 IN IP4 192.168.20.20
s=session
c=IN IP4 192.168.20.20
b=CT:1000
t=0 0
m=audio 57206 RTP/AVP 97 101 13 0 8
c=IN IP4 192.168.20.20
a=rtcp:57207
a=label:Audio
a=sendrecv
a=rtpmap:97 RED/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=ptime:20
|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/SIPTcp/wait_SdlReadRsp: SignalCounter = 13070|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Transport/0x0/gConnTab=0xb45042c8, addr=192.168.30.1, port=60883, connid=12823, transport=TCP|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Info/0x0/Added context(0xb4350800) with key=[46068] to table|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.30.1,Port 60883, Transport 2, SentBy Port 64859|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/States/0xb4350800/0xb4350800 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)|1,100,56,1.13072^192.168.30.1^*
16:22:57.691 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.30.1,Port 60883, Transport 2, SentBy Port 5060|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Transport/0x0/Dialog Transaction Address 192.168.30.1,Port 60883, Transport 2, SentBy Port 64859|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Info/0x0/No GTD found in inbound container|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Info/0xb4350800/****Adding to UAS Request table.|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Info/0xb4350800/Added to table. ccb=0xb4350800 key=ac5efce9-64be-4fe9-9fac-918747781af51001|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Info/0xb4350800/Calling name Lync User, number 2001, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 1001, o|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/Stack/Info/0xb4350800/Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/SIPHandler/ccbId=0/scbId=0/findTrunkInfoByAddr: Cannot find the SIP Trunk with Name=192.168.30.1, Source Port=5066, IpAddress Type=0|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/SIPHandler/ccbId=0/scbId=0/getRel1xxType: No matching SIP trunk found in hash table, returning rel1xx disabled|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/SIPHandler/ccbId=0/scbId=0/sipSPIGetCallExtensionSupported: SIPRel1xxEnabledServiceParamSetting=0 , ccb->pld.outboundRel1xx=1|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_EXPIRES value=1800000 retries=0|1,100,56,1.13072^192.168.30.1^*
16:22:57.692 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_EXPIRES value=1800000 retries=0|1,100,56,1.13072^192.168.30.1^*
16:22:57.704 |//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo: parseResult[1]|1,100,56,1.13072^192.168.30.1^*
16:22:57.711 |//SIP/SIPHandler/ccbId=0/scbId=0/getCodecAndFramesFromSDP: -- Error!!!!! Cannot convert SDP pt=13 to CM payload type.|1,100,56,1.13072^192.168.30.1^*
16:22:57.734 |//SIP/SIPHandler/ccbId=0/scbId=0/findTrunkInfoByAddr: Cannot find the SIP Trunk with Name=192.168.30.1, Source Port=5066, IpAddress Type=0|1,100,56,1.13072^192.168.30.1^*
16:22:57.734 |//SIP/Stack/Info/0xb4350800/ccsip_api_call_setup_ind returned: SIP_INTERNAL_ERR|1,100,56,1.13072^192.168.30.1^*
16:22:57.734 |//SIP/Stack/Info/0xb4350800/Application Layer internal request|1,100,56,1.13072^192.168.30.1^*
16:22:57.734 |//SIP/Stack/Info/0xb4350800/****Adding to UAS Response table.|1,100,56,1.13072^192.168.30.1^*
16:22:57.734 |//SIP/Stack/Info/0xb4350800/Added to table. ccb=0xb4350800 key=ac5efce9-64be-4fe9-9fac-918747781af5295860660|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/Transport/0xb4350800/msg=0xb3e2f310, addr=192.168.30.1, port=60883, sentBy_port=64859, is_req=0, transport=2, switch=0, callBack=0xa101286|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/Transport/0xb4350800/Proceedable for sending msg immediately|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/Transport/0xb4350800/switch transport is 0|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb3e2f310, addr=192.168.30.1, port=60883, connId=12823 for TCP|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.30.1 on port 60883 index 12823
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/TCP 192.168.20.20:64859;branch=z9hG4bKfb77143;received=192.168.30.1
From: "Lync User"<sip:2001@el24-lync.uc.local;user=phone>;epid=625504215D;tag=591dd5a74d
To: <sip:1001@192.168.30.35;user=phone>;tag=295860660
Date: Sun, 07 Nov 2010 15:22:57 GMT
Call-ID: ac5efce9-64be-4fe9-9fac-918747781af5
CSeq: 388 INVITE
Allow-Events: presence
Content-Length: 0

|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/Info/0xb4350800/Sent an 3456XX Error Response|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/Stack/States/0xb4350800/0xb4350800 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_DISCONNECTING, SUBSTATE_NONE)|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_CONNECT value=500 retries=6|1,100,56,1.13072^192.168.30.1^*
16:22:57.735 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_CONNECT value=500 retries=6|1,100,56,1.13072^192.168.30.1^*
16:22:57.738 |//SIP/SIPTcp/wait_SdlReadRsp: SdlRead bufferLen=357|1,100,56,1.13073^192.168.30.1^*
16:22:57.739 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 192.168.30.1 on port 60883 index 12823 with 357 bytes:
ACK sip:1001@192.168.30.35;user=phone SIP/2.0
FROM: "Lync User"<sip:2001@el24-lync.uc.local;user=phone>;tag=591dd5a74d;epid=625504215D
TO: <sip:1001@192.168.30.35;user=phone>;tag=295860660
CSEQ: 388 ACK
CALL-ID: ac5efce9-64be-4fe9-9fac-918747781af5
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 192.168.20.20:64859;branch=z9hG4bKfb77143
CONTENT-LENGTH: 0

Thanks for helping my out!

[Joseph Martini · Accepted solution]

It looks like your home setup that is working you have on your call manager trunk destination set to 192.168.10.42 which is correct since that's the address the INVITE is coming from.  For your work system you do not have a SIP trunk configured with a destination address of 192.168.30.1 and port 5066.  If you change the destination of the SIP trunk to 192.168.30.1 port 5066 it should work.  Here's the message that indicates this "Cannot find the SIP Trunk with Name=192.168.30.1, Source Port=5066, IpAddress Type=0".

[mamkreutz01]

Your totally right Joemar2, I couldn't place the 30.1, however that's the gateway of the Voice VLAN.

At my home environment I don't use different VLANs, however at work I configured a data VLAN (192.168.20.*) and a voice VLAN (192.168.30.*). The Lync sits on the data VLAN and the CUCM on the data VLAN.

I also have an Exchange 2010 server, however the problem doesn't happen with the exchange trunk because the exchange is a VM that I gave two network interfaces for both VLANs.

Thanks, will look into it!

[mamkreutz01]

Hey Joemar2,

I will be checking your solution in a couple of hours, however I was thinking about it and noticed some strange behavior. At the moment I think it has to do with the seperate VLANs for the Lync and CUCM server, because the invite is from the Voice VLAN gateway IP.

However, during troubleshooting I created a VPN as stated in my original post between my home and work (DATA VLAN) environment. I configured my home CUCM to use the Lync server at work and this worked. But this would be the same like using two seperate VLANs, because both VPN endpoint also have different ranges, so the invite would also go wrong by using the default gateway ip, don't it? However this goes succesful.

I will be checking your solution in a couple of hours, however just something to think about until I have time to troubleshoot it.

Thanks for your help!

[mamkreutz01]

Did some more research. The problem lies in the Fortigate firewall on my work environment. It's in the way the FortiGate handles inter vlan routing. I didn't exactly found the problem in the FortiGate yet, but I configured a Trunk between the CUCM at work and the Lync at home and noticed it was also working. This brought me to the conclusion that inter VLAN routing through the FortiGate breaks the SIP connection from Lync (DATA VLAN) to CUCM (VOICE VLAN). CUCM receives an incoming call from Lync on the DATA VLAN as if the default gateway of the CUCMs own VLAN (VOICE) intializes it (INVITE).

Will look into this tomorrow to see if I can find the problem in the FortiGate.

I'll wait until I found some more info on the problem tomorrow before I will mark this topic as answered.

Thanks!

[Joseph Martini]

Sounds good thanks for the follow up.

[mamkreutz01]

I figured it out. I enabled (SIPs best friend) NAT for inter VLAN routing between the Data and Voice VLANs. When I disabled NAT, everything worked like a charm!

Thanks for pointing me in the right direction!

Problem solved