Sender appears to be ignoring max_frame_size

[TezzM0]

Hi there,

I'm experiencing a problem where messages that are larger than the max_frame_size are not sent and an error is thrown.

My expectation (which may be incorrect) is that the sender should send chunks of the message buffer, each of which is smaller than the max_frame_size, until the whole message is sent.

I am using Amazon MQ (ActiveMQ) which is sending back a max_frame_size of 131072. My message appears to be size 160228 (not sure what unit this is in, I assume bytes?). I can see the message being sent, and then I get a reply that the "specified frame size 160228 greater than maximum valid frame size 131072".

I have also tried setting the max_frame_size explicitly higher and lower, but it doesn't seem to have any effect.

Any help would be most appreciated!

Logs:

  rhea:message Encoding section 1 of 4: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: [Function (anonymous)] { typecode: 208 } }, value: [ Typed { type: [TypeDesc], value: null } ], descriptor: Typed { type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Function] }, value: 112 } } +0ms
  rhea:message Encoding section 2 of 4: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: [Function (anonymous)] { typecode: 208 } }, value: [ <2 empty items>, Typed { type: [TypeDesc], value: null }, <3 empty items>, Typed { type: [TypeDesc], value: 'text/plain' }, <2 empty items>, Typed { type: [TypeDesc], value: 1695348259630 } ], descriptor: Typed { type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Function] }, value: 115 } } +9ms
  rhea:message Encoding section 3 of 4: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: [Function (anonymous)] { typecode: 209 } }, value: [ Typed { type: [TypeDesc], value: 'content-type' }, Typed { type: [TypeDesc], value: 'text/plain' }, Typed { type: [TypeDesc], value: 'content-length' }, Typed { type: [TypeDesc], value: 160079 } ], descriptor: Typed { type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Function] }, value: 116 } } +1ms
  rhea:message Encoding section 4 of 4: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: [Function (anonymous)] { typecode: 176 } }, value: <Buffer 7b 22 6c 69 66 65 74 69 6d 65 22 3a 7b 22 67 61 6d 65 70 61 64 22 3a 7b 22 33 33 22 3a 7b 22 70 6c 61 79 65 72 73 6f 75 74 6c 69 76 65 64 22 3a 32 36 ... 160029 more bytes>, descriptor: Typed { type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Function] }, value: 117 } } +1ms
  rhea:message encoded 160200 bytes +0ms
  rhea:flow [connection-1] Link has no credit +0ms
  rhea:io [connection-1] connected 20.3.0.130:50649 -> 10.101.114.14:5671 +0ms
  rhea:frames [connection-1] -> { protocol_id: 3, major: 1, minor: 0, revision: 0 } +0ms
  rhea:io [connection-1] read 42 bytes +747ms
  rhea:frames [connection-1] <- { protocol_id: 3, major: 1, minor: 0, revision: 0 } +747ms
  rhea:io [connection-1] got frame of size 34 +3ms
  rhea:raw [connection-1] RECV: 34 0000002202010000005340c01501e01202a305504c41494e09414e4f4e594d4f5553 +0ms
  rhea:frames [connection-1]:0 <- sasl_mechanisms#40 {"sasl_server_mechanisms":["PLAIN","ANONYMOUS"]}  +5ms
  rhea:frames [connection-1]:0 -> sasl_init#41 {"mechanism":"PLAIN","initial_response":{"type":"Buffer","data":[0,97,109,113,97,100,109,105,110,0,88,87,107,33,100,117,65,84,111,65,110,98,90,51,101,72]},"hostname":"*************************"}  +1ms  rhea:raw [connection-1] SENT: 124 0000007c02010000005341d00000006c00000003a305504c41494ea01a00616d7161646d696e0058576b21647541546f416e625a336548a143622d37363134626635342d316239642d346235362d393265342d3934303732303938613335652d312e6d712e75732d656173742d312e616d617a6f6e6177732e636f6d +8ms
  rhea:io [connection-1] read 16 bytes +349ms
  rhea:io [connection-1] got frame of size 16 +1ms
  rhea:raw [connection-1] RECV: 16 0000001002010000005344c003015000 +342ms
  rhea:frames [connection-1]:0 <- sasl_outcome#44 {}  +347ms
  rhea:frames [connection-1] -> { protocol_id: 0, major: 1, minor: 0, revision: 0 } +1ms
  rhea:frames [connection-1]:0 -> open#10 {"container_id":"QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199","max_frame_size":1000}  +1ms  // NOTE - Explicit setting of max_frame_size
  rhea:raw [connection-1] SENT: 121 0000007902000000005310d00000006900000003a15d51756575654d616e616765722d3864 ////// .... Truncated data...
  rhea:frames [connection-1]:0 -> begin#11 {"incoming_window":2048,"outgoing_window":4294967295}  +3ms
  rhea:raw [connection-1] SENT: 32 0000002002000000005311d000000010000000044043700000080070ffffffff +2ms
  rhea:frames [connection-1]:0 -> attach#12 {"name":"b6f9bed8-0e93-a44c-8fd3-c052e3de186c","source":[],"target":["***********"]}  +1ms
  rhea:raw [connection-1] SENT: 110 0000006e02000000005312d00000005e0000000aa12462366639626564382d306539332d61343 ///// .... Truncated data...
  rhea:io [connection-1] read 8 bytes +352ms
  rhea:frames [connection-1] <- { protocol_id: 0, major: 1, minor: 0, revision: 0 } +345ms
  rhea:io [connection-1] read 195 bytes +349ms
  rhea:io [connection-1] got frame of size 195 +1ms
  rhea:raw [connection-1] RECV: 195 000000c3020000000053 ///// ... Truncated data...
  rhea:frames [connection-1]:0 <- open#10 {"container_id":"*******","max_frame_size":131072,"channel_max":32767,"idle_time_out":15000,"offered_capabilities":["ANONYMOUS-RELAY","DELAYED_DELIVERY"],"properties":{"product":"ActiveMQ","topic-prefix":"topic://","queue-prefix":"queue://","version":"5.15.15","platform":"Java/1.8.0_382"}}  +351ms
  rhea:events [connection-1] Connection got event: connection_open +0ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: connection_open +2ms
  rhea:io [connection-1] read 34 bytes +392ms
  rhea:io [connection-1] got frame of size 34 +0ms
  rhea:raw [connection-1] RECV: 34 0000002202000000005311c0150560000052017000003fff707fffffff700000ffff +394ms
  rhea:frames [connection-1]:0 <- begin#11 {"next_outgoing_id":1,"incoming_window":16383,"outgoing_window":2147483647,"handle_max":65535}  +394ms
  rhea:events [connection-1] Session got event: session_open +391ms
  rhea:events [connection-1] Connection got event: session_open +1ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: session_open +0ms
  rhea:io [connection-1] read 131 bytes +5ms
  rhea:io [connection-1] got frame of size 97 +1ms
  rhea:raw [connection-1] RECV: 97 00000061020000 // .... Truncated data ...
  rhea:frames [connection-1]:0 <- attach#12 {"name":"b6f9bed8-0e93-a44c-8fd3-c052e3de186c","role":true,"snd_settle_mode":2,"source":[],"target":["***********"]}  +5ms
  rhea:events [connection-1] Link got event: sender_open +4ms
  rhea:events [connection-1] Session got event: sender_open +1ms
  rhea:events [connection-1] Connection got event: sender_open +1ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: sender_open +0ms
  rhea:io [connection-1] got frame of size 34 +5ms
  rhea:raw [connection-1] RECV: 34 0000002202000000005313c01507437000003fff5201707fffffff434370000003e8 +4ms
  rhea:frames [connection-1]:0 <- flow#13 {"incoming_window":16383,"next_outgoing_id":1,"outgoing_window":2147483647,"link_credit":1000}  +3ms
  rhea:events [connection-1] Link got event: sender_flow +2ms
  rhea:events [connection-1] Session got event: sender_flow +0ms
  rhea:events [connection-1] Connection got event: sender_flow +2ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: sender_flow +0ms
  rhea:events [connection-1] Link got event: sendable +1ms
  rhea:events [connection-1] Session got event: sendable +0ms
  rhea:events [connection-1] Connection got event: sendable +0ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: sendable +0ms
  rhea:frames [connection-1]:0 -> transfer#14 {"delivery_tag":{"type":"Buffer","data":[48]}} <Buffer 00 53 70 d0 00 00 00 05 00 00 00 01 40 00 53 73 d0 00 00 00 21 00 00 00 0a 40 40 40 40 40 40 a3 0a 74 65 78 74 2f 70 6c 61 69 6e 40 40 83 00 00 01 8a ... 160150 more bytes> +6ms
  rhea:raw [connection-1] SENT: 160228 000271e4020000 ///// ... Truncated a heap of data ...
  rhea:io [connection-1] read 175 bytes +4s
  rhea:io [connection-1] got frame of size 175 +10ms
  rhea:raw [connection-1] RECV: 175 000000a ///// .... Truncated data ...
  rhea:frames [connection-1]:0 <- close#18 {"error":{"condition":"amqp:connection:framing-error","description":"org.apache.qpid.proton.engine.TransportException: specified frame size 160228 greater than maximum valid frame size 131072"}}  +4s
  rhea:events [connection-1] Connection got event: connection_error +4s
  rhea:events [connection-1] Connection got event: connection_close +3ms
  rhea:events [QueueManager-8da191cd-a6dc-d342-852c-a9f05fe01e76-Sender-4cd6ae29-3206-a745-ab6f-2592a2913199] Container got event: connection_close +1ms
  rhea:frames [connection-1]:0 -> detach#16 {"closed":true}  +4ms
  rhea:raw [connection-1] SENT: 22 0000001602000000005316d000000006000000024341 +5ms
  rhea:frames [connection-1]:0 -> close#18 {}  +1ms
  rhea:raw [connection-1] SENT: 12 0000000c0200000000531845 +1ms
