Doors opening without commands?

[drprm1]

Both of my MyQ controlled garage doors opened this morning seemingly without any commands from  eisy. (or was there?)

Here is a piece from the nodeserver log when it happened.

 

 

2023-05-16 06:25:01,046 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg0860126d59 :: GV0 to 46376 UOM 58
2023-05-16 06:25:01,171 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg08200e4ffc :: GV0 to 330461 UOM 58
2023-05-16 06:26:00,896 Thread-606 udi_interface      INFO     myqns:longPoll: Updating node states in longPoll()...
2023-05-16 06:26:01,072 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg0860126d59 :: GV0 to 46435 UOM 58
2023-05-16 06:26:01,151 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg08200e4ffc :: GV0 to 330520 UOM 58
2023-05-16 06:26:50,617 Command    udi_interface.node ERROR    node:runCmd: node service command DOF not defined
2023-05-16 06:26:50,660 Command    udi_interface.node ERROR    node:runCmd: node gw0f000aa6dd command DOF not defined
2023-05-16 06:26:51,463 Command    udi_interface.node ERROR    node:runCmd: node gw270009dd76 command DOF not defined
2023-05-16 06:26:51,544 Command    udi_interface      INFO     nodes:cmd_dof: Closing door for Patio Garage Door in DOF command handler.
2023-05-16 06:26:52,000 Command    udi_interface      INFO     nodes:cmd_dof: Closing door for Garage Door Opener in DOF command handler.
2023-05-16 06:26:52,049 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg08200e4ffc :: ST to 3 UOM 25
2023-05-16 06:26:52,386 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg0860126d59 :: ST to 3 UOM 25
2023-05-16 06:27:02,263 Thread-611 udi_interface      INFO     myqns:shortPoll: Updating node states in shortPoll()...
2023-05-16 06:27:02,416 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg0860126d59 :: ST to 4 UOM 25
2023-05-16 06:27:02,548 MQTT       udi_interface.interface INFO     interface:_message: Successfully set cg0860126d59 :: GV0 to 7 UOM 58

 

Would appreciate any insight here

Edited May 16, 2023 by drprm1

[stevehoyt]

did you look in the MyQ history in the app.

Sometimes there is additional info there as to where the command came from.

[drprm1]

History in app just shows both opened. No additional info unfortunately..

[drprm1]

Don't know if relevant but in my isy error log there are about twenty entries at the time they opened

"140005 ISY"

Don't know if this is any help but I sure don't need them opening like this again. 

[Geddy]

@drprm1 probably best course of action is to submit a support ticket to UDI perhaps submit your ISY error log and node server log package in the ticket when you submit. This way UDI can review the IoX log files and review the node server log with the developer. 

https://www.universal-devices.com/my-tickets/

For the node server log click on log, change it to debug wait a little bit then restart the node server and wait again. If log has reset to "info" put it back in debug and operate the door a couple of times (by button/remote press, MyQ app, and IoX command). Just so all types of triggers are attempted and perhaps any logging done by the node server will be captured. Then download the log for the node server. The log type should change back to info, but be sure it's set to "info" when you are done. It's not a good idea to leave logs in debug mode. I think they have edited PG3/PG3x to reset it to info to not have huge log files, but best bet is to set it yourself.

Of course UDI Support might suggest other logging options as well, but this will at least give them a better starting point when opening the ticket. 

[Goose66]

There appears to be two things going on here (both which may be issues):

1. There appears to have been an "All Off" command sent to most likely all your devices. This is evident in that both of your garage door opener nodes received a DOF (Close) command at 06:26:50 am in addition to two gateway nodes and the MyQ Service node, which logged errors because they don't support Close (DOF) commands.

