none
WCS hosted in IIS8.5 - Windows Authentication hangs at some timings with no error/warning RRS feed

  • Question

  • Hello Gurus,

    I posted this on IIS forum earlier but wondered if I should on WCF. This is my first posting and also I am new to IIS/WCF - your help will be very much appreciated.
    I have been working on this issue quite a bit and hit to the point I don't know how to proceed the diagnose from here. In a short, the issue is that Windows authentication hangs at IIS during the process all the sudden at some timings in a day.

    Below issue description:

    [Servers]
    IIS 8.5 hosting WCF on Win2012R2, AppPool: v4.0, Integrated, running with a domain service account identity (SPN registered for Kerberos authentication), Windows Authentication (Kernel-mode, NTLM/Negotiate)
    SQL Server 2012

    [Consumer]
    Windows form application developed with .NET Framework4 vb, HTTP endpoints SSL/TLS - basicHttpBinding

    [System Structure]
    Consumer(Client PC) - IIS Server - SQL Server

    [Issue Description]
    -Windows Authentication (either Negotiate/NTLM) hangs all the sudden during the process at IIS, several times a day. Using the same single domain user ID and IP address for testing and there are no other accesses to the site.
    -Request hung are verified from Worker Process as with a big TimeElapsed value "Url: /MyService.svc Verb:POST Client IP: xx.xx.xx State: AuthenticateRequest, ModuleName: ServiceModel-4.0"
    -Sometimes it resumes working fine after a while, and other times application pool (single app pool for the site) needs to be recycled. Recycling fixes the issue temporary and then it recurs after a while.
    -It does not seem to be related to access volume nor w3wp memory usage, rather seem to be random or sometimes time-related. (e.g. 10am,1pm,5pm ...) 
    -Looking into Fiddler trace, IIS does not respond to client after receiving Windows Authentication request header from client as follows:
       1.Client sends anonymous request (Request Header)
       2.IIS rejects with 401, IIS sends challenge to Client (Response Body)
       3.Client sends Windows Authentication (Request Header) 
       4.IIS does not send Respond Body and process hangs
    -Looking into WireShark trace log and compare it with normal case, it is observed that IIS does not even try to TCP to SQL server for proceeding authentication while it always does when authentication succeeds.
    -To see exactly where the process stops, ran FRT and it was observed that the process ends right before setting response header gracefully and no error/warning is thrown. *Log attached at the bottom, sorry for the long snippet

    I have been wondering if it is to do with our network router or system env. but have no clue how to verify it.
    Is there any way to see what actually is going on during the transactions of "System.ServiceModel.Activation.ServiceHttpModule" when the process cuts off? Or any advice for proceeding more diagnose? (I wanted to attach Service Log image but was not allowed to do so. No exception is thrown and instead it gracefully stops processing without executing the service.)

    Many thanks in advance.

    S.KC

    [EDIT] -------------
    Since this specific WCF service was not developed by me, I totally missed out giving this information that this service refers to <appSettings> in web.config, where SQL Server connection information is referred to. (e.g. <add key="ServerInfo" value="ServerName" /> )
    The service attempts to connect to the SQL server for a specific transaction referring to the value and then sets status code (200/500) depending on the result at SQL server.
    I could reproduce the issue by manipulating this value to non-existing server information. 
    Based upon the fact, it seems that for some reason, service call hangs since it can not connect (find) to the SQL server at some timings.
    Now the question would be what condition would be making this possibly happen and how to capture the root cause..
    -------------

    ------- FRT output Start-------------------------
    37. -AUTH_START 
    38. -AUTH_END

    41. -AUTH_START 
    42. -AUTH_REQUEST_AUTH_TYPE 

    43. -AUTH_SUCCEEDED
    45. -AUTH_END

    67. -FILTER_AUTH_COMPLETE_START 
    68. -FILTER_AUTH_COMPLETE_END

    69 NOTIFY_MODULE_END ModuleName="IsapiFilterModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE"
    70 NOTIFY_MODULE_START ModuleName="DefaultAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true"
    71 AspNetPipelineEnter Data1="System.Web.Security.DefaultAuthenticationModule"
    72 AspNetPipelineLeave Data1="System.Web.Security.DefaultAuthenticationModule"
    73 NOTIFY_MODULE_END ModuleName="DefaultAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE"
    74 NOTIFY_MODULE_START ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true"
    75 AspNetPipelineEnter Data1="System.ServiceModel.Activation.ServiceHttpModule"
    76 GENERAL_READ_ENTITY_START 
    77 GENERAL_READ_ENTITY_END BytesReceived="570", ErrorCode="The operation completed successfully. (0x0)"
    78 GENERAL_REQUEST_ENTITY Buffer="<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Header><ActivityId CorrelationId="f64aee0e-1e9c-4620-a185-3b9d7e377eb8" xmlns="http://schemas.microsoft.com/2004/09/ServiceModel/Diagnostics">1a5a474a-ee28-4246-80b6-b0554ac364be</ActivityId></s:Header><s:Body>.......</s:Body></s:Envelope>"
    79 NOTIFY_MODULE_COMPLETION ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", CompletionBytes="570", ErrorCode="The operation completed successfully. (0x0)"

    =====[Cut-off Here when authentication fails, below when it succeeds]==================

    80 GENERAL_SET_RESPONSE_HEADER HeaderName="Content-Length", HeaderValue="356", Replace="false"
    81 AspNetPipelineLeave Data1="System.ServiceModel.Activation.ServiceHttpModule"
    82 GENERAL_SET_RESPONSE_HEADER HeaderName="Content-Type", HeaderValue="text/xml; charset=utf-8", Replace="true"
    83 NOTIFY_MODULE_COMPLETION ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", CompletionBytes="0", ErrorCode="The operation completed successfully. (0x0)"
    84 NOTIFY_MODULE_END ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_FINISH_REQUEST"
    85 NOTIFY_MODULE_START ModuleName="AspNetFilterModule", Notification="LOG_REQUEST", fIsPostNotification="false"
    86 NOTIFY_MODULE_END ModuleName="AspNetFilterModule", Notification="LOG_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    87 NOTIFY_MODULE_START ModuleName="CustomLoggingModule", Notification="LOG_REQUEST", fIsPostNotification="false"
    88 NOTIFY_MODULE_END ModuleName="CustomLoggingModule", Notification="LOG_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    89 NOTIFY_MODULE_START ModuleName="DynamicIpRestrictionModule", Notification="END_REQUEST", fIsPostNotification="false"
    90 NOTIFY_MODULE_END ModuleName="DynamicIpRestrictionModule", Notification="END_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    91 NOTIFY_MODULE_START ModuleName="ScriptModule-4.0", Notification="END_REQUEST", fIsPostNotification="false"
    92 AspNetPipelineEnter Data1="System.Web.Handlers.ScriptModule"
    93 AspNetPipelineLeave Data1="System.Web.Handlers.ScriptModule"
    94 NOTIFY_MODULE_END ModuleName="ScriptModule-4.0", Notification="END_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    95 NOTIFY_MODULE_START ModuleName="Session", Notification="END_REQUEST", fIsPostNotification="false"
    96 AspNetPipelineEnter Data1="System.Web.SessionState.SessionStateModule"
    97 AspNetPipelineLeave Data1="System.Web.SessionState.SessionStateModule"
    98 NOTIFY_MODULE_END ModuleName="Session", Notification="END_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    99 NOTIFY_MODULE_START ModuleName="Profile", Notification="END_REQUEST", fIsPostNotification="false"
    100 AspNetPipelineEnter Data1="System.Web.Profile.ProfileModule"
    101 AspNetPipelineLeave Data1="System.Web.Profile.ProfileModule"
    102 GENERAL_SET_RESPONSE_HEADER HeaderName="Content-Type", HeaderValue="text/xml; charset=utf-8", Replace="true"
    103 NOTIFY_MODULE_END ModuleName="Profile", Notification="END_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    104 NOTIFY_MODULE_START ModuleName="ClientLoggingHandler", Notification="END_REQUEST", fIsPostNotification="false"
    105 NOTIFY_MODULE_END ModuleName="ClientLoggingHandler", Notification="END_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    106 NOTIFY_MODULE_START ModuleName="ManagedPipelineHandler", Notification="END_REQUEST", fIsPostNotification="true"
    107 GENERAL_SET_RESPONSE_HEADER HeaderName="Content-Type", HeaderValue="text/xml; charset=utf-8", Replace="true"
    108 AspNetEndHandler 
    109 NOTIFY_MODULE_END ModuleName="ManagedPipelineHandler", Notification="END_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE"
    110 NOTIFY_MODULE_START ModuleName="ApplicationInitializationModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    111 NOTIFY_MODULE_END ModuleName="ApplicationInitializationModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    112 NOTIFY_MODULE_START ModuleName="HttpLoggingModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    113 NOTIFY_MODULE_END ModuleName="HttpLoggingModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    114 NOTIFY_MODULE_START ModuleName="IsapiModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    115 NOTIFY_MODULE_END ModuleName="IsapiModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    116 NOTIFY_MODULE_START ModuleName="DigestAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    117 NOTIFY_MODULE_END ModuleName="DigestAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    118 NOTIFY_MODULE_START ModuleName="WindowsAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    119 GENERAL_SET_RESPONSE_HEADER HeaderName="Persistent-Auth", HeaderValue="false", Replace="false"
    120 NOTIFY_MODULE_END ModuleName="WindowsAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    121 NOTIFY_MODULE_START ModuleName="BasicAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    122 NOTIFY_MODULE_END ModuleName="BasicAuthenticationModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    123 NOTIFY_MODULE_START ModuleName="ProtocolSupportModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    124 GENERAL_SET_RESPONSE_HEADER HeaderName="X-Powered-By", HeaderValue="ASP.NET", Replace="false"
    125 NOTIFY_MODULE_END ModuleName="ProtocolSupportModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    126 NOTIFY_MODULE_START ModuleName="IsapiFilterModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    127 NOTIFY_MODULE_END ModuleName="IsapiFilterModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    128 NOTIFY_MODULE_START ModuleName="DynamicCompressionModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    129 DYNAMIC_COMPRESSION_START 
    130 DYNAMIC_COMPRESSION_SUCCESS 
    131 DYNAMIC_COMPRESSION_DO OriginalSize="356", CompressedSize="315"
    132 DYNAMIC_COMPRESSION_END 
    133 NOTIFY_MODULE_END ModuleName="DynamicCompressionModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    134 NOTIFY_MODULE_START ModuleName="HttpCacheModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    135 NOTIFY_MODULE_END ModuleName="HttpCacheModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    136 NOTIFY_MODULE_START ModuleName="CustomErrorModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    137 GENERAL_NOT_SEND_CUSTOM_ERROR Reason="SETSTATUS_SUCCESS"
    138 NOTIFY_MODULE_END ModuleName="CustomErrorModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    139 NOTIFY_MODULE_START ModuleName="DynamicIpRestrictionModule", Notification="SEND_RESPONSE", fIsPostNotification="false"
    140 NOTIFY_MODULE_END ModuleName="DynamicIpRestrictionModule", Notification="SEND_RESPONSE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE"
    141 HTTPSYS_CACHEABLE HttpsysCacheable="false", Reason="VERB_NOT_GET", CachePolicy="NO_CACHE", TimeToLive="0"
    142 GENERAL_FLUSH_RESPONSE_START 
    143 GENERAL_RESPONSE_HEADERS Headers="Content-Type: text/xml; charset=utf-8 Content-Encoding: gzip Vary: Accept-Encoding Server: Microsoft-IIS/8.5 Persistent-Auth: false X-Powered-By: ASP.NET "
    144 GENERAL_RESPONSE_ENTITY_BUFFER Buffer="%1F%8B%08"
    145 GENERAL_RESPONSE_ENTITY_BUFFER Buffer="%E8%FF%01dL%B2Rd%01"
    146 GENERAL_FLUSH_RESPONSE_END BytesSent="826", ErrorCode="The operation completed successfully. (0x0)"
    147 GENERAL_REQUEST_END BytesSent="826", BytesReceived="3777", HttpStatus="200", HttpSubStatus="0"
    ------- FRT output End-------------------------






    • Edited by s.kc Friday, September 18, 2015 12:19 AM
    Wednesday, September 16, 2015 11:59 PM