failed Error: Sender connection error

[grs]

Are you waiting for the connection to be opened before sending?

[TezzM0]

Thanks so much for the help @grs - this appears to have been the problem.

I previously had:

// snip - set up connection
connection.connect();
sender.open();
sender.send(message);

Which appears to work somewhat - the message is sent successfully, as long as it doesn't exceed max_frame_size of the server.

I've now changed it to:

// snip - set up connection
connection.connect();
sender.open();
sender.once('sendable', () => {
    sender.send(message);
});

Now it picks up the max_frame_size from the server side and splits the large message up correctly.

All that being said - I think there is a problem here. Shouldn't I be able to set the max_frame_size on the connection myself?

This test case fails for me:

const container = require('rhea');

describe('Connection Options', () => {
  it('should set max_frame_size', () => {
    let connection;
    try {
      connection = container.connect({ host: '127.0.0.1', port: 5672, max_frame_size: 1000 });
      expect(connection.max_frame_size).toBe(1000);
    } finally {
      if (connection) {
        connection.close();
      }
    }
  });
});

I feel like if I'm not supposed to set max_frame_size on the client side, then it shouldn't be an option in the library, and if I'm allowed to set it then it should be honoured.

Again, I really appreciate the help!

[grs]

Each side sets its max-frame-size independently. So if you set it on your connection, that is the max frame size that the broker is allowed to send to you. You cannot alter the max-frame-size the broker will accept by setting the value on your side of the connection. (If that is something that can be configured it would be configured on the broker side)

[TezzM0]

Ah that makes sense. Thanks again!

Perhaps it could be named something like max_receive_frame_size, or have a comment indicating this.