Disaster recovery and virtualisation

[Buxton]

@akbooer I hate to add more to the pile... but I'm still seeing a receive error for the connection to mosquitto. openLuup 2021.04.29b

Here's the log error:

2021-05-01 14:22:38.815   openLuup.io.server:: MQTT:1882 connection closed  tcp{client}: 0x5579919e9c58
2021-05-01 14:22:38.816   openLuup.mqtt:: RECEIVE ERROR: closed tcp{client}: 0x5579919e9c58
2021-05-01 14:22:43.935   luup.io.incoming:: bytes received: 51, status: OK tcp{client}: 0x557990e7f528
2021-05-01 14:22:48.435   luup.io.incoming:: bytes received: 51, status: OK tcp{client}: 0x557990e7f528
2021-05-01 14:22:49.763   luup.variable_set:: 10181.urn:micasaverde-com:serviceId:EnergyMetering1.KWHReading was: 1619904116 now: 1619904168 #hooks:0
2021-05-01 14:22:50.158   openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x557991971ff8
2021-05-01 14:22:53.834   openLuup.io.server:: MQTT:1882 connection from 127.0.0.1 tcp{client}: 0x5579920dc0b8
2021-05-01 14:22:53.834   openLuup.mqtt:: client is in ERROR empty
2021-05-01 14:22:53.834   openLuup.mqtt:: credentials is in ERROR empty
2021-05-01 14:22:53.834   openLuup.mqtt:: subscriptions is in ERROR empty

using the below error trapping in function "MQTTservlet"

  local function MQTTservlet (client)
  
	if client == nil then
	  _log ("client is in ERROR nil")
	else
	  	if table.concat(client) == "" then
		_log ("client is in ERROR empty")
		else
	   _log (table.concat {"MQTT ERROR: ", table.concat(client)})
	    end
	end 
	
	if credentials == nil then
	  _log ("credentials is in ERROR nil")
	else
	  	if table.concat(credentials) == "" then
		_log ("credentials is in ERROR empty")
		else
	   _log (table.concat {"MQTT ERROR: ", table.concat(credentials)})
	    end
	end 
	
	if subscriptions == nil then
	  _log ("subscriptions is in ERROR nil")
	else
	  	if table.concat(subscriptions) == "" then
		_log ("subscriptions is in ERROR empty")
		else
	    _log (table.concat {"MQTT ERROR: ", table.concat(subscriptions)})
	    end
	end
	
    return function () incoming (client, credentials, subscriptions) end
  end

I can't find a deeper layer in the stack where I can trap for the incoming message to see what's in the message that is throwing the error. As near as I can tell, if openLuup tries to connect to a running mosquitto instance, then it fails to see the topics and messages, and passes empty--but not nil--strings when the servlet interface sees incoming bytes.

If I restart mosquitto, openLuup then sees the topics and messages and the error messages stop--and the connection to mosquitto remains stable.

This behavior does not occur when I aim an IOT device directly at openLuup--in that the connection to the device always resumes when openLuup reloads--in other words, I don't need to restart the IOT device to enable the connection.

[akbooer]

@christian_fabre

I simply cannot reproduce this error, so can I ask you to try it again after having added this line to openLuup Startup (which enables debog logging for the MQTT server):

luup.attr_set ("openLuup.MQTT.DEBUG", true)

That may give a little more to go on.

I've have tried everything I can think of, deleting the Shelly plugin, and reproducing the announce message from your device. It all works just fine.

[christian_fabre]

I added "luup.attr_set (" openLuup.MQTT.DEBUG ", true)"
and I did a RELOAD
here is the log

