ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Previous development branch now released as 1.36
Locked
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

Background: I'm using a bash script to keep my events folder to a certain size, I need ZMaudit.pl to run after this to clear out the now empty events, but it isn't working.

I couldn't get this to work at all yesterday, I thought it might have to do with "AUDIT_MIN_AGE" in the system settings, so I reduced this to 1 minute (these events are only about 24 hours old). I ran my script, it cleared the events folder from around 14GB to 10GB. This left lots of old "empty" events in the console. I ran ZMAudit.pl and it spat out a load of stuff and presto, now ZM showed the correct number of events and file size.

I then wanted to make some changes, so I used my script to lower the folder size to 9GB (confirmed this myself), which again left empty events in the ZM console. Now ZMAudit won't do anything about this. I just get an output like this instead:

Code: Select all

isabell@isabell-MS-7C52:~$ sudo zmaudit.pl
15/06/20 23:31:41.939639 zmaudit[1598].INF [main:199] [Auditing All Storage Areas]
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 4 log table entries by time
Deleted 0 log table entries by time
I'm not sure what this is notifying me of, but it's clearly not the same as when it worked and the empty events are still in ZM and it has the wrong file size. What gives? Has this something to do with the events being so recent?
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

----
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

I posted a comment here that I didn't mean to do and deleting comments is disabled. I wrote "IGNORE" on it, I just want to clarify that I do need help with this :D
User avatar
iconnor
Posts: 2904
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by iconnor »

If you turn on debug logging, there should be more info in /var/log/zm/zmaudit.log
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

OK, So I wasn't really sure which debugging to turn on in options, so I just switched them all on.

I had a few runs at it and I can't even tell why it just worked perfectly once. I didn't change anything except the debugging options.

I've been shrinking the folder size using my script and then running ZMaudit.pl to see what happens.

Since it obviously just repeats the same lines over, I'll just put in the first part of each log.

This was an unsuccessful audit:

Code: Select all

16/06/20 17:51:05.096254 zmaudit[24289].INF [main:199] [Auditing All Storage Areas]
16/06/20 17:51:05.305473 zmaudit[24289].WAR [ZoneMinder::Event:533] [Path not found for Event 8638 at /var/cache/zoneminder/HighResCamEvents/11/2020-06-15/8638]
16/06/20 17:51:05.314296 zmaudit[24289].WAR [main:630] [Not found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-15/8638 was found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-15/8638]
16/06/20 17:51:05.316453 zmaudit[24289].WAR [main:631] [ZoneMinder::Event: AlarmFrames => 190 AvgScore => 1 Cause => External Motion DefaultVideo => 8638-video.mp4 DiskSpace => 9465463 EndTime => 2020-06-15 23:37:10 Frames => 235 Height => 1536 Id => 8638 Length => 23.40 MaxScore => 1 MonitorId => 11 Name => Event- 8638 Notes => External Motion:  Orientation => ROTATE_0 Scheme => Medium StartTime => 2020-06-15 23:36:47 StateId => 1 StorageId => 6 TotScore => 190 Width => 2304]
16/06/20 17:51:05.318399 zmaudit[24289].WAR [main:632] [ZoneMinder::Event: Id => 8638 MonitorId => 11 Scheme => Medium StartTime => 2020-06-16 16:50:39 StorageId => 6]
16/06/20 17:51:05.322824 zmaudit[24289].WAR [ZoneMinder::Event:533] [Path not found for Event 8966 at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8966]
16/06/20 17:51:05.324995 zmaudit[24289].WAR [main:630] [Not found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8966 was found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8966]
16/06/20 17:51:05.326611 zmaudit[24289].WAR [main:631] [ZoneMinder::Event: AlarmFrames => 363 AvgScore => 1 Cause => External Motion DefaultVideo => 8966-video.mp4 DiskSpace => 12543606 EndTime => 2020-06-16 13:23:57 Frames => 408 Height => 1536 Id => 8966 Length => 20.51 MaxScore => 1 MonitorId => 11 Name => Event- 8966 Notes => External Motion:  Orientation => ROTATE_0 Scheme => Medium StartTime => 2020-06-16 13:23:36 StateId => 1 StorageId => 6 TotScore => 363 Width => 2304]
16/06/20 17:51:05.329415 zmaudit[24289].WAR [main:632] [ZoneMinder::Event: Id => 8966 MonitorId => 11 Scheme => Medium StartTime => 2020-06-16 16:50:40 StorageId => 6]
16/06/20 17:51:05.333746 zmaudit[24289].WAR [ZoneMinder::Event:533] [Path not found for Event 8969 at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8969]
16/06/20 17:51:05.336453 zmaudit[24289].WAR [main:630] [Not found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8969 was found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8969]
16/06/20 17:51:05.339201 zmaudit[24289].WAR [main:631] [ZoneMinder::Event: AlarmFrames => 371 AvgScore => 1 Cause => External Motion DefaultVideo => 8969-video.mp4 DiskSpace => 13046795 EndTime => 2020-06-16 13:24:51 Frames => 416 Height => 1536 Id => 8969 Length => 20.86 MaxScore => 1 MonitorId => 11 Name => Event- 8969 Notes => External Motion:  Orientation => ROTATE_0 Scheme => Medium StartTime => 2020-06-16 13:24:30 StateId => 1 StorageId => 6 TotScore => 371 Width => 2304]
16/06/20 17:51:05.341886 zmaudit[24289].WAR [main:632] [ZoneMinder::Event: Id => 8969 MonitorId => 11 Scheme => Medium StartTime => 2020-06-16 16:50:40 StorageId => 6]
16/06/20 17:51:05.346195 zmaudit[24289].WAR [ZoneMinder::Event:533] [Path not found for Event 8802 at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8802]

