Mosquitto receives but wont send: It's Killing me

I have checked and re checked. Read and re read the tasmota wiki. Run any of these commands in the Sonoff web log (ip address of sonoff/cs) to glean info that might help. Edited my items file 100 times. tested connections between OH and Mosquitto, used MQTTlens and client-tools to verify connections.
The light WILL NOT TURN ON!!!
Mosquitto and MQTTlens receive status updates from the Sonoff subscribed to:

mosquitto_sub -h localhost -t ‘diana/cord1/#’ -v and diana/cord1/# - respectively

lights.items

Switch Cord1 "Trav's-lamp" { mqtt=">[mosquitto:cmnd/diana/cord1/POWER:command:*:default], <[mosquitto:stat/diana/cord1/POWER:state:default]" }

mosquitto.conf

pid_file /var/run/lib/mosquitto.pid

persistence true

persistence_location /var/lib/mosquitto/

log_dest file /var/log/mosquitto/mosquitto.log

include_dir /etc/mosquitto/conf.d

connection_messages true

allow_anonymous true

mqtt.cfg

mosquitto.url=tcp://localhost:1883
mosquitto.clientId=openhabian
mosquitto.qos=1
mosquitto.retain=true
mosquitto.async=false

Sonoff settings


Host (domus1)

192.168.1.200


Port (1883)

1883


Client Id (DVES_970D9F)

Cord1


User (DVES_USER)

openhabian


Password

•


Topic = %topic% (sonoff)

cord1


Full Topic (%prefix%/%topic%/)

diana/cord1/

the sonoff web log

00:00:00 APP: Project sonoff Cord1 (Topic cord1, Fallback Cord1, GroupTopic sonoffs) Version 5.5.2
00:00:00 Wifi: Connecting to AP1 Travalon in mode 11N as Cord1...
00:00:04 Wifi: Connected
00:00:04 HTTP: Webserver active on Cord1 with IP address 192.168.1.202
00:00:04 UPnP: Multicast (re)joined
00:00:06 MQTT: Attempting connection...
08:02:15 MQTT: Connected
08:02:15 MQTT: diana/cord1/LWT = Online (retained)
08:02:15 MQTT: diana/cord1/cmnd/POWER = 
08:02:15 MQTT: diana/cord1/INFO1 = {"Module":"Sonoff Basic", "Version":"5.5.2", "FallbackTopic":"Cord1", "GroupTopic":"sonoffs"}
08:02:15 MQTT: diana/cord1/INFO2 = {"WebserverMode":"Admin", "Hostname":"Cord1", "IPaddress":"192.168.1.202"}
08:02:15 MQTT: diana/cord1/INFO3 = {"Started":"Software/System restart"}
08:02:16 MQTT: diana/cord1/UPTIME = {"Time":"2017-08-20T08:02:16", "Uptime":1}
08:02:16 UPnP: Multicast (re)joined
08:02:17 MQTT: diana/cord1/RESULT = {"POWER":"OFF"}
08:02:17 MQTT: diana/cord1/POWER = OFF
08:02:24 MQTT: diana/cord1/STATE = {"Time":"2017-08-20T08:02:24", "Uptime":1, "Vcc":3.251, "POWER":"OFF", "Wifi":{"AP":1, "SSID":"Travalon", "RSSI":100, "APMac":"30:5A:3A:A0:4A:18"}}
08:07:24 MQTT: diana/cord1/STATE = {"Time":"2017-08-20T08:07:24", "Uptime":1, "Vcc":3.248, "POWER":"OFF", "Wifi":{"AP":1, "SSID":"Travalon", "RSSI":100, "APMac":"30:5A:3A:A0:4A:18"}}

#If I type power on or off in the web log console, below is the result in the web logs.

08:08:40 CMND: power on
08:08:40 MQTT: diana/cord1/RESULT = {"POWER":"ON"}
08:08:40 MQTT: diana/cord1/POWER = ON
08:08:46 CMND: power off
08:08:47 MQTT: diana/cord1/RESULT = {"POWER":"OFF"}
08:08:47 MQTT: diana/cord1/POWER = OFF
 
and results for for same commands

 openhabian@openHABianPi:/etc/mosquitto$ mosquitto_sub -h localhost -t 'diana/cord1/#' -v
diana/cord1/LWT Online
diana/cord1/STATE {"Time":"2017-08-20T08:02:24", "Uptime":1, "Vcc":3.251, "POWER":"OFF", "Wifi":{"AP":1, "SSID":"Travalon", "RSSI":100, "APMac":"30:5A:3A:A0:4A:18"}}
diana/cord1/STATE {"Time":"2017-08-20T08:07:24", "Uptime":1, "Vcc":3.248, "POWER":"OFF", "Wifi":{"AP":1, "SSID":"Travalon", "RSSI":100, "APMac":"30:5A:3A:A0:4A:18"}}
diana/cord1/RESULT {"POWER":"ON"}
diana/cord1/POWER ON
diana/cord1/RESULT {"POWER":"OFF"}
diana/cord1/POWER OFF

