search

ep1cman / unifi-protect-backup

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

Unique constraint issues again #113

Closed Swallowtail23 closed 7 months ago

Swallowtail23 commented 8 months ago

I haven't updated to the new .10 versions yet, but I'm getting unique constraint issues again:

ERROR: 2023-11-04 09:19:04 [   ERROR   ] unifi_protect_backup.uploader              : [65457fce036fb703e401cc26]  Unexpected exception occurred, abandoning event 65457fce036fb703e401cc26:
Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
    await self._update_database(event, destination)
  File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
    await self._db.execute(
  File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
    cursor = await self._execute(self._conn.execute, sql, parameters)
  File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
    return await future
  File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
    result = function()
sqlite3.IntegrityError: UNIQUE constraint failed: events.id

Unifi Protect Backup version: 0.9.3 Unifi Protect version: UNVR 3.1.16, Protect 2.9.33 Are you using a docker container or native?: Container

Originally posted by @Swallowtail23 in https://github.com/ep1cman/unifi-protect-backup/issues/63#issuecomment-1793395554

ep1cman commented 8 months ago

How often is this occurring? Can you share logs for when this occurred?

Swallowtail23 commented 8 months ago

A lot... 30 or 40 times a day. This is today:

2023-11-05T05:17:40.183556297+10:00 stderr F 2023-11-04 19:17:40 [   INFO    ] unifi_protect_backup.downloader            : [65460c39033db703e4025dcb]  Downloading event: 65460c39033db703e4025dcb
2023-11-05T05:17:40.184967174+10:00 stderr F 2023-11-04 19:17:40 [   INFO    ] unifi_protect_backup.uploader              : [65460c1b0238b703e4025da0]  Uploading event: 65460c1b0238b703e4025da0
2023-11-05T05:17:40.873143926+10:00 stderr F 2023-11-04 19:17:40 [   INFO    ] unifi_protect_backup.downloader            : [65460c39033db703e4025dcb]  Downloading event: 65460c39033db703e4025dcb
2023-11-05T05:17:47.086018471+10:00 stderr F 2023-11-04 19:17:47 [   ERROR   ] unifi_protect_backup.uploader              : [65460c1b0238b703e4025da0]  Unexpected exception occurred, abandoning event 65460c1b0238b703e4025da0:
2023-11-05T05:17:47.086018471+10:00 stderr F Traceback (most recent call last):
2023-11-05T05:17:47.086018471+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T05:17:47.086018471+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T05:17:47.086018471+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T05:17:47.086018471+10:00 stderr F     await self._db.execute(
2023-11-05T05:17:47.086018471+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T05:17:47.086018471+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T05:17:47.086018471+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T05:17:47.086018471+10:00 stderr F     return await future
2023-11-05T05:17:47.086018471+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T05:17:47.086018471+10:00 stderr F     result = function()
2023-11-05T05:17:47.086018471+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T05:17:47.086374065+10:00 stderr F 2023-11-04 19:17:47 [   INFO    ] unifi_protect_backup.uploader              : [65460c39033db703e4025dcb]  Uploading event: 65460c39033db703e4025dcb
2023-11-05T05:18:09.367209465+10:00 stderr F 2023-11-04 19:18:09 [   INFO    ] unifi_protect_backup.downloader            : [65462553032bb703e4027707]  Downloading event: 65462553032bb703e4027707
2023-11-05T05:18:09.368490704+10:00 stderr F 2023-11-04 19:18:09 [   INFO    ] unifi_protect_backup.uploader              : [65460c39033db703e4025dcb]  Uploading event: 65460c39033db703e4025dcb
2023-11-05T05:18:10.041951314+10:00 stderr F 2023-11-04 19:18:10 [   INFO    ] unifi_protect_backup.downloader            : [65462553032bb703e4027707]  Downloading event: 65462553032bb703e4027707
2023-11-05T05:18:16.291160600+10:00 stderr F 2023-11-04 19:18:16 [   ERROR   ] unifi_protect_backup.uploader              : [65460c39033db703e4025dcb]  Unexpected exception occurred, abandoning event 65460c39033db703e4025dcb:
2023-11-05T05:18:16.291160600+10:00 stderr F Traceback (most recent call last):
2023-11-05T05:18:16.291160600+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T05:18:16.291160600+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T05:18:16.291160600+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T05:18:16.291160600+10:00 stderr F     await self._db.execute(
2023-11-05T05:18:16.291160600+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T05:18:16.291160600+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T05:18:16.291160600+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T05:18:16.291160600+10:00 stderr F     return await future
2023-11-05T05:18:16.291160600+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T05:18:16.291160600+10:00 stderr F     result = function()
2023-11-05T05:18:16.291160600+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T05:18:16.291446146+10:00 stderr F 2023-11-04 19:18:16 [   INFO    ] unifi_protect_backup.uploader              : [65462553032bb703e4027707]  Uploading event: 65462553032bb703e4027707
2023-11-05T07:05:11.320966675+10:00 stderr F 2023-11-04 21:05:11 [   INFO    ] unifi_protect_backup.downloader            : [6546264c01d4b703e402782a]  Downloading event: 6546264c01d4b703e402782a
2023-11-05T07:05:11.323148819+10:00 stderr F 2023-11-04 21:05:11 [   INFO    ] unifi_protect_backup.uploader              : [65462553032bb703e4027707]  Uploading event: 65462553032bb703e4027707
2023-11-05T07:05:12.068590424+10:00 stderr F 2023-11-04 21:05:12 [   INFO    ] unifi_protect_backup.downloader            : [6546264c01d4b703e402782a]  Downloading event: 6546264c01d4b703e402782a
2023-11-05T07:05:17.244192871+10:00 stderr F 2023-11-04 21:05:17 [   ERROR   ] unifi_protect_backup.uploader              : [65462553032bb703e4027707]  Unexpected exception occurred, abandoning event 65462553032bb703e4027707:
2023-11-05T07:05:17.244192871+10:00 stderr F Traceback (most recent call last):
2023-11-05T07:05:17.244192871+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T07:05:17.244192871+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T07:05:17.244192871+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T07:05:17.244192871+10:00 stderr F     await self._db.execute(
2023-11-05T07:05:17.244192871+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T07:05:17.244192871+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T07:05:17.244192871+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T07:05:17.244192871+10:00 stderr F     return await future
2023-11-05T07:05:17.244192871+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T07:05:17.244192871+10:00 stderr F     result = function()
2023-11-05T07:05:17.244192871+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T07:05:17.244710003+10:00 stderr F 2023-11-04 21:05:17 [   INFO    ] unifi_protect_backup.uploader              : [6546264c01d4b703e402782a]  Uploading event: 6546264c01d4b703e402782a
2023-11-05T07:09:27.900152354+10:00 stderr F 2023-11-04 21:09:27 [   INFO    ] unifi_protect_backup.downloader            : [6546268c03e3b703e4027872]  Downloading event: 6546268c03e3b703e4027872
2023-11-05T07:09:27.902773481+10:00 stderr F 2023-11-04 21:09:27 [   INFO    ] unifi_protect_backup.uploader              : [6546264c01d4b703e402782a]  Uploading event: 6546264c01d4b703e402782a
2023-11-05T07:09:28.459992193+10:00 stderr F 2023-11-04 21:09:28 [   INFO    ] unifi_protect_backup.downloader            : [6546268c03e3b703e4027872]  Downloading event: 6546268c03e3b703e4027872
2023-11-05T07:09:32.571978897+10:00 stderr F 2023-11-04 21:09:32 [   ERROR   ] unifi_protect_backup.uploader              : [6546264c01d4b703e402782a]  Unexpected exception occurred, abandoning event 6546264c01d4b703e402782a:
2023-11-05T07:09:32.571978897+10:00 stderr F Traceback (most recent call last):
2023-11-05T07:09:32.571978897+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T07:09:32.571978897+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T07:09:32.571978897+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T07:09:32.571978897+10:00 stderr F     await self._db.execute(
2023-11-05T07:09:32.571978897+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T07:09:32.571978897+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T07:09:32.571978897+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T07:09:32.571978897+10:00 stderr F     return await future
2023-11-05T07:09:32.571978897+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T07:09:32.571978897+10:00 stderr F     result = function()
2023-11-05T07:09:32.571978897+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T07:09:32.572327511+10:00 stderr F 2023-11-04 21:09:32 [   INFO    ] unifi_protect_backup.uploader              : [6546268c03e3b703e4027872]  Uploading event: 6546268c03e3b703e4027872
2023-11-05T07:10:30.726944201+10:00 stderr F 2023-11-04 21:10:30 [   INFO    ] unifi_protect_backup.downloader            : [654627930034b703e4027989]  Downloading event: 654627930034b703e4027989
2023-11-05T07:10:30.729361922+10:00 stderr F 2023-11-04 21:10:30 [   INFO    ] unifi_protect_backup.uploader              : [6546268c03e3b703e4027872]  Uploading event: 6546268c03e3b703e4027872
2023-11-05T07:10:31.540999584+10:00 stderr F 2023-11-04 21:10:31 [   INFO    ] unifi_protect_backup.downloader            : [654627930034b703e4027989]  Downloading event: 654627930034b703e4027989
2023-11-05T07:10:35.585279505+10:00 stderr F 2023-11-04 21:10:35 [   ERROR   ] unifi_protect_backup.uploader              : [6546268c03e3b703e4027872]  Unexpected exception occurred, abandoning event 6546268c03e3b703e4027872:
2023-11-05T07:10:35.585279505+10:00 stderr F Traceback (most recent call last):
2023-11-05T07:10:35.585279505+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T07:10:35.585279505+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T07:10:35.585279505+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T07:10:35.585279505+10:00 stderr F     await self._db.execute(
2023-11-05T07:10:35.585279505+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T07:10:35.585279505+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T07:10:35.585279505+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T07:10:35.585279505+10:00 stderr F     return await future
2023-11-05T07:10:35.585279505+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T07:10:35.585279505+10:00 stderr F     result = function()
2023-11-05T07:10:35.585279505+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T07:10:35.585505881+10:00 stderr F 2023-11-04 21:10:35 [   INFO    ] unifi_protect_backup.uploader              : [654627930034b703e4027989]  Uploading event: 654627930034b703e4027989
2023-11-05T07:14:55.001988642+10:00 stderr F 2023-11-04 21:14:55 [   INFO    ] unifi_protect_backup.downloader            : [654627c60372b703e40279ce]  Downloading event: 654627c60372b703e40279ce
2023-11-05T07:14:55.004328724+10:00 stderr F 2023-11-04 21:14:55 [   INFO    ] unifi_protect_backup.uploader              : [654627930034b703e4027989]  Uploading event: 654627930034b703e4027989
2023-11-05T07:14:56.142793894+10:00 stderr F 2023-11-04 21:14:56 [   INFO    ] unifi_protect_backup.downloader            : [654627c60372b703e40279ce]  Downloading event: 654627c60372b703e40279ce
2023-11-05T07:14:59.607334971+10:00 stderr F 2023-11-04 21:14:59 [   ERROR   ] unifi_protect_backup.uploader              : [654627930034b703e4027989]  Unexpected exception occurred, abandoning event 654627930034b703e4027989:
2023-11-05T07:14:59.607334971+10:00 stderr F Traceback (most recent call last):
2023-11-05T07:14:59.607334971+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T07:14:59.607334971+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T07:14:59.607334971+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T07:14:59.607334971+10:00 stderr F     await self._db.execute(
2023-11-05T07:14:59.607334971+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T07:14:59.607334971+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T07:14:59.607334971+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T07:14:59.607334971+10:00 stderr F     return await future
2023-11-05T07:14:59.607334971+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T07:14:59.607334971+10:00 stderr F     result = function()
2023-11-05T07:14:59.607334971+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T07:14:59.607642286+10:00 stderr F 2023-11-04 21:14:59 [   INFO    ] unifi_protect_backup.uploader              : [654627c60372b703e40279ce]  Uploading event: 654627c60372b703e40279ce
2023-11-05T07:16:16.135818136+10:00 stderr F 2023-11-04 21:16:16 [   INFO    ] unifi_protect_backup.downloader            : [654694d80228b703e402e961]  Downloading event: 654694d80228b703e402e961
2023-11-05T07:16:16.139672902+10:00 stderr F 2023-11-04 21:16:16 [   INFO    ] unifi_protect_backup.uploader              : [654627c60372b703e40279ce]  Uploading event: 654627c60372b703e40279ce
2023-11-05T07:16:16.719474175+10:00 stderr F 2023-11-04 21:16:16 [   INFO    ] unifi_protect_backup.downloader            : [654694d80228b703e402e961]  Downloading event: 654694d80228b703e402e961
2023-11-05T07:16:22.322118841+10:00 stderr F 2023-11-04 21:16:22 [   ERROR   ] unifi_protect_backup.uploader              : [654627c60372b703e40279ce]  Unexpected exception occurred, abandoning event 654627c60372b703e40279ce:
2023-11-05T07:16:22.322118841+10:00 stderr F Traceback (most recent call last):
2023-11-05T07:16:22.322118841+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 78, in start
2023-11-05T07:16:22.322118841+10:00 stderr F     await self._update_database(event, destination)
2023-11-05T07:16:22.322118841+10:00 stderr F   File "/usr/lib/python3.10/site-packages/unifi_protect_backup/uploader.py", line 108, in _update_database
2023-11-05T07:16:22.322118841+10:00 stderr F     await self._db.execute(
2023-11-05T07:16:22.322118841+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-05T07:16:22.322118841+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-05T07:16:22.322118841+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-05T07:16:22.322118841+10:00 stderr F     return await future
2023-11-05T07:16:22.322118841+10:00 stderr F   File "/usr/lib/python3.10/site-packages/aiosqlite/core.py", line 102, in run
2023-11-05T07:16:22.322118841+10:00 stderr F     result = function()
2023-11-05T07:16:22.322118841+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-05T07:16:22.322374497+10:00 stderr F 2023-11-04 21:16:22 [   INFO    ] unifi_protect_backup.uploader              : [654694d80228b703e402e961]  Uploading event: 654694d80228b703e402e961
2023-11-05T08:43:10.875772473+10:00 stderr F 2023-11-04 22:43:10 [   INFO    ] unifi_protect_backup.purge                 :  Purging event: 64582bb2018f6903e4011dc7.
2023-11-05T08:43:16.697922848+10:00 stderr F 2023-11-04 22:43:16 [   INFO    ] unifi_protect_backup.purge                 :  Purging event: 6458974101086903e40127cc.
2023-11-05T08:43:22.199541398+10:00 stderr F 2023-11-04 22:43:22 [   INFO    ] unifi_protect_backup.purge                 :  Purging event: 6458981d01336903e40127dc.
2023-11-05T08:43:26.825601593+10:00 stderr F 2023-11-04 22:43:26 [   INFO    ] unifi_protect_backup.purge                 :  Purging event: 6458b39a02666903e401293c.
Swallowtail23 commented 8 months ago

I have a suspicion...

UI updated Protect to 2.9.33 Official release a couple of days ago. It's now been pulled back to EA due to issues... :(

https://community.ui.com/releases/UniFi-Protect-Application-2-9-33/1c1949d2-0c84-49f0-a880-14335d44878e

They seem to have changed a few things - what's the betting that is related...

I'm waiting to see what they do to resolve it, as I'm not keen to manually force a downgrade back to 2.8.35 (and they are recommending not to)

ep1cman commented 8 months ago

Wouldn't be the first buggy release that made it through EA. I had one totally killed my UDM and forced me to factory reset.

In theory this situation should be impossible unless UniFi protect is sending out the same ID multiple times. Can you run this with verbosity set to -vv to find out where these duplicate events come from, are they being added by the missed event checker or by the websocket listener?

I'd also be curious to know if they are the same length etc, but we might need to add some extra logging to debug this. I want to be sure these events with the same ID are identical before I add code to ignore this error

Swallowtail23 commented 8 months ago

I've coincidentally had a data corruption issue on my KVM host and had to spend 1 day rebuilding it. It also hosted the UPB container, so I've started from scratch... The new server is RHEL 9.2, and I had no end of fun setting up the container. I had to setup in user space as a rootless container, which added some learning for me. Got there in the end though, I'll document it at some point. I've nuked the DB and I'm resyncing the full 20 days that the UNVR has onboard, no errors so far after a few hours, so I'll monitor this and let you know.

Swallowtail23 commented 7 months ago

OK, after it's been up and running for a day.

Firstly it's missing some events completely.

For example, using one camera as an example: "Patio Camera" had People events noted in NVR console at:

Yet in my Onedrive folder for that camera I see:

This is the entire log from 10:49pm last night to now at 9.39am:

2023-11-06T22:49:35.690129277+10:00 stderr F 2023-11-06 12:49:35 [   INFO    ] unifi_protect_backup.uploader              : [6548a6b102f40f03e401c9df]  Uploading event: 6548a6b102f40f03e401c9df
2023-11-06T22:49:43.586437800+10:00 stderr F 2023-11-06 12:49:43 [   INFO    ] unifi_protect_backup.uploader              : [6548e08e038f0f03e4020646]  Uploading event: 6548e08e038f0f03e4020646
2023-11-07T08:49:05.527665501+10:00 stderr F 2023-11-06 22:49:05 [   INFO    ] unifi_protect_backup.downloader            : [6548e1d203d20f03e40207a3]  Downloading event: 6548e1d203d20f03e40207a3
2023-11-07T08:49:05.528002986+10:00 stderr F 2023-11-06 22:49:05 [   INFO    ] unifi_protect_backup.uploader              : [6548e08e038f0f03e4020646]  Uploading event: 6548e08e038f0f03e4020646
2023-11-07T08:49:06.541215143+10:00 stderr F 2023-11-06 22:49:06 [   INFO    ] unifi_protect_backup.downloader            : [6548e1d203d20f03e40207a3]  Downloading event: 6548e1d203d20f03e40207a3
2023-11-07T08:49:15.829511937+10:00 stderr F 2023-11-06 22:49:15 [   ERROR   ] unifi_protect_backup.uploader              : [6548e08e038f0f03e4020646]  Unexpected exception occurred, abandoning event 6548e08e038f0f03e4020646:
2023-11-07T08:49:15.829511937+10:00 stderr F Traceback (most recent call last):
2023-11-07T08:49:15.829511937+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
2023-11-07T08:49:15.829511937+10:00 stderr F     await self._update_database(event, destination)
2023-11-07T08:49:15.829511937+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
2023-11-07T08:49:15.829511937+10:00 stderr F     await self._db.execute(
2023-11-07T08:49:15.829511937+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-07T08:49:15.829511937+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-07T08:49:15.829511937+10:00 stderr F              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-07T08:49:15.829511937+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-07T08:49:15.829511937+10:00 stderr F     return await future
2023-11-07T08:49:15.829511937+10:00 stderr F            ^^^^^^^^^^^^
2023-11-07T08:49:15.829511937+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
2023-11-07T08:49:15.829511937+10:00 stderr F     result = function()
2023-11-07T08:49:15.829511937+10:00 stderr F              ^^^^^^^^^^
2023-11-07T08:49:15.829511937+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-07T08:49:15.830092787+10:00 stderr F 2023-11-06 22:49:15 [   INFO    ] unifi_protect_backup.uploader              : [6548e1d203d20f03e40207a3]  Uploading event: 6548e1d203d20f03e40207a3
2023-11-07T08:54:11.848708868+10:00 stderr F 2023-11-06 22:54:11 [   INFO    ] unifi_protect_backup.downloader            : [6548e1ec038b0f03e40207cd]  Downloading event: 6548e1ec038b0f03e40207cd
2023-11-07T08:54:11.850276882+10:00 stderr F 2023-11-06 22:54:11 [   INFO    ] unifi_protect_backup.uploader              : [6548e1d203d20f03e40207a3]  Uploading event: 6548e1d203d20f03e40207a3
2023-11-07T08:54:12.749376758+10:00 stderr F 2023-11-06 22:54:12 [   INFO    ] unifi_protect_backup.downloader            : [6548e1ec038b0f03e40207cd]  Downloading event: 6548e1ec038b0f03e40207cd
2023-11-07T08:54:17.618361318+10:00 stderr F 2023-11-06 22:54:17 [   ERROR   ] unifi_protect_backup.uploader              : [6548e1d203d20f03e40207a3]  Unexpected exception occurred, abandoning event 6548e1d203d20f03e40207a3:
2023-11-07T08:54:17.618361318+10:00 stderr F Traceback (most recent call last):
2023-11-07T08:54:17.618361318+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
2023-11-07T08:54:17.618361318+10:00 stderr F     await self._update_database(event, destination)
2023-11-07T08:54:17.618361318+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
2023-11-07T08:54:17.618361318+10:00 stderr F     await self._db.execute(
2023-11-07T08:54:17.618361318+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-07T08:54:17.618361318+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-07T08:54:17.618361318+10:00 stderr F              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-07T08:54:17.618361318+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-07T08:54:17.618361318+10:00 stderr F     return await future
2023-11-07T08:54:17.618361318+10:00 stderr F            ^^^^^^^^^^^^
2023-11-07T08:54:17.618361318+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
2023-11-07T08:54:17.618361318+10:00 stderr F     result = function()
2023-11-07T08:54:17.618361318+10:00 stderr F              ^^^^^^^^^^
2023-11-07T08:54:17.618361318+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-07T08:54:17.618505076+10:00 stderr F 2023-11-06 22:54:17 [   INFO    ] unifi_protect_backup.uploader              : [6548e1ec038b0f03e40207cd]  Uploading event: 6548e1ec038b0f03e40207cd
2023-11-07T08:54:39.677069914+10:00 stderr F 2023-11-06 22:54:39 [   INFO    ] unifi_protect_backup.downloader            : [654934d0006b0f03e4025b65]  Downloading event: 654934d0006b0f03e4025b65
2023-11-07T08:54:39.678747196+10:00 stderr F 2023-11-06 22:54:39 [   INFO    ] unifi_protect_backup.uploader              : [6548e1ec038b0f03e40207cd]  Uploading event: 6548e1ec038b0f03e40207cd
2023-11-07T08:54:39.989720215+10:00 stderr F 2023-11-06 22:54:39 [   INFO    ] unifi_protect_backup.downloader            : [654934d0006b0f03e4025b65]  Downloading event: 654934d0006b0f03e4025b65
2023-11-07T08:54:44.397980855+10:00 stderr F 2023-11-06 22:54:44 [   ERROR   ] unifi_protect_backup.uploader              : [6548e1ec038b0f03e40207cd]  Unexpected exception occurred, abandoning event 6548e1ec038b0f03e40207cd:
2023-11-07T08:54:44.397980855+10:00 stderr F Traceback (most recent call last):
2023-11-07T08:54:44.397980855+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
2023-11-07T08:54:44.397980855+10:00 stderr F     await self._update_database(event, destination)
2023-11-07T08:54:44.397980855+10:00 stderr F   File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
2023-11-07T08:54:44.397980855+10:00 stderr F     await self._db.execute(
2023-11-07T08:54:44.397980855+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
2023-11-07T08:54:44.397980855+10:00 stderr F     cursor = await self._execute(self._conn.execute, sql, parameters)
2023-11-07T08:54:44.397980855+10:00 stderr F              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-07T08:54:44.397980855+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
2023-11-07T08:54:44.397980855+10:00 stderr F     return await future
2023-11-07T08:54:44.397980855+10:00 stderr F            ^^^^^^^^^^^^
2023-11-07T08:54:44.397980855+10:00 stderr F   File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
2023-11-07T08:54:44.397980855+10:00 stderr F     result = function()
2023-11-07T08:54:44.397980855+10:00 stderr F              ^^^^^^^^^^
2023-11-07T08:54:44.397980855+10:00 stderr F sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-07T08:54:44.398113813+10:00 stderr F 2023-11-06 22:54:44 [   INFO    ] unifi_protect_backup.uploader              : [654934d0006b0f03e4025b65]  Uploading event: 654934d0006b0f03e4025b65

The database was last updated at 8:54am today, in line with the last log message.

Then I restarted the container.

New log:

2023-11-07T09:42:13.043703128+10:00 stdout F
2023-11-07T09:42:13.043703128+10:00 stdout F User UID:    911
2023-11-07T09:42:13.043703128+10:00 stdout F User GID:    911
2023-11-07T09:42:13.043703128+10:00 stdout F ───────────────────────────────────────
2023-11-07T09:42:13.043703128+10:00 stdout F
2023-11-07T09:42:13.057749711+10:00 stdout F [custom-init] No custom files found, skipping...
2023-11-07T09:42:13.063259579+10:00 stdout F [ls.io-init] done.
2023-11-07T09:42:13.063783270+10:00 stdout F
2023-11-07T09:42:13.537192827+10:00 stderr F 2023-11-06 23:42:13 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting...
2023-11-07T09:42:14.516084922+10:00 stderr F 2023-11-06 23:42:14 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Checking rclone configuration...
2023-11-07T09:42:15.446824817+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Connecting to Unifi Protect...
2023-11-07T09:42:15.939510901+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Found cameras:
2023-11-07T09:42:15.939569970+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 63ca52ad03962a03e4001983: Study Camera
2023-11-07T09:42:15.939625919+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 638c28e50378bf03e401a5c1: Cattery Camera
2023-11-07T09:42:15.939677968+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 638be21d01f4bf03e4014287: Kitchen Camera
2023-11-07T09:42:15.939744117+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 636e06e900cfa003e7000406: Front Camera
2023-11-07T09:42:15.939794086+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 63ca3f3902c52a03e40015d5: Pool Camera
2023-11-07T09:42:15.939841625+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 636e06e900e6a003e7000407: Patio Camera
2023-11-07T09:42:15.939887204+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 63ca489903202a03e4001787: Shed Camera
2023-11-07T09:42:15.939933193+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 636e06e9009ba003e7000404: Front Doorbell
2023-11-07T09:42:15.939978143+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 636e06e900b8a003e7000405: Garage Camera
2023-11-07T09:42:15.940022532+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :   - 638a8e6603547a03e407b19f: Side Camera
2023-11-07T09:42:15.941218952+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.unifi_protect_backup_core :  Starting Tasks...
2023-11-07T09:42:15.941341680+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.downloader            :  Starting Downloader
2023-11-07T09:42:15.941393289+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.uploader              :  Starting Uploader
2023-11-07T09:42:15.941512747+10:00 stderr F 2023-11-06 23:42:15 [   INFO    ] unifi_protect_backup.missing_event_checker :  Starting Missing Event Checker
2023-11-07T09:42:21.534782099+10:00 stderr F 2023-11-06 23:42:21 [  WARNING  ] unifi_protect_backup.missing_event_checker :   Found missing events, adding to backup queue
2023-11-07T09:42:21.535628245+10:00 stderr F 2023-11-06 23:42:21 [   INFO    ] unifi_protect_backup.downloader            : [6549693502760f03e40291ca]  Downloading event: 6549693502760f03e40291ca
2023-11-07T09:42:22.028484135+10:00 stderr F 2023-11-06 23:42:22 [   INFO    ] unifi_protect_backup.downloader            : [65495170010e0f03e4027916]  Downloading event: 65495170010e0f03e4027916
2023-11-07T09:42:22.029100065+10:00 stderr F 2023-11-06 23:42:22 [   INFO    ] unifi_protect_backup.uploader              : [6549693502760f03e40291ca]  Uploading event: 6549693502760f03e40291ca
2023-11-07T09:42:22.330012763+10:00 stderr F 2023-11-06 23:42:22 [   INFO    ] unifi_protect_backup.downloader            : [6549495300c20f03e402708c]  Downloading event: 6549495300c20f03e402708c
2023-11-07T09:42:23.056427835+10:00 stderr F 2023-11-06 23:42:23 [   INFO    ] unifi_protect_backup.downloader            : [65495a9400720f03e402829a]  Downloading event: 65495a9400720f03e402829a
2023-11-07T09:42:23.428604405+10:00 stderr F 2023-11-06 23:42:23 [   INFO    ] unifi_protect_backup.downloader            : [654948ae037e0f03e4026fcc]  Downloading event: 654948ae037e0f03e4026fcc
2023-11-07T09:42:24.378119014+10:00 stderr F 2023-11-06 23:42:24 [   INFO    ] unifi_protect_backup.downloader            : [6549561d037a0f03e4027df0]  Downloading event: 6549561d037a0f03e4027df0
2023-11-07T09:42:25.058789996+10:00 stderr F 2023-11-06 23:42:25 [   INFO    ] unifi_protect_backup.downloader            : [6549513f00370f03e40278ca]  Downloading event: 6549513f00370f03e40278ca
2023-11-07T09:42:26.063243131+10:00 stderr F 2023-11-06 23:42:26 [   INFO    ] unifi_protect_backup.downloader            : [65495fd902540f03e4028809]  Downloading event: 65495fd902540f03e4028809
2023-11-07T09:42:26.537737360+10:00 stderr F 2023-11-06 23:42:26 [   INFO    ] unifi_protect_backup.downloader            : [65495e6e03800f03e402869e]  Downloading event: 65495e6e03800f03e402869e
2023-11-07T09:42:27.026989791+10:00 stderr F 2023-11-06 23:42:27 [   INFO    ] unifi_protect_backup.downloader            : [654955d301390f03e4027d96]  Downloading event: 654955d301390f03e4027d96
2023-11-07T09:42:28.709942034+10:00 stderr F 2023-11-06 23:42:28 [   INFO    ] unifi_protect_backup.uploader              : [65495170010e0f03e4027916]  Uploading event: 65495170010e0f03e4027916
2023-11-07T09:42:28.896408447+10:00 stderr F 2023-11-06 23:42:28 [   INFO    ] unifi_protect_backup.downloader            : [6549494f03b70f03e402708b]  Downloading event: 6549494f03b70f03e402708b
2023-11-07T09:42:29.195601805+10:00 stderr F 2023-11-06 23:42:29 [   INFO    ] unifi_protect_backup.downloader            : [654955cc01f00f03e4027d8b]  Downloading event: 654955cc01f00f03e4027d8b
2023-11-07T09:42:29.725723519+10:00 stderr F 2023-11-06 23:42:29 [   INFO    ] unifi_protect_backup.downloader            : [6549699e02760f03e4029248]  Downloading event: 6549699e02760f03e4029248
2023-11-07T09:42:30.264308540+10:00 stderr F 2023-11-06 23:42:30 [   INFO    ] unifi_protect_backup.downloader            : [6549699503600f03e4029246]  Downloading event: 6549699503600f03e4029246
2023-11-07T09:42:30.798731941+10:00 stderr F 2023-11-06 23:42:30 [   INFO    ] unifi_protect_backup.downloader            : [654969a103d30f03e4029254]  Downloading event: 654969a103d30f03e4029254
2023-11-07T09:42:30.901284596+10:00 stderr F 2023-11-06 23:42:30 [   INFO    ] unifi_protect_backup.downloader            : [654948bf01180f03e4026fda]  Downloading event: 654948bf01180f03e4026fda
2023-11-07T09:42:31.648063195+10:00 stderr F 2023-11-06 23:42:31 [   INFO    ] unifi_protect_backup.downloader            : [654972e600b00f03e4029c3a]  Downloading event: 654972e600b00f03e4029c3a
2023-11-07T09:42:32.756682108+10:00 stderr F 2023-11-06 23:42:32 [   INFO    ] unifi_protect_backup.uploader              : [6549495300c20f03e402708c]  Uploading event: 6549495300c20f03e402708c
2023-11-07T09:42:33.874084844+10:00 stderr F 2023-11-06 23:42:33 [   INFO    ] unifi_protect_backup.downloader            : [6549697200be0f03e4029212]  Downloading event: 6549697200be0f03e4029212
2023-11-07T09:42:34.262179456+10:00 stderr F 2023-11-06 23:42:34 [   INFO    ] unifi_protect_backup.downloader            : [6549513a02280f03e40278be]  Downloading event: 6549513a02280f03e40278be
2023-11-07T09:42:34.593681140+10:00 stderr F 2023-11-06 23:42:34 [   INFO    ] unifi_protect_backup.downloader            : [65497325023e0f03e4029c81]  Downloading event: 65497325023e0f03e4029c81
2023-11-07T09:42:41.197356417+10:00 stderr F 2023-11-06 23:42:41 [   INFO    ] unifi_protect_backup.uploader              : [65495a9400720f03e402829a]  Uploading event: 65495a9400720f03e402829a
2023-11-07T09:42:47.330225523+10:00 stderr F 2023-11-06 23:42:47 [   INFO    ] unifi_protect_backup.uploader              : [654948ae037e0f03e4026fcc]  Uploading event: 654948ae037e0f03e4026fcc
2023-11-07T09:42:55.577672833+10:00 stderr F 2023-11-06 23:42:55 [   INFO    ] unifi_protect_backup.uploader              : [6549561d037a0f03e4027df0]  Uploading event: 6549561d037a0f03e4027df0
2023-11-07T09:43:02.684765842+10:00 stderr F 2023-11-06 23:43:02 [   INFO    ] unifi_protect_backup.uploader              : [6549513f00370f03e40278ca]  Uploading event: 6549513f00370f03e40278ca
2023-11-07T09:43:10.445304281+10:00 stderr F 2023-11-06 23:43:10 [   INFO    ] unifi_protect_backup.uploader              : [65495fd902540f03e4028809]  Uploading event: 65495fd902540f03e4028809
2023-11-07T09:43:16.196729513+10:00 stderr F 2023-11-06 23:43:16 [   INFO    ] unifi_protect_backup.uploader              : [65495e6e03800f03e402869e]  Uploading event: 65495e6e03800f03e402869e
2023-11-07T09:43:22.629819830+10:00 stderr F 2023-11-06 23:43:22 [   INFO    ] unifi_protect_backup.uploader              : [654955d301390f03e4027d96]  Uploading event: 654955d301390f03e4027d96
2023-11-07T09:43:43.985167776+10:00 stderr F 2023-11-06 23:43:43 [   INFO    ] unifi_protect_backup.uploader              : [6549494f03b70f03e402708b]  Uploading event: 6549494f03b70f03e402708b
2023-11-07T09:43:49.370149381+10:00 stderr F 2023-11-06 23:43:49 [   INFO    ] unifi_protect_backup.uploader              : [654955cc01f00f03e4027d8b]  Uploading event: 654955cc01f00f03e4027d8b
2023-11-07T09:43:53.862414842+10:00 stderr F 2023-11-06 23:43:53 [   INFO    ] unifi_protect_backup.downloader            : [65497a2a03a90f03e402a3e9]  Downloading event: 65497a2a03a90f03e402a3e9
2023-11-07T09:43:55.294200740+10:00 stderr F 2023-11-06 23:43:55 [   INFO    ] unifi_protect_backup.uploader              : [6549699e02760f03e4029248]  Uploading event: 6549699e02760f03e4029248
2023-11-07T09:44:02.142332145+10:00 stderr F 2023-11-06 23:44:02 [   INFO    ] unifi_protect_backup.downloader            : [65497a2a03a90f03e402a3e9]  Downloading event: 65497a2a03a90f03e402a3e9
2023-11-07T09:44:04.079210447+10:00 stderr F 2023-11-06 23:44:04 [   INFO    ] unifi_protect_backup.uploader              : [6549699503600f03e4029246]  Uploading event: 6549699503600f03e4029246
2023-11-07T09:44:10.613958313+10:00 stderr F 2023-11-06 23:44:10 [   INFO    ] unifi_protect_backup.uploader              : [654969a103d30f03e4029254]  Uploading event: 654969a103d30f03e4029254
2023-11-07T09:44:13.735214894+10:00 stderr F 2023-11-06 23:44:13 [   INFO    ] unifi_protect_backup.uploader              : [654948bf01180f03e4026fda]  Uploading event: 654948bf01180f03e4026fda
2023-11-07T09:44:21.290396497+10:00 stderr F 2023-11-06 23:44:21 [   INFO    ] unifi_protect_backup.uploader              : [654972e600b00f03e4029c3a]  Uploading event: 654972e600b00f03e4029c3a

...andd now it picks up the missing events, with no errors so far.

Swallowtail23 commented 7 months ago

Running in interactive mode with vvvv...

An event just triggered, and the timestamp is incorrect:

2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Downloading video...
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Downloaded video size: 12.8MiBs
2023-11-07 00:15:17 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:
        {
            "streams": [
                {
                    "index": 1,
                    "codec_name": "h264",
                    "codec_long_name": "H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10",
                    "codec_type": "video",
                    "codec_tag_string": "avc1",
                    "codec_tag": "0x31637661",
                    "width": 3840,
                    "height": 2160,
                    "coded_width": 3840,
                    "coded_height": 2160,
                    "closed_captions": 0,
                    "film_grain": 0,
                    "has_b_frames": 0,
                    "level": -99,
                    "refs": 1,
                    "is_avc": "true",
                    "nal_length_size": "4",
                    "id": "0x2",
                    "r_frame_rate": "24/1",
                    "avg_frame_rate": "24/1",
                    "time_base": "1/90000",
                    "start_pts": 0,
                    "start_time": "0.000000",
                    "duration_ts": 1811250,
                    "duration": "20.125000",
                    "bit_rate": "5289135",
                    "nb_frames": "483",
                    "extradata_size": 44,
                    "disposition": {
                        "default": 1,
                        "dub": 0,
                        "original": 0,
                        "comment": 0,
                        "lyrics": 0,
                        "karaoke": 0,
                        "forced": 0,
                        "hearing_impaired": 0,
                        "visual_impaired": 0,
                        "clean_effects": 0,
                        "attached_pic": 0,
                        "timed_thumbnails": 0,
                        "captions": 0,
                        "descriptions": 0,
                        "metadata": 0,
                        "dependent": 0,
                        "still_image": 0
                    },
                    "tags": {
                        "creation_time": "2023-11-07T00:15:17.000000Z",
                        "language": "und",
                        "handler_name": "Video track",
                        "vendor_id": "[0][0][0][0]"
                    }
                }
            ]
        }
2023-11-07 00:15:17 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Downloaded video length: 20.125s(+4.162s)
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]  Added to upload queue
2023-11-07 00:15:17 [   INFO    ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]  Downloading event: 6549818002100f03e402ab99
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]  Remaining Download Queue: 0
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]  Video Download Buffer: 12.8MiB/1.5GiB
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Camera: Patio Camera
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Type: smartDetectZone (person)
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Start: 2023-11-07T20-14-53 (1699352093.676)
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    End: 2023-11-07T20-15-09 (1699352109.639)
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Duration: 15.963s
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.downloader            : [6549818002100f03e402ab99]    Sleeping (35999.411559s) to ensure clip is ready to download...
2023-11-07 00:15:17 [   INFO    ] unifi_protect_backup.uploader              : [6549818002100f03e402ab99]  Uploading event: 6549818002100f03e402ab99
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.uploader              : [6549818002100f03e402ab99]   Remaining Upload Queue: 0 (0.0B)
2023-11-07 00:15:17 [   DEBUG   ] unifi_protect_backup.uploader              : [6549818002100f03e402ab99]   Destination: Onedrive:/Unifi-Protect-Backup/Patio Camera/2023-11-07/2023-11-07T20-15-09 smartDetectZone (person).mp4

Creation date is 2023-11-07T00:15:17.000000Z but it's been tagged into OneDrive as "2023-11-07T20-15-09"

Swallowtail23 commented 7 months ago

If you want me to document the rootless container let me know, in case you think that is contributing. Also I can Discord chat if that's easier

Swallowtail23 commented 7 months ago

Still in vvvv interactive mode.

Tested by going outside and triggering lots of people events.

UPB picked them all up, and ended up here:

2023-11-07 00:32:33 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 6549858601e60f03e402b012 to queue (Current download queue=14)
2023-11-07 00:32:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-07 00:32:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-07 00:33:28 [   DEBUG   ] unifi_protect_backup.missing_event_checker :  Running check for missing events...
2023-11-07 00:33:28 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-05-11 00:33:28.039758 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:28 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-19 10:46:52.352000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:29 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-22 03:26:47.367000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:29 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-23 21:21:05.426000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:29 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-25 04:27:45.049000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:30 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-26 22:00:16.141000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:30 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-28 04:18:37.585000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:31 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-29 06:39:10.001000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:31 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-31 02:04:33.517000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:32 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-01 07:53:36.903000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:33 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-03 04:59:59.829000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:33 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-05 12:28:47.074000+00:00 - 2023-11-07 00:33:28.039798
2023-11-07 00:33:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-07 00:33:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-07 00:34:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-07 00:34:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-07 00:35:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-07 00:35:59 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.

So we now have a download queue of 14 events, but it appears that none of them are actually getting actioned

Swallowtail23 commented 7 months ago

...and a restart of the container triggers that download queue into action and it clears, uploading events (all correctly timestamped)

ep1cman commented 7 months ago

Ok so about the event name being wrong on your cloud storage, thats because its using the end time of the event not the start time, I should fix that.

I am going to need to see a log in maximum verbosity to get a understanding on whats happening here. It seems like they have changed the way the web socket messages behave and what I was using to mark the end of an event is now occuring multiple times, hence multiple events with the same ID.

The reason the missing event checker works is because it uses a different mechanism, rather than watching websocket messages in realtime to track events, it queries unifi protect for all events available in the retention window and check those against what it already has. This clearly returns well formed events but the websocket isn't anymore.

The API the event checker uses is very expensive and heavy on the unifi host machine. In the past it was totally killing setups with many cameras so I am reluctant to move to a purely polling based system using that API.

Once you can send me a dump of the websocket messages from logs at maximum verbosity and I can try and decypher what is going in, but I would also like to wait till a new stable release is out to make sure this isnt a bug on their behalf.

Swallowtail23 commented 7 months ago

OK, I'll run it at vvvv and capture a log for you.

Here's one just captured apparently at 7.40am on the 8th Nov (it's currently 9.51pm on 7th Nov): image

Interestingly, I've not seen ANY unique constraint issues in 12 hours of restarting it every 15 minutes.

kitleyn commented 7 months ago

Hopefully the below logs help identify the cause

2023-11-20 13:13:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:13:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:14:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:14:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:14:27 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.ADD: 'add'>, new_update_id=UUID('76fe2f09-9a52-45c5-aa4c-4599152184d6'), changed_data={'model': <ModelType.EVENT: 'event'>, 'id': '655b5bb301e72303e40021bb', 'type': <EventType.SMART_DETECT: 'smartDetectZone'>, 'start': datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=datetime.timezone.utc), 'end': None, 'score': 60, 'heatmap_id': None, 'camera_id': '63a5fb560081b803e40003ef', 'smart_detect_types': [<SmartDetectObjectType.VEHICLE: 'vehicle'>], 'smart_detect_event_ids': [], 'thumbnail_id': None, 'user_id': None, 'timestamp': None, 'metadata': {'client_platform': None, 'reason': None, 'app_update': None, 'light_id': None, 'light_name': None, 'type': None, 'sensor_id': None, 'sensor_name': None, 'sensor_type': None, 'doorlock_id': None, 'doorlock_name': None, 'from_value': None, 'to_value': None, 'mount_type': None, 'status': None, 'alarm_type': None, 'device_id': None, 'mac': None, 'license_plate': None}, 'deleted_at': None, 'deletion_type': None}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5bb301e72303e40021bb', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=datetime.timezone.utc), end=None, score=60, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=None)
2023-11-20 13:14:42 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.UPDATE: 'update'>, new_update_id=UUID('539351d2-f3b3-4f2e-9b53-8571a8c7ab8b'), changed_data={'end': datetime.datetime(2023, 11, 20, 13, 14, 40, 766000, tzinfo=datetime.timezone.utc), 'score': 76}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5bb301e72303e40021bb', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=datetime.timezone.utc), end=datetime.datetime(2023, 11, 20, 13, 14, 40, 766000, tzinfo=datetime.timezone.utc), score=76, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5bb301e72303e40021bb', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=datetime.timezone.utc), end=None, score=60, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None))
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 655b5bb301e72303e40021bb to queue (Current download queue=1)
2023-11-20 13:14:42 [   INFO    ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Downloading event: 655b5bb301e72303e40021bb
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Remaining Download Queue: 0
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Video Download Buffer: 0.0B/512.0MiB
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Camera: Front Door
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Type: smartDetectZone (vehicle)
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Start: 2023-11-20T13-14-23 (1700486063.974)
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    End: 2023-11-20T13-14-40 (1700486080.766)
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Duration: 16.792s
2023-11-20 13:14:42 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Sleeping (5.952861s) to ensure clip is ready to download...
2023-11-20 13:14:43 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.UPDATE: 'update'>, new_update_id=UUID('b7b6c80f-c61c-4772-bd72-eb0345f980d3'), changed_data={'smart_detect_types': [<SmartDetectObjectType.VEHICLE: 'vehicle'>], 'metadata': {}}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5bb301e72303e40021bb', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), end=datetime.datetime(2023, 11, 20, 13, 14, 40, 766000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), score=76, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5bb301e72303e40021bb', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 14, 23, 974000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), end=datetime.datetime(2023, 11, 20, 13, 14, 40, 766000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), score=76, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None))
2023-11-20 13:14:43 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 655b5bb301e72303e40021bb to queue (Current download queue=1)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloading video...
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloaded video size: 5.3MiBs
2023-11-20 13:14:48 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:
    {
        "streams": [
            {
                "index": 1,
                "codec_name": "h264",
                "codec_long_name": "H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10",
                "codec_type": "video",
                "codec_tag_string": "avc1",
                "codec_tag": "0x31637661",
                "width": 1600,
                "height": 1200,
                "coded_width": 1600,
                "coded_height": 1200,
                "closed_captions": 0,
                "film_grain": 0,
                "has_b_frames": 0,
                "level": -99,
                "refs": 1,
                "is_avc": "true",
                "nal_length_size": "4",
                "id": "0x2",
                "r_frame_rate": "45/1",
                "avg_frame_rate": "71640000/1591841",
                "time_base": "1/90000",
                "start_pts": 0,
                "start_time": "0.000000",
                "duration_ts": 1591841,
                "duration": "17.687122",
                "bit_rate": "2437926",
                "nb_frames": "796",
                "extradata_size": 45,
                "disposition": {
                    "default": 1,
                    "dub": 0,
                    "original": 0,
                    "comment": 0,
                    "lyrics": 0,
                    "karaoke": 0,
                    "forced": 0,
                    "hearing_impaired": 0,
                    "visual_impaired": 0,
                    "clean_effects": 0,
                    "attached_pic": 0,
                    "timed_thumbnails": 0,
                    "captions": 0,
                    "descriptions": 0,
                    "metadata": 0,
                    "dependent": 0,
                    "still_image": 0
                },
                "tags": {
                    "creation_time": "2023-11-20T13:14:48.000000Z",
                    "language": "und",
                    "handler_name": "Video track",
                    "vendor_id": "[0][0][0][0]"
                }
            }
        ]
    }
2023-11-20 13:14:48 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloaded video length: 17.687s(+0.895s)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Added to upload queue
2023-11-20 13:14:48 [   INFO    ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Downloading event: 655b5bb301e72303e40021bb
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Remaining Download Queue: 0
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Video Download Buffer: 5.3MiB/512.0MiB
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Camera: Front Door
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Type: smartDetectZone (vehicle)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Start: 2023-11-20T13-14-23 (1700486063.974)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    End: 2023-11-20T13-14-40 (1700486080.766)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Duration: 16.792s
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloading video...
2023-11-20 13:14:48 [   INFO    ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]  Uploading event: 655b5bb301e72303e40021bb
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]   Remaining Upload Queue: 0 (0.0B)
2023-11-20 13:14:48 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]   Destination: backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-14-40 smartDetectZone (vehicle).mp4
2023-11-20 13:14:49 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloaded video size: 5.3MiBs
2023-11-20 13:14:49 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:
    {
        "streams": [
            {
                "index": 1,
                "codec_name": "h264",
                "codec_long_name": "H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10",
                "codec_type": "video",
                "codec_tag_string": "avc1",
                "codec_tag": "0x31637661",
                "width": 1600,
                "height": 1200,
                "coded_width": 1600,
                "coded_height": 1200,
                "closed_captions": 0,
                "film_grain": 0,
                "has_b_frames": 0,
                "level": -99,
                "refs": 1,
                "is_avc": "true",
                "nal_length_size": "4",
                "id": "0x2",
                "r_frame_rate": "45/1",
                "avg_frame_rate": "71640000/1591841",
                "time_base": "1/90000",
                "start_pts": 0,
                "start_time": "0.000000",
                "duration_ts": 1591841,
                "duration": "17.687122",
                "bit_rate": "2437926",
                "nb_frames": "796",
                "extradata_size": 45,
                "disposition": {
                    "default": 1,
                    "dub": 0,
                    "original": 0,
                    "comment": 0,
                    "lyrics": 0,
                    "karaoke": 0,
                    "forced": 0,
                    "hearing_impaired": 0,
                    "visual_impaired": 0,
                    "clean_effects": 0,
                    "attached_pic": 0,
                    "timed_thumbnails": 0,
                    "captions": 0,
                    "descriptions": 0,
                    "metadata": 0,
                    "dependent": 0,
                    "still_image": 0
                },
                "tags": {
                    "creation_time": "2023-11-20T13:14:49.000000Z",
                    "language": "und",
                    "handler_name": "Video track",
                    "vendor_id": "[0][0][0][0]"
                }
            }
        ]
    }
