[Reactor] Bug when sending MQTT boolean payloads

[Alan_F]

Reactor latest-22067 on Raspberry Pi, Influx DB 1.8, both in Docker. Controlling two separate Hubitat C7s.

I am storing data for CPU load and free memory from the Hub Information device on the Hubitat Hub in the Influx database so that I can graph them.

I noticed that for the last two days I was not getting the free memory on my graph. (I don't currently graph the CPU data.) When I restarted Reactor I got two data points and then nothing for a while.

I looked at the Hubitat Hub Information device and could see the numbers changing there. I also watched the entities screen in Reactor and could see it flash green when it updated. Both the Hubitat device and the Reactor entities matched and were updating.

However the Influx database stopped getting new data. What I see in Grafana matches what I see when I directly query the database in a terminal window, so it is not an issue with Grafana.

The Hub Temperature data is updating in the database every time it changes. It is not one of the extra attributes that I added. It is logged as a regular temperature_sensor.

This is the relevant portion of reactor.yaml:

      select_capabilities:   
        light_sensor: true   
        x_hubitat_Thermostat:
          attributes:
            - coolingSetpoint
            - heatingSetpoint
            - thermostatFanMode
            - thermostatMode
            - thermostatOperatingState
            - thermostatSetpoint
            - temperature
        x_hubitat_extra_attributes:
          attributes:
            - cpu5Min
            - cpuPct
            - freeMemory
        wx:
          attributes:
            - temperature
            - humidity
            - cloud_cover

This chart from Grafana illustrates what is happening. The data points circled in red are the pairs of points from two restarts of Reactor. The yellow line and green line represent the two separate Hubitat hubs that I'm connected to. The blue line is the CPU temperature from one of the hubs.

Here is the same graph from a little later to show the CPU temp is continuing to update, but the free memory is not:

Again, the free memory is changing in the entities screen every time it changes in the hub, but the data isn't being saved to InfluxDB after the first two data points.

Looking at the most recent documentation, I saw the format for the attributes was different, using a trailing ":true" intead of a leading "-", so I tried switching my reactor.yaml to match. The section now reads:

    x_hubitat_extra_attributes:
      attributes:
        cpu5Min: true
        cpuPct: true
        freeMemory: true

I restarted Reactor and got the same result.

Final observation... the second data point in each pair is incorrect...

After the last restart I pulled the data from the database.

time                controller    cpu5Min cpuPct entity            freeMemory name
----                ----------    ------- ------ ------            ---------- ----
1646918194198000000 hubitat_11705 0.07    1.75   hubitat_11705>130 526192     Hub information
1646918045910000000 hubitat       0.23    5.75   hubitat>483       324088     Hub information
1646918032985000000 hubitat_11705 0.07    1.75   hubitat_11705>130 526192     Hub information

The first and third lines are relevant here. They are both for the 'hubitat_11705' hub. They show the free memory as 526192 on both lines.

But when the second data point was saved to the database the reactor entity showed:

x_hubitat_extra_attributes.freeMemory="525728"

and the Hubitat device shows:

So the second data point should have been saved in the database as '525728' but instead it saved the previous value of 526192.

Looking back at the annotated Grafana graph I can see the same thing happened with the earlier pairs of points... the second point was the same value as the first, and then there was no more data logged until the next Reactor restart.

[toggledbits]

Checking the logs would be useful here (again: not seeing what you expect? Look at the logs.). Also you haven't shown your queries in Grafana. If you've got mean() or other aggregates in the query, or anything in group by, the presentation is not a representation of the raw feed. Remove all aggregates and groups to make sure you are looking at the raw data. Can be very confusing otherwise. On the road, won't be much responding to this more until I return around 3/20.

[Alan_F]

@toggledbits I wasn't expecting a reply until you got back from vacation and handled other higher priority things, but I'll try to add the additional information now:

What I'm expecting is that each time the data on the Hubitat Hub Information device changes, that the values for that I added in my reactor.yaml file (cpu5Min, cpuPct, freeMemory) will be written to the influx database. This is what it was doing up until two days ago, and I think the change in behavior matches up to when I upgraded to 22067.

The Grafana queries are not using aggregates, nor was the direct query I ran from Influx via the command line, but I should have posted the query I used to pull the data. Here is data I just pulled directly from Influx using a command prompt, filtering on only one hub to make it simpler:

> select * from x_hubitat_extra_attributes where entity = 'hubitat>483' order by time desc limit 6
name: x_hubitat_extra_attributes
time                controller cpu5Min cpuPct entity      freeMemory name
----                ---------- ------- ------ ------      ---------- ----
1646918045910000000 hubitat    0.23    5.75   hubitat>483 324088     Hub information
1646918032714000000 hubitat    0.23    5.75   hubitat>483 324088     Hub information
1646916245576000000 hubitat            3      hubitat>483 325848     Hub information
1646916119494000000 hubitat            3      hubitat>483 325848     Hub information
1646914445106000000 hubitat    0.11    2.75   hubitat>483 325904     Hub information
1646914238104000000 hubitat    0.11    2.75   hubitat>483 325904     Hub information

Starting from the bottom of the list with the oldest two records, they are about 4 minutes apart but show the exact same numbers.

The next two records again are about 4 minutes apart and show the same numbers.

The top two records are about 1 minute apart and show the same numbers.

Between each pair of logged values I restarted Reactor. On the last set - the top two in this list - I was watching the Reactor Entities screen and saw that the Hub Information entity updated at the time the last data point was stored, but the values were NOT 0.23, 5.75, and 324088.

I can upload logs when you get back. I looked at the times in the log when this data was stored and I don't see anything related to Influx. I do see the updates coming from the Hub Information device.

I was able to find the logs corresponding to the two records in the middle (showing 325848 as the freeMemory)

The timestamp on the older one converts to: Thursday, March 10, 2022 12:41:59.494 PM

In the logs I find the value for the freeMemory a few minutes earlier at 12:39:05Z. I think the time discrepancy is because I restarted Reactor between when the value was logged and when it got written to the database. When Reactor started up, it wrote the most recent value to Influx.

[latest-22067]2022-03-10T12:39:05.568Z <HubitatController#hubitat:5:HubitatController.js:641> HubitatController#hubitat received DEVICE event [Object]{ "source": "DEVICE", "name": "freeMemory", "displayName": "Hub information", "value": "325848", "type": "null", "unit": "KB", "deviceId": 483, "hubId": 0, "installedAppId": 0, "descriptionText": "null" }
[latest-22067]2022-03-10T12:39:05.569Z <HubitatController#hubitat:INFO> HubitatController#hubitat fast update Entity#hubitat>483 event freeMemory="325848"
[latest-22067]2022-03-10T12:39:05.569Z <HubitatController#hubitat:INFO> HubitatController#hubitat fast update Entity#hubitat>483 event freeMemory="325848"

The next record from the database with the same values has a timestamp that converts to Thursday, March 10, 2022 12:44:05.576 PM

That matches up in the logs with this:

[latest-22067]2022-03-10T12:44:05.632Z <HubitatController#hubitat:5:HubitatController.js:641> HubitatController#hubitat received DEVICE event [Object]{ "source": "DEVICE", "name": "freeMemory", "displayName": "Hub information", "value": "325884", "type": "null", "unit": "KB", "deviceId": 483, "hubId": 0, "installedAppId": 0, "descriptionText": "null" }
[latest-22067]2022-03-10T12:44:05.633Z <HubitatController#hubitat:5:HubitatController.js:643> HubitatController#hubitat ws DEVICE event device 483 freeMemory="325884"
[latest-22067]2022-03-10T12:44:05.633Z <HubitatController#hubitat:INFO> HubitatController#hubitat fast update Entity#hubitat>483 event freeMemory="325884"

So at 12:44:05 I'm expecting the freeMemory written to the database to be 325884, but the database query returned 325848, the previous value from a few minutes earlier in the logs.

The next instance of the hub freeMemory in the logs is at 12:49:05Z

[latest-22067]2022-03-10T12:49:05.763Z <HubitatController#hubitat:5:HubitatController.js:641> HubitatController#hubitat received DEVICE event [Object]{ "source": "DEVICE", "name": "freeMemory", "displayName": "Hub information", "value": "325664", "type": "null", "unit": "KB", "deviceId": 483, "hubId": 0, "installedAppId": 0, "descriptionText": "null" }
[latest-22067]2022-03-10T12:49:05.764Z <HubitatController#hubitat:5:HubitatController.js:643> HubitatController#hubitat ws DEVICE event device 483 freeMemory="325664"
[latest-22067]2022-03-10T12:49:05.765Z <HubitatController#hubitat:INFO> HubitatController#hubitat fast update Entity#hubitat>483 event freeMemory="325664"

There is no corresponding record in the Influx database. I would expect an entry with freeMemory of 325664.

There are additional logs showing the Hubitat Hub Information device updating values every few minutes, but nothing was added to the database until after 1:13:52Z when I restarted Reactor. Then I got the two entries showing a freeMemory of 324088, but as with the middle two record in the query results, the second one of the pair is wrong. The last (top of the list) data in the database shows freeMemory of 324088 and its timestamp converts to Thursday, March 10, 2022 1:14:05.910 PM

The log shows:

[latest-22067]2022-03-10T13:14:05.943Z <HubitatController#hubitat:5:HubitatController.js:641> HubitatController#hubitat received DEVICE event [Object]{ "source": "DEVICE", "name": "freeMemory", "displayName": "Hub information", "value": "323712", "type": "null", "unit": "KB", "deviceId": 483, "hubId": 0, "installedAppId": 0, "descriptionText": "null" }
[latest-22067]2022-03-10T13:14:05.945Z <HubitatController#hubitat:5:HubitatController.js:643> HubitatController#hubitat ws DEVICE event device 483 freeMemory="323712"
[latest-22067]2022-03-10T13:14:05.945Z <HubitatController#hubitat:INFO> HubitatController#hubitat fast update Entity#hubitat>483 event freeMemory="323712"

I would have expected the database entry at 13:14:05Z to show 323712 as the freeMemory value.

I haven't restarted Reactor since then, and as I type this several hours later, no new data for these attributes has made it into the database.

[toggledbits]

I'm not quite out the door yet; I was just leaving ample room for packing, and whatever support my older son needed for a final exam he was taking today.

So I see two things contributing here:

1. There is an opportunity for a value change that occurs during a loss of connection to the hub and a reconnect to be missed; that is, if Reactor stays running, but the hub is rebooted, Reactor may miss a value that changes (and free memory would almost certainly change there). This would be due to the new fast update behavior, so a new issue. That will take a code fix, which I can safely and quickly make in the next hour or so.

2. The event websocket is sending all values for updated (Hubitat) attributes as strings. That's disappointing. That will make InfluxDB choke, because the values given by Maker API, which are the first values inserted into the database, will be numbers, thereby cementing the type for that field in InfluxDB. Thereafter, the attempt to insert a string will fail because the data types don't match. This is a chronic InfluxDB problem, and I actually made some code changes to the integration about a month ago to help get around that problem when it comes up. So, you will need to modify your InfluxDB plugin config to look more like this:

        x_hubitat_extra_attributes:
          attributes:
            cpu5Min:
              type: number
            cpuPct:
              type: number
            freeMemory:
              type: number
            uptime:
              type: number

This will make the plugin coerce (if it can) each value to its "proper" type before handing it off to InfluxDB. You can do this now, and it should have an immediate effect on your updates. The code change mentioned above (item 1) handles a rarer circumstance that you could also see, but is probably not the major contributor to what is going on for you today. Try this change out, and see if it helps. I expect it will. If so, you may want to consider adding this to other attributes being exported to InfluxDB.

I can do more in HubitatController to make sure the types are properly converted when they come in from the event websocket, but that's a bigger change that I'm reticent to make right now. The code change to fix the restart update is small, so I'm more confident in making that change today, but I'll leave the rest for later. The type configuration should work around that issue pretty effectively until I get back.

[Alan_F]

Just realized I was only looking in the Hubitat.log file, which we turned on while trying to troubleshoot something else, and not in the reactor.log file... Ugh... need more coffee before trying to troubleshoot. Apologies for making this more difficult by missing that. In the reactor.log files I found the Influx errors saying that the database field was type 'float' and the data from the hub was 'string'. If I had posted that at the top of this thread, it would be a much shorter read.

After changing the attributes as you showed above I'm now getting correct data into the database and I'm not seeing errors in reactor.log.

[toggledbits]

What you posted was great, and I was able to see the string data in the events, so clue attained, and that's a win. We'll fix it right when I get back.