if I toggle from an alternate automation solution UI i get:

:/etc/mosquitto$ mosquitto_sub -h localhost -t 'diana/cord1/#' -v
diana/cord1/STATE {"Time":"2017-08-20T08:12:24", "Uptime":1, "Vcc":3.250, "POWER":"OFF", "Wifi":{"AP":1, "SSID":"Travalon", "RSSI":100, "APMac":"30:5A:3A:A0:4A:18"}}
diana/cord1/power off
diana/cord1/power on
diana/cord1/power off
diana/cord1/power on

If I toggle from HABpanel I get nothing.

All this tells me OH connects to Mosquitto

[02:33:10] openhabian@openHABianPi:/etc/mosquitto$ mosquitto_sub -u openhab -P habopen -t openhab/#
ON

As well as my other clients, HA, MQTTlens, client-tools on different machines.
Mosquitto receives publications, (not from HABpanel) and passes them on.
Except TO the Sonoff.

An excerpt from Tasmotas MQTT features page:

Sonoff responds to the following MQTT commands using MQTT Topic for cmnd/sonoff/<command> and MQTT Message/Payload for <parameter>:

The relay can be controlled with cmnd/sonoff/power on, cmnd/sonoff/power off or cmnd/sonoff/power toggle. Sonoff will send a MQTT status message like stat/sonoff/POWER ON.

The power state message can be sent with the retain flag set. Enable this with cmnd/sonoff/PowerRetain on.

PLEASE…what am I missing?

You haven’t defined a user/pw in mqtt.cfg, is this intentional ? I ask since you show an example of mosquitto_sub were you actually use user/pw…

And here’s some logs

openhab.log