2023-11-20 13:14:49 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-11-20 13:14:49 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]    Downloaded video length: 17.687s(+0.895s)
2023-11-20 13:14:49 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5bb301e72303e40021bb]  Added to upload queue
2023-11-20 13:14:54 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:

2023-11-20 13:14:54 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:
    2023/11/20 13:14:49 DEBUG : Setting --config "/config/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/config/rclone/rclone.conf"
    2023/11/20 13:14:49 DEBUG : rclone: Version "v1.64.2-DEV" starting with parameters ["rclone" "rcat" "-vv" "backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-14-40 smartDetectZone (vehicle).mp4"]
    2023/11/20 13:14:49 DEBUG : Creating backend with remote "backblaze:/unifi-protect/Front Door/2023-11-20/"
    2023/11/20 13:14:49 DEBUG : Using RCLONE_CONFIG_PASS password.
    2023/11/20 13:14:49 DEBUG : Using config file from "/config/rclone/rclone.conf"
    2023/11/20 13:14:50 DEBUG : Couldn't decode error response: EOF
    2023/11/20 13:14:50 DEBUG : fs cache: renaming cache item "backblaze:/unifi-protect/Front Door/2023-11-20/" to be canonical "backblaze:unifi-protect/Front Door/2023-11-20"
    2023/11/20 13:14:50 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: File has 5543838 bytes, which makes only one chunk. Using direct upload.
    2023/11/20 13:14:54 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: sha1 = 804962c9e704d1a6c2f9d6089aa36a268ebb4789 OK
    2023/11/20 13:14:54 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: Size and sha1 of src and dst objects identical
    2023/11/20 13:14:54 DEBUG : 14 go routines active
