LOGBACK-1052 Have RequestLogImpl implement Jetty's LifeCycle interface

[kylesm]

Have RequestLogImpl implement Jetty's LifeCycle interface directly. This allows logback access to work with Jetty 9.3.0M1 and newer, where the Jetty API was changed in an incompatible way.

[kylesm]

Have RequestLogImpl implement Jetty's LifeCycle interface directly. This allows logback access to work with Jetty 9.3.0M1 and newer, where the Jetty API was changed in an incompatible way (LOGBACK-1052).

[blop]

+1 - Jetty 9.3 is released now and this needs to be fixed :)

[jdillon]

+1 to get this fixed, logback-access is useless asis in Jetty 9.3+ w/o this change.

BTW I tested locally on master and I only had to add Jetty LifeCycle to the impl, no other changes:

https://gist.github.com/jdillon/899193dc6e85e262107b

[fzakaria]

Any update on this?

[tpounds]

FWIW, you can workaround this issue by extending the base class and adding the missing interface as a stopgap if you don't want to rebuild everything from source.

package com.example.ch.qos.logback.access.jetty;

import ch.qos.logback.access.jetty.RequestLogImpl;
import org.eclipse.jetty.util.component.LifeCycle;

public class RequestLogImpl_Fix_LOGBACK_1052 extends RequestLogImpl implements LifeCycle {
}

The Jetty config would just need to be updated to use the wrapper class.

<Ref id="RequestLogHandler">
    <Set name="requestLog">
        <New id="requestLogImpl" class="com.example.ch.qos.logback.access.jetty.RequestLogImpl_Fix_LOGBACK_1052"/>
    </Set>
</Ref>

[robmoore]

If the fix doesn't seem imminent, I'd like to suggest the docs be updated to reflect this situation. I spent an unfortunate amount of time trying to work out why it's not working properly and would like to save others the pain.

[robmoore]

@kylesm Do you happen to know if this fix will be backwards compatible with older versions of Jetty? Just curious if this interface was introduced in the 9.x line.

[ghost]

@robmoore the LifeCycle interface has been around since at least Jetty 6.1.2. A couple of methods were added to it in Jetty 7 but RequestLogImpl has stubbed out versions of them (add/removeLifeCycleListener), so it shouldn't alter the minimum supported version of Jetty.

[robmoore]

@kylesm Thanks, Kyle. I was thinking that perhaps the issue of backwards compatibility was what might be holding this fix up. Good to know it's not an issue.

[joakime]

The RequestLog has transitioned from being a traditional Handler in the Jetty sense, to being a specialized implementation that the HttpChannel uses.

This was done to address many a bug with async request logging, along with request logging of bad requests (ones that cannot be sent to a context).

Since you are using slf4j & logback, you no longer need logback-access in Jetty 9.3+

Use the org.eclipse.jetty.server.Slf4jRequestLog implementation and just configure your normal logback to to route the named logging to the log appender of your choice.

[ChrisMacpherson]

@joakime That does work, but logback-access has specific access log PatternLayout that is really useful in order to create the log format.

I cant see how to create a similar access log format using the pattern facilities in Logback itself without having to write a load of code.

Do you know of a way?

[joakime]

@ChrisMacpherson-awin seeings as the Jetty Slf4jRequestLog is an implementation of the AbstractNCSARequestLog it it satisfying the NCSA output format correctly.

Altering it with a customizable pattern would no longer make it NCSA format compatible.

This logback-access pull request has it now using a LifeCycle, which is fine. I forget the original issues with this pull request. Will need to dig further.

[ChrisMacpherson]

@joakime Okay maybe I just didn't understand the hook up correctly. In logback it needs an encoder in the appender that you use in the named logger. I couldn't work out how to configure it to output the request log data directly without using a pattern. Do you know of any examples anywhere. I couldn't find any.

Anyway I've probably digressed from the purpose of this pull request

[kulinski]

Is there an update on why this PR couldn't be incorporated? We wasted many hours tracking down this issue for what looks like a simple fix that could have been implemented years ago. The current documentation for Jetty 9.3+ and Logback doesn't indicate that logback-access is now incompatible.

We also are using logback custom layouts so switching to Slf4jRequestLog isn't a proper resolution for us. We're currently using the workaround suggested by @tpounds

[davidyscott]

Bump? Any updates?

[mkristian]

we also using @tpounds workaround - rebase/merge this PR please !

[xak2000]

