Blue Iris randomly erased 4.7 TB of recordings, what happened?

[elkon]

Today at 2:01 AM EST Blue Iris decided to completely wipe out all recordings that weren't locked. Frustration aside, I would like to figure out why this happened to prevent it from happening again.

Blue Iris config has not been changed for over 6 months, while the last camera change was about 30 days ago. It's been humming along just fine, deleting old recordings as the drive fills up just fine.

My clip/archive settings are as follows:
New: 100GB very fast drive, moves to "Stored" after 1 day or 65GB used.
Stored: 6TB drive, deletes after 3800GB used or 999 days.
Alerts: same 6TB drive, deletes after 300GB / 999 days.
Archive: same 6TB drive, deletes after 1500GB / no day limit.
RAM_Disk: 1GB RAM drive, used for home automation purposes. Deletes after 1GB / 1 hour.

The Blue Iris version is rather old, 5.5.7.1 (5/14/22), but never had any issues with it.

Here's the relevant log entry where it decided to delete everything:

0     6/14/2023 2:01:29.372 AM    Stored                  Delete: 1991 items 3.60T [8462/23976 hrs, 7.47T/3.71T, 895.4G free] 84 locked
0     6/14/2023 2:02:28.657 AM    Archive                 Delete: 7424 items 1.08T [2.55T/1.46T, 4.47T free]

Full log for this time range:

