Solved Owntracks / Mosquitto String updates unexepectedly.

[CatmanV2]

All great stuff going on One thing I am wondering about is is it possible to view the entire payload coming from Owntracks at all?
Reason I ask is that my iPhone has changed its
string_sensor.value to null even though we are snowed in. This obviously trips the binary sensor to off.
The sensor entity I have set to owntracks_in_region however remains true.

The change happened at 0523 this morning (UTC) when I was still asleep:

[latest-22337]2022-12-13T05:19:13.053Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.70: GET /api/v1/systime
[latest-22337]2022-12-13T05:22:05.883Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.253: GET /api/v1/systime
[latest-22337]2022-12-13T05:23:01.087Z <MQTTController:WARN> MQTTController#mqqt if_expr expression payload._type == 'location' || payload._type='transition' returned non-boolean (string)
[latest-22337]2022-12-13T05:23:01.091Z <MQTTController:ERR> MQTTController#mqqt event handler failed for owntracks/catman/catmaniphone on catman_owntracks: [TypeError] Can't set NaN on attribute battery_power.level (mqqt>catman_owntracks) [-]
[latest-22337]2022-12-13T05:23:01.091Z <MQTTController:CRIT> TypeError: Can't set NaN on attribute battery_power.level (mqqt>catman_owntracks) [-]
TypeError: Can't set NaN on attribute battery_power.level (mqqt>catman_owntracks)
    at Entity.setAttribute (/home/catman/reactor/server/lib/Entity.js:453:19)
    at MQTTController.handle_event (/home/catman/reactor/ext/MQTTController/MQTTController.js:935:19)
    at MqttClient.<anonymous> (/home/catman/reactor/ext/MQTTController/MQTTController.js:424:38)
    at MqttClient.emit (node:events:527:28)
    at MqttClient.emit (node:domain:475:12)
    at MqttClient._handlePublish (/home/catman/reactor/ext/MQTTController/node_modules/mqtt/lib/client.js:1547:12)
    at MqttClient._handlePacket (/home/catman/reactor/ext/MQTTController/node_modules/mqtt/lib/client.js:535:12)
    at work (/home/catman/reactor/ext/MQTTController/node_modules/mqtt/lib/client.js:438:12)
    at Writable.writable._write (/home/catman/reactor/ext/MQTTController/node_modules/mqtt/lib/client.js:452:5)
    at doWrite (/home/catman/reactor/ext/MQTTController/node_modules/readable-stream/lib/_stream_writable.js:409:139)
[latest-22337]2022-12-13T05:23:01.092Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>catman_owntracks
[latest-22337]2022-12-13T05:23:01.092Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>catman_owntracks
[latest-22337]2022-12-13T05:23:01.097Z <Timer:null> Timer#rule-lbl1mbdn just a note: I'm setting a delay of only 9ms (from 1670908981095<13/12/2022, 05:23:01> to 1670908981104<13/12/2022, 05:23:01>)
[latest-22337]2022-12-13T05:23:01.098Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluated; rule state transition from RESET to SET!
[latest-22337]2022-12-13T05:23:01.118Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluated; trigger state unchanged (false); rule state remains SET
[latest-22337]2022-12-13T05:23:01.118Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluation complete
[latest-22337]2022-12-13T05:23:01.118Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluation complete
[latest-22337]2022-12-13T05:23:01.119Z <Engine:INFO> Enqueueing "Location Test<SET>" (rule-lbl1mbdn:S)
[latest-22337]2022-12-13T05:23:01.131Z <Engine:NOTICE> Starting reaction Location Test<SET> (rule-lbl1mbdn:S)
[latest-22337]2022-12-13T05:23:01.138Z <Engine:INFO> Location Test<SET> all actions completed.

FWIW I have noticed the issue with the NaN on battery_power.level previously but it was while I was messing around with stuff.

My phone seems to update more frequently than Mrs C's which has not updated at all since I did a location push at 1218 UTC yesterday (to clear the battery_power.level issue.

Debian Bullseye on bare metal

