Could not find matching start/end segment

[k0stett]

I have a lot of warnings like that:

[viseron.components.ffmpeg.recorder.openipctest] - Could not find matching start segment. Using earliest possible
[viseron.components.ffmpeg.recorder.nov32_3] - Could not find matching end segment. Using latest possible
[viseron.components.ffmpeg.recorder.nov32_6] - Could not find matching start segment. Using earliest possible
[viseron.components.ffmpeg.recorder.nov32_3] - Could not find matching start segment. Using earliest possible, message repeated 2 times

I use smb/cifs mount for folder with recordings and --tmpfs /tmp in docker run command. Also recorder section in config.yaml in each camera have segments_folder: /tmp parameter. What's wrong? How to debug recorder?

[roflcoopter]

Could you show your config?
If you check the recordings, do you feel like they miss the beginning of events?

The error can happen naturally when you stop/start cameras.
For instance, if you just started the camera and it instantly detects something, the calculated start of the event (based on the lookback config option) will be back in time where there were no generated segments because the camera was stopped at that point

[k0stett]

Could you show your config?

Yep.

ffmpeg:
  camera:
    nov32_3:
      name: Nov32-3
      host: 10.100.2.22
      port: 554
      path: /user=admin_password=PaSsWoRd_channel=1_stream=0.sdp?real_stream
      stream_format: rtsp
      #width: 2592
      #height: 1952
      fps: 15
      codec: h264_cuvid
      audio_codec: aac
      substream:
        path: /user=admin_password=PaSsWoRd_channel=1_stream=1.sdp?real_stream
        stream_format: rtsp
        width: 800
        height: 448
        fps: 15
        codec: h264_cuvid
        audio_codec: aac
        port: 554
      recorder:
        retain: 60
        lookback: 10
        idle_timeout: 5
        codec: hevc_nvenc
        audio_codec: aac
        segments_folder: /tmp
        filename_pattern: "%H-%M-%S"
        extension: mp4
        thumbnail:
          filename_pattern: "%H-%M-%S"
    nov32_6:
      name: Nov32-6
      host: 10.100.2.24
      port: 554
      path: /user=admin_password=PaSsWoRd_channel=1_stream=0.sdp?real_stream
      stream_format: rtsp
      #width: 2592
      #height: 1952
      fps: 15
      codec: h264_cuvid
      audio_codec: aac
      substream:
        path: /user=admin_password=PaSsWoRd_channel=1_stream=1.sdp?real_stream
        stream_format: rtsp
        width: 800
        height: 448
        fps: 15
        codec: h264_cuvid
        audio_codec: aac
        port: 554
      recorder:
        retain: 60
        lookback: 10
        idle_timeout: 5
        codec: hevc_nvenc
        audio_codec: aac
        segments_folder: /tmp
        filename_pattern: "%H-%M-%S"
        extension: mp4
        thumbnail:
          filename_pattern: "%H-%M-%S"
    openipctest:
      name: openipctest
      host: 10.100.2.30
      port: 554
      path: /stream=0
      username: admin
      password: PaSsWoRd
      stream_format: rtsp
      width: 1920
      height: 1080
      fps: 15
      audio_codec: aac
      codec: h264_cuvid
      # substream: # disabled due to ffprobe shitdown on it
      #   path: /stream=1
      #   stream_format: rtsp
      #   width: 640
      #   height: 360
      #   fps: 10
      #   codec: h264_cuvid
      #   port: 554
      recorder:
        retain: 60
        lookback: 10
        idle_timeout: 5
        codec: hevc_nvenc
        segments_folder: /tmp
        filename_pattern: "%H-%M-%S"
        extension: mp4
        thumbnail:
          filename_pattern: "%H-%M-%S"


mog2:
  motion_detector:
    cameras:
      nov32_3:
        trigger_recorder: true
        area: 0.02
        width: 400
        height: 300
      nov32_6:
        trigger_recorder: true
        area: 0.02
        width: 400
        height: 300
      openipctest:
        trigger_recorder: true
        area: 0.02
        width: 400
        height: 300

nvr:
  nov32_3:
  nov32_6:
  openipctest:

webserver:

logger:
  default_level: warning

mqtt:
  broker: 10.100.2.127
  port: 1883
  username: viseron
  password: "PaSsWoRd"
  home_assistant:

If you check the recordings, do you feel like they miss the beginning of events?

Yes, but in most recordings, endings is missing.

The error can happen naturally when you stop/start cameras.

Cameras working 24/7.

For instance, if you just started the camera and it instantly detects something, the calculated start of the event (based on the lookback config option) will be back in time where there were no generated segments because the camera was stopped at that point

Situation described by you happens when viseron starts. Cameras working 24/7 with reserved DC supply.

[k0stett]

I've trying to turn on debug and see what happens.
Good one:

