Cryptic "Access is Denied" exception from WCF service

Question

I have a secure WCF service with custom authentication. When I am stress testing it - having a few dozens of clients connect at the same time, I often get the following exception in my server-side logs:

System.ServiceModel.FaultException: Access is denied.
   at System.ServiceModel.Dispatcher.AuthorizationBehavior.Authorize(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)

I've enabled tracing through System.Diagnostics but that only got me a longer stack trace:

System.ServiceModel.Dispatcher.AuthorizationBehavior.Authorize(MessageRpc& rpc)
System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(MessageRpc& rpc)
System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)
System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(RequestContext request, Boolean cleanThread, OperationContext currentOperationContext)
System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(RequestContext request, OperationContext currentOperationContext)
System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(IAsyncResult result)
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke2()
System.Security.SecurityContext.Run(SecurityContext securityContext, ContextCallback callback, Object state)
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke()
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ProcessCallbacks()
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.CompletionCallback(Object state)
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ScheduledOverlapped.IOCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
System.ServiceModel.Diagnostics.Utility.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
System.Threading._IOCompletionCallback.PerformIOCompletionCallback

Why is this happening and how can I find out more about what's going wrong here?

Thanks, urig

Answer 1

From "custom authentication" and "[when] a few dozens of clients connect at the same time" I would guess that your custom authentication (from the stack trace: the authorization part) is not fully thread-safe. It could be that any error in the authorization part is (mis-)diagnosed as an "Access denied" error.

There might be some more information in the InnerException properties. But otherwise, maybe you can post some details of your own authorization code.

Answer 2

Still haven't fixed the problem but I'm sure it's indeed within my own custom authentication mechanism - so I'm accepting Henk's answer.

For me, the smoking gun was found when I added diagnostics for System.IdentityModel like so:

<system.diagnostics>
        <sources>
            <source name="System.IdentityModel" switchValue="All">
                <listeners>
                    <add type="System.Diagnostics.DefaultTraceListener" name="Default">
                        <filter type="" />
                    </add>
                    <add name="IdentityModelListener">
                        <filter type="" />
                    </add>
                </listeners>
            </source>
        </sources>
        <sharedListeners>
            <add initializeData="C:\Tracing\App_identitymodellog.svclog" type="System.Diagnostics.XmlWriterTraceListener, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
             name="IdentityModelListener" traceOutputOptions="Timestamp, Callstack">
                <filter type="" />
            </add>
        </sharedListeners>
        <trace autoflush="true" />
    </system.diagnostics>

and in the resulting traces saw this:

System.Environment.get_StackTrace() System.Diagnostics.TraceEventCache.get_Callstack() System.Diagnostics.XmlWriterTraceListener.WriteFooter(TraceEventCache eventCache) System.Diagnostics.TraceSource.TraceData(TraceEventType eventType, Int32 id, Object data) System.ServiceModel.Diagnostics.DiagnosticTrace.TraceEvent(TraceEventType type, TraceCode code, String description, TraceRecord trace, Exception exception, Object source) System.ServiceModel.Diagnostics.DiagnosticTrace.TraceEvent(TraceEventType type, TraceCode code, String description) System.IdentityModel.SecurityUtils.CreateDefaultAuthorizationContext(IList`1 authorizationPolicies) System.ServiceModel.ServiceSecurityContext.get_AuthorizationContext() Foo.Bar..Core.Security.SessionAuthorizationManager.CheckClaimSet(OperationContext operationContext) in ... Foo.Bar..Core.Security.SessionAuthorizationManager.CheckAccess(OperationContext operationContext, Message& message) in ... > System.ServiceModel.Dispatcher.AuthorizationBehavior.Authorize(MessageRpc& rpc) System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(MessageRpc& rpc) System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet) System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(RequestContext request, Boolean cleanThread, OperationContext currentOperationContext) System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(RequestContext request, OperationContext currentOperationContext) System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(IAsyncResult result) System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke2() System.Security.SecurityContext.Run(SecurityContext securityContext, ContextCallback callback, Object state) System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke() System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ProcessCallbacks() System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.CompletionCallback(Object state) System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ScheduledOverlapped.IOCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped) System.ServiceModel.Diagnostics.Utility.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped) System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)

The very next call after Dispatcher.AuthorizationBehavior.Authorize() is to my own implementation of AuthorizationManager. That is most probably where the problem comes from. The Authorize() method merely throws the FaultException as a result.