The only thing I can think of right now is that for some reason my phone is sending something duff (although the other parameters (i.e. elevation, long and lat) all seem fine. Forcing a publish from the App results in everything updating as expected.

Log level in Mosquitto is set to all.

C

[toggledbits]

@therealdb your test isNaN(payload.batt) may not be enough... in JavaScript, isNaN(null) is false, but parseFloat(null) is NaN. Some fun, eh?

[toggledbits]

@CatmanV2 said in Owntracks / Mosquitto String updates unexepectedly.:

One thing I am wondering about is is it possible to view the entire payload coming from Owntracks at all?

MQTTController - Reactor - Multi-Hub Automation

[CatmanV2]

@toggledbits Ahh apologies. Not sure I was clear. I can see the topics, what I can't see is the whole payload:

1670926555: New client connected from 192.168.70.1 as catmancatmaniphone (c0, k60, u'catman').
1670926555: Will message specified (32 bytes) (r0, q1).
1670926555:     owntracks/catman/catmaniphone
1670926555: Sending CONNACK to catmancatmaniphone (1, 0)
1670926555: Received PUBLISH from catmancatmaniphone (d0, q1, r1, m8, 'owntracks/catman/catmaniphone', ... (241 bytes))
1670926555: Sending PUBACK to catmancatmaniphone (Mid: 8)
1670926555: Sending PUBLISH to reactor_openluup_mqqt (d0, q0, r0, m0, 'owntracks/catman/catmaniphone', ... (241 bytes))
1670926555: Sending PUBLISH to catmancatmaniphone (d0, q1, r0, m6585, 'owntracks/catman/catmaniphone', ... (241 bytes))
1670926555: Received PUBACK from catmancatmaniphone (Mid: 6585)
1670926560: Received DISCONNECT from catmancatmaniphone

So I would like to see what's in here:

1670926555: Received PUBLISH from catmancatmaniphone (d0, q1, r1, m8, 'owntracks/catman/catmaniphone', ... (241 bytes))

Or am I misunderstanding the concepts?

C

[therealdb]

@toggledbits said in Owntracks / Mosquitto String updates unexepectedly.:

@therealdb your test isNaN(payload.batt) may not be enough... in JavaScript, isNaN(null) is false, but parseFloat(null) is NaN. Some fun, eh?

uh. I'll try to fix that in a future release of the templates. I'm travelling this week and I don't want to release something that's not fully tested.

[toggledbits]

@CatmanV2 said in Owntracks / Mosquitto String updates unexepectedly.:

Or am I misunderstanding the concepts?

Sort of. The topic logging will put the payload in the logged line as well.

Oh, and the snippet you showed isn't from MQTTController, so I don't know where that is or how you change it. I'm talking about what MQTTController can do.

[CatmanV2]

Gotcha, thanks. No it's from Mosquitto. Slightly frustrating that log config to make make timestamps human readable appears buggy as well

C

[therealdb]

I usually use mqtt explorer to see messages. Give it a try.

[CatmanV2]

Oooh that's neat. Ta!

C

[CatmanV2]

@therealdb my test mule has just demonstrated this working perfectly on her trip to the office. The only issue appears to be that NaN thing which makes string_sensor.value go null and so can't (as yet) be used for home presence location.
Other than that, thanks a huge amount! No panic for fix from my side. Will report anything else I see!

C

[therealdb]

@CatmanV2 yep, on my todo list for the week-end. feel free to send my your debug mqtt messages (even privately, if you prefer), and I'll test and fix this very quickly.

[toggledbits]

@therealdb Also know that I'm changing the behavior of the isNaN() function to return true when the argument is null. This is a break from JavaScript's behavior, but I find that behavior strange and inconsistent. In my mind, if parseFloat() and parseInt() return NaN for null, then so should isNaN(). Do you agree?

Edit: FYI, I plan on a released build in the next day or two.

[therealdb]

@toggledbits yes, OK for me. so, no actions on my part?

[toggledbits]

No, that will make it work the way expected (and I would have done the same). No change from you needed.

[CatmanV2]

Morning. Updated reactor and mqtt controller this morning (hope I did it right)

Mrs C left home and this happened:

Her owntrack_sensor:

battery_maintenance.charging=false
battery_maintenance.rechargeable=null
battery_maintenance.replace=false
battery_power.level=0.5
battery_power.since=null
binary_sensor.state=true
location.elevation=null
location.latitude=null
location.longitude=null
string_sensor.value=null
x_mqtt_device.online=true

[latest-22349]2022-12-17T08:05:51.851Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.253: GET /api/v1/systime
[latest-22349]2022-12-17T08:08:06.840Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.70: GET /api/v1/systime
[latest-22349]2022-12-17T08:11:53.693Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.253: GET /api/v1/systime
[latest-22349]2022-12-17T08:12:00.004Z <Rule:INFO> Garden lights on when the doors are open (rule-lb2h69nb in Outside Lights) starting evaluation; because timer-trigger Timer#rule-lb2h69nb
[latest-22349]2022-12-17T08:12:00.007Z <Rule:INFO> Garden lights on when the doors are open (rule-lb2h69nb in Outside Lights) trigger evaluation result is false (previously false)
[latest-22349]2022-12-17T08:12:00.008Z <Rule:INFO> Garden lights on when the doors are open (rule-lb2h69nb in Outside Lights) evaluated; trigger state unchanged (false); rule state remains RESET
[latest-22349]2022-12-17T08:12:00.009Z <Rule:INFO> Garden lights on when the doors are open (rule-lb2h69nb in Outside Lights) evaluation complete
[latest-22349]2022-12-17T08:13:18.980Z <MQTTController:WARN> MQTTController#mqqt if_expr expression payload._type == 'location' || payload._type='transition' returned non-boolean (string)
[latest-22349]2022-12-17T08:13:18.987Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>rachel_owntracks
[latest-22349]2022-12-17T08:13:18.987Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>rachel_owntracks
[latest-22349]2022-12-17T08:13:18.991Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) trigger evaluation result is true (previously false)
[latest-22349]2022-12-17T08:13:18.991Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluated; rule state transition from RESET to SET!
[latest-22349]2022-12-17T08:13:19.001Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) trigger evaluation result is false (previously false)
[latest-22349]2022-12-17T08:13:19.001Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) evaluated; trigger state unchanged (false); rule state remains RESET
[latest-22349]2022-12-17T08:13:19.002Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluation complete
[latest-22349]2022-12-17T08:13:19.002Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) evaluation complete
[latest-22349]2022-12-17T08:13:19.003Z <Engine:INFO> Enqueueing "Location Test<SET>" (rule-lbl1mbdn:S)
[latest-22349]2022-12-17T08:13:19.004Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) starting evaluation; because timer-trigger Timer#rule-lbl1mbdn
[latest-22349]2022-12-17T08:13:19.005Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) trigger evaluation result is false (previously true)
[latest-22349]2022-12-17T08:13:19.005Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluated; rule state transition from SET to RESET!
[latest-22349]2022-12-17T08:13:19.012Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluation complete
[latest-22349]2022-12-17T08:13:19.015Z <Engine:NOTICE> Starting reaction Location Test<SET> (rule-lbl1mbdn:S)
[latest-22349]2022-12-17T08:13:19.018Z <Notifier:null> Module Notifier v22283
[latest-22349]2022-12-17T08:13:19.021Z <Engine:INFO> Location Test<SET> all actions completed.

