nodes::updateState called every 30 seconds; any way to sync this with sending commands?

[DSwallow]

I was playing around today with an idea of hitting a ceiling fan with on commands for a short time to start it moving, then sending an off command and waiting a short time and doing the sequence again. This lets me gently spin the fan instead of being stuck at the lowest possible speed always-on. It's actually working out rather well in the sense I'm getting the gentle air movement I sometimes want. Right now I'm going 5 seconds on then 8 seconds off and repeating. Though I'll likely experiment with different patterns.

However, viewing the state of the fan in the UI, I rarely see the on/off state changing, so I looked at the Bond node server logs and see that the node server appears to query the state every 30 seconds and send that as an update. So, the state only matches up if it happens to do a query right after sending a command. Would there be a chance of either triggering the query of the specific device commanded immediately after processing a command, or similarly just sending the state as if the command executed?

I don't really need the current state to match exactly, but it might be useful in the future if it did, rather than only updating every 30 seconds, out of sync with commands.

Make sense?

[Goose66]

The Bond node server relies on two mechanisms for state updates. The first is polling the Bond Bridge via a REST API every shortPoll interval (the node server also uses the REST API to execute commands). The second is a UDP socket connection over which the Bond Bridge streams events in real-time. Bond refers to the UDP socket connection mechanism as "BPUP."

When you execute a command on a device connected to a Bond Bridge, the corresponding change(s) in state for the device should be streamed back to the node server via BPUP and your IoX should update in real-time. If this is not happening for you, then something is wrong with the node server on your platform and we need to debug what's going on. I will need log file package from the node server in DEBUG-level logging and containing a restart of the node server in order to determine why BPUP doesn't seem to be working for you.

Edited November 9, 2023 by Goose66

[DSwallow]

After doing the Restart it seems to be working. I went back down to just Info and notice now I see a log entry for "BPUP_Listener" corresponding to each command turning the fan on or off, which I did not see before. So I suppose there's nothing to follow up here at the moment and things are working. 

Looking at the logs, I see a time when after a command there was a similar log line, the last being:

2023-11-08 10:49:25,620 Command    udi_interface      INFO     nodes:cmd_dof: Turn off light in cmd_dof: {'address': '3c8f19f5_dl', 'cmd': 'DOF', 'query': {}}
2023-11-08 10:49:25,693 BPUP_Listener udi_interface      INFO     nodes:_BPUP_statusUpdate: Device status update received for device 3c8f19f5 on bridge zzdf73384.

And then the next commands have nothing:

2023-11-08 16:46:29,468 Command    udi_interface      INFO     nodes:cmd_don: Turn on fan in cmd_don: {'address': '3f071c36', 'cmd': 'DON', 'query': {}}
2023-11-08 16:46:29,543 Command    udi_interface      INFO     nodes:cmd_don: Turn on light in cmd_don: {'address': '3f071c36_dl', 'cmd': 'DON', 'query': {}}
2023-11-08 16:46:52,932 Thread-3101 udi_interface      INFO     nodes:updateNodeStates: Updating node states for bridge zzdf73384...

I will restart it with debug selected and leave it running; maybe after 6 hours or more it stops; looks like I'd last restarted it about 25 hours ago.   

[Goose66]

The BPUP_Listener is run on a separate thread and opens the socket to listen for BPUP events. If that thread is dying for some reason, that may be the problem. Mine has been running for months, however, and the thread stays up.

[DSwallow]

On 11/8/2023 at 9:55 PM, Goose66 said:

The BPUP_Listener is run on a separate thread and opens the socket to listen for BPUP events. If that thread is dying for some reason, that may be the problem. Mine has been running for months, however, and the thread stays up.

  

I noticed I was back to the delayed visibility of the current state and checked the latest log and found no BPUP_Listener thread again. I've been downloading logs mostly regularly and did discover I apparently captured the log where it stopped.

The relevant items look pretty straightforward, at least as to why the thread apparently died... after that error line, there's no sign of the thread again.

2023-11-15 14:34:16,692 Thread-2137 udi_interface.node DEBUG    node:setDriver: 5d7253e6_lt:Theatre Fan Light No change in ST's value
2023-11-15 14:34:20,230 BPUP_Listener udi_interface      DEBUG    bondapi:_BPUP_keepAlive: Sending keep alive message to Bond Bridge...
2023-11-15 14:34:22,241 BPUP_Listener udi_interface      ERROR    bondapi:_BPUP_keepAlive: Bond Bridge did not respond to keep-alive message - connection closed.
2023-11-15 14:34:45,906 MQTT       udi_interface.interface DEBUG    interface:_message: QUEUING incoming message shortPoll
2023-11-15 14:34:45,907 Command    udi_interface.interface DEBUG    interface:_parseInput: DEQUEING shortPoll
2023-11-15 14:34:45,907 Thread-2138 udi_interface      DEBUG    bondns:shortPoll: In shortPoll()...
2023-11-15 14:34:45,907 Thread-2138 udi_interface      INFO     nodes:updateNodeStates: Updating node states for bridge zzdf73384...
2023-11-15 14:34:45,907 Thread-2138 udi_interface      DEBUG    bondapi:_call_api: HTTP GET /v2/sys/version data: {}
2023-11-15 14:34:46,279 Thread-2138 udi_interface      DEBUG    bondapi:_call_api: HTTP response code: 200 data: {"target":"zermatt","fw_ver":"v2.14.5","fw_date":"Mon Aug 24 21:40:36 UTC 2020","uptime_s":93191,"boot_patch":"not outdated","make":"Olibra","model":"BD-1000","branding_profile":"OLIBRA_BD1000","bondid":"ZZDF73384","upgrade_http":true,"api":2,"_":"86d859b4"}

 

I've uploaded the full log package if that has anything you need, though I don't have a log from when the service initialized this time, I could provide one from restarting it now if that'd offer anything you need.

https://dswallow-my.sharepoint.com/:u:/g/personal/dswallow_2150_com/ERPLnR10CxFGgTZBxiuIGdMBbewwx0G7QtUzmqBW8yBZrA?e=0NGMff

 

[Goose66]

That’s pretty straightforward. It should restart the BPUP listener thread, however. I believe it does it in the next longpoll? I will look into it when I return to the U.S. in a couple of weeks.