[2023-05-16 13:01:09] [INFO    ] [viseron.components.ffmpeg.recorder.buh] - Stopping recorder
[2023-05-16 13:01:09] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Pausing segment cleanup
[2023-05-16 13:01:09] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Concatenating segments
**[2023-05-16 13:01:10] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - /tmp/buh/20230516130106.mp4 is locked. Trying again in 1 second, message repeated 3 times**
[2023-05-16 13:01:13] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Segment information: {'20230516130106.mp4': {'start_time': 1684231266.0, 'end_time': 1684231271.643}, '20230516130101.mp4': {'start_time': 1684231261.0, 'end_time': 1684231265.508}, '20230516130056.mp4': {'start_time': 1684231256.0, 'end_time': 1684231261.632}, '20230516130051.mp4': {'start_time': 1684231251.0, 'end_time': 1684231255.512}, '20230516130046.mp4': {'start_time': 1684231246.0, 'end_time': 1684231251.644}, '20230516130041.mp4': {'start_time': 1684231241.0, 'end_time': 1684231245.52}}
[2023-05-16 13:01:13] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Start event: 1684231247.770126, segment: 20230516130046.mp4
[2023-05-16 13:01:13] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - End event: 1684231269.620963, segment: 20230516130106.mp4
[2023-05-16 13:01:13] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Concatenation command: ffmpeg -hide_banner -loglevel error -y -protocol_whitelist file,pipe -f concat -safe 0 -i - -c:v hevc_nvenc -c:a copy -movflags +faststart /recordings/buh/2023-05-16/13-00-57.mp4
[2023-05-16 13:01:13] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Segment script: 
file 'file:/tmp/buh/20230516130046.mp4'
inpoint 1
file 'file:/tmp/buh/20230516130051.mp4'
file 'file:/tmp/buh/20230516130056.mp4'
file 'file:/tmp/buh/20230516130101.mp4'
file 'file:/tmp/buh/20230516130106.mp4'
outpoint 3
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Removing segment: 20230516130046.mp4
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Removing segment: 20230516130051.mp4
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Removing segment: 20230516130056.mp4
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Removing segment: 20230516130101.mp4
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Segments concatenated
[2023-05-16 13:01:14] [DEBUG   ] [viseron.components.ffmpeg.recorder.buh] - Resuming segment cleanup

As it decribed in log, it is trying to access locked segment each second while it start to be accessible. But sometimes it is giving up with trys and immedately says us "Could not fing matching segment":

[2023-05-16 13:04:28] [INFO    ] [viseron.components.ffmpeg.recorder.nov32_6] - Stopping recorder
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Pausing segment cleanup
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Concatenating segments
**[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - /tmp/nov32_6/20230516130420.mp4 is locked. Trying again in 1 second**
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Segment information: {'20230516130420.mp4': {'start_time': 1684231460.0, 'end_time': 1684231466.039}, '20230516130416.mp4': {'start_time': 1684231456.0, 'end_time': 1684231460.022}, '20230516130410.mp4': {'start_time': 1684231450.0, 'end_time': 1684231456.054}, '20230516130406.mp4': {'start_time': 1684231446.0, 'end_time': 1684231450.038}, '20230516130400.mp4': {'start_time': 1684231440.0, 'end_time': 1684231446.07}, '20230516130356.mp4': {'start_time': 1684231436.0, 'end_time': 1684231440.054}}
[2023-05-16 13:04:28] [WARNING ] [viseron.components.ffmpeg.recorder.nov32_6] - Could not find matching end segment. Using latest possible
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Start event: 1684231447.408139, segment: 20230516130406.mp4
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - End event: 1684231466.374729, segment: 20230516130420.mp4
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Concatenation command: ffmpeg -hide_banner -loglevel error -y -protocol_whitelist file,pipe -f concat -safe 0 -i - -c:v hevc_nvenc -c:a aac -movflags +faststart /recordings/nov32_6/2023-05-16/13-04-17.mp4
[2023-05-16 13:04:28] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Segment script: 
file 'file:/tmp/nov32_6/20230516130406.mp4'
inpoint 1
file 'file:/tmp/nov32_6/20230516130410.mp4'
file 'file:/tmp/nov32_6/20230516130416.mp4'
file 'file:/tmp/nov32_6/20230516130420.mp4'
outpoint 6
[2023-05-16 13:04:36] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Removing segment: 20230516130406.mp4
[2023-05-16 13:04:36] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Removing segment: 20230516130410.mp4
[2023-05-16 13:04:36] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Removing segment: 20230516130416.mp4
[2023-05-16 13:04:36] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Segments concatenated
[2023-05-16 13:04:36] [DEBUG   ] [viseron.components.ffmpeg.recorder.nov32_6] - Resuming segment cleanup

Seems like a bug. So cast @roflcoopter

[k0stett]

I'm a bit foolish, it's writing OK cause 0.3 seconds which produces warning is not an important thing. But sometimes segments lost in the middle of recording and it's creepy when watching it :))

[k0stett]

And losing segments in a middle is an achievment of incorrectly configured motion detection. So I take Background Subtractor instead of mog2 and make nextstepping configuration:

ffmpeg:
  camera:
    camera_one:
      ...
      recorder:
        ...
        lookback: 10
        idle_timeout: 10
        ...

background_subtractor:
  motion_detector:
    cameras:
      camera_one:
        fps: 4
        trigger_recorder: true
        recorder_keepalive: true
        max_recorder_keepalive: 300
        area: 0.002
        width: 640
        height: 480

And now all works perfectly nice.