mcsMQTT Stopped Recording Associated HS4 Devices Into InfluxDB

[jeanv]

Hello Michael McSharry,

You have been an amazing help in getting everything working. I have InfluxDB2 running and capturing data from mcsMQTT with no problem except from my temperature sensors that are Root/Parent devices. They captured for a while but then all of them stopped appearing in my InfluxDB. They are still being updated by mcsMQTT into the Mosquitto MQTT broker and I see their values change but there is no entry in InfluxDB for them. Other mcsMQTT devices appear just fine in InfluxDB but none of my temperature sensors do. I have tired stopping the service and restarting it and even tried rebooting the entire PC.



This is an example of a sensor that mcsMQTT used to record into InfluxDB but does not anymore. As you can see it updated today at 4:17:01 PM today.

Device Ref# 862 - TS - Bedroom

Here you can see that Device Ref# 862 is associated in HS4 with the H, S, and L fields checked. Same as another device Device Ref# 94 which an can also be seen above but IS getting updated reliably in InfluxDB unlike device .ASP Problems




My MQTT Explorer does see updates to the Bedroom Temperature sensor in the MQTT Broker. So mcsMQTT is updating the value of the device in MQTT. It just seems like it is the InfluxDB that is not getting the value.



Here you can see a chart from InfluxDB on the "TS - Bedroom" sensor we have been talking about. As you can see it only logged for a short time yesterday and then stopped logging while other devices in mcsMQTT had no problems. This is true with ALL my Temperature sensors where the device value is associated with the Root/Parent device (I do not know if that has anything to do with it, but all the ones that stopped logging do have that fact in common).

Any ideas on where I should start looking?

Thanks for any help!

[Michael McSharry]

They captured for a while but then all of them stopped appearing in my InfluxDB. They are still being updated by mcsMQTT into the Mosquitto MQTT broker and I see their values change but there is no entry in InfluxDB for them.

Analysis is from the mcsMQTT Debug.txt and the messages around HSEvent.

[jeanv]

I spent some time this morning enabling and reviewing the "mcsMQTT Debug.txt" and HS4 Event Logs. Here are the devices that are setup in mcsMQTT with "h, s, l" set but do not log to InfluxDB. All three are temperature sensors with the parent/root device being the one that gets the value updates for temperature.

1 - Bedroom_1 - Device Ref# 862
2 - Bathroom _1 - Device Ref# 810
3 - Attic _1 - Device Ref# 847

I also have a regular feature devices that DO get logged into InfluxDB and also has "h, s, l" set. Here is an example of one:

1 - Washer - Device Ref# 80

There is nothing in the HS4 Event Log that tells me anything related to this, but in the "mcsMQTT Debug.txt" I see the following excerpts:

8/29/2022 9:08:40 AM 259541 | HSEvent VALUE_CHANGE| 1024| | 68.5| 68.4| 862
8/29/2022 9:08:40 AM 259541 | Publish Jarvis/Temperature/Bedroom_1=68.5
8/29/2022 9:08:40 AM 259541 | ProcessMessage Jarvis/Temperature/Bedroom_1
8/29/2022 9:08:40 AM 259542 | ActOnMessageForTrigger QueueSize=0 ,Topic Jarvis/Temperature/Bedroom_1,Payload 68.5

8/29/2022 9:07:56 AM 215195 | HSEvent VALUE_CHANGE| 1024| | 73| 72.9| 810
8/29/2022 9:07:56 AM 215195 | Publish Jarvis/Temperature/Bathroom _1=73
8/29/2022 9:07:56 AM 215196 | ProcessMessage Jarvis/Temperature/Bathroom _1
8/29/2022 9:07:56 AM 215199 | ActOnMessageForTrigger QueueSize=0 ,Topic Jarvis/Temperature/Bathroom _1,Payload 73

8/29/2022 9:05:43 AM 82980 | HSEvent VALUE_CHANGE| 1024| | 81| 80.8| 847
8/29/2022 9:05:43 AM 82980 | Publish Jarvis/Temperature/Attic_1=81
8/29/2022 9:05:43 AM 82980 | ProcessMessage Jarvis/Temperature/Attic_1
8/29/2022 9:05:43 AM 82984 | ActOnMessageForTrigger QueueSize=0 ,Topic Jarvis/Temperature/Attic_1,Payload 81

