Tuesday, October 1, 2019

Azure @ Enterprise - Debugging App Service with Azure AD authentication issues

Not sure how many might have encountered the situation of debugging Azure App Service. Though Microsoft says it is PaaS (Platform as a Service) model, behind the scene it is IIS VMs on steroids. That is good in one way as we can debug in depth. Let us see one debug situation related to AAD authentication in App Service Web App.

Environment

A simple web application served from MVC action and it has some buttons making AJAX calls to the WebAPI Endpoints hosted in the same web application itself. Hosted as Azure App Service Web App. Application Insights configured through the portal itself.

AAD authentication enabled from the Azure Portal without any code change. No module, middleware or injectors used to deal with AAD done by development.

Issue - Symptom

After enabling AAD authentication and protection, the application returns HTTP 500 error instead of redirecting to the login page.

Analysis

Application Insights shows no activity. This is a point of confusion that the request reached to our web app or not. If not where in the Azure App Service runtime it failed.

Enabled logging in App Service. Then it started showing the below log for single HTTP request.
---
2019-10-01T18:39:11  Welcome, you are now connected to log-streaming service. The default timeout is 2 hours. Change the timeout with the App Setting SCM_LOGSTREAM_TIMEOUT (in seconds).
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml"><head><title>IIS Detailed Error - 500.79 - Internal Server Error</title>
<style type="text/css"><!--body{margin:0;font-size:.7em;font-family:Verdana,Arial,Helvetica,sans-serif;}code{margin:0;color:#006600;font-size:1.1em;font-weight:bold;}.config_source code{font-size:.8em;color:#000000;}pre{margin:0;font-size:1.4em;word-wrap:break-word;}ul,ol{margin:10px 0 10px 5px;}ul.first,ol.first{margin-top:5px;}fieldset{padding:0 15px 10px 15px;word-break:break-all;}.summary-container fieldset{padding-bottom:5px;margin-top:4px;}legend.no-expand-all{padding:2px 15px 4px 10px;margin:0 0 0 -12px;}legend{color:#333333;;margin:4px 0 8px -12px;_margin-top:0px;font-weight:bold;font-size:1em;}a:link,a:visited{color:#007EFF;font-weight:bold;}a:hover{text-decoration:none;}h1{font-size:2.4em;margin:0;color:#FFF;}h2{font-size:1.7em;margin:0;color:#CC0000;}h3{font-size:1.4em;margin:10px 0 0 0;color:#CC0000;}h4{font-size:1.2em;margin:10px 0 5px 0;}#header{width:96%;margin:0 0 0 0;padding:6px 2% 6px 2%;font-family:"trebuchet MS",Verdana,sans-serif;color:#FFF;background-color:#5C87B2;}#content{margin:0 0 0 2%;position:relative;}.summary-container,.content-container{background:#FFF;width:96%;margin-top:8px;padding:10px;position:relative;}.content-container p{margin:0 0 10px 0;}#details-left{width:35%;float:left;margin-right:2%;}#details-right{width:63%;float:left;overflow:hidden;}#server_version{width:96%;_height:1px;min-height:1px;margin:0 0 5px 0;padding:11px 2% 8px 2%;color:#FFFFFF;background-color:#5A7FA5;border-bottom:1px solid #C1CFDD;border-top:1px solid #4A6C8E;font-weight:normal;font-size:1em;color:#FFF;text-align:right;}#server_version p{margin:5px 0;}table{margin:4px 0 4px 0;width:100%;border:none;}td,th{vertical-align:top;padding:3px 0;text-align:left;font-weight:normal;border:none;}th{width:30%;text-align:right;padding-right:2%;font-weight:bold;}thead th{background-color:#ebebeb;width:25%;}#details-right th{width:20%;}table tr.alt td,table tr.alt th{}.highlight-code{color:#CC0000;font-weight:bold;font-style:italic;}.clear{clear:both;}.preferred{padding:0 5px 2px 5px;font-weight:normal;background:#006633;color:#FFF;font-size:.8em;}--></style>
</head>
<body><div id="content"><div class="content-container"><h3>
HTTP Error 500.79 - Internal Server Error</h3><h4>The page cannot be displayed because an internal server error has occurred.</h4></div><div class="content-container"><fieldset><h4>
Most likely causes:</h4><ul>
<li>IIS received the request; however, an internal error occurred during the processing of the request. The root cause of this error depends on which module handles the request and what was happening in the worker process when this error occurred.</li>
<li>IIS was not able to access the web.config file for the Web site or application. This can occur if the NTFS permissions are set incorrectly.</li>
<li>IIS was not able to process configuration for the Web site or application.</li>
<li>The authenticated user does not have permission to use this DLL.</li>
<li>The request is mapped to a managed handler but the .NET Extensibility Feature is not installed.</li> </ul></fieldset></div><div class="content-container"><fieldset>
<h4>Things you can try:</h4><ul>
<li>Ensure that the NTFS permissions for the web.config file are correct and allow access to the Web server's machine account.</li>
<li>Check the event logs to see if any additional information was logged.</li>
<li>Verify the permissions for the DLL.</li>
<li>Install the .NET Extensibility feature if the request is mapped to a managed handler.</li>
<li>Create a tracing rule to track failed requests for this HTTP status code. For more information about creating a tracing rule for failed requests, click <a href="http://go.microsoft.com/fwlink/?LinkID=66439">here</a>. </li> </ul></fieldset></div><div class="content-container"><fieldset>
<h4>Detailed Error Information:</h4><div id="details-left"><table border="0" cellpadding="0" cellspacing="0"><tr class="alt">
<th>Module</th><td>&nbsp;&nbsp;&nbsp;EasyAuthModule_32bit</td></tr><tr><th>Notification</th><td>&nbsp;&nbsp;&nbsp;BeginRequest</td></tr>
<tr class="alt"><th>Handler</th><td>&nbsp;&nbsp;&nbsp;ExtensionlessUrlHandler-Integrated-4.0</td></tr><tr><th>Error Code</th><td>&nbsp;&nbsp;&nbsp;0x80004005</td></tr>
</table></div><div id="details-right"><table border="0" cellpadding="0" cellspacing="0"><tr class="alt"><th>Requested URL</th><td>&nbsp;&nbsp;&nbsp;https://httpcaching:80/</td></tr><tr><th>Physical Path</th><td>&nbsp;&nbsp;&nbsp;D:\home\site\wwwroot</td></tr><tr class="alt"><th>Logon Method</th><td>&nbsp;&nbsp;&nbsp;Not yet determined</td></tr><tr><th>Logon User</th><td>&nbsp;&nbsp;&nbsp;Not yet determined</td></tr>
</table><div class="clear"></div></div></fieldset></div>
<div class="content-container"><fieldset><h4>More Information:</h4>This error means that there was a problem while processing the request. The request was received by the Web server, but during processing a fatal error occurred, causing the 500 error.<p><a href="http://go.microsoft.com/fwlink/?LinkID=62293&amp;IIS70Error=500,79,0x80004005,14393">View more information &raquo;</a></p><p>Microsoft Knowledge Base Articles:</p>

</fieldset></div></div></body></html><!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml"><head><title>IIS Detailed Error - 500.79 - Internal Server Error</title><style type="text/css"><!--body{margin:0;font-size:.7em;font-family:Verdana,Arial,Helvetica,sans-serif;}code{margin:0;color:#006600;font-size:1.1em;font-weight:bold;}.config_source code{font-size:.8em;color:#000000;}pre{margin:0;font-size:1.4em;word-wrap:break-word;}ul,ol{margin:10px 0 10px 5px;}ul.first,ol.first{margin-top:5px;}fieldset{padding:0 15px 10px 15px;word-break:break-all;}.summary-container fieldset{padding-bottom:5px;margin-top:4px;}legend.no-expand-all{padding:2px 15px 4px 10px;margin:0 0 0 -12px;}legend{color:#333333;;margin:4px 0 8px -12px;_margin-top:0px;font-weight:bold;font-size:1em;}a:link,a:visited{color:#007EFF;font-weight:bold;}a:hover{text-decoration:none;}h1{font-size:2.4em;margin:0;color:#FFF;}h2{font-size:1.7em;margin:0;color:#CC0000;}h3{font-size:1.4em;margin:10px 0 0 0;color:#CC0000;}h4{font-size:1.2em;margin:10px 0 5px 0;}#header{width:96%;margin:0 0 0 0;padding:6px 2% 6px 2%;font-family:"trebuchet MS",Verdana,sans-serif;color:#FFF;background-color:#5C87B2;}#content{margin:0 0 0 2%;position:relative;}.summary-container,.content-container{background:#FFF;width:96%;margin-top:8px;padding:10px;position:relative;}.content-container p{margin:0 0 10px 0;}#details-left{width:35%;float:left;margin-right:2%;}#details-right{width:63%;float:left;overflow:hidden;}#server_version{width:96%;_height:1px;min-height:1px;margin:0 0 5px 0;padding:11px 2% 8px 2%;color:#FFFFFF;background-color:#5A7FA5;border-bottom:1px solid #C1CFDD;border-top:1px solid #4A6C8E;font-weight:normal;font-size:1em;color:#FFF;text-align:right;}#server_version p{margin:5px 0;}table{margin:4px 0 4px 0;width:100%;border:none;}td,th{vertical-align:top;padding:3px 0;text-align:left;font-weight:normal;border:none;}th{width:30%;text-align:right;padding-right:2%;font-weight:bold;}thead th{background-color:#ebebeb;width:25%;}#details-right th{width:20%;}table tr.alt td,table tr.alt th{}.highlight-code{color:#CC0000;font-weight:bold;font-style:italic;}.clear{clear:both;}.preferred{padding:0 5px 2px 5px;font-weight:normal;background:#006633;color:#FFF;font-size:.8em;}--></style>
</head><body><div id="content"><div class="content-container"><h3>HTTP Error 500.79 - Internal Server Error</h3><h4>The page cannot be displayed because an internal server error has occurred.</h4></div><div class="content-container"><fieldset><h4>Most likely causes:</h4><ul> <li>IIS received the request; however, an internal error occurred during the processing of the request. The root cause of this error depends on which module handles the request and what was happening in the worker process when this error occurred.</li> <li>IIS was not able to access the web.config file for the Web site or application. This can occur if the NTFS permissions are set incorrectly.</li> <li>IIS was not able to process configuration for the Web site or application.</li> <li>The authenticated user does not have permission to use this DLL.</li> <li>The request is mapped to a managed handler but the .NET Extensibility Feature is not installed.</li> </ul></fieldset></div><div class="content-container"><fieldset><h4>Things you can try:</h4><ul> <li>Ensure that the NTFS permissions for the web.config file are correct and allow access to the Web server's machine account.</li> <li>Check the event logs to see if any additional information was logged.</li> <li>Verify the permissions for the DLL.</li> <li>Install the .NET Extensibility feature if the request is mapped to a managed handler.</li> <li>Create a tracing rule to track failed requests for this HTTP status code. For more information about creating a tracing rule for failed requests, click <a href="http://go.microsoft.com/fwlink/?LinkID=66439">here</a>. </li> </ul></fieldset></div>
<div class="content-container"><fieldset><h4>Detailed Error Information:</h4><div id="details-left"><table border="0" cellpadding="0" cellspacing="0"><tr class="alt"><th>Module</th><td>&nbsp;&nbsp;&nbsp;EasyAuthModule_32bit</td></tr><tr><th>Notification</th><td>&nbsp;&nbsp;&nbsp;BeginRequest</td></tr><tr class="alt"><th>Handler</th><td>&nbsp;&nbsp;&nbsp;StaticFile</td></tr><tr><th>Error Code</th><td>&nbsp;&nbsp;&nbsp;0x80004005</td></tr>
</table></div><div id="details-right"><table border="0" cellpadding="0" cellspacing="0"><tr class="alt"><th>Requested URL</th><td>&nbsp;&nbsp;&nbsp;https://httpcaching:80/favicon.ico</td></tr><tr><th>Physical Path</th><td>&nbsp;&nbsp;&nbsp;D:\home\site\wwwroot\favicon.ico</td></tr><tr class="alt"><th>Logon Method</th><td>&nbsp;&nbsp;&nbsp;Not yet determined</td></tr><tr><th>Logon User</th><td>&nbsp;&nbsp;&nbsp;Not yet determined</td></tr>
</table><div class="clear"></div></div></fieldset></div>
<div class="content-container"><fieldset><h4>More Information:</h4>This error means that there was a problem while processing the request. The request was received by the Web server, but during processing a fatal error occurred, causing the 500 error.<p><a href="http://go.microsoft.com/fwlink/?LinkID=62293&amp;IIS70Error=500,79,0x80004005,14393">View more information &raquo;</a></p><p>Microsoft Knowledge Base Articles:</p>
</fieldset></div></div></body></html>
2019-10-01T18:39:21  PID[11164] Information The Modules dll of version 1.0.0 has already been loaded.
2019-10-01T18:39:21  PID[11164] Critical    System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 
System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 
Microsoft.Azure.AppService.Middleware.ConfigurationErrorsException: The provided Issuer URL is not a valid absolute URI stringat Microsoft.Azure.AppService.Middleware.ModuleConfig.set_OpenIdIssuer(String value)--- 
End of inner exception stack trace ---
at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, BindingFlags invokeAttr, Binder binder, Object[] index, CultureInfo culture)
at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, Object[] index)
at Microsoft.Azure.AppService.Middleware.MiddlewareConfig.TryLoadConfig(Type type, HttpContextBase context)
at Microsoft.Azure.AppService.Middleware.ModuleConfig.EnsureConfigLoaded(HttpContextBase context)--- 
End of inner exception stack trace ---
at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadModuleConfig(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadAllModulesAndGetEnabledModules(HttpContextBase context)
at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.EnsureInitialized(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.<DispatchAsync>d__11.MoveNext()
2019-10-01T18:39:21  PID[11164] Information Sending response: 500.79 Internal Server Error
2019-10-01T18:39:21  PID[11164] Information The Modules dll of version 1.0.0 has already been loaded.
2019-10-01T18:39:21  PID[11164] Critical    System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> Microsoft.Azure.AppService.Middleware.ConfigurationErrorsException: The provided Issuer URL is not a valid absolute URI stringat Microsoft.Azure.AppService.Middleware.ModuleConfig.set_OpenIdIssuer(String value)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, BindingFlags invokeAttr, Binder binder, Object[] index, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, Object[] index)at Microsoft.Azure.AppService.Middleware.MiddlewareConfig.TryLoadConfig(Type type, HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleConfig.EnsureConfigLoaded(HttpContextBase context)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadModuleConfig(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadAllModulesAndGetEnabledModules(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.EnsureInitialized(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.<DispatchAsync>d__11.MoveNext()
2019-10-01T18:39:21  PID[11164] Information Sending response: 500.79 Internal Server Error
2019-10-01T18:39:21  PID[11164] Information The Modules dll of version 1.0.0 has already been loaded.
2019-10-01T18:39:21  PID[11164] Critical    System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> Microsoft.Azure.AppService.Middleware.ConfigurationErrorsException: The provided Issuer URL is not a valid absolute URI stringat Microsoft.Azure.AppService.Middleware.ModuleConfig.set_OpenIdIssuer(String value)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, BindingFlags invokeAttr, Binder binder, Object[] index, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, Object[] index)at Microsoft.Azure.AppService.Middleware.MiddlewareConfig.TryLoadConfig(Type type, HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleConfig.EnsureConfigLoaded(HttpContextBase context)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadModuleConfig(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadAllModulesAndGetEnabledModules(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.EnsureInitialized(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.<DispatchAsync>d__11.MoveNext()
2019-10-01T18:39:21  PID[11164] Information Sending response: 500.79 Internal Server Error
2019-10-01T18:39:21  PID[11164] Information The Modules dll of version 1.0.0 has already been loaded.
2019-10-01T18:39:21  PID[11164] Critical    System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> Microsoft.Azure.AppService.Middleware.ConfigurationErrorsException: The provided Issuer URL is not a valid absolute URI stringat Microsoft.Azure.AppService.Middleware.ModuleConfig.set_OpenIdIssuer(String value)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, BindingFlags invokeAttr, Binder binder, Object[] index, CultureInfo culture)at System.Reflection.RuntimePropertyInfo.SetValue(Object obj, Object value, Object[] index)at Microsoft.Azure.AppService.Middleware.MiddlewareConfig.TryLoadConfig(Type type, HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleConfig.EnsureConfigLoaded(HttpContextBase context)--- End of inner exception stack trace ---at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadModuleConfig(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.ModuleManager.LoadAllModulesAndGetEnabledModules(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.EnsureInitialized(HttpContextBase context)at Microsoft.Azure.AppService.Middleware.HttpModuleDispatcher.<DispatchAsync>d__11.MoveNext()
2019-10-01T18:39:21  PID[11164] Information Sending response: 500.79 Internal Server Error#Software: Microsoft Internet Information Services 8.0

---
The first part of the log is an HTML document. That can be viewed in the browser if we save that part into a .html file.

The second portion is a call stack. See the red highlighted area. It says the Issuer URL is not correct. Unfortunately, the Issuer URL in portal configuration was the GUID of the tenant. Not the proper URL.

Fix

Change the Issuer URL to its proper format using the tenant id. Sample below.
https://login.microsoftonline.com/<AAD Tenant Id>

Please note that all debugging sessions would not be this easy. Especially where multiple applications involved and calling each other.

No comments: