Deciphering Log Errors

Hi All,

I’m relative new comer to running Hassio and have a few general questions for the seasoned vets out there.

The perfectionist in me wants a clean log file with no errors or warnings, but I’m assuming there are some that will appear that don’t indicate poor system health. For example, when I see a log entry like below, I understand the MyQ (garage doors) API failed on a poll and will try again. Since I see only one entry, I write it off as a one time network/service hiccup with no need to investigate.:

2020-02-17 00:38:00 WARNING (MainThread) [pymyq.api] Device update failed; trying again in 1 seconds

Question 1 - that seem fair or am I misreading that?

However, when I see an entry like below, I don’t know where to be begin in understanding where the issue is coming from - which integration, automation, etc. triggered the error?

2020-02-16 10:29:27 ERROR (MainThread) [homeassistant.components.webhook] Error processing webhook e6c4b1b6155f53a3a8847c05b485dc91d29ecbc56a2034c84c3f28138c43f875
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/webhook/__init__.py", line 77, in async_handle_webhook
    response = await webhook["handler"](hass, webhook_id, request)
  File "/usr/src/homeassistant/homeassistant/components/mobile_app/webhook.py", line 143, in handle_webhook
    req_data = await request.json()
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_request.py", line 583, in json
    body = await self.text()
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_request.py", line 577, in text
    bytes_body = await self.read()
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_request.py", line 561, in read
    chunk = await self._payload.readany()
  File "/usr/local/lib/python3.7/site-packages/aiohttp/streams.py", line 380, in readany
    await self._wait('readany')
  File "/usr/local/lib/python3.7/site-packages/aiohttp/streams.py", line 298, in _wait
    await waiter
concurrent.futures._base.CancelledError

Question 2 - when we see call stacks like below, is that something that should raise an eye for investigation or are these occasionally common and can be ignored if they are one-off?

WARNINGs are probably not a big deal, though they are sometimes useful. It just depends on how the developer thought the LOGGER for that message should be flagged. Some warnings are there so you can fix them. For example, that warning, sporadically isn’t a problem. But seeing it every 1 second would indicate what the problem is.

The second error is usually due to unhandled exceptions…but not always. It’s so hard to cover every single corner case, especially if they are rare. In this case, my guess would be the webhook sent a 2nd request before receiving the first request, cancelling the concurrent.futures. Something like this could happen if the internet down, or the remote server was down. Or, maybe home assistant restarted while it was waiting for the reply. Or, I could just be wrong about that exception.

But, it’s not fair to classify these as ‘poorly handled’. Normally, you want to handle the normal exceptions in a reasonable manner, but you don’t just want to blindly ignore all exceptions with a catchall as thing would then break silently.

However, when I see an entry like below, I don’t know where to be begin in understanding where the issue is coming from - which integration, automation, etc. triggered the error?

In that mess of text, you can follow the traceback. Bottom to top will show you the path the code took until it got to the error. Just look at the FILE (ignore the line and everything after for now).

python3.7/site-packages/aiohttp is the python component that raise the error. Following up, we see more and more from that same package until finally we see who it was from home assistant that called that particular library.

homeassistant/components/mobile_app/webhook.py

So in this case, it was the mobile_app component.

Best thing to do from here is to google. Sometimes you’ll find a fix, sometimes you’ll find a thread talking about it…sometimes nothing. If you find literally nothing about it, submit an issue including the full error. If nothing else, it would help future people googling it, and might actually uncover a problem that needs to be fixed.

In this case, the issue is still open.

@jocnnor - this was awesome information. Thank you very much for the detailed response!