Re: Change in behaviour of CompressionFilter
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 [LW5/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 : 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B Ps..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 : 15 03 03 00 50 P [Raw read]: length = 80 : 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 : 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 [LW5/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 : 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 : 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
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 [LW5/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 : 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B Ps..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 : 15 03 03 00 50 P [Raw read]: length = 80 : 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 : 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 [LW5/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 : 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 : 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
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 [LW5/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 : 15 03 03 00 50 95 AF BB C6 73 1A CB 66 9B 80 8B Ps..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 : 15 03 03 00 50 P [Raw read]: length = 80 : 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 : 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 [LW5/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 : 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 : 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
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 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.
Re: Change in behaviour of CompressionFilter
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
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
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
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( ) 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:
> >> Hmmpp
> >>
> >> I have traced the calls when a session.write( ) 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
Re: Change in behaviour of CompressionFilter
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( ) 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:
Hmmpp
I have traced the calls when a session.write( ) 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 =
Re: Change in behaviour of CompressionFilter
Ok, I have a version that works better with the CompressionFilter.
Here is what I have changed :
- the session.write( ) 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:
Hmmpp
I have traced the calls when a session.write( ) 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
Hmmpp
I have traced the calls when a session.write( ) 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
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 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
I’ll look into not using mark reset there. On Wed, Mar 20, 2019 at 11:05 AM Emmanuel Lécharny 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
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
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
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
> 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
>> > mailto:elecha...@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
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
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
> > mailto:elecha...@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
(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
mailto:elecha...@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
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 wrote:
> Many thanks!
>
> Greg
>
> > On 20 Mar 2019, at 07:42, Emmanuel Lécharny 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( ) -> [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
> 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
>
> Tue, 16 Feb 2016 14:38:14 + (15:38 +0100)
>
> Greg
>
> On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere <
> jon.valli...@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 >
> > 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
Re: Change in behaviour of CompressionFilter
Many thanks!
Greg
> On 20 Mar 2019, at 07:42, Emmanuel Lécharny 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( ) -> [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
>>> 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
Tue, 16 Feb 2016 14:38:14 + (15:38 +0100)
Greg
On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere
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
> 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
>> wrote:
>>
>>> Have you pulled a diff between 13 and 14 to try to narrow it down?
> It’s
Re: Change in behaviour of CompressionFilter
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( ) -> [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
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
Tue, 16 Feb 2016 14:38:14 + (15:38 +0100)
Greg
On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere
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
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
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
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
Re: Change in behaviour of CompressionFilter
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( ) -> [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
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
Tue, 16 Feb 2016 14:38:14 + (15:38 +0100)
Greg
On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere
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
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
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
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]
Re: Change in behaviour of CompressionFilter
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( ) -> [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 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 Tue, 16 Feb 2016 14:38:14 + (15:38 +0100) Greg On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere 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 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 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 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
Re: Change in behaviour of CompressionFilter
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 Tue, 16 Feb 2016 14:38:14 + (15:38 +0100) Greg On Tue, 19 Mar 2019 at 17:17, Jonathan Valliere 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 > 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 > > 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 > > > 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
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 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 > 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 > > 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
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 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 > 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
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 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 >
