SMALL
Thingsboard MQTT로 단말이 서버로 Data 전송 중에 세션이 끊기는 현상이 주기적으로 발생하여 원인 분석을 진행하였다.
Thingsboard 로그 상의 단말 Entinity ID Device ID로 검색을 했다.
Exception 부분 부터 해당 내용을 Rule chain 따라 가며 분석을 진행했다.
익셉션 내용의 malformed JSON 단어의 뜻으로 대략적인 문제의 원인을 유추할 수 있다.
malformed 단어의 뜻
기형인
흉하게 일그러진
형태가 정상이 아닌
유의어로는 deformed, distorted, crooked 등이 있다.
MalformedJsonException 발생 단계 확인
문제원인 Summary
Failed to process publish msg [v1/devices/me/telemetry][4]
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
Closing current session due to invalid publish msg [v1/devices/me/telemetry][4]
Client disconnected!
sessionType: ASYNC
event: CLOSED
이하 로그의 Data 상세 내용 보시면 아스키 코드 34, 까지는 문자 변환되나 마지막 125 추가되어 있습니다.
마지막 문자로 인해 invalid publish msg 발생하며 session closed 이벤트 보냅니다.
아스키 코드 변환 사이트 : https://ko.rakko.tools/tools/76/
원인 분석을 위한 Thingsboard 로그
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: RuleNodeToRuleChainTellNextMsg(ruleChainId=b71bbf90-d1a9-11ec-b067-a1db09533645, originator=4e883e80-d1aa-11ec-b067-a1db09533645, relationTypes=[Success], failureMessage=null)
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.server.actors.TbActorMailbox - [RULE_NODE|4e88b3b0-d1aa-11ec-b067-a1db09533645] Going to process message: RuleChainToRuleNodeMsg(fromRelationType=Success)
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: RuleChainToRuleNodeMsg(fromRelationType=Success)
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.actors.ruleChain.RuleNodeActor - [b71bbf90-d1a9-11ec-b067-a1db09533645][4e88b3b0-d1aa-11ec-b067-a1db09533645][ss_attributes] Going to process rule engine msg: TbMsg(queueName=Main, id=68498fa2-2ea1-4a8f-a900-58092fd2bfe9, ts=1657105543251, type=POST_ATTRIBUTES_REQUEST, originator=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, customerId=d60cb270-7753-11ec-b3eb-e75d6a1d56fa, metaData=TbMsgMetaData(data={deviceType=AMT600D, deviceName=0695075, notifyDevice=false}), dataType=JSON, data={"tb_period":3,"inactivityTimeout":13000}, ruleChainId=b71bbf90-d1a9-11ec-b067-a1db09533645, ruleNodeId=4e87c950-d1aa-11ec-b067-a1db09533645, ctx=org.thingsboard.server.common.msg.TbMsgProcessingCtx@6c93fd6d, callback=org.thingsboard.server.service.queue.TbMsgPackCallback@7f2fdd57)
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.dao.sql.event.JpaBaseEventDao - Save event [Event(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, type=DEBUG_RULE_NODE, uid=null, entityId=4e88b3b0-d1aa-11ec-b067-a1db09533645, body={"type":"IN","server":"ip-10-0-20-80","entityId":"788d7e50-8b0c-11ec-9071-6fe3b4d1f91b","entityName":"DEVICE","msgId":"68498fa2-2ea1-4a8f-a900-58092fd2bfe9","msgType":"POST_ATTRIBUTES_REQUEST","dataType":"JSON","relationType":"Success","data":"{\"tb_period\":3,\"inactivityTimeout\":13000}","metadata":"{\"deviceType\":\"AMT600D\",\"deviceName\":\"0695075\",\"notifyDevice\":\"false\"}"}, bodyBytes=[123, 34, 116, 121, 112, 101, 34, 58, 34, 73, 78, 34, 44, 34, 115, 101, 114, 118, 101, 114, 34, 58, 34, 105, 112, 45, 49, 48, 45, 48, 45, 50, 48, 45, 56, 48, 34, 44, 34, 101, 110, 116, 105, 116, 121, 73, 100, 34, 58, 34, 55, 56, 56, 100, 55, 101, 53, 48, 45, 56, 98, 48, 99, 45, 49, 49, 101, 99, 45, 57, 48, 55, 49, 45, 54, 102, 101, 51, 98, 52, 100, 49, 102, 57, 49, 98, 34, 44, 34, 101, 110, 116, 105, 116, 121, 78, 97, 109, 101, 34, 58, 34, 68, 69, 86, 73, 67, 69, 34, 44, 34, 109, 115, 103, 73, 100, 34, 58, 34, 54, 56, 52, 57, 56, 102, 97, 50, 45, 50, 101, 97, 49, 45, 52, 97, 56, 102, 45, 97, 57, 48, 48, 45, 53, 56, 48, 57, 50, 102, 100, 50, 98, 102, 101, 57, 34, 44, 34, 109, 115, 103, 84, 121, 112, 101, 34, 58, 34, 80, 79, 83, 84, 95, 65, 84, 84, 82, 73, 66, 85, 84, 69, 83, 95, 82, 69, 81, 85, 69, 83, 84, 34, 44, 34, 100, 97, 116, 97, 84, 121, 112, 101, 34, 58, 34, 74, 83, 79, 78, 34, 44, 34, 114, 101, 108, 97, 116, 105, 111, 110, 84, 121, 112, 101, 34, 58, 34, 83, 117, 99, 99, 101, 115, 115, 34, 44, 34, 100, 97, 116, 97, 34, 58, 34, 123, 92, 34, 116, 98, 95, 112, 101, 114, 105, 111, 100, 92, 34, 58, 51, 44, 92, 34, 105, 110, 97, 99, 116, 105, 118, 105, 116, 121, 84, 105, 109, 101, 111, 117, 116, 92, 34, 58, 49, 51, 48, 48, 48, 125, 34, 44, 34, 109, 101, 116, 97, 100, 97, 116, 97, 34, 58, 34, 123, 92, 34, 100, 101, 118, 105, 99, 101, 84, 121, 112, 101, 92, 34, 58, 92, 34, 65, 77, 84, 54, 48, 48, 68, 92, 34, 44, 92, 34, 100, 101, 118, 105, 99, 101, 78, 97, 109, 101, 92, 34, 58, 92, 34, 48, 54, 57, 53, 48, 55, 53, 92, 34, 44, 92, 34, 110, 111, 116, 105, 102, 121, 68, 101, 118, 105, 99, 101, 92, 34, 58, 92, 34, 102, 97, 108, 115, 101, 92, 34, 125, 34, 125])]
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.dao.sql.event.JpaBaseEventDao - Save event [EventEntity(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, entityType=RULE_NODE, entityId=4e88b3b0-d1aa-11ec-b067-a1db09533645, eventType=DEBUG_RULE_NODE, eventUid=9420e1d1-fd1b-11ec-b01f-13d52824bbe7, body={"type":"IN","server":"ip-10-0-20-80","entityId":"788d7e50-8b0c-11ec-9071-6fe3b4d1f91b","entityName":"DEVICE","msgId":"68498fa2-2ea1-4a8f-a900-58092fd2bfe9","msgType":"POST_ATTRIBUTES_REQUEST","dataType":"JSON","relationType":"Success","data":"{\"tb_period\":3,\"inactivityTimeout\":13000}","metadata":"{\"deviceType\":\"AMT600D\",\"deviceName\":\"0695075\",\"notifyDevice\":\"false\"}"}, ts=1657105543277)]
2022-07-06 20:05:43,277 [DbCallbackExecutorService-50-2] DEBUG o.t.s.dao.sql.event.JpaBaseEventDao - Save event [Event(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, type=DEBUG_RULE_NODE, uid=null, entityId=4e88b3b0-d1aa-11ec-b067-a1db09533645, body={"type":"OUT","server":"ip-10-0-20-80","entityId":"788d7e50-8b0c-11ec-9071-6fe3b4d1f91b","entityName":"DEVICE","msgId":"68498fa2-2ea1-4a8f-a900-58092fd2bfe9","msgType":"POST_ATTRIBUTES_REQUEST","dataType":"JSON","relationType":"Failure","data":"{\"tb_period\":3,\"inactivityTimeout\":13000}","metadata":"{\"deviceType\":\"AMT600D\",\"deviceName\":\"0695075\",\"notifyDevice\":\"false\"}"}, bodyBytes=[123, 34, 116, 121, 112, 101, 34, 58, 34, 79, 85, 84, 34, 44, 34, 115, 101, 114, 118, 101, 114, 34, 58, 34, 105, 112, 45, 49, 48, 45, 48, 45, 50, 48, 45, 56, 48, 34, 44, 34, 101, 110, 116, 105, 116, 121, 73, 100, 34, 58, 34, 55, 56, 56, 100, 55, 101, 53, 48, 45, 56, 98, 48, 99, 45, 49, 49, 101, 99, 45, 57, 48, 55, 49, 45, 54, 102, 101, 51, 98, 52, 100, 49, 102, 57, 49, 98, 34, 44, 34, 101, 110, 116, 105, 116, 121, 78, 97, 109, 101, 34, 58, 34, 68, 69, 86, 73, 67, 69, 34, 44, 34, 109, 115, 103, 73, 100, 34, 58, 34, 54, 56, 52, 57, 56, 102, 97, 50, 45, 50, 101, 97, 49, 45, 52, 97, 56, 102, 45, 97, 57, 48, 48, 45, 53, 56, 48, 57, 50, 102, 100, 50, 98, 102, 101, 57, 34, 44, 34, 109, 115, 103, 84, 121, 112, 101, 34, 58, 34, 80, 79, 83, 84, 95, 65, 84, 84, 82, 73, 66, 85, 84, 69, 83, 95, 82, 69, 81, 85, 69, 83, 84, 34, 44, 34, 100, 97, 116, 97, 84, 121, 112, 101, 34, 58, 34, 74, 83, 79, 78, 34, 44, 34, 114, 101, 108, 97, 116, 105, 111, 110, 84, 121, 112, 101, 34, 58, 34, 70, 97, 105, 108, 117, 114, 101, 34, 44, 34, 100, 97, 116, 97, 34, 58, 34, 123, 92, 34, 116, 98, 95, 112, 101, 114, 105, 111, 100, 92, 34, 58, 51, 44, 92, 34, 105, 110, 97, 99, 116, 105, 118, 105, 116, 121, 84, 105, 109, 101, 111, 117, 116, 92, 34, 58, 49, 51, 48, 48, 48, 125, 34, 44, 34, 109, 101, 116, 97, 100, 97, 116, 97, 34, 58, 34, 123, 92, 34, 100, 101, 118, 105, 99, 101, 84, 121, 112, 101, 92, 34, 58, 92, 34, 65, 77, 84, 54, 48, 48, 68, 92, 34, 44, 92, 34, 100, 101, 118, 105, 99, 101, 78, 97, 109, 101, 92, 34, 58, 92, 34, 48, 54, 57, 53, 48, 55, 53, 92, 34, 44, 92, 34, 110, 111, 116, 105, 102, 121, 68, 101, 118, 105, 99, 101, 92, 34, 58, 92, 34, 102, 97, 108, 115, 101, 92, 34, 125, 34, 125])]
2022-07-06 20:05:43,277 [DbCallbackExecutorService-50-2] DEBUG o.t.s.dao.sql.event.JpaBaseEventDao - Save event [EventEntity(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, entityType=RULE_NODE, entityId=4e88b3b0-d1aa-11ec-b067-a1db09533645, eventType=DEBUG_RULE_NODE, eventUid=9420e1d2-fd1b-11ec-b01f-13d52824bbe7, body={"type":"OUT","server":"ip-10-0-20-80","entityId":"788d7e50-8b0c-11ec-9071-6fe3b4d1f91b","entityName":"DEVICE","msgId":"68498fa2-2ea1-4a8f-a900-58092fd2bfe9","msgType":"POST_ATTRIBUTES_REQUEST","dataType":"JSON","relationType":"Failure","data":"{\"tb_period\":3,\"inactivityTimeout\":13000}","metadata":"{\"deviceType\":\"AMT600D\",\"deviceName\":\"0695075\",\"notifyDevice\":\"false\"}"}, ts=1657105543277)]
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.server.actors.TbActorMailbox - [RULE_CHAIN|b71bbf90-d1a9-11ec-b067-a1db09533645] Going to process message: RuleNodeToRuleChainTellNextMsg(ruleChainId=b71bbf90-d1a9-11ec-b067-a1db09533645, originator=4e88b3b0-d1aa-11ec-b067-a1db09533645, relationTypes=[Failure], failureMessage=null)
2022-07-06 20:05:43,277 [rule-dispatcher-0-4] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: RuleNodeToRuleChainTellNextMsg(ruleChainId=b71bbf90-d1a9-11ec-b067-a1db09533645, originator=4e88b3b0-d1aa-11ec-b067-a1db09533645, relationTypes=[Failure], failureMessage=null)
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.DefaultTbRuleEngineConsumerService - Failed to process [1] messages
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.DefaultTbRuleEngineConsumerService - [29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa] Failed to process message: TbMsg(queueName=Main, id=68498fa2-2ea1-4a8f-a900-58092fd2bfe9, ts=1657105543251, type=POST_ATTRIBUTES_REQUEST, originator=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, customerId=d60cb270-7753-11ec-b3eb-e75d6a1d56fa, metaData=TbMsgMetaData(data={deviceType=AMT600D, deviceName=0695075, notifyDevice=false}), dataType=JSON, data={"tb_period":3}, ruleChainId=b71bbf90-d1a9-11ec-b067-a1db09533645, ruleNodeId=4e87c950-d1aa-11ec-b067-a1db09533645, ctx=org.thingsboard.server.common.msg.TbMsgProcessingCtx@4f60e7c3, callback=org.thingsboard.server.common.msg.queue.TbMsgCallback$1@7a6f2377), Last Rule Node: [RuleChain: AMT600D|RuleNode: ss_attributes(4e88b3b0-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.TbMsgPackProcessingContext - Top Rule Nodes by max execution time:
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e883e80-d1aa-11ec-b067-a1db09533645] max execution time: 22. [RuleChain: AMT600D|RuleNode: Save Peroid Attributes(4e883e80-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.TbMsgPackProcessingContext - [Main][b730ce30-d1a9-11ec-b067-a1db09533645] max execution time: 22. [RuleChain: AMT600D|RuleNode: Save Attributes(b730ce30-d1a9-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e87c950-d1aa-11ec-b067-a1db09533645] max execution time: 1. [RuleChain: AMT600D|RuleNode: Period_Time(4e87c950-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e88b3b0-d1aa-11ec-b067-a1db09533645] max execution time: 0. [RuleChain: AMT600D|RuleNode: ss_attributes(4e88b3b0-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - Top Rule Nodes by avg execution time:
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e883e80-d1aa-11ec-b067-a1db09533645] avg execution time: 22.0. [RuleChain: AMT600D|RuleNode: Save Peroid Attributes(4e883e80-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][b730ce30-d1a9-11ec-b067-a1db09533645] avg execution time: 22.0. [RuleChain: AMT600D|RuleNode: Save Attributes(b730ce30-d1a9-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e87c950-d1aa-11ec-b067-a1db09533645] avg execution time: 1.0. [RuleChain: AMT600D|RuleNode: Period_Time(4e87c950-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e88b3b0-d1aa-11ec-b067-a1db09533645] avg execution time: 0.0. [RuleChain: AMT600D|RuleNode: ss_attributes(4e88b3b0-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - Top Rule Nodes by execution count:
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e883e80-d1aa-11ec-b067-a1db09533645] execution count: 1. [RuleChain: AMT600D|RuleNode: Save Peroid Attributes(4e883e80-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e87c950-d1aa-11ec-b067-a1db09533645] execution count: 1. [RuleChain: AMT600D|RuleNode: Period_Time(4e87c950-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][b730ce30-d1a9-11ec-b067-a1db09533645] execution count: 1. [RuleChain: AMT600D|RuleNode: Save Attributes(b730ce30-d1a9-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] INFO o.t.s.s.q.TbMsgPackProcessingContext - [Main][4e88b3b0-d1aa-11ec-b067-a1db09533645] execution count: 0. [RuleChain: AMT600D|RuleNode: ss_attributes(4e88b3b0-d1aa-11ec-b067-a1db09533645)]
2022-07-06 20:05:43,277 [tb-rule-engine-consumer-53-thread-20 | Main-1] DEBUG o.t.s.s.q.p.TbRuleEngineProcessingStrategyFactory - [Main] Reprocessing skipped for 1 failed and 0 timeout messages
2022-07-06 20:05:43,313 [sql-queue-2-events-4-thread-1] DEBUG o.t.s.dao.sql.TbSqlBlockingQueue - [Events] Going to save 2 entities
2022-07-06 20:05:43,323 [sql-queue-1-events-3-thread-1] DEBUG o.t.s.dao.sql.TbSqlBlockingQueue - [Events] Going to save 8 entities
2022-07-06 20:05:43,369 [nioEventLoopGroup-6-9] DEBUG o.t.s.t.m.adaptors.JsonMqttAdaptor - Failed to decode post telemetry request
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
at com.google.gson.JsonParser.parse(JsonParser.java:65)
at com.google.gson.JsonParser.parse(JsonParser.java:45)
at org.thingsboard.server.transport.mqtt.adaptors.JsonMqttAdaptor.convertToPostTelemetry(JsonMqttAdaptor.java:77)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processDevicePublish(MqttTransportHandler.java:410)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processPublish(MqttTransportHandler.java:362)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processRegularSessionMsg(MqttTransportHandler.java:319)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.lambda$processMsgQueue$0(MqttTransportHandler.java:313)
at org.thingsboard.server.transport.mqtt.session.DeviceSessionCtx.tryProcessQueuedMsgs(DeviceSessionCtx.java:236)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processMsgQueue(MqttTransportHandler.java:313)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.enqueueRegularSessionMsg(MqttTransportHandler.java:305)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processMqttMsg(MqttTransportHandler.java:248)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.channelRead(MqttTransportHandler.java:209)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1567)
at com.google.gson.stream.JsonReader.checkLenient(JsonReader.java:1416)
at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:546)
at com.google.gson.stream.JsonReader.peek(JsonReader.java:429)
at com.google.gson.JsonParser.parse(JsonParser.java:60)
... 32 common frames omitted
2022-07-06 20:05:43,369 [nioEventLoopGroup-6-9] DEBUG o.t.s.t.mqtt.MqttTransportHandler - [b1b8f555-c4c5-46ac-a750-32bbea4f598b] Failed to process publish msg [v1/devices/me/telemetry][4]
org.thingsboard.server.common.adaptor.AdaptorException: com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
at org.thingsboard.server.transport.mqtt.adaptors.JsonMqttAdaptor.convertToPostTelemetry(JsonMqttAdaptor.java:80)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processDevicePublish(MqttTransportHandler.java:410)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processPublish(MqttTransportHandler.java:362)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processRegularSessionMsg(MqttTransportHandler.java:319)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.lambda$processMsgQueue$0(MqttTransportHandler.java:313)
at org.thingsboard.server.transport.mqtt.session.DeviceSessionCtx.tryProcessQueuedMsgs(DeviceSessionCtx.java:236)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processMsgQueue(MqttTransportHandler.java:313)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.enqueueRegularSessionMsg(MqttTransportHandler.java:305)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.processMqttMsg(MqttTransportHandler.java:248)
at org.thingsboard.server.transport.mqtt.MqttTransportHandler.channelRead(MqttTransportHandler.java:209)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
at com.google.gson.JsonParser.parse(JsonParser.java:65)
at com.google.gson.JsonParser.parse(JsonParser.java:45)
at org.thingsboard.server.transport.mqtt.adaptors.JsonMqttAdaptor.convertToPostTelemetry(JsonMqttAdaptor.java:77)
... 30 common frames omitted
Caused by: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 154 path $
at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1567)
at com.google.gson.stream.JsonReader.checkLenient(JsonReader.java:1416)
at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:546)
at com.google.gson.stream.JsonReader.peek(JsonReader.java:429)
at com.google.gson.JsonParser.parse(JsonParser.java:60)
... 32 common frames omitted
2022-07-06 20:05:43,369 [nioEventLoopGroup-6-9] INFO o.t.s.t.mqtt.MqttTransportHandler - [b1b8f555-c4c5-46ac-a750-32bbea4f598b] Closing current session due to invalid publish msg [v1/devices/me/telemetry][4]
2022-07-06 20:05:43,369 [nioEventLoopGroup-6-9] DEBUG o.t.s.t.mqtt.MqttTransportHandler - [b1b8f555-c4c5-46ac-a750-32bbea4f598b] Client disconnected!
2022-07-06 20:05:43,372 [sql-queue-0-events-2-thread-1] DEBUG o.t.s.dao.sql.TbSqlBlockingQueue - [Events] Going to save 1 entities
2022-07-06 20:05:43,373 [app-dispatcher-40-thread-1] DEBUG o.t.server.actors.TbActorMailbox - [TENANT|13814000-1dd2-11b2-8080-808080808080] Going to process message: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}
, callback=org.thingsboard.server.service.queue.TbPackCallback@2fa8130d)
2022-07-06 20:05:43,373 [app-dispatcher-40-thread-1] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}
, callback=org.thingsboard.server.service.queue.TbPackCallback@2fa8130d)
2022-07-06 20:05:43,373 [tenant-dispatcher-0-2] DEBUG o.t.server.actors.TbActorMailbox - [TENANT|29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa] Going to process message: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}
, callback=org.thingsboard.server.service.queue.TbPackCallback@2fa8130d)
2022-07-06 20:05:43,373 [tenant-dispatcher-0-2] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}
, callback=org.thingsboard.server.service.queue.TbPackCallback@2fa8130d)
2022-07-06 20:05:43,373 [device-dispatcher-1-1] DEBUG o.t.server.actors.TbActorMailbox - [DEVICE|788d7e50-8b0c-11ec-9071-6fe3b4d1f91b] Going to process message: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}
, callback=org.thingsboard.server.service.queue.TbPackCallback@2fa8130d)
2022-07-06 20:05:43,373 [device-dispatcher-1-1] DEBUG o.t.s.a.service.ContextAwareActor - Processing msg: TransportToDeviceActorMsgWrapper(tenantId=29d4e4e0-5724-11ec-b3eb-e75d6a1d56fa, deviceId=788d7e50-8b0c-11ec-9071-6fe3b4d1f91b, msg=sessionInfo {
nodeId: "ip-10-0-20-80"
sessionIdMSB: -5640488784559257940
sessionIdLSB: -6390552088567391861
tenantIdMSB: 3014285702803493356
tenantIdLSB: -5482033732995164422
deviceIdMSB: 8686738140662862316
deviceIdLSB: -8038520836097705701
deviceName: "0695075"
deviceType: "AMT600D"
deviceProfileIdMSB: 7820077307030606316
deviceProfileIdLSB: -5735437638306679227
customerIdMSB: -3022845053764431380
customerIdLSB: -5482033732995164422
}
sessionEvent {
sessionType: ASYNC
event: CLOSED
}결론
단말 ( Device Entify ID : 788d7e50-8b0c-11ec-9071-6fe3b4d1f91b )서버 세션 종료 원인 분석 내용
Rule-chain ss_attributes(4e88b3b0-d1aa-11ec-b067-a1db09533645)] 단계에서 JSON 파싱 문제로 세션 종료
단말단에서 MQTT Data 올려줄 떄 구조체 초기화 코드 보완
서버 Rule Chain 쪽에서 예외 처리 하는 부분은 보류 하였다.
LIST
'SW Developer > Iot ThingsBoard' 카테고리의 다른 글
| Thingsboard SMS 발신 설정 방법 (0) | 2022.07.10 |
|---|---|
| Thingsboard AWS PostgreSQL DB 연결 방법 (0) | 2022.07.10 |
| Thingsboard PostgreSQL AWS RDS로 이전 migration 방법 (0) | 2022.06.30 |
| IoT 솔루션 Thingsboard sysadmin@thingsboard.org password initialize 시스템 관리자 비밀번호 초기화 방법 (0) | 2022.06.15 |
| Troubleshooting Thingsboard websocket error 1011 solution (0) | 2022.02.04 |
댓글