Add support for NCSA Extended Log File Format

[jmcc0nn3ll]

migrated from Bugzilla #404328
status ASSIGNED severity minor in component server for 9.3.x
Reported in version 9.0.0 on platform All
Assigned to: Project Inbox

On 2013-03-26 02:01:20 -0400, Greg Wilkins wrote:

It would be good if the request getHost could be logged in the NCSA request log format without breaking its compatibility with common tools.

On 2013-05-21 20:17:04 -0400, Joakim Erdfelt wrote:

We would probably have to support the Extended Log File Format spec a bit better then.

http://www.w3.org/TR/WD-logfile

Such as producing the directives lines at the top of every log file we produce indicating which fields we are emitting.

I think this new field would be "cs-dns".

On 2014-09-22 18:12:57 -0400, Joakim Erdfelt wrote:

Reassigning to default, flagging as helpwanted (our equiv of "low hanging fruit")

On 2015-04-22 20:31:41 -0400, Greg Wilkins wrote:

hmmm serverName is already an option

[joakime]

@gregw looks like this will be hard to implement with the new HttpChannel based RequestLog (see commit 34a8da2). The Response object is no longer being passed to the RequestLog interface.

[bushwakko]

As far as I can see, the Response object is passed to the RequestLog interface:
https://github.com/eclipse/jetty.project/blob/ac24196b0d341534793308d585161381d5bca4ac/jetty-server/src/main/java/org/eclipse/jetty/server/RequestLog.java

It's just not passed to abstract logExtended() method here:
https://github.com/eclipse/jetty.project/blob/ac24196b0d341534793308d585161381d5bca4ac/jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java

[gregw]

@joakime We are passing a Jetty Request, not a Servlet Request, so the getResponse() method is available. So access is not a problem... I'd be more concerned about what values exist and are valid at the time the log is generated.

[joakime]

Issue #342 re-introduced the Response object.
doh! i said Request in the commit, meant Response. :-(

@bushwakko to understand what @gregw said, you can do this ...

    @Override
    protected void logExtended(Request request, StringBuilder b) throws IOException
    {
        Response response = request.getResponse();
        b.append("content-type=").append(response.getContentType());
    }

[gregw]

It would also be good to support %X style info (aborted, persisted, closed) logging

[gregw]

I think it would be good to have a CustomRequestLog that used a format string to format the log lines. I think this can probably be done efficiently with methodHandles, but my handle-foo is not totally up to speed yet. So I have asked https://stackoverflow.com/questions/52962364/how-to-chain-methodhandle-invocations to find out a good way to do this. If I get a satisfactory answer, then I'll give it a go.

[gregw]

I have experimented with MethodHandles as a mechanism for a flexible requestLog and the results are good. The JMH test is committed here c086608#diff-e863396909916b7e9fd3c8cc56e47dff and produced the following results:

Benchmark                                                                         Mode  Cnt         Score         Error   Units
RequestLogBenchmark.testFixed                                                    thrpt   10  18778396.371 ± 4077552.768   ops/s
RequestLogBenchmark.testFixed:·gc.alloc.rate                                     thrpt   10      2174.985 ±     260.236  MB/sec
RequestLogBenchmark.testFixed:·gc.alloc.rate.norm                                thrpt   10       167.950 ±       0.001    B/op
RequestLogBenchmark.testFixed:·gc.churn.CodeHeap_'non-profiled_nmethods'         thrpt   10         0.003 ±       0.004  MB/sec
RequestLogBenchmark.testFixed:·gc.churn.CodeHeap_'non-profiled_nmethods'.norm    thrpt   10        ≈ 10⁻⁴                  B/op
RequestLogBenchmark.testFixed:·gc.churn.G1_Old_Gen                               thrpt   10      2219.510 ±     423.048  MB/sec
RequestLogBenchmark.testFixed:·gc.churn.G1_Old_Gen.norm                          thrpt   10       171.025 ±      18.887    B/op
RequestLogBenchmark.testFixed:·gc.count                                          thrpt   10        74.000                counts
RequestLogBenchmark.testFixed:·gc.time                                           thrpt   10       105.000                    ms
RequestLogBenchmark.testHandle                                                   thrpt   10  18839006.360 ± 3246004.143   ops/s
RequestLogBenchmark.testHandle:·gc.alloc.rate                                    thrpt   10      2091.453 ±     206.936  MB/sec
RequestLogBenchmark.testHandle:·gc.alloc.rate.norm                               thrpt   10       167.950 ±       0.001    B/op
RequestLogBenchmark.testHandle:·gc.churn.CodeHeap_'non-profiled_nmethods'        thrpt   10         0.002 ±       0.002  MB/sec
RequestLogBenchmark.testHandle:·gc.churn.CodeHeap_'non-profiled_nmethods'.norm   thrpt   10        ≈ 10⁻⁴                  B/op
RequestLogBenchmark.testHandle:·gc.churn.G1_Old_Gen                              thrpt   10      2127.172 ±     306.451  MB/sec
RequestLogBenchmark.testHandle:·gc.churn.G1_Old_Gen.norm                         thrpt   10       170.731 ±      15.334    B/op
RequestLogBenchmark.testHandle:·gc.count                                         thrpt   10        69.000                counts
RequestLogBenchmark.testHandle:·gc.time                                          thrpt   10        97.000                    ms
RequestLogBenchmark.testIterate                                                  thrpt   10  16706241.650 ± 2928242.515   ops/s
RequestLogBenchmark.testIterate:·gc.alloc.rate                                   thrpt   10      1839.781 ±     243.576  MB/sec
RequestLogBenchmark.testIterate:·gc.alloc.rate.norm                              thrpt   10       167.950 ±       0.001    B/op
RequestLogBenchmark.testIterate:·gc.churn.CodeHeap_'non-profiled_nmethods'       thrpt   10         0.001 ±       0.001  MB/sec
RequestLogBenchmark.testIterate:·gc.churn.CodeHeap_'non-profiled_nmethods'.norm  thrpt   10        ≈ 10⁻⁴                  B/op
RequestLogBenchmark.testIterate:·gc.churn.G1_Old_Gen                             thrpt   10      1884.937 ±     239.737  MB/sec
RequestLogBenchmark.testIterate:·gc.churn.G1_Old_Gen.norm                        thrpt   10       172.285 ±      12.548    B/op
RequestLogBenchmark.testIterate:·gc.count                                        thrpt   10        62.000                counts
RequestLogBenchmark.testIterate:·gc.time                                         thrpt   10        67.000                    ms

So methodHandles are just as fast as dedicated format code, but produce a little less garbage! @sbordet @joakim can you see anything I can improve with the MethodHandle usage?

[gregw]

@lachlan-roberts Can you work on this issue? We need to create a new class called CustomRequestLog that will take format strings roughly based on http://httpd.apache.org/docs/current/mod/mod_log_config.html. An early task will be to look at that table and see what matches to things we already have logging for, what we can add and what is not really compatible - we should document our own table before writing any code. Then look at the JMH test above to see the technique that I'm suggesting we use... and come up with a way to turn a format string into such a methodHandle. Should be fun!