Kestrel + Nginx cache Error

[ngonzalezromero]

OS: Centos 7
Runtime: Net Core RC2

nginx config

   proxy_cache_path /usr/local/nginx/proxy_temp/ levels=1:2 keys_zone=cache:10m inactive=10m     
   max_size=1000M;

   server {
            listen       80;
             server_name  localhost;
            location / {
                        proxy_set_header  x-real-IP        $remote_addr;
                        proxy_set_header  x-forwarded-for  $proxy_add_x_forwarded_for;
                        proxy_set_header  host             $http_host;
                         proxy_pass http://127.0.0.1:51056/;
                         proxy_cache cache;
                    }   
              }

Kestrel Error

2016-06-16 10:09:10.162 -04:00 [Error] Connection id ""0HKSLTEB67JIM"": An unhandled exception was thrown by the application. System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.<CopyToAsync>d__1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.StaticFiles.StaticFileContext.<SendAsync>d__46.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.<Invoke>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.Server.Kestrel.Http.Frame1.d__2.MoveNext()
2016-06-16 10:09:10.162 -04:00 [Error] Connection id ""0HKSLTEB67JIL"": An unhandled exception was thrown by the application.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.StaticFiles.StaticFileContext.d__46.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.Server.Kestrel.Http.Frame1.<RequestProcessingAsync>d__2.MoveNext() 2016-06-16 10:09:11.855 -04:00 [Warning] Connection processing ended abnormally System.IO.IOException: Error -104 ECONNRESET connection reset by peer ---> Microsoft.AspNetCore.Server.Kestrel.Networking.UvException: Error -104 ECONNRESET connection reset by peer --- End of inner exception stack trace --- at Microsoft.AspNetCore.Server.Kestrel.Http.SocketInput.GetResult() at Microsoft.AspNetCore.Server.Kestrel.Http.Frame1.d__2.MoveNext()
2016-06-16 10:13:14.619 -04:00 [Error] Connection id ""0HKSLTEB67JJI"": An unhandled exception was thrown by the application.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.StaticFiles.StaticFileContext.d__46.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.AspNetCore.Server.Kestrel.Http.Frame1.<RequestProcessingAsync>d__2.MoveNext() 2016-06-16 10:22:07.749 -04:00 [Error] Connection id ""0HKSLTEB67JK7"": An unhandled exception was thrown by the application. System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at Microsoft.AspNetCore.Http.Extensions.StreamCopyOperation.<CopyToAsync>d__1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.StaticFiles.StaticFileContext.<SendAsync>d__46.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.<Invoke>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.Server.Kestrel.Http.Frame1.d__2.MoveNext()
2016-06-16 10:29:17.534 -04:00 [Error] Connection id ""0HKSLTEB67JKM"": An unhandled exception was thrown by the application.
System.Threading.Tasks.TaskCanceledException: A task was canceled.

