DEADLINE_EXCEEDED on mqtt pkg 2.6.0

Toit

#DEADLINE_EXCEEDED on mqtt pkg 2.6.0

Thread channel in help

Rikke 01/16/2024 11:12 AM

I keep getting mqtt "DEADLINE_EXCEEDED" error on mqtt pkg 2.6.0, followed by a "out of memory" message, but I assume the OOM is caused by a new tls handshake. I checked the mqtt source, but I do not see any timeouts or deadline related to this.

If someone can point me in the right direction it would be nice.

I would like to understand this exception better.

OPRikke

I keep getting mqtt "DEADLINE_EXCEEDED" error on mqtt pkg 2.6.0, followed by a "out of memory" message, but I assume the OOM is caused by a new tls handshake. I checked the mqtt so...

floitsch 01/16/2024 12:54 PM

It's a bit weird, because the error message doesn't match up with the stack trace.

floitsch 01/16/2024 12:54 PM

The error message is set in the close --reason function.

floitsch 01/16/2024 12:55 PM

But we don't record where that happens...

floitsch 01/16/2024 12:56 PM

The throw in line 138 just rethrows the reason it got for closing down.

Rikke 01/16/2024 12:56 PM

Yes, thats why I am having problems figuring out where/why the "deadline" happens

floitsch 01/16/2024 12:56 PM

If you want to know who set the reason the easiest is to add a line in the close function:

close --reason=null:
  if is_closed: return
  if reason:
    catch --trace: throw "get trace"
  ...

floitsch 01/16/2024 12:57 PM

alternatively, you can go through the places where there is a call to close --reason= and add a --trace to the catch that is preceding it.

floitsch 01/16/2024 12:58 PM

Not 100% sure that would always work.

floitsch 01/16/2024 12:59 PM

To me it looks like there are only two places where this could happen: in the read and in the write function.

Rikke 01/16/2024 01:00 PM

I will add some --trace and see if i can reproduce it again

floitsch 01/16/2024 01:00 PM

I wonder if it's a default timeout from the TCP socket.

floitsch 01/16/2024 01:00 PM

Just asked Kasper and Erik if they know more.

Rikke 01/16/2024 01:01 PM

Thanks!

floitsch 01/16/2024 01:06 PM

Erik things there shouldn't be one.

Rikke 01/16/2024 01:09 PM

It happens when we have high mqtt activity, sending around 3-5 messages per second. And if I start OTA, which starts getting the image from a http client, I start to see this error. I will keep looking

bitphlipphar 01/16/2024 01:21 PM

There is a timeout on the TLS handshake.

bitphlipphar 01/16/2024 01:21 PM

(10s)

Rikke 01/16/2024 02:07 PM

And we are getting handshakes randomly, or only when we try to (re)connect?

floitsch 01/16/2024 02:07 PM

Only when connecting

Rikke 01/16/2024 02:07 PM

Okay its not the tls handshake then

Rikke 01/18/2024 07:33 AM

Cannot figure out why it happens, but it does seem related to high mqtt activity.

floitsch 01/18/2024 08:34 AM

The best is probably to add more debugging information to the mqtt package.

floitsch 01/18/2024 08:35 AM

You can just change it in the .packages directory. (It's read-only by default, but that's easy to change).
Just remember to revert eventually (removing the directory and doing a pkg install).

24 messages in total