Razor compilation issues on startup with multiple concurrent requests

[jdixon-86]

trafficstars

Prerequisites

• [x] I have written a descriptive issue title
• [x] I have verified that I am running the latest version of Nancy
• [x] I have verified if the problem exist in both DEBUG and RELEASE mode
• [x] I have searched open and closed issues to ensure it has not already been reported

Description

Random unhandled exceptions happen in Nancy.ViewEngines.Razor which seems to be related to the session cookie. While this happens you cannot get to any pages and the only way is recycle IIS or clear the cache out of the browser.

I really wish I had more information but I have multiple environments reporting this issue (customers) and they usually fix it by recycling IIS. The strange thing is I store the sessions in the database so technically recycling IIS doesn't expire the session.

Steps to Reproduce

This is actually pretty hard to reproduce and currently not able to provide any information. It seems the longer the session is inactive or close to expiring is when this shows up the most.

System Configuration

• Nancy version: 2.0.0 Clint Eastwood & Dangermouse
• Nancy host
  • [x] ASP.NET
  • [ ] OWIN
  • [ ] Self-Hosted
  • [ ] Other:
• Other Nancy packages and versions: Nancy.Authentication.Forms, Nancy.Authentication.Stateless, Nancy.Authentication.Aspnet, Nancy.ViewEngines.Razor (all clint eastwood)
• Environment (Operating system, version and so on): Some running 2008 R2, 2012 R2 and even 2016. Happens on all
• .NET Framework version: .NET 4.6.1
• Additional information: Occurs in this method:

private static int GetLineNumber(int startLineIndex, IReadOnlyList<string> compilationSource)
        {

            for (var lineIndex = startLineIndex; lineIndex >= 0; lineIndex--)
            {
                var match = Regex.Match(compilationSource[lineIndex], @"#line (?<row>[\d]+)");
                if (match.Success)
                {
                    return int.Parse(match.Groups["row"].Value);
                }
            }

            return -1;
        }

[jdixon-86]

I just realized I didn't post the error message:

Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code. 

Exception Details: System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index

Source Error: 

An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below.

Stack Trace: 


[ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index]
   System.ThrowHelper.ThrowArgumentOutOfRangeException(ExceptionArgument argument, ExceptionResource resource) +72
   System.SZArrayHelper.get_Item(Int32 index) +13816967
   Nancy.ViewEngines.Razor.RazorViewEngine.GetLineNumber(Int32 startLineIndex, IReadOnlyList`1 compilationSource) +39
   Nancy.ViewEngines.Razor.<>c__DisplayClass19_0.<BuildErrorMessages>b__0(Diagnostic error) +118
   System.Linq.WhereSelectArrayIterator`2.MoveNext() +80
   System.Linq.WhereEnumerableIterator`1.MoveNext() +51
   System.Linq.Buffer`1..ctor(IEnumerable`1 source) +250
   System.Linq.Enumerable.ToArray(IEnumerable`1 source) +106
   Nancy.ViewEngines.Razor.RazorViewEngine.BuildErrorMessages(IEnumerable`1 errors, IList`1 templateLines, IReadOnlyList`1 compilationSource) +272
   Nancy.ViewEngines.Razor.RazorViewEngine.BuildErrorMessage(EmitResult result, ViewLocationResult viewLocationResult, String sourceCode) +366
   Nancy.ViewEngines.Razor.<>c__DisplayClass14_0.<GenerateRazorViewFactory>b__0() +49
   Nancy.ViewEngines.Razor.RazorViewEngine.GetViewInstance(ViewLocationResult viewLocationResult, IRenderContext renderContext, Object model) +1064
   Nancy.ViewEngines.Razor.<>c__DisplayClass9_0.<RenderView>b__0(Stream stream) +4700
   Nancy.Hosting.Aspnet.<ProcessRequest>d__2.MoveNext() +381
   System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +13891908
   System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +61
   System.Web.TaskAsyncHelper.EndTask(IAsyncResult ar) +69
   System.Web.CallHandlerExecutionStep.OnAsyncHandlerCompletion(IAsyncResult ar) +178

[jdixon-86]

Attached is more information when this occurs in an environment. It looks like something didn't load in Nancy right when the application pool recycles sometimes?

Nancy - Razor Compilation Error_files.zip

[thecodejunkie]

Does anyone have a small project that, reliably, reproduces this? It's not unlikely that there is a bug in the GetLineNumber method but we need a reliable way to reproduce it so we can fix it

Thanks!

[jdixon-86]

I am still working on it trying to find out how to reproduce. I've only experienced it in release mode and haven't seen it in debug mode "so far". I can say that once this issue presents itself the only way to fix it is by recycling the application pool and the image above will present itself regardless of the route you attempt to access.

Hopefully I can get more details by EOB today because I plan on dedicating today on reproducing this.

Thank you for the response!

EDIT: I would also like to point out that "System.ArgumentOutOfRangeException: Index was out of range" is an exception in the GetLineNumber() method which causes it to generate a 500 error and display the IIS 500 error message page. I wrapped that in a try/catch returning -1 if an exception occurred. This is what generated the image above now that it no longer throws an exception in GetLineNumber().

[jdixon-86]

Well... I noticed this issue happening when the application pool restarts on idle time or recycling on an interval. I've also noticed this across multiple systems running my application.

I was troubleshooting today, but I can't really attach to the process and monitor this because when the application pool restarts, a new process with a new process ID is generated... creating a problem for me to reproduce it.

[xt0rted]

I've been playing around with back porting the roslyn changes to 1.4 and found a couple spots where we can optimize the code. One of those removes the GetLineNumber() method entirely. Try swapping out your BuildErrorMessages() method for this version.

private static string BuildErrorMessages(IEnumerable<Diagnostic> errors, IList<string> templateLines, IReadOnlyList<string> compilationSource)
{
    var messages = errors.Select(error =>
    {
        var lineSpan = error.Location.GetMappedLineSpan();

        if (!lineSpan.IsValid)
        {
            return null;
        }

        var linePosition = lineSpan.StartLinePosition;
        var lineNumber = linePosition.Line;

        templateLines[lineNumber] = string.Format("<a name='{0}'><span class='error'>{1}</span></a>", lineNumber + 1, templateLines[lineNumber]);

        return string.Format(
            "<li>[{0}] Line: {1} Column: {2} - {3} (<a href='#{1}'>show</a>)</li>",
            error.Id,
            lineNumber + 1,
            linePosition.Character,
            error.GetMessage());
    }).Where(x => x != null).ToArray();

    return string.Join(string.Empty, messages);
}

[jdixon-86]

I haven't tried changing that method but I will give it a shot. Sorry I can't figure out how to reproduce this yet but I do get a lot of reports of this issue. For now I have been telling people to adjust the idle time on the application pool to 0 so it doesn't recycle so much.

[mylemans]

I have a similar issue, and for my project it is easy to get in the faulted state: Simple startup the site, and while its starting (first request is loading) press F5 or open another page on the site in a tab before the first request finishes and you'll get the issue.

From that point on the site is broken until I restart the site.

Any update on this? As we're going live soon and this issue is haunting me :/

[grumpydev]

@mylemans did you try swapping the method out like xt0rted suggested above?

[jdixon-86]

@grumpydev The root cause isn't with the building of the error messages. When this issue occurs it looks like it caused GetLineNumber to throw an exception which was hiding the problem. When I got GetLineNumber to stop throwing the exception you can see the actual error it was throwing in the image above. It seems to be the library is not loading correctly when this issue occurs.

[grumpydev]

@KnowMoreIT ok, thanks, I will take a look at it this week.

[jdixon-86]

@grumpydev Any luck on spotting anything?

[jdixon-86]

@mylemans Have you had any luck troubleshooting this or coming up with a solution?

[jdixon-86]

This is still an issue on the latest prerelease. I've tried to debug this but I don't know enough about the inner working of Nancy yet. Here is where it seems the exception is actually happening:

To me it seems like when loaded there is something wrong with the assembly compliation which results in the Activator.CreateInstance throwing an exception here: return () => (INancyRazorView)Activator.CreateInstance(viewAssembly.GetType("RazorOutput.RazorView"));

Which is caused by the PreExecute method:

Which ends up here (notice the viewAssembly has no defind types):

[jdixon-86]

This MAJOR bug is still a problem. As a workaround I modified some code to at least not cache a bad assembly. I still get notice of people running into this issue from time to time. Nancyfx REALLY needs to fix this.

From what I can tell, Nancy is caching an invalid library. I probably need to make the

 if (!result.Success)
                {
                    return () => new NancyRazorErrorView(BuildErrorMessage(result, viewLocationResult, sourceCode), this.traceConfiguration);
                }

throw an exception as well so it doesn't cache a error view for ALL sessions which requires the application pool to be restarted if result.Success == false.

private Func<INancyRazorView> GenerateRazorViewFactory(IRazorViewRenderer renderer, GeneratorResults generatorResults, Type passedModelType, ViewLocationResult viewLocationResult)
        {
            var modelType = GetModelTypeFromGeneratedCode(generatorResults, passedModelType);
            var sourceCode = string.Empty;

            if (this.razorConfiguration != null)
            {
                if (this.razorConfiguration.AutoIncludeModelNamespace)
                {
                    AddModelNamespace(generatorResults, modelType);
                }
            }

            using (var writer = new StringWriter())
            {
                renderer.Provider.GenerateCodeFromCompileUnit(generatorResults.GeneratedCode, writer, new CodeGeneratorOptions());
                sourceCode = writer.ToString();
            }

            var compilation = CSharpCompilation.Create(
                assemblyName: string.Format("Temp_{0}.dll", Guid.NewGuid().ToString("N")),
                syntaxTrees: new[] { CSharpSyntaxTree.ParseText(sourceCode) },
                references: this.GetMetadataReferences().Value,
                options: new CSharpCompilationOptions(OutputKind.DynamicallyLinkedLibrary));

            using (var ms = new MemoryStream())
            {
                var result = compilation.Emit(ms);

                if (!result.Success)
                {
                    return () => new NancyRazorErrorView(BuildErrorMessage(result, viewLocationResult, sourceCode), this.traceConfiguration);
                }

                ms.Seek(0, SeekOrigin.Begin);
                var viewAssembly = Assembly.Load(ms.ToArray());

                // The compiler seems to mess up sometimes and leave out the RazorView in the assembly. Discard if that is the case
                if (viewAssembly.GetType("RazorOutput.RazorView") == null)
                {
                    throw new BadImageFormatException();
                }

                return () => (INancyRazorView) Activator.CreateInstance(viewAssembly.GetType("RazorOutput.RazorView"));
            }
        }

@thecodejunkie

[jdixon-86]

Any chance on looking at this?