ep1cman / unifi-protect-backup

Python tool to backup unifi event clips in realtime
MIT License
576 stars 25 forks source link

UNVR Pros Crashing when running Unifi Protect Backup #95

Closed N2Nathan closed 8 months ago

N2Nathan commented 12 months ago

Description

Trying to run Unifi Protect Backup on a UNVR Pro results in Unifi Protect Crashing. It then is stuck in an infinite loop until rebooting the entire UNVR Pro. This happens on two of our UNVR Pros. Both of which we've factory reset.

What I Did

2023-07-07 16:26:54 [ WARNING ] pyunifiprotect.api : Websocket connection not active, failing back to polling 2023-07-07 16:26:54 [ WARNING ] unifi_protect_backup.event_listener : Lost connection to Unifi Protect. 2023-07-07 16:26:54 [ WARNING ] unifi_protect_backup.event_listener : Attempting reconnect... 2023-07-07 16:26:54 [ ERROR ] unifi_protect_backup.missing_event_checker : Unexpected exception occurred during missing event check: Traceback (most recent call last): File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 128, in start wanted_events = await self._get_missing_events() File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events unifi_events = await self._protect.get_events( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events response = await self.get_events_raw( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw return await self.api_request_list("events", params=params) File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list data = await self.api_request( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request data = await self.api_request_raw( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 278, in api_request_raw response = await self.request(method, url, require_auth=require_auth, auto_close=False, **kwargs) File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 240, in request response = await req_context.aenter() # pylint: disable=unnecessary-dunder-call File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 1141, in aenter self._resp = await self._coro File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 400, in _request raise RuntimeError("Session is closed") RuntimeError: Session is closed

Then it errors with this:

2023-07-07 16:28:18 [ ERROR ] unifi_protect_backup.event_listener : Unexpected exception occurred while trying to reconnect: Traceback (most recent call last): File "/usr/lib/python3.10/site-packages/unifi_protect_backup/event_listener.py", line 116, in _check_websocket_and_reconnect await self._protect.update(force=True) File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 600, in update self._bootstrap = await self.get_bootstrap() File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 763, in get_bootstrap data = await self.api_request_obj("bootstrap") File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 328, in api_request_obj data = await self.api_request( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request data = await self.api_request_raw( File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 288, in api_request_raw raise BadRequest(msg % (url, response.status, reason)) pyunifiprotect.exceptions.BadRequest: Request failed: /proxy/protect/api/bootstrap - Status: 404 - Reason: Not Found

ep1cman commented 12 months ago

Are you doing an initial backup of the NVR or is this occuring even after the initial backlog has been downloaded? If so could you try with the --skip-missing argument and see if that stops the crashing? What this does is ignore all missing events at the time of launch and only downloads events that occur after the tool is running. If this does fix it, I think I will need to implement some sort of rate limiting on the download requests.

I have faced a lot of issues with unifi protect crashing recently (and its getting worse). I am unable to scroll around in the timeline of a camera for more than a few seconds before unifi protect will crash on my UDM Pro.

N2Nathan commented 12 months ago

This was an initial backup of the NVR. I tried adding the --skip-missing argument but sadly it looks to still be crashing the unifi protect app.;

This is the error message I receive, I believe it's slightly different:

[custom-init] No custom files found, skipping...
[ls.io-init] done.
v
2023-07-08 14:15:36 [   ERROR   ] unifi_protect_backup.unifi_protect_backup_core :  Unexpected exception occurred in main loop:
Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/unifi_protect_backup_core.py", line 265, in start
    await missing.ignore_missing()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 108, in ignore_missing
    wanted_events = await self._get_missing_events()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
    unifi_events = await self._protect.get_events(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
    response = await self.get_events_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
    return await self.api_request_list("events", params=params)
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
    data = await self.api_request(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
    data = await self.api_request_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 288, in api_request_raw
    raise BadRequest(msg % (url, response.status, reason))
pyunifiprotect.exceptions.BadRequest: Request failed: /proxy/protect/api/events - Status: 404 - Reason: Not Found
2023-07-08 14:15:46 [   ERROR   ] aiorun                                     :  Unhandled exception; stopping loop: 'Task exception was never retrieved'
Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/aiorun.py", line 237, in new_coro
    await coro
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/unifi_protect_backup_core.py", line 265, in start
    await missing.ignore_missing()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 108, in ignore_missing
    wanted_events = await self._get_missing_events()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
    unifi_events = await self._protect.get_events(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
    response = await self.get_events_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
    return await self.api_request_list("events", params=params)
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
    data = await self.api_request(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
    data = await self.api_request_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 288, in api_request_raw
    raise BadRequest(msg % (url, response.status, reason))
pyunifiprotect.exceptions.BadRequest: Request failed: /proxy/protect/api/events - Status: 404 - Reason: Not Found
Traceback (most recent call last):
  File "/usr/bin/unifi-protect-backup", line 8, in <module>
    sys.exit(main())
  File "/usr/lib/python3.10/site-packages/click/core.py", line 1137, in __call__
    return self.main(*args, **kwargs)
  File "/usr/lib/python3.10/site-packages/click/core.py", line 1062, in main
    rv = self.invoke(ctx)
  File "/usr/lib/python3.10/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/lib/python3.10/site-packages/click/core.py", line 763, in invoke
    return __callback(*args, **kwargs)
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/cli.py", line 176, in main
    run(event_listener.start(), stop_on_unhandled_errors=True)
  File "/usr/lib/python3.10/site-packages/aiorun.py", line 400, in run
    raise pending_exception_to_raise
  File "/usr/lib/python3.10/site-packages/aiorun.py", line 237, in new_coro
    await coro
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/unifi_protect_backup_core.py", line 265, in start
    await missing.ignore_missing()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 108, in ignore_missing
    wanted_events = await self._get_missing_events()
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
    unifi_events = await self._protect.get_events(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
    response = await self.get_events_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
    return await self.api_request_list("events", params=params)
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
    data = await self.api_request(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
    data = await self.api_request_raw(
  File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 288, in api_request_raw
    raise BadRequest(msg % (url, response.status, reason))
pyunifiprotect.exceptions.BadRequest: Request failed: /proxy/protect/api/events - Status: 404 - Reason: Not Found
****
ep1cman commented 12 months ago

Hi, could you try the latest dev version? I have added a setting to rate limit the download requests and I have fixed some issues where the tool was trying to execute queued jobs after a connection was lost.

I would suggest limiting it to something very slow like 1 per minute and lets see if it survives that. If not, can you please share a full log.

N2Nathan commented 11 months ago

Hey, thanks so much for adding the rate limit functionality. It sadly looks to still be crashing. I tried the new version on both the stacked UNVR Pro and the stand alone UNVR Pro. The regular UNVRs have no problem. The rate limit functionality will be very helpful in other cases though!

Here are the support logs: https://drive.google.com/drive/folders/1J6hT3ReB0wyWKjDmVIWHWe8Z1zpUtuea?usp=drive_link

ep1cman commented 11 months ago

Could you also share the full logs of unifi-protect-backup leading upto the crash? I would like to see what it is doing to cause the crash

ep1cman commented 11 months ago

Looking through your support logs, I can see two things:

So a few things come to mind:

AndrewPaglusch commented 11 months ago

I am also affected by this. The Protect UI and both of my Viewports die once I start the container.

docker-compose file

  unifi-protect-backup:
    image: ghcr.io/ep1cman/unifi-protect-backup
    container_name: unifi-protect-backup
    restart: unless-stopped
    environment:
      - UFP_USERNAME=REDACTED
      - UFP_PASSWORD=REDACTED
      - UFP_ADDRESS=10.151.160.2
      - UFP_SSL_VERIFY=false
      - RCLONE_DESTINATION=enc_b2_paglusch-unifi-protect-clips:/
      - RCLONE_RETENTION=365d
      #- VERBOSITY=vvv
    volumes:
      - ./unifi-protect-backup/data:/data
      - ./unifi-protect-backup/db:/config/database
      - ./unifi-protect-backup/config/rclone.conf:/config/rclone/rclone.conf:ro

Lots of events in the DB:

sqlite3 unifi-protect-backup/db/events.sqlite 'SELECT COUNT(*) FROM events'
71320

Here are the relevant logs:

unifi-protect-backup  | 2023-07-29 07:12:55 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting Tasks...
unifi-protect-backup  | 2023-07-29 07:12:55 [   INFO    ] unifi_protect_backup.downloader            :  Starting Downloader
unifi-protect-backup  | 2023-07-29 07:12:55 [   INFO    ] unifi_protect_backup.uploader              :  Starting Uploader
unifi-protect-backup  | 2023-07-29 07:12:55 [   DEBUG   ] unifi_protect_backup.event_listener        :  Subscribed to websocket
unifi-protect-backup  | 2023-07-29 07:12:55 [   INFO    ] unifi_protect_backup.missing_event_checker :  Starting Missing Event Checker
unifi-protect-backup  | 2023-07-29 07:13:55 [  WARNING  ] pyunifiprotect.api                         :  Websocket connection not active, failing back to polling
unifi-protect-backup  | 2023-07-29 07:13:55 [  WARNING  ] unifi_protect_backup.event_listener        :  Lost connection to Unifi Protect.
unifi-protect-backup  | 2023-07-29 07:13:55 [  WARNING  ] unifi_protect_backup.event_listener        :  Attempting reconnect...
unifi-protect-backup  | 2023-07-29 07:13:55 [   ERROR   ] unifi_protect_backup.missing_event_checker :  Unexpected exception occurred during missing event check:
unifi-protect-backup  | Traceback (most recent call last):
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 131, in start
unifi-protect-backup  |     wanted_events = await self._get_missing_events()
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
unifi-protect-backup  |     unifi_events = await self._protect.get_events(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
unifi-protect-backup  |     response = await self.get_events_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
unifi-protect-backup  |     return await self.api_request_list("events", params=params)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
unifi-protect-backup  |     data = await self.api_request(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
unifi-protect-backup  |     data = await self.api_request_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 278, in api_request_raw
unifi-protect-backup  |     response = await self.request(method, url, require_auth=require_auth, auto_close=False, **kwargs)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 240, in request
unifi-protect-backup  |     response = await req_context.__aenter__()  # pylint: disable=unnecessary-dunder-call
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 1141, in __aenter__
unifi-protect-backup  |     self._resp = await self._coro
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 400, in _request
unifi-protect-backup  |     raise RuntimeError("Session is closed")
unifi-protect-backup  | RuntimeError: Session is closed

Adding the SKIP_MISSING=True does not fix the problem. Protect still crashes.

unifi-protect-backup  | 2023-07-29 07:24:45 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  NVR TZ: America/Chicago
unifi-protect-backup  | 2023-07-29 07:24:45 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  Local TZ: UTC
unifi-protect-backup  | 2023-07-29 07:24:45 [   DEBUG   ] unifi_protect_backup.downloader            :  ffprobe found: /usr/bin/ffprobe
unifi-protect-backup  | 2023-07-29 07:24:45 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Ignoring missing events

**crash happens here**

unifi-protect-backup  | 2023-07-29 07:26:14 [   INFO    ] unifi_protect_backup.missing_event_checker :   Ignoring 71317 missing events
unifi-protect-backup  | 2023-07-29 07:26:27 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting Tasks...
unifi-protect-backup  | 2023-07-29 07:26:27 [   INFO    ] unifi_protect_backup.downloader            :  Starting Downloader
unifi-protect-backup  | 2023-07-29 07:26:27 [   INFO    ] unifi_protect_backup.uploader              :  Starting Uploader
unifi-protect-backup  | 2023-07-29 07:26:27 [   DEBUG   ] unifi_protect_backup.event_listener        :  Subscribed to websocket
unifi-protect-backup  | 2023-07-29 07:26:27 [   INFO    ] unifi_protect_backup.missing_event_checker :  Starting Missing Event Checker

**crash happens here**

unifi-protect-backup  | 2023-07-29 07:27:27 [  WARNING  ] pyunifiprotect.api                         :  Websocket connection not active, failing back to polling
unifi-protect-backup  | 2023-07-29 07:27:27 [  WARNING  ] unifi_protect_backup.event_listener        :  Lost connection to Unifi Protect.
unifi-protect-backup  | 2023-07-29 07:27:27 [  WARNING  ] unifi_protect_backup.event_listener        :  Attempting reconnect...
unifi-protect-backup  | 2023-07-29 07:27:27 [   ERROR   ] unifi_protect_backup.missing_event_checker :  Unexpected exception occurred during missing event check:
unifi-protect-backup  | Traceback (most recent call last):
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 131, in start
unifi-protect-backup  |     wanted_events = await self._get_missing_events()
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
unifi-protect-backup  |     unifi_events = await self._protect.get_events(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
unifi-protect-backup  |     response = await self.get_events_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
unifi-protect-backup  |     return await self.api_request_list("events", params=params)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
unifi-protect-backup  |     data = await self.api_request(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
unifi-protect-backup  |     data = await self.api_request_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 278, in api_request_raw
unifi-protect-backup  |     response = await self.request(method, url, require_auth=require_auth, auto_close=False, **kwargs)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 240, in request
unifi-protect-backup  |     response = await req_context.__aenter__()  # pylint: disable=unnecessary-dunder-call
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 1141, in __aenter__
unifi-protect-backup  |     self._resp = await self._coro
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 400, in _request
unifi-protect-backup  |     raise RuntimeError("Session is closed")
unifi-protect-backup  | RuntimeError: Session is closed
unifi-protect-backup  | 2023-07-29 07:27:42 [   INFO    ] unifi_protect_backup.event_listener        :  Re-established connection to Unifi Protect and to the websocket.
ep1cman commented 11 months ago

@AndrewPaglusch, could you try the dev branch/container and see if the newly added rate limit option helps?

AndrewPaglusch commented 11 months ago

@ep1cman I added the rate limit and switched to the :dev tag. It still crashes Protect when the container starts up. I added some markers to the logs below to show you where the crash happens

unifi-protect-backup  | [migrations] started
unifi-protect-backup  | [migrations] no migrations found
unifi-protect-backup  | cp: cannot stat '/root/.config/rclone/rclone.conf': No such file or directory
unifi-protect-backup  | chown: changing ownership of '/config/rclone/rclone.conf': Read-only file system
unifi-protect-backup  | usermod: no changes
unifi-protect-backup  | ───────────────────────────────────────
unifi-protect-backup  |   _____ __ __ _____ _____ _____ _____
unifi-protect-backup  |  |     |  |  |   __|_   _|     |     |
unifi-protect-backup  |  |   --|  |  |__   | | | |  |  | | | |
unifi-protect-backup  |  |_____|_____|_____| |_| |_____|_|_|_|
unifi-protect-backup  |        _____ __ __ _ __    ____
unifi-protect-backup  |       | __  |  |  | |  |  |    \
unifi-protect-backup  |       | __ -|  |  | |  |__|  |  |
unifi-protect-backup  |       |_____|_____|_|_____|____/
unifi-protect-backup  |
unifi-protect-backup  |   Based on images from linuxserver.io
unifi-protect-backup  | ───────────────────────────────────────
unifi-protect-backup  |
unifi-protect-backup  | To support LSIO projects visit:
unifi-protect-backup  | https://www.linuxserver.io/donate/
unifi-protect-backup  |
unifi-protect-backup  | ───────────────────────────────────────
unifi-protect-backup  | GID/UID
unifi-protect-backup  | ───────────────────────────────────────
unifi-protect-backup  |
unifi-protect-backup  | User UID:    911
unifi-protect-backup  | User GID:    911
unifi-protect-backup  | ───────────────────────────────────────
unifi-protect-backup  |
unifi-protect-backup  | [custom-init] No custom files found, skipping...
unifi-protect-backup  | [ls.io-init] done.
unifi-protect-backup  | v
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  Config:
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    address='10.151.160.2'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    port=443
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    username='api-clip-backup'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    password=REDACTED
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    verify_ssl=False
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    rclone_destination='enc_b2_paglusch-unifi-protect-clips:/'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    retention='365d'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    rclone_args=''
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    rclone_purge_args=''
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    ignore_cameras=()
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    verbose=1
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    detection_types=['motion', 'person', 'vehicle', 'ring']
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    file_structure_format='{camera_name}/{event.start:%Y-%m-%d}/{event.end:%Y-%m-%dT%H-%M-%S} {detection_type}.mp4'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    sqlite_path='/config/database/events.sqlite'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    download_buffer_size=512.0MiB
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    purge_interval='1d'
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    apprise_notifiers=()
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    skip_missing=False
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :    download_rate_limit=1.0 events per minute
unifi-protect-backup  | 2023-07-29 15:55:05 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting...
unifi-protect-backup  | 2023-07-29 15:55:05 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Checking rclone configuration...
unifi-protect-backup  | 2023-07-29 15:55:05 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  rclone found: /usr/bin/rclone
unifi-protect-backup  | 2023-07-29 15:55:06 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Connecting to Unifi Protect...
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Found cameras:
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 63769c7a03047c03e70f4f79: Driveway - North
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6266dca80042cb03e703821c: Server Rack
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6266ddb602e0cb03e703823b: Living Room
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a34f01eb4203e70008a4: Back - West (Egress)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 64875dc301f97103e40005ce: Doorbell
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a330035a4203e70008a1: Front Door
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a562028d4203e70008b2: Side - Southeast (Ellis)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a32602bc4203e70008a0: Back - South (Bay Window)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a36c03cf4203e70008a6: Side - West (Ellis)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a33a02c14203e70008a3: Front - North (Tree)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a36300f14203e70008a5: Driveway - East
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 62a7a09901e6fc03e706ed85: Side - North (AC)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185a31e01884203e700089f: Driveway - Northeast
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 6185c3a801304203e7000c02: Side - Southwest (Neighbor)
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 638a638b006fb103e403507c: Chloe TV™
unifi-protect-backup  | 2023-07-29 15:55:07 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  NVR TZ: America/Chicago
unifi-protect-backup  | 2023-07-29 15:55:07 [   DEBUG   ] unifi_protect_backup.unifi_protect_backup_core :  Local TZ: UTC
unifi-protect-backup  | 2023-07-29 15:55:07 [   DEBUG   ] unifi_protect_backup.downloader            :  ffprobe found: /usr/bin/ffprobe
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting Tasks...
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.downloader            :  Starting Downloader
unifi-protect-backup  | 2023-07-29 15:55:07 [   DEBUG   ] unifi_protect_backup.downloader            :  Waiting for rate limit
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.uploader              :  Starting Uploader
unifi-protect-backup  | 2023-07-29 15:55:07 [   DEBUG   ] unifi_protect_backup.event_listener        :  Subscribed to websocket
unifi-protect-backup  | 2023-07-29 15:55:07 [   INFO    ] unifi_protect_backup.missing_event_checker :  Starting Missing Event Checker

**crash happens here**

unifi-protect-backup  | 2023-07-29 15:56:07 [  WARNING  ] pyunifiprotect.api                         :  Websocket connection not active, failing back to polling
unifi-protect-backup  | 2023-07-29 15:56:07 [  WARNING  ] unifi_protect_backup.event_listener        :  Lost connection to Unifi Protect.
unifi-protect-backup  | 2023-07-29 15:56:07 [  WARNING  ] unifi_protect_backup.event_listener        :  Attempting reconnect...
unifi-protect-backup  | 2023-07-29 15:56:07 [   ERROR   ] unifi_protect_backup.missing_event_checker :  Unexpected exception occurred during missing event check:
unifi-protect-backup  | Traceback (most recent call last):
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 131, in start
unifi-protect-backup  |     wanted_events = await self._get_missing_events()
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/missing_event_checker.py", line 59, in _get_missing_events
unifi-protect-backup  |     unifi_events = await self._protect.get_events(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 720, in get_events
unifi-protect-backup  |     response = await self.get_events_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 690, in get_events_raw
unifi-protect-backup  |     return await self.api_request_list("events", params=params)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 345, in api_request_list
unifi-protect-backup  |     data = await self.api_request(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 311, in api_request
unifi-protect-backup  |     data = await self.api_request_raw(
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 278, in api_request_raw
unifi-protect-backup  |     response = await self.request(method, url, require_auth=require_auth, auto_close=False, **kwargs)
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/pyunifiprotect/api.py", line 240, in request
unifi-protect-backup  |     response = await req_context.__aenter__()  # pylint: disable=unnecessary-dunder-call
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 1141, in __aenter__
unifi-protect-backup  |     self._resp = await self._coro
unifi-protect-backup  |   File "/usr/lib/python3.10/site-packages/aiohttp/client.py", line 400, in _request
unifi-protect-backup  |     raise RuntimeError("Session is closed")
unifi-protect-backup  | RuntimeError: Session is closed
unifi-protect-backup  | 2023-07-29 15:56:16 [   INFO    ] unifi_protect_backup.event_listener        :  Re-established connection to Unifi Protect and to the websocket.

Here's my updated docker-compose.yml with the rate limit added:

  unifi-protect-backup:
    image: ghcr.io/ep1cman/unifi-protect-backup:dev
    container_name: unifi-protect-backup
    restart: unless-stopped
    environment:
      - UFP_USERNAME=api-clip-backup
      - UFP_PASSWORD=REDACTED
      - UFP_ADDRESS=10.151.160.2
      - UFP_SSL_VERIFY=false
      - RCLONE_DESTINATION=enc_b2_paglusch-unifi-protect-clips:/
      - RCLONE_RETENTION=365d
      - DOWNLOAD_RATELIMIT=1
      #- SKIP_MISSING=True
      #- VERBOSITY=vvv
    volumes:
      - ./unifi-protect-backup/data:/data
      - ./unifi-protect-backup/db:/config/database
      - ./unifi-protect-backup/config/rclone.conf:/config/rclone/rclone.conf:ro
sardonicsloth commented 11 months ago

I am also having this issue -- i have switched to dev branch and do still see crashing. To be of note i am going through a proxy to reach the nvr but @AndrewPaglusch is not i believe.

I see the following logs in the NVR itself during the inital startup crash that always happens:

` 2023-08-04T20:44:14.270Z - info: https[nvrbackups ] 55ms 200 GET /proxy/protect/api/events?start=1691181853180&end=1691181853180

2023-08-04T20:44:47.244Z - info: websocket proxy closed from src: /proxy/protect/ws/updates%3FlastUpdateId=9ce92707-6887-4617-a17a-7520035b31b6?lastUpdateId=9ce92707-6887-4617-a17a-7520035b31b6 > ws://localhost:7080/ws/updates?lastUpdateId=9ce92707-6887-4617-a17a-7520035b31b6 1000 `

From the HTTP logs it looks like the script is closing the websocket. Maybe try and break down large-ish time frame requests into 1 month or 1 week requests?

ep1cman commented 8 months ago

If my guess that this is caused by querying the server for too many events, then this should be resolved now with v0.9.5

N2Nathan commented 8 months ago

Your guess was spot on it seems. After deploying the new release none of the unvrs or unvr pros are crashing. Thank you so much!