search

twrecked / hass-aarlo

Asynchronous Arlo Component for Home Assistant
GNU Lesser General Public License v3.0
394 stars 78 forks source link

Lots of "Client exceeded max pending messages [2]: 512" #61

Closed rccoleman closed 5 years ago

rccoleman commented 5 years ago

I've been getting frequent bursts of messages like this, and it looks like they may be related to aarlo:

2019-05-18 14:42:00 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Client exceeded max pending messages [2]: 512

and followed shortly thereafter by this:

2019-05-18 14:55:07 INFO (MainThread) [homeassistant.components.websocket_api.http.connection.140146016004304] Connection closed by client
2019-05-18 14:55:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport
Traceback (most recent call last):
  File "uvloop/sslproto.pyx", line 574, in uvloop.loop.SSLProtocol._do_shutdown
  File "/usr/local/lib/python3.7/ssl.py", line 767, in unwrap
    return self._sslobj.shutdown()
ssl.SSLError: [SSL: KRB5_S_INIT] application data after close notify (_ssl.c:2609)

There's no useful debug when I just use the default "info" logger level, but when I turn on debug for homeassistant.components.websocket_api:, I get lots of this before the above error:

2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_living_room', 'id': 1758}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_family_room', 'id': 1759}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_front_door', 'id': 1760}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_back_door', 'id': 1761}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_dining_room', 'id': 1762}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_living_room', 'id': 1763}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_family_room', 'id': 1764}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_front_door', 'id': 1765}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_back_door', 'id': 1766}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_dining_room', 'id': 1767}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_living_room', 'id': 1768}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_family_room', 'id': 1769}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_front_door', 'id': 1770}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_back_door', 'id': 1771}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_dining_room', 'id': 1772}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_living_room', 'id': 1773}
2019-05-18 14:42:00 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Received {'type': 'camera_thumbnail', 'entity_id': 'camera.aarlo_family_room', 'id': 1774}
2019-05-18 14:42:00 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139799196644688] Client exceeded max pending messages [2]: 512

That goes on for quite a while. My cameras aren't reporting motion while this is happening, and I'm not currently viewing the cameras in Lovelace. If I don't have debug turned on for homeassistant.components.websocket_api:, I just periodically get a flood of "exceeded max pending messages" lines.

I just turned on debug for aarlo using custom_components.aarlo: debug and I see log messages during boot, but nothing around the "exceeded max pending messages" logs (which still show up periodically).

twrecked commented 5 years ago

A quick search for 'python client exceeded max pending' shows a lot of hits for previous versions of home-assistant - so I'm not sure this is me, it looks like a UI issue, But, you never know, so...

When you say 'motion isn't responding' do you mean on the GUI or messages from Arlo? If you can turn debug on and you see motion events coming in then it's after my component. Also, can you turn pyaarlo debug on as well, that will show us more low level stuff:

logger:
    default: info
    logs:
        pyaarlo: debug

Thanks!

rccoleman commented 5 years ago

I already turned debug on in your component earlier and there were no messages from it around the ‘exceeded’ messages, but I haven’t tried pyarlo yet. It was really the large number of websocket messages related to aarlo immediately before and nowhere else that pointed me in this direction. @awarecan recommended this debug approach in one of the hits in the forum.

When I mentioned that there was no motion detected around the errors, I mean that the Arlo app isn’t triggering on motion and recording when I see these errors. Two cameras were armed and three others were not, but none were reporting any motion. Do you know what would cause all of that camera_thumbnail traffic?

twrecked commented 5 years ago

Sorry, I missed that, I forgot scroll left...

The aarlo-glance card will ask for a camera thumbnail when the configuration changes. And it will ask for a couple of thumbnails when a snapshot request has happened. But that's done on a per camera basis so I don't know why you'd get a bunch of cameras coming in at the same time. Anyway, you said you weren't viewing in Lovelace. Do you use NodeRed or AppDaemon?

The pyaarlo debug might give us a clue. It will list all incoming events and I might be able to tie one of those to the 'camera_thumbnail' message. Maybe something is locked up in the pyaarlo code.

rccoleman commented 5 years ago

I don’t use Node Red, but I do use AppDaemon and I use motion events from the front and back door cameras as triggers. They would both record on a trigger and they didn’t (no recorded clips at all today), so I don’t think they saw anything. I’ll turn on debug for pyarlo and see what I get.

rccoleman commented 5 years ago

That traffic just seems to happen without any provocation. I have both aarlo and pyarlo debug enabled and neither says anything before the burst of websocket activity. I have websocket debug turned off in this build, but it just looks like what I posted above with rapid-fire request for thumbnails from all cameras over and over.

I get the first three lines every minute or so and I don't think they're related to the burst of websocket activity.


2019-05-18 19:42:29 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-05-18 19:42:29 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/4R03767JA2801
2019-05-18 19:42:30 DEBUG (EventStream) [pyaarlo] async ping response subscriptions/DAAS-100-48473165_web

