You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by Greg Thomas <gr...@gmail.com> on 2019/03/19 12:25:35 UTC
Change in behaviour of CompressionFilter
Openfire - an XMPP server,
https://www.igniterealtime.org/projects/openfire/index.jsp - makes heavy
use of Apache MINA for it's I/O.
One of the things it uses is the CompressionFilter - if clients enable the
Compression XMPP option.
We've recently updated to a newer version of MINA, and with no other code
changes found that enabling compression (in XMPP clients) fails. I've
narrowed it down to changes between MINA 2.0.13 (where it works) and 2.0.14
through to 2.1.0 (where it doesn't) - with Openfire throwing the following
stack trace:
java.nio.InvalidMarkException: null
at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
at
org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
~[mina-core-2.0.14.jar:?]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
~[mina-core-2.0.14.jar:?]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
~[?:1.8.0_162]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
~[?:1.8.0_162]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
Narrowing down even further the commit at
https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
seems
to be the culprit.
At this point, I'm drawing a blank.
It's possible Openfire is using the CompressionFilter wrongly, which was
being masked until the above commit.
It's possible the above commit doesn't do what was intended, but I don't
pretend to understand what it is/should be doing.
It's possible I've got the wrong end of the stick, and it's something else
between MINA 2.0.13 and 2.0.14 that changed that is causing the problem.
But at this point, I don't know where to start, so would appreciate any
pointers!
Thanks,
Greg
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@apache.org>.
And all use of mark() should be removed through the entire codebase... but
thats a second step.
On Wed, Mar 20, 2019 at 10:30 AM Jonathan Valliere <jo...@apache.org>
wrote:
> The offending code is in AbstractPollingIoProcessor. Are you agreeing
> that AbstractPollingIoProcessor has no place modifying the buffer
> positions? Removing buf.reset() would probably fix the problem.
>
>
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commitdiff;h=44b58469f84ce991074cdc187b1c1f23b94cf445;hp=a42871a778c772b52267ef5a68d72cc043aaef54
>
>
> On Wed, Mar 20, 2019 at 10:26 AM Emmanuel Lécharny <el...@gmail.com>
> wrote:
>
>> (replying to the mailing list)
>>
>> On 20/03/2019 15:11, Jonathan Valliere wrote:
>> > And mina is calling reset() bad combo. Why would mina ever need to
>> > modify the position? Just keep on writing the buffer as-is until
>> flushed?
>>
>> It should. Any filter taking a IoBuffer as an input should *never*
>> modify it. It could replace it, but not reset/flip/whatever.
>>
>> I suspect there is some attempt to avoid creating a new buffer at some
>> point, for performance reasons. We shoudl review all the filters to
>> check that they are not doing such a thing...
>>
>> >
>> > On Wed, Mar 20, 2019 at 10:01 AM Emmanuel Lécharny
>> > <elecharny@gmail.com <ma...@gmail.com>> wrote:
>> >
>> >
>> > On 20/03/2019 14:02, Jonathan Valliere wrote:
>> > > Nothing in Mina should use the mark/reset functionality because
>> > it does not
>> > > compound and the unknown addition of filters create edge cases
>> > where it is
>> > > compounded. Should manually grab he position and manually
>> > revert the
>> > > position when necessary.
>> >
>> >
>> > The zlib class is flipping the buffer, that may be the cause of
>> > this issue.
>> >
>> > public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
>> > if (mode == MODE_INFLATER) {
>> > throw new IllegalStateException("not initialized as
>> > DEFLATER");
>> > }
>> >
>> > byte[] inBytes = new byte[inBuffer.remaining()];
>> > inBuffer.get(inBytes).flip();
>> >
>>
>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
On 25/03/2019 02:10, Jonathan Valliere wrote:
> I’m going to look at this starting Tuesday. Emmanuel do you mind creating
> a branch for this Jira issue so I can track what you’re working on?
The branch name is 'mina-write-request'. It's from MINA 2.1.
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
On 25/03/2019 02:10, Jonathan Valliere wrote:
> I’m going to look at this starting Tuesday. Emmanuel do you mind creating
> a branch for this Jira issue so I can track what you’re working on?
Sure
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
FTR, I have all the test passwing with my committed changes, but one :
SslFilterTest.testMessageSentIsCalled_With_SSL. I get this stack trace :
`
javax.net.ssl.SSLException: bad record MAC
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1946)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1022)
at
sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1367)
at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:750)
at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:123)
at java.io.OutputStream.write(OutputStream.java:75)
at
org.apache.mina.example.echoserver.ssl.SslFilterTest.writeMessage(SslFilterTest.java:137)
at
org.apache.mina.example.echoserver.ssl.SslFilterTest.testMessageSentIsCalled(SslFilterTest.java:100)
at
org.apache.mina.example.echoserver.ssl.SslFilterTest.testMessageSentIsCalled_With_SSL(SslFilterTest.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at
org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:89)
at
org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:41)
at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:541)
at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:763)
at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:463)
at
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:209)
Caused by: javax.crypto.BadPaddingException: bad record MAC
at sun.security.ssl.InputRecord.decrypt(InputRecord.java:219)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1017)
... 32 more
I'm investigating this one. Most certainly a buffer issue (the test
passes in 2.0.20).
On 25/03/2019 02:10, Jonathan Valliere wrote:
> I’m going to look at this starting Tuesday. Emmanuel do you mind creating
> a branch for this Jira issue so I can track what you’re working on?
>
> On Sun, Mar 24, 2019 at 3:54 AM Emmanuel Lécharny <el...@gmail.com>
> wrote:
>
>> Things are complicated :/
>>
>> Ok, after two days of investigation, my take is that the original sin
>> was to use a IoBuffer to propagate a message across the filters.
>> IoBuffers can be consumed (ie, when you read them, their position
>> change) making it very complex not to abuse them when writing a filter.
>>
>> Typical problem arose in SslFilter, ProtocolCodecFilter, LoggingFilter,
>> CompressionFilter (and probably some more). Lets see what happens for
>> those filters.
>>
>> LoggingFilter: actually, nothing is logged for filterWrite ! That kind
>> of 'fix' the issue, by ignoring it. OTOH, it's not consistent: we may
>> want to know what is being written...
>>
>> SslFilter: it's pretty obvious that the incoming filter will be fully
>> consumed, and a new buffer will be produced. The interesting thing is
>> that the SslEngine use ByteBuffer to encrypt/decrypt data. Anyway, we
>> consume the incoming buffer, no matter what, and it's a side effect.
>>
>> ProtocolCodecFilter: it also consume the incoming message, which can be
>> any kind of data structure. It doesn't matter because the factory is
>> application specific (or it's one of the on the shelf factories). The
>> special case is when the incoming message is an IoBuffer (not really
>> frequently the case...)
>>
>> CompressionFilter: it takes a IoBuffer as input and produce a new one,
>> having consumed the incoming IoBuffer.
>>
>> etc, etc.
>>
>> So when we have fully written the message, any IoBuffer than have been
>> created in the filters - or any IoBBuffer that was passed by the
>> application - would have been consumed. If we want to propagate a
>> messageSent event, we need to have kept a track of the original message,
>> and if it was a IoBuffer, that would mean duplicating it, or flip it
>> before calling messageSent() just after having written it fully...
>>
>> Now, why are we using IoBuffer at all ? For three reasons:
>>
>> - ByteBuffer are immutable. It's valuable to be able to 'grow' a
>> IoBuffer, typically when we inflate a message
>>
>> - SslEngine is using ByteBuffer, IoBuffer encapsulate one
>>
>> - Ultimately, writing into a channel is done using a ByteBuffer, so not
>> having to create one when calling write on a channel saves some copy.
>> But this is really when we have an app that has no filter modifying the
>> IoBuffer. A rare corner case.
>>
>> So my take is that using an IoBuffer is a premature optimization. Just
>> because channels require ByteBuffer does not lmean we shiould use
>> ByteBuffer acorss the filters, except for the SslBuffer - which should
>> always be the first filter in the chain anyway. We should also always
>> keep a track of the original message, unmodified, so that the
>> messageSent eveent can be propagated properly. Obviously, if the
>> original message is an IoBuffer, and is never modified by any filteer,
>> duplicating it before sending it just because we want to keep it intact
>> for the messageSent event is a waste, but OTOH, it's very unlikely to be
>> a frequent use case...
>>
>> I'm currently working on implementing that, and so far, it's going well.
>>
>>
>> I'll keep the list informed.
>>
>> On 22/03/2019 13:35, Emmanuel Lécharny wrote:
>>> Ok, I have a version that works better with the CompressionFilter.
>>>
>>>
>>> Here is what I have changed :
>>>
>>> - the session.write( <message> ) method will inject the original
>>> message into the WriteRequest
>>>
>>> - any filterWrite filter that is going to create a new version of the
>>> message will store it in the same writeRequest, into a modifiedMessage
>>> field. (The WriteRequest impl thus holds 2 versions of the message,
>>> the odiginal one and the modified one)
>>>
>>> - when the modified message is written to the remote peer (it's now an
>>> IoBuffer), messageSent will be called with the original message, or
>>> with the written IoBuffer flipped if the original message was a
>>> IoBuffer and was never modified.
>>>
>>> The first test I did with the chat example seems to work pretty well.
>>> It's going through a TextLineCodecFactory codec filter, a
>>> CompressionFilter. I have to test it with the LoginFilter and the
>>> SslFilter.
>>>
>>>
>>> All in all, the MINA code is much simpler and should be faster too, as
>>> we spare spurious calls to messageSent and filterWrite with an Empty
>>> message.
>>>
>>>
>>> More to come soon.
>>>
>>> On 22/03/2019 04:58, Emmanuel Lécharny wrote:
>>>> Hmmpphhhh....
>>>>
>>>> I have traced the calls when a session.write( <blah> ) is done.
>>>>
>>>>
>>>> It's all a kind of a hack.
>>>>
>>>>
>>>> In order to be able to send the messageSent() event, the
>>>> protocolFilter will call the nextFilter.filterWrite() method twice :
>>>>
>>>> public void filterWrite(NextFilter nextFilter, IoSession session,
>>>> WriteRequest writeRequest) throws Exception {
>>>> Object message = writeRequest.getMessage();
>>>>
>>>> ...
>>>> // Write all the encoded messages now
>>>> while (!bufferQueue.isEmpty()) {
>>>> Object encodedMessage = bufferQueue.poll();
>>>>
>>>> // Flush only when the buffer has remaining.
>>>> if (!(encodedMessage instanceof IoBuffer) ||
>>>> ((IoBuffer) encodedMessage).hasRemaining()) {
>>>> SocketAddress destination =
>>>> writeRequest.getDestination();
>>>> WriteRequest encodedWriteRequest = new
>>>> EncodedWriteRequest(encodedMessage, null, destination);
>>>>
>>>> nextFilter.filterWrite(session,
>>>> encodedWriteRequest);
>>>> }
>>>> }
>>>>
>>>> // Call the next filter
>>>> nextFilter.filterWrite(session, new
>>>> MessageWriteRequest(writeRequest));
>>>>
>>>> The first call we go down the chain with an IoBuffer containing the
>>>> encoded message, the second call will use th e original message
>>>> wrapped in a specific MessageWriteRequest instance, which will always
>>>> return an empty IoBuffer when a getMessage() is called on it :
>>>>
>>>> private static class MessageWriteRequest extends
>>>> WriteRequestWrapper {
>>>> @Override
>>>> public Object getMessage() {
>>>> return EMPTY_BUFFER;
>>>> }
>>>>
>>>> It goes down the chain to the HeadFilter where it gets stacked to be
>>>> written. But as it's an empty buffer, the flush() method will do
>>>> nothing but initiate a call to messageSent() which will pop up to the
>>>> handler. Actually, the messageSent() event will be issued twice, once
>>>> with the encoded message, and it will be swallowed silently by the
>>>> ProtocolCodecFilter :
>>>>
>>>> public void messageSent(NextFilter nextFilter, IoSession session,
>>>> WriteRequest writeRequest) throws Exception {
>>>> if (writeRequest instanceof EncodedWriteRequest) {
>>>> return;
>>>>
>>>> and a second time with the EMPTY buffer, which will bubble up to the
>>>> IoHandler, with the original message.
>>>>
>>>>
>>>> This is overly complex, and leads to spurious CPU being consumed. It
>>>> would be way smarter to encapsulate the original message in a
>>>> WriteRequest instance, go though the filters with that, up to the
>>>> encoder filter to feed a IoBuffer into this WriteRequest, which will
>>>> be written to the remote peer, and when done, a messageSent event
>>>> will be generated using the original message. If th eoriginal message
>>>> is a IoBuffer that does not require encoding, then it's enough to
>>>> keep the encoded message to null, up to the HeadFilter to find out
>>>> that the original was never transformed so that it can write it, and
>>>> let the IoProcessor generate a messageSent event after having flipped
>>>> the original message to rest it back to its original position and
>>>> limit. No reset, no mark, just a flip.
>>>>
>>>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
All tests are now passing green with my last commit in the write request
branch.
Feel free to have a look at it.
On 25/03/2019 19:12, Emmanuel Lécharny wrote:
> Ok, I know what's the cause of this failure.
>
> What happens when we process the handshake is that the SslFilter
> exchange some messages with the remote peer. Those messages have no
> reason to be transmitted to the application though the messageSent
> event, so teh SslFilter must swallow this event during the HS
> negotiation.
>
> The problem is when the last HS message is written, the SslEngine is
> now in a state where it wan absorb encrypted messages, which must be
> sent back to the application through the messagSent event. The
> difficulty is that the last SSL HS message currently goes through the
> messageSent's SslFilter handler, and pop up to the application instead
> of being swallowed.
>
> Previously, we were encapsulating such messages in a WriteRequest
> inherited class, and I removed this (useless) class. Obviously, I need
> a flag to 'mark' the HS messages and block them in the messageSent
> SSLMFilter handler.
>
>
> Working on that atm.
>
> On 25/03/2019 07:48, Emmanuel Lécharny wrote:
>> And here are the SSL debug traces :
>>
>>
>> ...
>>
>> 0update handshake state: change_cipher_spec
>> 0upcoming handshake states: server finished[20]
>> 10: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
>> 0020: EC D3 BF 1A 5B 4C 57 87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
>> 0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D ..t.....y.....9.
>> 0040: 5E 1A 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ^...............
>> NioProcessor-2, WRITE: TLSv1.2 Alert, length = 80
>> [Raw write]: length = 85
>> 0000: 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B ....P....s..f...
>> 0010: 2A 15 9C 5D E2 22 C6 8E 6C E6 98 F9 56 AA 3B 4D *..]."..l...V.;M
>> 0020: 7A 86 41 19 1A E1 05 E6 82 FD 27 21 2E 1A AD 63 z.A.......'!...c
>> 0030: 08 C6 DF B7 B9 BC 13 72 AE E7 CE 66 EC A4 7A F9 .......r...f..z.
>> 0040: 5C 9B F7 AA 84 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 \..........D....
>> 0050: FF 32 D1 46 DA .2.F.
>> [Raw read]: length = 5
>> 0000: 15 03 03 00 50 ....P
>> [Raw read]: length = 80
>> 0000: 95 AF BB C6 73 1A CB 66 9B 80 8B 2A 15 9C 5D E2 ....s..f...*..].
>> 0010: 22 C6 8E 6C E6 98 F9 56 AA 3B 4D 7A 86 41 19 1A "..l...V.;Mz.A..
>> 0020: E1 05 E6 82 FD 27 21 2E 1A AD 63 08 C6 DF B7 B9 .....'!...c.....
>> 0030: BC 13 72 AE E7 CE 66 EC A4 7A F9 5C 9B F7 AA 84 ..r...f..z.\....
>> 0040: 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 FF 32 D1 46 DA ......D.....2.F.
>> main, READ: TLSv1.2 Alert, length = 80
>> Padded plaintext after DECRYPTION: len = 80
>> 0000: 6F 87 2A C3 50 2C C5 61 70 CE F7 D3 5F E8 DC 9B o.*.P,.ap..._...
>> 0010: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
>> 0020: EC D3 BF 1A 5B 4C 57 NioProcessor-2, called closeInbound()
>> 87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
>> NioProcessor-2, fatal error: 80: Inbound closed before receiving
>> peer's close_notify: possible truncation attack?
>> javax.net.ssl.SSLException: Inbound closed before receiving peer's
>> close_notify: possible truncation attack?
>> %% Invalidated: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
>> 0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D
>> ..t.....NioProcessor-2, SEND TLSv1.2 ALERT: fatal, description =
>> internal_error
>> y.NioProcessor-2, Exception sending alert: java.io.IOException:
>> writer side was already closed.
>> ....9.
>> 0040: 5E 1A 0D 0D 0D 0NioProcessor-2, called closeOutbound()
>> D 0D 0D 0DNioProcessor-2, closeOutboundInternal()
>> 0D 0D 0D 0D 0D 0D 0D ^...............
>> %% Invalidated: [Session-2, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
>> main, SEND TLSv1.2 ALERT: fatal, description = bad_record_mac
>> Padded plaintext before ENCRYPTION: len = 80
>> 0000: 6B 84 AC 13 A7 85 B0 16 18 B0 08 3B 37 F2 AE 0A k..........;7...
>> 0010: 02 14 59 5D 17 A2 0A 96 09 F6 58 18 EA CC 04 3E ..Y]......X....>
>> 0020: F2 68 34 FE 03 F5 0A 9A 93 52 AF 38 83 B6 13 80 .h4......R.8....
>> 0030: D5 14 2E E6 E4 C9 FC B9 DC 35 9A A1 FF 33 69 FD .........5...3i.
>> 0040: 86 07 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ................
>> main, WRITE: TLSv1.2 Alert, length = 80
>> [Raw write]: length = 85
>> 0000: 15 03 03 00 50 2A C2 E4 D1 E6 D6 71 FC 61 D5 44 ....P*.....q.a.D
>> 0010: C8 72 9A AB 2A 56 51 70 7B C4 8F BA C8 79 EF D8 .r..*VQp.....y..
>> 0020: E7 F3 DF 58 E0 53 CD C2 80 ED 8C 8D 1F DB 28 13 ...X.S........(.
>> 0030: 91 1D 24 7E B5 29 A3 61 41 F9 9C 46 AD 58 FD BD ..$..).aA..F.X..
>> 0040: D5 59 C9 0F 93 AA 9E C7 9D A4 3D 39 75 A1 28 08 .Y........=9u.(.
>> 0050: 07 FE B9 6B F0 ...k.
>> main, called closeSocket()
>> main, handling exception: javax.net.ssl.SSLException: bad record MAC
>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Ok, I know what's the cause of this failure.
What happens when we process the handshake is that the SslFilter
exchange some messages with the remote peer. Those messages have no
reason to be transmitted to the application though the messageSent
event, so teh SslFilter must swallow this event during the HS negotiation.
The problem is when the last HS message is written, the SslEngine is now
in a state where it wan absorb encrypted messages, which must be sent
back to the application through the messagSent event. The difficulty is
that the last SSL HS message currently goes through the messageSent's
SslFilter handler, and pop up to the application instead of being swallowed.
Previously, we were encapsulating such messages in a WriteRequest
inherited class, and I removed this (useless) class. Obviously, I need a
flag to 'mark' the HS messages and block them in the messageSent
SSLMFilter handler.
Working on that atm.
On 25/03/2019 07:48, Emmanuel Lécharny wrote:
> And here are the SSL debug traces :
>
>
> ...
>
> 0update handshake state: change_cipher_spec
> 0upcoming handshake states: server finished[20]
> 10: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
> 0020: EC D3 BF 1A 5B 4C 57 87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
> 0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D ..t.....y.....9.
> 0040: 5E 1A 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ^...............
> NioProcessor-2, WRITE: TLSv1.2 Alert, length = 80
> [Raw write]: length = 85
> 0000: 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B ....P....s..f...
> 0010: 2A 15 9C 5D E2 22 C6 8E 6C E6 98 F9 56 AA 3B 4D *..]."..l...V.;M
> 0020: 7A 86 41 19 1A E1 05 E6 82 FD 27 21 2E 1A AD 63 z.A.......'!...c
> 0030: 08 C6 DF B7 B9 BC 13 72 AE E7 CE 66 EC A4 7A F9 .......r...f..z.
> 0040: 5C 9B F7 AA 84 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 \..........D....
> 0050: FF 32 D1 46 DA .2.F.
> [Raw read]: length = 5
> 0000: 15 03 03 00 50 ....P
> [Raw read]: length = 80
> 0000: 95 AF BB C6 73 1A CB 66 9B 80 8B 2A 15 9C 5D E2 ....s..f...*..].
> 0010: 22 C6 8E 6C E6 98 F9 56 AA 3B 4D 7A 86 41 19 1A "..l...V.;Mz.A..
> 0020: E1 05 E6 82 FD 27 21 2E 1A AD 63 08 C6 DF B7 B9 .....'!...c.....
> 0030: BC 13 72 AE E7 CE 66 EC A4 7A F9 5C 9B F7 AA 84 ..r...f..z.\....
> 0040: 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 FF 32 D1 46 DA ......D.....2.F.
> main, READ: TLSv1.2 Alert, length = 80
> Padded plaintext after DECRYPTION: len = 80
> 0000: 6F 87 2A C3 50 2C C5 61 70 CE F7 D3 5F E8 DC 9B o.*.P,.ap..._...
> 0010: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
> 0020: EC D3 BF 1A 5B 4C 57 NioProcessor-2, called closeInbound()
> 87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
> NioProcessor-2, fatal error: 80: Inbound closed before receiving
> peer's close_notify: possible truncation attack?
> javax.net.ssl.SSLException: Inbound closed before receiving peer's
> close_notify: possible truncation attack?
> %% Invalidated: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
> 0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D
> ..t.....NioProcessor-2, SEND TLSv1.2 ALERT: fatal, description =
> internal_error
> y.NioProcessor-2, Exception sending alert: java.io.IOException: writer
> side was already closed.
> ....9.
> 0040: 5E 1A 0D 0D 0D 0NioProcessor-2, called closeOutbound()
> D 0D 0D 0DNioProcessor-2, closeOutboundInternal()
> 0D 0D 0D 0D 0D 0D 0D ^...............
> %% Invalidated: [Session-2, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
> main, SEND TLSv1.2 ALERT: fatal, description = bad_record_mac
> Padded plaintext before ENCRYPTION: len = 80
> 0000: 6B 84 AC 13 A7 85 B0 16 18 B0 08 3B 37 F2 AE 0A k..........;7...
> 0010: 02 14 59 5D 17 A2 0A 96 09 F6 58 18 EA CC 04 3E ..Y]......X....>
> 0020: F2 68 34 FE 03 F5 0A 9A 93 52 AF 38 83 B6 13 80 .h4......R.8....
> 0030: D5 14 2E E6 E4 C9 FC B9 DC 35 9A A1 FF 33 69 FD .........5...3i.
> 0040: 86 07 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ................
> main, WRITE: TLSv1.2 Alert, length = 80
> [Raw write]: length = 85
> 0000: 15 03 03 00 50 2A C2 E4 D1 E6 D6 71 FC 61 D5 44 ....P*.....q.a.D
> 0010: C8 72 9A AB 2A 56 51 70 7B C4 8F BA C8 79 EF D8 .r..*VQp.....y..
> 0020: E7 F3 DF 58 E0 53 CD C2 80 ED 8C 8D 1F DB 28 13 ...X.S........(.
> 0030: 91 1D 24 7E B5 29 A3 61 41 F9 9C 46 AD 58 FD BD ..$..).aA..F.X..
> 0040: D5 59 C9 0F 93 AA 9E C7 9D A4 3D 39 75 A1 28 08 .Y........=9u.(.
> 0050: 07 FE B9 6B F0 ...k.
> main, called closeSocket()
> main, handling exception: javax.net.ssl.SSLException: bad record MAC
>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
And here are the SSL debug traces :
...
0update handshake state: change_cipher_spec
0upcoming handshake states: server finished[20]
10: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
0020: EC D3 BF 1A 5B 4C 57 87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D ..t.....y.....9.
0040: 5E 1A 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ^...............
NioProcessor-2, WRITE: TLSv1.2 Alert, length = 80
[Raw write]: length = 85
0000: 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B ....P....s..f...
0010: 2A 15 9C 5D E2 22 C6 8E 6C E6 98 F9 56 AA 3B 4D *..]."..l...V.;M
0020: 7A 86 41 19 1A E1 05 E6 82 FD 27 21 2E 1A AD 63 z.A.......'!...c
0030: 08 C6 DF B7 B9 BC 13 72 AE E7 CE 66 EC A4 7A F9 .......r...f..z.
0040: 5C 9B F7 AA 84 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 \..........D....
0050: FF 32 D1 46 DA .2.F.
[Raw read]: length = 5
0000: 15 03 03 00 50 ....P
[Raw read]: length = 80
0000: 95 AF BB C6 73 1A CB 66 9B 80 8B 2A 15 9C 5D E2 ....s..f...*..].
0010: 22 C6 8E 6C E6 98 F9 56 AA 3B 4D 7A 86 41 19 1A "..l...V.;Mz.A..
0020: E1 05 E6 82 FD 27 21 2E 1A AD 63 08 C6 DF B7 B9 .....'!...c.....
0030: BC 13 72 AE E7 CE 66 EC A4 7A F9 5C 9B F7 AA 84 ..r...f..z.\....
0040: 95 03 E3 E3 A1 E3 44 E5 CD 9B 11 FF 32 D1 46 DA ......D.....2.F.
main, READ: TLSv1.2 Alert, length = 80
Padded plaintext after DECRYPTION: len = 80
0000: 6F 87 2A C3 50 2C C5 61 70 CE F7 D3 5F E8 DC 9B o.*.P,.ap..._...
0010: 01 00 D5 D2 05 1B C0 51 13 A6 40 EC 80 9F 2A 4C .......Q..@...*L
0020: EC D3 BF 1A 5B 4C 57 NioProcessor-2, called closeInbound()
87 E3 D9 0B 35 2F 32 20 64 ....[LW....5/2 d
NioProcessor-2, fatal error: 80: Inbound closed before receiving peer's
close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's
close_notify: possible truncation attack?
%% Invalidated: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
0030: DE 93 74 81 EA 08 9E C1 79 B2 7C 9D C8 E5 39 0D
..t.....NioProcessor-2, SEND TLSv1.2 ALERT: fatal, description =
internal_error
y.NioProcessor-2, Exception sending alert: java.io.IOException: writer
side was already closed.
....9.
0040: 5E 1A 0D 0D 0D 0NioProcessor-2, called closeOutbound()
D 0D 0D 0DNioProcessor-2, closeOutboundInternal()
0D 0D 0D 0D 0D 0D 0D ^...............
%% Invalidated: [Session-2, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
main, SEND TLSv1.2 ALERT: fatal, description = bad_record_mac
Padded plaintext before ENCRYPTION: len = 80
0000: 6B 84 AC 13 A7 85 B0 16 18 B0 08 3B 37 F2 AE 0A k..........;7...
0010: 02 14 59 5D 17 A2 0A 96 09 F6 58 18 EA CC 04 3E ..Y]......X....>
0020: F2 68 34 FE 03 F5 0A 9A 93 52 AF 38 83 B6 13 80 .h4......R.8....
0030: D5 14 2E E6 E4 C9 FC B9 DC 35 9A A1 FF 33 69 FD .........5...3i.
0040: 86 07 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D ................
main, WRITE: TLSv1.2 Alert, length = 80
[Raw write]: length = 85
0000: 15 03 03 00 50 2A C2 E4 D1 E6 D6 71 FC 61 D5 44 ....P*.....q.a.D
0010: C8 72 9A AB 2A 56 51 70 7B C4 8F BA C8 79 EF D8 .r..*VQp.....y..
0020: E7 F3 DF 58 E0 53 CD C2 80 ED 8C 8D 1F DB 28 13 ...X.S........(.
0030: 91 1D 24 7E B5 29 A3 61 41 F9 9C 46 AD 58 FD BD ..$..).aA..F.X..
0040: D5 59 C9 0F 93 AA 9E C7 9D A4 3D 39 75 A1 28 08 .Y........=9u.(.
0050: 07 FE B9 6B F0 ...k.
main, called closeSocket()
main, handling exception: javax.net.ssl.SSLException: bad record MAC
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@emoten.com>.
I’m going to look at this starting Tuesday. Emmanuel do you mind creating
a branch for this Jira issue so I can track what you’re working on?
On Sun, Mar 24, 2019 at 3:54 AM Emmanuel Lécharny <el...@gmail.com>
wrote:
> Things are complicated :/
>
> Ok, after two days of investigation, my take is that the original sin
> was to use a IoBuffer to propagate a message across the filters.
> IoBuffers can be consumed (ie, when you read them, their position
> change) making it very complex not to abuse them when writing a filter.
>
> Typical problem arose in SslFilter, ProtocolCodecFilter, LoggingFilter,
> CompressionFilter (and probably some more). Lets see what happens for
> those filters.
>
> LoggingFilter: actually, nothing is logged for filterWrite ! That kind
> of 'fix' the issue, by ignoring it. OTOH, it's not consistent: we may
> want to know what is being written...
>
> SslFilter: it's pretty obvious that the incoming filter will be fully
> consumed, and a new buffer will be produced. The interesting thing is
> that the SslEngine use ByteBuffer to encrypt/decrypt data. Anyway, we
> consume the incoming buffer, no matter what, and it's a side effect.
>
> ProtocolCodecFilter: it also consume the incoming message, which can be
> any kind of data structure. It doesn't matter because the factory is
> application specific (or it's one of the on the shelf factories). The
> special case is when the incoming message is an IoBuffer (not really
> frequently the case...)
>
> CompressionFilter: it takes a IoBuffer as input and produce a new one,
> having consumed the incoming IoBuffer.
>
> etc, etc.
>
> So when we have fully written the message, any IoBuffer than have been
> created in the filters - or any IoBBuffer that was passed by the
> application - would have been consumed. If we want to propagate a
> messageSent event, we need to have kept a track of the original message,
> and if it was a IoBuffer, that would mean duplicating it, or flip it
> before calling messageSent() just after having written it fully...
>
> Now, why are we using IoBuffer at all ? For three reasons:
>
> - ByteBuffer are immutable. It's valuable to be able to 'grow' a
> IoBuffer, typically when we inflate a message
>
> - SslEngine is using ByteBuffer, IoBuffer encapsulate one
>
> - Ultimately, writing into a channel is done using a ByteBuffer, so not
> having to create one when calling write on a channel saves some copy.
> But this is really when we have an app that has no filter modifying the
> IoBuffer. A rare corner case.
>
> So my take is that using an IoBuffer is a premature optimization. Just
> because channels require ByteBuffer does not lmean we shiould use
> ByteBuffer acorss the filters, except for the SslBuffer - which should
> always be the first filter in the chain anyway. We should also always
> keep a track of the original message, unmodified, so that the
> messageSent eveent can be propagated properly. Obviously, if the
> original message is an IoBuffer, and is never modified by any filteer,
> duplicating it before sending it just because we want to keep it intact
> for the messageSent event is a waste, but OTOH, it's very unlikely to be
> a frequent use case...
>
> I'm currently working on implementing that, and so far, it's going well.
>
>
> I'll keep the list informed.
>
> On 22/03/2019 13:35, Emmanuel Lécharny wrote:
> > Ok, I have a version that works better with the CompressionFilter.
> >
> >
> > Here is what I have changed :
> >
> > - the session.write( <message> ) method will inject the original
> > message into the WriteRequest
> >
> > - any filterWrite filter that is going to create a new version of the
> > message will store it in the same writeRequest, into a modifiedMessage
> > field. (The WriteRequest impl thus holds 2 versions of the message,
> > the odiginal one and the modified one)
> >
> > - when the modified message is written to the remote peer (it's now an
> > IoBuffer), messageSent will be called with the original message, or
> > with the written IoBuffer flipped if the original message was a
> > IoBuffer and was never modified.
> >
> > The first test I did with the chat example seems to work pretty well.
> > It's going through a TextLineCodecFactory codec filter, a
> > CompressionFilter. I have to test it with the LoginFilter and the
> > SslFilter.
> >
> >
> > All in all, the MINA code is much simpler and should be faster too, as
> > we spare spurious calls to messageSent and filterWrite with an Empty
> > message.
> >
> >
> > More to come soon.
> >
> > On 22/03/2019 04:58, Emmanuel Lécharny wrote:
> >> Hmmpphhhh....
> >>
> >> I have traced the calls when a session.write( <blah> ) is done.
> >>
> >>
> >> It's all a kind of a hack.
> >>
> >>
> >> In order to be able to send the messageSent() event, the
> >> protocolFilter will call the nextFilter.filterWrite() method twice :
> >>
> >> public void filterWrite(NextFilter nextFilter, IoSession session,
> >> WriteRequest writeRequest) throws Exception {
> >> Object message = writeRequest.getMessage();
> >>
> >> ...
> >> // Write all the encoded messages now
> >> while (!bufferQueue.isEmpty()) {
> >> Object encodedMessage = bufferQueue.poll();
> >>
> >> // Flush only when the buffer has remaining.
> >> if (!(encodedMessage instanceof IoBuffer) ||
> >> ((IoBuffer) encodedMessage).hasRemaining()) {
> >> SocketAddress destination =
> >> writeRequest.getDestination();
> >> WriteRequest encodedWriteRequest = new
> >> EncodedWriteRequest(encodedMessage, null, destination);
> >>
> >> nextFilter.filterWrite(session,
> >> encodedWriteRequest);
> >> }
> >> }
> >>
> >> // Call the next filter
> >> nextFilter.filterWrite(session, new
> >> MessageWriteRequest(writeRequest));
> >>
> >> The first call we go down the chain with an IoBuffer containing the
> >> encoded message, the second call will use th e original message
> >> wrapped in a specific MessageWriteRequest instance, which will always
> >> return an empty IoBuffer when a getMessage() is called on it :
> >>
> >> private static class MessageWriteRequest extends
> >> WriteRequestWrapper {
> >> @Override
> >> public Object getMessage() {
> >> return EMPTY_BUFFER;
> >> }
> >>
> >> It goes down the chain to the HeadFilter where it gets stacked to be
> >> written. But as it's an empty buffer, the flush() method will do
> >> nothing but initiate a call to messageSent() which will pop up to the
> >> handler. Actually, the messageSent() event will be issued twice, once
> >> with the encoded message, and it will be swallowed silently by the
> >> ProtocolCodecFilter :
> >>
> >> public void messageSent(NextFilter nextFilter, IoSession session,
> >> WriteRequest writeRequest) throws Exception {
> >> if (writeRequest instanceof EncodedWriteRequest) {
> >> return;
> >>
> >> and a second time with the EMPTY buffer, which will bubble up to the
> >> IoHandler, with the original message.
> >>
> >>
> >> This is overly complex, and leads to spurious CPU being consumed. It
> >> would be way smarter to encapsulate the original message in a
> >> WriteRequest instance, go though the filters with that, up to the
> >> encoder filter to feed a IoBuffer into this WriteRequest, which will
> >> be written to the remote peer, and when done, a messageSent event
> >> will be generated using the original message. If th eoriginal message
> >> is a IoBuffer that does not require encoding, then it's enough to
> >> keep the encoded message to null, up to the HeadFilter to find out
> >> that the original was never transformed so that it can write it, and
> >> let the IoProcessor generate a messageSent event after having flipped
> >> the original message to rest it back to its original position and
> >> limit. No reset, no mark, just a flip.
> >>
> >>
>
--
CONFIDENTIALITY NOTICE: The contents of this email message and any
attachments are intended solely for the addressee(s) and may contain
confidential and/or privileged information and may be legally protected
from disclosure.
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Things are complicated :/
Ok, after two days of investigation, my take is that the original sin
was to use a IoBuffer to propagate a message across the filters.
IoBuffers can be consumed (ie, when you read them, their position
change) making it very complex not to abuse them when writing a filter.
Typical problem arose in SslFilter, ProtocolCodecFilter, LoggingFilter,
CompressionFilter (and probably some more). Lets see what happens for
those filters.
LoggingFilter: actually, nothing is logged for filterWrite ! That kind
of 'fix' the issue, by ignoring it. OTOH, it's not consistent: we may
want to know what is being written...
SslFilter: it's pretty obvious that the incoming filter will be fully
consumed, and a new buffer will be produced. The interesting thing is
that the SslEngine use ByteBuffer to encrypt/decrypt data. Anyway, we
consume the incoming buffer, no matter what, and it's a side effect.
ProtocolCodecFilter: it also consume the incoming message, which can be
any kind of data structure. It doesn't matter because the factory is
application specific (or it's one of the on the shelf factories). The
special case is when the incoming message is an IoBuffer (not really
frequently the case...)
CompressionFilter: it takes a IoBuffer as input and produce a new one,
having consumed the incoming IoBuffer.
etc, etc.
So when we have fully written the message, any IoBuffer than have been
created in the filters - or any IoBBuffer that was passed by the
application - would have been consumed. If we want to propagate a
messageSent event, we need to have kept a track of the original message,
and if it was a IoBuffer, that would mean duplicating it, or flip it
before calling messageSent() just after having written it fully...
Now, why are we using IoBuffer at all ? For three reasons:
- ByteBuffer are immutable. It's valuable to be able to 'grow' a
IoBuffer, typically when we inflate a message
- SslEngine is using ByteBuffer, IoBuffer encapsulate one
- Ultimately, writing into a channel is done using a ByteBuffer, so not
having to create one when calling write on a channel saves some copy.
But this is really when we have an app that has no filter modifying the
IoBuffer. A rare corner case.
So my take is that using an IoBuffer is a premature optimization. Just
because channels require ByteBuffer does not lmean we shiould use
ByteBuffer acorss the filters, except for the SslBuffer - which should
always be the first filter in the chain anyway. We should also always
keep a track of the original message, unmodified, so that the
messageSent eveent can be propagated properly. Obviously, if the
original message is an IoBuffer, and is never modified by any filteer,
duplicating it before sending it just because we want to keep it intact
for the messageSent event is a waste, but OTOH, it's very unlikely to be
a frequent use case...
I'm currently working on implementing that, and so far, it's going well.
I'll keep the list informed.
On 22/03/2019 13:35, Emmanuel Lécharny wrote:
> Ok, I have a version that works better with the CompressionFilter.
>
>
> Here is what I have changed :
>
> - the session.write( <message> ) method will inject the original
> message into the WriteRequest
>
> - any filterWrite filter that is going to create a new version of the
> message will store it in the same writeRequest, into a modifiedMessage
> field. (The WriteRequest impl thus holds 2 versions of the message,
> the odiginal one and the modified one)
>
> - when the modified message is written to the remote peer (it's now an
> IoBuffer), messageSent will be called with the original message, or
> with the written IoBuffer flipped if the original message was a
> IoBuffer and was never modified.
>
> The first test I did with the chat example seems to work pretty well.
> It's going through a TextLineCodecFactory codec filter, a
> CompressionFilter. I have to test it with the LoginFilter and the
> SslFilter.
>
>
> All in all, the MINA code is much simpler and should be faster too, as
> we spare spurious calls to messageSent and filterWrite with an Empty
> message.
>
>
> More to come soon.
>
> On 22/03/2019 04:58, Emmanuel Lécharny wrote:
>> Hmmpphhhh....
>>
>> I have traced the calls when a session.write( <blah> ) is done.
>>
>>
>> It's all a kind of a hack.
>>
>>
>> In order to be able to send the messageSent() event, the
>> protocolFilter will call the nextFilter.filterWrite() method twice :
>>
>> public void filterWrite(NextFilter nextFilter, IoSession session,
>> WriteRequest writeRequest) throws Exception {
>> Object message = writeRequest.getMessage();
>>
>> ...
>> // Write all the encoded messages now
>> while (!bufferQueue.isEmpty()) {
>> Object encodedMessage = bufferQueue.poll();
>>
>> // Flush only when the buffer has remaining.
>> if (!(encodedMessage instanceof IoBuffer) ||
>> ((IoBuffer) encodedMessage).hasRemaining()) {
>> SocketAddress destination =
>> writeRequest.getDestination();
>> WriteRequest encodedWriteRequest = new
>> EncodedWriteRequest(encodedMessage, null, destination);
>>
>> nextFilter.filterWrite(session,
>> encodedWriteRequest);
>> }
>> }
>>
>> // Call the next filter
>> nextFilter.filterWrite(session, new
>> MessageWriteRequest(writeRequest));
>>
>> The first call we go down the chain with an IoBuffer containing the
>> encoded message, the second call will use th e original message
>> wrapped in a specific MessageWriteRequest instance, which will always
>> return an empty IoBuffer when a getMessage() is called on it :
>>
>> private static class MessageWriteRequest extends
>> WriteRequestWrapper {
>> @Override
>> public Object getMessage() {
>> return EMPTY_BUFFER;
>> }
>>
>> It goes down the chain to the HeadFilter where it gets stacked to be
>> written. But as it's an empty buffer, the flush() method will do
>> nothing but initiate a call to messageSent() which will pop up to the
>> handler. Actually, the messageSent() event will be issued twice, once
>> with the encoded message, and it will be swallowed silently by the
>> ProtocolCodecFilter :
>>
>> public void messageSent(NextFilter nextFilter, IoSession session,
>> WriteRequest writeRequest) throws Exception {
>> if (writeRequest instanceof EncodedWriteRequest) {
>> return;
>>
>> and a second time with the EMPTY buffer, which will bubble up to the
>> IoHandler, with the original message.
>>
>>
>> This is overly complex, and leads to spurious CPU being consumed. It
>> would be way smarter to encapsulate the original message in a
>> WriteRequest instance, go though the filters with that, up to the
>> encoder filter to feed a IoBuffer into this WriteRequest, which will
>> be written to the remote peer, and when done, a messageSent event
>> will be generated using the original message. If th eoriginal message
>> is a IoBuffer that does not require encoding, then it's enough to
>> keep the encoded message to null, up to the HeadFilter to find out
>> that the original was never transformed so that it can write it, and
>> let the IoProcessor generate a messageSent event after having flipped
>> the original message to rest it back to its original position and
>> limit. No reset, no mark, just a flip.
>>
>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Ok, I have a version that works better with the CompressionFilter.
Here is what I have changed :
- the session.write( <message> ) method will inject the original message
into the WriteRequest
- any filterWrite filter that is going to create a new version of the
message will store it in the same writeRequest, into a modifiedMessage
field. (The WriteRequest impl thus holds 2 versions of the message, the
odiginal one and the modified one)
- when the modified message is written to the remote peer (it's now an
IoBuffer), messageSent will be called with the original message, or with
the written IoBuffer flipped if the original message was a IoBuffer and
was never modified.
The first test I did with the chat example seems to work pretty well.
It's going through a TextLineCodecFactory codec filter, a
CompressionFilter. I have to test it with the LoginFilter and the SslFilter.
All in all, the MINA code is much simpler and should be faster too, as
we spare spurious calls to messageSent and filterWrite with an Empty
message.
More to come soon.
On 22/03/2019 04:58, Emmanuel Lécharny wrote:
> Hmmpphhhh....
>
> I have traced the calls when a session.write( <blah> ) is done.
>
>
> It's all a kind of a hack.
>
>
> In order to be able to send the messageSent() event, the
> protocolFilter will call the nextFilter.filterWrite() method twice :
>
> public void filterWrite(NextFilter nextFilter, IoSession session,
> WriteRequest writeRequest) throws Exception {
> Object message = writeRequest.getMessage();
>
> ...
> // Write all the encoded messages now
> while (!bufferQueue.isEmpty()) {
> Object encodedMessage = bufferQueue.poll();
>
> // Flush only when the buffer has remaining.
> if (!(encodedMessage instanceof IoBuffer) ||
> ((IoBuffer) encodedMessage).hasRemaining()) {
> SocketAddress destination =
> writeRequest.getDestination();
> WriteRequest encodedWriteRequest = new
> EncodedWriteRequest(encodedMessage, null, destination);
>
> nextFilter.filterWrite(session, encodedWriteRequest);
> }
> }
>
> // Call the next filter
> nextFilter.filterWrite(session, new
> MessageWriteRequest(writeRequest));
>
> The first call we go down the chain with an IoBuffer containing the
> encoded message, the second call will use th e original message
> wrapped in a specific MessageWriteRequest instance, which will always
> return an empty IoBuffer when a getMessage() is called on it :
>
> private static class MessageWriteRequest extends
> WriteRequestWrapper {
> @Override
> public Object getMessage() {
> return EMPTY_BUFFER;
> }
>
> It goes down the chain to the HeadFilter where it gets stacked to be
> written. But as it's an empty buffer, the flush() method will do
> nothing but initiate a call to messageSent() which will pop up to the
> handler. Actually, the messageSent() event will be issued twice, once
> with the encoded message, and it will be swallowed silently by the
> ProtocolCodecFilter :
>
> public void messageSent(NextFilter nextFilter, IoSession session,
> WriteRequest writeRequest) throws Exception {
> if (writeRequest instanceof EncodedWriteRequest) {
> return;
>
> and a second time with the EMPTY buffer, which will bubble up to the
> IoHandler, with the original message.
>
>
> This is overly complex, and leads to spurious CPU being consumed. It
> would be way smarter to encapsulate the original message in a
> WriteRequest instance, go though the filters with that, up to the
> encoder filter to feed a IoBuffer into this WriteRequest, which will
> be written to the remote peer, and when done, a messageSent event will
> be generated using the original message. If th eoriginal message is a
> IoBuffer that does not require encoding, then it's enough to keep the
> encoded message to null, up to the HeadFilter to find out that the
> original was never transformed so that it can write it, and let the
> IoProcessor generate a messageSent event after having flipped the
> original message to rest it back to its original position and limit.
> No reset, no mark, just a flip.
>
>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Hmmpphhhh....
I have traced the calls when a session.write( <blah> ) is done.
It's all a kind of a hack.
In order to be able to send the messageSent() event, the protocolFilter
will call the nextFilter.filterWrite() method twice :
public void filterWrite(NextFilter nextFilter, IoSession session,
WriteRequest writeRequest) throws Exception {
Object message = writeRequest.getMessage();
...
// Write all the encoded messages now
while (!bufferQueue.isEmpty()) {
Object encodedMessage = bufferQueue.poll();
// Flush only when the buffer has remaining.
if (!(encodedMessage instanceof IoBuffer) ||
((IoBuffer) encodedMessage).hasRemaining()) {
SocketAddress destination =
writeRequest.getDestination();
WriteRequest encodedWriteRequest = new
EncodedWriteRequest(encodedMessage, null, destination);
nextFilter.filterWrite(session, encodedWriteRequest);
}
}
// Call the next filter
nextFilter.filterWrite(session, new
MessageWriteRequest(writeRequest));
The first call we go down the chain with an IoBuffer containing the
encoded message, the second call will use th e original message wrapped
in a specific MessageWriteRequest instance, which will always return an
empty IoBuffer when a getMessage() is called on it :
private static class MessageWriteRequest extends WriteRequestWrapper {
@Override
public Object getMessage() {
return EMPTY_BUFFER;
}
It goes down the chain to the HeadFilter where it gets stacked to be
written. But as it's an empty buffer, the flush() method will do nothing
but initiate a call to messageSent() which will pop up to the handler.
Actually, the messageSent() event will be issued twice, once with the
encoded message, and it will be swallowed silently by the
ProtocolCodecFilter :
public void messageSent(NextFilter nextFilter, IoSession session,
WriteRequest writeRequest) throws Exception {
if (writeRequest instanceof EncodedWriteRequest) {
return;
and a second time with the EMPTY buffer, which will bubble up to the
IoHandler, with the original message.
This is overly complex, and leads to spurious CPU being consumed. It
would be way smarter to encapsulate the original message in a
WriteRequest instance, go though the filters with that, up to the
encoder filter to feed a IoBuffer into this WriteRequest, which will be
written to the remote peer, and when done, a messageSent event will be
generated using the original message. If th eoriginal message is a
IoBuffer that does not require encoding, then it's enough to keep the
encoded message to null, up to the HeadFilter to find out that the
original was never transformed so that it can write it, and let the
IoProcessor generate a messageSent event after having flipped the
original message to rest it back to its original position and limit. No
reset, no mark, just a flip.
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
On 20/03/2019 16:13, Jonathan Valliere wrote:
> I’ll look into not using mark reset there.
I agree that using mark and reset is a kind of a non sense. Let's go
back to the original requirement :
- when we call a session.write(message), we know the message will go
through multiple filters
- at some point, it will be loaded into a IoBuffer (if not injected as
is when the session.write method is called)
- this IoBuffer will be consumed when we write it to the remote peer
- eventually, we want the original message (whatever it was) to be sent
back to the IoHandler, for it to know that it was sent
This is the last requirement that is the root cause of the problem. It
requires that we keep the message as is to be sent back to the
IoHandler. When we call session.write(), we create a new instance of
DefaultWriteRequest() which hold the original message, and we except to
keep it unmodified until we get it back in the IoHandler.messageSent().
This is OK when the original message is not an IoBuufer (which is likely
to be the case), but when it's a IoBuffer, then we are in trouble...
In the current impl, the AbstractPollingIoProcessor.writeBuffer() method
is most certainly overdoing. We could assume that we don't need to reset
the IoBuffer before calling messageSent(), and expect the IoHandler who
called session.write( IoBuffer ) to *know* that the IoBuffer has been
consumed, up to it to reset the IoBuffer. That put back the burden of
dealing with IoBuffer consommation to the user, which frankly is not a
big deal, because you are not really supposed to pass a mutable message
to the session (most of the time, there will be some Protocol filter in
the chain that will transform the message anyway.
So here is my take :
- stop calling reset before calling messageSent
- fix the tests that may fail because of this change
Note that it may impact MINA users who expect the message to be reset,
when message is an IoBuffer, and when the IoHandler implements
messageSent().
Thoughts ?
>
> On Wed, Mar 20, 2019 at 11:05 AM Emmanuel Lécharny <el...@gmail.com>
> wrote:
>
>> On 20/03/2019 15:30, Jonathan Valliere wrote:
>>> The offending code is in AbstractPollingIoProcessor. Are you agreeing
>> that
>>> AbstractPollingIoProcessor has no place modifying the buffer positions?
>>> Removing buf.reset() would probably fix the problem.
>>
>> The reason we reset the buffer is that we need to send it back to the
>> IoHandler in the messageSent event, and to make it readable from its
>> starting point.
>>
>>
>> If the app is sending a message containg "hello world", this string will
>> be put into a IoBuffer, which will be read when the data will get sent
>> to the remote peer, and the position will then change. The messageSent
>> event will send this IoBuffer back to the IoHandler, which will then be
>> incapable of telling the app the message "hello world" has been sent,
>> because the buffer has been exhausted by the peer write...
>>
>>
>> This is the reason why we reset the buffer *after* it has been fully sent.
>>
>>
>>
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@apache.org>.
I’ll look into not using mark reset there.
On Wed, Mar 20, 2019 at 11:05 AM Emmanuel Lécharny <el...@gmail.com>
wrote:
>
> On 20/03/2019 15:30, Jonathan Valliere wrote:
> > The offending code is in AbstractPollingIoProcessor. Are you agreeing
> that
> > AbstractPollingIoProcessor has no place modifying the buffer positions?
> > Removing buf.reset() would probably fix the problem.
>
>
> The reason we reset the buffer is that we need to send it back to the
> IoHandler in the messageSent event, and to make it readable from its
> starting point.
>
>
> If the app is sending a message containg "hello world", this string will
> be put into a IoBuffer, which will be read when the data will get sent
> to the remote peer, and the position will then change. The messageSent
> event will send this IoBuffer back to the IoHandler, which will then be
> incapable of telling the app the message "hello world" has been sent,
> because the buffer has been exhausted by the peer write...
>
>
> This is the reason why we reset the buffer *after* it has been fully sent.
>
>
>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
On 20/03/2019 15:30, Jonathan Valliere wrote:
> The offending code is in AbstractPollingIoProcessor. Are you agreeing that
> AbstractPollingIoProcessor has no place modifying the buffer positions?
> Removing buf.reset() would probably fix the problem.
The reason we reset the buffer is that we need to send it back to the
IoHandler in the messageSent event, and to make it readable from its
starting point.
If the app is sending a message containg "hello world", this string will
be put into a IoBuffer, which will be read when the data will get sent
to the remote peer, and the position will then change. The messageSent
event will send this IoBuffer back to the IoHandler, which will then be
incapable of telling the app the message "hello world" has been sent,
because the buffer has been exhausted by the peer write...
This is the reason why we reset the buffer *after* it has been fully sent.
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@apache.org>.
The offending code is in AbstractPollingIoProcessor. Are you agreeing that
AbstractPollingIoProcessor has no place modifying the buffer positions?
Removing buf.reset() would probably fix the problem.
https://gitbox.apache.org/repos/asf?p=mina.git;a=commitdiff;h=44b58469f84ce991074cdc187b1c1f23b94cf445;hp=a42871a778c772b52267ef5a68d72cc043aaef54
On Wed, Mar 20, 2019 at 10:26 AM Emmanuel Lécharny <el...@gmail.com>
wrote:
> (replying to the mailing list)
>
> On 20/03/2019 15:11, Jonathan Valliere wrote:
> > And mina is calling reset() bad combo. Why would mina ever need to
> > modify the position? Just keep on writing the buffer as-is until
> flushed?
>
> It should. Any filter taking a IoBuffer as an input should *never*
> modify it. It could replace it, but not reset/flip/whatever.
>
> I suspect there is some attempt to avoid creating a new buffer at some
> point, for performance reasons. We shoudl review all the filters to
> check that they are not doing such a thing...
>
> >
> > On Wed, Mar 20, 2019 at 10:01 AM Emmanuel Lécharny
> > <elecharny@gmail.com <ma...@gmail.com>> wrote:
> >
> >
> > On 20/03/2019 14:02, Jonathan Valliere wrote:
> > > Nothing in Mina should use the mark/reset functionality because
> > it does not
> > > compound and the unknown addition of filters create edge cases
> > where it is
> > > compounded. Should manually grab he position and manually
> > revert the
> > > position when necessary.
> >
> >
> > The zlib class is flipping the buffer, that may be the cause of
> > this issue.
> >
> > public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
> > if (mode == MODE_INFLATER) {
> > throw new IllegalStateException("not initialized as
> > DEFLATER");
> > }
> >
> > byte[] inBytes = new byte[inBuffer.remaining()];
> > inBuffer.get(inBytes).flip();
> >
>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
(replying to the mailing list)
On 20/03/2019 15:11, Jonathan Valliere wrote:
> And mina is calling reset() bad combo. Why would mina ever need to
> modify the position? Just keep on writing the buffer as-is until flushed?
It should. Any filter taking a IoBuffer as an input should *never*
modify it. It could replace it, but not reset/flip/whatever.
I suspect there is some attempt to avoid creating a new buffer at some
point, for performance reasons. We shoudl review all the filters to
check that they are not doing such a thing...
>
> On Wed, Mar 20, 2019 at 10:01 AM Emmanuel Lécharny
> <elecharny@gmail.com <ma...@gmail.com>> wrote:
>
>
> On 20/03/2019 14:02, Jonathan Valliere wrote:
> > Nothing in Mina should use the mark/reset functionality because
> it does not
> > compound and the unknown addition of filters create edge cases
> where it is
> > compounded. Should manually grab he position and manually
> revert the
> > position when necessary.
>
>
> The zlib class is flipping the buffer, that may be the cause of
> this issue.
>
> public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
> if (mode == MODE_INFLATER) {
> throw new IllegalStateException("not initialized as
> DEFLATER");
> }
>
> byte[] inBytes = new byte[inBuffer.remaining()];
> inBuffer.get(inBytes).flip();
>
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@apache.org>.
Nothing in Mina should use the mark/reset functionality because it does not
compound and the unknown addition of filters create edge cases where it is
compounded. Should manually grab he position and manually revert the
position when necessary.
On Wed, Mar 20, 2019 at 4:23 AM Greg Thomas <gr...@gmail.com> wrote:
> Many thanks!
>
> Greg
>
> > On 20 Mar 2019, at 07:42, Emmanuel Lécharny <el...@gmail.com> wrote:
> >
> > I can reproduce the issue with a much simpler application (using the
> 'chat' example).
> >
> > I will try to get a fix asap.
> >
> >
> >> On 19/03/2019 23:33, Emmanuel Lécharny wrote:
> >> Ok, looking at the CompressionFilter, here is what I see:
> >>
> >>
> >> @Override
> >> protected Object doFilterWrite(NextFilter nextFilter, IoSession
> session, WriteRequest writeRequest)
> >> throws IOException {
> >> ...
> >> IoBuffer inBuffer = (IoBuffer) writeRequest.getMessage();
> >> if (!inBuffer.hasRemaining()) {
> >> // Ignore empty buffers
> >> return null;
> >> } else {
> >> return deflater.deflate(inBuffer);
> >> }
> >> }
> >>
> >>
> >> and
> >>
> >>
> >> public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
> >> if (mode == MODE_INFLATER) {
> >> throw new IllegalStateException("not initialized as
> DEFLATER");
> >> }
> >>
> >> byte[] inBytes = new byte[inBuffer.remaining()];
> >> inBuffer.get(inBytes).flip();
> >>
> >>
> >> and finally :
> >>
> >>
> >> public final IoBuffer flip() {
> >> buf().flip();
> >> mark = -1;
> >> return this;
> >> }
> >>
> >> mark is now -1, so setting a position on it will produce the error you
> get.
> >>
> >>
> >> Sounds like a bug to me...
> >>
> >>> On 19/03/2019 23:04, Emmanuel Lécharny wrote:
> >>> Hi Greg, Jonathan,
> >>>
> >>> it was 3 years ago, and I don't remember what was the root cause of
> this change. However, reading the diff, what I can tell is that the changed
> version assume that the original message (ie the message the app is
> writing) may not be a IoBuffer, and in this case, we needed to process it
> differently.
> >>>
> >>>
> >>> Let me clarify.
> >>>
> >>> When a message is written by an application, it can be anything ( a
> String, a data structure, some byte[], whatever), but it means something
> for the application. Then it goes through the filter chain, and it get
> encoded, encrypted, compressed, it all depends on the filters in use. When
> it hits the bottom of the chain, it's a IoBuffer that has to be written to
> the remote peer. When this IoBuffer has been fully written, we can send the
> MessageSend event back to the IoHandler, and we do so by using the
> 'original' message (ie the message before it get
> encoded/compressed/encrypted) to avoid having to decode/decrypt/decompress
> it again. It's like :
> >>>
> >>>
> >>> IoHandler write( <original message> ) -> [filter] --(origMsg,
> transformedMsg)--> [filter] --(origMsg, transformedMsg)--> ...--(origMsg,
> transformedMsg)--> [Head]-> write transformed data to socket
> >>>
> >>> when the data has been fully sent, we go back :
> >>>
> >>> [Head] --(origMsg)--> [filter] --> ... --(origMsg)--> IoHandler "The
> <origMsg> message has been fully sent"
> >>>
> >>> This original message is likely not to be contained in a IoBuffer, so
> we have to keep it as is. OTOH, if it was a IoBuffer, its position has
> changed while being processed in the filter chain, as ity has been read, so
> we need to reset its position to the very beginning.
> >>>
> >>>
> >>> Anyway, looking at the exception you get, here is what I suspect : the
> buffer has been flipped, or cleared, and the mark is now -1, which leads to
> the message you get when trying top do a reset on it.
> >>>
> >>>
> >>> Is there a way to see the code that get called when you get this error
> ?
> >>>
> >>>> On 19/03/2019 18:18, Greg Thomas wrote:
> >>>> Details from
> >>>>
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> >>>>
> >>>> Don't try to reset a message when it's not a IoBuffer
> >>>>
> >>>> Emmanuel Lécharny <el...@symas.com>
> >>>>
> >>>> Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
> >>>>
> >>>> Greg
> >>>>
> >>>> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere <
> jon.valliere@emoten.com>
> >>>> wrote:
> >>>>
> >>>>> I’m trying to look it up in gitbox and it doesn’t show the ids. What
> was
> >>>>> the date / first few words of commit message?
> >>>>>
> >>>>> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <greg.d.thomas@gmail.com
> >
> >>>>> wrote:
> >>>>>
> >>>>>> So just to clarify;
> >>>>>>
> >>>>>> If we run against 2.0.14, connections using the CompressionFilter
> fail.
> >>>>>>
> >>>>>> If I ...
> >>>>>>
> >>>>>> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
> >>>>>> $ cd mina
> >>>>>> $ git checkout 2.0.14
> >>>>>> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
> >>>>>> $ mvn clean package
> >>>>>>
> >>>>>> and use the JAR files from that, connections using the
> CompressionFilter
> >>>>>> succeed.
> >>>>>>
> >>>>>> So I'm pretty confident that commit
> >>>>>> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just
> don't
> >>>>>> understand the code well enough to be able to suggest why/how to
> fix it.
> >>>>>>
> >>>>>> Greg
> >>>>>>
> >>>>>>
> >>>>>> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <johnnyv@apache.org
> >
> >>>>>> wrote:
> >>>>>>
> >>>>>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
> >>>>> It’s
> >>>>>>> always possible that there is a concurrency problem with
> compression
> >>>>>> filter
> >>>>>>> which is now exposed through other changes... like what we have
> with
> >>>>> SSL.
> >>>>>>> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <
> greg.d.thomas@gmail.com>
> >>>>>>> wrote:
> >>>>>>>
> >>>>>>>> Openfire - an XMPP server,
> >>>>>>>> https://www.igniterealtime.org/projects/openfire/index.jsp -
> makes
> >>>>>> heavy
> >>>>>>>> use of Apache MINA for it's I/O.
> >>>>>>>>
> >>>>>>>> One of the things it uses is the CompressionFilter - if clients
> >>>>> enable
> >>>>>>> the
> >>>>>>>> Compression XMPP option.
> >>>>>>>>
> >>>>>>>> We've recently updated to a newer version of MINA, and with no
> other
> >>>>>> code
> >>>>>>>> changes found that enabling compression (in XMPP clients) fails.
> I've
> >>>>>>>> narrowed it down to changes between MINA 2.0.13 (where it works)
> and
> >>>>>>> 2.0.14
> >>>>>>>> through to 2.1.0 (where it doesn't) - with Openfire throwing the
> >>>>>>> following
> >>>>>>>> stack trace:
> >>>>>>>>
> >>>>>>>> java.nio.InvalidMarkException: null
> >>>>>>>> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
>
> >>>>>>>> ~[mina-core-2.0.14.jar:?]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>
> >>>>>>>> ~[?:1.8.0_162]
> >>>>>>>> at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>
> >>>>>>>> ~[?:1.8.0_162]
> >>>>>>>> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
> >>>>>>>>
> >>>>>>>> Narrowing down even further the commit at
> >>>>>>>>
> >>>>>>>>
> >>>>>
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> >>>>>>>> seems
> >>>>>>>> to be the culprit.
> >>>>>>>>
> >>>>>>>> At this point, I'm drawing a blank.
> >>>>>>>>
> >>>>>>>> It's possible Openfire is using the CompressionFilter wrongly,
> which
> >>>>>> was
> >>>>>>>> being masked until the above commit.
> >>>>>>>>
> >>>>>>>> It's possible the above commit doesn't do what was intended, but I
> >>>>>> don't
> >>>>>>>> pretend to understand what it is/should be doing.
> >>>>>>>>
> >>>>>>>> It's possible I've got the wrong end of the stick, and it's
> something
> >>>>>>> else
> >>>>>>>> between MINA 2.0.13 and 2.0.14 that changed that is causing the
> >>>>>> problem.
> >>>>>>>> But at this point, I don't know where to start, so would
> appreciate
> >>>>> any
> >>>>>>>> pointers!
> >>>>>>>>
> >>>>>>>> Thanks,
> >>>>>>>>
> >>>>>>>> Greg
> >>>>>>>>
> >>>>> --
> >>>>>
> >>>>> CONFIDENTIALITY NOTICE: The contents of this email message and any
> >>>>> attachments are intended solely for the addressee(s) and may contain
> >>>>> confidential and/or privileged information and may be legally
> protected
> >>>>> from disclosure.
> >>>>>
>
Re: Change in behaviour of CompressionFilter
Posted by Greg Thomas <gr...@gmail.com>.
Many thanks!
Greg
> On 20 Mar 2019, at 07:42, Emmanuel Lécharny <el...@gmail.com> wrote:
>
> I can reproduce the issue with a much simpler application (using the 'chat' example).
>
> I will try to get a fix asap.
>
>
>> On 19/03/2019 23:33, Emmanuel Lécharny wrote:
>> Ok, looking at the CompressionFilter, here is what I see:
>>
>>
>> @Override
>> protected Object doFilterWrite(NextFilter nextFilter, IoSession session, WriteRequest writeRequest)
>> throws IOException {
>> ...
>> IoBuffer inBuffer = (IoBuffer) writeRequest.getMessage();
>> if (!inBuffer.hasRemaining()) {
>> // Ignore empty buffers
>> return null;
>> } else {
>> return deflater.deflate(inBuffer);
>> }
>> }
>>
>>
>> and
>>
>>
>> public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
>> if (mode == MODE_INFLATER) {
>> throw new IllegalStateException("not initialized as DEFLATER");
>> }
>>
>> byte[] inBytes = new byte[inBuffer.remaining()];
>> inBuffer.get(inBytes).flip();
>>
>>
>> and finally :
>>
>>
>> public final IoBuffer flip() {
>> buf().flip();
>> mark = -1;
>> return this;
>> }
>>
>> mark is now -1, so setting a position on it will produce the error you get.
>>
>>
>> Sounds like a bug to me...
>>
>>> On 19/03/2019 23:04, Emmanuel Lécharny wrote:
>>> Hi Greg, Jonathan,
>>>
>>> it was 3 years ago, and I don't remember what was the root cause of this change. However, reading the diff, what I can tell is that the changed version assume that the original message (ie the message the app is writing) may not be a IoBuffer, and in this case, we needed to process it differently.
>>>
>>>
>>> Let me clarify.
>>>
>>> When a message is written by an application, it can be anything ( a String, a data structure, some byte[], whatever), but it means something for the application. Then it goes through the filter chain, and it get encoded, encrypted, compressed, it all depends on the filters in use. When it hits the bottom of the chain, it's a IoBuffer that has to be written to the remote peer. When this IoBuffer has been fully written, we can send the MessageSend event back to the IoHandler, and we do so by using the 'original' message (ie the message before it get encoded/compressed/encrypted) to avoid having to decode/decrypt/decompress it again. It's like :
>>>
>>>
>>> IoHandler write( <original message> ) -> [filter] --(origMsg, transformedMsg)--> [filter] --(origMsg, transformedMsg)--> ...--(origMsg, transformedMsg)--> [Head]-> write transformed data to socket
>>>
>>> when the data has been fully sent, we go back :
>>>
>>> [Head] --(origMsg)--> [filter] --> ... --(origMsg)--> IoHandler "The <origMsg> message has been fully sent"
>>>
>>> This original message is likely not to be contained in a IoBuffer, so we have to keep it as is. OTOH, if it was a IoBuffer, its position has changed while being processed in the filter chain, as ity has been read, so we need to reset its position to the very beginning.
>>>
>>>
>>> Anyway, looking at the exception you get, here is what I suspect : the buffer has been flipped, or cleared, and the mark is now -1, which leads to the message you get when trying top do a reset on it.
>>>
>>>
>>> Is there a way to see the code that get called when you get this error ?
>>>
>>>> On 19/03/2019 18:18, Greg Thomas wrote:
>>>> Details from
>>>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>
>>>> Don't try to reset a message when it's not a IoBuffer
>>>>
>>>> Emmanuel Lécharny <el...@symas.com>
>>>>
>>>> Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
>>>>
>>>> Greg
>>>>
>>>> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere <jo...@emoten.com>
>>>> wrote:
>>>>
>>>>> I’m trying to look it up in gitbox and it doesn’t show the ids. What was
>>>>> the date / first few words of commit message?
>>>>>
>>>>> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>> So just to clarify;
>>>>>>
>>>>>> If we run against 2.0.14, connections using the CompressionFilter fail.
>>>>>>
>>>>>> If I ...
>>>>>>
>>>>>> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
>>>>>> $ cd mina
>>>>>> $ git checkout 2.0.14
>>>>>> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>>> $ mvn clean package
>>>>>>
>>>>>> and use the JAR files from that, connections using the CompressionFilter
>>>>>> succeed.
>>>>>>
>>>>>> So I'm pretty confident that commit
>>>>>> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
>>>>>> understand the code well enough to be able to suggest why/how to fix it.
>>>>>>
>>>>>> Greg
>>>>>>
>>>>>>
>>>>>> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
>>>>>> wrote:
>>>>>>
>>>>>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
>>>>> It’s
>>>>>>> always possible that there is a concurrency problem with compression
>>>>>> filter
>>>>>>> which is now exposed through other changes... like what we have with
>>>>> SSL.
>>>>>>> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> Openfire - an XMPP server,
>>>>>>>> https://www.igniterealtime.org/projects/openfire/index.jsp - makes
>>>>>> heavy
>>>>>>>> use of Apache MINA for it's I/O.
>>>>>>>>
>>>>>>>> One of the things it uses is the CompressionFilter - if clients
>>>>> enable
>>>>>>> the
>>>>>>>> Compression XMPP option.
>>>>>>>>
>>>>>>>> We've recently updated to a newer version of MINA, and with no other
>>>>>> code
>>>>>>>> changes found that enabling compression (in XMPP clients) fails. I've
>>>>>>>> narrowed it down to changes between MINA 2.0.13 (where it works) and
>>>>>>> 2.0.14
>>>>>>>> through to 2.1.0 (where it doesn't) - with Openfire throwing the
>>>>>>> following
>>>>>>>> stack trace:
>>>>>>>>
>>>>>>>> java.nio.InvalidMarkException: null
>>>>>>>> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
>>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>>>>>>>> ~[?:1.8.0_162]
>>>>>>>> at
>>>>>>>>
>>>>>>>>
>>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>>>>>>>> ~[?:1.8.0_162]
>>>>>>>> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
>>>>>>>>
>>>>>>>> Narrowing down even further the commit at
>>>>>>>>
>>>>>>>>
>>>>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>>>>> seems
>>>>>>>> to be the culprit.
>>>>>>>>
>>>>>>>> At this point, I'm drawing a blank.
>>>>>>>>
>>>>>>>> It's possible Openfire is using the CompressionFilter wrongly, which
>>>>>> was
>>>>>>>> being masked until the above commit.
>>>>>>>>
>>>>>>>> It's possible the above commit doesn't do what was intended, but I
>>>>>> don't
>>>>>>>> pretend to understand what it is/should be doing.
>>>>>>>>
>>>>>>>> It's possible I've got the wrong end of the stick, and it's something
>>>>>>> else
>>>>>>>> between MINA 2.0.13 and 2.0.14 that changed that is causing the
>>>>>> problem.
>>>>>>>> But at this point, I don't know where to start, so would appreciate
>>>>> any
>>>>>>>> pointers!
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>>
>>>>>>>> Greg
>>>>>>>>
>>>>> --
>>>>>
>>>>> CONFIDENTIALITY NOTICE: The contents of this email message and any
>>>>> attachments are intended solely for the addressee(s) and may contain
>>>>> confidential and/or privileged information and may be legally protected
>>>>> from disclosure.
>>>>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
I can reproduce the issue with a much simpler application (using the
'chat' example).
I will try to get a fix asap.
On 19/03/2019 23:33, Emmanuel Lécharny wrote:
> Ok, looking at the CompressionFilter, here is what I see:
>
>
> @Override
> protected Object doFilterWrite(NextFilter nextFilter, IoSession
> session, WriteRequest writeRequest)
> throws IOException {
> ...
> IoBuffer inBuffer = (IoBuffer) writeRequest.getMessage();
> if (!inBuffer.hasRemaining()) {
> // Ignore empty buffers
> return null;
> } else {
> return deflater.deflate(inBuffer);
> }
> }
>
>
> and
>
>
> public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
> if (mode == MODE_INFLATER) {
> throw new IllegalStateException("not initialized as
> DEFLATER");
> }
>
> byte[] inBytes = new byte[inBuffer.remaining()];
> inBuffer.get(inBytes).flip();
>
>
> and finally :
>
>
> public final IoBuffer flip() {
> buf().flip();
> mark = -1;
> return this;
> }
>
> mark is now -1, so setting a position on it will produce the error you
> get.
>
>
> Sounds like a bug to me...
>
> On 19/03/2019 23:04, Emmanuel Lécharny wrote:
>> Hi Greg, Jonathan,
>>
>> it was 3 years ago, and I don't remember what was the root cause of
>> this change. However, reading the diff, what I can tell is that the
>> changed version assume that the original message (ie the message the
>> app is writing) may not be a IoBuffer, and in this case, we needed to
>> process it differently.
>>
>>
>> Let me clarify.
>>
>> When a message is written by an application, it can be anything ( a
>> String, a data structure, some byte[], whatever), but it means
>> something for the application. Then it goes through the filter chain,
>> and it get encoded, encrypted, compressed, it all depends on the
>> filters in use. When it hits the bottom of the chain, it's a IoBuffer
>> that has to be written to the remote peer. When this IoBuffer has
>> been fully written, we can send the MessageSend event back to the
>> IoHandler, and we do so by using the 'original' message (ie the
>> message before it get encoded/compressed/encrypted) to avoid having
>> to decode/decrypt/decompress it again. It's like :
>>
>>
>> IoHandler write( <original message> ) -> [filter] --(origMsg,
>> transformedMsg)--> [filter] --(origMsg, transformedMsg)-->
>> ...--(origMsg, transformedMsg)--> [Head]-> write transformed data to
>> socket
>>
>> when the data has been fully sent, we go back :
>>
>> [Head] --(origMsg)--> [filter] --> ... --(origMsg)--> IoHandler "The
>> <origMsg> message has been fully sent"
>>
>> This original message is likely not to be contained in a IoBuffer, so
>> we have to keep it as is. OTOH, if it was a IoBuffer, its position
>> has changed while being processed in the filter chain, as ity has
>> been read, so we need to reset its position to the very beginning.
>>
>>
>> Anyway, looking at the exception you get, here is what I suspect :
>> the buffer has been flipped, or cleared, and the mark is now -1,
>> which leads to the message you get when trying top do a reset on it.
>>
>>
>> Is there a way to see the code that get called when you get this error ?
>>
>> On 19/03/2019 18:18, Greg Thomas wrote:
>>> Details from
>>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>
>>>
>>> Don't try to reset a message when it's not a IoBuffer
>>>
>>> Emmanuel Lécharny <el...@symas.com>
>>>
>>> Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
>>>
>>> Greg
>>>
>>> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere
>>> <jo...@emoten.com>
>>> wrote:
>>>
>>>> I’m trying to look it up in gitbox and it doesn’t show the ids.
>>>> What was
>>>> the date / first few words of commit message?
>>>>
>>>> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com>
>>>> wrote:
>>>>
>>>>> So just to clarify;
>>>>>
>>>>> If we run against 2.0.14, connections using the CompressionFilter
>>>>> fail.
>>>>>
>>>>> If I ...
>>>>>
>>>>> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
>>>>> $ cd mina
>>>>> $ git checkout 2.0.14
>>>>> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>> $ mvn clean package
>>>>>
>>>>> and use the JAR files from that, connections using the
>>>>> CompressionFilter
>>>>> succeed.
>>>>>
>>>>> So I'm pretty confident that commit
>>>>> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
>>>>> understand the code well enough to be able to suggest why/how to
>>>>> fix it.
>>>>>
>>>>> Greg
>>>>>
>>>>>
>>>>> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
>>>>> wrote:
>>>>>
>>>>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
>>>> It’s
>>>>>> always possible that there is a concurrency problem with compression
>>>>> filter
>>>>>> which is now exposed through other changes... like what we have with
>>>> SSL.
>>>>>> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas
>>>>>> <gr...@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>>> Openfire - an XMPP server,
>>>>>>> https://www.igniterealtime.org/projects/openfire/index.jsp - makes
>>>>> heavy
>>>>>>> use of Apache MINA for it's I/O.
>>>>>>>
>>>>>>> One of the things it uses is the CompressionFilter - if clients
>>>> enable
>>>>>> the
>>>>>>> Compression XMPP option.
>>>>>>>
>>>>>>> We've recently updated to a newer version of MINA, and with no
>>>>>>> other
>>>>> code
>>>>>>> changes found that enabling compression (in XMPP clients) fails.
>>>>>>> I've
>>>>>>> narrowed it down to changes between MINA 2.0.13 (where it works)
>>>>>>> and
>>>>>> 2.0.14
>>>>>>> through to 2.1.0 (where it doesn't) - with Openfire throwing the
>>>>>> following
>>>>>>> stack trace:
>>>>>>>
>>>>>>> java.nio.InvalidMarkException: null
>>>>>>> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
>>>>
>>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>>>>
>>>>>>> ~[?:1.8.0_162]
>>>>>>> at
>>>>>>>
>>>>>>>
>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>>>>
>>>>>>> ~[?:1.8.0_162]
>>>>>>> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
>>>>>>>
>>>>>>> Narrowing down even further the commit at
>>>>>>>
>>>>>>>
>>>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>
>>>>>>> seems
>>>>>>> to be the culprit.
>>>>>>>
>>>>>>> At this point, I'm drawing a blank.
>>>>>>>
>>>>>>> It's possible Openfire is using the CompressionFilter wrongly,
>>>>>>> which
>>>>> was
>>>>>>> being masked until the above commit.
>>>>>>>
>>>>>>> It's possible the above commit doesn't do what was intended, but I
>>>>> don't
>>>>>>> pretend to understand what it is/should be doing.
>>>>>>>
>>>>>>> It's possible I've got the wrong end of the stick, and it's
>>>>>>> something
>>>>>> else
>>>>>>> between MINA 2.0.13 and 2.0.14 that changed that is causing the
>>>>> problem.
>>>>>>> But at this point, I don't know where to start, so would appreciate
>>>> any
>>>>>>> pointers!
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> Greg
>>>>>>>
>>>> --
>>>>
>>>> CONFIDENTIALITY NOTICE: The contents of this email message and any
>>>> attachments are intended solely for the addressee(s) and may contain
>>>> confidential and/or privileged information and may be legally
>>>> protected
>>>> from disclosure.
>>>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Ok, looking at the CompressionFilter, here is what I see:
@Override
protected Object doFilterWrite(NextFilter nextFilter, IoSession
session, WriteRequest writeRequest)
throws IOException {
...
IoBuffer inBuffer = (IoBuffer) writeRequest.getMessage();
if (!inBuffer.hasRemaining()) {
// Ignore empty buffers
return null;
} else {
return deflater.deflate(inBuffer);
}
}
and
public IoBuffer deflate(IoBuffer inBuffer) throws IOException {
if (mode == MODE_INFLATER) {
throw new IllegalStateException("not initialized as DEFLATER");
}
byte[] inBytes = new byte[inBuffer.remaining()];
inBuffer.get(inBytes).flip();
and finally :
public final IoBuffer flip() {
buf().flip();
mark = -1;
return this;
}
mark is now -1, so setting a position on it will produce the error you get.
Sounds like a bug to me...
On 19/03/2019 23:04, Emmanuel Lécharny wrote:
> Hi Greg, Jonathan,
>
> it was 3 years ago, and I don't remember what was the root cause of
> this change. However, reading the diff, what I can tell is that the
> changed version assume that the original message (ie the message the
> app is writing) may not be a IoBuffer, and in this case, we needed to
> process it differently.
>
>
> Let me clarify.
>
> When a message is written by an application, it can be anything ( a
> String, a data structure, some byte[], whatever), but it means
> something for the application. Then it goes through the filter chain,
> and it get encoded, encrypted, compressed, it all depends on the
> filters in use. When it hits the bottom of the chain, it's a IoBuffer
> that has to be written to the remote peer. When this IoBuffer has been
> fully written, we can send the MessageSend event back to the
> IoHandler, and we do so by using the 'original' message (ie the
> message before it get encoded/compressed/encrypted) to avoid having to
> decode/decrypt/decompress it again. It's like :
>
>
> IoHandler write( <original message> ) -> [filter] --(origMsg,
> transformedMsg)--> [filter] --(origMsg, transformedMsg)-->
> ...--(origMsg, transformedMsg)--> [Head]-> write transformed data to
> socket
>
> when the data has been fully sent, we go back :
>
> [Head] --(origMsg)--> [filter] --> ... --(origMsg)--> IoHandler "The
> <origMsg> message has been fully sent"
>
> This original message is likely not to be contained in a IoBuffer, so
> we have to keep it as is. OTOH, if it was a IoBuffer, its position
> has changed while being processed in the filter chain, as ity has been
> read, so we need to reset its position to the very beginning.
>
>
> Anyway, looking at the exception you get, here is what I suspect : the
> buffer has been flipped, or cleared, and the mark is now -1, which
> leads to the message you get when trying top do a reset on it.
>
>
> Is there a way to see the code that get called when you get this error ?
>
> On 19/03/2019 18:18, Greg Thomas wrote:
>> Details from
>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>
>>
>> Don't try to reset a message when it's not a IoBuffer
>>
>> Emmanuel Lécharny <el...@symas.com>
>>
>> Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
>>
>> Greg
>>
>> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere
>> <jo...@emoten.com>
>> wrote:
>>
>>> I’m trying to look it up in gitbox and it doesn’t show the ids. What
>>> was
>>> the date / first few words of commit message?
>>>
>>> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com>
>>> wrote:
>>>
>>>> So just to clarify;
>>>>
>>>> If we run against 2.0.14, connections using the CompressionFilter
>>>> fail.
>>>>
>>>> If I ...
>>>>
>>>> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
>>>> $ cd mina
>>>> $ git checkout 2.0.14
>>>> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
>>>> $ mvn clean package
>>>>
>>>> and use the JAR files from that, connections using the
>>>> CompressionFilter
>>>> succeed.
>>>>
>>>> So I'm pretty confident that commit
>>>> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
>>>> understand the code well enough to be able to suggest why/how to
>>>> fix it.
>>>>
>>>> Greg
>>>>
>>>>
>>>> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
>>>> wrote:
>>>>
>>>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
>>> It’s
>>>>> always possible that there is a concurrency problem with compression
>>>> filter
>>>>> which is now exposed through other changes... like what we have with
>>> SSL.
>>>>> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
>>>>> wrote:
>>>>>
>>>>>> Openfire - an XMPP server,
>>>>>> https://www.igniterealtime.org/projects/openfire/index.jsp - makes
>>>> heavy
>>>>>> use of Apache MINA for it's I/O.
>>>>>>
>>>>>> One of the things it uses is the CompressionFilter - if clients
>>> enable
>>>>> the
>>>>>> Compression XMPP option.
>>>>>>
>>>>>> We've recently updated to a newer version of MINA, and with no other
>>>> code
>>>>>> changes found that enabling compression (in XMPP clients) fails.
>>>>>> I've
>>>>>> narrowed it down to changes between MINA 2.0.13 (where it works) and
>>>>> 2.0.14
>>>>>> through to 2.1.0 (where it doesn't) - with Openfire throwing the
>>>>> following
>>>>>> stack trace:
>>>>>>
>>>>>> java.nio.InvalidMarkException: null
>>>>>> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
>>>
>>>>>> ~[mina-core-2.0.14.jar:?]
>>>>>> at
>>>>>>
>>>>>>
>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>>>
>>>>>> ~[?:1.8.0_162]
>>>>>> at
>>>>>>
>>>>>>
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>>>
>>>>>> ~[?:1.8.0_162]
>>>>>> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
>>>>>>
>>>>>> Narrowing down even further the commit at
>>>>>>
>>>>>>
>>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>
>>>>>> seems
>>>>>> to be the culprit.
>>>>>>
>>>>>> At this point, I'm drawing a blank.
>>>>>>
>>>>>> It's possible Openfire is using the CompressionFilter wrongly, which
>>>> was
>>>>>> being masked until the above commit.
>>>>>>
>>>>>> It's possible the above commit doesn't do what was intended, but I
>>>> don't
>>>>>> pretend to understand what it is/should be doing.
>>>>>>
>>>>>> It's possible I've got the wrong end of the stick, and it's
>>>>>> something
>>>>> else
>>>>>> between MINA 2.0.13 and 2.0.14 that changed that is causing the
>>>> problem.
>>>>>> But at this point, I don't know where to start, so would appreciate
>>> any
>>>>>> pointers!
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> Greg
>>>>>>
>>> --
>>>
>>> CONFIDENTIALITY NOTICE: The contents of this email message and any
>>> attachments are intended solely for the addressee(s) and may contain
>>> confidential and/or privileged information and may be legally protected
>>> from disclosure.
>>>
Re: Change in behaviour of CompressionFilter
Posted by Emmanuel Lécharny <el...@gmail.com>.
Hi Greg, Jonathan,
it was 3 years ago, and I don't remember what was the root cause of this
change. However, reading the diff, what I can tell is that the changed
version assume that the original message (ie the message the app is
writing) may not be a IoBuffer, and in this case, we needed to process
it differently.
Let me clarify.
When a message is written by an application, it can be anything ( a
String, a data structure, some byte[], whatever), but it means something
for the application. Then it goes through the filter chain, and it get
encoded, encrypted, compressed, it all depends on the filters in use.
When it hits the bottom of the chain, it's a IoBuffer that has to be
written to the remote peer. When this IoBuffer has been fully written,
we can send the MessageSend event back to the IoHandler, and we do so by
using the 'original' message (ie the message before it get
encoded/compressed/encrypted) to avoid having to
decode/decrypt/decompress it again. It's like :
IoHandler write( <original message> ) -> [filter] --(origMsg,
transformedMsg)--> [filter] --(origMsg, transformedMsg)-->
...--(origMsg, transformedMsg)--> [Head]-> write transformed data to socket
when the data has been fully sent, we go back :
[Head] --(origMsg)--> [filter] --> ... --(origMsg)--> IoHandler "The
<origMsg> message has been fully sent"
This original message is likely not to be contained in a IoBuffer, so we
have to keep it as is. OTOH, if it was a IoBuffer, its position has
changed while being processed in the filter chain, as ity has been read,
so we need to reset its position to the very beginning.
Anyway, looking at the exception you get, here is what I suspect : the
buffer has been flipped, or cleared, and the mark is now -1, which leads
to the message you get when trying top do a reset on it.
Is there a way to see the code that get called when you get this error ?
On 19/03/2019 18:18, Greg Thomas wrote:
> Details from
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>
> Don't try to reset a message when it's not a IoBuffer
>
> Emmanuel Lécharny <el...@symas.com>
>
> Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
>
> Greg
>
> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere <jo...@emoten.com>
> wrote:
>
>> I’m trying to look it up in gitbox and it doesn’t show the ids. What was
>> the date / first few words of commit message?
>>
>> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com>
>> wrote:
>>
>>> So just to clarify;
>>>
>>> If we run against 2.0.14, connections using the CompressionFilter fail.
>>>
>>> If I ...
>>>
>>> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
>>> $ cd mina
>>> $ git checkout 2.0.14
>>> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
>>> $ mvn clean package
>>>
>>> and use the JAR files from that, connections using the CompressionFilter
>>> succeed.
>>>
>>> So I'm pretty confident that commit
>>> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
>>> understand the code well enough to be able to suggest why/how to fix it.
>>>
>>> Greg
>>>
>>>
>>> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
>>> wrote:
>>>
>>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
>> It’s
>>>> always possible that there is a concurrency problem with compression
>>> filter
>>>> which is now exposed through other changes... like what we have with
>> SSL.
>>>> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
>>>> wrote:
>>>>
>>>>> Openfire - an XMPP server,
>>>>> https://www.igniterealtime.org/projects/openfire/index.jsp - makes
>>> heavy
>>>>> use of Apache MINA for it's I/O.
>>>>>
>>>>> One of the things it uses is the CompressionFilter - if clients
>> enable
>>>> the
>>>>> Compression XMPP option.
>>>>>
>>>>> We've recently updated to a newer version of MINA, and with no other
>>> code
>>>>> changes found that enabling compression (in XMPP clients) fails. I've
>>>>> narrowed it down to changes between MINA 2.0.13 (where it works) and
>>>> 2.0.14
>>>>> through to 2.1.0 (where it doesn't) - with Openfire throwing the
>>>> following
>>>>> stack trace:
>>>>>
>>>>> java.nio.InvalidMarkException: null
>>>>> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
>>>>> ~[mina-core-2.0.14.jar:?]
>>>>> at
>>>>>
>>>>>
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>>>>> ~[?:1.8.0_162]
>>>>> at
>>>>>
>>>>>
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>>>>> ~[?:1.8.0_162]
>>>>> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
>>>>>
>>>>> Narrowing down even further the commit at
>>>>>
>>>>>
>> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
>>>>> seems
>>>>> to be the culprit.
>>>>>
>>>>> At this point, I'm drawing a blank.
>>>>>
>>>>> It's possible Openfire is using the CompressionFilter wrongly, which
>>> was
>>>>> being masked until the above commit.
>>>>>
>>>>> It's possible the above commit doesn't do what was intended, but I
>>> don't
>>>>> pretend to understand what it is/should be doing.
>>>>>
>>>>> It's possible I've got the wrong end of the stick, and it's something
>>>> else
>>>>> between MINA 2.0.13 and 2.0.14 that changed that is causing the
>>> problem.
>>>>> But at this point, I don't know where to start, so would appreciate
>> any
>>>>> pointers!
>>>>>
>>>>> Thanks,
>>>>>
>>>>> Greg
>>>>>
>> --
>>
>> CONFIDENTIALITY NOTICE: The contents of this email message and any
>> attachments are intended solely for the addressee(s) and may contain
>> confidential and/or privileged information and may be legally protected
>> from disclosure.
>>
Re: Change in behaviour of CompressionFilter
Posted by Greg Thomas <gr...@gmail.com>.
Details from
https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
Don't try to reset a message when it's not a IoBuffer
Emmanuel Lécharny <el...@symas.com>
Tue, 16 Feb 2016 14:38:14 +0000 (15:38 +0100)
Greg
On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere <jo...@emoten.com>
wrote:
> I’m trying to look it up in gitbox and it doesn’t show the ids. What was
> the date / first few words of commit message?
>
> On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com>
> wrote:
>
> > So just to clarify;
> >
> > If we run against 2.0.14, connections using the CompressionFilter fail.
> >
> > If I ...
> >
> > $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
> > $ cd mina
> > $ git checkout 2.0.14
> > $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
> > $ mvn clean package
> >
> > and use the JAR files from that, connections using the CompressionFilter
> > succeed.
> >
> > So I'm pretty confident that commit
> > 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
> > understand the code well enough to be able to suggest why/how to fix it.
> >
> > Greg
> >
> >
> > On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
> > wrote:
> >
> > > Have you pulled a diff between 13 and 14 to try to narrow it down?
> It’s
> > > always possible that there is a concurrency problem with compression
> > filter
> > > which is now exposed through other changes... like what we have with
> SSL.
> > >
> > > On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
> > > wrote:
> > >
> > > > Openfire - an XMPP server,
> > > > https://www.igniterealtime.org/projects/openfire/index.jsp - makes
> > heavy
> > > > use of Apache MINA for it's I/O.
> > > >
> > > > One of the things it uses is the CompressionFilter - if clients
> enable
> > > the
> > > > Compression XMPP option.
> > > >
> > > > We've recently updated to a newer version of MINA, and with no other
> > code
> > > > changes found that enabling compression (in XMPP clients) fails. I've
> > > > narrowed it down to changes between MINA 2.0.13 (where it works) and
> > > 2.0.14
> > > > through to 2.1.0 (where it doesn't) - with Openfire throwing the
> > > following
> > > > stack trace:
> > > >
> > > > java.nio.InvalidMarkException: null
> > > > at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> > > > ~[mina-core-2.0.14.jar:?]
> > > > at
> > > >
> > > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> > > > ~[?:1.8.0_162]
> > > > at
> > > >
> > > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > > > ~[?:1.8.0_162]
> > > > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
> > > >
> > > > Narrowing down even further the commit at
> > > >
> > > >
> > >
> >
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> > > > seems
> > > > to be the culprit.
> > > >
> > > > At this point, I'm drawing a blank.
> > > >
> > > > It's possible Openfire is using the CompressionFilter wrongly, which
> > was
> > > > being masked until the above commit.
> > > >
> > > > It's possible the above commit doesn't do what was intended, but I
> > don't
> > > > pretend to understand what it is/should be doing.
> > > >
> > > > It's possible I've got the wrong end of the stick, and it's something
> > > else
> > > > between MINA 2.0.13 and 2.0.14 that changed that is causing the
> > problem.
> > > >
> > > > But at this point, I don't know where to start, so would appreciate
> any
> > > > pointers!
> > > >
> > > > Thanks,
> > > >
> > > > Greg
> > > >
> > >
> >
> --
>
> CONFIDENTIALITY NOTICE: The contents of this email message and any
> attachments are intended solely for the addressee(s) and may contain
> confidential and/or privileged information and may be legally protected
> from disclosure.
>
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@emoten.com>.
I’m trying to look it up in gitbox and it doesn’t show the ids. What was
the date / first few words of commit message?
On Tue, Mar 19, 2019 at 1:13 PM Greg Thomas <gr...@gmail.com> wrote:
> So just to clarify;
>
> If we run against 2.0.14, connections using the CompressionFilter fail.
>
> If I ...
>
> $ git clone http://gitbox.apache.org/repos/asf/mina.git mina
> $ cd mina
> $ git checkout 2.0.14
> $ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
> $ mvn clean package
>
> and use the JAR files from that, connections using the CompressionFilter
> succeed.
>
> So I'm pretty confident that commit
> 44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
> understand the code well enough to be able to suggest why/how to fix it.
>
> Greg
>
>
> On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org>
> wrote:
>
> > Have you pulled a diff between 13 and 14 to try to narrow it down? It’s
> > always possible that there is a concurrency problem with compression
> filter
> > which is now exposed through other changes... like what we have with SSL.
> >
> > On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
> > wrote:
> >
> > > Openfire - an XMPP server,
> > > https://www.igniterealtime.org/projects/openfire/index.jsp - makes
> heavy
> > > use of Apache MINA for it's I/O.
> > >
> > > One of the things it uses is the CompressionFilter - if clients enable
> > the
> > > Compression XMPP option.
> > >
> > > We've recently updated to a newer version of MINA, and with no other
> code
> > > changes found that enabling compression (in XMPP clients) fails. I've
> > > narrowed it down to changes between MINA 2.0.13 (where it works) and
> > 2.0.14
> > > through to 2.1.0 (where it doesn't) - with Openfire throwing the
> > following
> > > stack trace:
> > >
> > > java.nio.InvalidMarkException: null
> > > at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
> > > at
> > >
> > >
> >
> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> > > ~[mina-core-2.0.14.jar:?]
> > > at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> > > ~[?:1.8.0_162]
> > > at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > > ~[?:1.8.0_162]
> > > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
> > >
> > > Narrowing down even further the commit at
> > >
> > >
> >
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> > > seems
> > > to be the culprit.
> > >
> > > At this point, I'm drawing a blank.
> > >
> > > It's possible Openfire is using the CompressionFilter wrongly, which
> was
> > > being masked until the above commit.
> > >
> > > It's possible the above commit doesn't do what was intended, but I
> don't
> > > pretend to understand what it is/should be doing.
> > >
> > > It's possible I've got the wrong end of the stick, and it's something
> > else
> > > between MINA 2.0.13 and 2.0.14 that changed that is causing the
> problem.
> > >
> > > But at this point, I don't know where to start, so would appreciate any
> > > pointers!
> > >
> > > Thanks,
> > >
> > > Greg
> > >
> >
>
--
CONFIDENTIALITY NOTICE: The contents of this email message and any
attachments are intended solely for the addressee(s) and may contain
confidential and/or privileged information and may be legally protected
from disclosure.
Re: Change in behaviour of CompressionFilter
Posted by Greg Thomas <gr...@gmail.com>.
So just to clarify;
If we run against 2.0.14, connections using the CompressionFilter fail.
If I ...
$ git clone http://gitbox.apache.org/repos/asf/mina.git mina
$ cd mina
$ git checkout 2.0.14
$ git revert 44b58469f84ce991074cdc187b1c1f23b94cf445
$ mvn clean package
and use the JAR files from that, connections using the CompressionFilter
succeed.
So I'm pretty confident that commit
44b58469f84ce991074cdc187b1c1f23b94cf445 is the culprit. I just don't
understand the code well enough to be able to suggest why/how to fix it.
Greg
On Tue, 19 Mar 2019 at 14:39, Jonathan Valliere <jo...@apache.org> wrote:
> Have you pulled a diff between 13 and 14 to try to narrow it down? It’s
> always possible that there is a concurrency problem with compression filter
> which is now exposed through other changes... like what we have with SSL.
>
> On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com>
> wrote:
>
> > Openfire - an XMPP server,
> > https://www.igniterealtime.org/projects/openfire/index.jsp - makes heavy
> > use of Apache MINA for it's I/O.
> >
> > One of the things it uses is the CompressionFilter - if clients enable
> the
> > Compression XMPP option.
> >
> > We've recently updated to a newer version of MINA, and with no other code
> > changes found that enabling compression (in XMPP clients) fails. I've
> > narrowed it down to changes between MINA 2.0.13 (where it works) and
> 2.0.14
> > through to 2.1.0 (where it doesn't) - with Openfire throwing the
> following
> > stack trace:
> >
> > java.nio.InvalidMarkException: null
> > at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
> > at
> >
> >
> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> > ~[mina-core-2.0.14.jar:?]
> > at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> > ~[?:1.8.0_162]
> > at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> > ~[?:1.8.0_162]
> > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
> >
> > Narrowing down even further the commit at
> >
> >
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> > seems
> > to be the culprit.
> >
> > At this point, I'm drawing a blank.
> >
> > It's possible Openfire is using the CompressionFilter wrongly, which was
> > being masked until the above commit.
> >
> > It's possible the above commit doesn't do what was intended, but I don't
> > pretend to understand what it is/should be doing.
> >
> > It's possible I've got the wrong end of the stick, and it's something
> else
> > between MINA 2.0.13 and 2.0.14 that changed that is causing the problem.
> >
> > But at this point, I don't know where to start, so would appreciate any
> > pointers!
> >
> > Thanks,
> >
> > Greg
> >
>
Re: Change in behaviour of CompressionFilter
Posted by Jonathan Valliere <jo...@apache.org>.
Have you pulled a diff between 13 and 14 to try to narrow it down? It’s
always possible that there is a concurrency problem with compression filter
which is now exposed through other changes... like what we have with SSL.
On Tue, Mar 19, 2019 at 8:33 AM Greg Thomas <gr...@gmail.com> wrote:
> Openfire - an XMPP server,
> https://www.igniterealtime.org/projects/openfire/index.jsp - makes heavy
> use of Apache MINA for it's I/O.
>
> One of the things it uses is the CompressionFilter - if clients enable the
> Compression XMPP option.
>
> We've recently updated to a newer version of MINA, and with no other code
> changes found that enabling compression (in XMPP clients) fails. I've
> narrowed it down to changes between MINA 2.0.13 (where it works) and 2.0.14
> through to 2.1.0 (where it doesn't) - with Openfire throwing the following
> stack trace:
>
> java.nio.InvalidMarkException: null
> at java.nio.Buffer.reset(Buffer.java:306) ~[?:1.8.0_162]
> at
>
> org.apache.mina.core.buffer.AbstractIoBuffer.reset(AbstractIoBuffer.java:424)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:940)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:840)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:767)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:68)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1125)
> ~[mina-core-2.0.14.jar:?]
> at
>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> ~[mina-core-2.0.14.jar:?]
> at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> ~[?:1.8.0_162]
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> ~[?:1.8.0_162]
> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
>
> Narrowing down even further the commit at
>
> https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=44b58469f84ce991074cdc187b1c1f23b94cf445
> seems
> to be the culprit.
>
> At this point, I'm drawing a blank.
>
> It's possible Openfire is using the CompressionFilter wrongly, which was
> being masked until the above commit.
>
> It's possible the above commit doesn't do what was intended, but I don't
> pretend to understand what it is/should be doing.
>
> It's possible I've got the wrong end of the stick, and it's something else
> between MINA 2.0.13 and 2.0.14 that changed that is causing the problem.
>
> But at this point, I don't know where to start, so would appreciate any
> pointers!
>
> Thanks,
>
> Greg
>