CompressionFilter returns error -5 (Z_BUF_ERROR) from jzlib in MINA 1.0 but not in MINA 0.9.4

• Key: DIRMINA-279
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Major
• Assignee: Trustin Lee
• Reporter: Frederic Bregier
• Component/s: Core, Filter
• Affects Version/s: 1.0.0, 1.0.1, 1.0.2, 1.0.3, 1.1.0
• Fix Version/s: 1.0.4, 1.1.1

Description

I found an issue in MINA 1.0 that was not present in MINA 0.9.4 with the compression filter.
I was able to reproduced the problem in small example that I will attach.
The example use both compression and serialization from MINA filters.
The example has two kind of servers : one using demuxingIoHandler and another one without such an IoHandler (simpler).
The example was inspired from the SumUp example. This one should also bug but it was not detected
since the SumUp example was not printing any error while an exception occurs.
The exception is the following, both on the client and server :

java.io.IOException: Compression failed with return value : -5
at org.apache.mina.filter.support.Zlib.deflate(Zlib.java:181)
at org.apache.mina.filter.CompressionFilter.filterWrite(CompressionFilter.java:198)
at org.apache.mina.common.support.AbstractIoFilterChain.callPreviousFilterWrite(AbstractIoFilterChain.java:573)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:52)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.filterWrite(AbstractIoFilterChain.java:789)
at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:221)
at org.apache.mina.common.support.AbstractIoFilterChain.callPreviousFilterWrite(AbstractIoFilterChain.java:573)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:52)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.filterWrite(AbstractIoFilterChain.java:789)
at org.apache.mina.common.support.AbstractIoFilterChain$2.filterWrite(AbstractIoFilterChain.java:213)
at org.apache.mina.common.support.AbstractIoFilterChain.callPreviousFilterWrite(AbstractIoFilterChain.java:573)
at org.apache.mina.common.support.AbstractIoFilterChain.fireFilterWrite(AbstractIoFilterChain.java:564)
at org.apache.mina.transport.socket.nio.SocketSessionImpl.write0(SocketSessionImpl.java:186)
at org.apache.mina.common.support.BaseIoSession.write(BaseIoSession.java:146)
at org.apache.mina.common.support.BaseIoSession.write(BaseIoSession.java:132)
at test.ClientSessionHandler.sessionOpened(ClientSessionHandler.java:30)
at org.apache.mina.common.support.AbstractIoFilterChain$2.sessionOpened(AbstractIoFilterChain.java:156)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionOpened(AbstractIoFilterChain.java:431)
at org.apache.mina.common.support.AbstractIoFilterChain.access$600(AbstractIoFilterChain.java:52)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionOpened(AbstractIoFilterChain.java:752)
at org.apache.mina.common.IoFilterAdapter.sessionOpened(IoFilterAdapter.java:63)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionOpened(AbstractIoFilterChain.java:431)
at org.apache.mina.common.support.AbstractIoFilterChain.access$600(AbstractIoFilterChain.java:52)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionOpened(AbstractIoFilterChain.java:752)
at org.apache.mina.common.IoFilterAdapter.sessionOpened(IoFilterAdapter.java:63)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionOpened(AbstractIoFilterChain.java:431)
at org.apache.mina.common.support.AbstractIoFilterChain.access$600(AbstractIoFilterChain.java:52)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionOpened(AbstractIoFilterChain.java:752)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:261)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:305)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:595)

I have one idea for the reason of the bug but I am not sure since I am not an expert on jzlib usage :
In Mina 0.9.4, the threadpool was inside Mina using its own way.
In Mina 1.0, the threadpool is using backport (or native JDK 1.5 if change are made in Mina code).
(both case are in bugs, with and without backport)
Perhaps the reason of the bug could be any persistent data needed by jzlib in order to compressed
that are not persistent in Mina 1.0.
However, the bug is relative both to the server and the client (which is not supposed to use any thread pool).
And the bug is immediate with only one client making only one connection and from the first write.
So it should not be this way.

Frederic

Comments

[Frederic Bregier]

Attached is a small program that reproduced the bug, inspired from the SumUp example.

[Trustin Lee]

Thank you for attaching a program. Let me test it when this long holiday ends.

[Trustin Lee]

I found that it was because of the change of the behavior of ProtocolCodecFilter. It produces an empty byte buffer as a message delimiter. The filters which are operating in byte-level can have a problem in this case; SSLFilter and CompressionFilter. I modified the default IoFilterChain implementation to bypass next filters if the size of the buffer is 0 to avoid this problem.

[Frederic Bregier]

So I think I can close this issue !
Thank you !

[Frederic Bregier]

Hi all,
I recently upgraded to MINA-trunk (2-M1) and this bug reappears
(compression returns (-5) in exception as described before).
Probably the fix in 1.1 was not redo in 2-M1 ?
WDYT ?
Frederic

[Frederic Bregier]

Change the version concerned by the bug.

[Trustin Lee]

Confirmed my previous fix doesn't resolve the problem when the compression filter is the first filter in the filter chain, due to my small mistake.

[Trustin Lee]

The fix has been checked in.

[Frederic Bregier]

Hi Trustin, it seems the fix generates something wrong in ProtocolCodecFilter.
In fact, right now, even if I don't use compression (most if the time I don't use compression),
for every sent message, I get an exception from server point of vue.
Of course this was not the case before updating.
Here is the error I get since I updated a few minutes ago from svn trunk (MINA 2-M1).

org.apache.mina.filter.codec.ProtocolDecoderException: java.lang.NullPointerException (Hexdump: 00 00 00 55 AC ED 00 05 73 72 00 2A 6F 70 65 6E 6C 73 64 2E 6E 65 74 77 6F 72 6B 2E 63 6F 6D 6D 6F 6E 2E 6D 65 73 73 61 67 65 2E 4C 53 44 4D 73 67 41 64 6D 69 6E 78 70 68 80 00 00 00 00 00 00 00 80 00 00 00 00 00 00 00 01 74 00 0C 61 62 63 64 65 66 67 68 69 6A 6B 6C)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:189)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:395)
at org.apache.mina.common.support.AbstractIoFilterChain.access$5(AbstractIoFilterChain.java:389)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:835)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:256)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:318)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.NullPointerException
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:175)
... 8 more

Should it be considered as a new issue or as the same unresolved ?

Perhaps it could be considered as unresolved on trunk ?
Frederic

[Trustin Lee]

It was other problem cause by my silly mistake! :(
It should work now.

[Frederic Bregier]

No problem Trustin! I was sure you find the problem as always!
Thank you again !
I hope I can post on Mina list some message soon about my project
that is almost ready thanks to Mina...

Frederic