Strange filter chaining when an EOFException occurred

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Strange filter chaining when an EOFException occurred

Bongjae Chang
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@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

Reply | Threaded
Open this post in threaded view
|

Re: Strange filter chaining when an EOFException occurred

oleksiys
Administrator
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@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


Reply | Threaded
Open this post in threaded view
|

Re: Strange filter chaining when an EOFException occurred

Bongjae Chang
Hi Alexey,

No, I didn’t have the testcase yet. Sometimes I saw errors in production environments. (Actually, I could rarely meet the EOFException.)

Later, I will try to write a testcase and investigate causes more as your hint.

Thanks!

Regards,
Bongjae Chang


From: Oleksiy Stashok <[hidden email]>
Reply-To: <[hidden email]>
Date: Wednesday, August 6, 2014 at 2:59 AM
To: <[hidden email]>
Subject: Re: Strange filter chaining when an EOFException occurred

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@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