search

ep1cman / unifi-protect-backup

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

Configure sleep time before download? #47

Closed jsumners closed 1 year ago

jsumners commented 1 year ago

https://github.com/ep1cman/unifi-protect-backup/blob/031d4e48623f6f15b8b3262394d5d255efac391c/unifi_protect_backup/unifi_protect_backup.py#L482-L493

I like that we are waiting for the video to be ready, but in my initial setup and test I got:

2022-08-24 13:42:02 [INFO]:unifi_protect_backup.unifi_protect_backup:   Listening for events...
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 630663b402dc570387000b84-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-24 13:45:30 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 630663b402dc570387000b84-6304e6f900f75703870003ea
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: motion
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-24T13-45-18 (1661363118.658)
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-24T13-45-42 (1661363142.653)
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 23.995
2022-08-24 13:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Sleeping (14420.020939s) to ensure clip is ready to download...
2022-08-24 13:45:36 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 630663b400fa570387000b83-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-24 13:48:46 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 6306647503ca570387000b94-6304e6f900f75703870003ea to queue (Current queue=2)
2022-08-24 13:48:46 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 6306646d00d4570387000b91-6304e6f900f75703870003ea to queue (Current queue=3)

Unless I'm mistaken, 14420.020939s is roughly 4 hours. That's a very long time to wait before uploading an event that could result in someone stealing the gear. I would think we want to upload the event to the offsite back up as soon as possible, i.e. before the gear is stolen.

ep1cman commented 1 year ago

Yeah no something has gone horribly wrong there, its supposed to wait 7.5s or less, but what I didnt do is check if time_since_event_end is negative which it clearly is here. Out of curiosity what time zone are you in?

jsumners commented 1 year ago

America/New_York.

ep1cman commented 1 year ago

Ah, so 4 hours difference from UTC. Thats where that is coming from. Are you running this directly on your machine or via the docker container? If you are using a container, have you set the TZ env variable to match your timezone?

jsumners commented 1 year ago

I'm running it in a container and have not set any TZ settings there.

❯ docker exec -it protect-backup /bin/bash
root@7e647d72082d:/app# date
Wed Aug 24 14:46:20 UTC 2022
root@7e647d72082d:/app# env | grep TZ
TZ=UTC
root@7e647d72082d:/app#
ep1cman commented 1 year ago

Could you try adding the the following TZ=America/New_York env variable to your container. I will add a note for this in the docs because its come up a few times now. I will also put a check in the code for if the value is negative and issue a warning

jsumners commented 1 year ago

Unfortunately, I got the same thing:

❯ docker exec -it protect-backup /bin/bash
root@fcb92574c618:/app# date
Wed Aug 24 10:53:33 EDT 2022
root@fcb92574c618:/app# env | grep TZ
TZ=America/New_York
root@fcb92574c618:/app#
2022-08-24 10:50:22 [INFO]:unifi_protect_backup.unifi_protect_backup:   Listening for events...
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 63067362012f570387000be0-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-24 10:52:23 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 63067362012f570387000be0-6304e6f900f75703870003ea
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: motion
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-24T14-52-12 (1661367132.199)
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-24T14-52-35 (1661367155.202)
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 23.003
2022-08-24 10:52:23 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Sleeping (14419.091665s) to ensure clip is ready to download...
2022-08-24 10:52:24 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 6306736302fa570387000be1-6304e6f900f75703870003ea to queue (Current queue=1)
ep1cman commented 1 year ago

Can you also confirm your NVR has the correct time zone configured? If so its definitely an issue on my end and I will try figure it out.

jsumners commented 1 year ago

It's a UDM-PRO. So the setting is inherited in the "Protect" app from the base OS.

image

ep1cman commented 1 year ago

Thanks for checking and reporting the bug, I will look into this now and hopefully have a fix soon. I am annoyingly in the GMT time zone so dont get to experience these issues and its difficult to test

jsumners commented 1 year ago

Timezones are difficult.

I don't know the Python for it, but generally, I would normalize the recording timestamp to UTC and then perform the calculations.

ep1cman commented 1 year ago