2023-11-20 13:14:58 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]  Uploaded
2023-11-20 13:14:58 [   INFO    ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]  Uploading event: 655b5bb301e72303e40021bb
2023-11-20 13:14:58 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]   Remaining Upload Queue: 0 (0.0B)
2023-11-20 13:14:58 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]   Destination: backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-14-40 smartDetectZone (vehicle).mp4
2023-11-20 13:15:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:15:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:15:05 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:

2023-11-20 13:15:05 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:
    2023/11/20 13:14:59 DEBUG : Setting --config "/config/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/config/rclone/rclone.conf"
    2023/11/20 13:14:59 DEBUG : rclone: Version "v1.64.2-DEV" starting with parameters ["rclone" "rcat" "-vv" "backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-14-40 smartDetectZone (vehicle).mp4"]
    2023/11/20 13:14:59 DEBUG : Creating backend with remote "backblaze:/unifi-protect/Front Door/2023-11-20/"
    2023/11/20 13:14:59 DEBUG : Using RCLONE_CONFIG_PASS password.
    2023/11/20 13:14:59 DEBUG : Using config file from "/config/rclone/rclone.conf"
    2023/11/20 13:15:00 DEBUG : Couldn't decode error response: EOF
    2023/11/20 13:15:00 DEBUG : fs cache: renaming cache item "backblaze:/unifi-protect/Front Door/2023-11-20/" to be canonical "backblaze:unifi-protect/Front Door/2023-11-20"
    2023/11/20 13:15:00 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: File has 5543838 bytes, which makes only one chunk. Using direct upload.
    2023/11/20 13:15:05 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: sha1 = e6a7e1602035eaa71cb66cfa65aeac4a75890591 OK
    2023/11/20 13:15:05 DEBUG : 2023-11-20T13-14-40 smartDetectZone (vehicle).mp4: Size and sha1 of src and dst objects identical
    2023/11/20 13:15:05 DEBUG : 10 go routines active