0     6/14/2023 2:00:03.020 AM    Clips                   DBCompact: started
1     6/14/2023 2:00:30.911 AM    Cam6slowdown            Signal: network retry
1     6/14/2023 2:00:33.782 AM    Cam4                    Signal: network retry
1     6/14/2023 2:00:34.230 AM    Cam6                    Signal: network retry
1     6/14/2023 2:00:34.472 AM    Cam4s3                  Signal: network retry
1     6/14/2023 2:00:35.152 AM    Cam6s3                  Signal: network retry
1     6/14/2023 2:00:40.182 AM    Cam5                    Signal: network retry
1     6/14/2023 2:00:40.847 AM    Cam6slowdown            Signal: network retry
1     6/14/2023 2:00:40.976 AM    Cam5s3                  Signal: network retry
1     6/14/2023 2:00:43.888 AM    Cam4                    Signal: network retry
1     6/14/2023 2:00:44.374 AM    Cam6                    Signal: network retry
1     6/14/2023 2:00:44.432 AM    Cam4                    Signal: Failed to connect
1     6/14/2023 2:00:44.619 AM    Cam4s3                  Signal: network retry
1     6/14/2023 2:00:45.096 AM    Cam6                    Signal: Failed to connect
1     6/14/2023 2:00:45.122 AM    Cam6s3                  Signal: network retry
1     6/14/2023 2:00:45.253 AM    Cam4s3                  Signal: Failed to connect
1     6/14/2023 2:00:45.920 AM    Cam6s3                  Signal: Failed to connect
1     6/14/2023 2:00:46.941 AM    Cam4                    Signal: Failed to connect
1     6/14/2023 2:00:47.604 AM    Cam6                    Signal: Failed to connect
1     6/14/2023 2:00:47.968 AM    Cam4s3                  Signal: Failed to connect
1     6/14/2023 2:00:48.630 AM    Cam6s3                  Signal: Failed to connect
1     6/14/2023 2:00:50.201 AM    Cam5                    Signal: network retry
1     6/14/2023 2:00:50.764 AM    Cam5                    Signal: Failed to connect
1     6/14/2023 2:00:51.019 AM    Cam5s3                  Signal: network retry
1     6/14/2023 2:00:51.939 AM    Cam5s3                  Signal: Failed to connect
1     6/14/2023 2:00:53.271 AM    Cam5                    Signal: Failed to connect
1     6/14/2023 2:00:53.923 AM    Cam6slowdown            Signal: Failed to connect
1     6/14/2023 2:00:54.647 AM    Cam5s3                  Signal: Failed to connect
0     6/14/2023 2:00:55.077 AM    Clips                   DBCompact: finished
3     6/14/2023 2:00:55.906 AM    Cam6slowdown            WATCHDOG
1     6/14/2023 2:00:56.107 AM    Cam6slowdown            Signal: network retry
0     6/14/2023 2:00:56.867 AM    Cam6slowdown            Email: Elkon <redacted@example.com> with 0 attachment/s
1     6/14/2023 2:00:57.597 AM    Cam6slowdown            Signal: Failed to connect
3     6/14/2023 2:00:58.912 AM    Cam4                    WATCHDOG
1     6/14/2023 2:00:59.113 AM    Cam4                    Signal: network retry
0     6/14/2023 2:00:59.296 AM    Cam4                    Email: Elkon <redacted@example.com> with 1 attachment/s
3     6/14/2023 2:00:59.397 AM    Cam6                    WATCHDOG
1     6/14/2023 2:00:59.599 AM    Cam6                    Signal: network retry
0     6/14/2023 2:00:59.647 AM    Cam6                    Email: Elkon <redacted@example.com> with 1 attachment/s
3     6/14/2023 2:00:59.822 AM    Cam4s3                  WATCHDOG
1     6/14/2023 2:00:59.823 AM    Cam4s3                  Signal: network retry
0     6/14/2023 2:01:00.090 AM    Cam4s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
1     6/14/2023 2:01:00.306 AM    Cam6slowdown            Signal: Failed to connect
3     6/14/2023 2:01:00.328 AM    Cam6s3                  WATCHDOG
1     6/14/2023 2:01:00.329 AM    Cam6s3                  Signal: network retry
0     6/14/2023 2:01:00.566 AM    Cam6s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
1     6/14/2023 2:01:01.466 AM    Cam2s3                  Signal: network retry
1     6/14/2023 2:01:01.694 AM    Cam2                    Signal: network retry
4     6/14/2023 2:01:02.170 AM    Cam6                    Signal: restored
4     6/14/2023 2:01:02.187 AM    Cam4n                   Signal: restored
4     6/14/2023 2:01:02.193 AM    Cam4                    Signal: restored
4     6/14/2023 2:01:02.364 AM    Cam4s3                  Signal: restored
0     6/14/2023 2:01:02.428 AM    Cam6                    Email: Elkon <redacted@example.com> with 1 attachment/s
0     6/14/2023 2:01:02.597 AM    Cam4                    Email: Elkon <redacted@example.com> with 1 attachment/s
0     6/14/2023 2:01:02.754 AM    Cam4s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:03.056 AM    Cam6s3                  Signal: restored
0     6/14/2023 2:01:03.196 AM    Cam6s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
1     6/14/2023 2:01:04.383 AM    Cam3s3                  Signal: network retry
1     6/14/2023 2:01:04.739 AM    Cam3                    Signal: network retry
3     6/14/2023 2:01:05.207 AM    Cam5                    WATCHDOG
1     6/14/2023 2:01:05.407 AM    Cam5                    Signal: network retry
0     6/14/2023 2:01:05.473 AM    Cam5                    Email: Elkon <redacted@example.com> with 1 attachment/s
1     6/14/2023 2:01:06.167 AM    Cam6slowdown            Signal: network retry
3     6/14/2023 2:01:06.186 AM    Cam5s3                  WATCHDOG
1     6/14/2023 2:01:06.190 AM    Cam5s3                  Signal: network retry
0     6/14/2023 2:01:06.386 AM    Cam5s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:08.134 AM    Cam5n                   Signal: restored
4     6/14/2023 2:01:08.189 AM    Cam5                    Signal: restored
0     6/14/2023 2:01:08.451 AM    Cam5                    Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:08.652 AM    Cam5s3                  Signal: restored
4     6/14/2023 2:01:08.729 AM    Cam6slowdown            Signal: restored
0     6/14/2023 2:01:08.795 AM    Cam5s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
2     6/14/2023 2:01:09.843 AM    Cam4s3                  AddToBIDB failed 1
0     6/14/2023 2:01:09.893 AM    Cam6slowdown            Email: Elkon <redacted@example.com> with 1 attachment/s
2     6/14/2023 2:01:10.030 AM    Cam4                    AddToBIDB failed 1
2     6/14/2023 2:01:10.350 AM    Cam6s3                  AddToBIDB failed 1
2     6/14/2023 2:01:10.595 AM    Cam6                    AddToBIDB failed 1
0     6/14/2023 2:01:10.787 AM    New                     Move: 38 items 55.3G [18/24 hrs, 122.1G/65.0G, 40.5G free] 17 locked
1     6/14/2023 2:01:11.528 AM    Cam2s3                  Signal: network retry
1     6/14/2023 2:01:11.820 AM    Cam2                    Signal: network retry
1     6/14/2023 2:01:12.301 AM    Cam2s3                  Signal: Failed to connect
1     6/14/2023 2:01:12.458 AM    Cam2                    Signal: Failed to connect
1     6/14/2023 2:01:14.214 AM    Cam3s3                  Signal: network retry
1     6/14/2023 2:01:14.810 AM    Cam3                    Signal: network retry
1     6/14/2023 2:01:14.965 AM    Cam2                    Signal: Failed to connect
1     6/14/2023 2:01:15.029 AM    Cam2s3                  Signal: Failed to connect
1     6/14/2023 2:01:15.301 AM    Cam3s3                  Signal: Failed to connect
1     6/14/2023 2:01:15.481 AM    Cam3                    Signal: Failed to connect
1     6/14/2023 2:01:17.989 AM    Cam3                    Signal: Failed to connect
1     6/14/2023 2:01:18.010 AM    Cam3s3                  Signal: Failed to connect
3     6/14/2023 2:01:26.692 AM    Cam2s3                  WATCHDOG
1     6/14/2023 2:01:26.693 AM    Cam2s3                  Signal: network retry
0     6/14/2023 2:01:26.802 AM    Cam2s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
3     6/14/2023 2:01:26.906 AM    Cam2                    WATCHDOG
1     6/14/2023 2:01:27.107 AM    Cam2                    Signal: network retry
0     6/14/2023 2:01:27.156 AM    Cam2                    Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:29.080 AM    Cam2s3                  Signal: restored
0     6/14/2023 2:01:29.313 AM    Cam2s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
0     6/14/2023 2:01:29.372 AM    Stored                  Delete: 1991 items 3.60T [8462/23976 hrs, 7.47T/3.71T, 895.4G free] 84 locked
0     6/14/2023 2:01:29.377 AM    Alerts                  Delete: nothing to do [7357/23976 hrs, 46.8G/300.0G, 4.47T free] 34 locked
0     6/14/2023 2:01:29.708 AM    Cam3s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
1     6/14/2023 2:01:29.768 AM    Cam3s3                  Signal: network retry
3     6/14/2023 2:01:29.778 AM    Cam3s3                  WATCHDOG
3     6/14/2023 2:01:29.808 AM    Cam3                    WATCHDOG
1     6/14/2023 2:01:30.009 AM    Cam3                    Signal: network retry
4     6/14/2023 2:01:30.160 AM    Cam2                    Signal: restored
0     6/14/2023 2:01:30.234 AM    Cam3                    Email: Elkon <redacted@example.com> with 1 attachment/s
0     6/14/2023 2:01:30.421 AM    Cam2                    Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:32.501 AM    Cam3s3                  Signal: restored
0     6/14/2023 2:01:32.623 AM    Cam3s3                  Email: Elkon <redacted@example.com> with 1 attachment/s
4     6/14/2023 2:01:34.156 AM    Cam3                    Signal: restored
0     6/14/2023 2:01:34.412 AM    Cam3                    Email: Elkon <redacted@example.com> with 1 attachment/s
3     6/14/2023 2:01:37.706 AM    Cam1n                   MOTION_ABCG
0     6/14/2023 2:02:28.657 AM    Archive                 Delete: 7424 items 1.08T [2.55T/1.46T, 4.47T free]
0     6/14/2023 2:02:28.661 AM    Timelapse               Delete: nothing to do [29.3G/300.0G, 5.56T free]
1     6/14/2023 2:02:29.676 AM    Clips                   MoveFile Error 32: N:\New\Cam1n.20230614_010047.bvr
1     6/14/2023 2:02:31.662 AM    Clips                   MoveFile Error 32: N:\New\Cam5.20230614_000000.bvr
1     6/14/2023 2:02:33.721 AM    Clips                   MoveFile Error 32: N:\New\Cam3.20230614_000000.bvr
1     6/14/2023 2:02:36.059 AM    Clips                   MoveFile Error 32: N:\New\Cam2.20230614_000000.bvr
3     6/14/2023 2:10:24.906 AM    Cam1n                   MOTION_ABCG
3     6/14/2023 2:18:37.200 AM    Cam1n                   MOTION_ABCG