pyunifiprotect already normalises everyhting to UTC which lead to some confusing messages for users. I now try to normalise everything to the NVR timezone, but I think https://github.com/ep1cman/unifi-protect-backup/blob/031d4e48623f6f15b8b3262394d5d255efac391c/unifi_protect_backup/unifi_protect_backup.py#L489 is wrong. I am now testing a fix and will produce a dev container for you to test too once it works for me

ep1cman commented 1 year ago

Could you try the latest :dev container and see if that is any better?

jsumners commented 1 year ago 
2022-08-24 11:27:18 [INFO]:unifi_protect_backup.unifi_protect_backup:   Listening for events...
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 63067bd801bb570387000c12-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-24 11:28:30 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 63067bd801bb570387000c12-6304e6f900f75703870003ea
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: motion
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-24T15-28-18 (1661369298.347)
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-24T15-28-41 (1661369321.351)
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 23.004
2022-08-24 11:28:30 [WARNING]:unifi_protect_backup.unifi_protect_backup:           Negative time since event ended, please check timezone of host and NVR match.
2022-08-24 11:28:30 [WARNING]:unifi_protect_backup.unifi_protect_backup:        Unexpected exception occurred, abandoning event 63067bd801bb570387000c12-6304e6f900f75703870003ea:
2022-08-24 11:28:30 [ERROR]:unifi_protect_backup.unifi_protect_backup:  unsupported operand type(s) for -: 'datetime.timedelta' and 'int'
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/unifi_protect_backup/unifi_protect_backup.py", line 495, in _backup_events
    sleep_time = (timedelta(seconds=10) - time_since_event_ended).total_seconds()
TypeError: unsupported operand type(s) for -: 'datetime.timedelta' and 'int'
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 63067bd70017570387000c11-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-24 11:28:30 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 63067bd70017570387000c11-6304e6f900f75703870003ea
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: smartDetectZone (person)
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-24T15-28-16 (1661369296.666)
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-24T15-28-41 (1661369321.595)
2022-08-24 11:28:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 24.929
2022-08-24 11:28:30 [WARNING]:unifi_protect_backup.unifi_protect_backup:           Negative time since event ended, please check timezone of host and NVR match.
2022-08-24 11:28:30 [WARNING]:unifi_protect_backup.unifi_protect_backup:        Unexpected exception occurred, abandoning event 63067bd70017570387000c11-6304e6f900f75703870003ea:
2022-08-24 11:28:30 [ERROR]:unifi_protect_backup.unifi_protect_backup:  unsupported operand type(s) for -: 'datetime.timedelta' and 'int'
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/unifi_protect_backup/unifi_protect_backup.py", line 495, in _backup_events
    sleep_time = (timedelta(seconds=10) - time_since_event_ended).total_seconds()
TypeError: unsupported operand type(s) for -: 'datetime.timedelta' and 'int'
ep1cman commented 1 year ago

Sorry about that. Try again now? I have also added some logging output about timezones. Could you paste the full log segment. I just changed my UDM Pro to be new york as well as my container and it seems to work:

unifi-protect-backup_1  | 2022-08-24 15:44:26 [DEBUG]:unifi_protect_backup.unifi_protect_backup:        NVR TZ: America/New_York
unifi-protect-backup_1  | 2022-08-24 15:44:26 [DEBUG]:unifi_protect_backup.unifi_protect_backup:        Local TZ: EDT
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup: Found cameras:
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup:  - 60ae3a6002138a0387000734: Driveway (Back)
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup:  - 62156e8a00b5900387007c88: G3 Instant
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup:  - 62ef94df02daf403870eb6a6: Back Garden
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup:  - 60b1208b00378a0387001b3f: Doorbell
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup:  - 60ae2fa300e18a03870006f3: Driveway (Front)
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup: Setting up purge task...
unifi-protect-backup_1  | 2022-08-24 15:44:26 [INFO]:unifi_protect_backup.unifi_protect_backup: Listening for events...
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:        Adding event 63067fc6011a250387000794-62ef94df02daf403870eb6a6 to queue (Current queue=1)
unifi-protect-backup_1  | 2022-08-24 15:45:27 [INFO]:unifi_protect_backup.unifi_protect_backup: Backing up event: 63067fc6011a250387000794-62ef94df02daf403870eb6a6
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:        Remaining Queue: 0
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Camera: Back Garden
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Type: motion
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Start: 2022-08-24T15-45-07 (1661370307.299)
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          End: 2022-08-24T15-45-20 (1661370320.7)
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Duration: 13.401
unifi-protect-backup_1  | 2022-08-24 15:45:27 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Sleeping (2.921207s) to ensure clip is ready to download...
unifi-protect-backup_1  | 2022-08-24 15:45:30 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Downloading video...
unifi-protect-backup_1  | 2022-08-24 15:45:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Downloaded video length: 14.292s(+0.891s)
unifi-protect-backup_1  | 2022-08-24 15:45:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:          Uploading video via rclone...
unifi-protect-backup_1  | 2022-08-24 15:45:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:            To: local:/data/Back Garden/2022-08-24/2022-08-24T15-45-20 motion.mp4
unifi-protect-backup_1  | 2022-08-24 15:45:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:            Size: 15.4MiB
unifi-protect-backup_1  | 2022-08-24 15:45:32 [INFO]:unifi_protect_backup.unifi_protect_backup: Backed up successfully!
jsumners commented 1 year ago

