MQTT broker - Server closed connection without DISCONNECT

Setup, Configuration and Use Installation
, ,
41

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 spcgw1
42

Looks 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.

43

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
44 
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.

45

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
46

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.

47

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

48

No, just using port 1883

49

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?

50

@falkena, you are using the embedded broker. Can you check if it is the same with mosquito?

@roryd I have no idea what is wrong at your setup. I think - don‘t know exactly how - mosquito is also writing a log. It would be interesting to see what is in that log when the connection attempt fails.

@ollo Could it be that you publish before any subscription is made?

51

mosquitto.log doesn’t tell me much, apart from almost exclusively these messages:

1576053940: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.

Can someone tell me if I have the correct trace log settings for mqtt? I’m not sure I have the roots correct.

openhab> log:get
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
com.hivemq                                         │ TRACE
com.hivemq.client.mqtt                             │ TRACE
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.eclipse.smarthome                              │ INFO
org.eclipse.smarthome.io.transport.mqtt            │ TRACE
org.eclipse.smarthome.mqttbroker                   │ DEBUG
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.binding.mqtt                           │ TRACE
org.openhab.ui.paper                               │ WARN
org.openhab.ui.paper.internal                      │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ INFO
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR
openhab>
52

Try this to see if your trace-log is set correct:

openhab> bundle:list -s | grep -i mqtt
218 x Active x  80 x 1.1.2                   x com.hivemq.client.mqtt
245 x Active x  80 x 2.5.0                   x org.openhab.binding.mqtt
246 x Active x  81 x 2.5.0                   x org.openhab.binding.mqtt.generic
247 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homeassistant
248 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homie
255 x Active x  80 x 2.5.0                   x org.openhab.core.io.transport.mqtt
openhab>

Maybe this helps ?!

53

Thanks Peter,

openhab> bundle:list -s | grep -i mqtt
206 x Active x  80 x 1.1.2                   x com.hivemq.client.mqtt
234 x Active x  80 x 2.5.0                   x org.openhab.binding.mqtt
235 x Active x  81 x 2.5.0                   x org.openhab.binding.mqtt.generic
236 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homeassistant
237 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homie
240 x Active x  80 x 2.5.0                   x org.openhab.core.io.transport.mqtt
245 x Active x  80 x 1.14.0                  x org.openhab.io.transport.mqtt
248 x Active x  80 x 1.14.0                  x org.openhab.persistence.mqtt
openhab>

I’ve also set all those to TRACE:

openhab> log:get|grep mqtt
com.hivemq.client.mqtt                             x TRACE
org.eclipse.smarthome.io.transport.mqtt            x TRACE
org.eclipse.smarthome.mqttbroker                   x TRACE
org.openhab.binding.mqtt                           x TRACE
org.openhab.binding.mqtt.generic                   x TRACE
org.openhab.binding.mqtt.homeassistant             x TRACE
org.openhab.binding.mqtt.homie                     x TRACE
org.openhab.core.io.transport.mqtt                 x TRACE
org.openhab.io.transport.mqtt                      x TRACE
org.openhab.persistence.mqtt                       x TRACE
openhab>

But I still only see the same 4 TRACE records in the logs:

