Answered by:
OCS2007R2 RCC Issues

Question
-
We are running OCS2007R2 (3.5.6907.196) EE and are running into periodic issues were individuals will not be able to initiate remote call control (RCC) We are using E.164 numbers, and have normalization rules in place for everything internal to dial 4 digit extensions. I was able to capture some errros from the MOC client-
Event log
Log Name: Application
Source: Communicator
Date: 6/14/2012 3:02:00 PM
Event ID: 11
Task Category: None
Level: Warning
Keywords: Classic
User: N/A
Computer: user-e6420B.corp.mycompany.com
Description:
A SIP request made by Communicator failed in an unexpected manner (status code 80ef0193). More information is contained in the following technical data:
RequestUri: sip:4265;phone-context=dialstring@mycompany.com;user=phone
From: sip:jochang@mycompany.com;tag=857aa521e5
To: sip:4265;phone-context=dialstring@mycompany.com;user=phone;tag=D1645BC74AEFCF5DEDC301332DDC1DC7
Call-ID: d39aed346d7c4d2298e0e73fc6ad4b52
Content-type: application/sdp;call-type=audiovideo
(null)
Response Data:
101 Progress Report
ms-diagnostics: 14012;reason="Dialstring phone context used no translation done";source="irv-edc-ms30.corp.mycompany.com";appName="TranslationService"
403 Forbidden
ms-diagnostics: 1012;reason="From URI is not authorized to communicate with users outside the enterprise";source="irv-edc-ms30.corp.mycompany.com"
Log Files-
06/14/2012|14:50:01.841 144C:2680 INFO :: CallControlChannel::Initialize[0710CB48]-URI=sip:user@oc1-cti-server.corp.mycompany.com, ID=tel:4911;phone-context=dialstring, Replace[00000000]
06/14/2012|14:50:01.841 144C:2680 TRACE :: New mpss created: 070FC760, stack=002F8D60, 0
06/14/2012|14:50:01.841 144C:2680 INFO :: MSP.SetMultipartySsnRole[070FC760] 0->0
06/14/2012|14:50:01.841 144C:2680 INFO :: CUccRemoteCallControlEndpoint::EstablishCall[0710CB48]-Type=1,Call=070FC760
06/14/2012|14:50:01.841 144C:2680 TRACE :: MULTIPARTY_SESSION::SetConnectParams[070FC760] n=(null), uri=- Log message too long!
06/14/2012|14:50:01.841 144C:2680 TRACE :: MULTIPARTY_SESSION::AddParty - Enter participant: sip:user@oc1-cti-server.corp.mycompany.com, this=sip:user@mycompany.com, RM=(null)
06/14/2012|14:50:01.841 144C:2680 TRACE :: MULTIPARTY_SESSION::AddParty SessionState 0, m_fAddedFirstParty 0, participant: sip:user@oc1-cti-server.corp.mycompany.com, this 070FC760
06/14/2012|14:50:01.841 144C:2680 TRACE :: New SipCall:0710EEB8, dialog=0710EF0C, first=1, typ=0, mpss=070FC760, redir=00000000
06/14/2012|14:50:01.841 144C:2680 INFO :: There is no Service-Route to copy
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_STACK::FindProviderSAContext SA_CONTEXT not found:sip.mycompany.com, this 002F8D60
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_STACK::FindProviderSAContext SA_CONTEXT not found:sip.mycompany.com, this 002F8D60
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_STACK::FindProviderSAContext SA_CONTEXT not found:sip.mycompany.com, this 002F8D60
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_MSG_PROCESSOR::GetSAListEntry- SA not found for TargetName: sip/irv-edc-ms30.corp.mycompany.com Auth: 8, this 0710EF0C
06/14/2012|14:50:01.841 144C:2680 WARN :: SIP_MSG_PROCESSOR::AddSAToList cannot find SA [04B77D48] in list, inserting list entry [08050528] into list, TargetName sip/irv-edc-ms30.corp.mycompany.com, Auth: 8, this 0710EF0C
06/14/2012|14:50:01.841 144C:2680 INFO :: call.SetRemote[0710EEB8] sip:user@oc1-cti-server.corp.mycompany.com:(null);(null),0,0
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_CALL::SetLocalAndRemoteForConnect - enter LocalDisplayName:
06/14/2012|14:50:01.841 144C:2680 INFO :: SIP_CALL::SetLocalAndRemoteForConnect - Call.Invite[0710EEB8]0:sip:user@mycompany.com==>sip:user@oc1-cti-server.corp.mycompany.com:, RM=(null)
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_MSG_PROCESSOR::OnRequestSocketConnectComplete - Enter this: 0710EF0C, callid=(null), ErrorCode: 0x0
06/14/2012|14:50:01.841 144C:2680 INFO :: Outgoing 0710EF0C-<sip:user@oc1-cti-server.corp.mycompany.com>, local=sip:user@mycompany.com
06/14/2012|14:50:01.841 144C:2680 INFO :: call.SetRemote[0710EEB8] sip:user@oc1-cti-server.corp.mycompany.com:(null);(null)
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_CALL::CreateOutgoingInviteTransaction[0710EEB8], first=1, headers=0, cookie=0
06/14/2012|14:50:01.841 144C:2680 TRACE :: call.SetState[0710EEB8] SIP_CALL_STATE_IDLE-->SIP_CALL_STATE_CONNECTING for sip:user@oc1-cti-server.corp.mycompany.com, stack=002F8D60
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_CALL::NotifyCallStateChange[0710EEB8] : CallState : 3 StatusCode: 0, s=3
06/14/2012|14:50:01.841 144C:2680 TRACE :: MULTIPARTY_SESSION::NotifyCallChange[070FC760]- call-leg:0710EEB8, Callstate:3 StatusCode:0 SessionState:0
06/14/2012|14:50:01.841 144C:2680 INFO :: MSP.SetState[070FC760] SIP_CALL_STATE_IDLE->SIP_CALL_STATE_CONNECTING, local=sip:user@mycompany.com
06/14/2012|14:50:01.841 144C:2680 INFO :: CUccRemoteCallControlEndpoint::NotifyCallChange - m_enState=0,sipState=3,status=0x00000000
06/14/2012|14:50:01.841 144C:2680 INFO :: CUccRemoteCallControlEndpoint::OnChannelStateChange - enState=0->1,status=0x0,text=(null)
06/14/2012|14:50:01.841 144C:2680 TRACE :: SIP_STACK::FindProviderSAContext SA_CONTEXT found:sip/irv-edc-ms30.corp.mycompany.com- 04B77D48, SA list entry 04B8A8D0, this 002F8D60
06/14/2012|14:50:01.841 144C:2680 TRACE :: signed buffer: <Kerberos><e3718e89><10><SIP Communications Service><sip/irv-edc-ms30.corp.mycompany.com><dc250c2422ec48bfb73013bd9d26d158><1><INVITE><sip:user@mycompany.com><17d9ae60ef><sip:user@oc1-cti-server.corp.mycompany.com><><><><> - length- 212. SSPI context:3001232-78941520.
06/14/2012|14:50:01.841 144C:2680 INFO :: Sending Packet - 10.1.100.113:5061 (From Local Address: 10.7.26.209:9172) 1369 bytes:
06/14/2012|14:50:01.841 144C:2680 INFO :: INVITE sip:user@oc1-cti-server.corp.mycompany.com SIP/2.0
Via: SIP/2.0/TLS 10.7.26.209:9172
Max-Forwards: 70
From: <sip:user@mycompany.com>;tag=17d9ae60ef;epid=ae0579b463
To: <sip:user@oc1-cti-server.corp.mycompany.com>
Call-ID: dc250c2422ec48bfb73013bd9d26d158
CSeq: 1 INVITE
Contact: <sip:user@mycompany.com;opaque=user:epid:Uwn4kkzAmVGkqOqkiF4RzQAA;gruu>
User-Agent: UCCAPI/3.5.6907.236 OC/3.5.6907.253 (Microsoft Office Communicator 2007 R2)
Content-Disposition: signal;handling=required
Supported: timer
Supported: histinfo
Supported: ms-safe-transfer
Supported: ms-sender
Supported: ms-early-media
ms-keep-alive: UAC;hop-hop=yes
Allow: INVITE, BYE, ACK, CANCEL, INFO, UPDATE, REFER, NOTIFY, BENOTIFY, OPTIONS
Proxy-Authorization: Kerberos qop="auth", realm="SIP Communications Service", opaque="E7D921C9", targetname="sip/irv-edc-ms30.corp.mycompany.com", crand="e3718e89", cnum="10", response="602306092a864886f71201020201011100ffffffff3919dade251430513c85d84866701a28" Content-Type: application/csta+xml Content-Length: 329 <?xml version="1.0"?> <RequestSystemStatus xmlns="http://www.ecma-international.org/standards/ecma-323/csta/ed3"><extensions><privateData><private><lcs:line xmlns:lcs="http://schemas.microsoft.com/Lcs/2005/04/RCCExtension">tel:4911;phone-context=dialstring</lcs:line></private></privateData></extensions></RequestSystemStatus> 06/14/2012|14:50:01.841 144C:2680 INFO :: End of Sending Packet - 10.1.100.113:5061 (From Local Address: 10.7.26.209:9172) 1369 bytes
more info from the OCS Server Trace-
Anyone have any thoughts on what to look at?
Thanks,
Jon
Thursday, June 14, 2012 10:50 PM
Answers
-
Hi,
The following article is about How Remote Call Control Powers OCS 2007 R2, hope it can help you:
http://technet.microsoft.com/en-us/magazine/2009.03.rcc.aspx
Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread.
- Marked as answer by Sean_Xiao Friday, June 29, 2012 2:19 AM
Wednesday, June 20, 2012 7:26 AM -
In RCC a sip session is established between the communicator client and RCC gateway when the RCC user logs into communicator client and the session is maintained till the user does not sign out of communciator client
The command flow between the RCC gateway and communicator client using SIP info messages
In the above screenshot I see an invite being sent but if I look at the user agent I see Zeacom RCC gateway, so whay is RCC gateway sending an invite
Enable logging in communicator client Tools-->options-->general-->logging and check both the opitons. You will find the logs at %userprofile%\tracing and open the uccp logs in snopper to check for error messages when RCC stops working.
What do you have to do to make it work again, does it start working withouth any action? Do you have to restart the RCC gateway or sign out or sign into communicator client?
User configured for RCC use normalization rules from the address book company normalization file so make sure you have the normalization rules in the file
- Marked as answer by Sean_Xiao Friday, June 29, 2012 2:19 AM
Saturday, June 23, 2012 9:17 AM
All replies
-
Hi,
The following article is about How Remote Call Control Powers OCS 2007 R2, hope it can help you:
http://technet.microsoft.com/en-us/magazine/2009.03.rcc.aspx
Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread.
- Marked as answer by Sean_Xiao Friday, June 29, 2012 2:19 AM
Wednesday, June 20, 2012 7:26 AM -
In RCC a sip session is established between the communicator client and RCC gateway when the RCC user logs into communicator client and the session is maintained till the user does not sign out of communciator client
The command flow between the RCC gateway and communicator client using SIP info messages
In the above screenshot I see an invite being sent but if I look at the user agent I see Zeacom RCC gateway, so whay is RCC gateway sending an invite
Enable logging in communicator client Tools-->options-->general-->logging and check both the opitons. You will find the logs at %userprofile%\tracing and open the uccp logs in snopper to check for error messages when RCC stops working.
What do you have to do to make it work again, does it start working withouth any action? Do you have to restart the RCC gateway or sign out or sign into communicator client?
User configured for RCC use normalization rules from the address book company normalization file so make sure you have the normalization rules in the file
- Marked as answer by Sean_Xiao Friday, June 29, 2012 2:19 AM
Saturday, June 23, 2012 9:17 AM -
Sean,
Thanks for the reply. There is seemingly nothing we can do to get it to start working again. At least not for everyone, all the time. I think sometimes restarting the Zeacom OCS gateway may help, but not for everyone. We also get the 'No Phone system Connection' error in MOC, with a 'Cannot connect to the phone system, The call control server may be temporarily unavailable'
Here is a capture of a failed call from the trace logs-
06/29/2012|09:57:40.710 1D9C:1E28 TRACE :: SIP_CALL::StopSessionExpiresTimer disable session timer
06/29/2012|09:57:40.710 1D9C:1E28 TRACE :: call.SetState[0E697E60] SIP_CALL_STATE_ALERTING-->SIP_CALL_STATE_DISCONNECTED for sip:+19075559976@mycompany.com;user=phone, stack=00A2CFF0
06/29/2012|09:57:40.710 1D9C:1E28 TRACE :: SIP_CALL::NotifyCallStateChange[0E697E60] : CallState : 2 StatusCode: 80ef0194, s=2
06/29/2012|09:57:40.710 1D9C:1E28 TRACE :: displayName [(null)]
06/29/2012|09:57:40.711 1D9C:1E28 TRACE :: MULTIPARTY_SESSION::NotifyCallChange[0831CCE8]- call-leg:0E697E60, Callstate:2 StatusCode:80ef0194 SessionState:5
06/29/2012|09:57:40.711 1D9C:1E28 INFO :: CUccMultipartySession::NotifyPartyChange[0E4477BC] - for participant [sip:+19075559976@mycompany.com;user=phone]
06/29/2012|09:57:40.712 1D9C:1E28 INFO :: Function: CRTCMediaEndpointManager::CollectIceStatistics
06/29/2012|09:57:40.712 1D9C:1E28 TRACE :: Condition failed with 00000001: 'GetNegotiatedIceVersion() != RTC_ICE_VERSION_NONE'
06/29/2012|09:57:40.736 1D9C:1E28 ERROR :: CRTCMediaParticipant::RemoveStream[00A5AB68] InternalHasStream failed (1). 80ee0002
06/29/2012|09:57:40.736 1D9C:1E28 ERROR :: CRTCMediaParticipant::RemoveStream[00A5AB68] InternalHasStream failed (2). 80ee0002
06/29/2012|09:57:40.737 1D9C:1E28 INFO :: CUccSessionParticipant::InternalSetState [074F82E0] - state: 0x2->0x5
06/29/2012|09:57:40.737 1D9C:1E28 TRACE :: CUccSession::InternalRemoveParticipant - Removing participant sip:+19075559976@mycompany.com;user=phone
06/29/2012|09:57:40.737 1D9C:1E28 INFO :: Function: SIP_MESSAGE::GetHeader
06/29/2012|09:57:40.737 1D9C:1E28 ERROR :: SIP_MESSAGE::GetHeader: HRESULT failed: 80ee0005 = hr. GetHeader
06/29/2012|09:57:40.737 1D9C:1E28 TRACE :: MULTIPARTY_SESSION::HandleCallLegNotifyDisconnect number of participants remaining 0, this 0831CCE8
06/29/2012|09:57:40.737 1D9C:1E28 INFO :: MSP.SetState[0831CCE8] SIP_CALL_STATE_ALERTING->SIP_CALL_STATE_DISCONNECTED, local=sip:jlundfelt@mycompany.com
06/29/2012|09:57:40.738 1D9C:1E28 INFO :: CUccSessionParticipant::InternalSetState [074F7C00] - state: 0x2->0x5
06/29/2012|09:57:40.738 1D9C:1E28 TRACE :: CUccSession::InternalRemoveParticipant - Removing participant sip:jlundfelt@mycompany.com
06/29/2012|09:57:40.746 1D9C:1E28 INFO :: Function: CUccCollection::get_Item
06/29/2012|09:57:40.746 1D9C:1E28 TRACE :: Condition failed with 80070057: '(0 < lIndex) && (lIndex <= m_Elements.GetSize())'
06/29/2012|09:57:40.748 1D9C:1E28 INFO :: Function: CUccCollection::get_Item
06/29/2012|09:57:40.748 1D9C:1E28 TRACE :: Condition failed with 80070057: '(0 < lIndex) && (lIndex <= m_Elements.GetSize())'
06/29/2012|09:57:42.712 1D9C:1E28 TRACE :: SECURE_SOCKET: decrypting buffer size: 2053 (first 8):
06/29/2012|09:57:42.713 1D9C:1E28 TRACE :: 17 03 01 08 00 FE 18 FA :.....þ.ú
06/29/2012|09:57:42.714 1D9C:1E28 INFO :: Data Received - 10.1.100.113:5061 (To Local Address: 10.7.26.36:57531) 2021 bytes:
06/29/2012|09:57:42.714 1D9C:1E28 INFO :: BENOTIFY sip:10.7.26.36:57531;transport=tls;ms-opaque=cc40f2aef7;ms-received-cid=15E700 SIP/2.0
Via: SIP/2.0/TLS 10.1.100.113:5061;branch=z9hG4bK3EC06469.A955BB955BEA8D86;branched=FALSE
Proxy-Authentication-Info: Kerberos rspauth="602306092A864886F71201020201011100FFFFFFFFD82E675763FAC6681182C4E48D75FEEC", srand="D03CD216", snum="515", opaque="3FE483CD", qop="auth", targetname="sip/irv-edc-ms30.corp.mycompany.com", realm="SIP Communications Service"
Max-Forwards: 70
To: <sip:jlundfelt@mycompany.com>;tag=2b45d10f19;epid=33dee81ab1
Content-Length: 1228
From: <sip:jlundfelt@mycompany.com>;tag=D63C0080
Call-ID: cae8b1483fa04212bde032a63954046e
CSeq: 972 BENOTIFY
Require: eventlist
Content-Type: application/msrtc-event-categories+xml
Event: presence
subscription-state: active;expires=24678
<categories xmlns="http://schemas.microsoft.com/2006/09/sip/categories" uri="sip:againor@mycompany.com"><category xmlns="http://schemas.microsoft.com/2006/09/sip/categories" name="state" instance="1" publishTime="2012-06-29T16:57:42.460">
<state xsi:type="aggregateState" lastActive="2012-06-29T16:57:42" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://schemas.microsoft.com/2006/09/sip/state"><availability>15500</availability><delimiter xmlns="http://schemas.microsoft.com/2006/09/sip/commontypes" /><device>computer</device><end xmlns="http://schemas.microsoft.com/2006/09/sip/commontypes" /></state>
</category>
<category xmlns="http://schemas.microsoft.com/2006/09/sip/categories" name="services" instance="0" publishTime="2012-06-29T16:57:42.460">
<services xmlns="http://schemas.microsoft.com/2006/09/sip/service"><service uri="sip:againor@mycompany.com"><capabilities><text render="true" capture="true" deviceAvailability="15500" /><gifInk render="true" capture="false" deviceAvailability="15500" /><isfInk render="true" capture="false" deviceAvailability="15500" /><applicationSharing render="true" capture="true" deviceAvailability="15500" /></capabilities></service></services>
</category>
</categories>
06/29/2012|09:57:42.714 1D9C:1E28 INFO :: End of Data Received - 10.1.100.113:5061 (To Local Address: 10.7.26.36:57531) 2021 bytes
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: SIP_STACK::FindProviderSAContext SA_CONTEXT found:sip/irv-edc-ms30.corp.mycompany.com- 041AFBF0, SA list entry 041F37A8, this 00A2CFF0
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: SIP_MSG_PROCESSOR::GetSAListEntry SA [041AFBF0] targetname sip/irv-edc-ms30.corp.mycompany.com, auth 8, this 07561264
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: SIP_MSG_PROCESSOR::AddSAToList found SA [041AFBF0] from list entry [07550AA0] with TargetName: sip/irv-edc-ms30.corp.mycompany.com Auth: 8 , this 07561264
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: SIP_MSG_PROCESSOR::GetSAListEntry SA [041AFBF0] targetname sip/irv-edc-ms30.corp.mycompany.com, auth 8, this 07561264
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: verified buffer: <Kerberos><D03CD216><515><SIP Communications Service><sip/irv-edc-ms30.corp.mycompany.com><cae8b1483fa04212bde032a63954046e><972><BENOTIFY><sip:jlundfelt@mycompany.com><D63C0080><sip:jlundfelt@mycompany.com><2b45d10f19><><><>-length-207. signature:602306092A864886F71201020201011100FFFFFFFFD82E675763FAC6681182C4E48D75FEEC
06/29/2012|09:57:42.715 1D9C:1E28 TRACE :: AddTag 07561264-<sip:jlundfelt@mycompany.com>;tag=D63C0080, local=sip:jlundfelt@mycompany.com
06/29/2012|09:57:42.720 1D9C:1E28 TRACE :: CUccLogicalSubscription::ProcessCategoryDataCollection - Presentity object not found for [sip:againor@mycompany.com], this 04172518
06/29/2012|09:57:42.722 1D9C:1E28 TRACE :: CUccLogicalSubscription::ProcessCategoryDataCollection - Presentity object not found for [sip:againor@mycompany.com], this 041726F8
06/29/2012|09:57:42.722 1D9C:1E28 TRACE :: CUccLogicalSubscription::ProcessCategoryDataCollection - Presentity object not found for [sip:againor@mycompany.com], this 04172838
06/29/2012|09:57:42.722 1D9C:1E28 TRACE :: CUccLogicalSubscription::ProcessCategoryDataCollection - Presentity object not found for [sip:againor@mycompany.com], this 041728D8
06/29/2012|09:57:42.725 1D9C:1E28 TRACE :: CUccPresentity::get_SourceType - enter [0x0741D330]
06/29/2012|09:57:42.725 1D9C:1E28 TRACE :: CUccPresentity::get_SourceType - exit [0741D330]
06/29/2012|09:57:52.260 1D9C:1E28 TRACE :: SECURE_SOCKET: decrypting buffer size: 1477 (first 8):
06/29/2012|09:57:52.260 1D9C:1E28 TRACE :: 17 03 01 05 C0 DD C8 5B :....ÀÝÈ[
06/29/2012|09:57:52.261 1D9C:1E28 INFO :: Data Received - 10.1.100.113:5061 (To Local Address: 10.7.26.36:57531) 1437 bytes:
06/29/2012|09:57:52.261 1D9C:1E28 INFO :: BENOTIFY sip:10.7.26.36:57531;transport=tls;ms-opaque=cc40f2aef7;ms-received-cid=15E700 SIP/2.0
Via: SIP/2.0/TLS 10.1.100.113:5061;branch=z9hG4bK3FC06469.20E6C1B95E3F3D8F;branched=FALSE
Proxy-Authentication-Info: Kerberos rspauth="602306092A864886F71201020201011100FFFFFFFF67A8E27A5F42CD29035352436AD5195A", srand="E9E54702", snum="516", opaque="3FE483CD", qop="auth", targetname="sip/irv-edc-ms30.corp.mycompany.com", realm="SIP Communications Service"
Max-Forwards: 70
To: <sip:jlundfelt@mycompany.com>;tag=2b45d10f19;epid=33dee81ab1
Content-Length: 645
From: <sip:jlundfelt@mycompany.com>;tag=D63C0080
Call-ID: cae8b1483fa04212bde032a63954046e
CSeq: 973 BENOTIFY
Require: eventlist
Content-Type: application/msrtc-event-categories+xml
Event: presence
subscription-state: active;expires=24668
Thanks for the help.
-Jon
Friday, June 29, 2012 4:59 PM