Support access logging with Common Log Format/Extended Log Format

This is interesting. I wasn't aware the log file format was a standard. Do we think we'd just do this internally in Kestrel or would we try to use ILoggerFactory somehow, e.g. have Kestrel support using its own ILoggerFactory instance which would have an ILoggerProvider configured for this format by default, but could add any other provider to it too via API.

muratg commented 7 years ago

@DamianEdwards Yeah, this is a simple format and there are a bunch of analysis tools since forever that can parse this format and provide information.

We discussed different options for implementing this (just doing it internally and writing a file, providing a stream that user can do whatever they want with, using the existing logging abstractions) -- each has pros and cons.

muratg commented 7 years ago

From @DamianEdwards on February 3, 2017 21:31

Would be good to capture the different approaches and their pros and cons.

muratg commented 7 years ago

From @cesarbs on February 3, 2017 21:35

@DamianEdwards The advantage of using existing log infrastructure is the flexibility and if people use Serilog they get log file rotation and such. The downside is that setting it up is more involved than just offering an option in KestrelServerOptions where they set the file name or Stream to write the logs to.

muratg commented 7 years ago

From @DamianEdwards on February 3, 2017 21:50

How would it work using ILogger? Would Kestrel do all the formatting itself internally and just log the messages through the current ILoggerFactory to whatever providers were configured? Is that enough to get the correct output?

muratg commented 7 years ago

From @cesarbs on February 17, 2017 0:10

Yeah, Kestrel would have to do the formatting. If a logger were to intercept the messages and decorate it in any way, that would make the message useless since it couldn't be parsed by tools that look into these logs.

muratg commented 7 years ago

From @halter73 on February 17, 2017 0:31

Decorated messages wouldn't exactly be useless, but they wouldn't fit the common log format. Presumably if you're using a logger that decorates messages, you aren't to interested in the common log format to begin with. There's also nothing stopping developers from configuring multiple logger providers: one that decorates and another that doesn't for common logs.

I think that common logs should have a unique source so providers can be configured to filter out everything else. Being able to use existing providers to get features like rolling log files, logging to some other persistence layer, etc. certainly would be nice.

muratg commented 7 years ago

From @benaadams on February 17, 2017 0:42

Is it an external component though? The while the layout is standard the output is configurable

For example IIS's options for W3C logging

The fields would have to be identifiable so they can be switched on and off

muratg commented 7 years ago

From @cesarbs on February 17, 2017 1:16

@benaadams Yeah, that's the extended format. The first W3C log format had fixed fields, but modern servers also support Extended Log Format which allows you to specify which fields you want logged per access.

We'd have to add a ServerOptions.AccessLogFormat option, like Apache's LogFormat directive: http://httpd.apache.org/docs/current/logs.html#accesslog

muratg commented 7 years ago

@shirhatti Needs design (though lower pri for 2.0.0)

cwe1ss commented 7 years ago

How about doing this with a DiagnosticListener and one of the existing DiagnosticSource events (EndRequest, HttpRequestIn.Stop)? Requests rejected by the server (e.g. Kestrel) should call some method on Hosting that then raises another DiagnosticSource event - which would be interesting for many other use cases as well anyway.

davidfowl commented 7 years ago

@cwe1ss That's the idea. The one thing we need to figure out is rejected requests that don't make it into hosting.

Tratcher commented 7 years ago

@muratg at this point I assume this isn't happening for 2.0?

muratg commented 7 years ago

@glennc Could you please add this as a feature to track with the 2.1.0 project so that it gets prioritized with the rest of the features.

aliostad commented 6 years ago

This is a very basic feature that should have been in alpha. I understand that originally Kestrel was supposed to run behind proxy but now that it is supported as a standalone. This is especially important for us since we need to run on Service Fabric when no IIS is allowed near it.

muratg commented 6 years ago

@glennc this needs design.

dfdumaresq commented 6 years ago

Should this be mentioned in the 2.2 Roadmap? I don't see a mention of it in Announcements. https://github.com/aspnet/Announcements/issues/307

DamianEdwards commented 6 years ago

It's not in scope for 2.2

dfdumaresq commented 6 years ago

Thanks, @DamianEdwards. When can we expect it?

DamianEdwards commented 6 years ago

Sorry, we have no details on that right now. It hasn't made it's way high enough on the priority list yet.

dfdumaresq commented 6 years ago

Okay. It is a high priority for us. I would venture to say a minimal implementation (i.e. common log format without extended logging) would be a great step forward.

kwkaiwang commented 6 years ago

As a workaround, I use NLog.config to filter 'Microsoft.AspNetCore.Hosting.Internal.WebHost' related entries:

<logger name="*" minlevel="Trace" writeTo="app" />
<logger name="Microsoft.AspNetCore.Hosting.Internal.WebHost" minlevel="Trace" writeTo="web" />