2023-11-20 13:15:05 [   ERROR   ] unifi_protect_backup.uploader              : [655b5bb301e72303e40021bb]  Unexpected exception occurred, abandoning event 655b5bb301e72303e40021bb:
Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
    await self._update_database(event, destination)
  File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
    await self._db.execute(
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
    cursor = await self._execute(self._conn.execute, sql, parameters)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
    return await future
           ^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
    result = function()
             ^^^^^^^^^^
sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-20 13:15:05 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-11-20 13:15:05 [   INFO    ] apprise                                    :  Sent Pushover notification to ALL_DEVICES.
2023-11-20 13:16:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:16:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:17:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:17:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:17:27 [   DEBUG   ] unifi_protect_backup.missing_event_checker :  Running check for missing events...
2023-11-20 13:17:27 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-21 13:17:27.580536 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:28 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-12 13:23:12.253000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:29 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-12 20:49:55.236000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:30 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-13 16:09:44.199000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:30 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-14 00:02:53.369000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:31 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-14 16:42:22.657000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:32 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-15 11:22:25.713000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:33 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-16 08:20:50.422000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:34 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-16 20:56:45.128000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:34 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-17 15:30:31.008000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:35 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-18 09:16:25.378000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:17:36 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-19 13:42:56.549000+00:00 - 2023-11-20 13:17:27.580651
2023-11-20 13:18:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:18:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:19:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:19:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:19:52 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.ADD: 'add'>, new_update_id=UUID('8e920663-60c5-4e3c-9181-c8f795120481'), changed_data={'model': <ModelType.EVENT: 'event'>, 'id': '655b5cf802bc2303e4002207', 'type': <EventType.SMART_DETECT: 'smartDetectZone'>, 'start': datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=datetime.timezone.utc), 'end': None, 'score': 68, 'heatmap_id': None, 'camera_id': '63a5fb560081b803e40003ef', 'smart_detect_types': [<SmartDetectObjectType.VEHICLE: 'vehicle'>], 'smart_detect_event_ids': [], 'thumbnail_id': None, 'user_id': None, 'timestamp': None, 'metadata': {'client_platform': None, 'reason': None, 'app_update': None, 'light_id': None, 'light_name': None, 'type': None, 'sensor_id': None, 'sensor_name': None, 'sensor_type': None, 'doorlock_id': None, 'doorlock_name': None, 'from_value': None, 'to_value': None, 'mount_type': None, 'status': None, 'alarm_type': None, 'device_id': None, 'mac': None, 'license_plate': None}, 'deleted_at': None, 'deletion_type': None}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5cf802bc2303e4002207', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=datetime.timezone.utc), end=None, score=68, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=None)
2023-11-20 13:20:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:20:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:20:05 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.UPDATE: 'update'>, new_update_id=UUID('9763dcca-a112-4f51-a3cd-cd4ad1b49b73'), changed_data={'end': datetime.datetime(2023, 11, 20, 13, 20, 3, 516000, tzinfo=datetime.timezone.utc), 'score': 73}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5cf802bc2303e4002207', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=datetime.timezone.utc), end=datetime.datetime(2023, 11, 20, 13, 20, 3, 516000, tzinfo=datetime.timezone.utc), score=73, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5cf802bc2303e4002207', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=datetime.timezone.utc), end=None, score=68, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None))
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 655b5cf802bc2303e4002207 to queue (Current download queue=1)
2023-11-20 13:20:05 [   INFO    ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Downloading event: 655b5cf802bc2303e4002207
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Remaining Download Queue: 0
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Video Download Buffer: 0.0B/512.0MiB
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Camera: Front Door
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Type: smartDetectZone (vehicle)
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Start: 2023-11-20T13-19-49 (1700486389.29)
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    End: 2023-11-20T13-20-03 (1700486403.516)
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Duration: 14.226s
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Sleeping (5.879303s) to ensure clip is ready to download...
2023-11-20 13:20:05 [WEBSOCKET_DATA] unifi_protect_backup.event_listener        :  WSSubscriptionMessage(action=<WSAction.UPDATE: 'update'>, new_update_id=UUID('4175e999-388f-4076-b5df-2b55136c852a'), changed_data={'smart_detect_types': [<SmartDetectObjectType.VEHICLE: 'vehicle'>], 'metadata': {}}, new_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5cf802bc2303e4002207', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), end=datetime.datetime(2023, 11, 20, 13, 20, 3, 516000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), score=73, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None), old_obj=Event(model=<ModelType.EVENT: 'event'>, id='655b5cf802bc2303e4002207', type=<EventType.SMART_DETECT: 'smartDetectZone'>, start=datetime.datetime(2023, 11, 20, 13, 19, 49, 290000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), end=datetime.datetime(2023, 11, 20, 13, 20, 3, 516000, tzinfo=zoneinfo.ZoneInfo(key='Europe/London')), score=73, heatmap_id=None, camera_id='63a5fb560081b803e40003ef', smart_detect_types=[<SmartDetectObjectType.VEHICLE: 'vehicle'>], smart_detect_event_ids=[], thumbnail_id=None, user_id=None, timestamp=None, metadata=EventMetadata(client_platform=None, reason=None, app_update=None, light_id=None, light_name=None, type=None, sensor_id=None, sensor_name=None, sensor_type=None, doorlock_id=None, doorlock_name=None, from_value=None, to_value=None, mount_type=None, status=None, alarm_type=None, device_id=None, mac=None, license_plate=None), deleted_at=None, deletion_type=None))
2023-11-20 13:20:05 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 655b5cf802bc2303e4002207 to queue (Current download queue=1)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloading video...
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloaded video size: 3.1MiBs
2023-11-20 13:20:11 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:
    {
        "streams": [
            {
                "index": 1,
                "codec_name": "h264",
                "codec_long_name": "H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10",
                "codec_type": "video",
                "codec_tag_string": "avc1",
                "codec_tag": "0x31637661",
                "width": 1600,
                "height": 1200,
                "coded_width": 1600,
                "coded_height": 1200,
                "closed_captions": 0,
                "film_grain": 0,
                "has_b_frames": 0,
                "level": -99,
                "refs": 1,
                "is_avc": "true",
                "nal_length_size": "4",
                "id": "0x2",
                "r_frame_rate": "45/1",
                "avg_frame_rate": "63540000/1411859",
                "time_base": "1/90000",
                "start_pts": 0,
                "start_time": "0.000000",
                "duration_ts": 1411859,
                "duration": "15.687322",
                "bit_rate": "1572949",
                "nb_frames": "706",
                "extradata_size": 45,
                "disposition": {
                    "default": 1,
                    "dub": 0,
                    "original": 0,
                    "comment": 0,
                    "lyrics": 0,
                    "karaoke": 0,
                    "forced": 0,
                    "hearing_impaired": 0,
                    "visual_impaired": 0,
                    "clean_effects": 0,
                    "attached_pic": 0,
                    "timed_thumbnails": 0,
                    "captions": 0,
                    "descriptions": 0,
                    "metadata": 0,
                    "dependent": 0,
                    "still_image": 0
                },
                "tags": {
                    "creation_time": "2023-11-20T13:20:11.000000Z",
                    "language": "und",
                    "handler_name": "Video track",
                    "vendor_id": "[0][0][0][0]"
                }
            }
        ]
    }
2023-11-20 13:20:11 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloaded video length: 15.687s(+1.461s)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Added to upload queue
2023-11-20 13:20:11 [   INFO    ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Downloading event: 655b5cf802bc2303e4002207
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Remaining Download Queue: 0
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Video Download Buffer: 3.1MiB/512.0MiB
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Camera: Front Door
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Type: smartDetectZone (vehicle)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Start: 2023-11-20T13-19-49 (1700486389.29)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    End: 2023-11-20T13-20-03 (1700486403.516)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Duration: 14.226s
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloading video...
2023-11-20 13:20:11 [   INFO    ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]  Uploading event: 655b5cf802bc2303e4002207
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]   Remaining Upload Queue: 0 (0.0B)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]   Destination: backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-20-03 smartDetectZone (vehicle).mp4
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloaded video size: 3.1MiBs
2023-11-20 13:20:11 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:
    {
        "streams": [
            {
                "index": 1,
                "codec_name": "h264",
                "codec_long_name": "H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10",
                "codec_type": "video",
                "codec_tag_string": "avc1",
                "codec_tag": "0x31637661",
                "width": 1600,
                "height": 1200,
                "coded_width": 1600,
                "coded_height": 1200,
                "closed_captions": 0,
                "film_grain": 0,
                "has_b_frames": 0,
                "level": -99,
                "refs": 1,
                "is_avc": "true",
                "nal_length_size": "4",
                "id": "0x2",
                "r_frame_rate": "45/1",
                "avg_frame_rate": "63540000/1411859",
                "time_base": "1/90000",
                "start_pts": 0,
                "start_time": "0.000000",
                "duration_ts": 1411859,
                "duration": "15.687322",
                "bit_rate": "1572949",
                "nb_frames": "706",
                "extradata_size": 45,
                "disposition": {
                    "default": 1,
                    "dub": 0,
                    "original": 0,
                    "comment": 0,
                    "lyrics": 0,
                    "karaoke": 0,
                    "forced": 0,
                    "hearing_impaired": 0,
                    "visual_impaired": 0,
                    "clean_effects": 0,
                    "attached_pic": 0,
                    "timed_thumbnails": 0,
                    "captions": 0,
                    "descriptions": 0,
                    "metadata": 0,
                    "dependent": 0,
                    "still_image": 0
                },
                "tags": {
                    "creation_time": "2023-11-20T13:20:11.000000Z",
                    "language": "und",
                    "handler_name": "Video track",
                    "vendor_id": "[0][0][0][0]"
                }
            }
        ]
    }
2023-11-20 13:20:11 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]    Downloaded video length: 15.687s(+1.461s)
2023-11-20 13:20:11 [   DEBUG   ] unifi_protect_backup.downloader            : [655b5cf802bc2303e4002207]  Added to upload queue
2023-11-20 13:20:16 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:

