Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mode changes no longer working #68

Open
rccoleman opened this issue Jun 1, 2019 · 36 comments

Comments

@rccoleman
Copy link
Contributor

commented Jun 1, 2019

I know that a recent change was made to the API used to change modes and I wonder if it's affecting me as well. In my case, I have 5 Arlo Pro (wireless, proprietary rechargeable cube battery) with a hub.

If I try to change the mode like this, it doesn't take effect:

  arlo_away:
    sequence:
      - service: alarm_control_panel.alarm_arm_away
        entity_id: alarm_control_panel.aarlo_arlo_base

These are the logs:

2019-06-01 07:31:53 INFO (MainThread) [homeassistant.helpers.script] Script arlo_away: Running script
2019-06-01 07:31:53 INFO (MainThread) [homeassistant.helpers.script] Script arlo_away: Executing step call service
2019-06-01 07:31:53 DEBUG (SyncWorker_6) [pyaarlo] set:4R03767JA2801/activeSchedule=None
2019-06-01 07:31:53 DEBUG (SyncWorker_6) [pyaarlo] Arlo Base:new-mode=armed,id=mode1
2019-06-01 07:31:53 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/automation/active

The cameras all work in Home Assistant, as do the motion sensors. I can change the mode in the Arlo iOS app with no problems.

Here's my "home" program (mode == 'doors') and the result:

  arlo_home:
    sequence:
      - service: alarm_control_panel.alarm_arm_home
        entity_id: alarm_control_panel.aarlo_arlo_base
2019-06-01 07:39:35 INFO (MainThread) [homeassistant.helpers.script] Script arlo_home: Running script
2019-06-01 07:39:35 INFO (MainThread) [homeassistant.helpers.script] Script arlo_home: Executing step call service
2019-06-01 07:39:35 DEBUG (SyncWorker_18) [pyaarlo] set:4R03767JA2801/activeSchedule=None
2019-06-01 07:39:35 DEBUG (SyncWorker_18) [pyaarlo] Arlo Base:new-mode=doors,id=mode3
2019-06-01 07:39:35 DEBUG (ArloBackgroundWorker) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/automation/active

Here's where I think the modes are discovered at startup:

2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] mode0<=M=>disarmed
2019-05-31 22:56:32 DEBUG (MainThread) [pyaarlo] starting request=https://arlo.netgear.com/hmsweb/users/devices/startStream
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIdToName/mode0=disarmed
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeNameToId/disarmed=mode0
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIsSchedule/disarmed=False
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] mode1<=M=>armed
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIdToName/mode1=armed
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeNameToId/armed=mode1
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIsSchedule/armed=False
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] mode3<=M=>doors
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIdToName/mode3=doors
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeNameToId/doors=mode3
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIsSchedule/doors=False
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] schedule.1<=S=>schedule.1
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIdToName/schedule.1=schedule.1
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeNameToId/schedule.1=schedule.1
2019-05-31 22:56:32 DEBUG (ArloBackgroundWorker) [pyaarlo] set:4R03767JA2801/modeIsSchedule/schedule.1=True

Any idea what's going on? I'm using the latest 0.0.11 release. Mode changing used to work reliably, but I've had to manually change modes often with the recent releases.

@rafuz

This comment has been minimized.

Copy link

commented Jun 2, 2019

I am affected by the same problem.
Mode change has gone unreliable starting from yesterday. I am using latest 0.0.11 too.
This night has not changed modes, I have restarted HASS this morning and now is changing modes again.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jun 3, 2019

I've had the same thing happen to me after a couple of days running. It might be to do with the v2 api. I've restarted my device with some extra debug so I'm hoping to track it down but, 48 hours later, it's running file. In the mean time I've created a branch where I'm hoping to track down the issues; it includes extra debug and the ability to force the API version - https://github.com/twrecked/hass-aarlo/tree/mode-api

You set the API version with:

aarlo:
  mode_api: v1

--or--
aarlo:
  mode_api: v2

--or--
aarlo:
  mode_api: auto
@rccoleman

This comment has been minimized.

Copy link
Contributor Author

commented Jun 3, 2019

Thanks, Steve. It worked fine for me today. I'll pull down the branch tonight in case it happens again.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jun 3, 2019

@rccoleman There is something odd happening. I had it stop on me but I'd been running for a week. The branch includes extra debug before and after the request has been sent so I'm hoping that helps.

Also, it will show your password on startup so be careful uploading debug traces.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jun 13, 2019

I might have found the issue here.

I was trying some different ideas and found if I has the event log out and back in I would lose the ability the set the modes but everything else seemed to work. I then found if I had the stream log out and back in and then request a list of devices everything worked again.

I've modified the mode-api branch to periodically ask for the devices and see if that helps with the issue.

@twrecked twrecked self-assigned this Jun 13, 2019
@rccoleman

This comment has been minimized.

Copy link
Contributor Author

commented Jun 13, 2019

That would great news! It works on and off for me and I haven't been able to find any common thread. I'll grab the mode-api branch (for real this time) and see if it helps.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jun 13, 2019

If this doesn't work I might have a plan to periodically log off and back on.

@Tiippex

This comment has been minimized.

Copy link

commented Jun 16, 2019

Hi,
this might be the wrong place to ask for support (where is the correct place to ask questions? I guess not the issues D;) but my question is related to the modes.

Is it possible to change the mode to the geofencing mode?

Regards

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jun 16, 2019

I don't believe we can change to geofencing from the Aaro module. Basically, if we can do it from the web interface we can do it from the Aarlo module and geofencing can only be enabled from the mobile app.

And this thread https://community.home-assistant.io/t/arlo-replacement-pyarlo-module/93511 has quite a bit of useful info but I'll answer questions anywhere!

@rccoleman

This comment has been minimized.

Copy link
Contributor Author

commented Jun 16, 2019

I pulled the mode-api branch a few days ago and mode changes were working fine until this morning when they stopped working. Unfortunately, I had optimistically turned off anything beyond "info" for aarlo/pyarlo and there wasn't anything useful in the logs. I turned debug back on, restarted HA, and mode changes started working again. It looks like I'm missing the merge from June 14th, so I just pulled the new changes and I'll keep an eye on it.

@Tiippex

This comment has been minimized.

Copy link

commented Jun 29, 2019

So what worked for me is to activate the geofencing mode in the app. When I swapped the mode via home assistant the mode swapped to "geofencing deactivated/activated" so that worked for me.
Saidly, geofencing from arlo doesn't work that good. So I created a switch which is supposed to be triggered automatically when nobody is at home:

switch:
  - platform: template
    switches:
      homeempty:
         friendly_name: "Niemand zuhause" 
         value_template: "{{ is_state(alarm_control_panel.aarlo_get_mode', 'armed') }}"
         turn_on:
           service: alarm_control_panel.aarlo_set_mode
           data:
             entity_id: alarm_control_panel.aarlo_arlo_whz
             mode: armed
         turn_off:
           service: alarm_control_panel.aarlo_set_mode
           data:
             entity_id: alarm_control_panel.aarlo_arlo_whz
             mode: disarmed

That used to work but doesn't work anymore since I updated to home assistant 0.95.*

value_template: "{{ is_state(alarm_control_panel.aarlo_set_mode', 'armed') }}"

is there a better way to get the state of the current mode?

@joch

This comment has been minimized.

Copy link

commented Jun 30, 2019

I was affected by mode changes stopped working as well. I’m using a separate Arlo user for home assistant which has access to all devices using the grant access feature. Noticed this in the log:

2019-06-30 08:14:07 WARNING (ArloBackgroundWorker) [pyaarlo] error in response={'data': {'error': 'AUTO-5010', 'message': "Device doesn't belong to the User", 'reason': "REDACTED doesn't belong to the User / Is not provisioned"}, 'success': False}

The redacted ID points to the main Arlo hub, which is not shareable using grant access.

When changing to my main user though, mode changes started working again as expected.

Edit: Tested the mode-api branch and setting v1 makes it work with the invited user.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jul 2, 2019

You could also try the refresh_devices_every option in the master branch. I think this problem happens after AARLO has been logged in for a while. I'm also trying a version of the code that logs out and back in.

@Tiippex

This comment has been minimized.

Copy link

commented Jul 9, 2019

Tried that for the last few days with 12 and 6 hours. That didn’t work.
So I swapped to 2 hours now.

Can you commit the login and logout thingy in a different branch please? Would like to test that.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jul 24, 2019

I haven't forgotten about this - vacation and real work has been getting in the way...

I'll revisit the logout/login code this week. The previous version was a little messy and I want to tidy it up, I'll send a link when it's ready.

I'm also wondering if catching the is not provisioned error and retrying the last command might not be a good solution too. But that involves tracking sending state and is more work.

@twrecked

This comment has been minimized.

Copy link
Owner

commented Jul 26, 2019

Can you try this branch: https://github.com/twrecked/hass-aarlo/tree/reconnect

You will need to add reconnect_every to your config and set it to the number of minutes between logoff/login cycles. The example below is very 70 minutes.

aarlo:
  username: !secret arlo_username
  password: !secret arlo_password
  reconnect_every: 70

There is still work to do on this branch - I'm going to introduce a state - but this will let us know if the logoff/login will fix the issue.

edit: Fair warning, this is based off a development branch that has a few other changes included...

@gcorgnet

This comment has been minimized.

Copy link

commented Aug 5, 2019

Hi, any way to test out a branch in hass.io via HACS?

@twrecked

This comment has been minimized.

Copy link
Owner

commented Aug 6, 2019

@gcorgnet Can I ask which version you upgraded from? Same question to everyone really... (I had an idea, my original thought was that I broke the mode API but now I'm wondering if I didn't fix the event stream API and found an issue with the back end. )

I've created a test version - v0.0.7-reconnect - to expose the reconnect branch to HACS, let me know if you can see it.

@rccoleman

This comment has been minimized.

Copy link
Contributor Author

commented Aug 6, 2019

I can see it once I enable beta from the hamburger menu on the right. I was coming from 0.5.5 and mode switching failed from time to time.

@gcorgnet

This comment has been minimized.

Copy link

commented Aug 6, 2019

@gcorgnet Can I ask which version you upgraded from? Same question to everyone really... (I had an idea, my original thought was that I broke the mode API but now I'm wondering if I didn't fix the event stream API and found an issue with the back end. )

I've created a test version - v0.0.7-reconnect - to expose the reconnect branch to HACS, let me know if you can see it.

Hard to say from memory. Will check once at home in case I still have the files on disk. It was pre HACS, that's all I know.

@gcorgnet

This comment has been minimized.

Copy link

commented Aug 6, 2019

I tried v0.0.7 via hassio/hacs and not much luck. About 1-2h later, I could not chanhe the mode. I had set the reconnect_every to 70min.
Should I try a lower value? What's the impact?

@twrecked

This comment has been minimized.

Copy link
Owner

commented Aug 6, 2019

It just logs out and back in, there shouldn't be any impact.

Can you turn on debugging? I'd love to see the messages when the mode changes fails. This change to the logger section of configuration.yaml is usually enough:

logger:
    default: info
    logs:
        pyaarlo: debug

We're looking for a message with something like this in it: 'message': "Device doesn't belong to the User", 'reason': "REDACTED doesn't belong to the User / Is not provisioned"}.

edit: I've just moved my main system to 0.0.7 so I'll keep track of that too.

@ynazar1

This comment has been minimized.

Copy link

commented Aug 6, 2019

Confirming seeing same thing. Happens after few days of hass uptime for me. Sorry no debug enabled. Running the e6bc68c branch. Unclear if its still trying but failing or not even trying. Running virtualenv python 3.6.6 on jessie raspberry 3. I'm not running the card, just the alarm_panel sensor.

2019-08-02 08:08:45 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for alarm_control_panel.aarlo (<class 'custom_components.aarlo.alarm_control_panel.ArloBaseStation'>) took 51.370 seconds. Please report platform to the developers at URL

Me Arriving home, automation kicking off:
2019-08-05 20:10:12 WARNING (ArloBackgroundWorker) [pyaarlo] error in response={'data': {'error': 'AUTO-5010', 'message': "Device doesn't belong to the User", 'reason': "<base_station> doesn't belong to the User / Is not provisioned"}, 'success': False}

