Wrong output for async servlets

[serban-petrescu]

Summary

Currently, this library produces a misleading output if the Servlet is async enabled. This is because the filter would be called twice: once on the REQUEST dispatch, where the async processing would start and once on the ASYNC dispatch.

I understand that the logging context / correlation ID propagation is out of scope, but the request / response logging is actually faulty in this particular case.

Steps to reproduce:

It easiest to reproduce this with Spring (a lot easier to setup all the stuff):

1. Create a new Spring Boot App.
2. Add the filter.

@Bean
public FilterRegistrationBean loggingFilter() {
	FilterRegistrationBean bean = new FilterRegistrationBean(new RequestLoggingFilter());
	bean.addUrlPatterns("/*");
	return bean;
}

3. Create a controller which returns a Future.

@RestController
class DemoController {
	private static final Logger LOG = LoggerFactory.getLogger(DemoController.class);

	@GetMapping("/something")
	public CompletableFuture<ResponseEntity<String>> doSomething() {
		LOG.info("Inside sync method.");
		return CompletableFuture.supplyAsync(() -> {
			LOG.info("Inside async supply.");
			return new ResponseEntity<>("Something!", HttpStatus.CREATED);
		});
	}
}

Expected behaviour:

The response is logged only once, with the correct size, status, etc.

Actual behaviour:

We get two logs from the RequestLoggingFilter (one for each dispatcher type). The first one has incorrect status / size / etc:

c.s.h.c.l.c.LogContext                   : generated new correlation id
c.e.d.DemoController                     : Inside sync method.
c.e.d.DemoController                     : Inside async supply.
c.s.h.c.l.s.f.RequestLoggingFilter       : {"request":"/something","referer":"-","response_sent_at":"2018-05-14T05:16:12.781Z","response_status":200,"method":"GET","response_size_b":-1,"request_size_b":-1,"remote_port":"redacted","layer":"[SERVLET]","remote_host":"redacted","x_forwarded_for":"-","remote_user":"-","protocol":"HTTP/1.1","remote_ip":"redacted","response_content_type":"-","request_received_at":"2018-05-14T05:16:12.759Z","response_time_ms":22.124503,"direction":"IN"}
c.s.h.c.l.c.LogContext                   : generated new correlation id
c.s.h.c.l.s.f.RequestLoggingFilter       : {"request":"/something","referer":"-","response_sent_at":"2018-05-14T05:16:12.817Z","response_status":201,"method":"GET","response_size_b":10,"request_size_b":-1,"remote_port":"redacted","layer":"[SERVLET]","remote_host":"redacted","x_forwarded_for":"-","remote_user":"-","protocol":"HTTP/1.1","remote_ip":"redacted","response_content_type":"text/plain;charset=UTF-8","request_received_at":"2018-05-14T05:16:12.803Z","response_time_ms":13.84298,"direction":"IN"}

[ChristophEichhorn]

Hi,
currently we do not support async spring servlets. We've tried to reproduce the described behavior. In our case the RequestLoggingFilter was only triggered during Request dispatch and not during Async dispatch.
Best Regards
Christoph

[serban-petrescu]

Hi Christoph,

Async servlets are not Spring-specific, they are part of the Java servlet 3.1 specification. I will try to provide you an example without spring, but I guess I will have to create a project for that, as it involves more configuration.

Regardless, even if you only got the REQUEST dispatch (which most likely means that you simply called complete and not dispatch on the async context; you can find more info on the AsyncContext JavaDoc), the response attributes that you are logging in that case would NOT be the final ones. Based on the java servlet specification 3.1 (which you seem to aim to support), chapter 2.3.3.3, the normal flow for an async servlet is:

1 The request is received and passed via normal filters for authentication etc. to the
servlet.
...
4 The servlet returns without generating a response
...