This is (and has been for some time) possible from the top-level of the node tree. I think it is an artifact leftover from when 99% of your devices were Insteon lights. As is the case with most node servers, the MyQ node server uses the base On (DON) and Off (DOF) commands for actions, in that the ISY didn't support a lot of specific commands (like an Open or Close command) in the early days. That may not be the case now, but the MyQ node server has always used DON and DOF for open and close going all the way back to the Polyglot v1 version. But if the user goes to the top level of the node tree in the Admin Console and does an "All On" or "All Off," all of the nodes receive the DON or DOF command and will respond accordingly (or error out if DON and/or DOF are not supported).

2. It further appears that both doors received the Close (DOF) commands, sent "close" commands to the MyQ service for both doors, and then changed the status of the doors to "Closing" (again, as evident from the log entries posted). However, 10 seconds later the status returned from the MyQ service for at least the first door was "Opening." So, either something went wrong in the MyQ service in receiving the "close" command and it opened the doors instead, or the doors were opened, started closing, and hit some sort of obstacle and reopened after the command. This may be a harder issue to nail down, and would be best troubleshooted by changing the logging level for the node server to "DEBUG" in the PG3 Dashboard and then opening and closing the doors via commands from the ISY Admin Console (please allow a couple of minutes between commands so that the doors can get through the whole remote open and close cycles). Then DM me the log files. NOTE: changing the logging level to Debug WILL EXPOSE YOUR CREDENTIALS in the log file, so only DM me the log files and don't post any log entries here.

Edited May 16, 2023 by Goose66

[drprm1]

Tried to DM but get error "Goose66 cannot recieve messages"

[Goose66]

2 minutes ago, drprm1 said:

Tried to DM but get error "Goose66 cannot recieve messages"

Hmmm.... @Geddy ?

[drprm1]

Sent,

thanks!

[Goose66]

14 minutes ago, drprm1 said:

Sent,

thanks!

Oops, sorry. I meant to say that I can see I can't get messages and that I was asking @Geddy why that was the case. Maybe a little TOO MUCH shorthand. Anyway, maybe @Geddy will forward to me.

[drprm1]

🤣

Thought yall were sitting next to each other

Edited May 16, 2023 by drprm1

[Geddy]

@Goose66 looks like you’ve hit the quota on messages. Maybe delete some and @drprm1 can msg you.

LOL @drprm1 nice try. I’m “just” a user like many others. Only helping out on the forums to keep things neat and tidy at times. 

[Goose66]

Thanks, @Geddy. @drprm1, try sending the log file to me again.

[drprm1]

Tried. Won’t go through

Tried again with success

Edited May 17, 2023 by drprm1

[Goose66]

@drprm1 Received the DM with the log files. Good to know you found the "All Off" command and disabled it. That one really doesn't make much sense in the current ISY ecosystem because so many different types of devices are integrated in the controller. 

Looks like after the initial problem at 6:26 am the MyQ service behaved pretty well, i.e., if you sent an open command they went to "Opening" state and then "Open" state in a few seconds, and if you sent a close command they went to "Closing" and then "Closed" state. Hopefully the physical response you noticed in the door operation was consistent with this. From your door IDs, I am going to guess that you have the MyQ Smart Garage Control system and not actual Chamberlain/Liftmaster door openers. Because this system can only assume the open/closed state from the last position change transmitted by the sensor, it is possible that the MyQ service had a bad internal state and sent an activation to the door even though it was already closed. That would have caused it to actually open, and then when the sensor transmitted the state change, the state changed from "Closing" to "Opening" and then eventually to "Open."

If you check your "History" in the MyQ app, it should show the Close commands coming through around 6:26 am yesterday from your name, and it would be interesting to see if there are subsequent entries with no name changing the state to "Open."

Just to wrap up, the net-net is that I don't really see any To-Dos here for the the MyQ Node Server, and we just need to watch more carefully and see if this weird state tracking error (if that is what it was) happens again.

[drprm1]

Very much appreciate your time spent on this.  I will wait for it to happen again....

At least you got your mailbox cleaned out.

Cheers