Thanks, I'll give it a go tomorrow (Thursday).

jsumners commented 1 year ago

Looks like you got it figured out 😄 

2022-08-25 04:43:55 [INFO]:unifi_protect_backup.unifi_protect_backup:   Starting...
2022-08-25 04:43:55 [INFO]:unifi_protect_backup.unifi_protect_backup:   Checking rclone configuration...
2022-08-25 04:43:55 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  rclone found: /usr/bin/rclone
2022-08-25 04:43:55 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  ffprobe found: /usr/bin/ffprobe
2022-08-25 04:43:55 [INFO]:unifi_protect_backup.unifi_protect_backup:   Connecting to Unifi Protect...
2022-08-25 04:43:56 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  NVR TZ: America/New_York
2022-08-25 04:43:56 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Local TZ: EDT
2022-08-25 04:43:56 [INFO]:unifi_protect_backup.unifi_protect_backup:   Found cameras:
2022-08-25 04:43:56 [INFO]:unifi_protect_backup.unifi_protect_backup:    - 6304e6f900f75703870003ea: Driveway
2022-08-25 04:43:56 [INFO]:unifi_protect_backup.unifi_protect_backup:   Setting up purge task...
2022-08-25 04:43:56 [INFO]:unifi_protect_backup.unifi_protect_backup:   Listening for events...
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 63076efb00075703870011a5-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-25 04:45:49 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 63076efb00075703870011a5-6304e6f900f75703870003ea
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: motion
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-25T08-45-40 (1661431540.883)
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-25T08-46-03 (1661431563.379)
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 22.496
2022-08-25 04:45:49 [WARNING]:unifi_protect_backup.unifi_protect_backup:          Negative time since event ended, please check timezone of host and NVR match.
2022-08-25 04:45:49 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Sleeping (10.0s) to ensure clip is ready to download...
2022-08-25 04:45:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 63076efa02855703870011a4-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-25 04:45:59 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Downloading video...
2022-08-25 04:46:00 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Downloaded video length: 22.958s(+0.462s)
2022-08-25 04:46:00 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Uploading video via rclone...

Thank you for investigating this. It's ridiculous that the community has to add these obviously necessary features. But I like the way you did it; choosing rclone gives us a wide selection of destinations.

ep1cman commented 1 year ago

That's very interesting, yours throws the new warning I added and then corrects the negative time since event despite both our setups showing the same timezones in the log. There is something different in your setup to mine that is causing that negative calculation to occur that isn't for me.

I've cured the symptom but not the cause sadly.

jsumners commented 1 year ago

I have kept the TZ=America/New_York in the container's environment.

ep1cman commented 1 year ago

Out of curiosity a) what version of unifi protect do you have and b) what are you running this container on? x86 or arm?

jsumners commented 1 year ago

Protect = 2.1.1 Docker host is x86_64

processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 94
model name      : Intel(R) Core(TM) i5-6500T CPU @ 2.50GHz
ep1cman commented 1 year ago