Night automation kicking off:
2019-08-05 21:00:00 WARNING (ArloBackgroundWorker) [pyaarlo] error in response={'data': {'error': 'AUTO-5010', 'message': "Device doesn't belong to the User", 'reason': "<base_station> doesn't belong to the User / Is not provisioned"}, 'success': False}

Digging around some more:
pi@scorpi:~ $ host arlo.netgear.com
arlo.netgear.com is an alias for arlo.vz.netgear.com.
arlo.vz.netgear.com is an alias for ArloProdLB-1815857678.eu-west-1.elb.amazonaws.com.
ArloProdLB-1815857678.eu-west-1.elb.amazonaws.com has address 34.252.53.228
ArloProdLB-1815857678.eu-west-1.elb.amazonaws.com has address 108.128.37.233

I also see that i have an established connection to one of the IPs:
tcp 0 0 <home_IP>:41010 34.252.53.228:443 ESTABLISHED 632/python3.6

I tend to have some vague recollections that python tends to be VERY lazy about closing or recycling connection/sockets.

Update: Logging in through webUI with Hass running. Generated lots more of "not provisioned" errors as well as somewhat expected message before kicking me out of the browser.

2019-08-06 13:32:22 WARNING (EventStream) [pyaarlo] logged out? did you log in from elsewhere?

Another Edit: After logging in via WebUI. It took an hour for me to be kicked out by the system, so someone should try the reconnect_every: {<60 minutes} option :)

Edit 8/12: Still working after 6 days of uptime and no changes since last time. I'm beginning to wonder if its something that happens on arlo side that trips it up.

Update 8/15: Finally broke, but because I'm baddie no debug. But interesting log error right before it happened this time, the hacs error is the first time it occurred in the logs.
2019-08-15 08:50:46 WARNING (MainThread) [custom_components.hacs.template] Error rendering info template expected token 'end of statement block', got 'version_installed'
2019-08-15 09:00:00 WARNING (ArloBackgroundWorker) [pyaarlo] error in response={'data': {'error': 'AUTO-5010', 'message': "Device doesn't belong to the User", 'reason': "[device id] doesn't belong to the User / Is not provisioned"}, 'success': False}

@ynazar1

This comment has been minimized.

Copy link

commented Aug 23, 2019

Update: Still happening on and off after few days of uptime. Switched to 0.0.7-test4 branch. Enabled debug. reconnect_every: 55
Please stand by for (eventual) debug once it crashes. (Probably early next week).

@ynazar1

This comment has been minimized.

Copy link

commented Aug 28, 2019

Whelp, apparently it failed nice and well on 8-25 at 9:00:00 pm but then reconnect got it working again. Debug below. Relevant breakage at 21:00:00 when it attempts to arm arlo. I'm now wondering its the primary user vs secondary user that's authorized to control.

