search

daniel-sc / rocketchat-modern-client

Client SDK for https://rocket.chat employing reactive style.
MIT License
11 stars 11 forks source link

The decoded text message was too big for the output buffer and the endpoint does not support partial messages #13

Closed tuxmartin closed 4 years ago

tuxmartin commented 4 years ago

My app using rocketchat-modern-client 0.1.0 is crashing approximately from 2.6.2020 with this error. In my app I do not change anything.

Jun 09 21:15:00 zabbix.example.net rocketchat-notificator[15221]: 2020-06-09 21:15:00 INFO  c.g.d.r.m.RocketChatClient:77 - connecting to wss://rc.example.net:443/websocket
Jun 09 21:15:00 zabbix.example.net rocketchat-notificator[15221]: 2020-06-09 21:15:00 WARN  c.g.d.r.m.RocketChatClient:261 - Unhandled message: {"msg":"added","collection":"users","id":"sxTFtgYegvMK8EJiX","fields":{"emails":[{"address":"servery@example.net","verified":true}],"username":"notificator"}}
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]: 2020-06-09 21:15:01 WARN  c.g.d.r.m.RocketChatClient:261 - Unhandled message: {"msg":"updated","methods":["6dd1b146-89ff-4620-9dc0-9c543c2aa07e"]}
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]: 2020-06-09 21:15:01 WARN  c.g.d.r.m.RocketChatClient:267 - connection closed: CloseReason: code [1009], reason [The decoded text message was too big for the output buffer and the endpoint does not support partial messages]
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]: java.util.concurrent.CompletionException: java.lang.RuntimeException: connection closed: CloseReason: code [1009], reason [The decoded text message was too big for the output buffer and the endpoint does not support partial messages]
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1019)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at com.github.daniel_sc.rocketchat.modern_client.RocketChatClient$WSClient.lambda$onClose$2(RocketChatClient.java:274)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at com.github.daniel_sc.rocketchat.modern_client.RocketChatClient$WSClient.onClose(RocketChatClient.java:270)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.pojo.PojoEndpointBase.onClose(PojoEndpointBase.java:103)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:555)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:501)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient.close(WsFrameClient.java:132)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient.resumeProcessing(WsFrameClient.java:221)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient.access$300(WsFrameClient.java:31)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.doResumeProcessing(WsFrameClient.java:186)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.completed(WsFrameClient.java:163)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.completed(WsFrameClient.java:148)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.AsyncChannelWrapperSecure$WrapperFuture.complete(AsyncChannelWrapperSecure.java:464)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at org.apache.tomcat.websocket.AsyncChannelWrapperSecure$ReadTask.run(AsyncChannelWrapperSecure.java:331)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]:         at java.base/java.lang.Thread.run(Thread.java:834)
Jun 09 21:15:01 zabbix.example.net rocketchat-notificator[15221]: Caused by: java.lang.RuntimeException: connection closed: CloseReason: code [1009], reason [The decoded text message was too big for the output buffer and the endpoint does not support partial messages]
tuxmartin commented 4 years ago

After update to git master (0.1.3) it crash on the same error.

At rocket.chat server log I see this error:

I20200609-21:31:51.753(2) Exception while invoking method 'sendMessage' Error: The 'rid' property on the message object is missing.     at executeSendMessage (app/lib/server/methods/sendMessage.js:66:9)     at MethodInvocation.sendMessage (app/lib/server/methods/sendMessage.js:104:10)     at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1771:12)     at DDP._CurrentMethodInvocation.withValue (packages/ddp-server/livedata_server.js:719:19)     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)     at DDPServer._CurrentWriteFence.withValue (packages/ddp-server/livedata_server.js:717:46)     at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1234:12)     at Promise (packages/ddp-server/livedata_server.js:715:46)     at new Promise (<anonymous>)     at Session.method (packages/ddp-server/livedata_server.js:689:23)     at packages/ddp-server/livedata_server.js:559:43
daniel-sc commented 4 years ago

Hi @tuxmartin do you have an example message/snippet that reproduces this?

tuxmartin commented 4 years ago

@daniel-sc It crash on:

private RocketChatClient client;
ChatMessage chatMessage = client.sendMessageExtendedParams(message, roomId, rcAlias, rcAvatar, rcEmoji, groupable, attachments).join();

Message has the same length as usual:

