locked
OCS2007R2 RCC Issues RRS feed

  • 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