What wrong with this PR (I mean why it isn't accepted)? I'm one of those folks that spent several hours of debugging to understand why the documented behaviour of logback-access library isn't working: the start() method isn't called by Jetty because of this Lifecycle absense. And without debugging and deep knowledge of Jetty internals, it looks like it just silently doesn't work for an unknown reason.

This PR is almost 4 years old and all this time people like me spend time for no reason. If several years ago Jetty 9.3 can be seen as something new, now it is very actual version, if not old (I use 9.4.7 and current version is 9.4.15). So with time passing this PR's demand will only increase.

[joakime]

Note that Jetty 9.4.15+ has a CustomRequestLog that accepts formatting.

Example usage (with slf4j)

        Slf4jRequestLogWriter slf4jRequestLogWriter = new Slf4jRequestLogWriter();
        slf4jRequestLogWriter.setLoggerName("my.requestlog"); // the slf4j named logger to output to
        // The format of the output. (See javadoc for CustomRequestLog for details)
        String requestLogFormat = "%{client}a - %u %t \"%r\" %s %O \"%{Referer}i\" \"%{User-Agent}i\"";
        CustomRequestLog requestLog = new CustomRequestLog(slf4jRequestLogWriter, requestLogFormat);
        server.setRequestLog(requestLog);

[xak2000]

Thanks @joakime ! CustomRequestLog is good if it fulfill your requirements.

But unfortunately, it doesn't have parity in functionality with logback-access.

For example, what I need:

• Full request/response headers (not just one header with specific name, but all).
• Full request/response body (I understand that this requires buffering but when you need debug functionality and load isn't too high - it is acceptable). logback-access supports this out of the box with TeeFilter and you can always disable that filter if debug is off.
• Ability to filter by request URL (e.g. to prevent loadbalancer's healthcheck spamming). See ch.qos.logback.core.filter.EvaluatorFilter and ch.qos.logback.access.net.URLEvaluator.

The main difference between logback-access and other approaches like CustomRequestLog is that with logback-access you have access to current http request/response from the logging event (see ch.qos.logback.access.spi.AccessEvent), while at the same time you can use some functionality of logback (filtering). On the other hand, CustomRequestLog passes just an opaque string to the Slf4j logger. You can't use this string to filtering on logback side. Mabye this can be achievable by using some MDC keys containing request/response info.

[joakime]

• Full request/response headers (not just one header with specific name, but all).

This probably doesn't work on HTTP/2 (or the upcoming HTTP/3), nor would presenting the header hierarchy (current exchange's http fields delta to physical connection's http fields) be useful.

• Full request/response body (I understand that this requires buffering but when you need debug functionality and load isn't too high - it is acceptable). logback-access supports this out of the box with TeeFilter and you can always disable that filter if debug is off.

Any request buffering solution, using traditional Servlet 2.x techniques is incompatible with Servlet 3.0 and the various Async I/O processing. The existence of such a filter or wrapper in the filter chain pretty much means you will not be able to use async features. Every container has gone through this, and moved away from these kinds of approaches (see Jetty's GzipFilter -> GzipHandler + Interceptor pattern)

• Ability to filter by request URL (e.g. to prevent loadbalancer's healthcheck spamming). See ch.qos.logback.core.filter.EvaluatorFilter and ch.qos.logback.access.net.URLEvaluator.

This is supported by ContextHandler facilities in Jetty already.

Finally ...

If these features are what you want, then using Jetty's RequestLog layer is NOT the appropriate place (it never was for the feature set you just provided). The RequestLog layer will log all requests (even upgrade requests, and internal include/forward requests), and on all DispatcherTypes.

Lets evaluate ...

Regarding HttpServletRequest header fields to dump ... Which fields? the actual ones sent on the network connection? (this would be my preference, and that's handled by either a HttpConfiguration.Customizer or HttpChannel.Listener.onRequestBegin()) Or the ones that were seen by the first entry in the servlet/filter chain? (can be different!) Or the state seen at the end of processing of the servlet/filter chain? (can be different again, this is where RequestLog lives) Under which DispatcherType? REQUEST, INCLUDE, FORWARD, ASYNC, ERROR? - (probably good to limit the scope to initial REQUEST / ASYNC types) Point is, HttpServletRequest header fields are not immutable, and many components add/remove/change/decode/encode the header fields to suit the application. Some people might want the "Network Headers" (onRequestBegin()), while others might want "The ones seen by the Servlet" (onBeforeDispatch()), while others might want "The ones at the end of dispatch" (onAfterDispatch()), or even some other point in the HTTP Exchange lifecycle (onDispatchFailure()??). How does logback-access choose?

Regarding the HttpServletResponse header fields to dump ... Which fields? the actual ones sent on the network connection? (best handled by HttpChannel.Listener.onResponseCommit()) The ones seen at the end of dispatch? (this is where RequestLog lives) which DispatcherType? (should probably focus on REQUEST / ASYNC)

Regarding Full Request / Response body ... That's best handled by the Interceptor layer. Use HttpInput.Interceptor to see the body content on Requests Use HttpOutput.Interceptor to see the body content on Responses Make sure you get your interceptor slotted in before/after the GzipHandler's interceptors to see the decoded body content. Don't use Filters, HttpServletRequestWrapper, HttpServletResponseWrapper, or wrapped ServletInputStream, or wrapped ServletOutputStream to accomplish this.

Regarding the filtering by URL ... Note that the URL changes based on the Request DispatcherType. The URL can also change based on other components (such as RedirectHandler's rewrite modes) Be aware of encoded vs decoded vs raw modes that the Servlet 3.0+ spec has introduced with the various URL getters.