this is typical of the mqtt problems… they are afraid of me 
Anyway… joking aside… i wanted to understand why this was happening (2nd connection) and I still don’t get it.
I closed the issue on github with the simple comment: “I have no clue” 
1 Like
I will revise all the steps again… will keep you informed! (but here the 2nd connection never appeared)
this (mDNS) is a discovery method that the Sonoff is using to identify remote MQTT Servers (Brokers).
Don’t worry about this one. It’s an extra, nice to have feature that doesn’t apply in your case since you hard code the remote broker in your Sonoff configuration. I don’t think that Mosquiito with a default configuration will reply to this mDNS scan.
the question now is: Why the Sonoff times out the connection to the broker…
I don’t know what could the root cause… is there any kind of keepalive setting on the Sonoff?
How often do these disconnects and then reconnects happen from the Sonoff to the broker?
Are you sure that you are using a unique clientId for each client being connected to the broker?
I didn’t do any special setting on Sonoff.
Yes, I had this issue before, now the only clientIds are the Sonoff and the MQTT.fx.
I’m looking at the mosquitto.log and now the MQTT.fx is connecting and disconnecting to the server:
1500985689: Client mosqpub|4645-raspberryp disconnected.
1500985704: New connection from 127.0.0.1 on port 1883.
1500985704: New client connected from 127.0.0.1 as mosqpub|4648-raspberryp (c1, k60, u’openhabian’).
1500985704: Client mosqpub|4648-raspberryp disconnected.
1500985726: New connection from 127.0.0.1 on port 1883.
1500985726: New client connected from 127.0.0.1 as mosqpub|4653-raspberryp (c1, k60, u’openhabian’).
1500985726: Client mosqpub|4653-raspberryp disconnected.
1500985747: New connection from 10.0.0.101 on port 1883.
1500985747: New client connected from 10.0.0.101 as mosqpub|4656-raspberryp (c1, k60, u’openhabian’).
1500985747: Client mosqpub|4656-raspberryp disconnected.
1500985808: New connection from 10.0.0.101 on port 1883.
1500985808: New client connected from 10.0.0.101 as mosqpub|4663-raspberryp (c1, k60, u’openhabian’).
1500985808: Client mosqpub|4663-raspberryp disconnected.
1500985811: New connection from 10.0.0.101 on port 1883.
I tried to send messages and I now the publish doesn’t work on MQTT.fx. I don’t know if the socket error is because of the publish message. The client name is “6a29e68559d34eb1a73e7bd9f304ef01”
1500986350: Socket error on client 6a29e68559d34eb1a73e7bd9f304ef01, disconnecting.
1500985811: Client mosqpub|4664-raspberryp disconnected.
1500986145: New connection from 10.0.0.101 on port 1883.
@narf27 congratulations!
I’m reviewing step by step everything again,
I’d like to ask you to share your configuration files or any other changes you made that you think that might be useful… I’ll check with my files again…
thank you
I have stopped and started OH2. The log is below:
2017-07-26 22:56:31.955 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://10.0.0.101:8080
2017-07-26 22:56:31.971 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://10.0.0.101:8443
2017-07-26 22:56:45.249 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘sonoff.items’
2017-07-26 22:56:52.892 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘casa.sitemap’
2017-07-26 22:56:58.569 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-07-26 22:56:58.962 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:17d6c495
2017-07-26 22:56:59.000 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-07-26 22:56:59.498 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:17d6c495
2017-07-26 22:56:59.860 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-07-26 22:56:59.875 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-07-26 22:56:59.881 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2017-07-26 22:56:59.922 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTED - org.openhab.binding.mqtt
2017-07-26 22:57:00.351 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=197, service.id=320, service.bundleid=200, service.scope=bundle} - org.openhab.binding.mqtt
2017-07-26 22:57:00.420 [DEBUG] [penhab.io.transport.mqtt.MqttService] - Starting MQTT Service…
2017-07-26 22:57:00.434 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=195, service.id=319, service.bundleid=200, service.scope=bundle} - org.openhab.binding.mqtt
2017-07-26 22:57:00.460 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item Abajur_light
2017-07-26 22:57:00.487 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item ‘Abajur_light’ : 1 subscribers, 1 publishers
2017-07-26 22:57:00.515 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item LivingRoom_Light_Reachable
2017-07-26 22:57:00.530 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item ‘LivingRoom_Light_Reachable’ : 1 subscribers, 0 publishers
2017-07-26 22:57:00.539 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item LivingRoom_Light_RSSI
2017-07-26 22:57:00.543 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item ‘LivingRoom_Light_RSSI’ : 1 subscribers, 0 publishers
2017-07-26 22:57:00.551 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item LivingRoom_Light_Verbose
2017-07-26 22:57:00.554 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item ‘LivingRoom_Light_Verbose’ : 3 subscribers, 0 publishers
2017-07-26 22:57:00.562 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/, service.pid=org.openhab.mqtt-eventbus, component.name=org.openhab.binding.mqtt.eventbus, component.id=196, service.id=322, service.bundleid=200, service.scope=bundle} - org.openhab.binding.mqtt
2017-07-26 22:57:00.617 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-07-26 22:57:00.635 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - Initializing MQTT Event Bus Binding
2017-07-26 22:57:00.637 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus State Publisher
2017-07-26 22:57:00.638 [DEBUG] [org.openhab.io.transport.mqtt ] - ServiceEvent REGISTERED - {org.openhab.io.transport.mqtt.MqttService, org.osgi.service.cm.ManagedService}={service.pid=org.openhab.mqtt, component.name=MQTT Connection Service, component.id=202, service.id=318, service.bundleid=203, service.scope=bundle} - org.openhab.io.transport.mqtt
2017-07-26 22:57:00.639 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus State Subscriber
2017-07-26 22:57:00.641 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus Command Publisher
2017-07-26 22:57:00.644 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus Command Subscriber
2017-07-26 22:57:00.647 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT Event Bus Binding initialization completed.
2017-07-26 22:57:00.660 [DEBUG] [org.openhab.io.transport.mqtt ] - BundleEvent STARTING - org.openhab.io.transport.mqtt
2017-07-26 22:57:00.661 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property: raspberrypi.clientId = openHAB2
2017-07-26 22:57:00.665 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property: raspberrypi.pwd = password
2017-07-26 22:57:00.666 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property: raspberrypi.url = tcp://127.0.0.1:1883
2017-07-26 22:57:00.669 [TRACE] [penhab.io.transport.mqtt.MqttService] - Processing property: raspberrypi.user = openhabian
2017-07-26 22:57:00.671 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-07-26 22:57:00.681 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection ‘raspberrypi’
2017-07-26 22:57:00.695 [DEBUG] [org.openhab.io.transport.mqtt ] - BundleEvent STARTED - org.openhab.io.transport.mqtt
2017-07-26 22:57:00.728 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Creating new client for ‘tcp://127.0.0.1:1883’ using id ‘openHAB2’ and file store ‘/var/lib/openhab2/tmp/raspberrypi’
2017-07-26 22:57:00.752 [WARN ] [mqtt.internal.MqttPersistenceService] - mqtt-persistence:topic
2017-07-26 22:57:00.755 [WARN ] [mqtt.internal.MqttPersistenceService] - mqtt-persistence:message
2017-07-26 22:57:01.233 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘stat/sonoff-abajur/POWER’
2017-07-26 22:57:01.255 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘tele/sonoff-abajur/LWT’
2017-07-26 22:57:01.272 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘tele/sonoff-abajur/STATE’
2017-07-26 22:57:01.279 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘tele/sonoff-abajur/INFO1’
2017-07-26 22:57:01.283 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘stat/sonoff-abajur/STATUS2’
2017-07-26 22:57:01.292 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker ‘raspberrypi’ on topic ‘stat/sonoff-abajur/RESULT’
2017-07-26 22:57:01.296 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - Starting message producer for broker ‘raspberrypi’
2017-07-26 22:57:01.301 [TRACE] [t.mqtt.internal.MqttBrokerConnection] - Starting message producer for broker ‘raspberrypi’
2017-07-26 22:57:01.646 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-07-26 22:57:01.796 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
I didn’t see the Sonoff connection at OpenHAB log, the only connection is from Raspberry PI, Client id OpenHAB2.
At the same time that I started the service, I disconnected and connected Sonoff, and it appears at the console:
00:00:00 APP: Project sonoff Sonoff (Topic sonoff-abajur, Fallback DVES_A7F83D, GroupTopic sonoffs) Version 5.2.1
00:00:00 Wifi: Connecting to AP1 Home in mode 11N as sonoff-abajur-6205…
00:00:05 Wifi: Connected
00:00:05 mDNS: Initialized
00:00:05 HTTP: Webserver active on sonoff-abajur-6205.local with IP address 10.0.0.104
00:00:07 MQTT: Attempting connection…
02:56:31 mDNS: Query done with 0 mqtt services found
02:56:31 MQTT: Connected
BUT when I see the mosquitto.log it appears that Sonoff (DVES_A7F83D) is connected…
1501120591: New connection from 10.0.0.104 on port 1883.
1501120591: New client connected from 10.0.0.104 as DVES_A7F83D (c1, k15, u’openhabian’).
1501120621: New connection from 127.0.0.1 on port 1883.
1501120621: New client connected from 127.0.0.1 as openHAB2 (c1, k60, u’openhabian’).
1501122104: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
Any clues??
Paulo
that is your openHAB2 system (with clientId openHAB2) connecting to the broker (with server name raspberrypi)
You will not see the Sonoff connecting to OH2 within the openhab.log since the Sonoff is a MQTT client for the broker.
You see the Sonoff connecting to the broker in the mosquitto.log (and this is working fine)
Remember the way that stuff are interconnected: OH2<->Broker(Mosquitto)<->Sonoff
If your item configs are correct, you will see (in openhab.log) the MQTT messages coming to OH2 from the Broker when the Sonoff publishes something to a topic. The same is true when OH2 will publish something to the Broker for the Sonoff at a destination topic (where the Sonoff is subscribing to).
You always have the Mosquitto MQTT server as an intermediate (oversimplified: that’s the meaning of the word broker… Mosquitto is brokering messages)
Your logs look clean and the OH2<->Broker connection looks good and established.
Post your items configs and the Sonoff config to check the topics.
Ps: I would recommend uninstalling MQTT persistence service addon and MQTT Action addon (if installed)
1 Like
it worked!!!
The only thing that I did was unistalling MQTT persistence… (MQTT action was uninstalled too, but not now…)
I want to check again if this is the real cause, but I am feared to do that… 
If you really want me to do that to double check, which files should I backup in order to retrieve them in case of error??
Paulo
1 Like
Nah, forget it… No need to try to replicate the problem.
Have fun with the OH2 & Sonoff stuff !
to report an issue (that can be then later classified as a bug from the maintainers), you need to be able to provide clear steps to reproduce the issue…
Can you document the steps that anyone can perform to reach to the same outcome (problem) as you were experiencing ?
Well I really am suspicious that MQTT Action and/or MQTT persistence is the responsible for MQTT not working… this was my only change, after that Sonoff magically started to respond to everything…
But I confess that I’m feared to activate these Action/Persistence and after that MQTT stops working… 
1 Like
sorry i got here late. seems yours is working now, too.
if you still need configs let me know!
1 Like