8/29/2022 9:09:30 AM 309720 | Write Influx Name Watts - Washer
8/29/2022 9:09:30 AM 309735 | HSEvent VALUE_CHANGE| 1024| CB78CCF3-018-Q6| 1.395| 1.498| 80
8/29/2022 9:09:30 AM 309735 | Publish Jarvis/Energy/Washer=1.395
8/29/2022 9:09:30 AM 309735 | ProcessMessage Jarvis/Energy/Washer
8/29/2022 9:09:30 AM 309736 | ActOnMessageForTrigger QueueSize=0 ,Topic Jarvis/Energy/Washer,Payload 1.395

Only the Washer has the line "Write Influx Name Watts - Washer". I see this over and over in the "mcsMQTT Debug.txt".

I am thinking I can remove all the devices and re-add them back into mcsMQTT, but even if that works I have no idea why it stopped logging or how to prevent it if it happens again.

Attached is the entire "mcsMQTT Debug.txt" log

Thanks for the help!

[jeanv]

So I went ahead and removed all the devices that were not being written to the InfluxDB. I then stopped and restarted the mcsMQTT plugin and then added them all back in to mcsMQTT. They are back to being written into the InfluxDB. I hope it stays that way. No idea on why they stopped being written.

[Michael McSharry]

mcsMQTT builds a dictionary of Ref vs. the InfluxDB field name. It builds this dictionary on startup and when the field name selection on History tab changes. It also selectively edits when the L column on the Assocation table is altered. The lack of write in HSEvent means that the Ref is not in this dictionary. Clues as to why may be around the type of actions that you have been taking that affect this dictionary as described in herein.

[jeanv]

Ok this is becoming a problem. Once again the Temperature sensors that are parent/root device (and ONLY those) STOPPPED logging all of a sudden exactly like before. I did not touch or change anything. What is going on here? I take no actions on the devices. The RFXCom plugin reliably updates the values of the Oregon Scientific temperature sensors. The one that is NOT experiencing this problem is a ZWave temperature sensor. There are no events or any manipulation of the devices at all on my end.



As you can see three of my Oregon Scientific temperature sensors just stopped all of a sudden. These three are also all Parent/Root devices.

TS - Bedroom - Device Ref# 862
TS - Bathroom Shower Area - Device Ref# 810
TS - Attic - Device Ref# 847

But then I also have a ZWave Temperature sensor (TS - MS - Utility Room 1) that works just fine and does not stop logging. It is a child/feature device.

Can you tell me what steps I need to take to understand why this is happening and how I can make logging the temperature reliable from all my devices?

My other thought that I really want to avoid doing was just to create an event for each temperature sensor that triggers when the value is set and have it fire off a script that logs the value into InfluxDB. This should work, but I would really prefer to keep everything in mcsMQTT itself.

[Michael McSharry]

In the attached is a plugin version that has debug output for every step in the process of writing to InfluxDB starting from the HSEvent. Seven steps are added to the debug. My test output is shown below. Odd that the HSEvent does not show up first, but likely just a threading sequence issue to file output.

1) is the list of Ref's and InfluxDB Field names. The Ref needs to be in this list to proceed, Ref is number before colon and next field separate with comma
2) Ref present so request to put into queue
3) & 4) managing the queue
5) remove from queue in different thread
6) write to InfluxDB completed
7) when queue becomes empty and second thread goes into hibernation

8/30/2022 8:56:15 AM 1277905 | 1)Influx Fields 35:DS18B20_DS18B20_DS18B20:DS18B20-1:Id-012025907848:Temperature, 36:DS18B20_DS18B20_DS18B20:DS18B20-6:Id2-H6:Humidity,
8/30/2022 8:56:15 AM 1277934 | 2)Request InfluxDB 35 DS18B20_DS18B20_DS18B20:DS18B20-1:Id-012025907848:Temperature to 11
8/30/2022 8:56:15 AM 1277966 | 3)InfluxQueueRequest for 35 DS18B20_DS18B20_DS18B20:DS18B20-1:Id-012025907848:Temperature to 11
8/30/2022 8:56:15 AM 1277966 | 4)InfluxQueueRequest for 35 queued
8/30/2022 8:56:15 AM 1278004 | 5)InfluxDB Dequeued, Remaining Queue size =0
8/30/2022 8:56:15 AM 1278004 | Write Influx Name DS18B20_DS18B20_DS18B20:DS18B20-1:Id-012025907848:Temperature
8/30/2022 8:56:15 AM 1278004 | HSEvent VALUE_SET| 2048| DS18B20| 11| 11| 35
8/30/2022 8:56:17 AM 1280060 | 6)InfluxDB Write Completed, Remaining Queue size =0
8/30/2022 8:56:17 AM 1280060 | 7)InfluxDB queue empty, thread waiting

