Errors in log: Unexpected exception occurred, abandoning event; pyunifiprotect.exceptions.BadRequest: Client not initalized, run `update` first

timotab commented 12 months ago

Unifi Protect Backup version: 0.9.2
Unifi Protect version: 2.8.28
Python version: 3.9.10
Operating System: Raspbian GNU/Linux 10 (buster)
Are you using a docker container or native?: Native

Description

Was restarting system after an extended power outage. I noticed some errors in the logs. I made sure everything was updated (Unifi Protect Backup was already updated, pyunifiprotect was a little behind, rclone was a little behind)

Requirement already satisfied: pyunifiprotect in /home/thunt/.local/lib/python3.9/site-packages (4.4.1)
Collecting pyunifiprotect
  Downloading https://www.piwheels.org/simple/pyunifiprotect/pyunifiprotect-4.10.4-py3-none-any.whl (105 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 105.3/105.3 kB 434.0 kB/s eta 0:00:00

Collecting rclone
  Downloading https://www.piwheels.org/simple/rclone/rclone-0.4.4-py3-none-any.whl (4.5 kB)
Collecting loguru>=0.5.3 (from rclone)
  Downloading https://www.piwheels.org/simple/loguru/loguru-0.7.0-py3-none-any.whl (59 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 60.0/60.0 kB 396.0 kB/s eta 0:00:00
Collecting tqdm>=4.62.3 (from rclone)
  Downloading https://www.piwheels.org/simple/tqdm/tqdm-4.65.0-py3-none-any.whl (77 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 77.1/77.1 kB 578.2 kB/s eta 0:00:00
Installing collected packages: tqdm, loguru, rclone
Successfully installed loguru-0.7.0 rclone-0.4.4 tqdm-4.65.0

Further investigation showed errors started June 10, well before power outage. No apparent reason. No unifi equipment updated that day (though Protect updated on June 20). Even after making sure everything was updated as above, errors still occurred.

What I Did


unifi-protect-backup --address 192.168.1.1 --no-verify-ssl --retention 60M --rclone-destination awsbackups:${backupbucket} >> unifi-protect.log 2>&1

2023-06-10 04:23:53 [   INFO    ] unifi_protect_backup.uploader              : [6421dac9012df803e7003672]  Uploading event: 6421dac9012df803e7003672
2023-06-10 04:23:54 [   INFO    ] unifi_protect_backup.uploader              : [62693d57011bc0038700aada]  Uploading event: 62693d57011bc0038700aada
2023-06-10 04:23:59 [  WARNING  ] pyunifiprotect.api                         :  Websocket connection not active, failing back to polling
2023-06-10 04:23:59 [  WARNING  ] unifi_protect_backup.event_listener        :  Lost connection to Unifi Protect.
2023-06-10 04:23:59 [  WARNING  ] unifi_protect_backup.event_listener        :  Attempting reconnect...
2023-06-10 04:24:00 [   INFO    ] unifi_protect_backup.uploader              : [626d76c501fade038700109c]  Uploading event: 626d76c501fade038700109c
2023-06-10 04:24:00 [   ERROR   ] unifi_protect_backup.uploader              : [626d76c501fade038700109c]  Unexpected exception occurred, abandoning event 626d76c501fade038700109c:
Traceback (most recent call last):
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 74, in start
    destination = await self._generate_file_path(event)
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 153, in _generate_file_path
    "camera_name": await get_camera_name(self._protect, event.camera_id),
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/utils.py", line 286, in get_camera_name
    return protect.bootstrap.cameras[id].name
  File "/home/thunt/.local/lib/python3.9/site-packages/pyunifiprotect/api.py", line 552, in bootstrap
    raise BadRequest("Client not initalized, run `update` first")
pyunifiprotect.exceptions.BadRequest: Client not initalized, run `update` first
2023-06-10 04:24:00 [   INFO    ] unifi_protect_backup.uploader              : [6317b78f0009820387016898]  Uploading event: 6317b78f0009820387016898
2023-06-10 04:24:00 [   ERROR   ] unifi_protect_backup.uploader              : [6317b78f0009820387016898]  Unexpected exception occurred, abandoning event 6317b78f0009820387016898:
Traceback (most recent call last):
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 74, in start
    destination = await self._generate_file_path(event)
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 153, in _generate_file_path
    "camera_name": await get_camera_name(self._protect, event.camera_id),
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/utils.py", line 286, in get_camera_name
    return protect.bootstrap.cameras[id].name
  File "/home/thunt/.local/lib/python3.9/site-packages/pyunifiprotect/api.py", line 552, in bootstrap
    raise BadRequest("Client not initalized, run `update` first")
pyunifiprotect.exceptions.BadRequest: Client not initalized, run `update` first
2023-06-10 04:24:00 [   INFO    ] unifi_protect_backup.uploader              : [647a3fb00240ce03e400e237]  Uploading event: 647a3fb00240ce03e400e237
2023-06-10 04:24:00 [   ERROR   ] unifi_protect_backup.uploader              : [647a3fb00240ce03e400e237]  Unexpected exception occurred, abandoning event 647a3fb00240ce03e400e237:
Traceback (most recent call last):
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 74, in start
    destination = await self._generate_file_path(event)
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/uploader.py", line 153, in _generate_file_path
    "camera_name": await get_camera_name(self._protect, event.camera_id),
  File "/home/thunt/.local/lib/python3.9/site-packages/unifi_protect_backup/utils.py", line 286, in get_camera_name
    return protect.bootstrap.cameras[id].name
  File "/home/thunt/.local/lib/python3.9/site-packages/pyunifiprotect/api.py", line 552, in bootstrap
    raise BadRequest("Client not initalized, run `update` first")
pyunifiprotect.exceptions.BadRequest: Client not initalized, run `update` first

ep1cman commented 12 months ago

Thanks for reporting this. I have also started seeing this recently.

The jist of whats going wrong here is:

The tool has lost connection to unifi protect
Before it is able to re-establish the connection, a queued upload is trying to fetch the camera's name and this is causing an error.

I think two things can be done to improve this:

Cache the camera names so that uploads can continue even when the connection is lost
Add some locks around anything that accesses the protect client, which can be locked out when the connection is lost.

I shall try and work on this ASAP

ep1cman commented 12 months ago

The latest release should address this

ep1cman / unifi-protect-backup

Errors in log: Unexpected exception occurred, abandoning event; pyunifiprotect.exceptions.BadRequest: Client not initalized, run `update` first #94

Description

What I Did