2019-08-25 20:53:05 DEBUG (ArloBackgroundWorker) [pyaarlo] no device reload
2019-08-25 20:53:05 DEBUG (ArloBackgroundWorker) [pyaarlo] deduced v2 api
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode0<=M=>disarmed
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode0=disarmed
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/disarmed=mode0
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/disarmed=False
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode1<=M=>armed
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode1=armed
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/armed=mode1
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/armed=False
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] schedule.1<=S=>schedule.1
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/schedule.1=schedule.1
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/schedule.1=schedule.1
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/schedule.1=True
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:53:06 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:53:07 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] sending cameras to CAMERA_1_ID
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] Back Camera CAMERA got one cameras
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] Back Camera got cameras
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] base info
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/activityState=idle
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/audioDetected=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/batteryLevel=100
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/batteryTech=Rechargeable
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/brightness=0
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/connectionState=available
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/chargerTech=None
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/chargingState=Off
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/flip=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/mirror=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionDetected=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionSetupModeEnabled=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionSetupModeSensitivity=80
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/powerSaveMode=2
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/privacyActive=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/signalStrength=3
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] sending cameras to CAMERA_2_ID
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] Front camera CAMERA got one cameras
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] Front camera got cameras
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] base info
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/activityState=idle
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/audioDetected=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/batteryLevel=100
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/batteryTech=Rechargeable
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/brightness=0
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/connectionState=available
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/chargerTech=None
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/chargingState=Off
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/flip=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/mirror=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionDetected=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionSetupModeEnabled=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionSetupModeSensitivity=80
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/powerSaveMode=2
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/privacyActive=False
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/signalStrength=3
2019-08-25 20:53:07 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:54:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:54:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:54:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:54:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:55:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:55:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:55:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:55:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:56:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:56:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:56:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:56:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:57:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:57:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:57:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:57:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:58:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:58:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:58:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:58:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 20:59:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 20:59:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 20:59:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 20:59:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:00:00 DEBUG (MainThread) [pyaarlo] set:BASE_ID_HERE/activeSchedule=None
2019-08-25 21:00:00 DEBUG (MainThread) [pyaarlo] home Arlo:new-mode=armed,id=mode1
2019-08-25 21:00:00 DEBUG (MainThread) [pyaarlo] deduced v2 api
2019-08-25 21:00:00 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:00:00 WARNING (ArloBackgroundWorker) [pyaarlo] error in response={'data': {'error': 'AUTO-5010', 'message': "Device doesn't belong to the User", 'reason': "BASE_ID_HERE doesn't belong to the User / Is not provisioned"}, 'success': False}
2019-08-25 21:00:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:00:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:00:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:00:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:01:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:01:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:01:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:01:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:02:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:02:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:02:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:02:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:03:05 DEBUG (ArloBackgroundWorker) [pyaarlo] slow refresh
2019-08-25 21:03:05 DEBUG (ArloBackgroundWorker) [pyaarlo] no device reload
2019-08-25 21:03:05 DEBUG (ArloBackgroundWorker) [pyaarlo] deduced v2 api
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode0<=M=>disarmed
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode0=disarmed
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/disarmed=mode0
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/disarmed=False
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode1<=M=>armed
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode1=armed
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/armed=mode1
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/armed=False
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] schedule.1<=S=>schedule.1
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/schedule.1=schedule.1
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/schedule.1=schedule.1
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/schedule.1=True
2019-08-25 21:03:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:03:07 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:03:07 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:03:07 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:03:07 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] sending cameras to CAMERA_1_ID
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] Back Camera CAMERA got one cameras
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] Back Camera got cameras
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] base info
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/activityState=idle
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/audioDetected=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/batteryLevel=100
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/batteryTech=Rechargeable
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/brightness=0
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/connectionState=available
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/chargerTech=None
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/chargingState=Off
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/flip=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/mirror=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionDetected=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionSetupModeEnabled=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/motionSetupModeSensitivity=80
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/powerSaveMode=2
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/privacyActive=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_1_ID/signalStrength=3
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] sending cameras to CAMERA_2_ID
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] Front camera CAMERA got one cameras
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] Front camera got cameras
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] base info
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/activityState=idle
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/audioDetected=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/batteryLevel=100
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/batteryTech=Rechargeable
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/brightness=0
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/connectionState=available
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/chargerTech=None
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/chargingState=Off
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/flip=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/mirror=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionDetected=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionSetupModeEnabled=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/motionSetupModeSensitivity=80
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/powerSaveMode=2
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/privacyActive=False
2019-08-25 21:03:07 DEBUG (ArloEventStream) [pyaarlo] set:CAMERA_2_ID/signalStrength=3
2019-08-25 21:03:08 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:04:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:04:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:04:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:04:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:05:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:05:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:05:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:05:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:06:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:06:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:06:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:06:47 DEBUG (ArloEventStream) [pyaarlo] error2=
2019-08-25 21:07:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:07:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:07:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:07:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:08:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:08:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:08:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:08:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:09:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:09:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:09:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:09:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:10:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:10:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:10:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:10:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:11:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:11:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:11:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:11:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:12:05 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:12:05 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
2019-08-25 21:12:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:12:06 DEBUG (ArloEventStream) [pyaarlo] async ping response subscriptions/JF3RVBGD-140-51023887_web
2019-08-25 21:13:05 DEBUG (ArloBackgroundWorker) [pyaarlo] slow refresh
2019-08-25 21:13:05 DEBUG (ArloBackgroundWorker) [pyaarlo] no device reload
2019-08-25 21:13:05 DEBUG (ArloBackgroundWorker) [pyaarlo] deduced v2 api
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode0<=M=>disarmed
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode0=disarmed
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/disarmed=mode0
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/disarmed=False
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] mode1<=M=>armed
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/mode1=armed
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/armed=mode1
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/armed=False
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] schedule.1<=S=>schedule.1
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIdToName/schedule.1=schedule.1
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeNameToId/schedule.1=schedule.1
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] set:BASE_ID_HERE/modeIsSchedule/schedule.1=True
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] finish request=200
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] fast refresh
2019-08-25 21:13:06 DEBUG (ArloBackgroundWorker) [pyaarlo] day testing with 2019-08-25!
@twrecked