So treating an asynchronous servlet exactly the same way as a synchronous one is not the correct way to go. In the point of time where your chain.doFilter(..) call returns, the response is not yet available and the logged values will not be correct. The "right" place to do logging would be either in an ASYNC dispatcher or in an AsyncListener.

BR,
Serban

[serban-petrescu]

Here (Gist) you can find an example, which is a very dumbed down version of what Spring's Async Servlet is doing.

Output:

com.sap.hcp.cf.logging.common.LogContext [{component_id=-, component_instance=0, component_name=-, component_type=application, container_id=-, correlation_id=784e42ed-b367-4956-bd14-114119da6a05, organization_id=-, organization_name=-, space_id=-, space_name=-}] - generated new correlation id
com.example.demo.DemoServlet [{component_id=-, component_instance=0, component_name=-, component_type=application, container_id=-, correlation_id=784e42ed-b367-4956-bd14-114119da6a05, organization_id=-, organization_name=-, request_id=-, space_id=-, space_name=-}] - Inside sync method.
com.example.demo.DemoServlet [{}] - Inside async method.
com.sap.hcp.cf.logging.servlet.filter.RequestLoggingFilter [{component_id=-, component_instance=0, component_name=-, component_type=application, container_id=-, correlation_id=784e42ed-b367-4956-bd14-114119da6a05, organization_id=-, organization_name=-, request_id=-, space_id=-, space_name=-}] - {"request":"/","referer":"-","response_sent_at":"2018-05-21T13:12:42.436Z","response_status":200,"method":"GET","response_size_b":-1,"request_size_b":-1,"remote_port":"redacted","layer":"[SERVLET]","remote_host":"redacted","x_forwarded_for":"-","remote_user":"-","protocol":"HTTP/1.1","remote_ip":"redacted","response_content_type":"-","request_received_at":"2018-05-21T13:12:42.433Z","response_time_ms":3.259266,"direction":"IN"}
com.sap.hcp.cf.logging.common.LogContext [{component_id=-, component_instance=0, component_name=-, component_type=application, container_id=-, correlation_id=07e2f087-d6d5-4d30-9d85-1b548cde357c, organization_id=-, organization_name=-, space_id=-, space_name=-}] - generated new correlation id
com.sap.hcp.cf.logging.servlet.filter.RequestLoggingFilter [{component_id=-, component_instance=0, component_name=-, component_type=application, container_id=-, correlation_id=07e2f087-d6d5-4d30-9d85-1b548cde357c, organization_id=-, organization_name=-, request_id=-, space_id=-, space_name=-}] - {"request":"/","referer":"-","response_sent_at":"2018-05-21T13:12:43.450Z","response_status":201,"method":"GET","response_size_b":9,"request_size_b":-1,"remote_port":"redacted","layer":"[SERVLET]","remote_host":"redacted","x_forwarded_for":"-","remote_user":"-","protocol":"HTTP/1.1","remote_ip":"redacted","response_content_type":"-","request_received_at":"2018-05-21T13:12:43.450Z","response_time_ms":0.012095,"direction":"IN"}

As previously stated, the problem is not so much the fact that it logs twice (which can be avoided by not using dispatch but complete - assuming that you have access to the servlet code), but the fact that it logs completely wrong values on the REQUEST dispatcher (which will always be logged in the current library version).

[ChristophEichhorn]

Hi Serban,

thank you again for the examples and your valuable feedback. We are currently investigating how to address this.

Best Regards
Christoph

[KarstenSchnitter]

Hi @serban-petrescu,

once more thank you for reporting this issue and providing such a nice example. I am working on a solution to that issue, that works for a general Servlet.

Best Regards,
Karsten

[serban-petrescu]

Hi Karsten,

My pleasure. To be honest, I initially wanted to help even more if possible (e.g. via a pull request), but I've been really swamped lately...

Thanks a lot for working on a solution. You can count on me for testing the functionality in a "real life" scenario once you manage to release it.

BR,
Serban

[KarstenSchnitter]

We published v2.2.0 that addresses this issue. Please check, whether this works for you.

