Fake motion event triggered when shedule period changed and recording never stopped

[emjas92]

This similar to my previous ticket #617 but is different enough to start a new ticket.

During a mode change sequence (04:17:06), motion was detected (04:17:08) and video capture started (04:17:14), but then the capture never stopped (video is just split every 5 minutes). The mode change commands seem to have interfered with the motion capture and prevented the Stop frames from counting, however I'm unsure why.

Please see the attached schedule log and first video segment (with %c %f).

[username7291]

Can confirm the bug but not the Reason. For me it seems "{2021/05/16 08:03:26} Reset motion state", 08:03:24 was the last real motion. Seems the endless Recoding of no motion stops if a real Motion is detected again(08:38).

[2021/05/16 08:03:26] Stop capture requested [2021/05/16 08:03:26] Send ca 0 {2021/05/16 08:03:26} Capturing stopped {2021/05/16 08:03:26} Add /var/www/html/media/16052021_080324.mp4 to Box Queue at pos 1 {2021/05/16 08:03:26} Reset motion state {2021/05/16 08:03:27} Start boxing /tmp//16052021_080324.h264 to /var/www/html/media/16052021_080324.mp4 Queue pos 1 {2021/05/16 08:03:28} Finished boxing /var/www/html/media/16052021_080324.mp4 from Box Queue at pos 1 {2021/05/16 08:03:28} Removed item from Box Queue [2021/05/16 08:03:28] Start capture requested from Pipe [2021/05/16 08:03:28] Send ca 1 {2021/05/16 08:03:28} Capturing started {2021/05/16 08:06:08} Stopping video from timer {2021/05/16 08:06:08} Capturing stopped {2021/05/16 08:06:08} Add /var/www/html/media/16052021_080328.mp4 to Box Queue at pos 2 {2021/05/16 08:06:08} Restarting next split of 160 seconds {2021/05/16 08:06:08} Capturing started {2021/05/16 08:06:09} Start boxing /tmp//16052021_080328.h264 to /var/www/html/media/16052021_080328.mp4 Queue pos 2 {2021/05/16 08:06:34} Finished boxing /var/www/html/media/16052021_080328.mp4 from Box Queue at pos 2 {2021/05/16 08:06:34} Removed item from Box Queue {2021/05/16 08:08:48} Stopping video from timer {2021/05/16 08:08:48} Capturing stopped {2021/05/16 08:08:48} Add /var/www/html/media/16052021_080608.mp4 to Box Queue at pos 3 {2021/05/16 08:08:49} Restarting next split of 160 seconds

[roberttidey]

I'll look into this. I haven't experienced it myself but it is possible it is a combination of using video split during the period change. I don't use video split myself for motion triggered applications as, normally, the video segments should be relatively short for those.

[username7291]

The video split i have for self kill protection on snow/rain. There was no split on the last right detected motion, only after the unexpected endless record. reset_motion_state() do a reset if its in a detection, "motion_state=0" then the detection routine cant hit the stop condition(case 1:). only if motion_state goes to 1 again like on a motion detection. My guess is, why ever reset_motion_state() is called, it should contain send_motion_stop();

[emjas92]

Hi Bob.

Did you get a chance to look at this one?

I've had another instance where video recording started spontaneously when the period changed (07:03:01), and did not stop until there was real motion detected (07:20:03).

My period 2 start command is md 1;em auto;mt 30;bi 8500000

Nothing was happeing at the time the period changed (i.e. no recording in progress). Any idea why this might happen?