`

[mikeharder]

This exception can be thrown if the client disconnects while the StaticFile middleware is sending the requested file. Is this what is happening in your scenario? If not, can you please share more information?

• A small application to reproduce the problem
• Does the problem only happen when nginx is proxying to Kestrel? What happens if clients connect directly to Kestrel?

CC: @Tratcher

[ngonzalezromero]

@mikeharder i can't share with us my application, but this error only happen when nginx is proxying.
kestrel works fine..

         public void Configure(IRestHelper restHelper, IServiceProvider service, IApplicationBuilder    
         appBuilder, IHostingEnvironment hostEnv, ILoggerFactory logger, IOptions<AppSettings> appSettings)
          {
           var platform = Microsoft.Extensions.PlatformAbstractions.PlatformServices.Default;
          Console.WriteLine($"Running on: {platform.Runtime.RuntimeType}");
          Console.WriteLine($"Api Rest Url : {appSettings.Value.RestServiceUrlBase}");
          Console.WriteLine($"Software Version: {appSettings.Value.Version}");

        if (hostEnv.IsDevelopment())
        {
            logger.AddConsole(LogLevel.Debug);
            logger.AddDebug(LogLevel.Debug);
        }
        else
        {
            logger.AddConsole(LogLevel.None);
            logger.AddSerilog();
        }

        appBuilder.UseStaticFiles();
        appBuilder.UseCompression();
        appBuilder.UseCustomHeaders();

        appBuilder.UseCookieAuthentication(new CookieAuthenticationOptions()
        {
            SessionStore = new SessionStore(),
            AutomaticAuthenticate = true,
            CookieHttpOnly = true,
            AutomaticChallenge = true
        });

        appBuilder.UseMvc();

        appBuilder.Use((context, next) =>
        {
            if (context.Request.Path.StartsWithSegments("/ping"))
            {
                return context.Response.WriteAsync("pong");
            }
            return next();
        });

        appBuilder.Use(async (context, next) =>
           {
               var path = context.Request.Path.Value;

               if (path == "/")
               {
                   context.Response.Redirect("Default/Index");
               }
               else if (path == "/Default")
               {
                   context.Response.Redirect("Default/Index");
               }
               else if (path == "Default/" || path == "/Default/")
               {
                   context.Response.Redirect("Index");
               }
               else
               {
                   await next();
               }
           }
        );
    }

project.json

         {
"configurations": {
    "Debug": {
        "buildOptions": {
            "define": [
                "DEBUG"
            ]
        }
    },
    "Release": {
        "buildOptions": {
            "define": [
                "RELEASE"
            ],
            "optimize": true
        }
    }
},
"version": "1.0.6",
"buildOptions": {
    "emitEntryPoint": true,
    "preserveCompilationContext": true,
    "debugType": "portable"
},
"runtimeOptions": {
    "configProperties": {
        "System.GC.Server": true,
        "System.GC.Concurrent": true
    }
},
"dependencies": {
    "Microsoft.NETCore.Platforms": "1.0.1-*",
    "Microsoft.AspNetCore.Server.Kestrel": "1.0.0-rc2-final",
    "Microsoft.AspNetCore.Diagnostics": "1.0.0-rc2-final",
    "Microsoft.AspNetCore.Mvc": "1.0.0-rc2-final",
    "Microsoft.AspNetCore.Mvc.TagHelpers": "1.0.0-rc2-final",
    "Microsoft.AspNetCore.StaticFiles": "1.0.0-rc2-final",
    "Microsoft.Extensions.Configuration.Json": "1.0.0-rc2-final",
    "Microsoft.Extensions.Logging": "1.0.0-rc2-final",
    "Microsoft.Extensions.Logging.Console": "1.0.0-rc2-final",
    "Microsoft.Extensions.Logging.Debug": "1.0.0-rc2-final",
    "Microsoft.AspNetCore.Authentication.Cookies": "1.0.0-rc2-final",
    "Microsoft.Extensions.Configuration.Binder": "1.0.0-rc2-final",
    "Serilog.Extensions.Logging": "1.0.0-rc2-10104",
    "Serilog.Sinks.RollingFile": "2.0.0-*",
    "Ngonzalez.Util": "1.2.15"
},
"frameworks": {
    "netcoreapp1.0": {
        "imports": [
            "dnxcore50"
        ],
        "dependencies": {
            "Microsoft.NETCore.App": {
                "version": "1.0.0-rc2-*",
                "type": "platform"
            }
        }
    }
},
"scripts": {
    "postrestore": [
        "bower install",
        "npm install"
    ],
    "prepare": [
        "grunt"
    ]
}

}

[mikeharder]

We still need more information:

• What is the client request which causes this exception? Downloading a static file? How large?
• What happens in the client when making the request both directly to Kestrel and through nginx? It works fine directly to Kestrel, but through nginx you see this exception, and I'm guessing the client fails to download the requested static file?

[ngonzalezromero]

@mikeharder

What is the client request which causes this exception? Downloading a static file? How large?

just only request to js script (angular, jquery, etc)

What happens in the client when making the request both directly to Kestrel and through nginx? It works fine directly to Kestrel, but through nginx you see this exception, and I'm guessing the client fails to download the requested static file?

if i start by making the request to kestrel, it works fine , no exception in nginx
then, if i making the request though to nginx, fails
and i again making the request to kestrel, fails

nginx error

      2016/06/16 10:31:23 [error] 30420#0: *118 upstream timed out (110: Connection timed out) while      
      reading response header from upstream, client:ipserver, server: localhost, request: "GET 
      /fonts/ionicons.ttf?v=2.0.0 HTTP/1.1", upstream: "http://127.0.0.1:51056/fonts/ionicons.ttf?v=2.0.0",  
     host: "ipserver:11002", referrer: "http://ipserver:11002/Default/Index"

ipserver:11002 -> Public ip
http://127.0.0.1:51056 -> kestrel ip

[mikeharder]

Can you try with a simpler nginx config? Just set proxy_pass but no other options, like so:

server {
    location / {
        proxy_pass http://127.0.0.1:51056;
    }
}

[ngonzalezromero]

@mikeharder my app with nginx + kestrel works fine. but adding this line in nginx.conf

     proxy_cache_path /usr/local/nginx/proxy_temp/ levels=1:2 keys_zone=cache:10m inactive=10m     
     max_size=1000M;

and this line (proxy_cache cache) in server section in nginx.conf

    server {
        listen       80;
         server_name  localhost;
        location / {
                    proxy_set_header  x-real-IP        $remote_addr;
                    proxy_set_header  x-forwarded-for  $proxy_add_x_forwarded_for;
                    proxy_set_header  host             $http_host;
                     proxy_pass http://127.0.0.1:51056/;            
                     proxy_cache cache;
                  }   
            }

the app fails

[halter73]

@ngonzalezromero Based on the nginx error, it seems to me that OperationCanceledException/UvException: Error -104 ECONNRESET connection reset by peer is probably happening after nginx times out the connection. To verify this I suggest you enable Trace/Verbose logging. To do this with serilog it would look something like this:

var serilogger = new LoggerConfiguration()
    .WriteTo.RollingFile("myLog.txt")
    .MinimumLevel.Verbose()
    .CreateLogger();

loggerFactory.AddSerilog(serilogger);

In this case it's better to use Serilog over the built-in console logger, because Serilog provides timestamps. Normal log output for a single connection with two requests might look something like this:

2016-06-17 12:18:12.403 -07:00 [Debug] Hosting starting
2016-06-17 12:18:12.633 -07:00 [Debug] Hosting started
2016-06-17 12:18:14.408 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" started.
2016-06-17 12:18:14.561 -07:00 [Information] Request starting HTTP/1.1 GET http://localhost:5000/
2016-06-17 12:18:14.666 -07:00 [Information] Request finished in 121.2029ms 200 text/plain
2016-06-17 12:18:14.679 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" completed keep alive response.
2016-06-17 12:18:14.757 -07:00 [Information] Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico
2016-06-17 12:18:14.762 -07:00 [Information] Request finished in 4.6533ms 200 text/plain
2016-06-17 12:18:14.762 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" completed keep alive response.
2016-06-17 12:18:24.198 -07:00 [Debug] Hosting shutdown
2016-06-17 12:18:24.212 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" disconnecting.
2016-06-17 12:18:24.213 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" sending FIN.
2016-06-17 12:18:24.221 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" sent FIN with status "0".
2016-06-17 12:18:24.223 -07:00 [Debug] Connection id ""0HKSMSGGK0K96"" stopped

I'm interested in confirming that the errors logged by Kestrel only occur after nginx's default proxy_read_timeout of 60 seconds. If so, we will need to investigate why the StaticFileMiddleware is failing to write a response in that time.

[mikeharder]

• Is the failing URL always /fonts/ionicons.ttf?v=2.0.0?
• Is this being served by the StaticFile handler?
• What's the meaning of the v=2.0.0 in the query string? I assume this would be ignored by the static file handler.
• What happens if you directly request this URL using a command-line tool like curl? Please test Kestrel, nginx proxy to Kestrel with no caching, and nginx proxy to Kestrel with caching.

[shahid-pk]

@ngonzalezromero it will be great if you put this log in a gist and link that gist in your comment. This long log is making the thread way too long and thus making it difficult to read the thread.

edit: Actuall i meant updating your previous comment but this is of course just an opinion which should probably go in the contributing/issues guidelines if the team members see fit. i am just a user.

[ngonzalezromero]

@shahid-pk @halter73 @mikeharder

https://gist.github.com/ngonzalezromero/b323153e1d8f9daa66ee460df3b82aa9