This comment has been minimized.

Copy link
Owner

commented Aug 29, 2019

My feeling is it's something Arlo is doing, and I wondering if it was a primary v secondary user issue to. I just have to work out a way of getting the connection back.

I've been playing around with my main system a little too much recently - upgrades and other Arlo bugs but I'm going to let it run now and concentrate on this issue.

You can also try this in your aarlo config, see if it helps:

refresh_devices_every: 1
@ynazar1

This comment has been minimized.

Copy link

commented Aug 29, 2019

'Will do' on the config.

Considering that the reconnect functionality seems to have it working again without restart (by the time of next automation kickoff at 9 am), would trying to do a full logout/login loop on catching the error be a reasonable compromise? Or would it be possible to delay and try again in like 60 seconds, not too sure if that's feasible with hass though.
That being said, it may have been a lucky accident on it continuing to work so who knows, further testing needed.

@Tiippex

This comment has been minimized.

Copy link

commented Sep 3, 2019

Looks good for me now. But I have to mention that I restarted HA quite often the last time. Will watch it a few more days!

@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 7, 2019

I played around a bit with this. Not done yet, but wanted to share progress so far in case it helps move things along. I've created a small test example to make the error more reproducible (for me at least). It seems to me that when pyaarlo does a re-login, the functionality to arm/disarm breaks with the error XXX doesn't belong to the User / Is not provisioned. I was only able to reproduce this when using an account which is not the owner of the base. The fix seems to be to simply _refresh_devices directly after logging in. I'm wildly guessing some part of the Arlo access control in their backend for guest devices is only initialized when requesting a list of all devices, and as the official client always does this on login, things work for them.

To make this more convenient to test, one needs to fix all the imports in pyarlo to relative imports, e.g., from custom_components.aarlo.pyaarlo.background import ArloBackground -> from .background import ArloBackground.

The script below should trigger the issue. As-is, this should arm your hub, and then get the error message (along with a lot of other debug info in the file foo.log). If you uncomment the lines to refresh devices, it should manage to arm and then disarm. The wait times are completely arbitrary, just something long enough to hopefully let all initialization et.c. happen between calls.

import logging
logging.basicConfig(level=logging.DEBUG,filename='foo.log')
import pyaarlo
import time

a = pyaarlo.PyArlo(USERNAME, PASSWORD, storage_dir='./storage')
time.sleep(30)
print('Arming')
a.base_stations[0].mode = 'armed'
time.sleep(30)
print('Forcing reconnect')
a._be.login(a._be.username, a._be.password) # The quickest and dirtiest way I could think of to trigger a re-login. This will log you in again, which will cause the SSE reader to notice a new login on the account, triggering a re-login. Can be replaced with logging in on another device if you wanna try timing. ;)
time.sleep(30)
#print('Refreshing devices')
#a._refresh_devices()
#time.sleep(20)
print('Disarming')
a.base_stations[0].mode = 'disarmed'
time.sleep(30)
gkreitz added a commit to gkreitz/hass-aarlo that referenced this issue Sep 7, 2019
@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 7, 2019

