Unknown "timeout" in Logs... Any Ideas Where it Might be From?

🚧 Developers
1

Question:
Does anyone know if the Hubitat system itself can post a debug entry in the log for a device, regardless of what the driver code has?

Background:
I was checking over my Logs while starting to investigate another thing with one of my drivers (Unifi Protect) and I found an odd Log entry (below is just a few of them to show the repetition). It is a debug entry that just reads "timeout" and happens every hour at X:55:34.

[dev:310]2024-02-04 10:55:34.443 AM[debug]timeout
[dev:310]2024-02-04 09:55:34.307 AM[debug]timeout
[dev:310]2024-02-04 08:55:34.280 AM[debug]timeout

What I am wondering is, what could be generating this message? The reason I ask is:

  1. I do not have ANY logging setup that could generate this message in my driver. EVERY log entry I make in my code uses a Logging function I wrote and a common element is that it always starts with the device name. So even if I DID make an entry named "timeout" my function would always start it with "UDMP Protect - " (dev 310's name). Here are a couple examples of how that comes out normally (with two entries showing data Unifi has added that my code is not handling yet, so it is letting me know to add support for them or ignore them):
[dev:310]2024-02-04 09:20:42.307 AM[debug]UDMP Protect - Unhandled data for NVR XYZ lastDeviceFWUpdatesCheckedAt = 1707034085561
[dev:310]2024-02-04 09:20:41.233 AM[debug]UDMP Protect - Unhandled data for Camera YZX audioSettings = [style:[nature]]
  1. I do not have ANY entries that are just "timeout" in the code. Even some cases where there are timeout responses for queries start off with "Request Timeout" or such.
  2. I do not have ANY log.debug that might bypass my Logging.
  3. I do not have ANY scheduled tasks that run near that timeframe. The only hourly task is a refresh, but that runs at X:20:40.

The only thing I can think of is that this driver/device does make use use WebSockets so it might be getting triggered by something there... but again, there is nothing in my driver code that could make a debug log entry like that. WebSocket code is based on @tomw's version with some changes I have made (one of which was switching all the logging over to my function).

If someone wants to look at the code it is the UnifiProtectAPI.groovy parent driver in the project I linked at the beginning.

EDIT:
Tagging @gopher.ny in the hopes someone in Hubitat might know since the forum has been crickets about this one for more than a week.

2

When you click on this part below - doesn't it highlight a device at the top of your logs page?

image

E.g.,

image

3

Yes, it does. It is for my UDMP Protect device. That is how I knew which device to check for any scheduled tasks, which driver to check, etc...

It is still happening... still on the hour schedule... even after updates and reboots as a result.

1 Like
4

Ah yes, sorry I was reading this on my phone and missed that.

Weird...

5

I figured. I just bookmark longer posts to read when I get home... since my phone never seems to do them justice.

Yeah, I am stumped on it, which is why I had to ask. I just cannot understand where they are coming from. I also turned the device's Logging (a Preference I have had for basically as long as I have written drivers) to Info... so nothing Debug or Trace should show up (only Info and Error)... but it is STILL happening.

I use the logging for a lot, especially on my drivers I am actively working on, so I can see if new data points are being returned (unhandled data is always flagged as a Debug for me) amongst other things... so having unknown entries in the logs? Not good.

1 Like
6

Can you PM me the hub id this happens on?
It doesn't ring any bells, but maybe engineering logs will have a clue.

1 Like
7

It appears to come from a websocket interface. "Timeout" is the exception message, so it doesn't appear in the code directly. You should also see a corresponding call to webSocketStatus method with "timeout" parameter.

I'll get rid of that debug logging bit, it doesn't add any value.

1 Like
8

I will check for the timeout in the webSocketStatus response... although my logging there only triggered if I was in Trace mode so I just changed the code (temporarily, otherwise the Trace logging for everything else the device is doing will get a git much). It will be interesting to see it come in plus I am surprised that my guess about it being webSocket related was correct!

At least I know I am not going crazy and it was not part of my code I was somehow blind to. Thanks for checking!

1 Like
9

Well... did not see the timeout in the webSocketStatus. The very first couple lines of it are:

def webSocketStatus( String Response ){
    Logging( "WebSocket Status = ${ Response }", 2 )

That logging function made other entries show in the log:

[dev:310]2024-02-16 06:42:03.531 AM[info]UDMP Protect - WebSocket Status = status: open
[dev:310]2024-02-16 06:41:55.838 AM[info]UDMP Protect - WebSocket Status = status: closing
[dev:310]2024-02-16 06:41:55.296 AM[info]UDMP Protect - WebSocket Status = status: open

But no timeout at the usual x:55. I checked the past logs and there was one at 5:55... so why one did not happen right now while I am watching for it... I will check the logs again when I am done with work.