[virtual-web-monitoring-XXXX]: web test failed: XX-XX.cz (1)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 INFO  c.g.d.r.m.RocketChatClient:67 - connecting to wss://rc.example.eu:443/websocket
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:224 - created WSClient
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:70 - created session: org.apache.tomcat.websocket.WsSession@6f0c9e35
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"server_id":"0"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:233 - sending connect
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:235 - connect ack: true
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"connected","session":"pHzwRJ3evmFTy2PCn"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:114 - REQUEST: {"method":"login","msg":"method","params":[{"user":{"username":"notificator"},"password":{"digest":"82a00e62b51bddbf8xxxxxxxxxxxxxxxx5d612f7c3ba6152a0fd422064ba3241","algorithm":"sha-256"}}],"id":"99f98db0-af08-495c-98f6-480ca62fff5e"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"added","collection":"users","id":"sxTFtgYegvMK8EJiX","fields":{"emails":[{"address":"servery@example.eu","verified":true}],"username":"notificator"}}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 WARN  c.g.d.r.m.RocketChatClient:251 - Unhandled message: {"msg":"added","collection":"users","id":"sxTFtgYegvMK8EJiX","fields":{"emails":[{"address":"servery@example.eu","verified":true}],"username":"notificator"}}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"result","id":"99f98db0-af08-495c-98f6-480ca62fff5e","result":{"id":"sxTFtgYegvMK8EJiX","token":"jux0Jt8Lk93pyDfw3xi5hcFE2v5CB-behSIrA_n_qUM","tokenExpires":{"$date":1599515662302},"type":"password"}}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:114 - REQUEST: {"method":"sendMessage","msg":"method","params":[{"msg":"**Cron Daemon \u003croot@passwd.example.eu\u003e** _76975_","rid":"","_id":"122d5865-7320-44c5-b0cb-fd148b265ef3","alias":"Email notifikator: servery@servery.example.eu","emoji":":e-mail:","groupable":false,"attachments":[{"color":"#0000FF","text":"Closing open files: rsyslogd.\nClosing open files: rsyslogd....","ts":"2020-06-09T21:54:22.003514Z","collapsed":false,"title":"Cron \u003croot@passwd\u003e /usr/lib/armbian/armbian-truncate-logs","title_link_download":true}]}],"id":"e25105cf-5496-4dde-8f21-c67e3e80b44d"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"updated","methods":["e25105cf-5496-4dde-8f21-c67e3e80b44d"]}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 WARN  c.g.d.r.m.RocketChatClient:251 - Unhandled message: {"msg":"updated","methods":["e25105cf-5496-4dde-8f21-c67e3e80b44d"]}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"result","id":"e25105cf-5496-4dde-8f21-c67e3e80b44d","error":{"isClientSafe":true,"error":500,"reason":"Internal server error","message":"Internal server error [500]","errorType":"Meteor.Error"}}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: 2020-06-09 23:54:22 ERROR e.v.r.service.RocketChat:109 - Exception in RocketChat.java:sendMsg()
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: java.util.concurrent.CompletionException: java.lang.RuntimeException: Send message failed: {"isClientSafe":true,"error":500.0,"reason":"Internal server error","message":"Internal server error [500]","errorType":"Meteor.Error"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1019)2020-06-09 23:54:22 DEBUG c.g.d.r.m.RocketChatClient:230 - Received msg: {"msg":"updated","methods":["99f98db0-af08-495c-98f6-480ca62fff5e"]}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at com.github.daniel_sc.rocketchat.modern_client.CompletableFutureWithMapper.completeAndMap(CompletableFutureWithMapper.java:24)2020-06-09 23:54:22 WARN  c.g.d.r.m.RocketChatClient:251 - Unhandled message: {"msg":"updated","methods":["99f98db0-af08-495c-98f6-480ca62fff5e"]}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at com.github.daniel_sc.rocketchat.modern_client.RocketChatClient$WSClient.onMessage(RocketChatClient.java:242)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at jdk.internal.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.pojo.PojoMessageHandlerWholeBase.onMessage(PojoMessageHandlerWholeBase.java:80)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameBase.sendMessageText(WsFrameBase.java:395)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameBase.processDataText(WsFrameBase.java:495)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:294)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:133)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient.processSocketRead(WsFrameClient.java:95)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient.resumeProcessing(WsFrameClient.java:209)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient.access$300(WsFrameClient.java:31)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.doResumeProcessing(WsFrameClient.java:186)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.completed(WsFrameClient.java:163)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.WsFrameClient$WsFrameClientCompletionHandler.completed(WsFrameClient.java:148)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.AsyncChannelWrapperSecure$WrapperFuture.complete(AsyncChannelWrapperSecure.java:464)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at org.apache.tomcat.websocket.AsyncChannelWrapperSecure$ReadTask.run(AsyncChannelWrapperSecure.java:331)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at java.base/java.lang.Thread.run(Thread.java:834)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]: Caused by: java.lang.RuntimeException: Send message failed: {"isClientSafe":true,"error":500.0,"reason":"Internal server error","message":"Internal server error [500]","errorType":"Meteor.Error"}
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at com.github.daniel_sc.rocketchat.modern_client.RocketChatClient.lambda$failOnError$11(RocketChatClient.java:151)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         at com.github.daniel_sc.rocketchat.modern_client.CompletableFutureWithMapper.completeAndMap(CompletableFutureWithMapper.java:22)
Jun 09 23:54:22 zabbix.example.eu rocketchat-notificator[31902]:         ... 20 more

I'm using Rocket.Chat server 2.4.11.

daniel-sc commented 4 years ago

Hi @tuxmartin , I could not reproduce this - can you reproduce this with the public server (wss://open.rocket.chat:443/websocket)? Could you share an integration test reproducing this?

daniel-sc commented 4 years ago

This should be resolved with v1.0.2