[jeanv]

This looks great! Here is what I did:

1. I installed your new version with the detailed debugging into the InfluxDB
2. I deleted the 3 Temperature sensors that seem to drop off
3. I even deleted the existing InfluxDB bucket and created an brand new one
4. I restarted everything
5. I turned debug on
6. I re-added the 3 Temperature sensors that seem to drop off (REF# 810 / REF# 847 / REF# 862)

I then looked at the debug log and here is what I saw:

8/30/2022 1:40:40 PM 827124 | 1)Influx Fields 1413:Watts - Whole House Phase A, 1414:Watts - Whole House Phase B, 1435:Watts - Whole House, 117:TS - MS - Utility Room 1, 129:Watts - Martys AC, 140:Watts - Dryer, 80:Watts - Washer, 94:Watts - Dishwasher, 847:TS - Attic, 862:TS - Bedroom, 810:TS - Bathroom Shower Area,
8/30/2022 1:40:40 PM 827124 | 2)Request InfluxDB 847 TS - Attic to 90.1
8/30/2022 1:40:40 PM 827124 | 3)InfluxQueueRequest for 847 TS - Attic to 90.1
8/30/2022 1:40:40 PM 827124 | 4)InfluxQueueRequest for 847 queued
8/30/2022 1:40:40 PM 827124 | 5)InfluxDB Dequeued, Remaining Queue size =0
8/30/2022 1:40:40 PM 827124 | Write Influx Name TS - Attic
8/30/2022 1:40:40 PM 827128 | 6)InfluxDB Write Completed, Remaining Queue size =0
8/30/2022 1:40:40 PM 827128 | 7)InfluxDB queue empty, thread waiting

So far so good! I will keep the debug going since logging the temperature on these three devices has not lasted more than a day before it stops for some reason.

Anything else I should be doing to capture the data?

[Michael McSharry]

You can assess if the HS Energy database is storing the data that you expect. This debug version has the DeviceAPI updates.

I would also suggest not storing data in short term database. It is primarily intended for data with temporary retention for analysis. If you have the same data in InfluxDB there is no point of which I am aware to store it in a second database.

[jeanv]

Ok, so unfortunately as expected, the 3 Temperature sensors that seem to drop off (REF# 810 / REF# 847 / REF# 862), did again drop off. I noticed that it happened after I stopped the mcsMQTT service and restarted it.

Those 3 temperature sensors (the ones that are updated from RFXCom plugin and are Parent/Root Devices) last logged at (8/31/2022 11:38:14 AM) after that were were no more log entries and the InfluxDB never saw them again. I did not change anything at all other than I stopped the mcsMQTT service and restarted it.

I will attach the log files both before and after.

Here is what I see:

Before stopping mcsMQTT:

8/31/2022 11:38:14 AM 41889097 | 1)Influx Fields 1413:Watts - Whole House Phase A, 1414:Watts - Whole House Phase B, 1435:Watts - Whole House, 117:TS - MS - Utility Room 1, 129:Watts - Martys AC, 140:Watts - Dryer, 80:Watts - Washer, 94:Watts - Dishwasher, 847:TS - Attic, 862:TS - Bedroom, 810:TS - Bathroom Shower Area,
8/31/2022 11:38:14 AM 41889097 | 2)Request InfluxDB 862 TS - Bedroom to 70.7
8/31/2022 11:38:14 AM 41889097 | 3)InfluxQueueRequest for 862 TS - Bedroom to 70.7
8/31/2022 11:38:14 AM 41889097 | 4)InfluxQueueRequest for 862 queued
8/31/2022 11:38:14 AM 41889097 | 5)InfluxDB Dequeued, Remaining Queue size =0
8/31/2022 11:38:14 AM 41889098 | Write Influx Name TS - Bedroom
8/31/2022 11:38:14 AM 41889102 | 6)InfluxDB Write Completed, Remaining Queue size =0
8/31/2022 11:38:14 AM 41889102 | 7)InfluxDB queue empty, thread waiting

