Did you set different clientids? Some brokers don‘t allow two connections with the same client id
The client IDs are identical, but they are both on diffferent sites, and both talking to different brokers, so there’s no connectivity at all between the two systems or brokers.
Please set org.eclipse.smarthome.io.transport.mqtt and com.hivemq to TRACE and show the output. Please also set the broker to debug logging and show that, too.
I’m back on M4 now as that’s working for me - do you want me to do the trace on that or 2.5.0-1?
M4 is not helping (old underlying mqtt library). 2.5.0 would be great.
Hi,
it seems to be the same error as here I setup debug envronment and run into the same exception. Additionally, log file is flood with
[.incoming.MqttIncomingPublishService] - No publish flow registered for MqttStatefulPublish{stateless=MqttPublish{topic=$aws/things/<blid>/shadow/update, payload=121byte, qos=AT_MOST_ONCE, retain=false}, packetIdentifier=-1, dup=false, topicAlias=0, subscriptionIdentifiers=[]}
Things definition can be found here
Please, ping me in case any assistance is need
Kind regards,
Alexander
Jan, is this what I need to set?
log:set TRACE org.eclipse.smarthome.io.transport.mqtt
log:set TRACE com.hivemq.client.mqtt
log:set DEBUG org.eclipse.smarthome.mqttbroker
log:set TRACE org.openhab.binding.mqtt
Here’s what I get when I create the broker:
09:24:23.852 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:e6bcc300
09:24:23.853 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:e6bcc300
09:24:23.856 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:e6bcc300' changed from UNINITIALIZED to INITIALIZING
09:24:23.860 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:e6bcc300' changed from INITIALIZING to OFFLINE
09:24:23.864 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'openhab' with clientid a3dfe15c-3c20-4d78-b869-391bd902dcea
09:24:23.866 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:e6bcc300
09:24:23.867 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:e6bcc300
09:24:23.876 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:e6bcc300' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Timeout
09:24:23.877 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:e6bcc300' changed from OFFLINE (COMMUNICATION_ERROR): Timeout to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
@roryd are you configuring your mqtt thing in a file or PaperUI?
Also, may help to post your mqtt config.
I’m configuring mqtt via Paper UI, so no mqtt.cfg (apart from the default one with all the options commented out).
Do you use the embeddedbroker? I understood you use mosquitto. If you use the embedded broker: Try mosquitto. The embedded broker has bugs. If you use mosquitto: with “broker” I meant mosquitto. Not sure about the syntax.
The other logs look goof, but I need around 20 lines after the initial connect, around 20 lines before and after the disconnect.
I installed the MQTT binding from Paper UI.
I had deleted the broker from Paper UI and then recreated it, and that resulted in the logs above.
I’m away from that system for the night, but I’ll redo the logs in the morning and post the results.
1 Like
So I deleted the broker in Paper UI at 16:01:33.259 below, and then recreated it at 16:04:01.872 (there was no activity between thosse times).
This is the log:
2019-12-18 15:58:22.357 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:141384D4-0288-2108-FFFFEC94D5582917-AI1
2019-12-18 15:58:22.357 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:141384D4-0288-2108-FFFFEC94D5582917-AI1
2019-12-18 15:58:22.357 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI1
2019-12-18 15:58:22.358 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI1
2019-12-18 15:58:22.358 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI1
2019-12-18 15:58:22.358 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI2
2019-12-18 15:58:22.359 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI2
2019-12-18 15:58:22.359 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel loxone:miniserver:504F94119076:14128ED7-01BC-C71B-FFFFEC94D5582917-AI2
2019-12-18 15:58:22.359 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel fronius:powerinverter:mybridge:myinverter:powerflowchannelpakku
2019-12-18 15:58:22.360 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel fronius:powerinverter:mybridge:myinverter:powerflowchannelpakku
2019-12-18 15:58:22.360 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel fronius:powerinverter:mybridge:myinverter:powerflowchannelpakku
2019-12-18 15:58:28.761 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-18 15:58:28.763 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw1
2019-12-18 15:59:28.765 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-18 15:59:28.766 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw1
2019-12-18 16:00:28.766 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-18 16:00:28.768 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw1
2019-12-18 16:01:28.769 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-18 16:01:28.770 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw1
2019-12-18 16:01:33.259 [TRACE] [.transport.mqtt.MqttBrokerConnection] - Closing the MQTT broker connection '11.153.2.22'
2019-12-18 16:04:01.872 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:81aab7dd
2019-12-18 16:04:01.872 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:81aab7dd
2019-12-18 16:04:01.878 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:04:01.885 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:81aab7dd
2019-12-18 16:04:01.885 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:81aab7dd
2019-12-18 16:04:11.889 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:04:11.891 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:05:11.891 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:05:11.892 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:06:11.892 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:06:11.893 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:07:11.894 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:07:11.894 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:08:11.895 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:08:11.896 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:09:11.896 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:09:11.897 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:10:11.897 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:10:11.898 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:11:11.899 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:11:11.900 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
2019-12-18 16:12:11.901 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
2019-12-18 16:12:11.904 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1Looks like it’s not connecting at all. I’m missing the thing-status events. For me it looks like:
18:05:00.341 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from UNINITIALIZED to INITIALIZING
18:05:00.403 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from INITIALIZING to OFFLINE
18:05:02.035 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid MyClientId
18:05:02.151 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from OFFLINE to ONLINE
18:05:02.167 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homeassistant_b4e62d6c93de:roomba:b4e62d6c93de' changed from UNINITIALIZED to INITIALIZING
18:05:02.179 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homeassistant_b4e62d6c93de:roomba:b4e62d6c93de' changed from INITIALIZING to OFFLINE (GONE): No response from the device yet
18:05:02.272 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:cdcdf6a4' changed from UNINITIALIZED to INITIALIZING
18:05:02.287 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:cdcdf6a4:percentTest
18:05:02.295 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@563a0c9b to discovery topic +/+/$homie on broker mqtt:broker:roomba
18:05:02.296 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@57590a16 to discovery topic homeassistant/# on broker mqtt:broker:roomba
18:05:02.298 [DEBUG] [hab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:cdcdf6a4:percentTest to topic: percent/state
18:05:02.302 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:cdcdf6a4' changed from INITIALIZING to ONLINE
18:05:02.311 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:roomba:state:wifistat
18:05:02.312 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:roomba:state' changed from UNINITIALIZED to INITIALIZING
18:05:02.314 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:roomba:state:shadow
18:05:02.313 [DEBUG] [mqtt.generic.AbstractMQTTThingHandler] - Channel mqtt:topic:cdcdf6a4:percentTest received REFRESH but no value cached, ignoring
18:05:02.318 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:roomba:state:WiFiQual
18:05:02.323 [DEBUG] [hab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:roomba:state:shadow to topic: $aws/things/3162831022440790/shadow/#
18:05:02.323 [DEBUG] [hab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:roomba:state:WiFiQual to topic: homie/thermo_ian/$stats/signal
18:05:02.323 [DEBUG] [hab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:roomba:state:wifistat to topic: wifistat
18:05:02.328 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:roomba:state' changed from INITIALIZING to ONLINE
18:05:02.330 [DEBUG] [mqtt.generic.AbstractMQTTThingHandler] - Channel mqtt:topic:roomba:state:wifistat received REFRESH but no value cached, ignoring
18:05:02.331 [DEBUG] [mqtt.generic.AbstractMQTTThingHandler] - Channel mqtt:topic:roomba:state:WiFiQual received REFRESH but no value cached, ignoring
18:05:02.331 [DEBUG] [mqtt.generic.AbstractMQTTThingHandler] - Channel mqtt:topic:roomba:state:shadow received REFRESH but no value cached, ignoring
The status should show why it’s not connecting.
My mistake, I posted a tail of openhab.log only. Here’s the log:tail from the console:
17:09:29.974 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62609.5 to -62520.5
17:09:35.558 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62520.5 to 62061.0
17:09:35.559 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62520.5 to -62061.0
17:09:40.292 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.7 to 18.6
17:09:40.293 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62061.0 to 61848.5
17:09:40.293 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62061.0 to -61848.5
17:09:45.355 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61848.5 to 61896.5
17:09:45.356 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61848.5 to -61896.5
17:09:51.475 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61896.5 to 61994.0
17:09:51.475 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61896.5 to -61994.0
17:09:56.852 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61994.0 to 61795.0
17:09:56.852 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61994.0 to -61795.0
17:10:02.252 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61795.0 to 61899.0
17:10:02.254 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61795.0 to -61899.0
17:10:07.459 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61899.0 to 61727.5
17:10:07.459 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61899.0 to -61727.5
17:10:12.024 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
17:10:12.025 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution to OFFLINE
17:10:12.025 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw1
17:10:12.028 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution
17:10:13.251 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61727.5 to 61900.0
17:10:13.251 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61727.5 to -61900.0
17:10:18.992 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.6 to 18.5
17:10:18.992 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61900.0 to 61686.5
17:10:18.992 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61900.0 to -61686.5
17:10:23.635 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61686.5 to 63758.5
17:10:23.635 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61686.5 to -63758.5
17:10:28.818 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63758.5 to 63808.5
17:10:28.818 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63758.5 to -63808.5
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14152E7F_02B2_0D97_FFFF3A9B996FEB33_AI1 changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - oplights_2_kitchen_cor1 changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14152E7F_02B2_0D97_FFFF3A9B996FEB33_AI2 changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - oplights_2_kitchen_cor2 changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14152E7F_02B2_0D97_FFFF3A9B996FEB33_MASTERVALUE changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14152E7F_02B2_0D97_FFFF3A9B996FEB33_M777 changed from OFF to ON
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14152E7F_02B2_0D97_FFFF3A9B996FEB33 changed from 778 to 777
17:10:30.891 [INFO ] [smarthome.event.ItemStateChangedEvent] - LoxoneMiniserver_NissanOfficeKitchenCorridor changed from 778 to 777
17:10:34.547 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.5 to 18.4
17:10:34.547 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63808.5 to 64122.0
17:10:34.547 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63808.5 to -64122.0
17:10:40.914 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 64122.0 to 64019.0
17:10:40.915 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -64122.0 to -64019.0
17:10:41.806 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution to REMOVING
17:10:41.808 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from REMOVING to REMOVED
17:10:41.809 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from REMOVED to UNINITIALIZED
17:10:41.811 [TRACE] [o.transport.mqtt.MqttBrokerConnection] - Closing the MQTT broker connection 'spcgw'
17:10:41.812 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from UNINITIALIZED to OFFLINE
17:10:41.815 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:81aab7dd' changed from OFFLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
17:10:45.717 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 64019.0 to 64075.5
17:10:45.717 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -64019.0 to -64075.5
17:10:50.362 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 64075.5 to 64047.5
17:10:50.363 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -64075.5 to -64047.5
17:10:56.848 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 64047.5 to 64026.5
17:10:56.848 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -64047.5 to -64026.5
17:11:02.257 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.4 to 18.3
17:11:02.258 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 64026.5 to 61933.5
17:11:02.259 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -64026.5 to -61933.5
17:11:07.675 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61933.5 to 61890.0
17:11:07.676 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61933.5 to -61890.0
17:11:12.696 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61890.0 to 62044.0
17:11:12.696 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61890.0 to -62044.0
17:11:17.901 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.3 to 18.2
17:11:17.902 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62044.0 to 61874.5
17:11:17.904 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62044.0 to -61874.5
17:11:24.237 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61874.5 to 62136.5
17:11:24.237 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61874.5 to -62136.5
17:11:28.836 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62136.5 to 61761.5
17:11:28.836 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62136.5 to -61761.5
17:11:33.446 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61761.5 to 61714.5
17:11:33.446 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61761.5 to -61714.5
17:11:39.433 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.2 to 18.1
17:11:39.434 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61714.5 to 63052.0
17:11:39.434 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61714.5 to -63052.0
17:11:45.152 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63052.0 to 63052.5
17:11:45.152 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63052.0 to -63052.5
17:11:49.930 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63052.5 to 63259.5
17:11:49.931 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63052.5 to -63259.5
17:11:54.567 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63259.5 to 63636.0
17:11:54.568 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63259.5 to -63636.0
17:12:00.727 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63636.0 to 63611.0
17:12:00.727 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63636.0 to -63611.0
17:12:06.444 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63611.0 to 63729.5
17:12:06.445 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63611.0 to -63729.5
17:12:11.816 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63729.5 to 63566.0
17:12:11.817 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63729.5 to -63566.0
17:12:16.672 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63566.0 to 63616.5
17:12:16.673 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63566.0 to -63616.5
17:12:18.310 [INFO ] [smarthome.event.ItemStateChangedEvent] - LoxoneMiniserver_NissanOfficeLights_JMcG changed from OFF to ON
17:12:18.311 [INFO ] [smarthome.event.ItemStateChangedEvent] - office_2_jmcgann changed from OFF to ON
17:12:18.311 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44E7_0075_F32B_FFFF3CF5CEE5AF54_AI1 changed from OFF to ON
17:12:18.312 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44E7_0075_F32B_FFFF3CF5CEE5AF54_M777 changed from OFF to ON
17:12:18.312 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44E7_0075_F32B_FFFF3CF5CEE5AF54 changed from 778 to 777
17:12:21.913 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63616.5 to 63637.0
17:12:21.914 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63616.5 to -63637.0
17:12:26.864 [INFO ] [smarthome.event.ItemStateChangedEvent] - office_2_nosullivan changed from OFF to ON
17:12:26.865 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44B4_0312_E3B6_FFFF7681DD7FEE50_AI1 changed from OFF to ON
17:12:26.865 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44B4_0312_E3B6_FFFF7681DD7FEE50_M777 changed from OFF to ON
17:12:26.866 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_141E44B4_0312_E3B6_FFFF7681DD7FEE50 changed from 778 to 777
17:12:27.393 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63637.0 to 63512.0
17:12:27.393 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63637.0 to -63512.0
17:12:32.306 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63512.0 to 63630.0
17:12:32.306 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63512.0 to -63630.0
17:12:37.550 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.1 to 18.0
17:12:37.551 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63630.0 to 63974.0
17:12:37.551 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63630.0 to -63974.0
17:12:41.460 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14141507_0144_A6AD_FFFFEC94D5582917_AI1 changed from ON to OFF
17:12:41.461 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14141507_0144_A6AD_FFFFEC94D5582917_M777 changed from ON to OFF
17:12:41.461 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14141507_0144_A6AD_FFFFEC94D5582917 changed from 777 to 778
17:12:42.802 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63974.0 to 63834.5
17:12:42.802 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63974.0 to -63834.5
17:12:48.759 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 63834.5 to 61680.5
17:12:48.760 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -63834.5 to -61680.5
17:12:53.751 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61680.5 to 62118.0
17:12:53.752 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61680.5 to -62118.0
17:12:58.603 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62118.0 to 62052.5
17:12:58.604 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62118.0 to -62052.5
17:13:02.804 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:09c5d203
17:13:02.804 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:09c5d203
17:13:02.806 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from UNINITIALIZED to INITIALIZING
17:13:02.809 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from INITIALIZING to OFFLINE
17:13:02.810 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw2
17:13:02.812 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:09c5d203
17:13:02.813 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:09c5d203
17:13:02.817 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Timeout
17:13:02.819 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE (COMMUNICATION_ERROR): Timeout to OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution
17:13:04.657 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 18.0 to 17.9
17:13:04.657 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62052.5 to 62091.5
17:13:04.657 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62052.5 to -62091.5
17:13:10.661 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62091.5 to 61965.5
17:13:10.662 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62091.5 to -61965.5
17:13:12.817 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
17:13:12.819 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution to OFFLINE
17:13:12.819 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw2
17:13:12.822 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution
17:13:16.087 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61965.5 to 61462.0
17:13:16.088 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61965.5 to -61462.0
17:13:20.707 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61462.0 to 61618.0
17:13:20.708 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61462.0 to -61618.0
17:13:26.047 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.9 to 17.8
17:13:26.048 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61618.0 to 61886.5
17:13:26.048 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61618.0 to -61886.5
17:13:31.547 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61886.5 to 60924.0
17:13:31.548 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61886.5 to -60924.0
17:13:36.596 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 60924.0 to 62749.5
17:13:36.597 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -60924.0 to -62749.5
17:13:41.938 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 62749.5 to 61955.0
17:13:41.938 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -62749.5 to -61955.0
17:13:47.026 [INFO ] [smarthome.event.ItemStateChangedEvent] - LoxoneMiniserver_AftersalesManagerLights changed from ON to OFF
17:13:47.027 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14136A22_033B_28FC_FFFFEC94D5582917_AI1 changed from ON to OFF
17:13:47.028 [INFO ] [smarthome.event.ItemStateChangedEvent] - LoxoneMiniserver_AftersalesManagerMoodBright changed from ON to OFF
17:13:47.028 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14136A22_033B_28FC_FFFFEC94D5582917_M777 changed from ON to OFF
17:13:47.028 [INFO ] [smarthome.event.ItemStateChangedEvent] - loxone_miniserver_504F94119076_14136A22_033B_28FC_FFFFEC94D5582917 changed from 777 to 778
17:13:47.029 [INFO ] [smarthome.event.ItemStateChangedEvent] - LoxoneMiniserver_AftersalesManagerLightingController changed from 777 to 778
17:13:47.381 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.8 to 17.7
17:13:47.382 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61955.0 to 61053.5
17:13:47.382 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61955.0 to -61053.5
17:13:53.537 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 61053.5 to 60735.5
17:13:53.538 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -61053.5 to -60735.5
17:13:58.289 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 60735.5 to 60772.5
17:13:58.289 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -60735.5 to -60772.5
17:14:02.899 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.7 to 17.6
17:14:02.900 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 60772.5 to 60557.5
17:14:02.900 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -60772.5 to -60557.5
17:14:08.642 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 60557.5 to 60184.0
17:14:08.642 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -60557.5 to -60184.0
17:13:12.822 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution
Maybe there is a typo in your configuration? Otherwise check you network, it seems the hostname can’t be resolved.
Again, my mistake. I’ve used the IP address now instead of a hostname. I deleted the broker and then recreated it again (in Paper UI):
17:25:03.673 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55954.0 to 60323.5
17:25:03.674 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55954.0 to -60323.5
17:25:10.081 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 60323.5 to 57836.0
17:25:10.081 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -60323.5 to -57836.0
17:25:12.842 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'spcgw'. Next attempt in 60000ms
17:25:12.842 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution to OFFLINE
17:25:12.843 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'spcgw' with clientid spcgw2
17:25:12.846 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution
17:25:14.926 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 57836.0 to 56820.0
17:25:14.926 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -57836.0 to -56820.0
17:25:19.506 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56820.0 to 55880.0
17:25:19.507 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56820.0 to -55880.0
17:25:24.872 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.0 to 16.9
17:25:24.872 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55880.0 to 55892.5
17:25:24.873 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55880.0 to -55892.5
17:25:31.514 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 16.9 to 17.0
17:25:31.515 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55892.5 to 55969.5
17:25:31.515 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55892.5 to -55969.5
17:25:36.051 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55969.5 to 56435.0
17:25:36.052 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55969.5 to -56435.0
17:25:40.680 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56435.0 to 56054.0
17:25:40.680 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56435.0 to -56054.0
17:25:46.398 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56054.0 to 56041.0
17:25:46.398 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56054.0 to -56041.0
17:25:52.020 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56041.0 to 56283.0
17:25:52.020 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56041.0 to -56283.0
17:25:57.376 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56283.0 to 55956.5
17:25:57.376 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56283.0 to -55956.5
17:26:02.090 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55956.5 to 56178.0
17:26:02.091 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55956.5 to -56178.0
17:26:07.218 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE (COMMUNICATION_ERROR): java.net.UnknownHostException: spcgw: Temporary failure in name resolution to REMOVING
17:26:07.220 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from REMOVING to REMOVED
17:26:07.221 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from REMOVED to UNINITIALIZED
17:26:07.224 [TRACE] [o.transport.mqtt.MqttBrokerConnection] - Closing the MQTT broker connection 'spcgw'
17:26:07.225 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from UNINITIALIZED to OFFLINE
17:26:07.227 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:09c5d203' changed from OFFLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
17:26:07.408 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56178.0 to 56022.0
17:26:07.408 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56178.0 to -56022.0
17:26:13.043 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56022.0 to 55989.0
17:26:13.043 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56022.0 to -55989.0
17:26:17.686 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55989.0 to 55881.5
17:26:17.687 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55989.0 to -55881.5
17:26:23.080 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55881.5 to 55882.0
17:26:23.080 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55881.5 to -55882.0
17:26:28.809 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55882.0 to 55989.5
17:26:28.813 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55882.0 to -55989.5
17:26:35.225 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55989.5 to 56087.5
17:26:35.226 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55989.5 to -56087.5
17:26:39.948 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56087.5 to 55995.5
17:26:39.949 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56087.5 to -55995.5
17:26:44.534 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55995.5 to 56298.5
17:26:44.534 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55995.5 to -56298.5
17:26:50.508 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56298.5 to 55938.0
17:26:50.509 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56298.5 to -55938.0
17:26:53.349 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:c67230e4
17:26:53.350 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:c67230e4
17:26:53.352 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from UNINITIALIZED to INITIALIZING
17:26:53.356 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from INITIALIZING to OFFLINE
17:26:53.356 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid b13f704e-3d1e-42c6-a0f2-0a0b918481ab
17:26:53.356 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:c67230e4
17:26:53.358 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:c67230e4
17:26:53.361 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Timeout
17:26:53.361 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE (COMMUNICATION_ERROR): Timeout to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
17:26:56.248 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55938.0 to 55913.0
17:26:56.249 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55938.0 to -55913.0
17:27:01.684 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55913.0 to 55951.5
17:27:01.684 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55913.0 to -55951.5
17:27:03.361 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
17:27:03.362 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT. to OFFLINE
17:27:03.363 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid b13f704e-3d1e-42c6-a0f2-0a0b918481ab
17:27:03.369 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
17:27:06.340 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 55951.5 to 56294.0
17:27:06.341 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -55951.5 to -56294.0
17:27:11.624 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56294.0 to 56324.0
17:27:11.625 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56294.0 to -56324.0
17:27:17.121 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56324.0 to 56005.5
17:27:17.122 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56324.0 to -56005.5
17:27:22.021 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56005.5 to 56461.5
17:27:22.022 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56005.5 to -56461.5
17:27:27.246 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 56461.5 to 53752.5
17:27:27.246 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -56461.5 to -53752.5
17:27:33.010 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53752.5 to 53725.5
17:27:33.011 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53752.5 to -53725.5
17:27:38.800 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53725.5 to 53739.5
17:27:38.800 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53725.5 to -53739.5
17:27:43.470 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53739.5 to 53774.5
17:27:43.471 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53739.5 to -53774.5
17:27:48.425 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53774.5 to 53789.0
17:27:48.426 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53774.5 to -53789.0
17:27:54.928 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53789.0 to 53636.0
17:27:54.929 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53789.0 to -53636.0
17:27:59.980 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.0 to 17.1
17:27:59.981 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53636.0 to 53583.0
17:27:59.984 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53636.0 to -53583.0
17:28:03.363 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
17:28:03.364 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT. to OFFLINE
17:28:03.364 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid b13f704e-3d1e-42c6-a0f2-0a0b918481ab
17:28:03.374 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:c67230e4' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
17:28:05.114 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 17.1 to 17.0
17:28:05.114 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 53583.0 to 54976.5
17:28:05.115 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -53583.0 to -54976.5
Did you configure SSL/TLS? If the server side settings and the client side setting differ you would get that message.
Edit: Try without SSL, just to see if where we need to look for the problem.
Hi,
some logs from my side. May be it helps…
cat /var/log/openhab2/events.log | grep mqtt return
2019-12-18 18:33:57.398 [hingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from UNINITIALIZED to INITIALIZING
2019-12-18 18:33:57.633 [hingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from INITIALIZING to OFFLINE
2019-12-18 18:33:59.021 [me.event.ThingUpdatedEvent] - Thing 'mqtt:broker:roomba' has been updated.
2019-12-18 18:33:59.025 [me.event.ThingUpdatedEvent] - Thing 'mqtt:broker:roomba' has been updated.
2019-12-18 18:34:00.724 [hingStatusInfoChangedEvent] - 'mqtt:broker:roomba' changed from OFFLINE to ONLINE
2019-12-18 18:34:45.744 [hingStatusInfoChangedEvent] - 'mqtt:topic:roomba:state' changed from UNINITIALIZED to INITIALIZING
2019-12-18 18:34:46.257 [hingStatusInfoChangedEvent] - 'mqtt:topic:roomba:state' changed from INITIALIZING to ONLINE
cat /var/log/openhab2/openhab.log | grep mqtt return
2019-12-18 18:33:15.204 [INFO ] [roker.internal.EmbeddedBrokerService] - Broker persistence file: mqttembedded.bin
2019-12-18 18:33:17.901 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid embedded-mqtt-broker
2019-12-18 18:33:57.523 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.XXX.XXX.XXX' with clientid <blid>
The connection is secured and read work stable:
/var/log/openhab2/events.log:2019-12-18 19:26:03.834 [vent.ItemStateChangedEvent] - RoombaWifistatJSON changed from {"state":{"reported":{"signal":{"rssi":-42,"snr":46}}}} to {"state":{"reported":{"signal":{"rssi":-43,"snr":47}}}}
/var/log/openhab2/events.log:2019-12-18 19:26:10.031 [vent.ItemStateChangedEvent] - RoombaWifistatJSON changed from {"state":{"reported":{"signal":{"rssi":-43,"snr":47}}}} to {"state":{"reported":{"signal":{"rssi":-42,"snr":47}}}}
Only send strikes… I have no Homie or HomeAssistant devices configured.
Additionally i found this bugreport. It seems that openhab core bug is related.
Kind regards,
Alexander
No, just using port 1883
Hi Jan,
here my openhab.log with error messages on MQTT connecting to Roomba broker using the same setup as falkena. I’m on snapshot 1776 using docker image. There is something going on with session expire and reconnect. The bridge to roomba broker is using secure connection on port 8883 indeed.
openhab.log (41.7 KB)
Interestingly in the end the connection is restored and working fine.
Is there anything else I shall/can provide?