Author Topic: MQTT Client Plugin  (Read 29424 times)

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #60 on: September 05, 2016, 02:44:21 am »
I'm connecting to mosquitto.
before uploading the last file the connection went well.

Below my log

Code: [Select]
# cat /tmp/log/cmh/LuaUPnP.log | grep SensorMqtt1

06 09/05/16 7:16:43.224 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"ArmedTripped\":0,\"DeviceId\":114,\"DeviceName\":\"MKT Garagepoort\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:DoorSensor:1\",\"OldArmedTripped\":1,\"RoomId\":1,\"RoomName\":\"1-Alarmsysteem\",\"ServiceId\":\"urn:micasaverde-com:serviceId:SecuritySensor1\",\"Time\":1473052602,\"Variable\":\"ArmedTripped\"}","Topic":"vera/MKT Garagepoort/ArmedTripped"} now: {"Payload":"{\"DeviceId\":114,\"DeviceName\":\"MKT Garagepoort\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:DoorSensor:1\",\"OldTripped\":1,\"RoomId\":1,\"RoomName\":\"1-Alarmsysteem\",\"ServiceId\":\"urn:micasaverde-com:serviceId:SecuritySensor1\",\"Time\":1473052603,\"Tripped\":0,\"Variable\":\"Tripped\"}","Topic":"vera/MKT Garagepoort/Tripped"} #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x35670680>
06 09/05/16 8:17:02.452 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Disconnected now: Connected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
06 09/05/16 8:17:02.517 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 1 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
06 09/05/16 8:17:02.521 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"DeviceId\":114,\"DeviceName\":\"MKT Garagepoort\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:DoorSensor:1\",\"OldTripped\":1,\"RoomId\":1,\"RoomName\":\"1-Alarmsysteem\",\"ServiceId\":\"urn:micasaverde-com:serviceId:SecuritySensor1\",\"Time\":1473052603,\"Tripped\":0,\"Variable\":\"Tripped\"}","Topic":"vera/MKT Garagepoort/Tripped"} now: {"Payload":"{\"DeviceId\":195,\"DeviceName\":\"Presence\",\"DeviceType\":\"urn:schemas-dcineco-com:device:MSwitch195:1\",\"OldStatus2\":0,\"RoomId\":12,\"RoomName\":\"10-Location\",\"ServiceId\":\"urn:dcineco-com:serviceId:MSwitch1\",\"Status2\":1,\"Time\":1473056222,\"Variable\":\"Status2\"}","Topic":"vera/Presence/Status2"} #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
06 09/05/16 8:17:02.601 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Disconnected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
06 09/05/16 8:17:02.604 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
06 09/05/16 8:17:02.679 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"DeviceId\":195,\"DeviceName\":\"Presence\",\"DeviceType\":\"urn:schemas-dcineco-com:device:MSwitch195:1\",\"OldStatus2\":0,\"RoomId\":12,\"RoomName\":\"10-Location\",\"ServiceId\":\"urn:dcineco-com:serviceId:MSwitch1\",\"Status2\":1,\"Time\":1473056222,\"Variable\":\"Status2\"}","Topic":"vera/Presence/Status2"} now: {"Payload":"{\"DeviceId\":18,\"DeviceName\":\"House Modes Plugin\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:HouseModes:1\",\"HMode\":1,\"OldHMode\":2,\"RoomId\":3,\"RoomName\":\"6-System\",\"ServiceId\":\"urn:micasaverde-com:serviceId:HouseModes1\",\"Time\":1473056222,\"Variable\":\"HMode\"}","Topic":"vera/House Modes Plugin/HMode"} #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b376310>
50 09/05/16 8:27:02.829 luup_log:188: SensorMqtt plugin: loading library L_SensorMqtt1 ... <0x2c4df680>
50 09/05/16 8:27:03.054 luup_log:188: SensorMqtt plugin: library L_SensorMqtt1 loaded <0x2c4df680>
06 09/05/16 8:27:03.157 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x2c4df680>
06 09/05/16 8:27:03.163 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Disconnected now: Connected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2c4df680>
06 09/05/16 8:27:03.185 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 1 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2c4df680>
06 09/05/16 8:27:08.101 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Disconnected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x334df680>
06 09/05/16 8:27:08.103 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x334df680>
« Last Edit: September 06, 2016, 10:47:01 am by stefaanbolle »

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #61 on: September 05, 2016, 08:53:15 am »
I'm connecting to mosquitto.
before uploading the last file the connection went well.

Below my log

# cat /tmp/log/cmh/LuaUPnP.log | grep SensorMqtt1

Thanks.  I appreciate the testing...  I'm also using mosquito 1.4.8 for my testing and have two Vera+ units running UI7 and one Vera3 running UI5 and all are reporting over mqtt very reliably.

1.  Based upon your logs, I believe it is connecting and delivering payloads but reporting the "connection" status incorrectly.
2.  While I'm not seeing this issue on my installs, I just made one small update to the plugin to pre-allocate the "connection" status service variables to eliminate the __LEAK__ warning on UI5 and perhaps resolve the inconsistent status reporting that you are seeing.
3.  Please upgrade to the latest plugin, INCLUDING uploading/refreshing the dependencies because they were updated too.
4, Then grep for SensorMqtt - not SensorMqtt1 - and reload the luup engine.  Copy the connection status and at least one variable change update.

Here is an example of my output, albeit on UI5:

Code: [Select]
$ ssh vera.home tail -f /var/log/cmh/LuaUPnP.log | grep SensorMqtt
09 09/05/16 8:44:05.233 JobHandler_LuaUPnP::Run device 53 MQTT Sender room 4 type urn:schemas-sensor-mqtt-se:device:SensorMqtt:1 id  parent 0/0xdadc30 upnp: 0 <0x2b27e000>
50 09/05/16 8:44:07.104 luup_log:53: SensorMqtt plugin: loading library L_SensorMqtt1 ... <0x2bbb1680>
50 09/05/16 8:44:07.175 luup_log:53: SensorMqtt plugin: library L_SensorMqtt1 loaded <0x2bbb1680>
50 09/05/16 8:44:07.176 luup_log:53: SensorMqtt:  Initializing SensorMqtt <0x2bbb1680>
06 09/05/16 8:44:07.203 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2bbb1680>
50 09/05/16 8:44:07.204 luup_log:53: SensorMqtt:  Connect to MQTT, mqttServerIp: 10.0.1.220 mqttServerPort: 1883 <0x2bbb1680>
50 09/05/16 8:44:07.208 luup_log:53: SensorMqtt:  Successfully connected to broker: 10.0.1.220 on port 1883 <0x2bbb1680>
50 09/05/16 8:44:07.210 luup_log:53: SensorMqtt:  MQTT connection status changed from "Disconnected" to "Connected" <0x2bbb1680>
06 09/05/16 8:44:07.211 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Connected #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bbb1680>
06 09/05/16 8:44:07.211 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2bbb1680>