As you can see REF# 862 is there and it also appears in the InfluxDB

After re-starting mcsMQTT

8/31/2022 11:56:35 AM 2915 | 1)Influx Fields 1413:Watts - Whole House Phase A, 1414:Watts - Whole House Phase B, 1435:Watts - Whole House, 117:TS - MS - Utility Room 1, 129:Watts - Martys AC, 140:Watts - Dryer, 80:Watts - Washer, 94:Watts - Dishwasher,
8/31/2022 11:56:35 AM 2915 | 2)Request InfluxDB 94 Watts - Dishwasher to 0
8/31/2022 11:56:35 AM 2916 | 3)InfluxQueueRequest for 94 Watts - Dishwasher to 0
8/31/2022 11:56:35 AM 2916 | 4)InfluxQueueRequest for 94 queued
8/31/2022 11:56:35 AM 2916 | 5)InfluxDB Dequeued, Remaining Queue size =0
8/31/2022 11:56:35 AM 2917 | Write Influx Name Watts - Dishwasher
8/31/2022 11:56:35 AM 2929 | 6)InfluxDB Write Completed, Remaining Queue size =0
8/31/2022 11:56:35 AM 2929 | 7)InfluxDB queue empty, thread waiting

Now as you can see, the exact three devices that tend to disappear (REF# 810 / REF# 847 / REF# 862) are gone from "1) Influx Fields". Why?

Here is the graph of the InfluxDB


You can see from the chart that they all stopped logging at about 11:40 AM.

I can record video of me adding these devices if you like and making them drop off the InfluxDB if that helps. One interesting note is that even though the updates to InfluxDB stops, mcsMQTT still keeps publishing their values to the MQTT Topic on the broker.

Here is the link to the zipped up log file:

https://www.dropbox.com/sh/02eze4rxp...E4bBEXXKa?dl=0

[Michael McSharry]

The key piece of information is that it is not dependent upon time, but upon a restart of the plugin. The problem manifests itself on initialization sequence during startup. The analysis is below just for the record, but 5.26.5.3 (attached) updates the logic in the alternate init path where the dependency on being a Feature still existed in the code. I removed this dependency and also added debug output during the init when the InfluxDB list of Refs is being collected.

I do not think you will have the same problem, but if you do then provide the debug again. Once confirmed I will remove the extra debug.


List of Ref going to InfluxDB on initial debug. Note 862 not in list

1413:Watts - Whole House Phase A,
1414:Watts - Whole House Phase B,
1435:Watts - Whole House,
117:TS - MS - Utility Room 1,
129:Watts - Martys AC,
140:Watts - Dryer,
80:Watts - Washer,
94:Watts - Dishwasher,
847:TS - Attic, 862:TS - Bedroom,
810:TS - Bathroom Shower Area,

List of Ref going to InfluxDB on 2nd debug. Note 847 & 810 no longer present

1413:Watts - Whole House Phase A,
1414:Watts - Whole House Phase B,
1435:Watts - Whole House,
117:TS - MS - Utility Room 1,
129:Watts - Martys AC,
140:Watts - Dryer,
80:Watts - Washer,
94:Watts - Dishwasher,

List of Ref going to InfluxDB on 3rd debug. Same as 2nd debug.

1413:Watts - Whole House Phase A,
1414:Watts - Whole House Phase B,
1435:Watts - Whole House,
117:TS - MS - Utility Room 1,
129:Watts - Martys AC,
140:Watts - Dryer,
80:Watts - Washer,
94:Watts - Dishwasher,

[jeanv]

Michael McSharry, this version of your plugin fixed the issue! I tried multiple stops of the plugin and even rebooted the entire PC and those devices still kept writing to the InfluxDB!!! Yay!!! I can't thank you enough and I truly appreciate all your work! You responsiveness and willingness to get everything working is amazing!

My next step will be to add the rest of my devices to be logged and work on creating charts of them...

[Michael McSharry]

Nice to work with those who are considerate and try to be as helpful as possible in describing the problems that they observe.