2023-11-20 13:20:16 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:
    2023/11/20 13:20:11 DEBUG : Setting --config "/config/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/config/rclone/rclone.conf"
    2023/11/20 13:20:11 DEBUG : rclone: Version "v1.64.2-DEV" starting with parameters ["rclone" "rcat" "-vv" "backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-20-03 smartDetectZone (vehicle).mp4"]
    2023/11/20 13:20:11 DEBUG : Creating backend with remote "backblaze:/unifi-protect/Front Door/2023-11-20/"
    2023/11/20 13:20:11 DEBUG : Using RCLONE_CONFIG_PASS password.
    2023/11/20 13:20:11 DEBUG : Using config file from "/config/rclone/rclone.conf"
    2023/11/20 13:20:12 DEBUG : Couldn't decode error response: EOF
    2023/11/20 13:20:12 DEBUG : fs cache: renaming cache item "backblaze:/unifi-protect/Front Door/2023-11-20/" to be canonical "backblaze:unifi-protect/Front Door/2023-11-20"
    2023/11/20 13:20:12 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: File has 3220175 bytes, which makes only one chunk. Using direct upload.
    2023/11/20 13:20:16 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: sha1 = 712c3f6f652379e7db2a78363f05bbe3ea3fbe3d OK
    2023/11/20 13:20:16 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: Size and sha1 of src and dst objects identical
    2023/11/20 13:20:16 DEBUG : 14 go routines active