06 09/05/16 8:45:37.913 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"CurrentTemperature\":60,\"DeviceId\":47,\"DeviceName\":\"Carport Temp Sensor\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:TemperatureSensor:1\",\"OldCurrentTemperature\":59,\"RoomId\":2,\"RoomName\":\"Outside\",\"ServiceId\":\"urn:upnp-org:serviceId:TemperatureSensor1\",\"Time\":1473078975,\"Variable\":\"CurrentTemperature\"}","Topic":"Vera/30002905/TemperatureSensor1/47"} now: {"Payload":"{\"DeviceId\":29,\"DeviceName\":\"Exterior Cameras (Power)\",\"DeviceType\":\"urn:schemas-upnp-org:device:BinaryLight:1\",\"OldTarget\":1,\"RoomId\":4,\"RoomName\":\"Supporting Devices & Scenes\",\"ServiceId\":\"urn:upnp-org:serviceId:SwitchPower1\",\"Target\":0,\"Time\":1473079537,\"Variable\":\"Target\"}","Topic":"Vera/30002905/SwitchPower1/29"} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2d9b1680>
06 09/05/16 8:45:38.123 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"DeviceId\":29,\"DeviceName\":\"Exterior Cameras (Power)\",\"DeviceType\":\"urn:schemas-upnp-org:device:BinaryLight:1\",\"OldTarget\":1,\"RoomId\":4,\"RoomName\":\"Supporting Devices & Scenes\",\"ServiceId\":\"urn:upnp-org:serviceId:SwitchPower1\",\"Target\":0,\"Time\":1473079537,\"Variable\":\"Target\"}","Topic":"Vera/30002905/SwitchPower1/29"} now: {"Payload":"{\"DeviceId\":29,\"DeviceName\":\"Exterior Cameras (Power)\",\"DeviceType\":\"urn:schemas-upnp-org:device:BinaryLight:1\",\"OldStatus\":1,\"RoomId\":4,\"RoomName\":\"Supporting Devices & Scenes\",\"ServiceId\":\"urn:upnp-org:serviceId:SwitchPower1\",\"Status\":0,\"Time\":1473079538,\"Variable\":\"Status\"}","Topic":"Vera/30002905/SwitchPower1/29"} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b9b1680>
06 09/05/16 8:48:15.157 Device_Variable::m_szValue_set device: 53 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttLastMessage was: {"Payload":"{\"DeviceId\":29,\"DeviceName\":\"Exterior Cameras (Power)\",\"DeviceType\":\"urn:schemas-upnp-org:device:BinaryLight:1\",\"OldStatus\":1,\"RoomId\":4,\"RoomName\":\"Supporting Devices & Scenes\",\"ServiceId\":\"urn:upnp-org:serviceId:SwitchPower1\",\"Status\":0,\"Time\":1473079538,\"Variable\":\"Status\"}","Topic":"Vera/30002905/SwitchPower1/29"} now: {"Payload":"{\"CurrentLevel\":90,\"DeviceId\":46,\"DeviceName\":\"Carport Motion Sensor\",\"DeviceType\":\"urn:schemas-micasaverde-com:device:MotionSensor:1\",\"OldCurrentLevel\":89,\"RoomId\":2,\"RoomName\":\"Outside\",\"ServiceId\":\"urn:micasaverde-com:serviceId:HumiditySensor1\",\"Time\":1473079695,\"Variable\":\"CurrentLevel\"}","Topic":"Vera/30002905/HumiditySensor1/46"} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b9b1680>

Thanks again for the testing and feedback.
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #62 on: September 05, 2016, 09:51:37 am »
Thanks a lot Blacey!
The connection still reports "disconnected".
After reloading LUUP it becomes connected for a second and then returns disconnected.

Below some log lines
Code: [Select]
06 09/05/16 15:43:55.102 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Disconnected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x32f37680>
06 09/05/16 15:43:55.103 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x32f37680>
root@MiOS_30105293:/tmp/log/cmh# cat LuaUPnP.log | grep SensorMqtt
09 09/05/16 15:42:51.361 JobHandler_LuaUPnP::Run device 188 MQTT Publish room 4 type urn:schemas-sensor-mqtt-se:device:SensorMqtt:1 cat 3:-1 id  parent 0/0x9fa4b0 upnp: 0 plugin:0 pnp:0 mac: ip: <0x2b9e3310>
09 09/05/16 15:43:23.792 JobHandler_LuaUPnP::Run device 188 MQTT Publish room 4 type urn:schemas-sensor-mqtt-se:device:SensorMqtt:1 cat 3:-1 id  parent 0/0x101d4b0 upnp: 0 plugin:0 pnp:0 mac: ip: <0x2b4f6310>
50 09/05/16 15:43:49.819 luup_log:188: SensorMqtt plugin: loading library L_SensorMqtt1 ... <0x2bf37680>
50 09/05/16 15:43:49.947 luup_log:188: SensorMqtt plugin: library L_SensorMqtt1 loaded <0x2bf37680>
50 09/05/16 15:43:49.948 luup_log:188: SensorMqtt:  Initializing SensorMqtt <0x2bf37680>
06 09/05/16 15:43:49.987 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x2bf37680>
50 09/05/16 15:43:49.988 luup_log:188: SensorMqtt:  Connect to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883 <0x2bf37680>
50 09/05/16 15:43:49.991 luup_log:188: SensorMqtt:  Successfully connected to broker: 192.168.1.40 on port 1883 <0x2bf37680>
50 09/05/16 15:43:49.992 luup_log:188: SensorMqtt:  MQTT connection status changed from "Disconnected" to "Connected" <0x2bf37680>
06 09/05/16 15:43:49.993 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Disconnected now: Connected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2bf37680>
06 09/05/16 15:43:50.016 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 1 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2bf37680>
50 09/05/16 15:43:55.101 luup_log:188: SensorMqtt:  MQTT connection status changed from "Connected" to "Disconnected" <0x32f37680>
06 09/05/16 15:43:55.102 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Disconnected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x32f37680>
06 09/05/16 15:43:55.103 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x32f37680>
09 09/05/16 15:49:45.408 JobHandler_LuaUPnP::Run device 188 MQTT Publish room 4 type urn:schemas-sensor-mqtt-se:device:SensorMqtt:1 cat 3:-1 id  parent 0/0xeb94b0 upnp: 0 plugin:0 pnp:0 mac: ip: <0x2b731310>
50 09/05/16 15:50:11.513 luup_log:188: SensorMqtt plugin: loading library L_SensorMqtt1 ... <0x2c173680>
50 09/05/16 15:50:11.627 luup_log:188: SensorMqtt plugin: library L_SensorMqtt1 loaded <0x2c173680>
50 09/05/16 15:50:11.637 luup_log:188: SensorMqtt:  Initializing SensorMqtt <0x2c173680>
06 09/05/16 15:50:11.718 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x2c173680>
50 09/05/16 15:50:11.719 luup_log:188: SensorMqtt:  Connect to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883 <0x2c173680>
50 09/05/16 15:50:11.728 luup_log:188: SensorMqtt:  Successfully connected to broker: 192.168.1.40 on port 1883 <0x2c173680>
50 09/05/16 15:50:11.730 luup_log:188: SensorMqtt:  MQTT connection status changed from "Disconnected" to "Connected" <0x2c173680>
06 09/05/16 15:50:11.730 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Disconnected now: Connected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2c173680>
06 09/05/16 15:50:11.763 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 0 now: 1 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2c173680>
50 09/05/16 15:50:16.103 luup_log:188: SensorMqtt:  MQTT connection status changed from "Connected" to "Disconnected" <0x33173680>
06 09/05/16 15:50:16.104 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerStatus was: Connected now: Disconnected #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x33173680>
06 09/05/16 15:50:16.106 Device_Variable::m_szValue_set device: 188 service: urn:upnp-sensor-mqtt-se:serviceId:SensorMqtt1 variable: mqttServerConnected was: 1 now: 0 #hooks: 1 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x33173680>
« Last Edit: September 06, 2016, 10:47:18 am by stefaanbolle »

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #63 on: September 05, 2016, 11:07:10 am »
Thanks a lot Blacey!
The connection still reports "disconnected".
After reloading LUUP it becomes connected for a second and then returns disconnected.

Ok, I just pushed another update that will report debug log messages when Verbose logging is enabled on the Vera.  Please do the following so we can figure this out:

1.  Enable Verbose logging on your Vera Controller
2.  Install the latest plugin (only the L_SensorMqtt1.lua and I_SensorMqtt1.xml changed)
3.  Collect logs using
Code: [Select]
grep '\(^01\|^02\|^35\|^50\).*SensorMqtt'4.  Report results here.  Note, it will be easier to read the logs if you post them as code blocks.