10:12:31.843 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 78358.0 to 78370.0
10:12:31.843 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -80713.0 to -80741.0
10:12:36.608 [INFO ] [smarthome.event.ItemStateChangedEvent] - AC_Powery changed from 296.0 to 297.0
10:12:36.609 [INFO ] [smarthome.event.ItemStateChangedEvent] - Day_Energy changed from 0.329 to 0.32930000000000004
10:12:36.610 [INFO ] [smarthome.event.ItemStateChangedEvent] - IAC changed from 1.26 to 1.31
10:12:36.610 [INFO ] [smarthome.event.ItemStateChangedEvent] - IDC changed from 0.52 to 0.53
10:12:36.611 [INFO ] [smarthome.event.ItemStateChangedEvent] - UAC changed from 231.6 to 232.9
10:12:36.611 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 644.1 to 645.0
10:12:36.611 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 78370.0 to 78593.0
10:12:36.612 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -80741.0 to -80959.0
10:12:37.891 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:10a9f5d6
10:12:37.892 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:10a9f5d6
10:12:37.896 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from UNINITIALIZED to INITIALIZING
10:12:37.898 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from INITIALIZING to OFFLINE
10:12:37.899 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw7
10:12:37.899 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@2f470034 to discovery topic homeassistant/# on broker mqtt:broker:10a9f5d6
10:12:37.899 [TRACE] [ng.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@614e0cd3 to discovery topic +/+/$homie on broker mqtt:broker:10a9f5d6
10:12:37.904 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Timeout
10:12:37.905 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from OFFLINE (COMMUNICATION_ERROR): Timeout to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
10:12:41.956 [INFO ] [smarthome.event.ItemStateChangedEvent] - AC_Powery changed from 297.0 to 285.0
10:12:41.957 [INFO ] [smarthome.event.ItemStateChangedEvent] - Day_Energy changed from 0.32930000000000004 to 0.32980000000000004
10:12:41.958 [INFO ] [smarthome.event.ItemStateChangedEvent] - Year_Energy changed from 3.9963872499999997 to 3.9963879999999996
10:12:41.958 [INFO ] [smarthome.event.ItemStateChangedEvent] - IAC changed from 1.31 to 1.22
10:12:41.958 [INFO ] [smarthome.event.ItemStateChangedEvent] - IDC changed from 0.53 to 0.51
10:12:41.959 [INFO ] [smarthome.event.ItemStateChangedEvent] - UAC changed from 232.9 to 231.5
10:12:41.959 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 645.0 to 670.8
10:12:41.959 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 78593.0 to 84605.5
10:12:41.960 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -80959.0 to -86974.5
10:12:47.812 [INFO ] [smarthome.event.ItemStateChangedEvent] - AC_Powery changed from 285.0 to 286.0
10:12:47.814 [INFO ] [smarthome.event.ItemStateChangedEvent] - Day_Energy changed from 0.32980000000000004 to 0.3301
10:12:47.814 [INFO ] [smarthome.event.ItemStateChangedEvent] - FAC changed from 49.97 to 49.98
10:12:47.815 [INFO ] [smarthome.event.ItemStateChangedEvent] - UAC changed from 231.5 to 231.0
10:12:47.815 [INFO ] [smarthome.event.ItemStateChangedEvent] - UDC changed from 670.8 to 663.0
10:12:47.815 [INFO ] [smarthome.event.ItemStateChangedEvent] - Grid_Power changed from 84605.5 to 83392.5
10:12:47.815 [INFO ] [smarthome.event.ItemStateChangedEvent] - Load_Power changed from -86974.5 to -85754.5
10:12:47.909 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
10:12:47.911 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT. to OFFLINE
10:12:47.911 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw7
10:12:47.921 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:broker:10a9f5d6' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Server closed connection without DISCONNECT.
10:12:53.284 [INFO ] [smarthome.event.ItemStateChangedEvent] - AC_Powery changed from 286.0 to 288.0
10:12:53.284 [INFO ] [smarthome.event.ItemStateChangedEvent] - Day_Energy changed from 0.3301 to 0.3306
10:12:53.285 [INFO ] [smarthome.event.ItemStateChangedEvent] - Year_Energy changed from 3.9963879999999996 to 3.99638875
10:12:53.285 [INFO ] [smarthome.event.ItemStateChangedEvent] - IAC changed from 1.22 to 1.28
10:12:53.285 [INFO ] [smarthome.event.ItemStateChangedEvent] - UAC changed from 231.0 to 230.2

Edit: I’ve also since uninstalled org.openhab.io.transport.mqtt and org.openhab.persistence.mqtt as they’re v1, but the results are still the same.

54

Sorry that I can’t help anymore, but it was just this line in your first log:

org.eclipse.smarthome.io.transport.mqtt            │ TRACE

which should now be:

org.openhab.io.transport.mqtt                      x TRACE

and the line:

org.openhab.core.io.transport.mqtt                 x TRACE

of which I think it was absent.(If I don’t squint :crazy_face:)

Do you use mqtt1 and mqtt2 simultaneously ?

55

Thanks Peter, I spotted that alright and I’ve since uninstalled the v1 bundles (I actually thought I had already removed them, but obviously not). This is now the setup:

openhab> bundle:list -s|grep -i mqtt
206 x Active x  80 x 1.1.2                   x com.hivemq.client.mqtt
234 x Active x  80 x 2.5.0                   x org.openhab.binding.mqtt
235 x Active x  81 x 2.5.0                   x org.openhab.binding.mqtt.generic
236 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homeassistant
237 x Active x  82 x 2.5.0                   x org.openhab.binding.mqtt.homie
240 x Active x  80 x 2.5.0                   x org.openhab.core.io.transport.mqtt
openhab>
56

Just as a sanity check, I downgraded to 2.5.0 M4 again, and here’s the openhab.log from startup to the creation of a broker in Paper UI, and all looks great - the broker works as intended:

2019-12-19 11:09:18.108 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_IE'.
2019-12-19 11:09:18.109 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SIUnits'.
2019-12-19 11:09:20.355 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.items'
2019-12-19 11:09:20.392 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.items'
2019-12-19 11:09:20.573 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2019-12-19 11:09:20.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.persist'
2019-12-19 11:09:20.758 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lukas.sitemap'
2019-12-19 11:09:20.767 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'inverters.sitemap'
2019-12-19 11:09:20.778 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.sitemap'
2019-12-19 11:09:20.791 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.sitemap'
2019-12-19 11:09:20.864 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.things'
2019-12-19 11:09:20.871 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.things'
2019-12-19 11:09:21.758 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-12-19 11:09:22.323 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://11.153.2.12:8080
2019-12-19 11:09:22.323 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://11.153.2.12:8443
2019-12-19 11:09:22.541 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2019-12-19 11:09:22.568 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt
2019-12-19 11:09:22.714 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2019-12-19 11:09:22.776 [DEBUG] [org.openhab.core.io.transport.mqtt  ] - BundleEvent STARTING - org.openhab.core.io.transport.mqtt
2019-12-19 11:09:22.792 [DEBUG] [org.openhab.core.io.transport.mqtt  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.transport.mqtt.internal.MqttBrokerConnectionServiceInstanceMarker}={esh.factoryservice=true, service.id=358, service.bundleid=227, service.scope=bundle, service.config.category=MQTT, service.pid=org.eclipse.smarthome.mqttbroker, service.config.label=MQTT system broker connection, component.name=org.eclipse.smarthome.io.transport.mqtt.internal.MqttBrokerConnectionServiceInstanceMarker, service.config.description.uri=mqtt:systemBrokerConnectionInstance, component.id=216} - org.openhab.core.io.transport.mqtt
2019-12-19 11:09:22.801 [DEBUG] [org.openhab.core.io.transport.mqtt  ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.transport.mqtt.MqttService}={service.id=359, service.bundleid=227, service.scope=bundle, service.pid=org.eclipse.smarthome.mqtt, component.name=org.eclipse.smarthome.io.transport.mqtt.internal.MqttServiceImpl, component.id=217} - org.openhab.core.io.transport.mqtt
2019-12-19 11:09:22.817 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory, org.openhab.binding.mqtt.discovery.MQTTTopicDiscoveryService}={service.id=360, service.bundleid=221, service.scope=bundle, component.name=org.openhab.binding.mqtt.internal.MqttBrokerHandlerFactory, component.id=205} - org.openhab.binding.mqtt
2019-12-19 11:09:22.834 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=361, service.bundleid=221, service.scope=bundle, component.name=org.openhab.binding.mqtt.internal.discovery.MqttServiceDiscoveryService, component.id=206} - org.openhab.binding.mqtt
2019-12-19 11:09:22.840 [DEBUG] [org.openhab.core.io.transport.mqtt  ] - BundleEvent STARTED - org.openhab.core.io.transport.mqtt
2019-12-19 11:09:23.059 [DEBUG] [org.openhab.io.transport.mqtt       ] - BundleEvent STARTING - org.openhab.io.transport.mqtt
2019-12-19 11:09:23.066 [DEBUG] [penhab.io.transport.mqtt.MqttService] - Starting MQTT Service...
2019-12-19 11:09:23.067 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.async' = false
2019-12-19 11:09:23.070 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.clientId' = openhab
2019-12-19 11:09:23.070 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - clientId property changed. client will be shut down.
2019-12-19 11:09:23.070 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Closing connection to broker 'mqtt'
2019-12-19 11:09:23.071 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.pwd' = <removed>
2019-12-19 11:09:23.071 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.qos' = 0
2019-12-19 11:09:23.072 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.retain' = true
2019-12-19 11:09:23.073 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.url' = tcp://11.153.2.22:1883
2019-12-19 11:09:23.073 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - url property changed. client will be shut down.
2019-12-19 11:09:23.074 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Closing connection to broker 'mqtt'
2019-12-19 11:09:23.074 [DEBUG] [org.openhab.io.transport.mqtt       ] - ServiceEvent REGISTERED - {org.openhab.io.transport.mqtt.MqttService, org.osgi.service.cm.ManagedService}={service.id=371, service.bundleid=233, service.scope=bundle, service.pid=org.openhab.mqtt, component.name=MQTT Connection Service, component.id=226} - org.openhab.io.transport.mqtt
2019-12-19 11:09:23.075 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.user' = spcgw
2019-12-19 11:09:23.075 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2019-12-19 11:09:23.075 [DEBUG] [org.openhab.io.transport.mqtt       ] - BundleEvent STARTED - org.openhab.io.transport.mqtt
2019-12-19 11:09:23.077 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqtt'
2019-12-19 11:09:23.079 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Creating new client for 'tcp://11.153.2.22:1883' using id 'openhab' and file store '/var/lib/openhab2/tmp/mqtt'
2019-12-19 11:09:23.317 [DEBUG] [org.openhab.persistence.mqtt        ] - BundleEvent STARTING - org.openhab.persistence.mqtt
2019-12-19 11:09:23.319 [DEBUG] [org.openhab.persistence.mqtt        ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService}={service.id=379, service.bundleid=237, service.scope=singleton} - org.openhab.persistence.mqtt
2019-12-19 11:09:23.323 [DEBUG] [mqtt.internal.MqttPersistenceService] - Deactivating MQTT Persistence
2019-12-19 11:09:23.323 [DEBUG] [mqtt.internal.MqttPersistenceService] - Configuration updated for MQTT Persistence.
2019-12-19 11:09:23.324 [DEBUG] [mqtt.internal.MqttPersistenceService] - Activating MQTT Persistence
2019-12-19 11:09:23.532 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 8e30a31d-f0ee-4688-9de2-30abe6a52268, base URL = http://localhost:8080)
2019-12-19 11:09:23.776 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - Starting message producer for broker 'mqtt'
2019-12-19 11:09:23.779 [DEBUG] [org.openhab.persistence.mqtt        ] - ServiceEvent REGISTERED - {org.openhab.core.persistence.PersistenceService}={broker=mqtt, service.id=380, topic=/SPC/, service.bundleid=237, service.scope=bundle, message=%1$s, %3$s, service.pid=org.openhab.mqtt-persistence, component.name=org.openhab.persistence.mqtt, component.id=232} - org.openhab.persistence.mqtt
2019-12-19 11:09:23.779 [DEBUG] [org.openhab.persistence.mqtt        ] - BundleEvent STARTED - org.openhab.persistence.mqtt
2019-12-19 11:09:24.100 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2019-12-19 11:09:24.126 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2019-12-19 11:09:24.158 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-12-19 11:09:24.204 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-12-19 11:09:24.207 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTING - org.openhab.binding.mqtt.generic
2019-12-19 11:09:24.210 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider}={service.id=438, service.bundleid=222, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider, component.id=284} - org.openhab.binding.mqtt.generic
2019-12-19 11:09:24.213 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelGroupTypeProvider, org.openhab.binding.mqtt.generic.MqttChannelTypeProvider}={service.id=439, service.bundleid=222, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelTypeProvider, component.id=285} - org.openhab.binding.mqtt.generic
2019-12-19 11:09:24.216 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=440, service.bundleid=222, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.internal.MqttThingHandlerFactory, component.id=286} - org.openhab.binding.mqtt.generic
2019-12-19 11:09:24.218 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTED - org.openhab.binding.mqtt.generic
2019-12-19 11:09:24.218 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTING - org.openhab.binding.mqtt.homeassistant
2019-12-19 11:09:24.223 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=441, service.bundleid=223, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.generic.internal.MqttThingHandlerFactory, component.id=287} - org.openhab.binding.mqtt.homeassistant
2019-12-19 11:09:24.231 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=442, service.bundleid=223, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery, component.id=288} - org.openhab.binding.mqtt.homeassistant
2019-12-19 11:09:24.232 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTED - org.openhab.binding.mqtt.homeassistant
2019-12-19 11:09:24.232 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTING - org.openhab.binding.mqtt.homie
2019-12-19 11:09:24.237 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=443, service.bundleid=224, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.generic.internal.MqttThingHandlerFactory, component.id=289} - org.openhab.binding.mqtt.homie
2019-12-19 11:09:24.239 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=444, service.bundleid=224, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery, component.id=290} - org.openhab.binding.mqtt.homie
2019-12-19 11:09:24.242 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTED - org.openhab.binding.mqtt.homie
2019-12-19 11:10:34.132 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingActions}={service.id=447, service.bundleid=221, service.scope=singleton} - org.openhab.binding.mqtt
2019-12-19 11:10:34.155 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw9 and file store '/var/lib/openhab2/mqtt/11.153.2.22'
2019-12-19 11:10:34.162 [TRACE] [ternal.TopicSubscribeMultiConnection] - Found suitable bridge mqtt:broker:2ff727be for listing to topic +/+/$homie
2019-12-19 11:10:34.162 [TRACE] [ternal.TopicSubscribeMultiConnection] - Found suitable bridge mqtt:broker:2ff727be for listing to topic homeassistant/#