[2022/07/22 06:42:56] Scheduled management tasks. Next at 1658432576 [2022/07/22 07:03:00] New period detected 2 [2022/07/22 07:03:00] Send md 1 {2022/07/22 07:03:00} Internal motion detection started {2022/07/22 07:03:00} recommended video buffer size 65536 {2022/07/22 07:03:00} h264 size set to 131072 {2022/07/22 07:03:00} recommended video buffers 1 {2022/07/22 07:03:00} h264 buffers set to recommended 1 {2022/07/22 07:03:00} Set up internal detect width=82 height=61 {2022/07/22 07:03:00} Motion mask /var/www/rpicam/mask.pgm loaded {2022/07/22 07:03:01} DEBUG 3 {2022/07/22 07:03:01} Executing macro /var/www/rpicam/macros/motion_event.sh "1" & {2022/07/22 07:03:01} send smd 1 [2022/07/22 07:03:02] Send em auto {2022/07/22 07:03:02} Change: exposure_mode = auto [2022/07/22 07:03:04] Send mt 30 {2022/07/22 07:03:04} Change: motion_threshold = 30 [2022/07/22 07:03:06] Send bi 8500000 {2022/07/22 07:03:06} Change: video_bitrate = 8500000 {2022/07/22 07:03:06} recommended video buffer size 65536 {2022/07/22 07:03:06} h264 size set to 131072 {2022/07/22 07:03:06} recommended video buffers 1 {2022/07/22 07:03:06} h264 buffers set to recommended 1 {2022/07/22 07:03:06} Set up internal detect width=82 height=61 {2022/07/22 07:03:06} Motion mask /var/www/rpicam/mask.pgm loaded {2022/07/22 07:03:07} DEBUG 3 [2022/07/22 07:03:08] Send mi /var/www/rpicam/mask.pgm {2022/07/22 07:03:08} Change: motion_image = /var/www/rpicam/mask.pgm [2022/07/22 07:03:10] Send sy motion_event.sh dawn {2022/07/22 07:03:10} Executing macro /var/www/rpicam/macros/motion_event.sh dawn & [2022/07/22 07:03:12] Start capture requested from Pipe [2022/07/22 07:03:12] Send ca 1 {2022/07/22 07:03:12} Capturing with split of 300 seconds {2022/07/22 07:03:12} Capturing started {2022/07/22 07:08:12} Stopping video from timer {2022/07/22 07:08:12} Capturing stopped {2022/07/22 07:08:12} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220722_070312_0000.h264" & {2022/07/22 07:08:12} DEBUG 3 {2022/07/22 07:08:12} Restarting next split of 300 seconds {2022/07/22 07:08:12} Capturing started {2022/07/22 07:13:12} Stopping video from timer {2022/07/22 07:13:12} Capturing stopped {2022/07/22 07:13:12} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220722_070812_0000.h264" & {2022/07/22 07:13:12} Restarting next split of 300 seconds {2022/07/22 07:13:12} Capturing started {2022/07/22 07:18:12} Stopping video from timer {2022/07/22 07:18:12} Capturing stopped {2022/07/22 07:18:12} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220722_071312_0000.h264" & {2022/07/22 07:18:12} DEBUG 3 {2022/07/22 07:18:12} Restarting next split of 300 seconds {2022/07/22 07:18:12} Capturing started {2022/07/22 07:20:03} Executing macro /var/www/rpicam/macros/motion_event.sh "1" & {2022/07/22 07:20:03} send smd 1 [2022/07/22 07:20:03] Start capture requested from Pipe [2022/07/22 07:20:03] Send ca 1 {2022/07/22 07:20:03} Capturing with split of 300 seconds {2022/07/22 07:20:03} Already capturing. Ignore {2022/07/22 07:20:22} Executing macro /var/www/rpicam/macros/motion_event.sh "0" & {2022/07/22 07:20:22} send smd 0 [2022/07/22 07:20:22] Stop capture requested [2022/07/22 07:20:22] Send ca 0 {2022/07/22 07:20:22} Capturing stopped {2022/07/22 07:20:22} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220722_071812_0000.h264" & {2022/07/22 07:20:22} DEBUG 3

[roberttidey]

The motion_threshold of 30 is quite low making it very sensitive to triggering on. I normally use between 250 and 500. I would also put parameter changes like this first in a period change before enabling detection.

You can also put a ca 0 at the start if you want to ensure any existing capture is stopped at that point.