Also, please provide your Mosquitto and Vera Firmware versions.

Thanks.  Looking forward to figuring out this mystery.

Here is a sample of what we should see:
Code: [Select]
50 09/05/16 11:38:03.143 luup_log:53: SensorMqtt: Loading plugin module L_SensorMqtt1 ... <0x2b951680>
50 09/05/16 11:38:03.208 luup_log:53: SensorMqtt: Plugin module L_SensorMqtt1 loaded <0x2b951680>
50 09/05/16 11:38:03.209 luup_log:53: SensorMqtt: Initializing SensorMqtt <0x2b951680>
50 09/05/16 11:38:03.237 luup_log:53: SensorMqtt: Connecting to MQTT, mqttServerIp: 10.0.1.220 mqttServerPort: 1883... <0x2b951680>
50 09/05/16 11:38:03.239 luup_log:53: SensorMqtt: Successfully connected to broker: 10.0.1.220 on port 1883 <0x2b951680>
35 09/05/16 11:38:03.242 luup_log:53: SensorMqtt: setConnectionStatus:  currentStatus = true previousStatus = false <0x2b951680>
50 09/05/16 11:38:03.242 luup_log:53: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2b951680>
35 09/05/16 11:38:03.261 luup_log:53: SensorMqtt: ************************************************ MQTT Settings ************************************************ <0x2b951680>
35 09/05/16 11:38:03.261 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:HVAC_OperatingState1 on variable ModeState with label ModeState <0x2b951680>
35 09/05/16 11:38:03.262 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:HVAC_OperatingState1 on variable ModeStateForEnergy with label ModeStateForEnergy <0x2b951680>
35 09/05/16 11:38:03.263 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:HVAC_UserOperatingMode1 on variable ModeStatus with label ModeStatus <0x2b951680>
35 09/05/16 11:38:03.264 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:HVAC_UserOperatingMode1 on variable ModeTarget with label ModeTarget <0x2b951680>
35 09/05/16 11:38:03.265 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:HVAC_UserOperatingMode1 on variable EnergyModeStatus with label EnergyModeStatus <0x2b951680>
35 09/05/16 11:38:03.266 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:HVAC_UserOperatingMode1 on variable EnergyModeTarget with label EnergyModeTarget <0x2b951680>
35 09/05/16 11:38:03.267 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:TemperatureSensor1 on variable CurrentTemperature with label CurrentTemperature <0x2b951680>
35 09/05/16 11:38:03.270 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:EnergyMetering1 on variable Watts with label Watts <0x2b951680>
35 09/05/16 11:38:03.275 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:EnergyMetering1 on variable UserSuppliedWattage with label UserSuppliedWattage <0x2b951680>
35 09/05/16 11:38:03.281 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:GenericSensor1 on variable CurrentLevel with label CurrentLevel <0x2b951680>
35 09/05/16 11:38:03.282 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:SwitchPower1 on variable Status with label Status <0x2b951680>
35 09/05/16 11:38:03.289 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:SwitchPower1 on variable Target with label Target <0x2b951680>
35 09/05/16 11:38:03.296 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:HaDevice1 on variable BatteryLevel with label BatteryLevel <0x2b951680>
35 09/05/16 11:38:03.308 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:HumiditySensor1 on variable CurrentLevel with label CurrentLevel <0x2b951680>
35 09/05/16 11:38:03.310 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:TemperatureSetpoint1_Cool on variable CurrentSetpoint with label CurrentSetpoint <0x2b951680>
35 09/05/16 11:38:03.311 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:TemperatureSetpoint1_Cool on variable SetpointTarget with label SetpointTarget <0x2b951680>
35 09/05/16 11:38:03.312 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:LightSensor1 on variable CurrentLevel with label CurrentLevel <0x2b951680>
35 09/05/16 11:38:03.313 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable ArmedTripped with label ArmedTripped <0x2b951680>
35 09/05/16 11:38:03.316 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Tripped with label Tripped <0x2b951680>
35 09/05/16 11:38:03.318 luup_log:53: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Armed with label Armed <0x2b951680>
35 09/05/16 11:38:03.320 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:TemperatureSetpoint1_Heat on variable CurrentSetpoint with label CurrentSetpoint <0x2b951680>
35 09/05/16 11:38:03.321 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:TemperatureSetpoint1_Heat on variable SetpointTarget with label SetpointTarget <0x2b951680>
35 09/05/16 11:38:03.322 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:Dimming1 on variable LoadLevelTarget with label LoadLevelTarget <0x2b951680>
35 09/05/16 11:38:03.325 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:Dimming1 on variable LoadLevelStatus with label LoadLevelStatus <0x2b951680>
35 09/05/16 11:38:03.328 luup_log:53: SensorMqtt: Watching urn:upnp-org:serviceId:HVAC_FanOperatingMode1 on variable Mode with label Mode <0x2b951680>
35 09/05/16 11:38:49.913 luup_log:53: SensorMqtt: Watch event - device: 19 variable: Watts value 40 => 36 <0x2b751680>
50 09/05/16 11:38:49.917 luup_log:53: SensorMqtt: Sending [Living Room Lamp] Watts changed to 36 from 40 on topic Vera/30002905/EnergyMetering1/19 <0x2b751680>
35 09/05/16 11:38:49.918 luup_log:53: SensorMqtt: Publish topic: Vera/30002905/EnergyMetering1/19 message:{"DeviceId":19,"DeviceName":"Living Room Lamp","DeviceType":"urn:schemas-upnp-org:device:DimmableLight:1","OldWatts":40,"RoomId":8,"RoomName":"Living Room","ServiceId":"urn:micasaverde-com:serviceId:EnergyMetering1","Time":1473089929,"Variable":"Watts","Watts":36} <0x2b751680>
35 09/05/16 11:38:49.925 luup_log:53: SensorMqtt: Watch event - device: 19 variable: LoadLevelStatus value 40 => 36 <0x2b751680>
50 09/05/16 11:38:49.929 luup_log:53: SensorMqtt: Sending [Living Room Lamp] LoadLevelStatus changed to 36 from 40 on topic Vera/30002905/Dimming1/19 <0x2b751680>
35 09/05/16 11:38:49.929 luup_log:53: SensorMqtt: Publish topic: Vera/30002905/Dimming1/19 message:{"DeviceId":19,"DeviceName":"Living Room Lamp","DeviceType":"urn:schemas-upnp-org:device:DimmableLight:1","LoadLevelStatus":36,"OldLoadLevelStatus":40,"RoomId":8,"RoomName":"Living Room","ServiceId":"urn:upnp-org:serviceId:Dimming1","Time":1473089929,"Variable":"LoadLevelStatus"} <0x2b751680>
35 09/05/16 11:38:51.282 luup_log:53: SensorMqtt: Watch event - device: 19 variable: Watts value 36 => 5 <0x2b751680>
50 09/05/16 11:38:51.285 luup_log:53: SensorMqtt: Sending [Living Room Lamp] Watts changed to 5 from 36 on topic Vera/30002905/EnergyMetering1/19 <0x2b751680>
35 09/05/16 11:38:51.286 luup_log:53: SensorMqtt: Publish topic: Vera/30002905/EnergyMetering1/19 message:{"DeviceId":19,"DeviceName":"Living Room Lamp","DeviceType":"urn:schemas-upnp-org:device:DimmableLight:1","OldWatts":36,"RoomId":8,"RoomName":"Living Room","ServiceId":"urn:micasaverde-com:serviceId:EnergyMetering1","Time":1473089931,"Variable":"Watts","Watts":5} <0x2b751680>
35
« Last Edit: September 05, 2016, 11:40:24 am by blacey »
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #64 on: September 06, 2016, 02:57:17 am »
Below the requested info:
Vera 3 with firmware 1.7.855
Mosquitto version 1.4.10 on Raspberry Pi 2B