And then this:

[latest-22349]2022-12-17T08:15:00.036Z <Rule:INFO> Morning Heating (rule-l60fkpo3 in Heating Control) evaluation complete
[latest-22349]2022-12-17T08:16:53.727Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.253: GET /api/v1/systime
[latest-22349]2022-12-17T08:19:07.154Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.70: GET /api/v1/systime
[latest-22349]2022-12-17T08:22:53.684Z <httpapi:INFO> httpapi: API request from ::ffff:192.168.70.253: GET /api/v1/systime
[latest-22349]2022-12-17T08:23:07.941Z <MQTTController:ERR> MQTTController#mqqt expression ( payload.event == 'leave' && lower(payload.data.description) != lower(homeRegionName) ) || ( payload.event == 'enter' && lower(payload.data.description) == lower(homeRegionName) )
 failed evaluation: [ReferenceError] Invalid scope in reference to member description of (object)null [-]
[latest-22349]2022-12-17T08:23:07.944Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>rachel_owntracks
[latest-22349]2022-12-17T08:23:07.944Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) starting evaluation; because entity-changed BinarySensor#mqqt>rachel_owntracks
[latest-22349]2022-12-17T08:23:07.945Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) trigger evaluation result is false (previously false)
[latest-22349]2022-12-17T08:23:07.945Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluated; trigger state unchanged (false); rule state remains RESET
[latest-22349]2022-12-17T08:23:07.945Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) trigger evaluation result is false (previously false)
[latest-22349]2022-12-17T08:23:07.946Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) evaluated; trigger state unchanged (false); rule state remains RESET
[latest-22349]2022-12-17T08:23:07.946Z <Rule:INFO> Location Test (rule-lbl1mbdn in Home or Away) evaluation complete
[latest-22349]2022-12-17T08:23:07.947Z <Rule:INFO> Rachel is at the office (rule-lb6bcyk5 in Home or Away) evaluation complet

Have I done something dumb?
Cheers

C
Also got a lot of these:

[therealdb]

@CatmanV2 nope, it's probably something on my end. But I need your mqtt messages, since I'm using it via HTTP-to-MQTT and messages are slightly different. I'll fix it as soon as I'll get yours. Thanks.

EDIT: just look for the message sent in the /event topic.

[CatmanV2]

@therealdb from MQTT explorer? Right?
Needs to be when it goes south?

Cheers

C

[therealdb]

@CatmanV2 yes. Look specifically for the event message and its payload.

[CatmanV2]

Of course it's not happening now!

C

[therealdb]

@CatmanV2 I have a new version anyway, that's trying to handle null values.
@toggledbits is it possible for MQTTController to dump the payload in case of errors? this will help a lot when dealing with such situations. Thanks.