2023-11-20 13:20:20 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]  Uploaded
2023-11-20 13:20:20 [   INFO    ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]  Uploading event: 655b5cf802bc2303e4002207
2023-11-20 13:20:20 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]   Remaining Upload Queue: 0 (0.0B)
2023-11-20 13:20:20 [   DEBUG   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]   Destination: backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-20-03 smartDetectZone (vehicle).mp4
2023-11-20 13:20:22 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stdout:

2023-11-20 13:20:22 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:
    2023/11/20 13:20:20 DEBUG : Setting --config "/config/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/config/rclone/rclone.conf"
    2023/11/20 13:20:20 DEBUG : rclone: Version "v1.64.2-DEV" starting with parameters ["rclone" "rcat" "-vv" "backblaze:/unifi-protect/Front Door/2023-11-20/2023-11-20T13-20-03 smartDetectZone (vehicle).mp4"]
    2023/11/20 13:20:20 DEBUG : Creating backend with remote "backblaze:/unifi-protect/Front Door/2023-11-20/"
    2023/11/20 13:20:20 DEBUG : Using RCLONE_CONFIG_PASS password.
    2023/11/20 13:20:20 DEBUG : Using config file from "/config/rclone/rclone.conf"
    2023/11/20 13:20:21 DEBUG : Couldn't decode error response: EOF
    2023/11/20 13:20:21 DEBUG : fs cache: renaming cache item "backblaze:/unifi-protect/Front Door/2023-11-20/" to be canonical "backblaze:unifi-protect/Front Door/2023-11-20"
    2023/11/20 13:20:21 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: File has 3220175 bytes, which makes only one chunk. Using direct upload.
    2023/11/20 13:20:22 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: sha1 = 712c3f6f652379e7db2a78363f05bbe3ea3fbe3d OK
    2023/11/20 13:20:22 DEBUG : 2023-11-20T13-20-03 smartDetectZone (vehicle).mp4: Size and sha1 of src and dst objects identical
    2023/11/20 13:20:22 DEBUG : 14 go routines active