Code: [Select]
cat /tmp/log/cmh/LuaUPnP.log | grep '\(^01\|^02\|^35\|^50\).*SensorMqtt'
50 09/06/16 8:52:37.021 luup_log:188: SensorMqtt: Loading plugin module L_SensorMqtt1 ... <0x2b9d3680>
50 09/06/16 8:52:37.187 luup_log:188: SensorMqtt: Plugin module L_SensorMqtt1 loaded <0x2b9d3680>
50 09/06/16 8:52:37.187 luup_log:188: SensorMqtt: Initializing SensorMqtt <0x2b9d3680>
50 09/06/16 8:52:37.230 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x2b9d3680>
50 09/06/16 8:52:37.233 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x2b9d3680>
50 09/06/16 8:52:37.235 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2b9d3680>
50 09/06/16 8:52:37.312 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x2b9d3680>
50 09/06/16 8:54:10.764 luup_log:188: SensorMqtt: Loading plugin module L_SensorMqtt1 ... <0x2b5a1680>
50 09/06/16 8:54:10.887 luup_log:188: SensorMqtt: Plugin module L_SensorMqtt1 loaded <0x2b5a1680>
50 09/06/16 8:54:10.908 luup_log:188: SensorMqtt: Initializing SensorMqtt <0x2b5a1680>
50 09/06/16 8:54:10.957 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x2b5a1680>
35 09/06/16 8:54:10.958 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x2b5a1680>
50 09/06/16 8:54:10.960 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x2b5a1680>
35 09/06/16 8:54:10.962 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = true previousStatus = false <0x2b5a1680>
50 09/06/16 8:54:10.963 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2b5a1680>
35 09/06/16 8:54:11.006 luup_log:188: SensorMqtt: ************************************************ MQTT Settings ************************************************ <0x2b5a1680>
35 09/06/16 8:54:11.006 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable ArmedTripped with label ArmedTripped <0x2b5a1680>
35 09/06/16 8:54:11.046 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Tripped with label Tripped <0x2b5a1680>
35 09/06/16 8:54:11.055 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Armed with label Armed <0x2b5a1680>
35 09/06/16 8:54:11.066 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:HouseModes1 on variable HMode with label HMode <0x2b5a1680>
35 09/06/16 8:54:11.068 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:HouseModes1 on variable Message with label Message <0x2b5a1680>
35 09/06/16 8:54:11.081 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status3 with label Status3 <0x2b5a1680>
35 09/06/16 8:54:11.105 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status1 with label Status1 <0x2b5a1680>
35 09/06/16 8:54:11.107 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status4 with label Status4 <0x2b5a1680>
35 09/06/16 8:54:11.108 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status2 with label Status2 <0x2b5a1680>
35 09/06/16 8:54:11.114 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventTime with label LastLogEventTime <0x2b5a1680>
35 09/06/16 8:54:11.122 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventUser with label LastLogEventUser <0x2b5a1680>
35 09/06/16 8:54:11.129 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEvent with label LastLogEvent <0x2b5a1680>
35 09/06/16 8:54:11.138 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventPartition with label LastLogEventPartition <0x2b5a1680>
35 09/06/16 8:54:11.148 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x2b5a1680>
35 09/06/16 8:54:11.148 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = true <0x2b5a1680>
50 09/06/16 8:54:11.149 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x2b5a1680>
35 09/06/16 8:54:16.103 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x325a1680>
35 09/06/16 8:54:16.104 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = false <0x325a1680>
35 09/06/16 8:54:21.103 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x325a1680>
35 09/06/16 8:54:21.104 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = false <0x325a1680>
35 09/06/16 8:54:26.104 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x325a1680>
35 09/06/16 8:54:26.104 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = false <0x325a1680>
35 09/06/16 8:54:31.012 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x325a1680>
35 09/06/16 8:54:31.013 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = false <0x325a1680>
35 09/06/16 8:54:36.103 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x325a1680>
35 09/06/16 8:54:36.104 luup_log:188: SensorMqtt: setConnectionStatus:  currentStatus = false previousStatus = false <0x325a1680>

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #65 on: September 06, 2016, 09:02:22 am »
Below the requested info:
Vera 3 with firmware 1.7.855
Mosquitto version 1.4.10 on Raspberry Pi 2B

Thanks - this is very helpful. The logs that confirm it is indeed an issue with the actual connection and not an issue with incorrect connection status reporting.  The way the connection state machine now works is that during plugin initialization it will attempt to connect to the broker and then process mqtt events in 5 second intervals (adequate for a persistent connection without any active subscriptions).  If the connection goes down, the client will continue to check for any new mqtt events but won't try to reconnect to the broker until it needs to publish a message; I did this intentionally because currently the client is a publish-only client but we are considering extending the client to subscribe to commands received via mqtt).  The "Connection down" is reported in 5 second intervals so that is what we are seeing (every attempt to check for mqtt events fails with the connection down). 

The only difference between our setups is that I am running the mqtt 1.4.8 from the ubuntu xenial PPA on an RPI 2B and I am not using an authenticated connection.  I have the SensorMqtt plugin running on both 1.7.2138 on V+ and 1.5.622 on V3.

I am traveling so it is a bit difficult for me to gin up a configuration similar to yours so I have published a new version for you to test that now provides a last will and testament message in the connection request.  Without the mosquito server logs, it is hard for me to know why the connection isn't staying up (seems like the broker isn't sending a CONNACK for some reason).  Please install the latest version and see if it resolves the issue (you only need to update the L_SensorMqtt1.lua file).

If this change does not resolve the problem, it would be very helpful if you could enable debug logging on the mosquitto broker and provide the logs from both the Vera (verbose and grep provided above to include debug info).  To enable logging on your RPI2, change /etc/mosquitto/mosquitto.conf to include log_type all:

Code: [Select]
log_dest file /var/log/mosquitto/mosquitto.log
log_type all

Then either kill -HUP the mosquitto process or use
Code: [Select]
sudo systemctl restart mosquitto so the broker will load the new config file.  Then tail -f /var/log/mosquitto/mosquitto.log on your RPI2 and restart the luup engine to reload the SensorMqtt plugin so it goes through the connection process.  Finally, trigger one of your watched variables so that the client initiates a reconnect and publish.

Hopefully this will provide all the necessary detail so we can see what is going on from the broker perspective.  Again, maybe you won't need to go through these additional steps with the revised plugin but if it doesn't work, we will need these additional details to triage further and remedy.

Thanks again for your testing...
« Last Edit: September 06, 2016, 09:11:30 am by blacey »
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #66 on: September 06, 2016, 09:26:41 am »
Mosquitto version 1.4.10 on Raspberry Pi 2B

I just thought of something else...  Are you using
Code: [Select]
clientid_prefixes prefix in your mosquito.conf?  If so, I changed the connection request in the large robustness refactoring to include the serial number for the Vera so it is unique to each controller.  The Vera will now pass 'Vera-(SerialNumber)' in the connection request - for example, Vera-3000299.  I will change the connection log to include the ClientId that the Vera is using to establish the connection but if your broker is configured with a prefix that doesn't match the current SensorMqtt client, then it would reject the connection request.  Perhaps you can also provide your mosquitto configuration file(s) here?
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #67 on: September 06, 2016, 10:45:51 am »
I updated to the latest version.
Debug logging will be enabled later on on Mosquitto

