KeyError: '(modes:59G1865E007ED|activeAutomations)' about pyaarlo

[twrecked]

That's good news.

I'll see if there is anything obvious why commands arriving closely will stop things working - although I do that all the time from my HA setup.

Also, I just pushed a change that stop asking for the mode every 10 minutes. It might help here.

[m0urs]

Just saw that this is not only with custom modes but also with built-in ones:

Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: 2020-10-28 14:57:21 - arlo-fhem - Received command: set-mode deaktiviert
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: Traceback (most recent call last):
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: File "/opt/fhem/arlo-fhem/arlo-fhem.py", line 158, in
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: base.mode = 'disarmed'
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: File "/opt/fhem/arlo-fhem/pyaarlo/base.py", line 239, in mode
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: _set_mode_v2_cb(1)
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: File "/opt/fhem/arlo-fhem/pyaarlo/base.py", line 221, in _set_mode_v2_cb
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: body = self._arlo.be.post(AUTOMATION_PATH, params=params, raw=True, tid=tid, wait_for=None)
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: File "/opt/fhem/arlo-fhem/pyaarlo/backend.py", line 646, in post
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: return self._wait_for_transaction(tid, timeout)
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: File "/opt/fhem/arlo-fhem/pyaarlo/backend.py", line 553, in _wait_for_transaction
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: while mnow < mend and self._requests[tid] is None:
Oct 28 14:57:21 raspberrypi02 arlo-fhem[4764]: KeyError: '(modes:4RD3837TA2965|activeAutomations)'
Oct 28 14:57:21 raspberrypi02 systemd[1]: arlo-fhem.service: Main process exited, code=exited, status=1/FAILURE

[twrecked]

This could be a race condition. Can you send me a snippet of the code calling this. And what settings are you using to start pyaarlo?

[m0urs]

I am running this script as a debian service and send commands to this service via a TCPIP socket:

https://github.com/m0urs/arlo-fhem/blob/issue_1_2/arlo-fhem.py

Let me know if you need more explanation.

Update: Corrected link to the current branch!

[twrecked]

There is nothing in the link you sent that looks odd. I'll definitely take a look at the mode change code though.

Do you see any "logged in from elsewhere" messages?

[m0urs]

Do you see any "logged in from elsewhere" messages?

No, I don't.

[m0urs]

Is there anything I can do to provide you with more information about that error? I do get it 1-2 times a day at the moment. Please let me know if and how I can help. Thanks.

[twrecked]

Sorry, I've been bogged down with real work, I'll give this a look.

Do you have any debug from before the crash? I'm looking for output that might contain something like starting transaction, finishing transaction and finished transaction.

[twrecked]

I just pulled #54 that might fix the issue. If it doesn't it will give us better debug to look at. We'll see got a key error and trying again, but synchronous in the log.

[m0urs]

Thanks a lot.

Is there a minimum requirement of Python3? I just updated my branch with the current master and on my Windows machine with Python 3.8 everything is working fine. On my Raspberrypi with Python 3.5.3 I do get the following error:

Traceback (most recent call last):
  File "arlo-fhem.py", line 10, in <module>
    import pyaarlo
  File "/opt/fhem/arlo-fhem/pyaarlo/__init__.py", line 9, in <module>
    from .backend import ArloBackEnd
  File "/opt/fhem/arlo-fhem/pyaarlo/backend.py", line 30, in <module>
    from .tfa import Arlo2FAConsole, Arlo2FAImap, Arlo2FARestAPI
  File "/opt/fhem/arlo-fhem/pyaarlo/tfa.py", line 68
    self._arlo.error(f"imap connection failed{str(e)}")
                                                     ^
SyntaxError: invalid syntax

Not sure if it is the Python version but I do not see any difference. I just pulled my repository from Github on both machines.

UPDATE: Just saw that formatted strings have been introduced in 3.6 so in 3.5 this is not working. I will see if and how I can upgrade my production Raspbery Pi to 3.8.

[m0urs]

I now have updated my installation to Python 3.8.6 and I am now runnng the latest master. I will let you know if I get the error again. Thanks a lot so far!

[twrecked]

Glad you got it fixed. I was just about to let you know formatted strings were added in 3.6. Truthfully, when I added the strings I didn't realize they were version specific.

Let me know if it works.

[m0urs]

It seems that the "KeyError" from above does no longer happen. However, now it seems that from time to time a command sent, will wait for up to 3 Minutes until it is really done.

You see that in m ylog that the command is sent at 22:32:35 and then nothing happens until 22:35:36. Then the command has been successful (which you can as the "<RequestsCookieJar" message appears (that is the message where nobody knows where it comes from ;-))

