dev@grizzly.java.net

Re: Strange filter chaining when an EOFException occurred

From: Oleksiy Stashok <oleksiy.stashok_at_oracle.com>
Date: Tue, 05 Aug 2014 10:59:18 -0700

Hi Bongjae,

my guess is that the same FilterChainContext is used simultaneously by 2
(or more) FilterChains. This may happen when FilterChainContext is
recycled, but still used.
You said it's difficult to reproduce, but is there a testcase, which
fails even if it happens rarely?

Thank you.

WBR,
Alexey.



On 05.08.14 02:29, Bongjae Chang wrote:
> Hi,
>
> When I met an EOFException at the TCPNIOTransportFilter, I saw some
> strange filter chainings.
>
> I have two TCPNIOTransports.
>
> 1. Custom client: it has only two filters(TransportFilter -->
> MyCustomFilter)
> 2. HttpServer using AJP protocol: it maybe has two more
> filters(TransportFilter --> httpServerCodecFilter -->
> IdleTimeoutFilter --> ...)
>
> First, HttpServer received AJP packets then the specific HttpHandler
> called the custom API with the custom client.
> If the http server met EOFException, the following exception occurred.
> I replaced real IP and domain into
> ${http_server_IP},${custom_server_domain} and ${custom_server_IP}.
>
> ====
> 8¿ù 01, 2014 9:38:30 ¿ÀÀü
> org.glassfish.grizzly.http.server.HttpHandler doHandle
> °æ°í: GRIZZLY0200: Service exception
> java.io.EOFException
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:632)
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:75)
> at
> org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:173)
> at
> org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
> at
> org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
> at
> com.kakao.common.util.StatisticKakaoThreadPoolExecutor$StatisticRunnable.run(StatisticKakaoThreadPoolExecutor.java:278)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.runTask(KakaoThreadPoolExecutor.java:950)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.run(KakaoThreadPoolExecutor.java:987)
> at java.lang.Thread.run(Thread.java:744)
>
> 8¿ù 01, 2014 9:38:30 ¿ÀÀü org.glassfish.grizzly.http.server.Request
> onAfterService
> °æ°í: GRIZZLY0204: Unexpected error during afterService notification
> java.lang.NullPointerException
> at
> org.glassfish.grizzly.filterchain.FilterChainContext.notifyDownstream(FilterChainContext.java:895)
> at
> org.glassfish.grizzly.filterchain.FilterChainContext.notifyDownstream(FilterChainContext.java:890)
> at
> org.glassfish.grizzly.http.server.HttpServerFilter$FlushResponseHandler.onAfterService(HttpServerFilter.java:470)
> at
> org.glassfish.grizzly.http.server.Request.onAfterService(Request.java:582)
> at
> org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:385)
> at
> org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:260)
> at
> org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
> at
> org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
> at
> com.kakao.common.util.StatisticKakaoThreadPoolExecutor$StatisticRunnable.run(StatisticKakaoThreadPoolExecutor.java:278)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.runTask(KakaoThreadPoolExecutor.java:950)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.run(KakaoThreadPoolExecutor.java:987)
> at java.lang.Thread.run(Thread.java:744)
>
> 8¿ù 01, 2014 9:38:30 ¿ÀÀü
> org.glassfish.grizzly.filterchain.DefaultFilterChain execute
> °æ°í: GRIZZLY0013: Exception during FilterChain execution
> java.lang.IndexOutOfBoundsException: Index: 5, Size: 2
> at java.util.ArrayList.rangeCheck(ArrayList.java:635)
> at java.util.ArrayList.get(ArrayList.java:411)
> at
> org.glassfish.grizzly.filterchain.ListFacadeFilterChain.get(ListFacadeFilterChain.java:145)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:193)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.write(DefaultFilterChain.java:413)
> at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:407)
> at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:371)
> at
> com.kakao.common.client.AbstractClient.sendInternal(AbstractClient.java:582)
> at
> com.kakao.capri.alfs.client.CapriAlfsClient.increaseAndCheck(CapriAlfsClient.java:46)
> at
> com.kakao.capri.alfs.client.spring.GrizzlyAlfsClientBean.increaseAndCheck(GrizzlyAlfsClientBean.java:300)
> at
> com.kakao.capri.api.server.alfs.AlfsClientDelegator.increaseAndCheck(AlfsClientDelegator.java:178)
> at
> com.kakao.capri.api.server.alfs.AlfsClientDelegator.increaseAndCheck(AlfsClientDelegator.java:156)
> at
> com.kakao.capri.api.server.handler.APIHandler.checkAlfsFilter(APIHandler.java:130)
> at
> com.kakao.capri.api.server.handler.APIHandler.beforeService(APIHandler.java:81)
> at
> com.kakao.server.web.handler.GrizzlyHandler.service(GrizzlyHandler.java:127)
> at
> org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
> at
> org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
> at
> org.glassfish.grizzly.http.server.HttpHandlerChain.doHandle(HttpHandlerChain.java:223)
> at
> org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
> at
> org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
> at
> org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
> at
> com.kakao.common.util.StatisticKakaoThreadPoolExecutor$StatisticRunnable.run(StatisticKakaoThreadPoolExecutor.java:278)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.runTask(KakaoThreadPoolExecutor.java:950)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.run(KakaoThreadPoolExecutor.java:987)
> at java.lang.Thread.run(Thread.java:744)
>
> 8¿ù 01, 2014 9:38:30 ¿ÀÀü org.glassfish.grizzly.ProcessorExecutor execute
> °æ°í: GRIZZLY0029: Error during Processor execution.
> Connection=TCPNIOConnection{localSocketAddress={/${http_server_IP}:33824},
> peerSocketAddress={${custom_server_domain}/${custom_server_IP}:10000}}
> ioEvent=READ
> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_55ef2704
> java.lang.IndexOutOfBoundsException: Index: 6, Size: 2
> at java.util.ArrayList.rangeCheck(ArrayList.java:635)
> at java.util.ArrayList.get(ArrayList.java:411)
> at
> org.glassfish.grizzly.filterchain.ListFacadeFilterChain.get(ListFacadeFilterChain.java:145)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.throwChain(DefaultFilterChain.java:478)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:159)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.write(DefaultFilterChain.java:413)
> at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:407)
> at org.glassfish.grizzly.nio.NIOConnection.write(NIOConnection.java:371)
> at
> com.kakao.common.client.AbstractClient.sendInternal(AbstractClient.java:582)
> at
> com.kakao.capri.alfs.client.CapriAlfsClient.increaseAndCheck(CapriAlfsClient.java:46)
> at
> com.kakao.capri.alfs.client.spring.GrizzlyAlfsClientBean.increaseAndCheck(GrizzlyAlfsClientBean.java:300)
> at
> com.kakao.capri.api.server.alfs.AlfsClientDelegator.increaseAndCheck(AlfsClientDelegator.java:178)
> at
> com.kakao.capri.api.server.alfs.AlfsClientDelegator.increaseAndCheck(AlfsClientDelegator.java:156)
> at
> com.kakao.capri.api.server.handler.APIHandler.checkAlfsFilter(APIHandler.java:130)
> at
> com.kakao.capri.api.server.handler.APIHandler.beforeService(APIHandler.java:81)
> at
> com.kakao.server.web.handler.GrizzlyHandler.service(GrizzlyHandler.java:127)
> at
> org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
> at
> org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
> at
> org.glassfish.grizzly.http.server.HttpHandlerChain.doHandle(HttpHandlerChain.java:223)
> at
> org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
> at
> org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
> at
> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
> at
> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
> at
> org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
> at
> org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
> at
> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
> at
> com.kakao.common.util.StatisticKakaoThreadPoolExecutor$StatisticRunnable.run(StatisticKakaoThreadPoolExecutor.java:278)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.runTask(KakaoThreadPoolExecutor.java:950)
> at
> com.kakao.common.util.KakaoThreadPoolExecutor$Worker.run(KakaoThreadPoolExecutor.java:987)
> at java.lang.Thread.run(Thread.java:744)
> ===
>
> I don't know whether the thread of stack traces is same or not. But I
> know the custom client has only two filter chains but it seems that it
> tries to refer to http filters.
> I think maybe current FilterChainContext or internalContext was wrong.
> In the last exception, peerSocketAddress was correct but
> DefaultFilterChain tried to get index 6 and you can see a NPE during
> getting getFilterChain() in FilterChainContext.
>
> Unfortunately, it is not easy to reproduce it. And I used grizzly
> version v2.3.13.
>
> Could I get some hints about this issue?
>
> Thanks!
>
> Regards,
> Bongjae Chang
>