From d663683f47386c3641128c1c1468c4a82c113e5d Mon Sep 17 00:00:00 2001 From: Isaac Connor Date: Wed, 11 Nov 2020 12:43:41 -0500 Subject: [PATCH 1/5] Add a bunch of debug statements to figure out crash --- src/zm_event.cpp | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/zm_event.cpp b/src/zm_event.cpp index cd7ba1918..ed478ad20 100644 --- a/src/zm_event.cpp +++ b/src/zm_event.cpp @@ -255,7 +255,7 @@ Event::~Event() { } // endtime is set in AddFrame, so SHOULD be set to the value of the last frame timestamp. - if ( ! end_time.tv_sec ) { + if ( !end_time.tv_sec ) { Warning("Empty endtime for event. Should not happen. Setting to now."); gettimeofday(&end_time, nullptr); } @@ -503,7 +503,7 @@ void Event::updateNotes(const StringSetMap &newNoteSetMap) { } // void Event::updateNotes(const StringSetMap &newNoteSetMap) void Event::AddFrames(int n_frames, Image **images, struct timeval **timestamps) { - for (int i = 0; i < n_frames; i += ZM_SQL_BATCH_SIZE) { + for ( int i = 0; i < n_frames; i += ZM_SQL_BATCH_SIZE ) { AddFramesInternal(n_frames, i, images, timestamps); } } @@ -592,6 +592,7 @@ void Event::WriteDbFrames() { frame->delta.fsec, frame->score); delete frame; + Debug(1, "SQL: %s", frame_insert_sql); } *(frame_insert_values_ptr-1) = '\0'; // The -1 is for the extra , added for values above db_mutex.lock(); @@ -600,6 +601,8 @@ void Event::WriteDbFrames() { db_mutex.unlock(); if ( rc ) { + Error("Can't insert frames: rc %d", rc); + Error("Can't insert frames: sql %s", frame_insert_sql); Error("Can't insert frames: %s, sql was %s", mysql_error(&dbconn), frame_insert_sql); return; } else { @@ -719,6 +722,9 @@ void Event::AddFrame(Image *image, struct timeval timestamp, int score, Image *a db_mutex.lock(); } db_mutex.unlock(); + } else { + Debug(1, "Not Adding %d frames to DB because write_to_db:%d or frames > analysis fps %f or BULK", + frame_data.size(), write_to_db, monitor->get_fps()); } // end if frame_type == BULK } // end if db_frame From f855f207e261c5755758ecc41e1a94889cb97fbe Mon Sep 17 00:00:00 2001 From: Isaac Connor Date: Wed, 11 Nov 2020 14:03:08 -0500 Subject: [PATCH 2/5] Limit that # of db frames to buffer to 120 because the sql will exceed 8192. --- src/zm_event.cpp | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/src/zm_event.cpp b/src/zm_event.cpp index ed478ad20..c858b1877 100644 --- a/src/zm_event.cpp +++ b/src/zm_event.cpp @@ -39,6 +39,7 @@ //#define USE_PREPARED_SQL 1 const char * Event::frame_type_names[3] = { "Normal", "Bulk", "Alarm" }; +#define MAX_DB_FRAMES 120 char frame_insert_sql[ZM_SQL_LGE_BUFSIZ] = "INSERT INTO `Frames` (`EventId`, `FrameId`, `Type`, `TimeStamp`, `Delta`, `Score`) VALUES "; int Event::pre_alarm_count = 0; @@ -577,6 +578,9 @@ void Event::AddFramesInternal(int n_frames, int start_frame, Image **images, str void Event::WriteDbFrames() { char *frame_insert_values_ptr = (char *)&frame_insert_sql + 90; // 90 == strlen(frame_insert_sql); + + /* Each frame needs about 63 chars. So if we buffer too many frames, we will exceed the size of frame_insert_sql; + */ Debug(1, "Inserting %d frames", frame_data.size()); while ( frame_data.size() ) { Frame *frame = frame_data.front(); @@ -592,17 +596,13 @@ void Event::WriteDbFrames() { frame->delta.fsec, frame->score); delete frame; - Debug(1, "SQL: %s", frame_insert_sql); } *(frame_insert_values_ptr-1) = '\0'; // The -1 is for the extra , added for values above db_mutex.lock(); - Debug(1, "SQL: %s", frame_insert_sql); int rc = mysql_query(&dbconn, frame_insert_sql); db_mutex.unlock(); if ( rc ) { - Error("Can't insert frames: rc %d", rc); - Error("Can't insert frames: sql %s", frame_insert_sql); Error("Can't insert frames: %s, sql was %s", mysql_error(&dbconn), frame_insert_sql); return; } else { @@ -691,14 +691,23 @@ void Event::AddFrame(Image *image, struct timeval timestamp, int score, Image *a Debug(1, "Frame delta is %d.%d - %d.%d = %d.%d", start_time.tv_sec, start_time.tv_usec, timestamp.tv_sec, timestamp.tv_usec, delta_time.sec, delta_time.fsec); + double fps = monitor->get_fps(); + bool db_frame = ( frame_type != BULK ) || (frames==1) || ((frames%config.bulk_frame_interval)==0) ; if ( db_frame ) { // The idea is to write out 1/sec frame_data.push(new Frame(id, frames, frame_type, timestamp, delta_time, score)); - if ( write_to_db or ( monitor->get_fps() and (frame_data.size() > monitor->get_fps())) or frame_type==BULK ) { + if ( write_to_db + or + (frame_data.size() > MAX_DB_FRAMES) + or + (frame_type==BULK) + or + ( fps and (frame_data.size() > fps) ) + ) { Debug(1, "Adding %d frames to DB because write_to_db:%d or frames > analysis fps %f or BULK", - frame_data.size(), write_to_db, monitor->get_fps()); + frame_data.size(), write_to_db, fps); WriteDbFrames(); last_db_frame = frames; @@ -724,7 +733,7 @@ void Event::AddFrame(Image *image, struct timeval timestamp, int score, Image *a db_mutex.unlock(); } else { Debug(1, "Not Adding %d frames to DB because write_to_db:%d or frames > analysis fps %f or BULK", - frame_data.size(), write_to_db, monitor->get_fps()); + frame_data.size(), write_to_db, fps); } // end if frame_type == BULK } // end if db_frame From 076d649189f2dcdf3b79d2b59c5c84514e27f3b3 Mon Sep 17 00:00:00 2001 From: Isaac Connor Date: Wed, 11 Nov 2020 16:12:30 -0500 Subject: [PATCH 3/5] Include Record Monitors in zmtrigger --- scripts/zmtrigger.pl.in | 15 ++++++--------- 1 file changed, 6 insertions(+), 9 deletions(-) diff --git a/scripts/zmtrigger.pl.in b/scripts/zmtrigger.pl.in index 1ee392c1e..be38c5e91 100644 --- a/scripts/zmtrigger.pl.in +++ b/scripts/zmtrigger.pl.in @@ -187,7 +187,7 @@ while (1) { } else { Fatal("Can't select: $!"); } - } # end if select returned activitiy + } # end if select returned activity # Check polled connections foreach my $connection ( @in_poll_connections ) { @@ -266,7 +266,7 @@ while (1) { Debug('Checking for timed actions'); my $now = time(); foreach my $action_time ( sort( grep { $_ < $now } @action_times ) ) { - Info("Found " . scalar @{$actions{$action_time}} . "actions expiring at $action_time"); + Info('Found '.(scalar @{$actions{$action_time}}).'actions expiring at '.$action_time); foreach my $action ( @{$actions{$action_time}} ) { my $connection = $action->{connection}; Info("Found action '$$action{message}'"); @@ -319,7 +319,7 @@ exit; sub loadMonitor { my $monitor = shift; - Debug("Loading monitor $monitor"); + Debug('Loading monitor '.$monitor); zmMemInvalidate($monitor); if ( zmMemVerify($monitor) ) { # This will re-init shared memory @@ -334,7 +334,7 @@ sub loadMonitors { my %new_monitors = (); my $sql = 'SELECT * FROM `Monitors` - WHERE find_in_set( `Function`, \'Modect,Mocord,Nodect\' )'. + WHERE find_in_set( `Function`, \'Modect,Mocord,Nodect,Record\' )'. ( $Config{ZM_SERVER_ID} ? ' AND `ServerId`=?' : '' ) ; my $sth = $dbh->prepare_cached( $sql ) @@ -387,12 +387,9 @@ sub handleMessage { } # Force a reload $monitor_reload_time = 0; - Info("Set monitor to $state"); + Info('Set monitor to '.$state); if ( $delay ) { - my $action_text = $id.'|'.( ($state eq 'enable') - ? 'disable' - : 'enable' - ); + my $action_text = $id.'|'.(($state eq 'enable') ? 'disable' : 'enable'); handleDelay($delay, $connection, $action_text); } } elsif ( $action =~ /^(on|off)(?:[ \+](\d+))?$/ ) { From 7b764d04d3a13f2f600868383a818291778594ff Mon Sep 17 00:00:00 2001 From: Isaac Connor Date: Wed, 11 Nov 2020 17:40:31 -0500 Subject: [PATCH 4/5] Fix use of next when it should be return. Improve some logging of errors. --- scripts/zmtrigger.pl.in | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/scripts/zmtrigger.pl.in b/scripts/zmtrigger.pl.in index be38c5e91..acd4ce255 100644 --- a/scripts/zmtrigger.pl.in +++ b/scripts/zmtrigger.pl.in @@ -372,9 +372,10 @@ sub handleMessage { Warning("Can't find monitor '$id' for message '$message'"); return; } - Debug("Found monitor for id '$id'"); - - next if !zmMemVerify($monitor); + if ( !zmMemVerify($monitor) ) { + Warning("Can't verify monitor '$id' for message '$message'"); + return; + } Debug("Handling action '$action'"); if ( $action =~ /^(enable|disable)(?:[\+ ](\d+))?$/ ) { @@ -393,12 +394,19 @@ sub handleMessage { handleDelay($delay, $connection, $action_text); } } elsif ( $action =~ /^(on|off)(?:[ \+](\d+))?$/ ) { - next if !$monitor->{Enabled}; + if ( !$monitor->{Enabled} ) { + Info('Motion detection not enabled on monitor '.$id); + return; + } my $trigger = $1; my $delay = $2; my $trigger_data; if ( $trigger eq 'on' ) { + if ( $score <= 0 ) { + Warning('Triggering on with invalid score will have no result.'); + return; + } zmTriggerEventOn($monitor, $score, $cause, $text); zmTriggerShowtext($monitor, $showtext) if defined($showtext); Info("Trigger '$trigger' '$cause'"); From 9636a76ccff7bbfdcc014ac3ef8ae1d28a25630a Mon Sep 17 00:00:00 2001 From: Isaac Connor Date: Wed, 11 Nov 2020 17:42:29 -0500 Subject: [PATCH 5/5] drop db lock before reporting mysql_errors --- src/zm_monitor.cpp | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/src/zm_monitor.cpp b/src/zm_monitor.cpp index 0acfb3ded..e2ea20f88 100644 --- a/src/zm_monitor.cpp +++ b/src/zm_monitor.cpp @@ -1307,10 +1307,11 @@ bool Monitor::Analyse() { db_mutex.lock(); static char sql[ZM_SQL_SML_BUFSIZ]; snprintf(sql, sizeof(sql), "INSERT INTO Monitor_Status (MonitorId,AnalysisFPS) VALUES (%d, %.2lf) ON DUPLICATE KEY UPDATE AnalysisFPS = %.2lf", id, fps, fps); - if ( mysql_query(&dbconn, sql) ) { - Error("Can't run query: %s", mysql_error(&dbconn)); - } + int rc = mysql_query(&dbconn, sql); db_mutex.unlock(); + if ( rc ) { + Error("Can't run query %s: %s", sql, mysql_error(&dbconn)); + } } // end if fps != new_fps last_fps_time = now.tv_sec; @@ -2583,11 +2584,11 @@ int Monitor::Capture() { "VALUES (%d, %.2lf, %u, 'Connected') ON DUPLICATE KEY UPDATE " "CaptureFPS = %.2lf, CaptureBandwidth=%u, Status='Connected'", id, fps, new_capture_bandwidth, fps, new_capture_bandwidth); - if ( mysql_query(&dbconn, sql) ) { - Error("Can't run query: %s", mysql_error(&dbconn)); - } + rc = mysql_query(&dbconn, sql); db_mutex.unlock(); - Debug(4,sql); + if ( rc ) { + Error("Can't run query %s: %s", sql, mysql_error(&dbconn)); + } } // end if time has changed since last update } // end if it might be time to report the fps } // end if captureResult