2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512
2019-05-18 19:42:39 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139742140092200] Client exceeded max pending messages [2]: 512```
twrecked commented 5 years ago

I've turned on the same debug as you and I'll take a look into this. The 'async ping responses' are keep alive packets, we have to send them every so often or Arlo closes the event stream.

twrecked commented 5 years ago

Do you have any Tracebacks in your log? I'm seeing the Received message but I'm also seeing a Sending response immediately after. And a Sending response with a lot of data in it.

rccoleman commented 5 years ago

Only the one in the initial comment here, and it doesn’t happen consistently. I can’t even tell if it’s related to the other messages, but it does seem to happen often enough shortly after the ‘exceeded’ messages that I’m suspicious.

I tried to re-capture the failure with websocket debug turned on for a while last night and couldn’t, but it happened as soon as I turned websocket debug off. It’s not hard for me to reproduce, but maybe gets harder with more debug.

twrecked commented 5 years ago

Still trying to track this one down...

What version of home-assistant and Aarlo are you using?

You say you aren't viewing any images in Lovelace but could you have had a browser tab open or a connection from a phone/tablet? The only way I see the web_socket messages is to open a web browser. I can still the web_socket messages happening if I log in from my Android device and leave a tab in the background or even lock the main screen.

The other piece is the camera_thumbnail web_socket is provided by the main camera component and just asks my component for the latest image, it should be returning almost immediately. But, that information is cached so we can wipe the cache by stopping home-assistant, deleting the pickle file (.aarlo/aarlo.pickle) and restarting home-assistant.

rccoleman commented 5 years ago

I remoted into my desktop machine at work and I see that it was sitting on the Arlo tab and displaying my 5 Arlo camera images. Sorry about that! It still seems like it may get into a weird state when a page is left open monitoring the camera feeds that ends up flooding the websocket layer periodically. This would have been through the Nabu Casa Remote UI, if that matters.

I'm using aarlo 0.0.7, the one you just released.

twrecked commented 5 years ago

I've not used the Nabu Casa Remote UI but it shouldn't be causing the flooding. The aarlo-glance card is a little over zealous but it will only grab a snapshot if:

I could see it getting behind if there is a network connectivity issue. I'll try and make some time to investigate some more.

rccoleman commented 5 years ago

I’ll try to reproduce locally to take Remote UI out of the picture in the next few days. I’m not overly worried about it because I didn’t see any visible effects from it, only the logs showing HA’s displeasure. Could have been Nabu Casa, the network at work or other things that we have no control over.

And really sorry for the misinformation earlier - I hate sending you off on a wild goose chase.

rccoleman commented 5 years ago

Here's another log snippet where I'm sitting on a normal connection with a Lovelace page containing 5 cameras is showing. I'm not actually playing any of the video, just watching the static thumbnails. This was about a minute after a bootup and before my Z-Wave network was up, but it looks like it's after the normal pyaarlo initialization completed. I also noticed that my automations that change the mode didn't trigger today, but that could be something else entirely. 

2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] sending mediaUploadNotification to 4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room CAMERA got one mediaUploadNotification
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] set:4XH5767BA5EC6/mediaObjectCount=8
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] set:4XH5767BA5EC6/presignedLastImageUrl=https://arlolastimage-z2.s3.amazonaws.co
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room thumbnail changed
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] queing image update
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] turning recent ON for Living Room
2019-05-23 12:20:13 DEBUG (ArloBackgroundWorker) [pyaarlo] getting image for Living Room
2019-05-23 12:20:13 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Living Room:recentActivity:True
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767BA5EC6 to 4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room CAMERA got one cameras/4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room got cameras/4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] set:4XH5767BA5EC6/activityState=idle
2019-05-23 12:20:13 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Living Room:activityState:idle
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767BA5EC6 to 4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room CAMERA got one cameras/4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] Living Room got cameras/4XH5767BA5EC6
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:13 DEBUG (EventStream) [pyaarlo] set:4XH5767BA5EC6/activityState=idle
2019-05-23 12:20:13 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Living Room:activityState:idle
2019-05-23 12:20:14 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767BA5EC6/lastImageSource=capture/05-23 12:20
2019-05-23 12:20:14 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767BA5EC6/presignedLastImageData=b'\xff\xd8\xff\xfe\x00\x10Lavc58.35.100
2019-05-23 12:20:14 DEBUG (ArloBackgroundWorker) [custom_components.aarlo.camera] callback:Living Room:presignedLastImageData:b'\xff\xd8\xff\xfe\x00\x10Lavc58.35.100\x00\xff\xdb\x00C\x00\x08\x10\x10\x13\x10
2019-05-23 12:20:14 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767BA5EC6/activityState=idle
2019-05-23 12:20:14 DEBUG (ArloBackgroundWorker) [custom_components.aarlo.camera] callback:Living Room:activityState:idle
2019-05-23 12:20:14 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767BA5EC6 to 4XH5767BA5EC6
2019-05-23 12:20:14 DEBUG (EventStream) [pyaarlo] Living Room CAMERA got one cameras/4XH5767BA5EC6
2019-05-23 12:20:14 DEBUG (EventStream) [pyaarlo] Living Room got cameras/4XH5767BA5EC6
2019-05-23 12:20:14 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:14 DEBUG (EventStream) [pyaarlo] set:4XH5767BA5EC6/activityState=idle
2019-05-23 12:20:14 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Living Room:activityState:idle
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 INFO (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Connection closed by client
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140038993704552] Client exceeded max pending messages [2]: 512
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] sending mediaUploadNotification to 4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door CAMERA got one mediaUploadNotification
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] set:4XH5767SA3644/mediaObjectCount=146
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] set:4XH5767SA3644/presignedLastImageUrl=https://arlolastimage-z2.s3.amazonaws.co
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door thumbnail changed
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] queing image update
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] turning recent ON for Front Door
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [pyaarlo] getting image for Front Door
2019-05-23 12:20:18 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Front Door:recentActivity:True
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767SA3644 to 4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door CAMERA got one cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door got cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] set:4XH5767SA3644/activityState=idle
2019-05-23 12:20:18 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Front Door:activityState:idle
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767SA3644 to 4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door CAMERA got one cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door got cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] set:4XH5767SA3644/activityState=idle
2019-05-23 12:20:18 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Front Door:activityState:idle
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767SA3644/lastImageSource=capture/05-23 12:20
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767SA3644/presignedLastImageData=b'\xff\xd8\xff\xfe\x00\x10Lavc58.35.100
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [custom_components.aarlo.camera] callback:Front Door:presignedLastImageData:b'\xff\xd8\xff\xfe\x00\x10Lavc58.35.100\x00\xff\xdb\x00C\x00\x08\x12\x12\x15\x12
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4XH5767SA3644/activityState=idle
2019-05-23 12:20:18 DEBUG (ArloBackgroundWorker) [custom_components.aarlo.camera] callback:Front Door:activityState:idle
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] sending cameras/4XH5767SA3644 to 4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door CAMERA got one cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] Front Door got cameras/4XH5767SA3644
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] device info
2019-05-23 12:20:18 DEBUG (EventStream) [pyaarlo] set:4XH5767SA3644/activityState=idle
2019-05-23 12:20:18 DEBUG (EventStream) [custom_components.aarlo.camera] callback:Front Door:activityState:idle
2019-05-23 12:20:27 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-05-23 12:20:27 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/4R03767JA2801
2019-05-23 12:20:28 DEBUG (EventStream) [pyaarlo] async ping response subscriptions/DAAS-100-48473165_web
2019-05-23 12:21:27 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-05-23 12:21:27 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/4R03767JA2801
2019-05-23 12:21:28 DEBUG (EventStream) [pyaarlo] async ping response subscriptions/DAAS-100-48473165_web
2019-05-23 12:22:26 INFO (SyncWorker_0) [homeassistant.components.ecobee] Ecobee data updated successfully
2019-05-23 12:22:27 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-05-23 12:22:27 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/4R03767JA2801
2019-05-23 12:22:28 DEBUG (EventStream) [pyaarlo] async ping response subscriptions/DAAS-100-48473165_web
2019-05-23 12:23:27 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-05-23 12:23:27 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/4R03767JA2801
2019-05-23 12:23:29 DEBUG (EventStream) [pyaarlo] async ping response subscriptions/DAAS-100-48473165_web
twrecked commented 5 years ago

Do you have streaming enabled? It will do a pre-load which causes all the cameras to start recording for a few minutes. At the start of the recording and after the recording all the cameras do a snapshot update. I find it annoying but I can't figure out how to turn it off.

(Unrelated, and totally not stalking, but you have an Ecobee - I love mine, it helped me track down some wiring issues in my heating system and saved me a fortune!)

rccoleman commented 5 years ago

Do Arlo Pros (battery powered) support that? I can’t find it in my settings.

Yes, I love my Ecobees and will get them for any future house. I just had my furnaces replaced and they tried to get me to switch to some matching thermostat. No way! I will say that I see nothing appealing in their new versions. Ecobee 3 does everything I need.

twrecked commented 5 years ago

It's a feature of the streaming code, I guess it really helps if you are streaming from local cameras. You'll notice when you restart home-assistant all your cameras will stay streaming and stop a short time after. My philosophy is these sorts of things should be turned off unless asked for.

I believe you can change the settings from the original camera glance card but I've struggled to find it.

I installed my Ecobee and it turned out I had a short and my air-conditioner and heating were fighting each other in the summer. Most expensive death-match ever. I have a patch to fix the weather component - it maps Ecobee's conditions to the expected ones - I should try and get that checked in.

rccoleman commented 5 years ago

I've updated a few versions of aarlo since I first reported this and I don't see these errors in my log now. I'll keep an eye on it, but perhaps it's not happening any more.

twrecked commented 5 years ago

Closing for now. Feel free to reopen if it happens again...