diff --git a/scripts/ZoneMinder/lib/ZoneMinder/Event.pm b/scripts/ZoneMinder/lib/ZoneMinder/Event.pm index 7110c473c3..7c035d0b12 100644 --- a/scripts/ZoneMinder/lib/ZoneMinder/Event.pm +++ b/scripts/ZoneMinder/lib/ZoneMinder/Event.pm @@ -46,6 +46,7 @@ require POSIX; use Date::Format qw(time2str); use Time::HiRes qw(gettimeofday tv_interval stat); use Scalar::Util qw(looks_like_number); +use List::Util (); #our @ISA = qw(ZoneMinder::Object); use parent qw(ZoneMinder::Object); @@ -1092,20 +1093,42 @@ FROM `Frames` WHERE `EventId`=?'; if (!$frame) { return 'Unable to retrieve frame data.'; } - if (!$frame->{EndDateTime}) { - return 'Unable to retrieve EndDateTime from Frames Table.'; + my $start = $self->Time(); + if (!$start) { + return 'Unable to determine the start time of the event.'; } - return $self->save({ - Name => sprintf('%s%d%s', $self->Monitor()->EventPrefix(), $self->{Id}, $tag), - EndDateTime => $frame->{EndDateTime}, - Length => $frame->{EndTimeStamp} - $self->Time(), - Frames => $frame->{Frames}, - AlarmFrames => $frame->{AlarmFrames}, - TotScore => $frame->{TotScore}, - AvgScore => ($frame->{AlarmFrames} ? int($frame->{TotScore} / $frame->{AlarmFrames}) : 0), - MaxScore => $frame->{MaxScore}, + + # zmc writes Frames rows in batches and updates the event row's Length, + # Frames and scores with each batch, so either can be ahead of the other when + # zmc dies. An event killed before its first batch has no Frames rows at all. + # Take the larger of the two for each. + my $end_date_time = $frame->{EndDateTime}; + my $length = $end_date_time ? $frame->{EndTimeStamp} - $start : 0; + if (!$end_date_time or ($self->{Length} // 0) > $length) { + $length = $self->{Length} // 0; + $end_date_time = time2str('%Y-%m-%d %H:%M:%S', $start + $length); + } + my $frames = List::Util::max($frame->{Frames} // 0, $self->{Frames} // 0); + my $alarm_frames = List::Util::max($frame->{AlarmFrames} // 0, $self->{AlarmFrames} // 0); + my $tot_score = List::Util::max($frame->{TotScore} // 0, $self->{TotScore} // 0); + my $max_score = List::Util::max($frame->{MaxScore} // 0, $self->{MaxScore} // 0); + + my %changes = ( + EndDateTime => $end_date_time, + Length => $length, + Frames => $frames, + AlarmFrames => $alarm_frames, + TotScore => $tot_score, + AvgScore => ($alarm_frames ? int($tot_score / $alarm_frames) : 0), + MaxScore => $max_score, Notes => $self->Notes() . ' ' . $text, - }); + ); + # Like zmc's own close (~Event: Name = IF(Name='New Event', ...)), keep a name + # the user gave the event; only the placeholder gets the recovered name. + if (($self->{Name} // 'New Event') eq 'New Event') { + $changes{Name} = sprintf('%s%d%s', $self->Monitor()->EventPrefix(), $self->{Id}, $tag); + } + return $self->save(\%changes); } # end sub Close sub Event_Tags { diff --git a/scripts/zmwatch.pl.in b/scripts/zmwatch.pl.in index b3478f229c..cf48350dee 100644 --- a/scripts/zmwatch.pl.in +++ b/scripts/zmwatch.pl.in @@ -55,6 +55,7 @@ use bytes; @EXTRA_PERL_LIB@ use ZoneMinder; use ZoneMinder::Monitor; +use ZoneMinder::Event; use POSIX; use DBI; use autouse 'Data::Dumper'=>qw(Dumper); @@ -102,6 +103,31 @@ my $last_pass_time = time(); my $start_time = time(); my %seen_healthy; +# --- Events left open by a zmc that died ------------------------------------ +# A zmc that is killed (or crashes) mid-event never writes the event's end, and +# nothing else closes it: zmaudit only does when ZM_RUN_AUDIT is on, and only a +# day later. A running zmc closes every event it opened before it reconnects, +# and records the time it connected as startup_time in shared memory, so any +# event of its monitor that started before then and is still open belongs to a +# process that is gone. Look once per zmc start, when its heartbeat shows it is +# up. Events from zma's re-analysis are created on the monitor too, with their +# original times, and are left to zma. +my %recovered_before; + +sub close_abandoned_events { + my ($monitor, $before) = @_; + foreach my $event (ZoneMinder::Event->find(custom => [ + '`MonitorId`=? AND `EndDateTime` IS NULL AND `StartDateTime` < FROM_UNIXTIME(?) AND NOT (`Cause` <=> ?)', + $$monitor{Id}, $before, 'Re-analysis'])) { + my $error = $event->Close(); + if ($error) { + Warning("Unable to close event $$event{Id} left open on monitor $$monitor{Id} $$monitor{Name}: $error"); + } else { + Info("Closed event $$event{Id} on monitor $$monitor{Id} $$monitor{Name}, left open since $$event{StartDateTime} by a capture daemon that is gone"); + } + } +} + while (!$zm_terminate) { my $db_was_down = 0; while (!($dbh and $dbh->ping()) and !$zm_terminate) { @@ -175,6 +201,12 @@ while (!$zm_terminate) { Debug("Monitor $monitor->{Id} $monitor->{Name}, heartbeat time $now - $heartbeat_time $heartbeat_elapsed < $Config{ZM_WATCH_MAX_DELAY}"); } + my $zmc_startup_time = zmGetStartupTime($monitor); + if ($zmc_startup_time and (($recovered_before{$monitor->{Id}} // 0) != $zmc_startup_time)) { + close_abandoned_events($monitor, $zmc_startup_time); + $recovered_before{$monitor->{Id}} = $zmc_startup_time; + } + next if $monitor->{Capturing} eq 'Ondemand'; next if $monitor->{Decoding} eq 'None' or $monitor->{Decoding} eq 'Ondemand'; diff --git a/tests/perl/test_event_close_recovered.pl b/tests/perl/test_event_close_recovered.pl new file mode 100644 index 0000000000..762261554a --- /dev/null +++ b/tests/perl/test_event_close_recovered.pl @@ -0,0 +1,130 @@ +#!/usr/bin/perl +# +# ZoneMinder::Event::Close() finishes an event that a capture daemon left open +# when it was killed (EndDateTime NULL). It is what zmeventtool.pl close and +# zmwatch use, so it has to cope with what such an event looks like: +# +# - zmc writes Frames rows in batches, so an event killed in its first seconds +# has none; +# - the event row's Length, Frames and scores are updated with each batch, so +# the row or the Frames rows can be ahead of the other. +# +# The database is stubbed. +# +# Run as: sudo -u www-data perl tests/perl/test_event_close_recovered.pl +# +use strict; +use warnings; +use FindBin; +use lib "$FindBin::Bin/../../scripts/ZoneMinder/lib"; +use POSIX qw(strftime); + +use ZoneMinder::Event; + +my $failures = 0; +my $passes = 0; + +# What the stubbed Frames aggregate returns, and what Close() asked save() to +# write. +my $frame_row; +my $saved; + +{ + no warnings qw(redefine once); + *ZoneMinder::Database::zmDbFetchOne = sub { return $frame_row; }; + *ZoneMinder::Event::save = sub { my ($self, $data) = @_; $saved = $data; return ''; }; +} + +package FakeMonitor { sub EventPrefix { return 'Event-' } } + +sub check { + my ($name, $got, $want) = @_; + if ((defined $got ? $got : '(undef)') eq (defined $want ? $want : '(undef)')) { + $passes++; + print "ok - $name\n"; + } else { + $failures++; + print "FAIL - $name\n"; + print ' got: '.(defined $got ? $got : '(undef)')."\n"; + print ' want: '.(defined $want ? $want : '(undef)')."\n"; + } +} + +my $start = 1791659945; # any whole second +my $start_str = strftime('%Y-%m-%d %H:%M:%S', localtime($start)); +sub at { return strftime('%Y-%m-%d %H:%M:%S', localtime($start + $_[0])); } + +sub event { + my (%fields) = @_; + return bless { + Id => 41, MonitorId => 2, Name => 'New Event', StartDateTime => $start_str, + Length => 0, Frames => 0, AlarmFrames => 0, TotScore => 0, MaxScore => 0, + Notes => '', Monitor => bless({}, 'FakeMonitor'), + %fields, + }, 'ZoneMinder::Event'; +} + +my $no_frames = {EndDateTime => undef, EndTimeStamp => undef, Frames => undef, + AlarmFrames => 0, TotScore => undef, MaxScore => undef}; + +# Killed before the first Frames batch: the row is all there is. +{ + $frame_row = $no_frames; $saved = undef; + my $event = event(Length => 4.6, Frames => 70, AlarmFrames => 3, TotScore => 45, MaxScore => 20); + my $error = $event->Close(); + check('closes an event that has no Frames rows', $error, ''); + check('end is start plus the row Length, in whole seconds', $$saved{EndDateTime}, at(4)); + check('Length from the row', $$saved{Length}, 4.6); + check('Frames from the row', $$saved{Frames}, 70); + check('alarm frames and scores from the row', join(',', @$saved{qw(AlarmFrames TotScore AvgScore MaxScore)}), '3,45,15,20'); + check('name gets the recovered tag', $$saved{Name}, 'Event-41(r)'); + check('notes say it was recovered', $$saved{Notes}, ' Recovered.'); +} + +# The Frames rows end later than the row was last updated: as before. +{ + $frame_row = {EndDateTime => at(20), EndTimeStamp => $start + 20, Frames => 300, + AlarmFrames => 2, TotScore => 30, MaxScore => 20}; + $saved = undef; + my $event = event(Length => 19.93, Frames => 290, Notes => 'person'); + $event->Close(); + check('end from the last Frames row when it is later', $$saved{EndDateTime}, at(20)); + check('Length from the last Frames row when it is later', $$saved{Length}, 20); + check('Frames from the Frames rows when higher', $$saved{Frames}, 300); + check('alarm frames and scores from the Frames rows', join(',', @$saved{qw(AlarmFrames TotScore AvgScore MaxScore)}), '2,30,15,20'); + check('appends to existing notes', $$saved{Notes}, 'person Recovered.'); +} + +# The row is ahead of the Frames rows: zmc died before writing its last batch. +{ + $frame_row = {EndDateTime => at(15), EndTimeStamp => $start + 15, Frames => 250, + AlarmFrames => 2, TotScore => 30, MaxScore => 25}; + $saved = undef; + my $event = event(Length => 19.93, Frames => 300, AlarmFrames => 5, TotScore => 80, MaxScore => 20); + $event->Close(); + check('Length from the row when it is longer', $$saved{Length}, 19.93); + check('end is start plus that Length, in whole seconds', $$saved{EndDateTime}, at(19)); + check('Frames from the row when higher', $$saved{Frames}, 300); + check('each score is the larger of the two', join(',', @$saved{qw(AlarmFrames TotScore AvgScore MaxScore)}), '5,80,16,25'); +} + +# The user renamed the event while it was recording: zmwatch closes it on its +# own now, so it keeps that name; the note still says it was recovered. +{ + $frame_row = $no_frames; $saved = undef; + my $event = event(Name => 'Front door delivery', Length => 4.6, Frames => 70); + $event->Close(); + check('keeps a name the user gave the event', exists $$saved{Name} ? $$saved{Name} : '(not changed)', '(not changed)'); + check('notes still say it was recovered', $$saved{Notes}, ' Recovered.'); +} + +# No start time: nothing to anchor the end to. +{ + $frame_row = $no_frames; $saved = undef; + my $event = event(StartDateTime => undef); + my $error = $event->Close(); + check('refuses an event without a start time', ($error and !$saved) ? 1 : 0, 1); +} + +print "\n$passes passed, $failures failed\n"; +exit($failures ? 1 : 0);