Below my mosquitto.conf
Code: [Select]
pid_file /var/run/mosquitto.pid
allow_zero_length_clientid false
persistent_client_expiration 7d
allow_duplicate_messages false
port 1883
listener 8883
cafile /etc/mosquitto/ca.crt
capath /etc/mosquitto/
certfile /etc/mosquitto/pki.crt
keyfile /etc/mosquitto/pki.key
tls_version tlsv1
require_certificate false
persistence true
persistence_location /var/lib/mosquitto/
log_dest file /var/log/mosquitto/mosquitto.log
connection_messages true
log_timestamp true
allow_anonymous false
password_file /etc/mosquitto/passwd
include_dir /etc/mosquitto/conf.d

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #68 on: September 06, 2016, 10:57:12 am »
With the newest version of the plugin (reloaded LUUP + rebooted):
Mosquitto log gives:
Code: [Select]
1473173330: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1473173330: Config loaded from /etc/mosquitto/mosquitto.conf.
1473173330: Opening ipv4 listen socket on port 8883.
1473173330: Opening ipv6 listen socket on port 8883.
1473173330: Warning: Address family not supported by protocol
1473173330: Opening ipv4 listen socket on port 1883.
1473173330: Opening ipv6 listen socket on port 1883.
1473173330: Warning: Address family not supported by protocol
1473173340: New connection from 192.168.1.40 on port 1883.
1473173340: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473173340: Sending CONNACK to openhab (0, 0)
1473173340: Received SUBSCRIBE from openhab
1473173340: owntracks/s7/event (QoS 0)
1473173340: openhab 0 owntracks/s7/event
1473173340: Sending SUBACK to openhab
1473173340: Received SUBSCRIBE from openhab
1473173340: /openHAB/in/+/state (QoS 0)
1473173340: openhab 0 /openHAB/in/+/state
1473173340: Sending SUBACK to openhab
1473173387: New connection from 192.168.1.251 on port 1883.
root@rpi2server:/etc/mosquitto# cat /var/log/mosquitto/mosquitto.log
1473173277: Socket error on client <unknown>, disconnecting.
1473173329: Error in poll: Interrupted system call.
1473173329: mosquitto version 1.4.10 terminating
1473173330: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1473173330: Config loaded from /etc/mosquitto/mosquitto.conf.
1473173330: Opening ipv4 listen socket on port 8883.
1473173330: Opening ipv6 listen socket on port 8883.
1473173330: Warning: Address family not supported by protocol
1473173330: Opening ipv4 listen socket on port 1883.
1473173330: Opening ipv6 listen socket on port 1883.
1473173330: Warning: Address family not supported by protocol
1473173340: New connection from 192.168.1.40 on port 1883.
1473173340: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473173340: Sending CONNACK to openhab (0, 0)
1473173340: Received SUBSCRIBE from openhab
1473173340: owntracks/s7/event (QoS 0)
1473173340: openhab 0 owntracks/s7/event
1473173340: Sending SUBACK to openhab
1473173340: Received SUBSCRIBE from openhab
1473173340: /openHAB/in/+/state (QoS 0)
1473173340: openhab 0 /openHAB/in/+/state
1473173340: Sending SUBACK to openhab
1473173387: New connection from 192.168.1.251 on port 1883.
1473173387: Sending CONNACK to 192.168.1.251 (0, 5)
1473173387: Socket error on client <unknown>, disconnecting.
1473173400: Received PUBLISH from openhab (d0, q0, r0, m0, '/openHAB/persist/feed', ... (17 bytes))
root@rpi2server:/etc/mosquitto# cat /var/log/mosquitto/mosquitto.log
1473173277: Socket error on client <unknown>, disconnecting.
1473173329: Error in poll: Interrupted system call.
1473173329: mosquitto version 1.4.10 terminating
1473173330: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1473173330: Config loaded from /etc/mosquitto/mosquitto.conf.
1473173330: Opening ipv4 listen socket on port 8883.
1473173330: Opening ipv6 listen socket on port 8883.
1473173330: Warning: Address family not supported by protocol
1473173330: Opening ipv4 listen socket on port 1883.
1473173330: Opening ipv6 listen socket on port 1883.
1473173330: Warning: Address family not supported by protocol
1473173340: New connection from 192.168.1.40 on port 1883.
1473173340: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473173340: Sending CONNACK to openhab (0, 0)
1473173340: Received SUBSCRIBE from openhab
1473173340: owntracks/s7/event (QoS 0)
1473173340: openhab 0 owntracks/s7/event
1473173340: Sending SUBACK to openhab
1473173340: Received SUBSCRIBE from openhab
1473173340: /openHAB/in/+/state (QoS 0)
1473173340: openhab 0 /openHAB/in/+/state
1473173340: Sending SUBACK to openhab
1473173387: New connection from 192.168.1.251 on port 1883.
1473173387: Sending CONNACK to 192.168.1.251 (0, 5)
1473173387: Socket error on client <unknown>, disconnecting.
1473173400: Received PUBLISH from openhab (d0, q0, r0, m0, '/openHAB/persist/feed', ... (17 bytes))
root@rpi2server:/etc/mosquitto# cat /var/log/mosquitto/mosquitto.log
1473173277: Socket error on client <unknown>, disconnecting.
1473173329: Error in poll: Interrupted system call.
1473173329: mosquitto version 1.4.10 terminating
1473173330: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1473173330: Config loaded from /etc/mosquitto/mosquitto.conf.
1473173330: Opening ipv4 listen socket on port 8883.
1473173330: Opening ipv6 listen socket on port 8883.
1473173330: Warning: Address family not supported by protocol
1473173330: Opening ipv4 listen socket on port 1883.
1473173330: Opening ipv6 listen socket on port 1883.
1473173330: Warning: Address family not supported by protocol
1473173340: New connection from 192.168.1.40 on port 1883.
1473173340: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473173340: Sending CONNACK to openhab (0, 0)
1473173340: Received SUBSCRIBE from openhab
1473173340: owntracks/s7/event (QoS 0)
1473173340: openhab 0 owntracks/s7/event
1473173340: Sending SUBACK to openhab
1473173340: Received SUBSCRIBE from openhab
1473173340: /openHAB/in/+/state (QoS 0)
1473173340: openhab 0 /openHAB/in/+/state
1473173340: Sending SUBACK to openhab
1473173387: New connection from 192.168.1.251 on port 1883.
1473173387: Sending CONNACK to 192.168.1.251 (0, 5)
1473173387: Socket error on client <unknown>, disconnecting.
1473173400: Received PUBLISH from openhab (d0, q0, r0, m0, '/openHAB/persist/feed', ... (17 bytes))
root@rpi2server:/etc/mosquitto# tail -f /var/log/mosquitto/mosquitto.log
1473173340: openhab 0 owntracks/s7/event
1473173340: Sending SUBACK to openhab
1473173340: Received SUBSCRIBE from openhab
1473173340: /openHAB/in/+/state (QoS 0)
1473173340: openhab 0 /openHAB/in/+/state
1473173340: Sending SUBACK to openhab
1473173387: New connection from 192.168.1.251 on port 1883.
1473173387: Sending CONNACK to 192.168.1.251 (0, 5)
1473173387: Socket error on client <unknown>, disconnecting.

vera log
Code: [Select]
cat /tmp/log/cmh/LuaUPnP.log | grep '\(^01\|^02\|^35\|^50\).*SensorMqtt'
35 09/06/16 16:52:55.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:00.104 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:05.118 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:10.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:15.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:20.111 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:25.116 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:30.104 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>
35 09/06/16 16:53:35.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x32f73680>

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #69 on: September 06, 2016, 11:23:50 am »
So I can deduce what is happening, what is the IP address of the broker on your RPI and the IP address of your Vera?  An earlier log showed MQTT client configured to connect to 192.168.1.40

Code: [Select]
50 09/06/16 8:52:37.187 luup_log:188: SensorMqtt: Initializing SensorMqtt <0x2b9d3680>
50 09/06/16 8:52:37.230 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x2b9d3680>
50 09/06/16 8:52:37.233 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x2b9d3680>
50 09/06/16 8:52:37.235 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2b9d3680>
50 09/06/16 8:52:37.312 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x2b9d3680>

