Dynamics 2011 CRM Org Service Authentication Failure

0

Update: I can make this work by using the DisableLoopbackCheck, but I'd prefer a solution that does not require switching off security features.

Getting an error connecting to Dynamics 2011 CRM Organisation Service Web API:

"The Security Support Provider Interface (SSPI) negotiation failed."

Environment is follows:

  • MS Dynamics 2011 CRM on-prem
  • Client .NET web application on SAME SERVER

N.B. The client application has been in use for several years, and works normally when hosted on a different server to Dynamics.

I have another .NET console that uses the same code to connect to the Org service, and this works normally. I've also translated the connection & query code from the problem app into PowerShell, and this works normally.

I'm guessing that, because client and server are on the same box, authentication is handled differently, but I don't understand enough to troubleshoot any further. Below are all the logs that I've been able to gather, and code from the client application.

Error logged by client application:

Exception :   The caller was not authenticated by the service.  
Trace :     
Server stack trace:
at System.ServiceModel.Security.IssuanceTokenProviderBase`1.DoNegotiation(TimeSpan timeout)
at System.ServiceModel.Security.SspiNegotiationTokenProvider.OnOpen(TimeSpan timeout)
at System.ServiceModel.Security.WrapperSecurityCommunicationObject.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Security.CommunicationObjectSecurityTokenProvider.Open(TimeSpan timeout)
at System.ServiceModel.Security.SymmetricSecurityProtocol.OnOpen(TimeSpan timeout)
at System.ServiceModel.Security.WrapperSecurityCommunicationObject.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Channels.SecurityChannelFactory`1.ClientSecurityChannel`1.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.CallOpenOnce.System.ServiceModel.Channels.ServiceChannel.ICallOnce.Call(ServiceChannel channel, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.CallOnceManager.CallOnce(TimeSpan timeout, CallOnceManager cascade)
at System.ServiceModel.Channels.ServiceChannel.EnsureOpened(TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)
Exception rethrown at [0]:
at (NameSpaceRoot).InfoPathFormSubmissionServices.BusinessLogic.GetWebUserFromWebUserLogon(String webUserLogon)
in (Source Files Path)\InfoPathFormSubmissionServices\InfoPathFormSubmissionServices\BusinessLogic.cs:line 68
at (NameSpaceRoot).InfoPathFormSubmissionServices.InfoPathFormSubmissionServices.SetWebUserStatusToLocked(String webUserLogon)
in (Source Files Path)\InfoPathFormSubmissionServices\InfoPathFormSubmissionServices\InfoPathFormSubmissionServices.asmx.cs:line 123

IIS Logs for Dynamics:

2019-06-25 23:41:11 fe80::7198:d8b:faac:2f66%12 GET /(Crm_Org)/XRMServices/2011/Organization.svc wsdl+OnBeginRequest:06/25/2019-23:41:11.602+LogEntries:4+SqlCalls:0+SqlCallsMs:0+GC:46+OnEndRequest:23:41:11.605 80 - fe80::7198:d8b:faac:2f66%12 - - 200 0 0 6
2019-06-25 23:41:11 fe80::7198:d8b:faac:2f66%12 GET /(Crm_Org)/XRMServices/2011/Organization.svc wsdl=wsdl0+OnBeginRequest:06/25/2019-23:41:11.613+LogEntries:4+SqlCalls:0+SqlCallsMs:0+GC:46+OnEndRequest:23:41:11.626 80 - fe80::7198:d8b:faac:2f66%12 - - 200 0 0 33
2019-06-25 23:41:11 fe80::7198:d8b:faac:2f66%12 POST /(Crm_Org)/XRMServices/2011/Organization.svc +OnBeginRequest:06/25/2019-23:41:11.948+LogEntries:4+SqlCalls:0+SqlCallsMs:0+GC:46+OnEndRequest:23:41:11.954 80 - fe80::7198:d8b:faac:2f66%12 - - 200 0 0 8
2019-06-25 23:41:11 fe80::7198:d8b:faac:2f66%12 POST /(Crm_Org)/XRMServices/2011/Organization.svc +OnBeginRequest:06/25/2019-23:41:11.960+LogEntries:4+SqlCalls:0+SqlCallsMs:0+GC:46+OnEndRequest:23:41:11.969 80 - fe80::7198:d8b:faac:2f66%12 - - 500 0 0 11

IIS Failed Request Trace (full trace at https://pastebin.com/4xig9bcv)

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>5</Level>
  <Opcode>49</Opcode>
  <Keywords>0x0</Keywords>
  <TimeCreated SystemTime="2019-06-25T23:41:11.969Z"/>
  <Correlation ActivityID="{00000000-0000-0000-6503-0080020000E3}"/>
  <Execution ProcessID="12028" ThreadID="4376"/>
  <Computer>(ServerName)</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{00000000-0000-0000-6503-0080020000E3}</Data>
  <Data Name="Buffer">&lt;s:Envelope xmlns:s=&quot;http://www.w3.org/2003/05/soap-envelope&quot; xmlns:a=&quot;http://www.w3.org/2005/08/addressing&quot;&gt;&lt;s:Header&gt;&lt;a:Action s:mustUnderstand=&quot;1&quot;&gt;http://www.w3.org/2005/08/addressing/soap/fault&lt;/a:Action&gt;&lt;a:RelatesTo&gt;urn:uuid:c5357be5-13c3-4292-8537-b5b7351075bf&lt;/a:RelatesTo&gt;&lt;/s:Header&gt;&lt;s:Body&gt;&lt;s:Fault&gt;&lt;s:Code&gt;&lt;s:Value&gt;s:Sender&lt;/s:Value&gt;&lt;s:Subcode&gt;&lt;s:Value xmlns:a=&quot;http://schemas.xmlsoap.org/ws/2005/02/trust&quot;&gt;a:FailedAuthentication&lt;/s:Value&gt;&lt;/s:Subcode&gt;&lt;/s:Code&gt;&lt;s:Reason&gt;&lt;s:Text xml:lang=&quot;en-AU&quot;&gt;The request for security token could not be satisfied because authentication failed.&lt;/s:Text&gt;&lt;/s:Reason&gt;&lt;/s:Fault&gt;&lt;/s:Body&gt;&lt;/s:Envelope&gt;</Data>
 </EventData>
 <RenderingInfo Culture="en-AU">
  <Opcode>GENERAL_RESPONSE_ENTITY_BUFFER</Opcode>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{D42CF7EF-DE92-473E-8B6C-621EA663113A}</EventGuid>
 </ExtendedTracingInfo>
</Event>

Dynamics Trace:

>AUTH: AuthenticationProvider [Microsoft.Crm.Authentication.PassThroughAuthenticationProvider] handled request [http://(fqdn)/(crm_org)/XRMServices/2011/Organization.svc] from [fe80::7198:d8b:faac:2f66%12].
[2019-06-24 15:55:53.498] Process: w3wp |Organization:00000000-0000-0000-0000-000000000000 |Thread:    8 |Category: Platform.Sdk |User: 00000000-0000-0000-0000-000000000000 |Level: Error |ReqId: cf76f77c-b8bc-43a0-bcc3-9ecb393e7857 | TraceSource.TraceData  ilOffset = 0x68
    at TraceSource.TraceData(TraceEventType eventType, Int32 id, Object data)  ilOffset = 0x68
    at LegacyDiagnosticTrace.TraceEvent(TraceEventType type, Int32 code, String msdnTraceCode, String description, TraceRecord trace, Exception exception, Object source)  ilOffset = 0x0
    at ExceptionUtility.ThrowHelper(Exception exception, TraceEventType eventType, TraceRecord extendedData)  ilOffset = 0x33
    at WindowsSspiNegotiation.GetOutgoingBlob(Byte[] incomingBlob, ChannelBinding channelbinding, ExtendedProtectionPolicy protectionPolicy)  ilOffset = 0x37B
    at SspiNegotiationTokenAuthenticator.ProcessNegotiation(SspiNegotiationTokenAuthenticatorState negotiationState, Message incomingMessage, BinaryNegotiation incomingNego)  ilOffset = 0x0
    at NegotiationTokenAuthenticator`1.ProcessRequestCore(Message request)  ilOffset = 0x206
    at NegotiationSyncInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)  ilOffset = 0x11
    at DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc)  ilOffset = 0x97
    at ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc)  ilOffset = 0x48
    at ImmutableDispatchRuntime.ProcessMessage11(MessageRpc& rpc)  ilOffset = 0x2B7
    at MessageRpc.Process(Boolean isOperationContextSet)  ilOffset = 0x65
    at ChannelHandler.DispatchAndReleasePump(RequestContext request, Boolean cleanThread, OperationContext currentOperationContext)  ilOffset = 0x239
    at ChannelHandler.HandleRequest(RequestContext request, OperationContext currentOperationContext)  ilOffset = 0xEC
    at ChannelHandler.AsyncMessagePump(IAsyncResult result)  ilOffset = 0x39
    at ChannelHandler.OnAsyncReceiveComplete(IAsyncResult result)  ilOffset = 0x19
    at AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)  ilOffset = 0x0
    at AsyncResult.Complete(Boolean completedSynchronously)  ilOffset = 0xC2
    at AsyncQueueReader.Set(Item item)  ilOffset = 0x2F
    at InputQueue`1.Dispatch()  ilOffset = 0x129
    at ScheduledOverlapped.IOCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)  ilOffset = 0x22
    at IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)  ilOffset = 0x5
    at _IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)  ilOffset = 0x78
>
<TraceRecord xmlns="http://schemas.microsoft.com/2004/10/E2ETraceEvent/TraceRecord" Severity="Error">

<TraceIdentifier>http://msdn.microsoft.com/en-AU/library/System.ServiceModel.Diagnostics.ThrowingException.aspx</TraceIdentifier>

<Description>Throwing an exception.</Description>

<AppDomain>/LM/W3SVC/1/ROOT-1-132058283697551644</AppDomain>

<Exception><ExceptionType>System.ComponentModel.Win32Exception, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089</ExceptionType>

<Message>The Security Support Provider Interface (SSPI) negotiation failed.</Message>

<StackTrace>   at System.ServiceModel.Security.WindowsSspiNegotiation.GetOutgoingBlob(Byte[] incomingBlob, ChannelBinding channelbinding, ExtendedProtectionPolicy protectionPolicy)
>   at System.ServiceModel.Security.SspiNegotiationTokenAuthenticator.ProcessNegotiation(SspiNegotiationTokenAuthenticatorState negotiationState, Message incomingMessage, BinaryNegotiation incomingNego)
>   at System.ServiceModel.Security.NegotiationTokenAuthenticator`1.ProcessRequestCore(Message request)
>   at System.ServiceModel.Security.NegotiationTokenAuthenticator`1.NegotiationHost.NegotiationSyncInvoker.Invoke(Object instance, Object[] inputs, Object[]&amp;amp; outputs)
>   at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc&amp;amp; rpc)
>   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(MessageRpc&amp;amp; rpc)
>   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage11(MessageRpc&amp;amp; rpc)
>   at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)
>   at System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(RequestContext request, Boolean cleanThread, OperationContext currentOperationContext)
>   at System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(RequestContext request, OperationContext currentOperationContext)
>   at System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(IAsyncResult result)
>   at System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(IAsyncResult result)
>   at System.Runtime.Fx.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
>   at System.Runtime.AsyncResult.Complete(Boolean completedSynchronously)
>   at System.Runtime.InputQueue`1.AsyncQueueReader.Set(Item item)
>   at System.Runtime.InputQueue`1.Dispatch()
>   at System.Runtime.IOThreadScheduler.ScheduledOverlapped.IOCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
>   at System.Runtime.Fx.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
>   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)
></StackTrace><ExceptionString>System.ComponentModel.Win32Exception (0x80004005): The Security Support Provider Interface (SSPI) negotiation failed.</ExceptionString>
<NativeErrorCode>8009030C</NativeErrorCode>
</Exception>
</TraceRecord>

Client Request Code (fails at service.RetrieveMultiple...):

public phx_web_user GetWebUserFromWebUserLogon(string webUserLogon)
{
    try
    {
        var webuserExp = new ConditionExpression
        {
            AttributeName = PhxMetadata.phx_web_user.Fields.phx_username,
            Operator = ConditionOperator.Equal,
            Values = { webUserLogon }
        };

        var filtExp = new FilterExpression();
        filtExp.AddCondition(webuserExp);

        QueryExpression query = new QueryExpression
        {
            EntityName = phx_web_user.EntityLogicalName,
            Criteria = filtExp
        };

        query.ColumnSet.AllColumns = true;
        query.NoLock = true;

        var response = service.RetrieveMultiple(query);

        if (response.Entities.Count > 0)
            return response.Entities[0].ToEntity<phx_web_user>();
        else
            return null;

    }
    catch (Exception ex)
    {

        throw ex;
    }
}   

Client Connection Code:

ClientCredentials credentials = new ClientCredentials();
credentials.Windows.ClientCredential = new System.Net.NetworkCredential(Global.crmLogon, Global.crmPassword, Global.crmDomain);
using (_serviceProxy = new OrganizationServiceProxy(Global.organizationUri, Global.homeRealmUri, credentials, null))
{
    _serviceProxy.ServiceConfiguration.CurrentServiceEndpoint.Behaviors.Add(new ProxyTypesBehavior());
    System.ServiceModel.EndpointAddress endpointAdd = new System.ServiceModel.EndpointAddress((Global.organizationUri), System.ServiceModel.EndpointIdentity.CreateDnsIdentity(""));
    _serviceProxy.ServiceConfiguration.CurrentServiceEndpoint.Address = endpointAdd;

    _serviceProxy.Timeout = new TimeSpan(0, 5, 0);

    _service = (IOrganizationService)_serviceProxy;
    BusinessLogic logic = new BusinessLogic(_service);

    using (PhoenixContext srv = new PhoenixContext(_service))
    {
        // Change statuse to Locked
        phx_web_user existingWebUser = new phx_web_user();

        phx_web_user tempWebUserRecord = logic.GetWebUserFromWebUserLogon(webUserLogon);

WCF Trace: Client's outgoing SSPI negotiation

Severity    Information
TraceIdentifier http://msdn.microsoft.com/en- 
AU/library/System.ServiceModel.Security.SpnegoClientNegotiation.aspx
Description Client's outgoing SSPI negotiation.
AppDomain   /LM/W3SVC/3/ROOT-1-132059851767534826
Protocol    NTLM
ServicePrincipalName    host/
MutualAuthentication    False
ImpersonationLevel  Impersonate

WCF Trace: Errors - received after outgoing SSPI negotiation

  • "The request for security token could not be satisfied because authentication failed."
  • "The caller was not authenticated by the service."

WCF Trace: Server events

  • Info: "Security Impersonation succeeded at the server." (immediately followed by...)
  • Error: "The Security Support Provider Interface (SSPI) negotiation failed." (and then...)
  • Warning: "Service security negotiation processing failure."

Windows Security Event Log:

  • Failed logon attempts by the user account being used to authenticate to Org Service. Status 0xC000006D suggests bad username/password, but I'm certain this is not the case. Same creds work succesfully from a remote computer.
.net
wcf
authentication
dynamics-crm
microsoft-dynamics
asked on Stack Overflow Jun 26, 2019 by andyb • edited Jun 26, 2019 by andyb

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0