So then I upgraded to 2.5.0 release build, and here’s the same corresponding log:

2019-12-19 11:16:11.824 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SIUnits'.
2019-12-19 11:16:14.223 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.items'
2019-12-19 11:16:14.310 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.items'
2019-12-19 11:16:14.471 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2019-12-19 11:16:14.484 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.persist'
2019-12-19 11:16:14.706 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lukas.sitemap'
2019-12-19 11:16:14.716 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'inverters.sitemap'
2019-12-19 11:16:14.754 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.sitemap'
2019-12-19 11:16:14.767 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.sitemap'
2019-12-19 11:16:14.883 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.things'
2019-12-19 11:16:14.890 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loxone.things'
2019-12-19 11:16:15.698 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-12-19 11:16:16.661 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2019-12-19 11:16:16.967 [DEBUG] [penhab.io.transport.mqtt.MqttService] - Starting MQTT Service...
2019-12-19 11:16:16.969 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.async' = false
2019-12-19 11:16:16.971 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.clientId' = openhab
2019-12-19 11:16:16.971 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - clientId property changed. client will be shut down.
2019-12-19 11:16:16.971 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Closing connection to broker 'mqtt'
2019-12-19 11:16:16.972 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.pwd' = <removed>
2019-12-19 11:16:16.972 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.qos' = 0
2019-12-19 11:16:16.972 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.retain' = true
2019-12-19 11:16:16.972 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.url' = tcp://11.153.2.22:1883
2019-12-19 11:16:16.972 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - url property changed. client will be shut down.
2019-12-19 11:16:16.973 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Closing connection to broker 'mqtt'
2019-12-19 11:16:16.973 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property 'mqtt.user' = spcgw
2019-12-19 11:16:16.973 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2019-12-19 11:16:16.974 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqtt'
2019-12-19 11:16:16.975 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Creating new client for 'tcp://11.153.2.22:1883' using id 'openhab' and file store '/var/lib/openhab2/tmp/mqtt'
2019-12-19 11:16:17.240 [DEBUG] [mqtt.internal.MqttPersistenceService] - Deactivating MQTT Persistence
2019-12-19 11:16:17.241 [DEBUG] [mqtt.internal.MqttPersistenceService] - Configuration updated for MQTT Persistence.
2019-12-19 11:16:17.241 [DEBUG] [mqtt.internal.MqttPersistenceService] - Activating MQTT Persistence
2019-12-19 11:16:17.243 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - Starting message producer for broker 'mqtt'
2019-12-19 11:16:17.492 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://11.153.2.12:8080
2019-12-19 11:16:17.493 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://11.153.2.12:8443
2019-12-19 11:16:17.527 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2019-12-19 11:16:17.547 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 8e30a31d-f0ee-4688-9de2-30abe6a52268, base URL = http://localhost:8080)
2019-12-19 11:16:17.559 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2019-12-19 11:16:17.590 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-12-19 11:16:17.620 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-12-19 11:17:48.357 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@69ce96c3 to discovery topic homeassistant/# on broker mqtt:broker:ce32736e
2019-12-19 11:17:48.358 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@30ed9019 to discovery topic +/+/$homie on broker mqtt:broker:ce32736e
2019-12-19 11:17:48.643 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw10
2019-12-19 11:17:48.654 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery@69ce96c3 to discovery topic homeassistant/# on broker mqtt:broker:ce32736e
2019-12-19 11:17:48.656 [TRACE] [g.mqtt.handler.AbstractBrokerHandler] - Subscribed org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery@30ed9019 to discovery topic +/+/$homie on broker mqtt:broker:ce32736e
2019-12-19 11:17:58.709 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-19 11:17:58.725 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw10
2019-12-19 11:18:58.731 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-19 11:18:58.734 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw10
2019-12-19 11:19:58.735 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '11.153.2.22'. Next attempt in 60000ms
2019-12-19 11:19:58.736 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '11.153.2.22' with clientid spcgw10
57