Nov 24 22:32:35 raspberrypi02 arlo-fhem[14589]: 2020-11-24 22:32:35 - arlo-fhem - Received command: set-mode garten_hinten
Nov 24 22:35:36 raspberrypi02 arlo-fhem[14589]: <RequestsCookieJar[Cookie(version=0, name='__cf_bm', value='03b010585405e88b4c4c6bf1ba67e5031f34e8b3-1606253433-1800-AZLCJXT/8ct6ysMgojA7OytgPmz2Tj/76IFyrDWbcW+hoctJpgLFdgoZ3Yv3AVUaXU9TBTRAW4NWGQonuUTK9hs=', port=None, port_specified=False, domain='.my.arlo.com', domain_specified=True, domain_initial_dot=True, path='/', path_specified=True, secure=True, expires=1606255233, discard=False, comment=None, comment_url=None, rest={'HttpOnly': None, 'SameSite': 'None'}, rfc2109=False), Cookie(version=0, name='__cfduid', value='d5411b2f3b101c0eda2be29b7b0f2c2a51606183228', port=None, port_specified=False, domain='.my.arlo.com', domain_specified=True, domain_initial_dot=True, path='/', path_specified=True, secure=False, expires=1608775228, discard=False, comment=None, comment_url=None, rest={'HttpOnly': None, 'SameSite': 'Lax'}, rfc2109=False), Cookie(version=0, name='__cf_bm', value='8131433e3faa7eb8c18b84f4c213397b6af622d6-1606183228-1800-AeP+Ru4DqsUdA5A/sUYdNU6Mb7ejhWgC5JxxMKYVwFRCRg0LNH5SFoYtRr9Sf6TvkQ+RtTSFYKwg7UrBQkGhkFY=', port=None, port_specified=False, domain='.ocapi-app.arlo.com', domain_specified=True, domain_initial_dot=True, path='/', path_specified=True, secure=True, expires=1606185028, discard=False, comment=None, comment_url=None, rest={'HttpOnly': None, 'SameSite': 'None'}, rfc2109=False), Cookie(version=0, name='__cfduid', value='dd2de2db2b14d4319f70dbba277e5561b1606183227', port=None, port_specified=False, domain='.ocapi-app.arlo.com', domain_specified=True, domain_initial_dot=True, path='/', path_specified=True, secure=False, expires=1608775227, discard=False, comment=None, comment_url=None, rest={'HttpOnly': None, 'SameSite': 'Lax'}, rfc2109=False), Cookie(version=0, name='__cfruid', value='a5ec0319cac87a76b93d1dd63adcd2e0c123479a-1606183228', port=None, port_specified=False, domain='.ocapi-app.arlo.com', domain_specified=True, domain_initial_dot=True, path='/', path_specified=True, secure=True, expires=None, discard=True, comment=None, comment_url=None, rest={'HttpOnly': None, 'SameSite': 'None'}, r
Nov 24 22:35:36 raspberrypi02 arlo-fhem[14589]: fc2109=False), Cookie(version=0, name='AWSELB', value='330F99231E37B937A721F0469577534959D6D111408DFD3AAED0FB609B4EE7D83FF330D9871DCF60A78C3359F25A0612683F08BD2BE758F7D00AC690D7EE3265EC943D17EA742978369590B1E212D8CBA4F5481359', port=None, port_specified=False, domain='my.arlo.com', domain_specified=False, domain_initial_dot=False, path='/hmsweb/', path_specified=True, secure=True, expires=None, discard=True, comment=None, comment_url=None, rest={'HTTPONLY': None}, rfc2109=False), Cookie(version=0, name='JSESSIONID', value='4726AAEB88190A288C7AC41A8614FAE7', port=None, port_specified=False, domain='my.arlo.com', domain_specified=False, domain_initial_dot=False, path='/hmsweb/', path_specified=True, secure=True, expires=None, discard=True, comment=None, comment_url=None, rest={'HttpOnly': None}, rfc2109=False), Cookie(version=0, name='ADRUM_BT', value='R:19|i:286186|g:77faf13c-8a41-4a5d-b95c-1a7bade5fc63360190|e:35|n:arlo-prod1_d3ab7f34-d387-4bc8-ae6b-d1fe09803cbd', port=None, port_specified=False, domain='ocapi-app.arlo.com', domain_specified=False, domain_initial_dot=False, path='/', path_specified=True, secure=False, expires=1606183258, discard=False, comment=None, comment_url=None, rest={}, rfc2109=False)]>

[twrecked]

The 3 minutes lines up with what I thought was happening. The initial mode change fails - or the reply get missed - and we will then make several retry attempts to make it happen. Because you're in synchronous mode the call will wait. If you have the debug from when the initial request went in maybe we can see if I'm missing something.

Try turning on packet dump and verbose debug.

arlo = pyaarlo.PyArlo(username=USERNAME, password=PASSWORD,
                      synchronous_mode=True, verbose_debug=True)

Look for packets around starting transaction, finishing transaction and finished transaction.

[m0urs]

Starting at 19:04 the issue should have been happened. Hopefully you will see something useful in the debug log ;-)
debug.log.encrypted.txt

[m0urs]

Just switched from sync mode to async mode. It is still working for me. I guess I did not understand the difference correctly. Seems that for me async mode is ok and that might fix the issue for me ... It also fixes the issue with the "<RequestsCookieJar" messages.

I will monitor the next 2 days if everything is correct and if yes, we can close the issue.

[m0urs]

It looks fine for me now. At least most of the time my commands are executed successfully. From time to time there seems to be a command missing if the time between them is too short. But I think I can live with that.

Thanks for your help and I close that issue now.