Blue Iris is configured to do DB maintenance at 2AM every day. In addition, on Wednesdays (the day this occurred), all cameras are set to reboot at 2AM.

The only odd thing I've noticed is the Clip Storage dialog is now showing duplicated storage bar graphs for both drives. I'm thinking this may be the root cause.. it saw used space was way over max as it is now duplicated?

Since this occurred I've completely restarted the Blue Iris machine, and the Clip Storage dialog still shows duplicated bar graphs (see screenshot).

Anyone have any insight as to what the heck happened!?

 

[bp2008]

What do the "Delete:" log lines look like before the problem occurred?

Were there any Restarted after unexpected shutdown events logged recently? Those are a likely time for database corruption to occur, which could explain the sudden rise in Blue Iris's perception of disk usage.

 

[elkon]

Here are the "Delete:" log lines from yesterday. The last "Restarted after unexpected shutdown" was 5 weeks ago on 5/4/2023

0     6/13/2023 12:03:16.588 AM    Stored                  Delete: 1 items 1.66G [8436/23976 hrs, 3.71T/3.71T, 954.3G free] 84 locked
0     6/13/2023 12:29:38.894 AM    Stored                  Delete: 1 items 1.54G [8436/23976 hrs, 3.71T/3.71T, 954.4G free] 84 locked
0     6/13/2023 12:50:38.050 AM    Stored                  Delete: 1 items 1.56G [8436/23976 hrs, 3.71T/3.71T, 954.3G free] 84 locked
0     6/13/2023 1:31:55.388 AM    Stored                  Delete: 2 items 1.72G [8437/23976 hrs, 3.71T/3.71T, 952.9G free] 84 locked
0     6/13/2023 1:53:03.881 AM    Stored                  Delete: 5 items 1.75G [8437/23976 hrs, 3.71T/3.71T, 952.8G free] 84 locked
0     6/13/2023 2:20:52.014 AM    Stored                  Delete: 3 items 11.4G [8438/23976 hrs, 3.71T/3.71T, 946.2G free] 84 locked
0     6/13/2023 4:40:44.556 AM    Stored                  Delete: 1 items 1.54G [8440/23976 hrs, 3.71T/3.71T, 954.1G free] 84 locked
0     6/13/2023 5:02:49.373 AM    Stored                  Delete: 1 items 1.55G [8441/23976 hrs, 3.71T/3.71T, 953.9G free] 84 locked
0     6/13/2023 5:40:27.425 AM    Stored                  Delete: 6 items 9.24G [8441/23976 hrs, 3.71T/3.71T, 952.7G free] 84 locked
0     6/13/2023 6:26:40.097 AM    Stored                  Delete: 1 items 1.58G [8442/23976 hrs, 3.71T/3.71T, 953.9G free] 84 locked
0     6/13/2023 7:49:09.285 AM    Stored                  Delete: 1 items 1.58G [8443/23976 hrs, 3.71T/3.71T, 953.5G free] 84 locked
0     6/13/2023 8:09:57.307 AM    Stored                  Delete: 1 items 1.54G [8444/23976 hrs, 3.71T/3.71T, 953.4G free] 84 locked
0     6/13/2023 8:21:03.070 AM    RAM_Disk                Delete: 99 items 6.76M [1/1 hrs, 11.5M/1.00G, 2.00T free]
0     6/13/2023 8:31:03.781 AM    Stored                  Delete: 1 items 1.54G [8444/23976 hrs, 3.71T/3.71T, 953.3G free] 84 locked
0     6/13/2023 9:12:21.178 AM    Stored                  Delete: 1 items 1.60G [8445/23976 hrs, 3.71T/3.71T, 951.8G free] 84 locked
0     6/13/2023 9:12:21.309 AM    RAM_Disk                Delete: 37 items 2.47M [1/1 hrs, 6.44M/1.00G, 2.00T free]
0     6/13/2023 9:18:35.968 AM    RAM_Disk                Delete: 33 items 2.27M [1/1 hrs, 3.96M/1.00G, 2.00T free]
0     6/13/2023 9:28:36.991 AM    RAM_Disk                Delete: 27 items 1.68M [1/1 hrs, 1.68M/1.00G, 2.00T free]
0     6/13/2023 9:38:37.803 AM    Stored                  Delete: 5 items 1.66G [8445/23976 hrs, 3.71T/3.71T, 952.4G free] 84 locked
0     6/13/2023 9:53:59.750 AM    Stored                  Delete: 1 items 1.54G [8445/23976 hrs, 3.71T/3.71T, 952.9G free] 84 locked
0     6/13/2023 10:09:33.700 AM    Stored                  Delete: 1 items 1.54G [8446/23976 hrs, 3.71T/3.71T, 952.8G free] 84 locked
0     6/13/2023 10:30:40.149 AM    Stored                  Delete: 1 items 1.54G [8446/23976 hrs, 3.71T/3.71T, 952.7G free] 84 locked
0     6/13/2023 10:51:40.771 AM    Stored                  Delete: 1 items 9.41G [8446/23976 hrs, 3.71T/3.71T, 952.5G free] 84 locked
0     6/13/2023 1:11:57.925 PM    Stored                  Delete: 5 items 6.23G [8449/23976 hrs, 3.71T/3.71T, 946.3G free] 84 locked
0     6/13/2023 1:22:16.971 PM    RAM_Disk                Delete: 61 items 4.15M [1/1 hrs, 4.15M/1.00G, 2.00T free]
0     6/13/2023 2:37:21.968 PM    RAM_Disk                Delete: 45 items 3.09M [1/1 hrs, 3.78M/1.00G, 2.00T free]
0     6/13/2023 2:42:22.323 PM    RAM_Disk                Delete: 10 items 707K [1/1 hrs, 707K/1.00G, 2.00T free]
0     6/13/2023 3:02:23.701 PM    Stored                  Delete: 1 items 1.54G [8451/23976 hrs, 3.71T/3.71T, 950.5G free] 84 locked
0     6/13/2023 3:23:34.182 PM    Stored                  Delete: 1 items 8.88G [8451/23976 hrs, 3.71T/3.71T, 950.5G free] 84 locked
0     6/13/2023 3:44:45.500 PM    Stored                  Delete: 1 items 1.56G [8451/23976 hrs, 3.71T/3.71T, 949.8G free] 84 locked
0     6/13/2023 3:59:22.691 PM    RAM_Disk                Delete: 41 items 2.83M [1/1 hrs, 8.48M/1.00G, 2.00T free]
0     6/13/2023 4:04:23.109 PM    RAM_Disk                Delete: 21 items 1.46M [1/1 hrs, 5.64M/1.00G, 2.00T free]
0     6/13/2023 4:14:23.969 PM    RAM_Disk                Delete: 61 items 4.18M [1/1 hrs, 4.18M/1.00G, 2.00T free]
0     6/13/2023 5:59:30.958 PM    Stored                  Delete: 6 items 8.58G [8453/23976 hrs, 3.71T/3.71T, 949.3G free] 84 locked
0     6/13/2023 6:41:58.186 PM    RAM_Disk                Delete: 100 items 6.94M [1/1 hrs, 14.8M/1.00G, 2.00T free]
0     6/13/2023 7:03:12.965 PM    Stored                  Delete: 4 items 6.28G [8455/23976 hrs, 3.71T/3.71T, 945.6G free] 84 locked
0     6/13/2023 7:03:13.148 PM    RAM_Disk                Delete: 58 items 4.03M [1/1 hrs, 7.89M/1.00G, 2.00T free]
0     6/13/2023 7:13:38.399 PM    RAM_Disk                Delete: 56 items 3.86M [1/1 hrs, 3.86M/1.00G, 2.00T free]
0     6/13/2023 9:13:46.381 PM    Stored                  Delete: 1 items 1.54G [8457/23976 hrs, 3.71T/3.71T, 949.8G free] 84 locked
0     6/13/2023 9:34:47.391 PM    Stored                  Delete: 1 items 275.7M [8457/23976 hrs, 3.71T/3.71T, 949.7G free] 84 locked
0     6/13/2023 10:00:51.811 PM    Stored                  Delete: 5 items 8.55G [8458/23976 hrs, 3.71T/3.71T, 948.4G free] 84 locked
0     6/13/2023 11:40:24.365 PM    Stored                  Delete: 4 items 6.63G [8459/23976 hrs, 3.71T/3.71T, 943.6G free] 84 locked

 

[bp2008]

All those older lines look normal. My best guess is that the 2AM compact/repair failed to keep the "database" locked properly, thereby allowing the much more frequent regular maintenance task (which moves/deletes clips) to happen at the same time and make decisions based on an incorrect view of the clip database. Since Blue Iris is not open source, only the developer could know for sure, and since this version is over a year old, the relevant code has likely changed a lot since then and the bug might not even be there anymore in the latest version.