Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WebSocket aggregation FrameTooLargeException handling doesn't close connection #3295

Closed
joebyneil opened this issue Jun 12, 2024 · 4 comments
Closed

WebSocket aggregation FrameTooLargeException handling doesn't close connection #3295

joebyneil opened this issue Jun 12, 2024 · 4 comments
Assignees
@violetagg
Labels
status/invalid We don't feel this issue is valid

Comments

@joebyneil
Copy link

Hey 👋

Expected Behavior

We receive the following exception caused by MessageAggregator when aggregating frames.
FluxReceive : [dfd30519-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:54580] An exception has been observed post termination, use DEBUG level to see the full stack: io.netty.handler.codec.TooLongFrameException: content length exceeded 5000000 bytes is received.

Expecting that that this situation would cause a close frame to be sent and the websocket is disposed. I expected this behaviour because this is what would happen if a single frame was oversized for the .maxFramePayloadLength(maxFramePayloadLength).

Where Netty throws this

Actual Behavior

The WebSocket remains open, but the frames have been dropped leading to application level failure. (RSocket in my case)

Steps to Reproduce

I'm struggling to make a reproducer for this because it's dealing with aggregated frames. But keen to see if you have any thoughts here, or if this is something we may just have to handle at the application level.

We have been able to reproduce with some internal testing pages.
We configure max payload limits both on both aggregateFrames and WebSocketServerSpec. Compression is explicitly disabled.

    var specBuilder = WebsocketServerSpec.builder()
        .compress(false)
        .maxFramePayloadLength(5_000_000);
    ...
    return response.setComplete().then(Mono.defer(() -> reactorResponse.sendWebsocket((in, out) -> {
      var connection = (Connection) in.aggregateFrames(5_000_000);
      ....

With both configured, sending large messages doesn't cause the WebSocket connection to close.
image

The error eventually shows in our logs, and by that point the connection has been killed due to application level keep alives being missed. (~60 seconds later)

Possible Solution

Wondering if the exception from MessageAggregator needs to be explicitly handled somewhere, or if I'm incorrect in expecting this to cause a websocket close and instead we should look to handle this at application level.

Your Environment

reactor-netty: 1.1.17

  • JVM version (java -version): openjdk version "17.0.6" 2023-01-17 LTS
  • OS and version (eg. uname -a): Darwin Joebys-Laptop 23.4.0 Darwin Kernel Version 23.4.0: Fri Mar 15 00:10:42 PDT 2024; root:xnu-10063.101.17~1/RELEASE_ARM64_T6000 arm64
@joebyneil joebyneil added status/need-triage A new issue that still need to be evaluated as a whole type/bug A general bug labels Jun 12, 2024
@violetagg violetagg removed the status/need-triage A new issue that still need to be evaluated as a whole label Jun 13, 2024
@violetagg violetagg self-assigned this Jun 13, 2024
violetagg added a commit that referenced this issue Jun 13, 2024
@violetagg
[test] Test TooLongFrameException is propagated and connection closed
630b673 
Related to #3295
@violetagg violetagg mentioned this issue Jun 13, 2024
Merged
@violetagg
Copy link
Member

@joebyneil I tried to reproduce this behaviour but without success - see #3298

Also this log An exception has been observed post termination means that we cannot propagate the exception because the receiver is already canceled.

@violetagg violetagg added the for/user-attention This issue needs user attention (feedback, rework, etc...) label Jun 13, 2024
violetagg added a commit that referenced this issue Jun 13, 2024
@violetagg
[test] Test TooLongFrameException is propagated and connection closed (…
e042a58 
…#3298)

Related to #3295
@joebyneil
Copy link
Author

Thanks for the example! I'll play around with this more tomorrow and see if I can reproduce without RSocket also in the picture.

I've added some debug logs below in case they show anything obvious, but does seem that the server is still reading and writing from the connection after getting the error.

The main observation is that HttpServer is still reading, but each time just produces another log to say that it already got TooLongFrameException previously.

// Just finished receiving 2.5MB in 65565 byte chunks
2024-06-13 18:34:45,450:DEBUG FluxReceive : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] [terminated=true, cancelled=false, pending=0, error=io.netty.handler.codec.TooLongFrameException: content length exceeded 2000000 bytes.]: dropping frame BinaryWebSocketFrame(data: CompositeByteBuf(ridx: 0, widx: 1000020, cap: 1000020, components=14)) 
2024-06-13 18:34:45,450:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ COMPLETE 
2024-06-13 18:34:46,779:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 4 Type: REQUEST_RESPONSE Flags: 0b0 Length: 23
Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 41 3f 22 3a 22 42 22 2c 22 42 22 3a 22 22 |{"A?":"B","B":""|
|00000010| 7d                                              |}               |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:46,781:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] WRITE: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 17 00 00 00 04 10 00 7b 22 41 3f 22 3a 22 42 |........{"A?":"B|
|00000010| 22 2c 22 42 22 3a 22 22 7d                      |","B":""}       |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:46,782:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] FLUSH 
2024-06-13 18:34:46,787:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ: 14B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 88 95 7b 57 bb 95 7b 57 bf bd 1b 2c c6       |...{W..{W...,.  |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:46,787:DEBUG FluxReceive : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] [terminated=true, cancelled=false, pending=0, error=io.netty.handler.codec.TooLongFrameException: content length exceeded 2000000 bytes.]: dropping frame BinaryWebSocketFrame(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 8)) 
2024-06-13 18:34:46,787:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ COMPLETE 
2024-06-13 18:34:47,290:DEBUG debug : [HttpClient-1-SelectorManager] [102s 128ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:34:47,291:DEBUG debug : [HttpClient-1-SelectorManager] [102s 128ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:34:47,291:DEBUG debug : [HttpClient-1-SelectorManager] [102s 128ms] HttpClientImpl(1) Next deadline is 3000 
2024-06-13 18:34:49,281:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,282:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] WRITE: 16B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 0e 00 00 00 00 0c 80 00 00 00 00 00 00 00 00 |................|
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:49,283:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] FLUSH 
2024-06-13 18:34:49,285:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,285:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,287:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ: 20B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 8e ab 2b 00 3e ab 2b 00 3e a7 2b 00 3e ab 2b |...+.>.+.>.+.>.+|
|00000010| 00 3e ab 2b                                     |.>.+            |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:49,287:DEBUG FluxReceive : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] [terminated=true, cancelled=false, pending=0, error=io.netty.handler.codec.TooLongFrameException: content length exceeded 2000000 bytes.]: dropping frame BinaryWebSocketFrame(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 14, cap: 14)) 
2024-06-13 18:34:49,287:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ COMPLETE 
2024-06-13 18:34:49,288:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,288:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,288:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,288:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,289:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,289:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b10000000 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,299:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,300:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:49,300:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0 Length: 14
Data:
 
2024-06-13 18:34:50,028:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ: 20B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 8e 16 60 e5 0a 16 60 e5 0a 1a e0 e5 0a 16 60 |...`...`.......`|
|00000010| e5 0a 16 60                                     |...`            |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:50,028:DEBUG FluxReceive : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] [terminated=true, cancelled=false, pending=0, error=io.netty.handler.codec.TooLongFrameException: content length exceeded 2000000 bytes.]: dropping frame BinaryWebSocketFrame(data: PooledUnsafeDirectByteBuf(ridx: 0, widx: 14, cap: 14)) 
2024-06-13 18:34:50,028:DEBUG HttpServer : [05d6fe40-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52460] READ COMPLETE 
2024-06-13 18:34:50,293:DEBUG debug : [HttpClient-1-SelectorManager] [105s 130ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:34:50,293:DEBUG debug : [HttpClient-1-SelectorManager] [105s 130ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:34:50,293:DEBUG debug : [HttpClient-1-SelectorManager] [105s 130ms] HttpClientImpl(1) Next deadline is 3000 
2024-06-13 18:34:52,058:DEBUG FrameLogger : sending -> 
Frame => Stream ID: 12 Type: REQUEST_RESPONSE Flags: 0b0 Length: 23
Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 41 3f 22 3a 22 42 22 2c 22 42 22 3a 22 22 |{"A?":"B","B":""|
|00000010| 7d                                              |}               |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:52,060:DEBUG HttpServer : [39bb44fb-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52101] WRITE: 25B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 17 00 00 00 0c 10 00 7b 22 41 3f 22 3a 22 42 |........{"A?":"B|
|00000010| 22 2c 22 42 22 3a 22 22 7d                      |","B":""}       |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:52,060:DEBUG HttpServer : [39bb44fb-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52101] FLUSH 
2024-06-13 18:34:52,062:DEBUG HttpServer : [39bb44fb-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52101] READ: 14B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 88 fa e7 0e e1 fa e7 0e ed d2 87 75 9c       |............u.  |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:52,062:DEBUG FrameLogger : receiving -> 
Frame => Stream ID: 12 Type: NEXT_COMPLETE Flags: 0b1100000 Length: 8
Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 7d                                           |{}              |
+--------+-------------------------------------------------+----------------+ 
2024-06-13 18:34:52,063:DEBUG HttpServer : [39bb44fb-1, L:/[0:0:0:0:0:0:0:1]:8083 - R:/[0:0:0:0:0:0:0:1]:52101] READ COMPLETE 
2024-06-13 18:34:53,294:DEBUG debug : [HttpClient-1-SelectorManager] [108s 131ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:34:53,294:DEBUG debug : [HttpClient-1-SelectorManager] [108s 131ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:34:53,294:DEBUG debug : [HttpClient-1-SelectorManager] [108s 132ms] HttpClientImpl(1) Next deadline is 3000 
2024-06-13 18:34:56,296:DEBUG debug : [HttpClient-1-SelectorManager] [111s 133ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:34:56,296:DEBUG debug : [HttpClient-1-SelectorManager] [111s 134ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:34:56,296:DEBUG debug : [HttpClient-1-SelectorManager] [111s 134ms] HttpClientImpl(1) Next deadline is 3000 
2024-06-13 18:34:59,297:DEBUG debug : [HttpClient-1-SelectorManager] [114s 135ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:34:59,298:DEBUG debug : [HttpClient-1-SelectorManager] [114s 135ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:34:59,298:DEBUG debug : [HttpClient-1-SelectorManager] [114s 135ms] HttpClientImpl(1) Next deadline is 3000 
2024-06-13 18:35:02,298:DEBUG debug : [HttpClient-1-SelectorManager] [117s 135ms] HttpClientImpl(1) next timeout: 0 
2024-06-13 18:35:02,298:DEBUG debug : [HttpClient-1-SelectorManager] [117s 135ms] HttpClientImpl(1) next expired: 0 
2024-06-13 18:35:02,298:DEBUG debug : [HttpClient-1-SelectorManager] [117s 136ms] HttpClientImpl(1) Next deadline is 3000

@violetagg
Copy link
Member

May be something around this https://github.com/rsocket/rsocket-java/blob/6e5917909e26e89305123d9a457d75c369c7acc9/rsocket-transport-netty/src/main/java/io/rsocket/transport/netty/server/WebsocketServerTransport.java#L111-L125

@joebyneil
Copy link
Author

I'll close for now. I can see the FrameTooLargeException being passed through to RSocket, so seems like everything on reactor-netty side is working as expected. I'll keep looking and raise anything I find on the rsocket-java side.

Thanks for taking a look at this, it has been really helpful and I appreciate you taking the time.

@violetagg violetagg added status/invalid We don't feel this issue is valid and removed type/bug A general bug for/user-attention This issue needs user attention (feedback, rework, etc...) labels Jun 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@violetagg violetagg

Labels
status/invalid We don't feel this issue is valid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@violetagg @joebyneil