Hello,
I recently updated my Victron Venus GX firmware and after the firmware 2.72 upgrade mqtt bindings have been unstable, and I am unable to find the cause.
After (re)starting the mqtt broker or genertic mqtt thing messages will start to be processed as normal. But after about a minute it stops updating with no message in the openhab.log or the mosquitto.log.
When I connect to the broker using an mqtt client like mqtt.fx I can see it receiving what appears to be an empty message after which it stops getting new messages for a while but then resumes receiving messages. This simply repeats.
OH 3 however does not resume and well I would like to find out what is causing the issue.
In the venus GX there is also no output from mosquitto (when running it from the command line not as a service). I cannot seem to find where the venus GX puts the mosquitto.log if it even logs at all.
The mosquitto service is running on the OpenHab 3.0.2 server and it is not reporting any errors.
I suspect there is some kind of keep alive issue between the two causing the interruption after an initially successful connection. But I simply can’t find any thing to verify that. My config on the OH side is still the same as before.
Any ideas as to where/how I could look for more clues as to why messages keep stopping?
I’m really confused as to how this is set up, what is being restarted and when.
mosquitto.log will only exist on the machine running Mosquitto. You say you are running Mosquitto on the same machine as openHAB, so what does the GX have to do with it? Nothing. If the GX has a log, it will log MQTT connection issues there.
Put the MQTT binding into debug level. to get more details.
Have you configured a LWT topic and message on the Broker Thing? Do you see the LWT message being published a few minutes after OH stops receiving messages? That will tell you whether or not OH is disconnecting from or at least not responding to the broker. There are some telemetry topics on Mosquitto, one of which will say how many clients are connected. Look at those to see if there are any changes around the time that OH stops receiving messages.
Make sure that all client have a unique client ID. If not when the second client with the same ID connects to the broker, the first one will be kicked off.
No LWT configured.
The GX is connecting to OH and publishing its topics I don’t see how you could do so without running Mosquitto that makes no sense to me. You need it in order to publish.
Of course there is more going on in the GX as it also publishes to two seperate Victron servers, their remote config/portals use mqtt but how exactly all that works is fuzzy to me.
I added to the config that it connects to the OH broker so it can tie some channels to topics.
connection gladosmqtt
address <IP of OH host>:1883
cleansession true
topic N/d0ff50ea609f/# out
remote_clientid ccgx_venus_gx
remote_username Redacted
remote_password Redacted
I did a dump messages using mqtt.fx but it just creates a empty file for the empty message.
What I did notice is that this “empty message” only occurred once I disabled and re-enabled the thing (mqtt:topic:GladosMQTT:solar)
My hunch is that it is because the re-enabling of the thing triggers something in the broker to try again.
Obviously I miss-configured something, but why does it always have to be such a quest to figure out what.
EDIT:
I did not mention this detail but the mqtt.fx client connects to the OH broker, not the GX.
So the GX is connected to the broker and publishing messages which the client in turn can successfully subscribe to. Only once the thing start being active does the problem occur.
Well I “put the binding in debug” using this post.
The logging produced is not particularly helpful so perhaps some additional logging options?
The below is produced when disabling and enabling the thing.
It does however not log anything regarding messages.
2021-07-20 00:44:01.097 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:acinvoltage form topic: N/d0ff50ea609f/vebus/261/Ac/ActiveIn/L1/V
2021-07-20 00:44:01.098 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:acoutpower form topic: N/d0ff50ea609f/system/0/Ac/Consumption/L1/Power
2021-07-20 00:44:01.097 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:solarchargeryield form topic: N/d0ff50ea609f/system/0/Dc/Pv/Power
2021-07-20 00:44:01.098 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:dcbatterycurrent form topic: N/d0ff50ea609f/system/0/Dc/Battery/Current
2021-07-20 00:44:01.100 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:acinpower form topic: N/d0ff50ea609f/system/0/Ac/Grid/L1/Power
2021-07-20 00:44:01.100 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:acoutvoltage form topic: N/d0ff50ea609f/vebus/261/Ac/Out/L1/V
2021-07-20 00:44:01.100 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:topic:GladosMQTT:solar:dcbatteryvoltage form topic: N/d0ff50ea609f/system/0/Dc/Battery/Voltage
2021-07-20 00:44:03.079 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:acoutpower
2021-07-20 00:44:03.080 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:solarchargeryield
2021-07-20 00:44:03.080 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:acinpower
2021-07-20 00:44:03.080 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:dcbatteryvoltage
2021-07-20 00:44:03.080 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:dcbatterycurrent
2021-07-20 00:44:03.080 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:acoutvoltage
2021-07-20 00:44:03.081 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:GladosMQTT:solar:acinvoltage
2021-07-20 00:44:03.082 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:acinvoltage to topic: N/d0ff50ea609f/vebus/261/Ac/ActiveIn/L1/V
2021-07-20 00:44:03.086 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:solarchargeryield to topic: N/d0ff50ea609f/system/0/Dc/Pv/Power
2021-07-20 00:44:03.086 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:acoutpower to topic: N/d0ff50ea609f/system/0/Ac/Consumption/L1/Power
2021-07-20 00:44:03.086 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:dcbatteryvoltage to topic: N/d0ff50ea609f/system/0/Dc/Battery/Voltage
2021-07-20 00:44:03.087 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:dcbatterycurrent to topic: N/d0ff50ea609f/system/0/Dc/Battery/Current
2021-07-20 00:44:03.087 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:acinpower to topic: N/d0ff50ea609f/system/0/Ac/Grid/L1/Power
2021-07-20 00:44:03.087 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:topic:GladosMQTT:solar:acoutvoltage to topic: N/d0ff50ea609f/vebus/261/Ac/Out/L1/V
It doesn’t, it connects to Mosquitto. Everything connects and communicates through Mosquitto when it comes to MQTT.
Your Victron device isn’t connecting to openHAB at all - it is communicating with Mosquitto.
openHAB also is connected to Mosquitto.
All MQTT communications go through Mosquitto. Mosquitto is the broker. Your openHAB broker Thing is just a an openHAB bridge Thing which connects to Mosquitto - it isn’t a broker itself.
Please read first, how MQTT works - then get back to your configuration. MQTT as technology is not a part of openHAB at all. It’s just a means of communication:
so, after reading the intro to MQTT, please get back to your installation and configure it accordingly, if you have specific questions, on how to do that, read the docs first, then ask again, please. You’re mixing up different things, which makes it nearly impossible for us to solve, as you clearly don’t understand the concept of MQTT (no offense! it’s just a statement…) :
There was nothing new in the mqtt intro.
I cannot configure accordingly because the docs don’t describe that.
Things are mixed up because I cannot check whether it is the GX that stops publishing the Broker that stops publishing or the bridge/OH3 that stops subscribing.
As stated the logs don’t hold any hints as to a problem.
However messages keep being interrupted causing the bridge to no longer update. The mqtt.fx client does resume receiving messages after the interruption.
I have tired increasing the QOS and different keep alive an reconnect values but no change.
Obviously there is something I am missing, if i was an expert on the matter there would be no need for a post.
This was working until the GX firmware was updated. Unfortunately Victron only publishes the release notes to their registered installers so I can’t check what they changed between 2.70 and 2.72.
The behavior points to some timing related issue as messages are received then stop then resume. From the message dump I can tell that the clients receive messages every couple of seconds for about a minute. Then 1 or 2 minutes of silence and again a minute of messages.
Since that is in the mqtt.fx client I am guessing the GX is a fault here and stops publishing for some odd reason.
If only the openHAB subscription was messing up, then mqtt.fx would continue to see messages since it is subscribed to the broker directly.
You seem to be saying mqtt.fx stops, so that seems to answer …
with a NO, it is not that.
That’s consistent with it not being openHAB
Or possibly messages are published but in some form the broker does not like.
If you cannot inspect logging on the GX, then you must find out how to capture your mosquitto logging.
Yes I was already updating my post.
The problem seems to be in the GX which is running mosquitto to publish to the broker on the OH machine. At least that is the way it is described to publish mqtt from the GX add a connection config to the existing mosquitto config on the GX.
Indeed logging on the GX should tell me more, just where to find it.
Yes that is normal operation for the GX it publishes about 1200 topics and I estimate about 100 of those change ever second or two. Although I am only interested in 8 of those.
Things like power consumption, grid voltage, battery voltage, battery current, PV current, etc are continuously changing.
Basically it is a live view of power consumption vs production which OH then uses to determine whether shutters should go down or up and whether to turn on the water heater and even what power level to set it to.
Yes I have seen a hivemq do a tuturial using NodeRed.
I guess if it becomes a performance issue I could do that though so far OH has been handling it just fine.
Since most of the topics are not subscribed to the data only get “streamed” to mosquitto where it is discarded. Sure I could shorten the list op topics that the GX publishes but it’s not even noticeable in the local network.
I also like the live view in hab panel. Though what I am missing most at the moment is the graphs I used to get as OH persisted the data. OH allowed me to have a more in depth look at the performance than what the Victron VRM pannel offers.
FYI, no response from the Victron community so far. Not even as to where I can get older firmware versions in order to do a rollback.
Victron doesn’t officially support mqtt so it’s up to the community to help one another integrate their products. Their back-end uses it but user integrations are not supported.
I don’t have a Victron GX, but thought on using the OSS GX on github on a Pi sometime. But I could imagine using an external MQTT broker (and not the one on the GX itself) would be better - so that you have direct access to its logfiles… or is this, what you asked in the Victron community?
That’s true, what annoyed me, was the logfile spamming. e.g. from my weather station: 22.233424 changed to 22.233425 every few seconds… So I used nodered to flatten this and I only get updates once the temperatre is 0.6 degress higher/lower.
…but of course, if your goal is to monitor your Photovoltaic within openHAB it’s better with “real-time” data.
Well the way I set it up was basically following an example I found in the Victron community.
Although I made is slightly less “hacky” as my solution is basically having the GX merge my mosquitto config on top of the Victron generated config when booting. but you could just have OH connect to the GX broker as well. My reasoning was more for security but the GX kinda screws that up as it does not allow for routing local subnets so I can’t isolate it in the network as then it cannot talk to me in another subnet. (No clue why since it’s a beagle board which should have the ability to route properly.
Now of course that can be fixed by using certificates though setting that up locally and offline capable is not trivial so I haven’t gotten around to that yet.
I don’t actually have any log spam in the OH log though I have of course omitted all logging from rules because they can get triggered a lot. My temperature sensors can have quite a bit of hysteresis.
The really funky thing is that with no change from my side this afternoon things suddenly resumed working. Or at least OH has been happily graphing away for about 5 hours now with not interruption.
I “love” these kinda things course you have no idea why it didn’t work, or what made it work, so you cant tell whether it will happen again. -_-
Well that was the first firmware update the GX got since I installed it, it sure was a hoot.
If I happen to find out what caused it or what fixed it I will document it here for prosperity.(assuming things keep working)
yes, it’s slowly a bit OT, but I meant this one:
2021-07-27 08:08:24.655 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'MQTTWetterstationBinder_Aussentemperatur' received command 17.50
2021-07-27 08:08:24.677 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'MQTTWetterstationBinder_Aussentemperatur' predicted to become 17.50
2021-07-27 08:08:24.699 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTWetterstationBinder_Aussentemperatur' changed from 17 °C to 17.5 °C
I bet, the weather station didn’t just jump from 17.0 to 17.5, but slowly from 17.0234 to 17.045454 to 17.081231 and so on… NodeRed filtered all out and rounded to one decimal point only.
It’s a bit of a nitpick but shouldn’t that be an update? You are not commanding a device to do something here but recording a sensor value. Especially if you are worried about events.log spam, using an update will reduce those three lines down to just the “changed” line as there will be no separate command event and nothing for autoupdate to “predict”.
