0

I have an async REST API that processes many parallel requests. At some moment after finishing processing around 50 requests (this number is always slightly different), I get the following error message stack:

java.lang.IllegalStateException: Cannot forward after response has been committed
    at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:321) ~[tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:311) ~[tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:395) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.core.StandardHostValve.status(StandardHostValve.java:254) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:349) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:412) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:158) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:222) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.4.jar:8.5.4]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

2016-07-29 16:36:28.505 ERROR 7040 --- [nio-8090-exec-2] o.a.c.c.C.[Tomcat].[localhost]           : Exception Processing ErrorPage[errorCode=0, location=/error]

I was strugelling the whole day with this error... The problem is that I don't understand its origin. I though it has something to do with the Executer, so I configured it as follows:

@Configuration
@SpringBootApplication
@EnableAsync
public class AppConfig {
    @Bean
    public javax.validation.Validator localValidatorFactoryBean() {
        return new LocalValidatorFactoryBean();
    }

    @Bean
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(500);
        executor.setMaxPoolSize(1000);
        executor.setQueueCapacity(1000);
        executor.setThreadNamePrefix("MyExecutor-");
        executor.initialize();
        return executor;
    }

    public static void main(String[] args) {
        SpringApplication.run(AppConfig.class, args);
    }

}

However, the problem still exists. I appreciate greatly if someone can explain me the reason of this issue and how to deal with it.

UPDATE:

In particular the following error is returned:

Whitelabel Error Page

This application has no explicit mapping for /error, so you are seeing this as a fallback.

Fri Jul 29 16:36:28 CEST 2016There was an unexpected error (type=Internal Server Error, status=500).No message available

THIS IS THE CODE:

CONTROLLER

@RestController
@RequestMapping("/test")
public class SController {

    private static long maxConcurrentRequests = 0;

    @Autowired
    Validator validator;

    @Autowired
    SAnalyzer analyzer;

    /**
     * Non-blocking processing
     * @param docId
     * @param document
     * @return
     */
    @RequestMapping(value = "/{docId}/getAnnotation", method = RequestMethod.GET)
    public DeferredResult<Annotations> getAnnotation(@PathVariable String docId,
                                                     @RequestParam(value = "document", defaultValue = "{'id':'1','title':'bla-bla','abstract':'bla-bla','text':'bla-bla'}") String document) {

                LOGGER.info("Logging output to console");
    long reqId = lastRequestId.getAndIncrement();
    long concReqs = concurrentRequests.getAndIncrement();

    LOGGER.info("{}: Start non-blocking request #{}", concReqs, reqId);

    SRequest srequest = new SRequest(SRequest.TYPE_ANNOTATION, docId, document, 1);
    this.validateRequest(srequest);

    // Initiate the processing in another thread
    DeferredResult<Annotations> response = new DeferredResult<>();
    analyzer.getAnnotation(reqId, concurrentRequests, srequest,response);

    LOGGER.info("{}: Processing of non-blocking request #{} leave the request thread", concReqs, reqId);

    // Return to let go of the precious thread we are holding on to...
    return response;

    }

    private void validateRequest(SRequest request) {
        DataBinder binder = new DataBinder(request);
        binder.setValidator(validator);
        binder.validate();
        if (binder.getBindingResult().hasErrors()) {
            throw new BadSysRequestException(binder.getBindingResult().toString());
        }
    }

}

@ResponseStatus(HttpStatus.BAD_REQUEST)
class BadSysRequestException extends RuntimeException {

    public BadSysRequestException(String message) {
        super("Bad request '" + message + "'.");
    }
}

TASK

   @Async
    @Override
    public void getAnnotation(long reqId, AtomicLong concurrentRequests, SRequest request, DeferredResult<Annotations> deferredResult)
    {
        this.deferredResultAnnotations = deferredResult;

        this.concurrentRequests = concurrentRequests;
        long concReqs = this.concurrentRequests.getAndDecrement();
        if (deferredResult.isSetOrExpired()) {
            LOGGER.warn("{}: Processing of non-blocking request #{} already expired {}", concReqs, reqId, request.getDocument());
        } else {
            // result = make some heavy calculations

            deferredResultAnnotations.setResult(result);
            LOGGER.info("{}: Processing of non-blocking request #{} done {}", concReqs, reqId, request.getDocument());
        }

    }
HackerDuck
  • 249
  • 1
  • 5
  • 17
  • Possible duplicate: http://stackoverflow.com/questions/22743803/servlet-with-java-lang-illegalstateexception-cannot-forward-after-response-has – Piotr Wilkin Jul 29 '16 at 14:46
  • @PiotrWilkin: I am not using `forward`. I will post my code snippet in a moment. – HackerDuck Jul 29 '16 at 14:50
  • @PiotrWilkin: I updated my thread. In the thread you provided the reason of the error is specified as: `forward should be called before the response has been committed to the client`. However, I don't understand where do I use `forward` in my code... In particular, I cannot get the point why X requests are successfully processed and only then the problem appears. – HackerDuck Jul 29 '16 at 14:57

1 Answers1

1

Okay, the relevant fragment from the CoyoteAdapter source reads:

        if (status==SocketEvent.TIMEOUT) {
            if (!asyncConImpl.timeout()) {
                asyncConImpl.setErrorState(null, false);
            }
        }

So, it's a socket timeout that wasn't properly handled.

Piotr Wilkin
  • 3,446
  • 10
  • 18
  • Thank you a lot. I will check it now. I send requests from Scala as follows: `val response: HttpResponse[String] = Http(url).timeout(connTimeoutMs = 10000, readTimeoutMs = 20000000).param(param,paramValue).asString`. Probably I need to change `connTimeoutMs`. Is it a good idea to set it to infinite? – HackerDuck Jul 29 '16 at 15:11
  • I increated `connTimeoutMs` and `readTimeputMs` (`connTimeoutMs = 1000000000, readTimeoutMs = 2000000000`), but this error appears again in approximately same moment. So, there is some other place where I should specify the socket timeout. Should I speify it in the REST API-side in some configs? – HackerDuck Jul 29 '16 at 15:20