This was a successful audit:

Code: Select all

16/06/20 17:59:06.927182 zmaudit[24606].INF [main:199] [Auditing All Storage Areas]
16/06/20 17:59:07.111981 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 8920 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8920]
16/06/20 17:59:07.168454 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 8920 from Monitor 10 StartTime:2020-06-16 13:07:59 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8920]
16/06/20 17:59:07.498645 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 8859 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8859]
16/06/20 17:59:07.567378 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 8859 from Monitor 10 StartTime:2020-06-16 12:45:00 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8859]
16/06/20 17:59:07.641224 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 8943 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8943]
16/06/20 17:59:07.643789 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 8943 from Monitor 10 StartTime:2020-06-16 13:14:00 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8943]
16/06/20 17:59:07.664572 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 9056 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/9056]
16/06/20 17:59:07.667084 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 9056 from Monitor 10 StartTime:2020-06-16 14:09:36 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/9056]
16/06/20 17:59:07.688701 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 9031 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/9031]
16/06/20 17:59:07.691178 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 9031 from Monitor 10 StartTime:2020-06-16 13:51:26 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/9031]
16/06/20 17:59:07.714149 zmaudit[24606].WAR [ZoneMinder::Event:533] [Path not found for Event 8710 at /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8710]
16/06/20 17:59:07.720960 zmaudit[24606].INF [ZoneMinder::Event:373] [Deleting event 8710 from Monitor 10 StartTime:2020-06-16 00:06:56 from /var/cache/zoneminder/HighResCamEvents/10/2020-06-16/8710]

I don't think there's anything helpful in here? I can see they're both different, I don't understand why the unsuccessful one has spit out information on the event and the successful one hasn't...

I'm going to post the bash script here that's doing the file deletion as I can just see someone asking for a look at it (not mine btw):

Code: Select all

#!/bin/bash
usage=$(du -sb /var/cache/zoneminder/HighResCamEvents  | cut -d $'\t' -f 1)
max=8000000000
if (( usage > max ))
then
  find /var/cache/zoneminder/HighResCamEvents -maxdepth 5 -type f -printf '%T@\t%s\t%p\n' | sort -n | \
    while (( usage > max )) && IFS=$'\t' read timestamp size file
    do
      rm -- "$file" && (( usage -= size ))
    done
fi
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

Has anyone any idea on what this bug is? I've tried looking at it myself, but I'm clueless. All I can tell is that this isn't true:

Code: Select all

if ( ! ($fs_events and defined( $fs_events->{$db_event} ) ) 
And this is what's generating the line:

Code: Select all

if ( $Event and ! $Event->check_for_in_filesystem() ) {
Warning('Not found at ' . $Event->Path() . ' was found at ' . $$fs_events{$db_event}->Path());
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

OK, maybe the issue is that I don't understand what ZMaudit is actually trying to do...

I have my script working now, but the answer is to run ZMaudit TWICE. The first time it generates all the warnings, the second time it actually removes the files. This surely isn't the correct way to work this?
BaconButty
Posts: 35
Joined: Fri Jun 12, 2020 1:29 pm

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by BaconButty »

Sorry to bring this up again. I have this setup and running now a while. I still have the issue that I end up with lots of empty events in Zoneminder as ZMaudit.pl doesn't pick them up as missing and I haven't a clue why.

There's no error showing, output of ZMaudit.pl looks like this (not picking up the missing events):

Code: Select all

06/07/20 16:09:10.358106 zmaudit[31010].INF [main:199] [Auditing All Storage Areas]
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 10 log table entries by time
Deleted 3 log table entries by time
Deleted 0 log table entries by time
dougmccrary
Posts: 1215
Joined: Sat Aug 31, 2019 7:35 am
Location: San Diego

Re: ZMaudit.pl not removing empty events. Doesn't like deleting young events?

Post by dougmccrary »

Seems to me this could be done with a filter or two.
Anyway, I noticed this, and am wondering if it's somehow part of the problem:

16/06/20 17:51:05.336453 zmaudit[24289].WAR [main:630]
[Not found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8969
was found at /var/cache/zoneminder/HighResCamEvents/11/2020-06-16/8969]

Do you have two storage areas with the same name?
Locked