2021-05-02 14:03:57.914   openLuup.io.server:: MQTT:1883 connection from 192.168.1.149 tcp{client}: 0x11320b0
2021-05-02 14:03:57.941   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.941   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/online : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.943   luup.shelly:87: New Shelly announced: shellyplug-s-20E453
2021-05-02 14:03:57.944   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:226: attempt to index field '?' (a nil value)
2021-05-02 14:03:57.944   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/announce : ./L_ShellyBridge.lua:226: attempt to index field '?' (a nil value)
2021-05-02 14:03:57.945   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.946   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/announce : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.947   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.947   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0/power : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.949   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.949   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0/energy : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.989   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.989   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0 : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.994   openLuup.server:: request completed (664 bytes, 1 chunks, 1140 ms) tcp{client}: 0x1403478
2021-05-02 14:03:57.995   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.995   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/temperature : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.997   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.997   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/temperature_f : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.998   openLuup.context_switch::  ERROR: [dev #87] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:57.999   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/overtemperature : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 14:03:58.000   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/command tcp{client}: 0x11320b0
2021-05-02 14:03:58.002   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/shellyplug-s-20E453/command tcp{client}: 0x11320b0
2021-05-02 14:03:58.003   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/shellyplug-s-20E453/relay/0/command tcp{client}: 0x11320b0

[akbooer]

Just what I needed to see, thanks, I’ll work on it.

[akbooer]

@christian_fabre

Can can give v21.5.2 from the testing branch a go?

[christian_fabre]

disabled MQTT on the Shelly socket
I deleted on OpenLuup

• the Shelly device in NoRoom
• the Shellies piece
  I did a Reload
  I installed version 2021.05.02
  I did a Reload
  Enabled MQTT on the Shelly socket
  I did a Reload
  Creation of the Shelly Bridge (88) in NoRoom
  Creation of the piece Shelly
  I still have the same problem

2021-05-02 17:51:56.712   openLuup.io.server:: MQTT:1883 connection from 192.168.1.149 tcp{client}: 0x184b970
2021-05-02 17:51:56.745   luup.create_device:: [88] D_ShellyBridge.xml / I_ShellyBridge.xml / D_ShellyBridge.json   (ShellyBridge)
2021-05-02 17:51:56.746   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.746   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/online : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.747   openLuup.scheduler:: [88] Shelly device startup
2021-05-02 17:51:56.747   luup.set_failure:: status = 0
2021-05-02 17:51:56.747   luup.variable_set:: 88.urn:micasaverde-com:serviceId:HaDevice1.CommFailure was: EMPTY now: 0 #hooks:0
2021-05-02 17:51:56.748   luup.variable_set:: 88.urn:micasaverde-com:serviceId:HaDevice1.CommFailureTime was: EMPTY now: 0 #hooks:0
2021-05-02 17:51:56.748   openLuup.scheduler:: [88] Shelly device startup completed: status=true, msg=OK, name=ShellyBridge
2021-05-02 17:51:56.749   luup.shelly:0: New Shelly announced: shellyplug-s-20E453
2021-05-02 17:51:56.749   openLuup.luup:: creating room [10] Shellies
2021-05-02 17:51:56.750   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:226: attempt to index field '?' (a nil value)
2021-05-02 17:51:56.750   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/announce : ./L_ShellyBridge.lua:226: attempt to index field '?' (a nil value)
2021-05-02 17:51:56.751   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.751   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/announce : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.752   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.752   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0/power : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.753   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.754   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0/energy : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.789   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.790   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/relay/0 : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.791   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.791   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/temperature : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.792   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.792   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/temperature_f : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.793   openLuup.context_switch::  ERROR: [dev #0] ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.793   openLuup.mqtt:: ERROR publishing application message for mqtt:shellies/shellyplug-s-20E453/overtemperature : ./L_ShellyBridge.lua:343: attempt to index field 'hadevice' (a nil value)
2021-05-02 17:51:56.795   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/command tcp{client}: 0x184b970
2021-05-02 17:51:56.796   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/shellyplug-s-20E453/command tcp{client}: 0x184b970
2021-05-02 17:51:56.797   openLuup.mqtt:: shellyplug-s-20E453 SUBSCRIBE to shellies/shellyplug-s-20E453/relay/0/command tcp{client}: 0x184b970
2021-05-02 17:51:57.208   openLuup.server:: request completed (1033 bytes, 1 chunks, 3858 ms) tcp{client}: 0x197dd68
2021-05-02 17:51:57.209   openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x197dd68

[akbooer]

I’m speechless. No explanation.

[christian_fabre]

ok thanks for trying to solve my problem.
in the near future i will try to reinstall OpenLuup on my Raspbery, maybe this will fix this problem.
Sorry for taking your precious time

[akbooer]

I haven’t given up. I can only think that, somehow, we are not running the same version of the code. You did confirm that your last install was, in fact, v21.5.2?

[Elcid]

Is @christian_fabre bridged to mosquitto? As when I reload OpenLuup I have to restart mosquitto to get them talking again.

[christian_fabre]

[therealdb]

@akbooer I will probably add more log, to see the exact payload sent. Sometimes those things are generating strange telemetry data, so maybe that's the case. I'll probably log what's going on around hadevice property as well. I was unable to re-produce it in my own install, so it should be something related to this particular model and its messages.

[akbooer]

@christian_fabre

If you are still interested, testing v21.5.3 is available. I have made considerable changes.

[christian_fabre]

I just installed the testing version 21.5.3.
It works great for Shelly but also for Tasmota

Merci bien

[akbooer]

@christian_fabre said in MQTT – setup and use:

Merci bien

Je vous en pris.

Believe me... I'm happy. So sorry for all the mis-steps, but I learned a few things along the way, so it was a worthwhile exercise!

[rafale77]

@akbooer

Now that you got that figured out, one awesome thing which could be done would be integrate this:

GitHub - Koenkk/zigbee2mqtt: Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨 - Koenkk/zigbee2mqtt

By creating a bridge supporting it on openLuup. It would enable me to move zigbee from home assistant to run directly to openLuup and I would likely take advantage of it to get rid of my hue hub as well, running a single zigbee network through mqtt...

[therealdb]

@rafale77 its topics are pretty organized, so it should be easy to do. The only difficult part is to get a reliable trace of messages, so an emulator could be written to facilitate development and testing.

[akbooer]

@buxton said in MQTT – setup and use:

As near as I can tell, if openLuup tries to connect to a running mosquitto instance, then it fails to see the topics and messages, and passes empty--but not nil--strings when the servlet interface sees incoming bytes.

OK, I’m ready to take a look at this. However the above statement makes no sense to me, since the server never connects to anything (because it’s a server – clients connect to it.)

[Buxton]

@akbooer Yes, that was poorly worded as it makes it sound like openLuup initiates the connection to Mosquitto.

The symptoms of the problem are that:

• if luup reloads, an occasional message that is sent to openLuup from Mosquitto causes a receive error in openLuup. It is unknown what that/those message(s) are.
• if mosquitto reloads, the openLuup error messages stop, so something changes in the way that openLuup sees the mosquitto data.
• this behavior does not occur with IOT devices.

A possible way to trouble shoot this is to place debug code at the incoming interface that will trap and display packets headed to the MQTT port. By comparing incoming timestamps with the error message timestamp, I should be able to tell what message is causing the receive error message--even though the message variable is empty at the time it causes the luup error. What is odd to me is that there is a lot of error trapping for bad messages in your code, but this message(s) seems to bypass all of that and arrives at the incoming routine empty.....

[akbooer]

I think we are being misled by your error messages. These tables are not empty...

local x = {a = 1, b = 2}
local y = table.concat (x)
print (y == '')

yields the expected result true.