In the mosquitto, please add/change (adjust log_dest as necessary)

log_dest file c:/users/jan/documents/mosquitto.log
log_type all
connection_messages true
#log_facility
log_timestamp true
log_timestamp_format %Y-%m-%dT%H:%M:%S

This generates a mosquitto.log that should look similar to

2019-12-21T09:15:49: Config loaded from mosquitto.conf.
2019-12-21T09:15:49: Opening ipv6 listen socket on port 1883.
2019-12-21T09:15:49: Opening ipv4 listen socket on port 1883.
2019-12-21T09:15:52: New connection from 127.0.0.1 on port 1883.
2019-12-21T09:15:52: New client connected from 127.0.0.1 as MyClientId (p2, c1, k60).
2019-12-21T09:15:52: No will message specified.
2019-12-21T09:15:52: Sending CONNACK to MyClientId (0, 0)
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	$aws/things/3162831022440790/shadow/# (QoS 0)
2019-12-21T09:15:52: MyClientId 0 $aws/things/3162831022440790/shadow/#
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	homeassistant/# (QoS 0)
2019-12-21T09:15:52: MyClientId 0 homeassistant/#
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	test/number (QoS 0)
2019-12-21T09:15:52: MyClientId 0 test/number
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	homie/thermo_ian/$stats/signal (QoS 0)
2019-12-21T09:15:52: MyClientId 0 homie/thermo_ian/$stats/signal
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	percent/state (QoS 0)
2019-12-21T09:15:52: MyClientId 0 percent/state
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	+/+/$homie (QoS 0)
2019-12-21T09:15:52: MyClientId 0 +/+/$homie
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	wifistat (QoS 0)
2019-12-21T09:15:52: MyClientId 0 wifistat
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:15:52: Received SUBSCRIBE from MyClientId
2019-12-21T09:15:52: 	homeassistant/switch/switch0/restart/config (QoS 0)
2019-12-21T09:15:52: MyClientId 0 homeassistant/switch/switch0/restart/config
2019-12-21T09:15:52: Sending SUBACK to MyClientId
2019-12-21T09:16:52: Received PINGREQ from MyClientId
2019-12-21T09:16:52: Sending PINGRESP to MyClientId
2019-12-21T09:17:52: Received PINGREQ from MyClientId

This should give more insight why the server closed the connection.

58

I got the exact same error message and i finaly found that the tcpd was blocking acces. Editing /etc/hosts.allow /etc/hosts.deny accordingly to my network address and mqtt port resolv the prob for me.

1 Like
59

Can you show how you configured these files? I’m not familiar with that.

60

You can comment out everything in those files and test if the broker works. If you still have an issue then the problem is not related to those files. If the problem is those files you will need to read up on how to set this for your network and purpose.