2023-11-20 13:20:22 [   ERROR   ] unifi_protect_backup.uploader              : [655b5cf802bc2303e4002207]  Unexpected exception occurred, abandoning event 655b5cf802bc2303e4002207:
Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
    await self._update_database(event, destination)
  File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
    await self._db.execute(
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
    cursor = await self._execute(self._conn.execute, sql, parameters)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
    return await future
           ^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
    result = function()
             ^^^^^^^^^^
sqlite3.IntegrityError: UNIQUE constraint failed: events.id
2023-11-20 13:20:22 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-11-20 13:20:23 [   INFO    ] apprise                                    :  Sent Pushover notification to ALL_DEVICES.
2023-11-20 13:21:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:21:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:22:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:22:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:22:37 [   DEBUG   ] unifi_protect_backup.missing_event_checker :  Running check for missing events...
2023-11-20 13:22:37 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-10-21 13:22:37.328345 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:38 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-12 13:23:12.253000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:39 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-12 20:49:55.236000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:40 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-13 16:09:44.199000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:41 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-14 00:02:53.369000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:42 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-14 16:42:22.657000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:42 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-15 11:22:25.713000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:43 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-16 08:20:50.422000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:44 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-16 20:56:45.128000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:45 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-17 15:30:31.008000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:46 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-18 09:16:25.378000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:22:47 [EXTRA_DEBUG] unifi_protect_backup.missing_event_checker :  Fetching events for interval: 2023-11-19 13:42:56.549000+00:00 - 2023-11-20 13:22:37.328532
2023-11-20 13:23:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:23:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
2023-11-20 13:24:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Checking the status of the websocket...
2023-11-20 13:24:01 [EXTRA_DEBUG] unifi_protect_backup.event_listener        :  Websocket is connected.
wssweb commented 7 months ago

I am seeing this as well.

Unifi Protect Backup version: latest (running in docker container) Unifi Protect version: UDM SE v3.1.16, Protect 2.9.42

2023-11-20 17:20:49 [ ERROR ] unifi_protect_backup.uploader : [655b954901922303e400263d] Unexpected exception occurred, abandoning event 6 55b954901922303e400263d:
Traceback (most recent call last):
File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 86, in start
await self._update_database(event, destination)
File "/usr/lib/python3.11/site-packages/unifi_protect_backup/uploader.py", line 118, in _update_database
await self._db.execute(
File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 184, in execute
cursor = await self._execute(self._conn.execute, sql, parameters)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 129, in _execute
return await future
^^^^^^^^^^^^
File "/usr/lib/python3.11/site-packages/aiosqlite/core.py", line 102, in run
result = function()
^^^^^^^^^^
sqlite3.IntegrityError: UNIQUE constraint failed: events.id

this started after the unifi protect updated at 3am this morning. It caused the backup to start uploading videos with events containing detections that were never detected.

ep1cman commented 7 months ago

Looks like unifi have dropped a new stable release 2.9.42, which seems to persist whatever changes they made to the websocket protocol.

Thank you @kitleyn for sharing logs including websocket data so I can see what is happening

I will investigate soon and try to resolve this.

ep1cman commented 7 months ago

Looking at @kitleyn's log I can see that unifi is now updating events after setting and end time. In their particular case it comes along after the end of the event and marks it as a vehicle detection.

The logic currently checks if the new event has an end time and if it does it will add it to the download queue. Previously only the last message sent would have this so it worked fine. Now that messages are being sent after this logic is breaking and adding events multiple times.

The fix to this particular issue is quite simple, rather than cheking the new_obj field for an end_time, I can check the change_data field for the end time, this should only ever happen once (unless unifi protect changes the event durations!)

However we now another problem: When an event ends we can no longer assume all the detection types are finalised, as they might be added later. This will be less than trivial to track.

Swallowtail23 commented 7 months ago

Thanks all, I've been unfortunately focused on other things and had not been able to drop logs in. To get around the other noted issue of downloads hanging I've been restarting the container every 15 mins, which keeps the queue up to date OK. It also stopped completely any unique constraint errors. As noted here though, I have been getting some very odd end times and some random "detections", but as they are all getting backed up I've let it run. I'm also now on v..42 as noted.

ep1cman commented 7 months ago

Hi folks,

There is a new release now processing that should address this duplicate ID issue, so I am going to mark this issue as closed. If you still encounter this issue then please comment back and I will re-open it.

I am however quite concerned about the instances where the tool has totally missed events in realtime from the websocket data stream and had to rely on the missing event checker to grab them. I have create a new issue to track this #117, please comment there if you find that things are still being missed.