[emjas92]

Appreciate the quick response and suggestions.

I've moved md 1 to the end. It's there to ensure detection is always enabled on boot.

Would changing parameters while a recording is in progress cause problems? Should ca 0 be used for that reason?

I use a low threshold as I've masked out large sections of the view to avoid capturing swaying plants and passing cars, which leaves only about a 3rd of the frame left to detect, and there's limited lighting at night.

In any case, I'll refine my motion settings and monitor it.

[emjas92]

Here's another instance where I did not have md 1 in the schedule.

A motion event was triggered when period was changed. Dawn period: em auto;mt 250; bi 8500000;mi /var/www/rpicam/masks/outdoor.pgm

The fake event was triggered at 06:24:03 however the recorded video pre-buffer starts at 06:24:07 so I can't see how the image was changing, though I suspect the exposure adjustment was detected as 'motion'.

The video recording was started ca 1 at 06:24:13 after all the period config. %c does not reach the threshold, and %f remains at 0 the whole time.

Somehow this event was 'forgotten' and the video capture was not stopped.

[2022/08/25 05:42:18] Scheduled management tasks. Next at 1661366538 [2022/08/25 06:24:03] New period detected 2 [2022/08/25 06:24:03] Send em auto {2022/08/25 06:24:03} Change: exposure_mode = auto {2022/08/25 06:24:03} Executing macro /var/www/rpicam/macros/motion_event.sh "1" & {2022/08/25 06:24:03} send smd 1 [2022/08/25 06:24:05] Send mt 250 {2022/08/25 06:24:05} Change: motion_threshold = 250 [2022/08/25 06:24:07] Send bi 8500000 {2022/08/25 06:24:07} Change: video_bitrate = 8500000 {2022/08/25 06:24:07} recommended video buffer size 65536 {2022/08/25 06:24:07} h264 size set to 131072 {2022/08/25 06:24:07} recommended video buffers 1 {2022/08/25 06:24:07} h264 buffers set to recommended 1 {2022/08/25 06:24:07} Set up internal detect width=82 height=61 {2022/08/25 06:24:07} Motion mask /var/www/rpicam/masks/outdoor_night.pgm loaded {2022/08/25 06:24:08} DEBUG 3 [2022/08/25 06:24:09] Send mi /var/www/rpicam/masks/outdoor.pgm {2022/08/25 06:24:09} Change: motion_image = /var/www/rpicam/masks/outdoor.pgm [2022/08/25 06:24:13] Start capture requested from Pipe [2022/08/25 06:24:13] Send ca 1 {2022/08/25 06:24:13} Capturing with split of 300 seconds {2022/08/25 06:24:13} Capturing started {2022/08/25 06:29:13} Stopping video from timer {2022/08/25 06:29:13} Capturing stopped {2022/08/25 06:29:13} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220825_062413_0000.h264" & {2022/08/25 06:29:13} DEBUG 3 {2022/08/25 06:29:13} Restarting next split of 300 seconds {2022/08/25 06:29:13} Capturing started {2022/08/25 06:34:13} Stopping video from timer {2022/08/25 06:34:13} Capturing stopped {2022/08/25 06:34:13} Executing macro /var/www/rpicam/macros/end_vid.sh "/var/www/rpicam/media/20220825_062913_0000.h264" & {2022/08/25 06:34:13} DEBUG 3 {2022/08/25 06:34:13} Restarting next split of 300 seconds {2022/08/25 06:34:13} Capturing started ... continuing until camera manually stopped

I'll try swap the order of commands and see if that helps (e.g. mask mi needs to be set first as the buffer bi reloads the existing mask).

[roberttidey]

It is possible that a camera setting change could cause a shift that could end up triggering motion detect but it should still take everal frames for the trigger to condition to build up.

You might find it tricky to see this on live video if it happens quickly. What you could do is use the video buffer setting so that it includes video leading up to the trigger in the captured video recording. That way when you view the capture you can see the conditions leading up to the trigger.