Sample output: 2018-09-10 23:07:31.7749,Info,WK-HOME,11844,1,Request starting HTTP/1.1 GET http://localhost:5000/api/folder
2018-09-10 23:07:31.7764,Info,WK-HOME,11844,2,Request finished in 5.3137ms 304 2018-09-10 23:07:33.1969,Info,WK-HOME,11844,1,Request starting HTTP/1.1 GET http://localhost:5000/sockjs-node/info?t=1536592053194
2018-09-10 23:07:33.1984,Info,WK-HOME,11844,2,Request finished in 9.6846ms 200 application/json; charset=UTF-8 2018-09-10 23:07:33.1984,Info,WK-HOME,11844,1,Request starting HTTP/1.1 GET http://localhost:5000/sockjs-node/659/fcfeqt2t/websocket

JeepNL commented 6 years ago

Hi @DamianEdwards,

You wrote Kestrel (post/request) logging is not high on the priority list for ASP.net Core team. Let me try to convince you otherwise.

a) For some time now you can use Kestrel as a 'stand alone' web server, without the need of a proxy server. It's fast and light weight. That's my setup and I'm loving it.

b) Post and Request logging (according to industry standards) is utterly important nowadays. You really need to have some easy way to check your log to see what's happening with your web server. Check IP addresses and check abuse.

I'm not talking about debugging, you have a couple of other solutions for what already, I'm talking about the safety and performance of my server.

Could you and your team please consider moving this issue higher up your priority list?

Many thanks for all of your hard work, your live videos etc. ASP.NET Core is what I've waited for all of my life. Since 1987 FidoNet :)

aliostad commented 6 years ago

@JeepNL extremely baffles me why they just don't get it.

davidfowl commented 6 years ago

@JeeepNL what exactly are you looking for?

JeepNL commented 6 years ago

@davidfowl Web server log files to analyze with a web server log file analyzer like AWStats

Tratcher commented 6 years ago

I did an experiment to implement this as middleware. Does this look like it would be of use to you @JeepNL? The information is all available on the request, it's just a matter of when. Even if this was implemented inside the server it would still have some timing issues to contend with such as when is the username available.

Output:

info: CommonLog.CommonLogMiddleware[0]
      ::1 Rfc931 Anonymous [15/Sep/2018:20:46:50 -07:00] "GET / HTTP/1.1" 200 6515

As middleware its order in the pipeline becomes an interesting topic that has a few advantages and disadvantages over a server implementation.

If placed after the ForwardedHeadersMiddleware then the remote IP could be reported more accurately behind a reverse proxy.
It could be placed before or after response compression and report byte counts accordingly.
Under some error conditions the server may respond without invoking the OnStarting event. It may also close the connection without responding, or without allowing a response to finish completely.

Where the logs are written to is a less interesting implementation detail. I opted to write them to the standard logging system for now under the assumption they could be filtered later for analysis.

JeepNL commented 6 years ago

Wow! That looks promising @Tratcher. I'm using Kestrel (on a Ubuntu Server) stand alone, not using a reverse proxy. And I'm using the experimental Blazor.net framework. But not for long I think, 'cause "Server Side Blazor" (ie Razor Components in ASP.NET Core 3.0) looks even better to me.

Thank you for your detailed reply! It's going to be fun to try that!

And if, or when it works I'll leave another reply of course :)

JeepNL commented 6 years ago

I did an experiment to implement this as middleware. Does this look like it would be of use to you @JeepNL?

@Tratcher IT WORKS!! Like a charm! It is exactly what I was looking for! And it was so easy to implement. I'm using it on a stand alone Kestrel web server, running a Blazor.net web site which runs on Ubuntu 18.04. Development is done on a Windows 10 desktop with Visual Studio.

Now I can log possible abuse :) I can publish the URL: https://www.ictz.net I mentioned the use of CommonLog on the homepage. The site itself is just for testing purposes. Mainly to test deploying ASP.NET Core Blazor to Ubuntu. For now at least. I have a gazillion ideas with Blazor.

I've added some code to log the info to a file on the server. It works, but is it the correct way of doing this you think? Maybe this impacts web server performance too much?

private void WriteLog(LogState state)
        {
            // TODO: Date formating
            Logger.LogInformation($"{state.RemoteHost} {state.Rfc931} {state.AuthUser} [{state.StartDate}] \"{state.RequestLine}\" {state.StatusCode} {state.Bytes}");

            // ADDED and TODO: Daily Rollover
            using (System.IO.StreamWriter writer = System.IO.File.AppendText("logfile.txt"))
            {
                writer.WriteLine($"{state.RemoteHost} {state.Rfc931} {state.AuthUser} [{state.StartDate}] \"{state.RequestLine}\" {state.StatusCode} {state.Bytes}");
            }
        }

This is so cool! I think you made a lot of people very happy and thank you again for your reply!

Tratcher commented 6 years ago

@JeepNL glad that worked for you. Please file issues in that repo for implementation questions so we can avoid distracting this thread.

keith-leung commented 5 years ago

@JeepNL glad that worked for you. Please file issues in that repo for implementation questions so we can avoid distracting this thread.

I stared your GitHub repo, it's good.

brianmed commented 4 years ago

If you use Serilog, then you can try this Middleware:

https://github.com/brianmed/SerilogW3cMiddleware

JeepNL commented 4 years ago

Any new developments on this? Kestrel support for W3C extended log format out of the box? For .NET 5 maybe?

dotnet / aspnetcore

Support access logging with Common Log Format/Extended Log Format #5894