Debug reports nothing when a large message is rejected

[richiejarvis]

Hi Team,

I was testing some ruby large message issues, and was surprised that a message that is too large doesn't output any errors or debug information to say why the message was rejected. Tested using https://github.com/ably/ably-ruby/releases/tag/v1.2.3

Terminal output:

ruby publish-subscribe-massive-message.rb 
Run this script in multiple consoles concurrently.
Each script will simultaneously receive the published message as all clients are subscribed to the "sport" channel.
14:57:29.243 DEBUG [ -- ] Ably::Realtime::Channel: Transitioned to attaching
14:57:29.243 DEBUG [ -- ] Ably::Realtime::Channel: StateEmitter changed from STATE.Initialized => attaching
14:57:29.243 DEBUG [ -- ] Connection: Prot msg queued =>: ACTION.Attach {"action":10,"channel":"sport"}
Press <enter> to publish a message. Use <ctrl>-c to stop.
14:57:29.243 DEBUG [ -- ] Ably::Realtime::Connection: Transitioned to connecting
14:57:29.243 DEBUG [ -- ] Ably::Realtime::Connection: StateEmitter changed from STATE.Initialized => connecting
14:57:29.243 DEBUG [ -- ] ConnectionManager: Opening a websocket transport connection
14:57:29.245 DEBUG [ -- ] ConnectionManager: Setting up automatic connection timeout timer for 10s
14:57:29.250 DEBUG [ -- ] Connection: Opening socket connection to realtime.ably.io:443/?key=API-KEY&format=msgpack&echo=true&v=1.2&agent=ably-ruby%2F1.2.3+ruby%2F3.0.2&heartbeats=false
14:57:29.250 DEBUG [ -- ] Connection: EventMachine connecting to realtime.ably.io:443 with URL: wss://realtime.ably.io:443?key=MyKey&format=msgpack&echo=true&v=1.2&agent=ably-ruby%2F1.2.3+ruby%2F3.0.2&heartbeats=false
14:57:29.324 DEBUG [ -- ] Ably::Realtime::Connection::WebsocketTransport: StateEmitter changed from STATE.Initialized => STATE.Connecting
14:57:29.412 DEBUG [ -- ] Ably::Realtime::Connection::WebsocketTransport: StateEmitter changed from STATE.Connecting => STATE.Connected
14:57:29.654 DEBUG [ -- ] WebsocketTransport: socket opened to wss://realtime.ably.io:443?key=MyKey&format=msgpack&echo=true&v=1.2&agent=ably-ruby%2F1.2.3+ruby%2F3.0.2&heartbeats=false, waiting for Connected protocol message
14:57:29.656 DEBUG [ -- ] WebsocketTransport: Prot msg recv <=: ACTION.Connected - {"action"=>4, "connectionId"=>"F6PqMg5joP", "connectionKey"=>"108IH1R_ABGZFh!F6PqMg5joPBqxWp3-cb5d7", "connectionSerial"=>-1, "connectionDetails"=>{"clientId"=>"*", "connectionKey"=>"108IH1R_ABGZFh!F6PqMg5joPBqxWp3-cb5d7", "maxMessageSize"=>128000, "maxInboundRate"=>100, "maxOutboundRate"=>100, "maxFrameSize"=>262144, "serverId"=>"frontend.8eeb.3.eu-west-1-A.i-0455ce25e4729c198.108IH1R_ABGZFh", "connectionStateTtl"=>120000, "maxIdleInterval"=>15000}}
14:57:29.657 DEBUG [ -- ] ACTION.Connected received: {"action":4,"connectionId":"F6PqMg5joP","connectionKey":"108IH1R_ABGZFh!F6PqMg5joPBqxWp3-cb5d7","connectionSerial":-1,"connectionDetails":{"clientId":"*","connectionKey":"108IH1R_ABGZFh!F6PqMg5joPBqxWp3-cb5d7","maxMessageSize":128000,"maxInboundRate":100,"maxOutboundRate":100,"maxFrameSize":262144,"serverId":"frontend.8eeb.3.eu-west-1-A.i-0455ce25e4729c198.108IH1R_ABGZFh","connectionStateTtl":120000,"maxIdleInterval":15000}}
14:57:29.657 DEBUG [ -- ] ConnectionManager: New connection created with ID F6PqMg5joP and key 108IH1R_ABGZFh!F6PqMg5joPBqxWp3-cb5d7
14:57:29.658 DEBUG [F6PqMg5joP] Ably::Realtime::Connection: Transitioned from connecting => connected
14:57:29.658 DEBUG [F6PqMg5joP] Ably::Realtime::Connection: StateEmitter changed from STATE.Connecting => connected
14:57:29.667 DEBUG [F6PqMg5joP] WebsocketTransport: Prot msg sent =>: ACTION.Attach {"action":10,"channel":"sport"}
14:57:30.093 DEBUG [F6PqMg5joP] WebsocketTransport: Prot msg recv <=: ACTION.Attached - {"action"=>11, "flags"=>983041, "channel"=>"sport", "channelSerial"=>"108WFPtxABGbHq91806047:-1"}
14:57:30.095 DEBUG [F6PqMg5joP] ACTION.Attached received: {"action":11,"flags":983041,"channel":"sport","channelSerial":"108WFPtxABGbHq91806047:-1"}
14:57:30.095 DEBUG [F6PqMg5joP] Ably::Realtime::Presence::MembersMap: StateEmitter changed from STATE.Initialized => sync_starting
14:57:30.096 DEBUG [F6PqMg5joP] Ably::Realtime::Channel: Transitioned from attaching => attached
14:57:30.096 DEBUG [F6PqMg5joP] Ably::Realtime::Channel: StateEmitter changed from STATE.Attaching => attached
14:57:30.327 DEBUG [F6PqMg5joP] WebsocketTransport: Prot msg recv <=: ACTION.Sync - {"action"=>16, "channel"=>"sport", "channelSerial"=>"108IH1R_ABGZFh05097427:", "presence"=>[]}
14:57:30.328 DEBUG [F6PqMg5joP] ACTION.Sync received: {"action":16,"channel":"sport","channelSerial":"108IH1R_ABGZFh05097427:","presence":[]}
14:57:30.328 DEBUG [F6PqMg5joP] Ably::Realtime::Presence::MembersMap: StateEmitter changed from STATE.SyncStarting => finalizing_sync
14:57:30.328 DEBUG [F6PqMg5joP] Ably::Realtime::Presence::MembersMap: StateEmitter changed from STATE.FinalizingSync => in_sync



14:57:44.653 DEBUG [F6PqMg5joP] ACTION.Heartbeat received: {"action":0,"source":"websocket"}
14:57:59.647 DEBUG [F6PqMg5joP] ACTION.Heartbeat received: {"action":0,"source":"websocket"}
14:58:14.646 DEBUG [F6PqMg5joP] ACTION.Heartbeat received: {"action":0,"source":"websocket"}

Code used attached. publish-subscribe-massive-message.rb.zip

┆Issue is synchronized with this Jira Task by Unito