search

thingsboard / thingsboard-gateway

Open-source IoT Gateway - integrates devices connected to legacy and third-party systems with ThingsBoard IoT Platform using Modbus, CAN bus, BACnet, BLE, OPC-UA, MQTT, ODBC and REST protocols
https://thingsboard.io/docs/iot-gateway/what-is-iot-gateway/
Apache License 2.0
1.74k stars 844 forks source link

tb gateway 2.04 loses connection to thingsboard service 2.1.0 #108

Closed abrasat closed 4 years ago

abrasat commented 6 years ago

tb gateway, tb service and mqtt broker all running locally on same windows 10 pc. the tb gateway is not able to maintain a stable connection to the tb service. this problem did not occur before updating to last 2.04 release, respectively last tb service 2.1.0. the tb gateway log:

2018-07-26 10:36:11,955 [main] INFO  o.t.gateway.GatewayApplication - Starting GatewayApplication v2.0.4-SNAPSHOT on NB158 with PID 9236 (D:\tb\tb-gateway\lib\tb-gateway.jar started by NB158$ in D:\tb\tb-gateway\conf)
2018-07-26 10:36:11,971 [main] DEBUG o.t.gateway.GatewayApplication - Running with Spring Boot v1.4.3.RELEASE, Spring v4.3.5.RELEASE
2018-07-26 10:36:11,971 [main] INFO  o.t.gateway.GatewayApplication - No active profile set, falling back to default profiles: default
2018-07-26 10:36:12,065 [main] INFO  o.s.b.c.e.AnnotationConfigEmbeddedWebApplicationContext - Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@d5c04e: startup date [Thu Jul 26 10:36:12 CEST 2018]; root of context hierarchy
2018-07-26 10:36:12,112 [background-preinit] INFO  o.h.validator.internal.util.Version - HV000001: Hibernate Validator 5.2.4.Final
2018-07-26 10:36:13,924 [main] INFO  o.s.b.f.config.PropertiesFactoryBean - Loading properties file from URL [jar:file:/D:/tb/tb-gateway/lib/tb-gateway.jar!/BOOT-INF/lib/spring-integration-core-4.3.6.RELEASE.jar!/META-INF/spring.integration.default.properties]
2018-07-26 10:36:13,940 [main] INFO  o.s.i.config.IntegrationRegistrar - No bean named 'integrationHeaderChannelRegistry' has been explicitly defined. Therefore, a default DefaultHeaderChannelRegistry will be created.
2018-07-26 10:36:14,346 [main] INFO  o.s.i.c.DefaultConfiguringBeanFactoryPostProcessor - No bean named 'errorChannel' has been explicitly defined. Therefore, a default PublishSubscribeChannel will be created.
2018-07-26 10:36:14,377 [main] INFO  o.s.i.c.DefaultConfiguringBeanFactoryPostProcessor - No bean named 'taskScheduler' has been explicitly defined. Therefore, a default ThreadPoolTaskScheduler will be created.
2018-07-26 10:36:14,643 [main] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [class org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$9f981343] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-07-26 10:36:14,846 [main] INFO  o.s.b.f.config.PropertiesFactoryBean - Loading properties file from URL [jar:file:/D:/tb/tb-gateway/lib/tb-gateway.jar!/BOOT-INF/lib/spring-integration-core-4.3.6.RELEASE.jar!/META-INF/spring.integration.default.properties]
2018-07-26 10:36:14,846 [main] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'integrationGlobalProperties' of type [class org.springframework.beans.factory.config.PropertiesFactoryBean] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-07-26 10:36:14,846 [main] INFO  o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'integrationGlobalProperties' of type [class java.util.Properties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-07-26 10:36:16,174 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat initialized with port(s): 9090 (http)
2018-07-26 10:36:16,190 [main] INFO  o.a.catalina.core.StandardService - Starting service Tomcat
2018-07-26 10:36:16,206 [main] INFO  o.a.catalina.core.StandardEngine - Starting Servlet Engine: Apache Tomcat/8.5.6
2018-07-26 10:36:16,362 [localhost-startStop-1] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext
2018-07-26 10:36:16,362 [localhost-startStop-1] INFO  o.s.web.context.ContextLoader - Root WebApplicationContext: initialization completed in 4297 ms
2018-07-26 10:36:16,612 [localhost-startStop-1] INFO  o.s.b.w.s.ServletRegistrationBean - Mapping servlet: 'dispatcherServlet' to [/]
2018-07-26 10:36:16,612 [localhost-startStop-1] INFO  o.s.b.w.s.FilterRegistrationBean - Mapping filter: 'characterEncodingFilter' to: [/*]
2018-07-26 10:36:16,612 [localhost-startStop-1] INFO  o.s.b.w.s.FilterRegistrationBean - Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2018-07-26 10:36:16,612 [localhost-startStop-1] INFO  o.s.b.w.s.FilterRegistrationBean - Mapping filter: 'httpPutFormContentFilter' to: [/*]
2018-07-26 10:36:16,612 [localhost-startStop-1] INFO  o.s.b.w.s.FilterRegistrationBean - Mapping filter: 'requestContextFilter' to: [/*]
2018-07-26 10:36:16,752 [pool-1-thread-1] TRACE o.t.g.s.update.DefaultUpdateService - Executing check update method for instanceId [d348df3f-cdd0-42d0-9915-ec4cb79c66eb], platform [windows] and version [2.0.4-SNAPSHOT]
2018-07-26 10:36:16,831 [main] INFO  o.t.g.s.DefaultTenantManagerService - [Tenant] Initializing gateway
2018-07-26 10:36:18,034 [nioEventLoopGroup-2-2] DEBUG o.t.g.s.gateway.MqttGatewayService - Gateway connect result code: [CONNECTION_ACCEPTED]
2018-07-26 10:36:18,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='null', payload={"shared":"configuration"}, timestamp=0, topic='v1/devices/me/attributes/request/1'id=f7d31efc-9440-4425-966b-8c61e10b550c, messageId=1}]
2018-07-26 10:36:18,112 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 10:36:18,112 [main] INFO  o.t.g.s.DefaultTenantManagerService - [Tenant] Initializing extension: [MQTT]
2018-07-26 10:36:18,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:18,112 [pool-4-thread-1] DEBUG o.t.g.service.MqttMessageReceiver - Successfully sent message: [null]
2018-07-26 10:36:18,112 [main] INFO  o.t.g.e.m.c.DefaultMqttClientService - [Tenant] Initializing MQTT client service!
2018-07-26 10:36:18,143 [nioEventLoopGroup-2-1] TRACE o.t.g.s.gateway.MqttGatewayService - Message arrived [v1/devices/me/attributes/response/1] {}
2018-07-26 10:36:18,143 [pool-2-thread-1] INFO  o.t.g.s.gateway.MqttGatewayService - Configuration arrived! {}
2018-07-26 10:36:18,159 [pool-2-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - Failed to process arrived message!
2018-07-26 10:36:18,393 [main] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - [localhost:22000] MQTT broker connection attempt!
2018-07-26 10:36:18,409 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] INFO  o.t.g.e.m.client.MqttBrokerMonitor - [localhost:22000] MQTT broker connection established!
2018-07-26 10:36:18,424 [main] INFO  o.t.g.s.gateway.MqttGatewayService - Subscription added: RpcCommandSubscription(deviceNameFilter=.*, listener=org.thingsboard.gateway.extensions.mqtt.client.MqttBrokerMonitor@1bd4fdd)
2018-07-26 10:36:18,424 [main] WARN  o.t.g.s.gateway.MqttGatewayService - Subscription was already added: RpcCommandSubscription(deviceNameFilter=.*, listener=org.thingsboard.gateway.extensions.mqtt.client.MqttBrokerMonitor@1bd4fdd)
2018-07-26 10:36:18,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594354788,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:18,674 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] INFO  o.t.g.s.gateway.MqttGatewayService - [HGC] Device Connected!
2018-07-26 10:36:18,674 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][4] Updating device telemetry: [BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594354788, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:18,690 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:18,893 [main] INFO  o.s.w.s.m.m.a.RequestMappingHandlerAdapter - Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@d5c04e: startup date [Thu Jul 26 10:36:12 CEST 2018]; root of context hierarchy
2018-07-26 10:36:19,049 [main] INFO  o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/sigfox/{deviceTypeId}],methods=[POST]}" onto public void org.thingsboard.gateway.extensions.http.HttpController.handleSigfoxRequest(java.lang.String,java.lang.String,java.lang.String) throws java.lang.Exception
2018-07-26 10:36:19,049 [main] INFO  o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/uplink/{converterId}],methods=[POST]}" onto public void org.thingsboard.gateway.extensions.http.HttpController.handleRequest(java.lang.String,java.lang.String) throws java.lang.Exception
2018-07-26 10:36:19,049 [main] INFO  o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-07-26 10:36:19,049 [main] INFO  o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-07-26 10:36:19,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='GATEWAY', payload={"ts":1532594178112,"values":{"devicesOnline":0,"attributesUploaded":0,"telemetryUploaded":0}}, timestamp=0, topic='v1/devices/me/telemetry'id=bf0725c9-b252-454f-bb47-2fe801eabf15, messageId=2}]
2018-07-26 10:36:19,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"device":"HGC","type":null}, timestamp=0, topic='v1/gateway/connect'id=070d4538-d611-446f-9668-ab4e6ed7178c, messageId=3}]
2018-07-26 10:36:19,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}]
2018-07-26 10:36:19,112 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [3] messages are still in progress
2018-07-26 10:36:19,112 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:19,112 [pool-4-thread-1] INFO  o.t.g.s.gateway.MqttGatewayService - [HGC][null][3] Device connect event is reported to Thingsboard!
2018-07-26 10:36:19,112 [pool-4-thread-1] INFO  o.t.g.s.gateway.MqttGatewayService - Gateway statistics {"ts":1532594178112,"values":{"devicesOnline":0,"attributesUploaded":0,"telemetryUploaded":0}} reported!
2018-07-26 10:36:19,112 [main] INFO  o.s.w.s.h.SimpleUrlHandlerMapping - Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-07-26 10:36:19,112 [main] INFO  o.s.w.s.h.SimpleUrlHandlerMapping - Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-07-26 10:36:19,190 [main] INFO  o.s.w.s.h.SimpleUrlHandlerMapping - Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-07-26 10:36:19,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594355789,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:19,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][5] Updating device telemetry: [BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594355789, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:19,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:19,518 [main] INFO  o.s.s.c.ThreadPoolTaskScheduler - Initializing ExecutorService  'taskScheduler'
2018-07-26 10:36:19,815 [main] INFO  o.s.j.e.a.AnnotationMBeanExporter - Registering beans for JMX exposure on startup
2018-07-26 10:36:19,815 [main] INFO  o.s.j.e.a.AnnotationMBeanExporter - Bean with name 'integrationMbeanExporter' has been autodetected for JMX exposure
2018-07-26 10:36:19,831 [main] INFO  o.s.j.e.a.AnnotationMBeanExporter - Located managed bean 'integrationMbeanExporter': registering with JMX server as MBean [org.springframework.integration.monitor:name=integrationMbeanExporter,type=IntegrationMBeanExporter]
2018-07-26 10:36:19,878 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Registering beans for JMX exposure on startup
2018-07-26 10:36:19,878 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Registering MessageChannel nullChannel
2018-07-26 10:36:19,878 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Located managed bean 'org.springframework.integration:type=MessageChannel,name=nullChannel': registering with JMX server as MBean [org.springframework.integration:type=MessageChannel,name=nullChannel]
2018-07-26 10:36:19,893 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Registering MessageChannel errorChannel
2018-07-26 10:36:19,893 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Located managed bean 'org.springframework.integration:type=MessageChannel,name=errorChannel': registering with JMX server as MBean [org.springframework.integration:type=MessageChannel,name=errorChannel]
2018-07-26 10:36:20,034 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Registering MessageHandler errorLogger
2018-07-26 10:36:20,034 [main] INFO  o.s.i.m.IntegrationMBeanExporter - Located managed bean 'org.springframework.integration:type=MessageHandler,name=errorLogger,bean=internal': registering with JMX server as MBean [org.springframework.integration:type=MessageHandler,name=errorLogger,bean=internal]
2018-07-26 10:36:20,065 [main] INFO  o.s.c.s.DefaultLifecycleProcessor - Starting beans in phase 0
2018-07-26 10:36:20,065 [main] INFO  o.s.i.endpoint.EventDrivenConsumer - Adding {logging-channel-adapter:_org.springframework.integration.errorLogger} as a subscriber to the 'errorChannel' channel
2018-07-26 10:36:20,065 [main] INFO  o.s.i.c.PublishSubscribeChannel - Channel 'tb-gateway:9090.errorChannel' has 1 subscriber(s).
2018-07-26 10:36:20,065 [main] INFO  o.s.i.endpoint.EventDrivenConsumer - started _org.springframework.integration.errorLogger
2018-07-26 10:36:20,081 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-0.0.0.0-9090"]
2018-07-26 10:36:20,096 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler [http-nio-0.0.0.0-9090]
2018-07-26 10:36:20,112 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - ThingsBoard MQTT connection failed. Reconnecting in [3000] milliseconds
2018-07-26 10:36:20,112 [main] INFO  o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2018-07-26 10:36:20,112 [pool-4-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - [HGC][4] Failed to publish device telemetry!
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:20,112 [pool-4-thread-1] WARN  o.t.g.service.MqttMessageReceiver - Failed to send message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}] due to [{}]
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:20,143 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 9090 (http)
2018-07-26 10:36:20,143 [main] INFO  o.t.gateway.GatewayApplication - Started GatewayApplication in 9.485 seconds (JVM running for 10.602)
2018-07-26 10:36:20,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594356789,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:20,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][6] Updating device telemetry: [BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594356789, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:20,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:21,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594357790,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:21,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][7] Updating device telemetry: [BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594357790, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:21,471 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:22,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594358792,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:22,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][8] Updating device telemetry: [BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594358792, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:22,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:23,112 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Attempting to reconnect to ThingsBoard.
2018-07-26 10:36:23,128 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Successfully reconnected to ThingsBoard.
2018-07-26 10:36:23,128 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}]
2018-07-26 10:36:23,128 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 10:36:23,128 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:23,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594359793,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:23,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][9] Updating device telemetry: [BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594359793, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:23,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:24,128 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - ThingsBoard MQTT connection failed. Reconnecting in [3000] milliseconds
2018-07-26 10:36:24,128 [pool-4-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - [HGC][4] Failed to publish device telemetry!
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:24,128 [pool-4-thread-1] WARN  o.t.g.service.MqttMessageReceiver - Failed to send message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}] due to [{}]
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:24,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594360794,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:24,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][10] Updating device telemetry: [BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594360794, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:24,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:25,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594361794,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:25,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][11] Updating device telemetry: [BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594361794, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:25,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:26,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594362795,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:26,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][12] Updating device telemetry: [BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594362795, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:26,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:27,128 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Attempting to reconnect to ThingsBoard.
2018-07-26 10:36:27,143 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Successfully reconnected to ThingsBoard.
2018-07-26 10:36:27,143 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}]
2018-07-26 10:36:27,143 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 10:36:27,143 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:27,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594363797,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:27,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][13] Updating device telemetry: [BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594363797, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:27,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:28,159 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - ThingsBoard MQTT connection failed. Reconnecting in [3000] milliseconds
2018-07-26 10:36:28,159 [pool-4-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - [HGC][4] Failed to publish device telemetry!
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:28,159 [pool-4-thread-1] WARN  o.t.g.service.MqttMessageReceiver - Failed to send message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}] due to [{}]
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:28,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594364798,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:28,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][14] Updating device telemetry: [BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594364798, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:28,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:29,128 [nioEventLoopGroup-2-15] WARN  o.t.g.s.gateway.MqttGatewayService - Lost connection to ThingsBoard.
2018-07-26 10:36:29,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594365798,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:29,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][15] Updating device telemetry: [BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594365798, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:29,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] INFO  o.t.g.s.gateway.MqttGatewayService - [HGC] Device Connected!
2018-07-26 10:36:29,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:30,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594366799,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:30,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][17] Updating device telemetry: [BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594366799, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:30,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:31,159 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Attempting to reconnect to ThingsBoard.
2018-07-26 10:36:31,159 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Successfully reconnected to ThingsBoard.
2018-07-26 10:36:31,175 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}]
2018-07-26 10:36:31,175 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 10:36:31,175 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:31,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594367801,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:31,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][18] Updating device telemetry: [BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594367801, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:31,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:32,175 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - ThingsBoard MQTT connection failed. Reconnecting in [3000] milliseconds
2018-07-26 10:36:32,175 [pool-4-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - [HGC][4] Failed to publish device telemetry!
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:32,175 [pool-4-thread-1] WARN  o.t.g.service.MqttMessageReceiver - Failed to send message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}] due to [{}]
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:32,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594368802,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:32,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][19] Updating device telemetry: [BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594368802, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:32,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:33,144 [nioEventLoopGroup-2-21] WARN  o.t.g.s.gateway.MqttGatewayService - Lost connection to ThingsBoard.
2018-07-26 10:36:33,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594369803,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:33,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][20] Updating device telemetry: [BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594369803, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:33,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] INFO  o.t.g.s.gateway.MqttGatewayService - [HGC] Device Connected!
2018-07-26 10:36:33,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:34,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594370803,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:34,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][22] Updating device telemetry: [BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594370803, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:34,503 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:35,175 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Attempting to reconnect to ThingsBoard.
2018-07-26 10:36:35,190 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Successfully reconnected to ThingsBoard.
2018-07-26 10:36:35,190 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}]
2018-07-26 10:36:35,190 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 10:36:35,190 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 10:36:35,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532594371804,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 10:36:35,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][23] Updating device telemetry: [BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532594371804, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 10:36:35,487 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 10:36:36,191 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - ThingsBoard MQTT connection failed. Reconnecting in [3000] milliseconds
2018-07-26 10:36:36,191 [pool-4-thread-1] WARN  o.t.g.s.gateway.MqttGatewayService - [HGC][4] Failed to publish device telemetry!
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)
2018-07-26 10:36:36,191 [pool-4-thread-1] WARN  o.t.g.service.MqttMessageReceiver - Failed to send message [{deviceId='HGC', payload={"HGC":[{"ts":1532594354788,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=c2d199fa-837f-456f-959a-64c592305c0e, messageId=4}] due to [{}]
java.util.concurrent.CancellationException: null
    at io.netty.util.concurrent.DefaultPromise.cancel(...)(Unknown Source)

and so on

abrasat commented 6 years ago

Forgot to tell that in the case above the telemetry data of the device are refreshed only once.

If making the device public, the telemetry data are refreshed correctly, but also cyclically set to 0 with the tb gateway start-time as timestamp (?!). The tb gateway log in this case:

2018-07-26 12:05:39,644 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532599715223,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=95b62e69-74a6-4c0a-8e43-2079e31c28ec, messageId=6373}]
2018-07-26 12:05:39,644 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 12:05:39,644 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 12:05:39,644 [pool-4-thread-1] DEBUG o.t.g.s.gateway.MqttGatewayService - [6373][HGC] Device telemetry published to ThingsBoard!
2018-07-26 12:05:39,893 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532599716225,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 12:05:39,893 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][6374] Updating device telemetry: [BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532599716225, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 12:05:39,893 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 12:05:40,659 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532599716225,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=a0087686-f0dd-4dc6-9898-b90596d637c5, messageId=6374}]
2018-07-26 12:05:40,659 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 12:05:40,659 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 12:05:40,659 [pool-4-thread-1] DEBUG o.t.g.s.gateway.MqttGatewayService - [6374][HGC] Device telemetry published to ThingsBoard!
2018-07-26 12:05:40,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532599717226,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 12:05:40,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][6375] Updating device telemetry: [BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532599717226, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 12:05:40,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 12:05:40,956 [nioEventLoopGroup-2-19] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: complete already: DefaultPromise@13a561b(failure: java.util.concurrent.CancellationException)
                at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:97)
                at nl.jk5.mqtt.MqttChannelHandler.handlePuback(MqttChannelHandler.java:215)
                at nl.jk5.mqtt.MqttChannelHandler.channelRead0(MqttChannelHandler.java:37)
                at nl.jk5.mqtt.MqttChannelHandler.channelRead0(MqttChannelHandler.java:11)
                at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at nl.jk5.mqtt.MqttPingHandler.channelRead(MqttPingHandler.java:39)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
                at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:284)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
                at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:146)
                at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
                at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
                at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
                at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
                at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
                at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
                at java.lang.Thread.run(Unknown Source)
2018-07-26 12:05:41,659 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Sending message [{deviceId='HGC', payload={"HGC":[{"ts":1532599717226,"values":{"Fr1":0.0,"Fr2":0.0,"Fr3":0.0,"Gap1":20.5,"Gap2":27.0,"Gap3":17.9,"Speed":0.0,"HeadLength":13.21,"TailLength":6.2}}]}, timestamp=0, topic='v1/gateway/telemetry'id=e32cb897-38b7-4a9f-a506-e9f219f47df0, messageId=6375}]
2018-07-26 12:05:41,659 [pool-3-thread-1] INFO  o.t.g.service.MqttMessageSender - Outgoing queue is not empty. [1] messages are still in progress
2018-07-26 12:05:41,659 [pool-3-thread-1] DEBUG o.t.g.service.MqttMessageSender - Waiting until all messages are sent before going to the next bucket
2018-07-26 12:05:41,659 [pool-4-thread-1] DEBUG o.t.g.s.gateway.MqttGatewayService - [6375][HGC] Device telemetry published to ThingsBoard!
2018-07-26 12:05:41,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.e.m.c.c.m.MqttJsonConverter - Parsing json message: {"ts":1532599718227,"values":{"Fr1":    0.00,"Fr2":    0.00,"Fr3":    0.00,"Srg1":   20.50,"Srg2":   27.00,"Srg3":   17.90,"Spd":    0.00,"HeadLength":   13.21,"TailLength":    6.20}}
2018-07-26 12:05:41,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] TRACE o.t.g.s.gateway.MqttGatewayService - [HGC][6376] Updating device telemetry: [BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr1'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr2'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Fr3'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=20.5} BasicKvEntry{key='Gap1'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=27.0} BasicKvEntry{key='Gap2'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=17.9} BasicKvEntry{key='Gap3'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=0.0} BasicKvEntry{key='Speed'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=13.21} BasicKvEntry{key='HeadLength'}}, BasicTsKvEntry{ts=1532599718227, kv=DoubleDataEntry{value=6.2} BasicKvEntry{key='TailLength'}}]
2018-07-26 12:05:41,909 [MQTT Call: 4def0eef-be0f-46f2-8a97-c9bfae83610d] DEBUG o.t.g.e.m.client.MqttBrokerMonitor - Re-scheduling keep alive timer for device HGC with timeout = 60000
2018-07-26 12:05:41,956 [nioEventLoopGroup-2-19] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: complete already: DefaultPromise@184c4e0(failure: java.util.concurrent.CancellationException)
                at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:97)
                at nl.jk5.mqtt.MqttChannelHandler.handlePuback(MqttChannelHandler.java:215)
                at nl.jk5.mqtt.MqttChannelHandler.channelRead0(MqttChannelHandler.java:37)
                at nl.jk5.mqtt.MqttChannelHandler.channelRead0(MqttChannelHandler.java:11)
                at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at nl.jk5.mqtt.MqttPingHandler.channelRead(MqttPingHandler.java:39)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
                at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:284)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
                at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
                at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
                at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:146)
                at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
                at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
                at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
                at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
                at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
                at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
                at java.lang.Thread.run(Unknown Source)
2018-07-26 12:05:42,175 [nioEventLoopGroup-2-19] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.IllegalStateException: complete already: DefaultPromise@1377c4e(failure: java.util.concurrent.CancellationException)
JozsefGuyas commented 6 years ago

Hello, I use the tb gateway 1.2.2, and I have a same problem.When I have tried to open the storage files in the /use/share/tb-gateway/bin/stroge/, I have experienced that every files are corrupted, so I have to remove these files.