Hmmm our setup is almost identical in that case, I'm struggling to think of ways our setup could differ at this point. What host OS are you using? I'm running UnraidOS

jsumners commented 1 year ago

Host OS is Void Linux.

ep1cman commented 1 year ago

That's a new one for me. I might setup a VM and check it out.

Dumb question but the time is set correctly on your host OS right?

Somehow one of the two systems is not returning the correct time. I might produce a dev build later today that logs a lot more info about the time stamps to try figure out which one is wrong for you.

jsumners commented 1 year ago

If I'm not mistaken, this could be the difference:

2022-08-25 05:04:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  NVR TZ: America/New_York
2022-08-25 05:04:32 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Local TZ: EDT

EDT = Eastern Daylight Time EDT = -4 UTC

EST = Eastern Standard Time EST = -5 UTC

Both are America/New_York. The one being used is determined by tzinfo.

This is what I would do: https://runkit.com/embed/r34oy1vat957

const luxon = require("luxon")

const clipTime = luxon.DateTime.fromJSDate(new Date('2022-08-25T09:00:00.000-04:00'))
const nowTime = luxon.DateTime.fromJSDate(new Date('2022-08-25T09:01:00.000-04:00'))

const seconds = nowTime.setZone('UTC').toUnixInteger() - clipTime.setZone('UTC').toUnixInteger()

console.log(seconds) // 60
ep1cman commented 1 year ago

Yeah I think I'll rework the code so the timezone conversion only happens for the printed messages but isn't used in any calculations. If you look at my log it also shows the same slightly different timezones as you but doesn't raise the warnings. Very odd. I'll produce a couple of containers for you to try later today once I'm off work

ep1cman commented 1 year ago

When you get a moment I would appreciate a log dump from running date followed by the latest :dev container. I added some extra logging to try figure out the source of wrong date. In theory all dates are UTC and are just being shifted to the NVR timezone. Since they all undergo the same shift there shouldn't be an issue with timezones not matching.

jsumners commented 1 year ago

Well I'm embarrassed. The clock on the system was way off. All I can say is that it's a brand new system that I'm still setting up and I just didn't even recognize that the clock is drifting so badly (or just wasn't being set correctly). I've added chrony to the host system and now things are looking fantastic on the current dev image (c406cc1b8a3a):

2022-08-30 05:10:08 [INFO]:unifi_protect_backup.unifi_protect_backup:   Listening for events...
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Adding event 630e0ee10053570387003015-6304e6f900f75703870003ea to queue (Current queue=1)
2022-08-30 09:21:50 [INFO]:unifi_protect_backup.unifi_protect_backup:   Backing up event: 630e0ee10053570387003015-6304e6f900f75703870003ea
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  Remaining Queue: 0
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Camera: Driveway
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Type: smartDetectZone (person)
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Start: 2022-08-30T09-21-30 (1661865690.774)
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    End: 2022-08-30T09-21-49 (1661865709.709)
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Duration: 18.935
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:  now=datetime.datetime(2022, 8, 30, 9, 21, 50, 58644, tzinfo=<DstTzInfo 'America/New_York' EDT-1 da
y, 20:00:00 DST>), event.start=datetime.datetime(2022, 8, 30, 9, 21, 30, 774000, tzinfo=<DstTzInfo 'America/New_York' EDT-1 day, 20:00:00 DST>), event.end=datetime.dateti
me(2022, 8, 30, 9, 21, 49, 709000, tzinfo=<DstTzInfo 'America/New_York' EDT-1 day, 20:00:00 DST>)
2022-08-30 09:21:50 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Sleeping (9.650356s) to ensure clip is ready to download...
2022-08-30 09:21:59 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Downloading video...
2022-08-30 09:22:00 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Downloaded video length: 23.667s(+4.732s)
2022-08-30 09:22:00 [DEBUG]:unifi_protect_backup.unifi_protect_backup:    Uploading video via rclone...

Note: you can see where I got chrony running in that log. The time shifts from 05:10:08 to 09:21:50.

I vote for shipping it.

ep1cman commented 1 year ago

An awesome, that solves that mystery! I’ll close this issue and update the main branch today with some extra docs and the additional checks/debug we added here.