tosiara
commented
8 months ago Looks like you have defined both movie_output onand movie_extpipe_use on, and therefore you get two video files, right?
Closed joeschmitt closed 8 months ago
tosiara
commented
8 months ago Looks like you have defined both movie_output onand movie_extpipe_use on, and therefore you get two video files, right?
joeschmitt
commented
8 months ago No I have only one video file. And yes both settings are on. "movie_output on" I understood is needed to create videos after a motion event is detected. And "movie_extpipe_use on" to tell motion to use the external program given by movie_extpipe.
And my experience after usage of motion for a longer time seems to support this. For example when I tried to integrate sound recording with the help of movie_extpipe and ffmpeg (which didn't work) I set movie_extpipe_use off for test which leads to the usage of the own motion encoder as expected . And movie_output on was still on. I looked a little bit into the source code for the on_movie_end (the only one I go deeper) and found that it's called for two cases, but I didn't dig deeper.
To verify it, I will check with my called program if two recordings with corresponding files can be detected.
joeschmitt
commented
8 months ago It seems to happen as I told. This is the log of my called program. The log shows that the called program can verify the file with extension mp4 (line 29 of program). The next log line 43 logs the call to another program. Afterwards lockrd is called again but now the filename has no extension mp4. This is the reason for that the line numbers between 43 and 45 are interrupted by another call to lockrd signaled by the fresh starting of the line numbers. And in the second case the message of line 29 that a recording file already exists is not logged instead the log shows that my next test afterwards for the missing extension is true and the log says that the second call is ignored means program exits then. This pattern happens each time motion detects an event. Hope this helps a little bit.
time=2024-02-12T18:40:06.306+01:00 level=DEBUG source=/home/pi/goprog/lockrd/lockrd.go:26 msg="lockrd called for movie file: [/home/pi/motion/lockrd /home/pi/motion/ramdisk/2024-02-1218-40-05.mp4]" time=2024-02-12T18:40:06.306+01:00 level=DEBUG source=/home/pi/goprog/lockrd/lockrd.go:29 msg="lockrd /home/pi/motion/ramdisk/2024-02-1218-40-05.mp4 exists after start" time=2024-02-12T18:40:06.306+01:00 level=DEBUG source=/home/pi/goprog/lockrd/lockrd.go:43 msg="lockrd calling rec_audio with:/home/pi/motion/ramdisk/2024-02-1218-40-05.mp4" time=2024-02-12T18:40:06.307+01:00 level=DEBUG source=/home/pi/goprog/lockrd/lockrd.go:26 msg="lockrd called for movie file: [/home/pi/motion/lockrd /home/pi/motion/ramdisk/2024-02-1218-40-05]" time=2024-02-12T18:40:06.307+01:00 level=DEBUG source=/home/pi/goprog/lockrd/lockrd.go:33 msg="lockrd second call which makes no sense and can be identified due to a missing file extension. Return immediately" time=2024-02-12T18:40:06.312+01:00 level=DEBUG source=/home/pi/goprog/rec_audio/main.go:45 msg="rec_audio called for movie file: [/home/pi/motion/rec_audio /home/pi/motion/ramdisk/2024-02-12__18-40-05.mp4]"
tomwhipple
commented
8 months ago I'm seeing similar behavior, with the on_movie_start and on_movie_end called multiple times, several seconds apart. It also appears that the movie may be getting overwritten at the same time.
tosiara
commented
8 months ago Do you also have defined both movie and extpipe?
tomwhipple
commented
8 months ago No, I don't have extpipe defined at all.
I think this was caused by setting max_movie_time to 11. If an event took longer than those 11 seconds, it seems like the event was reset, both triggering a new on_movie_end, and then beginning with a new on_movie_start as well as overwriting the video file from the prior interval. Now that I've removed that limit, the problem seems to have been resolved.
joeschmitt
commented
8 months ago I think you mean movie_max_time. The standard value is 120 (seconds) and I have set it to 60. So if your finding is right that every given value above 11 will show the observed behavior then it's a fault in my world.
tomwhipple
commented
8 months ago I'm using an older config syntax I think... https://github.com/tomwhipple/camera-watcher/blob/9f515789f90477660c5fa458efd1463fd869d245/etc/motion/motion.conf#L237
But in any case, I do think it's a bug, because I see the same behavior at every multiple of this setting. That might be OK if each video wasn't overwritten and '%v' incremented, but the current behavior caused a bunch of other issues downstream that had puzzled me for a while.
If I get the motivation I'll see about tracking it down further and submitting a PR, but no promises. :/
Mr-Dave
commented
8 months ago These are different issues and not a bugs.
First, specification of both a ext_pipe movie as well as movie_output causes two movies to be created and therefore the on_event's are called for each movie. This can not be observed via the OP because both of the movie file names are identical. If the movie names are changed between ext_pipe and movie_output is will become more apparent.
Next, there is an assumption was that the %v should be unique to each movie. This is not correct. %v is the event number not the movie number. Since there can be multiple movies per event, then if the name of the file only specifies an event number, it will get overwritten as new movies occur over the course of the event. Adding a time parameter to the movie file name will clarify this.
tomwhipple
commented
8 months ago I stand corrected. Further inspection shows that time was being set in the definition of %C, which I was then using for the filename, so I've added a minute/second parameter to the filename, which I expect will fully resolve my case.
Thanks @Mr-Dave!!
Did you read the guide?
Yes
What is the base version number of Motion being used?
4.6.x
What was the install method?
Installed via package tool
What is base architecture?
ARM-32bit
What is the distro being used?
Raspbian
Disto version number
Raspbian GNU/Linux 11 (bullseye)
Camera type(s) being used?
PI cam via libcamerify
Describe the issue/problem and steps to reproduce
The "problem" I think is that external programs are called twice. Once when the recording ends and a second time when the pipe to the external ffmpeg program is closed. For the first time the name of the file into which the recording happens contains the extension ".mp4" and the second time the extension is missing. This is can also be seen in the motion.log (log_level 9)
In my called programs I'm able to ignore the second call based on the missing extension. I stumbled over this when I tried to understand the behavior of my called programs. The programs are written (golang) by myself so I can do the logging as I want/need.
So what I try to understand is if this an intended behavior or a fault. I couldn't find an explanation based on the config options and it feels more like an error then a feature, or?
Motion log output at log_level 8