Another way to reproduce: Simply log in on the arlo website with the account you're using with home assistant. This will disconnect your hass instance and cause it to re-login, which makes it lose the ability to arm/disarm. With above PR, the bug no longer seems to trigger in that scenario.

As you may guess from the timing of messages, this has not been extensively tested yet. Running my main installation with this now, to see if this was enough to keep arming/disarming working well.

twrecked added a commit that referenced this issue Sep 9, 2019
#68 Minimal patch to make arming/disarming more stable by re-fetching device list when logging in
@twrecked

This comment has been minimized.

Copy link
Owner

commented Sep 9, 2019

Thanks @gkreitz, I checked in your pull request. Wonder if it would be worth while doing that before sending the set command?

If you look in the test branch you'll see I fixed all the imports in there! I also tidied up a bunch of issues found by PyCharm. I'm just chasing down one issue which I think is to do with me removing the import six directive before I start to merge that one back.

@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 11, 2019

Cool! I'm hoping its sufficient to do on login, but if that starts acting up too, I think what you propose with doing it before every set command makes a lot of sense. (I guess even cleaner would be to keep a bit of state on set commands, waiting for them to be ack:d by the server, but that feels messy as one would have to do it via timeouts). Annoying with bugs like these that take a week to manifest...

Nice that the imports had already changed in a branch! Easier that way when one needs to do something standalone.

gkreitz added a commit to gkreitz/hass-aarlo that referenced this issue Sep 13, 2019
@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 13, 2019

The fix with just re-fetching the device list on login is apparently not sufficient. :( My installation had the bug trigger again. I did a new patch in my repo (backing out the old patch, and instead fetching device list when a v2 mode change fails). Letting it run for a bit at home to see if this improves stability before doing a PR.

@ynazar1

This comment has been minimized.

Copy link

commented Sep 16, 2019

Very interesting update. It seems like it failed a day or two ago, but there's no correlating error log that I can determine (but its also 127k lines of log is there) and while the debug messages look fine-ish even now, the actual mode doesn't change. There is no weirdness in the log for last 5 days and I'm pretty sure it failed in the last 48 hours or so. Saved the log if someone willing to suggest what to look for in there...

@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 17, 2019

I've had my new patch running 4 days at home now. Looking at the logs, I can see that the problem we're chasing occurred 2 days ago, my old PR would not have fixed it but my new PR did. So, submitted a PR as this seems to at least be a step in the right direction stability-wise.

@gkreitz

This comment has been minimized.

Copy link
Contributor

commented Sep 17, 2019

@ynazar1 What I've done when debugging is to do:

grep arlo home-assistant.log > arlo.log

egrep -v "\[pyaarlo\] (set:|queing image update|parent is|fast refresh|day testing with|sending cameras to|.* CAMERA|.* got cameras|base info|finish request=200|starting request=\{\}|slow refresh|no device reload|async ping response|starting request=\{.*xcloudId.*\}|mode0<=M=>disarmed|mode1<=M=>armed|schedule.1<=S=>Arm)|starting request=\{.*action.*set.*resource.*subscriptions/.*_web|starting request=https://arlo.netgear.com/hmsweb/users/devices/notify/|starting request=https://arlo.netgear.com/hmsweb/users/automation/definitions|starting request=.*get.*cameras|starting request=.*get.*doorbells|deduced v2 api|adding" arlo.log | less

That monster of a regexp should filter out most of the noisy lines, and hopefully still work, or be easy to fix (I cleared it up a bit before posting here, as I had hardcoded some camera names et.c. :). If you're running an old version, you'll most likely see a login event (starting request=https://arlo.netgear.com/hmsweb/login/v2) between the last time arming/disarming works, and the first time it doesn't. If you're running a new version, I don't know of anything in the log that shows when it breaks.

Failed requests (if they are of the sort I've been seeing and debugging) can be easily spotted with a search for AUTO-5010 or Device doesn't belong to the User

twrecked added a commit that referenced this issue Sep 24, 2019
#68 Re-fetch device list when arm/disarm fails to hopefully make it stable
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
8 participants
You can’t perform that action at this time.