But your RPI broker log shows that IP address is used by your openhab node. 
Code: [Select]
1473173340: New connection from 192.168.1.40 on port 1883.
1473173340: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473173340: Sending CONNACK to openhab (0, 0)
1473173340: Received SUBSCRIBE from openhab
1473173340: owntracks/s7/event (QoS 0)

Are you running your broker on the same IP 192.168.1.140 as OpenHab or is your broker on a different IP?

Also, it looks like Vera is on 192.168.1.251?  Am I correct in deducing that?

Also, if you haven't, please enable the debug logging on your broker by adding the two lines I posted earlier to your mosquitto.conf file (I didn't see them in what you provided but the output looks like it was enabled).  Here is what I see on my broker with log_type all enabled.

Code: [Select]
1473174909: mosquitto version 1.4.8 terminating
1473174910: mosquitto version 1.4.8 (build date Fri, 19 Feb 2016 12:03:16 +0100) starting
1473174910: Config loaded from /etc/mosquitto/mosquitto.conf.
1473174910: Opening ipv4 listen socket on port 1883.
1473174910: Opening ipv6 listen socket on port 1883.
1473174910: Bridge local.brookside doing local SUBSCRIBE on topic Vera/#
1473174910: Connecting bridge brookside-to-mqtt (mqtt.blacey.com:8883)
1473174910: Bridge brookside sending CONNECT
1473174910: Received CONNACK on connection local.brookside.
1473174910: Bridge local.brookside sending UNSUBSCRIBE (Mid: 95, Topic: Vera/#)
1473174910: Received PUBACK from local.brookside (Mid: 94)
1473174910: Received UNSUBACK from local.brookside
1473174923: New connection from 10.0.1.225 on port 1883.
1473174923: New client connected from 10.0.1.225 as Vera-30002905 (c1, k60).
1473174923: Sending CONNACK to Vera-30002905 (0, 0)
1473174923: Received PUBLISH from Vera-30002905 (d0, q0, r0, m0, 'Vera/30002905/SwitchPower1/19', ... (255 bytes))
1473174923: Sending PUBLISH to local.brookside (d0, q0, r0, m0, 'Vera/30002905/SwitchPower1/19', ... (255 bytes))
1473174923: Received PUBLISH from Vera-30002905 (d0, q0, r0, m0, 'Vera/30002905/EnergyMetering1/19', ... (262 bytes))
1473174923: Sending PUBLISH to local.brookside (d0, q0, r0, m0, 'Vera/30002905/EnergyMetering1/19', ... (262 bytes))
1473174992: Received PINGREQ from Vera-30002905
1473174992: Sending PINGRESP to Vera-30002905

Finally, during your test, please poke your Vera to publishing a message by tripping or changing one of the watched variables - that will cause the Vera to try to connect again (perhaps you did in your last test?)

Stefan, I would also like to confirm that we are working with the same version of the dependencies.  Please compute the md5 checksums as follows:

Code: [Select]
root@MiOS_30002905:~# openssl dgst -md5 /usr/lib/lua/mqtt_library.lua
MD5(/usr/lib/lua/mqtt_library.lua)= d277c620e1d55b6981c905d0a336216f
root@MiOS_30002905:~# openssl dgst -md5 /usr/lib/lua/utility.lua
MD5(/usr/lib/lua/utility.lua)= 178cf5910a31768703efecf744691700

All of that said, I plan to make some changes but they won't change these results here:

  • Log the MQTT client id used by the SensorMqtt plugin
  • Add the MQTT client id to the Settings tab
  • Change the connection model to attempt reconnect based upon a user-supplied reconnect-interval (currently it only tries to reconnect when it publishes a message because the client is only a publisher but this change will be needed in the future when the SensorMqtt client also becomes a subscriber)

Looking forward to your reply with additional details!
« Last Edit: September 06, 2016, 10:02:28 pm by blacey »
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #70 on: September 07, 2016, 02:43:02 am »
My openhab 1.8.3 is running on 192.168.1.40
Mosquitto is also running on 192.168.1.40
Vera is 192.168.1.251

log_type all is set in mosquitto.
Code: [Select]
pid_file /var/run/mosquitto.pid
allow_zero_length_clientid false
persistent_client_expiration 7d
allow_duplicate_messages false
port 1883
listener 8883
cafile /etc/mosquitto/ca.crt
capath /etc/mosquitto/
certfile /etc/mosquitto/pki.crt
keyfile /etc/mosquitto/pki.key
tls_version tlsv1
require_certificate false
persistence true
persistence_location /var/lib/mosquitto/
log_dest file /var/log/mosquitto/mosquitto.log
log_type all
connection_messages true
log_timestamp true
allow_anonymous false
password_file /etc/mosquitto/passwd
include_dir /etc/mosquitto/conf.d

Below my logs
Mosquitto
Code: [Select]
1473230930: Sending PINGRESP to openhab
1473230983: Error in poll: Interrupted system call.
1473230983: mosquitto version 1.4.10 terminating
1473230983: mosquitto version 1.4.10 (build date Thu, 25 Aug 2016 10:12:09 +0100) starting
1473230983: Config loaded from /etc/mosquitto/mosquitto.conf.
1473230983: Opening ipv4 listen socket on port 8883.
1473230983: Opening ipv6 listen socket on port 8883.
1473230983: Warning: Address family not supported by protocol
1473230983: Opening ipv4 listen socket on port 1883.
1473230983: Opening ipv6 listen socket on port 1883.
1473230983: Warning: Address family not supported by protocol
1473231011: New connection from 192.168.1.251 on port 1883.
1473231011: Sending CONNACK to 192.168.1.251 (0, 5)
1473231011: Socket error on client <unknown>, disconnecting.
1473231018: New connection from 192.168.1.40 on port 1883.
1473231018: New client connected from 192.168.1.40 as openhab (c1, k60, u'openhab').
1473231018: Sending CONNACK to openhab (0, 0)
1473231031: New connection from 192.168.1.251 on port 1883.
1473231031: Sending CONNACK to 192.168.1.251 (0, 5)
1473231031: Socket error on client <unknown>, disconnecting.
1473231031: New connection from 192.168.1.251 on port 1883.
1473231031: Sending CONNACK to 192.168.1.251 (0, 5)
1473231031: Socket error on client <unknown>, disconnecting.
1473231031: New connection from 192.168.1.251 on port 1883.
1473231031: Sending CONNACK to 192.168.1.251 (0, 5)
1473231031: Socket error on client <unknown>, disconnecting.
1473231031: New connection from 192.168.1.251 on port 1883.
1473231031: Sending CONNACK to 192.168.1.251 (0, 5)
1473231031: Socket error on client <unknown>, disconnecting.
1473231032: New connection from 192.168.1.251 on port 1883.
1473231032: Sending CONNACK to 192.168.1.251 (0, 5)
1473231032: Socket error on client <unknown>, disconnecting.
1473231048: Received SUBSCRIBE from openhab
1473231048: owntracks/s7/event (QoS 0)
1473231048: openhab 0 owntracks/s7/event
1473231048: Sending SUBACK to openhab
1473231050: Received SUBSCRIBE from openhab

vera
Code: [Select]
50 09/07/16 8:50:11.700 luup_log:188: SensorMqtt: Loading plugin module L_SensorMqtt1 ... <0x2c2eb680>
50 09/07/16 8:50:11.842 luup_log:188: SensorMqtt: Plugin module L_SensorMqtt1 loaded <0x2c2eb680>
50 09/07/16 8:50:11.842 luup_log:188: SensorMqtt: Initializing SensorMqtt <0x2c2eb680>
50 09/07/16 8:50:11.868 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x2c2eb680>
35 09/07/16 8:50:11.869 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x2c2eb680>
50 09/07/16 8:50:11.872 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x2c2eb680>
50 09/07/16 8:50:11.873 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2c2eb680>
35 09/07/16 8:50:11.898 luup_log:188: SensorMqtt: ************************************************ MQTT Settings ************************************************ <0x2c2eb680>
35 09/07/16 8:50:11.899 luup_log:188: SensorMqtt: Watching urn:akbooer-com:serviceId:Netatmo1 on variable LastUpdated with label LastUpdated <0x2c2eb680>
35 09/07/16 8:50:11.906 luup_log:188: SensorMqtt: Watching urn:akbooer-com:serviceId:Netatmo1 on variable Timestamp with label Timestamp <0x2c2eb680>
35 09/07/16 8:50:11.913 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventTime with label LastLogEventTime <0x2c2eb680>
35 09/07/16 8:50:11.921 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventUser with label LastLogEventUser <0x2c2eb680>
35 09/07/16 8:50:11.928 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEvent with label LastLogEvent <0x2c2eb680>
35 09/07/16 8:50:11.936 luup_log:188: SensorMqtt: Watching urn:futzle-com:serviceId:CaddxNX584Security1 on variable LastLogEventPartition with label LastLogEventPartition <0x2c2eb680>
35 09/07/16 8:50:11.943 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status3 with label Status3 <0x2c2eb680>
35 09/07/16 8:50:11.945 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status1 with label Status1 <0x2c2eb680>
35 09/07/16 8:50:11.947 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status4 with label Status4 <0x2c2eb680>
35 09/07/16 8:50:11.948 luup_log:188: SensorMqtt: Watching urn:dcineco-com:serviceId:MSwitch1 on variable Status2 with label Status2 <0x2c2eb680>
35 09/07/16 8:50:11.950 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:HouseModes1 on variable HMode with label HMode <0x2c2eb680>
35 09/07/16 8:50:11.951 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:HouseModes1 on variable Message with label Message <0x2c2eb680>
35 09/07/16 8:50:11.953 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable ArmedTripped with label ArmedTripped <0x2c2eb680>
35 09/07/16 8:50:11.960 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Tripped with label Tripped <0x2c2eb680>
35 09/07/16 8:50:11.968 luup_log:188: SensorMqtt: Watching urn:micasaverde-com:serviceId:SecuritySensor1 on variable Armed with label Armed <0x2c2eb680>
35 09/07/16 8:50:11.976 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x2c2eb680>
50 09/07/16 8:50:11.977 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x2c2eb680>
35 09/07/16 8:50:16.119 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:21.105 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:26.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:31.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:31.488 luup_log:188: SensorMqtt: Watch event - device: 151 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.502 luup_log:188: SensorMqtt: Sending [Living - Humidity] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.503 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":151,"DeviceName":"Living - Humidity","DeviceType":"urn:schemas-micasaverde-com:device:HumiditySensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.503 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:31.504 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:31.507 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:31.508 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:31.591 luup_log:188: SensorMqtt: Watch event - device: 152 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.594 luup_log:188: SensorMqtt: Sending [Living - Temperature] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.595 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":152,"DeviceName":"Living - Temperature","DeviceType":"urn:schemas-micasaverde-com:device:TemperatureSensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
02 09/07/16 8:50:31.596 luup_log:188: SensorMqtt: Unable to publish, connection down.  Discarding message: {"DeviceId":152,"DeviceName":"Living - Temperature","DeviceType":"urn:schemas-micasaverde-com:device:TemperatureSensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.597 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x32ceb680>
35 09/07/16 8:50:31.696 luup_log:188: SensorMqtt: Watch event - device: 153 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.699 luup_log:188: SensorMqtt: Sending [Living - Pressure] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.700 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":153,"DeviceName":"Living - Pressure","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.701 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:31.701 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:31.705 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:31.706 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:31.771 luup_log:188: SensorMqtt: Watch event - device: 177 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.774 luup_log:188: SensorMqtt: Sending [Living - Noise] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.774 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":177,"DeviceName":"Living - Noise","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
02 09/07/16 8:50:31.776 luup_log:188: SensorMqtt: Unable to publish, connection down.  Discarding message: {"DeviceId":177,"DeviceName":"Living - Noise","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.777 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x32ceb680>
35 09/07/16 8:50:31.832 luup_log:188: SensorMqtt: Watch event - device: 178 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.835 luup_log:188: SensorMqtt: Sending [Living - CO2] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.836 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":178,"DeviceName":"Living - CO2","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.837 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:31.837 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:31.840 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:31.841 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:31.902 luup_log:188: SensorMqtt: Watch event - device: 156 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.905 luup_log:188: SensorMqtt: Sending [regenmeter - Rain] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.906 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":156,"DeviceName":"regenmeter - Rain","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
02 09/07/16 8:50:31.907 luup_log:188: SensorMqtt: Unable to publish, connection down.  Discarding message: {"DeviceId":156,"DeviceName":"regenmeter - Rain","DeviceType":"urn:akbooer-com:device:NetatmoMetric:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.908 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x32ceb680>
35 09/07/16 8:50:31.939 luup_log:188: SensorMqtt: Watch event - device: 157 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:31.943 luup_log:188: SensorMqtt: Sending [Tuin - Humidity] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:31.944 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":157,"DeviceName":"Tuin - Humidity","DeviceType":"urn:schemas-micasaverde-com:device:HumiditySensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:31.944 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:31.945 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:31.948 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:31.949 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:31.992 luup_log:188: SensorMqtt: Watch event - device: 158 variable: LastUpdated value 1473230501 => 1473231031 <0x32ceb680>
50 09/07/16 8:50:32.002 luup_log:188: SensorMqtt: Sending [Tuin - Temperature] LastUpdated changed to 1473231031 from 1473230501 on topic {} <0x32ceb680>
35 09/07/16 8:50:32.003 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":158,"DeviceName":"Tuin - Temperature","DeviceType":"urn:schemas-micasaverde-com:device:TemperatureSensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
02 09/07/16 8:50:32.005 luup_log:188: SensorMqtt: Unable to publish, connection down.  Discarding message: {"DeviceId":158,"DeviceName":"Tuin - Temperature","DeviceType":"urn:schemas-micasaverde-com:device:TemperatureSensor:1","LastUpdated":1473231031,"OldLastUpdated":1473230501,"RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231031,"Variable":"LastUpdated"} <0x32ceb680>
50 09/07/16 8:50:32.006 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x32ceb680>
35 09/07/16 8:50:32.127 luup_log:188: SensorMqtt: Watch event - device: 150 variable: Timestamp value Wed 08:41 => Wed 08:50 <0x32ceb680>
50 09/07/16 8:50:32.131 luup_log:188: SensorMqtt: Sending [Netatmo] Timestamp changed to Wed 08:50 from Wed 08:41 on topic {} <0x32ceb680>
35 09/07/16 8:50:32.131 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":150,"DeviceName":"Netatmo","DeviceType":"urn:akbooer-com:device:Netatmo:1","OldTimestamp":"Wed 08:41","RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231032,"Timestamp":"Wed 08:50","Variable":"Timestamp"} <0x32ceb680>
50 09/07/16 8:50:32.132 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:32.133 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:32.136 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:32.137 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:36.125 luup_log:188: SensorMqtt: Connection down: socket_client:receive(): closed <0x332eb680>
50 09/07/16 8:50:36.126 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x332eb680>
35 09/07/16 8:50:41.106 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:46.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:51.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:50:56.105 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:01.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:06.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:11.116 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:16.108 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:21.129 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:26.105 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>
35 09/07/16 8:51:31.115 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x332eb680>

checksums (just reuploaded latest download from github page)
Code: [Select]
MD5(/usr/lib/lua/mqtt_library.lua)= d277c620e1d55b6981c905d0a336216f
MD5(/usr/lib/lua/utility.lua)= 9bb0529b5a3d4368376a37ba9453dc4f
« Last Edit: September 07, 2016, 02:59:32 am by stefaanbolle »

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #71 on: September 07, 2016, 08:35:08 am »

My openhab 1.8.3 is running on 192.168.1.40
Mosquitto is also running on 192.168.1.40
Vera is 192.168.1.251

Below my logs
Mosquitto
Code: [Select]
1473231011: New connection from 192.168.1.251 on port 1883.
1473231011: Sending CONNACK to 192.168.1.251 (0, 5)
1473231011: Socket error on client <unknown>, disconnecting.

vera
Code: [Select]
50 09/07/16 8:50:11.868 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x2c2eb680>
35 09/07/16 8:50:11.869 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x2c2eb680>
50 09/07/16 8:50:11.872 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x2c2eb680>
50 09/07/16 8:50:11.873 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x2c2eb680>
35 09/07/16 8:50:11.976 luup_log:188: SensorMqtt: Connection down: /usr/lib/lua/mqtt_library.lua:382: MQTT.client:handler(): Not connected <0x2c2eb680>
50 09/07/16 8:50:11.977 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x2c2eb680>

35 09/07/16 8:50:32.127 luup_log:188: SensorMqtt: Watch event - device: 150 variable: Timestamp value Wed 08:41 => Wed 08:50 <0x32ceb680>
50 09/07/16 8:50:32.131 luup_log:188: SensorMqtt: Sending [Netatmo] Timestamp changed to Wed 08:50 from Wed 08:41 on topic {} <0x32ceb680>
35 09/07/16 8:50:32.131 luup_log:188: SensorMqtt: Publish topic: {} message:{"DeviceId":150,"DeviceName":"Netatmo","DeviceType":"urn:akbooer-com:device:Netatmo:1","OldTimestamp":"Wed 08:41","RoomId":9,"RoomName":"3-Netatmo","ServiceId":"urn:akbooer-com:serviceId:Netatmo1","Time":1473231032,"Timestamp":"Wed 08:50","Variable":"Timestamp"} <0x32ceb680>
50 09/07/16 8:50:32.132 luup_log:188: SensorMqtt: Connecting to MQTT, mqttServerIp: 192.168.1.40 mqttServerPort: 1883... <0x32ceb680>
35 09/07/16 8:50:32.133 luup_log:188: SensorMqtt: Authenticating with username: openhab <0x32ceb680>
50 09/07/16 8:50:32.136 luup_log:188: SensorMqtt: Successfully connected to broker: 192.168.1.40 on port 1883 <0x32ceb680>
50 09/07/16 8:50:32.137 luup_log:188: SensorMqtt: MQTT connection status changed from "Disconnected" to "Connected" <0x32ceb680>
35 09/07/16 8:50:36.125 luup_log:188: SensorMqtt: Connection down: socket_client:receive(): closed <0x332eb680>
50 09/07/16 8:50:36.126 luup_log:188: SensorMqtt: MQTT connection status changed from "Connected" to "Disconnected" <0x332eb680>

checksums (just reuploaded latest download from github page)
Code: [Select]
MD5(/usr/lib/lua/mqtt_library.lua)= d277c620e1d55b6981c905d0a336216f
MD5(/usr/lib/lua/utility.lua)= 9bb0529b5a3d4368376a37ba9453dc4f

After seeing this, I went back and scrubbed/inspected each and every client authentication step and found a typo in the variable name for the mqtt broker password!  I have fixed that typo, added the mqtt client id to the info logging and committed the changes to git.

Please try the latest version of the plugin on GitHub including the dependency utility.lua (I didn't update it but your checksum doesn't match the GitHub checksum so perhaps you missed this one when I upgraded SensorMqtt to use the Paho 0.3 mqtt lua client.  Here are the checksums for everything.

Code: [Select]
$ find . -type f -not -path './.git/*' -exec openssl dgst -md5 {} \;
MD5(./Dependencies/usr/lib/lua/JSON.lua)= 7df77af31f3854a8db9dc82fcf789dea
MD5(./Dependencies/usr/lib/lua/mqtt_library.lua)= d277c620e1d55b6981c905d0a336216f
MD5(./Dependencies/usr/lib/lua/utility.lua)= 70673ff99bbc4015803facd6fe6687b5
MD5(./Plugin/D_SensorMqtt1.json)= c7d8b12e2e5fe2d61edfd614b815f9e1
MD5(./Plugin/D_SensorMqtt1.xml)= 4326276bc240949c9914fb8bb1043c6b
MD5(./Plugin/I_SensorMqtt1.xml)= 3ff8c0074b14a9908586d70c3e507fc1
MD5(./Plugin/J_SensorMqtt1.js)= 5d63ee1c3e28221be85dea901c4a0993
MD5(./Plugin/L_SensorMqtt1.lua)= 9dce0494565d602abf15a89110aa27f5
MD5(./Plugin/S_SensorMqtt1.xml)= 23bc8fa230b8be8c29b130d6f9ce95c0
[code]

I really, really appreciate your patience in running numerous tests.  Had I not been traveling, I would have set up an authenticated broker instance running 1.4.10 to mimic your config and dug in to find this on my own.  I'm pretty sure we nailed it though and thanks again for all your help and patience!
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #72 on: September 07, 2016, 09:10:36 am »
Hi Blacey, guess what...

Code: [Select]
MQTT IP: 192.168.1.40
MQTT Port: 1883
MQTT User: openhab
MQTT Status: Connected
MQTT Last Message:
{"Payload":"{\"DeviceId\":150,\"DeviceName\":\"Netatmo\",\"DeviceType\":\"urn:akbooer-com:device:Netatmo:1\",\"OldTimestamp\":\"Wed 15:00\",\"RoomId\":9,\"RoomName\":\"3-Netatmo\",\"ServiceId\":\"urn:akbooer-com:serviceId:Netatmo1\",\"Time\":1473253666,\"Timestamp\":\"Wed 15:07\",\"Variable\":\"Timestamp\"}","Topic":"{}"}

I think the problem has been solved. Connection is established!
Thanks a lot for your support and quick response!
I'm looking forward to further developments of your plugin and I'm certainly willing to test if it can help you.

Subscribing to mqtt broker for reading values can be a great update since this could open the door to owntracks integration.

Offline blacey

  • Full Member
  • ***
  • Posts: 220
  • Karma: +24/-1
Re: MQTT Client Plugin
« Reply #73 on: September 07, 2016, 09:51:47 am »
I think the problem has been solved. Connection is established!
Thanks a lot for your support and quick response!
I'm looking forward to further developments of your plugin and I'm certainly willing to test if it can help you.

Subscribing to mqtt broker for reading values can be a great update since this could open the door to owntracks integration.

Awesome!   :) :) :)  Thanks for your diligent and methodical testing and feedback.

Feel free to outline the owntracks use case that you envision to influence the direction of the plugin. ;)
Three Vera-3 (Home, Seasonal 1 & 2) - Firmware: 1.5.622,   Zwave: 3.20 L:1
One Vera-Edge (Dependent) - Firmware: 1.7.1707, Zwave: 4.5 L:1

Offline stefaanbolle

  • Jr. Member
  • **
  • Posts: 52
  • Karma: +4/-1
Re: MQTT Client Plugin
« Reply #74 on: September 07, 2016, 10:24:52 am »
Owntracks reports it's status/presence on Android/iOS using mqtt to a mqtt broker.
It would be great if a plugin in Vera would allow to use owntracks as presence tracker (kind of iphone locator plugin) and additionally shows any monitored device (ie kids) on a map in vera.
That's in short my usecase.