2017-08-20 02:06:06.109 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-08-20 02:06:06.136 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2017-08-20 02:06:06.159 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt
2017-08-20 02:06:06.337 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'Cord1' : 1 subscribers, 1 publishers
2017-08-20 02:06:06.411 [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=203, service.id=321, service.bundleid=237, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-20 02:06:06.497 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-08-20 02:06:06.507 [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=204, service.id=323, service.bundleid=237, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-20 02:06:06.572 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=205, service.id=324, service.bundleid=237, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-20 02:06:23.472 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-08-20 02:06:23.613 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-08-20 02:06:29.134 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-08-20 02:06:29.499 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-08-20 02:11:07.919 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:11:53.019 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:11:54.636 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:14:44.734 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:14:45.851 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:14:47.113 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:14:47.881 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:14:48.505 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:15:06.048 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:20:55.498 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:20:57.431 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:30:48.604 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:30:49.297 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER
2017-08-20 02:30:49.924 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command OFF to cmnd/diana/cord1/POWER
2017-08-20 02:30:50.564 [DEBUG] [inding.mqtt.internal.MqttItemBinding] - Publishing command ON to cmnd/diana/cord1/POWER

events.log

2017-08-20 01:55:51.748 [ItemChannelLinkAddedEvent ] - Link 'WeMoLightSwitch_Switch-wemo:lightswitch:cord:state' has been added.
2017-08-20 01:55:52.010 [ThingAddedEvent           ] - Thing 'ntp:ntp:local' has been added.
2017-08-20 01:55:52.037 [ThingAddedEvent           ] - Thing 'yahooweather:weather:7e4604ff' has been added.
2017-08-20 02:04:42.522 [temChannelLinkRemovedEvent] - Link 'WeMoLightSwitch_Switch => wemo:lightswitch:cord:state' has been removed.
2017-08-20 02:04:45.565 [ThingRemovedEvent         ] - Thing 'ntp:ntp:local' has been removed.
2017-08-20 02:05:56.192 [ItemChannelLinkAddedEvent ] - Link 'WeMoLightSwitch_Switch-wemo:lightswitch:cord:state' has been added.
2017-08-20 02:05:56.626 [ThingAddedEvent           ] - Thing 'ntp:ntp:local' has been added.
2017-08-20 02:05:56.663 [ThingAddedEvent           ] - Thing 'yahooweather:weather:7e4604ff' has been added.
2017-08-20 02:11:07.812 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:11:08.601 [ItemStateChangedEvent     ] - Cord1 changed from NULL to ON
2017-08-20 02:11:53.019 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:11:53.119 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:11:54.638 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:11:54.667 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:14:44.736 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:14:44.790 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:14:45.851 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:14:45.948 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:14:47.116 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:14:47.147 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:14:47.884 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:14:47.962 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:14:48.505 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:14:48.544 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:15:06.048 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:15:06.135 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:20:55.500 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:20:55.648 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:20:57.435 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:20:57.464 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:30:48.606 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:30:48.696 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:30:49.301 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:30:49.351 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON
2017-08-20 02:30:49.924 [ItemCommandEvent          ] - Item 'Cord1' received command OFF
2017-08-20 02:30:50.014 [ItemStateChangedEvent     ] - Cord1 changed from ON to OFF
2017-08-20 02:30:50.563 [ItemCommandEvent          ] - Item 'Cord1' received command ON
2017-08-20 02:30:50.652 [ItemStateChangedEvent     ] - Cord1 changed from OFF to ON

mosquitto.log

1503206027: New connection from 192.168.1.218 on port 1883.
1503206027: New client connected from 192.168.1.218 as 49b20270-6298-468c-989a-64c5c39fb587 (c1, k60).
1503206074: New connection from 192.168.1.202 on port 1883.
1503206074: Client Cord1 already connected, closing old connection.
1503206074: Client Cord1 disconnected.
1503206074: New client connected from 192.168.1.202 as Cord1 (c1, k15, u'openhabian').
1503206447: Client 49b20270-6298-468c-989a-64c5c39fb587 disconnected.
1503206474: New connection from 192.168.1.218 on port 1883.
1503206474: New client connected from 192.168.1.218 as 9dc2024b-5672-488f-b2da-47e3c0937133 (c1, k60).
1503206958: New connection from 192.168.1.202 on port 1883.
1503206958: Client Cord1 already connected, closing old connection.
1503206958: Client Cord1 disconnected.
1503206958: New client connected from 192.168.1.202 as Cord1 (c1, k15, u'openhabian').
1503207062: New connection from 192.168.1.202 on port 1883.
1503207062: Client Cord1 already connected, closing old connection.
1503207062: Client Cord1 disconnected.
1503207062: New client connected from 192.168.1.202 as Cord1 (c1, k15, u'openhabian').
1503207255: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1503209056: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1503209378: New connection from ::1 on port 1883.
1503209378: New client connected from ::1 as mosqsub|2520-openHABian (c1, k60).
1503209403: New connection from 192.168.1.218 on port 1883.
1503209403: New client connected from 192.168.1.218 as mosqsub/10876-travis-As (c1, k60).
1503209481: New connection from 192.168.1.218 on port 1883.
1503209481: New client connected from 192.168.1.218 as mosqsub/10886-travis-As (c1, k60).
1503209898: Socket error on client mosqsub|2520-openHABian, disconnecting.
1503209907: New connection from ::1 on port 1883.
1503209907: New client connected from ::1 as mosqsub|2657-openHABian (c1, k60).
1503210535: New connection from 192.168.1.202 on port 1883.
1503210535: Client Cord1 already connected, closing old connection.
1503210535: Client Cord1 disconnected.
1503210535: New client connected from 192.168.1.202 as Cord1 (c1, k15, u'openhabian').
1503210857: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1503210920: Socket error on client mosqsub|2657-openHABian, disconnecting.
1503210933: New connection from ::1 on port 1883.
1503210933: New client connected from ::1 as mosqsub|2897-openHABian (c1, k60).
1503211027: Socket error on client mosqsub|2897-openHABian, disconnecting.
1503211038: New connection from ::1 on port 1883.
1503211038: New client connected from ::1 as mosqsub|2920-openHABian (c1, k60).
1503211136: Socket error on client mosqsub|2920-openHABian, disconnecting.
1503211139: New connection from ::1 on port 1883.
1503211139: New client connected from ::1 as mosqsub|2937-openHABian (c1, k60).
1503211700: Client openhabian disconnected.
1503211781: New connection from 127.0.0.1 on port 1883.
1503211781: New client connected from 127.0.0.1 as openhabian (c1, k60).
1503212081: Client openhabian disconnected.
1503212155: New connection from 127.0.0.1 on port 1883.
1503212156: New client connected from 127.0.0.1 as openhabian (c1, k60).
1503212534: New connection from 192.168.1.202 on port 1883.
1503212535: Client Cord1 already connected, closing old connection.
1503212535: Client Cord1 disconnected.
1503212535: New client connected from 192.168.1.202 as Cord1 (c1, k15, u'openhabian').
1503212538: Socket error on client mosqsub|2937-openHABian, disconnecting.
1503212542: New connection from ::1 on port 1883.
1503212542: New client connected from ::1 as mosqsub|4600-openHABian (c1, k60).
1503212658: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1503212681: Client openhabian disconnected.
1503212762: New connection from 127.0.0.1 on port 1883.
1503212762: New client connected from 127.0.0.1 as openhabian (c1, k60).
1503214181: Socket error on client mosqsub|4600-openHABian, disconnecting.
1503214239: New connection from ::1 on port 1883.
1503214239: New client connected from ::1 as mosqsub|5503-openHABian (c1, k60, u'openhabian').
1503214366: New connection from ::1 on port 1883.
1503214366: New client connected from ::1 as mosqpub|5534-openHABian (c1, k60, u'openhab').
1503214366: Client mosqpub|5534-openHABian disconnected.
1503214390: Socket error on client mosqsub|5503-openHABian, disconnecting.
1503214395: New connection from ::1 on port 1883.
1503214395: New client connected from ::1 as mosqsub|5544-openHABian (c1, k60, u'openhab').
1503214398: New connection from ::1 on port 1883.
1503214398: New client connected from ::1 as mosqpub|5545-openHABian (c1, k60, u'openhab').
1503214398: Client mosqpub|5545-openHABian disconnected.
1503214459: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1503214850: Socket error on client mosqsub|5544-openHABian, disconnecting.
[02:47:45] openhabian@openHABianPi:/var/log/mosquitto$ 

No password defined.

Try the following:

mosquitto.url=tcp://127.0.0.1:1883

stop OH2, modify mqtt.cfg as above, delete /var/lib/openhab2/config/org/openhab/mqtt.config (just in case), start OH2, monitor openhab.log and mosquitto.log for the OH2->Broker connection.

1 Like

@Dim
all done. how do i monitor in real time?

tail -f /var/log/openhab2/openhab.log -f /var/log/mosquitto.log

there seems to be something wrong going on with the connections to the Broker. I see a lot of re/dis/connection attempts from various clients (local & remote).
You need to debug that aspect with focus on the OH2 (local) client connection. Try to use also a different clientId in you mqtt.cfg to see if this helps.

diff client id for which client?

for the openHAB2 client (set it in /etc/openhab2/services/mqtt.cfg):

mosquitto.url=tcp://127.0.0.1:1883
mosquitto.clientId=newClientId
mosquitto.qos=1
mosquitto.retain=true
mosquitto.async=false

thats the ID for Mosquitto? AS in cord1 is for my Sonoff?

It’s now as such:
mosquitto.url=tcp://127.0.0.1:1883
mosquitto.clientId=mosqtt
mosquitto.qos=1
mosquitto.retain=true
mosquitto.async=false

that’s the unique clientId for the connection from a (any) client to the server (Mosquitto Broker)
Each client has to have a unique ID otherwise there is a conflict that causes the re/dis/connects.

Yes, your Sonoff clientId is Cord1 (with capital C) at ip 192.168.1.202

can I assign an ID to OH?
got to give the logs a bit of time had to amend the command and re run it.

you already did:

This is the clienId that openHAB2 will use to connect as a client to your MQTT Broker.
You can change it to whatever you like… just make sure that it is unique for this server across all clients :slight_smile:

1 Like

oops… I just saw this…
I think that you have an error in your topics… shouldn’t they be:

Switch Cord1 "Trav's-lamp" { mqtt=">[mosquitto:diana/cord1/power:command:*:default], <[mosquitto:diana/cord1/state:state:default]" }

double check this plz

Switch Cord1 "Trav's-lamp" { mqtt=">[mosquitto:cmnd/diana/cord1/POWER:command:*:default], <[mosquitto:stat/diana/cord1/POWER:state:default]" }

lets try another edit.

I don’t use Sonoff but I saw in your logs above that the topics that Sonoff is using are different than the defaults mentioned in the wiki.

For the command topic, it looks like you should be using: diana/cord1/power
not sure about the state… it looks like it should be diana/cord1/state but that’s not a simple ON/OFF payload. You may need to use another topic of a transformation to extract from the payload the ON/OFF state.

pulling the topic from the web logs

09:33:57 CMND: Topic
09:33:57 MQTT: diana/cord1/RESULT = {"Topic":"cord1"}
09:34:44 CMND: Fulltopic
09:34:44 MQTT: diana/cord1/RESULT = {"FullTopic":"diana/cord1/"}
1 Like

Sonoff responds to the following MQTT commands using MQTT Topic for cmnd/sonoff/ and MQTT Message/Payload for :

The relay can be controlled with cmnd/sonoff/power on, cmnd/sonoff/power off or cmnd/sonoff/power toggle. Sonoff will send a MQTT status message like stat/sonoff/POWER ON.

Status query:

tasmota/sonoff-mylight/cmnd/Power1 ← //empty message
↳ tasmota/sonoff-mylight/stat/RESULT → {“POWER1”:“OFF”}
↳ tasmota/sonoff-mylight/stat/POWER1 → OFF

try without the cmnd part in front of diana.
I need to read the wikis of Sonoff also :slight_smile:

this is where I’m getting my information.