search

ep1cman / unifi-protect-backup

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

Failed uploads don't get retried #106

Closed kitleyn closed 8 months ago

kitleyn commented 8 months ago

Description

Backup is configured to run from a CloudKey Gen2+ to Backblaze B2. Backup has been working since deployment a couple of weeks ago, including the initial seed of historic events, but over the last week or so I have seen an increasing number of events giving errors which result in a failed upload to Backblaze. These missed events get written to the UPB DB and therefore don't get re-attempted in the regular 'missing event' task. Some events upload without issue. The pertinent error seems to 'no tomes available (503 service_unavailable)' and this is referenced in an article from Backblaze with the suggestion to retry the upload again. I assume that this is built into the rclone functionality, and perhaps not something that UPB is even in control of, but then I noticed that the rclone version (v1.58.1-DEV) included in the docker image is from 2022 (as mentioned in #105) so an upgrade to this would be great in case it is something that has been fixed in a later version. That aside, the issue I am reporting here is that the event entry gets written to the events.sqlite db file despite the upload failing. From looking at the sqlite structure, it doesn't appear to contain any status value so I assume that the event id being present in the DB leads the system to believe it was successfully uploaded to the remote.

The logs show the following

2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.event_listener        :  Adding event 653fad6200d50003e4014893 to queue (Current download queue=1)
2023-10-30 13:19:48 [   INFO    ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]  Downloading event: 653fad6200d50003e4014893
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]  Remaining Download Queue: 0
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]  Video Download Buffer: 0.0B/512.0MiB
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Camera: Front Door
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Type: smartDetectZone (vehicle)
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Start: 2023-10-30T13-19-26 (1698671966.763)
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    End: 2023-10-30T13-19-38 (1698671978.992)
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Duration: 12.229s
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Downloading video...
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Downloaded video size: 2.2MiBs
2023-10-30 13:19: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": "50040000/1111889",
                "time_base": "1/90000",
                "start_pts": 0,
                "start_time": "0.000000",
                "duration_ts": 1111889,
                "duration": "12.354322",
                "bit_rate": "1421576",
                "nb_frames": "556",
                "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-10-30T13:19:48.000000Z",
                    "language": "und",
                    "handler_name": "Video track",
                    "vendor_id": "[0][0][0][0]"
                }
            }
        ]
    }
2023-10-30 13:19:48 [EXTRA_DEBUG] unifi_protect_backup.utils                 :  stderr:

2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]    Downloaded video length: 12.354s(+0.125s)
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.downloader            : [653fad6200d50003e4014893]  Added to upload queue
2023-10-30 13:19:48 [   INFO    ] unifi_protect_backup.uploader              : [653fad6200d50003e4014893]  Uploading event: 653fad6200d50003e4014893
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.uploader              : [653fad6200d50003e4014893]   Remaining Upload Queue: 0 (0.0B)
2023-10-30 13:19:48 [   DEBUG   ] unifi_protect_backup.uploader              : [653fad6200d50003e4014893]   Destination: backblaze:/unifi-protect/Front Door/2023-10-30/2023-10-30T13-19-38 smartDetectZone (vehicle).mp4
2023-10-30 13:19:49 [   ERROR   ] unifi_protect_backup.utils                 :  Failed to run: 'rclone rcat -vv  "backblaze:/unifi-protect/Front Door/2023-10-30/2023-10-30T13-19-38 smartDetectZone (vehicle).mp4"
2023-10-30 13:19:49 [   ERROR   ] unifi_protect_backup.utils                 :  stdout:

2023-10-30 13:19:49 [   ERROR   ] unifi_protect_backup.utils                 :  stderr:
    2023/10/30 13:19:48 DEBUG : Setting --config "/config/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/config/rclone/rclone.conf"
    2023/10/30 13:19:48 DEBUG : rclone: Version "v1.58.1-DEV" starting with parameters ["rclone" "rcat" "-vv" "backblaze:/unifi-protect/Front Door/2023-10-30/2023-10-30T13-19-38 smartDetectZone (vehicle).mp4"]
    2023/10/30 13:19:48 DEBUG : Creating backend with remote "backblaze:/unifi-protect/Front Door/2023-10-30/"
    2023/10/30 13:19:48 DEBUG : Using RCLONE_CONFIG_PASS password.
    2023/10/30 13:19:48 DEBUG : Using config file from "/config/rclone/rclone.conf"
    2023/10/30 13:19:49 DEBUG : Couldn't decode error response: EOF
    2023/10/30 13:19:49 DEBUG : fs cache: renaming cache item "backblaze:/unifi-protect/Front Door/2023-10-30/" to be canonical "backblaze:unifi-protect/Front Door/2023-10-30"
    2023/10/30 13:19:49 DEBUG : 2023-10-30T13-19-38 smartDetectZone (vehicle).mp4: File has 2302137 bytes, which makes only one chunk. Using direct upload.
    2023/10/30 13:19:49 DEBUG : 2023-10-30T13-19-38 smartDetectZone (vehicle).mp4: Clearing upload URL because of error: no tomes available (503 service_unavailable)
    2023/10/30 13:19:49 DEBUG : pacer: low level retry 1/1 (error no tomes available (503 service_unavailable))
    2023/10/30 13:19:49 DEBUG : pacer: Rate limited, increasing sleep to 1s
    2023/10/30 13:19:49 ERROR : 2023-10-30T13-19-38 smartDetectZone (vehicle).mp4: Post request rcat error: no tomes available (503 service_unavailable)
    2023/10/30 13:19:49 DEBUG : 10 go routines active
    2023/10/30 13:19:49 Failed to rcat with 2 errors: last error was: no tomes available (503 service_unavailable)
2023-10-30 13:19:49 [   ERROR   ] unifi_protect_backup.uploader              : [653fad6200d50003e4014893]   Failed to upload file: 'backblaze:/unifi-protect/Front Door/2023-10-30/2023-10-30T13-19-38 smartDetectZone (vehicle).mp4'
2023-10-30 13:19:49 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-10-30 13:19:49 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-10-30 13:19:49 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-10-30 13:19:49 [   INFO    ] apprise                                    :  Notifying 1 service(s) asynchronously.
2023-10-30 13:19:49 [   DEBUG   ] unifi_protect_backup.uploader              : [653fad6200d50003e4014893]  Uploaded
2023-10-30 13:19:50 [   INFO    ] apprise                                    :  Sent Pushover notification to ALL_DEVICES.

Many thanks

ep1cman commented 8 months ago

Thanks for providing logs. This isnt the first time I have had reports of events being added to the database but not being backed up. Thankfully this time there are clear logs showing whats happening. I will investigate and get a fix ASAP

ep1cman commented 8 months ago

Issue is now patched, fix will be included in the next release