Answers

  • Hi s.kc,

    According to this issue, may be you need to trace the log file.

    General Debugging Ideas:

    1. Ensure that the service is good by using wcfTestClient (type wcfTestClient in VS command prompt to launch)

    2. Use Tracing as mentioned in How to turn on WCF Tracing?

    3. Verify that the configuration values are in web.config/app.config and not in output.config (in case of auto generation using tools)

    4. Verify that you are referring proper wsdl (is it local file  or url from running service?)

    5. Verify that the wsdl can be viewed by browsing the svc file. Metadata is enabled

    6. Check whether it is relative path or absolute path in the "address" in the service

    7. Set  <serviceDebug includeExceptionDetailInFaults="true" /> in your web.config file.

    Besides, you could refer to the following links for more information:

    1. Configuring Tracing

    I hope that will be helpful to you.

    Best Regards,

    Grady

    Friday, September 18, 2015 1:56 AM
    Moderator

All replies

  • You can also try posting to StackOverFlow for help too.
    Thursday, September 17, 2015 4:04 PM
  • I have added additional info in the first posting with [Edit].
    Friday, September 18, 2015 12:14 AM
  • Hi s.kc,

    According to this issue, may be you need to trace the log file.

    General Debugging Ideas:

    1. Ensure that the service is good by using wcfTestClient (type wcfTestClient in VS command prompt to launch)

    2. Use Tracing as mentioned in How to turn on WCF Tracing?

    3. Verify that the configuration values are in web.config/app.config and not in output.config (in case of auto generation using tools)

    4. Verify that you are referring proper wsdl (is it local file  or url from running service?)

    5. Verify that the wsdl can be viewed by browsing the svc file. Metadata is enabled

    6. Check whether it is relative path or absolute path in the "address" in the service

    7. Set  <serviceDebug includeExceptionDetailInFaults="true" /> in your web.config file.

    Besides, you could refer to the following links for more information:

    1. Configuring Tracing

    I hope that will be helpful to you.

    Best Regards,

    Grady

    Friday, September 18, 2015 1:56 AM
    Moderator