Aspnetcore: Support access logging with Common Log Format/Extended Log Format

[muratg]

_From @cesarbs on February 3, 2017 18:6_

Every web server does this:

http://httpd.apache.org/docs/current/logs.html#accesslog

http://redmine.lighttpd.net/projects/1/wiki/Docs_ModAccessLog

http://nginx.org/en/docs/http/ngx_http_log_module.html#access_log

https://www.iis.net/configreference/system.applicationhost/log/centralw3clogfile

There are tools that analyze logs using those formats.

For reference:

https://en.wikipedia.org/wiki/Common_Log_Format

https://www.w3.org/TR/WD-logfile.html

_Copied from original issue: aspnet/KestrelHttpServer#1339_

[muratg]

_From @Tratcher on February 3, 2017 18:13_

Would this be better as middleware? Is there any information middleware wouldn't have access to?

[muratg]

_From @cesarbs on February 3, 2017 18:14_

With Kestrel at least, middleware wouldn't log bad requests rejected before the app runs.

[muratg]

@shirhatti @DamianEdwards thoughts?

[muratg]

_From @DamianEdwards on February 3, 2017 21:16_

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]

@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]

_From @DamianEdwards on February 3, 2017 21:31_

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

[muratg]

_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]

_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]

_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]

_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]

_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]

_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]

@shirhatti Needs design (though lower pri for 2.0.0)

[cwe1ss]

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]

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

[Tratcher]

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

[muratg]

@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]

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]

@glennc this needs design.

[dfdumaresq]

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]

It's not in scope for 2.2

[dfdumaresq]

Thanks, @DamianEdwards. When can we expect it?

[DamianEdwards]

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

[dfdumaresq]

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.

[kai-wang-]

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]

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]

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

[davidfowl]

@JeeepNL what exactly are you looking for?

[JeepNL]

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

[Tratcher]

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]

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]

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]

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

[keith-leung]

@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]

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

• https://github.com/brianmed/SerilogW3cMiddleware

[JeepNL]

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

See also Microsoft Docs: W3C Logging

[msftbot[bot]]

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We will evaluate the request when we are planning the work for the next milestone. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.