[serban-petrescu]

One fast point: it looks like you guys have a failing unit test which kills your build (seemingly due to the recent changes): https://travis-ci.org/SAP/cf-java-logging-support/jobs/400420012#L2547

[KarstenSchnitter]

Yes, I am currently working only. Unfortunately it works fine on my machine. I will see, what I can do to fix this.

[KarstenSchnitter]

Seems, that my first try was successful.

[oana-andreea]

Hi Karsten,

For the example above, when updating to version 2.2.0 we get instead of duplicated logging, an error:
onComplete() failed for listener of type [org.apache.catalina.core.AsyncListenerWrapper]

StackTrace:

java.lang.IllegalStateException: It is illegal to call getRequest() after complete() or any of the dispatch() methods has been called  
org.apache.catalina.core.getRequest(AsyncContextImpl.java:217) 
com.sap.hcp.cf.logging.servlet.filter.LoggingAsyncContextImpl.getRequest(LoggingAsyncContextImpl.java:104)
com.sap.hcp.cf.logging.servlet.filter.LoggingAsyncContextImpl$1.generateLog(LoggingAsyncContextImpl.java:33)  
com.sap.hcp.cf.logging.servlet.filter.LoggingAsyncContextImpl$1.onComplete(LoggingAsyncContextImpl.java:63)
org.apache.catalina.core.AsyncListenerWrapper.fireOnComplete(AsyncListenerWrapper.java:39)  
org.apache.catalina.core.AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:108)  
org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:353)  
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:196)  
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)  
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)  
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)  
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)  
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)  
org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:235)  
org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:225)  
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53)  
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)  
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1457)  
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)  
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)  
java.lang.Thread.run(Thread.java:745)

In LoggingAsyncContextImpl the anonymous AsyncListener in

public void onComplete(AsyncEvent event) throws IOException {
	generateLog(loggingVisitor);
}

But the request is already completed, when this method is called.

private void generateLog(final RequestLoggingVisitor loggingVisitor) {
	ServletRequest request = getRequest();

public ServletRequest getRequest() {
	return asyncContext.getRequest();

And in the RequestLoggingVisitor, the wrappers then don't have the request on which to call causing the error.

The temporary solution we found is disabling the wrappers, because then the org.apache.connector.AsyncContextImpl is used without ever instatiating you class LoggingAsyncContextImpl. [RequestLoggingFilter - >LoggingContextRequestWrapper->LoggingAsyncContextImpl].
This solution won't work if you need the content length tracking wrapper, which we don't need.

public FilterRegistrationBean requestLoggingFilterBean() {
        FilterRegistrationBean bean = new FilterRegistrationBean(new RequestLoggingFilter());
        bean.addUrlPatterns("/*");
        bean.addInitParameter("wrapResponse","false");
        bean.addInitParameter("wrapRequest","false");
        return bean;
    } 

[KarstenSchnitter]

Thanks for reporting this issue. Sorry to hear about it though. I will look into this. Disabling the RequestWrapping should also disable the RequestLogging for asynchronous requests. However, I should be able to fix this issue. The request is only needed to retrieve the ContextMap. I can use another way of accessing this one.

[KarstenSchnitter]

I had several tries with different test applications, but was unable to reproduce the issue. I understand from a coding point what the problem is. But the confidence in a solution is poor that way.

A further thing is, that you should register the filter in Spring with the dispatch type REQUEST. I added this to the documentation. Please add the following line to your FilterRegistrationBean:

filterRegistrationBean.setDispatcherTypes(DispatcherType.REQUEST);

[KarstenSchnitter]

I was able to reproduce the issue. It is related to the servlet container being used. It is triggered when using Tomcat, but I cannot reproduce it with Jetty or Undertow. I will fix this issue and test it with all three servlet containers.

[KarstenSchnitter]

I fixed the issue with version 2.2.1. This version will also be available in Maven Central in due time.