fix-high: close events left open by a capture daemon that died

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 {

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';
 

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);