Use of asp-session causing stack overflow #951
Comments
|
Could you post your config? What's the value of throwExceptions? |
<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
internalLogFile="C:\logging\NLog.log"
internalLogLevel="Warn"
autoReload="true">
<extensions>
<!--enable NLog.Web for ASP.NET5-->
<add assembly="NLog.Web.ASPNET5"/>
</extensions>
<!--
See https://github.com/nlog/nlog/wiki/Configuration-file
for information on customizing logging rules and outputs.
-->
<variable name="message_inline" value="${replace:inner=${message}:searchFor=\\r\\n|\\n:replaceWith=\\n:regex=true}"/>
<variable name="exception_inline" value="${replace:inner=${exception:format=ToString}:searchFor=\\r\\n|\\n:replaceWith=\\n:regex=true}"/>
<targets>
<target name="logFileWrapped" xsi:type="AsyncWrapper" overflowAction="Discard" queueLimit="10000" batchSize="100" timeToSleepBetweenBatches="50">
<target xsi:type="File"
fileName="C:\logging\app.log"
archiveFileName="C:\logging\archive\app-archive.{#}.log"
archiveEvery="Day"
archiveOldFileOnStartup="true"
archiveNumbering="DateAndSequence"
maxArchiveFiles="0"
layout="${machinename}|${windows-identity}|${iis-site-name}|${longdate}|${level:uppercase=true}|${logger}|${aspnet-session:Variable=appLoginID}|${callsite-linenumber:skipFrames=3}|${callsite:className=false:fileName=false:includeSourcePath=false:methodName=true:skipFrames=3}|${callsite:className=false:fileName=true:includeSourcePath=false:methodName=false:skipFrames=3}|${message_inline}|${exception_inline}"/>
</target>
<target name="csvFileWrapped" xsi:type="AsyncWrapper" overflowAction="Discard" queueLimit="10000" batchSize="100" timeToSleepBetweenBatches="50">
<target xsi:type="File"
fileName="C:\logging\app.csv"
archiveFileName="C:\logging\archive\app-archive.{#}.csv"
archiveEvery="Day"
archiveOldFileOnStartup="true"
archiveNumbering="DateAndSequence"
maxArchiveFiles="0">
<layout xsi:type="CsvLayout">
<column name="hostname" layout="${machinename}"/>
<column name="username" layout="${windows-identity}"/>
<column name="application" layout="${iis-site-name}"/>
<column name="level" layout="${level:uppercase=true}"/>
<column name="time" layout="${longdate}"/>
<column name="logger" layout="${logger}"/>
<column name="appLoginID" layout="${aspnet-session:Variable=AppLoginID}"/>
<column name="message" layout="${message}"/>
<column name="file" layout="${callsite:className=false:fileName=true:includeSourcePath=false:methodName=false:skipFrames=3}"/>
<column name="lineNumber" layout="${callsite-linenumber:skipFrames=3}"/>
<column name="class" layout="${callsite:className=true:fileName=false:includeSourcePath=false:methodName=false:skipFrames=3}"/>
<column name="method" layout="${callsite:className=false:fileName=false:includeSourcePath=false:methodName=true:skipFrames=3}"/>
<column name="stack" layout="${stacktrace:topFrames=10:skipFrames=3}" />
<column name="exception" layout="${exception}"/>
</layout>
</target>
</target>
<target name="jsonFileWrapped" xsi:type="AsyncWrapper" overflowAction="Discard" queueLimit="10000" batchSize="100" timeToSleepBetweenBatches="50">
<target xsi:type="File"
fileName="C:\logging\app.json"
archiveFileName="C:\logging\archive\app-archive.{#}.json"
archiveEvery="Day"
archiveOldFileOnStartup="true"
archiveNumbering="DateAndSequence"
maxArchiveFiles="0">
<layout xsi:type="JsonLayout">
<attribute name="hostname" layout="${machinename}"/>
<attribute name="username" layout="${windows-identity}"/>
<attribute name="application" layout="${iis-site-name}"/>
<attribute name="level" layout="${level:uppercase=true}"/>
<attribute name="time" layout="${longdate}"/>
<attribute name="logger" layout="${logger}"/>
<attribute name="appLoginID" layout="${aspnet-session:Variable=AppLoginID}"/>
<attribute name="message" layout="${message}"/>
<attribute name="file" layout="${callsite:className=false:fileName=true:includeSourcePath=false:methodName=false:skipFrames=3}"/>
<attribute name="lineNumber" layout="${callsite-linenumber:skipFrames=3}"/>
<attribute name="class" layout="${callsite:className=true:fileName=false:includeSourcePath=false:methodName=false:skipFrames=3}"/>
<attribute name="method" layout="${callsite:className=false:fileName=false:includeSourcePath=false:methodName=true:skipFrames=3}"/>
<attribute name="stack" layout="${stacktrace:topFrames=10:skipFrames=3}" />
<attribute name="exception" layout="${exception}"/>
</layout>
</target>
</target>
</targets>
<rules>
<logger name="*" minlevel="Trace" writeTo="logFileWrapped"/>
<logger name="*" minlevel="Trace" writeTo="csvFileWrapped"/>
<logger name="*" minlevel="Trace" writeTo="jsonFileWrapped"/>
</rules>
</nlog> |
|
There you go. Taking out the aspnet-session variables fixes everything. I'm not sure what you mean by throwExceptions. It doesn't appear to be in our log file though. |
|
ThrowExceptions is an attribute on I see that you have enabled the internal logger. Can you post the exception raised by NLog? |
|
Can you also post the platform an versions? (versions in NuGet ) |
|
Hi, I'm on my phone on the way home so limited in what I can give you but
|
|
I'm thinking for a solution. There are some directions possible:
|
|
PS: We think it is very important to fix this issue . |
|
Thanks for seeing it as important. It did kind of blow everything up for us (and left me very confused that it was taking down the whole process after changing no code!) Please be careful with disabling the logger as there are instances where the same logger is potentially being used on multiple threads/requests in asp.net. It may be best to put a try/catch around the call to the layout renderer and put those exceptions into the NLog file so that there is no risk of those exceptions causing a loop. I like your first solution though. (btw this is just comments based on our use case. I have very little knowledge of the internals. Versions: "dependencies": {
"Microsoft.AspNet.Diagnostics": "1.0.0-rc1-final",
"Microsoft.AspNet.Http.Features": "1.0.0-rc1-final",
"Microsoft.AspNet.IISPlatformHandler": "1.0.0-rc1-final",
"Microsoft.AspNet.Mvc": "6.0.0-rc1-final",
"Microsoft.AspNet.Mvc.Abstractions": "6.0.0-rc1-final",
"Microsoft.AspNet.Mvc.TagHelpers": "6.0.0-rc1-final",
"Microsoft.AspNet.Server.Kestrel": "1.0.0-rc1-final",
"Microsoft.AspNet.Session": "1.0.0-rc1-final",
"Microsoft.AspNet.StaticFiles": "1.0.0-rc1-final",
"Microsoft.AspNet.Tooling.Razor": "1.0.0-rc1-final",
"Microsoft.Extensions.Configuration.Json": "1.0.0-rc1-final",
"Microsoft.Extensions.Logging": "1.0.0-rc1-final",
"Microsoft.Extensions.Logging.Console": "1.0.0-rc1-final",
"Microsoft.Net.Http.Server": "1.0.0-rc1-final",
"Microsoft.AspNet.Hosting.Abstractions": "1.0.0-rc1-final",
"Microsoft.AspNet.Server.WebListener": "1.0.0-rc1-final",
"NLog.Extensions.Logging": "1.0.0-rc1-final-2016-02-06",
"NLog.Web.ASPNET5": "4.2.1"
}Here's the NLog log: |
|
Hi!
|
|
What's the platform (net 4.5?. Net core?) and what is the NLog version? (4.2.3, 4.3, 4.4 beta?) I'm thinking to fix this in NLog 4.3 (rc) and 4.4 beta. Because it could be also an problem with other layout renderers |
|
I checked the code, but don't get it. There is already a try-catch and the exception isn't rethrow by default
|
|
I think the issue is maybe (also) here: https://github.com/aspnet/Session/blob/1.0.0-rc1/src/Microsoft.AspNet.Session/DistributedSession.cs#L142 not sure how to fix this. |
|
Hmm it really does look like the only way to prevent this from happening is to turn the logger off while we're getting the value from the session. Not sure what the further impact is if doing this. It may be worth getting in contact with the asp.net team to a. let them know that this is a problem in this use case and b. see if they know if there is another solution. |
|
I have implemented a fix, can you confirm it's working? It's released as 4.2.2-RC: https://www.nuget.org/packages/NLog.Web.ASPNET5/4.2.2-RC |
|
Sorry I've only just had a chance to look at this. From a brief look, it looks like it is no longer crashing but it doesn't look like the value is being placed in the JSON output at least. I'll have to have another look in the morning. |
|
Hi @dgee2, any luck on this? |
|
Hi, it seems to have worked well. My only comment would be the the NLog log file is growing as we have a significant amount of logging outside of web requests. Currently have the following for 115000 lines... It might be worth looking into having an option to not log exceptions in a layout item or swallow this specific exception. I'm assuming that there isn't another error message that is sitting in the NLog log file that I should be aware of and it's virtually impossible to find anything else atm. |
|
BTW for anyone that sees this, the build suggested doesn't log all of the log levels correctly if you are using RC2 NLog with RC1 asp.net. This is due to the change in logging between RC1 and RC2 on Microsofts part. |
|
Indeed, it's not rc2 compatible. We are waiting for rc2 on nuget, which takes ages. I dunno how to test if the session is available without exception. If we can do that, we can solve this. |
|
I think I would probably wrap it in a try catch and inspect the exception
|
|
Nope didn't speak to aspnet team yet. A try catch without logging is bad. |
|
Well if you expect that this may happen and have a conduit option for it
|
I will do a try-catch and write the error as debug level as work around. If you set the internalloglevel on off, info, warn, error or fatal, this issues has been solved. Will fix this and will release NLog.Web.ASPNET5 4.2.2 afterwards |
|
Cool thanks
|
Done and now a more proper fix. Released in 4.2.2: https://www.nuget.org/packages/NLog.Web.ASPNET5/4.2.2 |
Hi,
I've got a situation where if dnx is restarted for any reason (and thus sessions invalidated) any logging that is performed that has a layout that includes aspnet-session causes a stack overflow. I assume that somewhere there is some code that is trying to log the fact that the session has expired and so given that nlog is then trying to access the session again, we are getting a stack overflow.
Is there any solution to this? We would like to log some information from the session but we obviously cannot have the server crash just from someone accessing the server with an expired session.
Below is a copy of the repeating section of the stack trace:
The text was updated successfully, but these errors were encountered: