search

silvanmelchior / RPi_Cam_Web_Interface

A web interface for the RPi Cam
MIT License
1.54k stars 493 forks source link

Video not stopping after Max_Capture anymore #382

Open konstantinj opened 6 years ago

konstantinj commented 6 years ago

Hi,

since update from 6.4.05 to 6.4.13 my motion triggered videos are way longer than before. Looks like there are not enough still frames to stop but that's the reason I have set Max_Capture to 120. Now videos are sometimes more than 30 minutes.

Here are my uconfig and schedule.json

anno_text_size 30 exposure_mode sports rotation 180 hflip 0 vflip 0 width 768 quality 50 video_width 1296 video_height 972 MP4Box 0 image_quality 100 motion_detection true motion_external false motion_noise 1000 motion_threshold 100 motion_stopframes 450

{"Fifo_In":"\/var\/www\/html\/FIFO1","Fifo_Out":"\/var\/www\/html\/FIFO","Cmd_Poll":"0.03","Mode_Poll":"10","Management_Interval":"3600","Management_Command":"","PurgeVideo_Hours":"0","PurgeImage_Hours":"0","PurgeLapse_Hours":"0","GMTOffset":"0","PurgeSpace_ModeEx":"1","PurgeSpace_Level":"10","DawnStart_Minutes":"-180","DayStart_Minutes":"0","DayEnd_Minutes":"0","DuskEnd_Minutes":"180","Latitude":"52.00","Longtitude":"0.00","Max_Capture":"120","DayMode":"0","AutoCapture_Interval":"0","AutoCamera_Interval":"0","Days":[["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"],["0","1","2","3","4","5","6"]],"Commands_On":["ca 1","ca 1","ca 1","ca 1","ca 1","","","","","","","","","","","",""],"Commands_Off":["ca 0","ca 0","ca 0","ca 0","ca 0","","","","","","","","","","","",""],"Modes":["","ec 0","ec 0","ec 0","ec 0","","","","","","","","","","","",""],"Times":["09:00","10:00","11:00","12:00","13:00","14:00","15:00","16:00","17:00","18:00","19:00","20:00"]}

I'm still investigating but wanted you to know.

roberttidey commented 6 years ago

OK. I did a quick Max_Capture test on 6.4.13 and it seemed OK. You should see something like following in log.

`[2017/12/10 13:10:21] Start capture requested from Pipe

[2017/12/10 13:10:21] Send ca 1

{2017/12/10 13:10:21} Capturing started

[2017/12/10 13:10:33] Maximum Capture reached. Sending off command

[2017/12/10 13:10:33] Send ca 0

{2017/12/10 13:10:33} Capturing stopped

` One thing I did notice was the manual button to stop the video is disabled when video is started from a motion trigger, which is a bit irritating. So I have changed that.

Let me know if you find anything, or if not then post the bit of the log around one of the extended recordings.

konstantinj commented 6 years ago

Today there was another video of this kind. This is the log:

{2017/12/11 07:40:08} send smd 1 [2017/12/11 07:40:08] Start capture requested from Pipe [2017/12/11 07:40:08] Send ca 1 {2017/12/11 07:40:08} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_0908_20171211_074008.mp4" & {2017/12/11 07:40:08} Capturing started {2017/12/11 07:40:09} Capturing image {2017/12/11 07:40:12} Capturing image {2017/12/11 07:40:16} Capturing image {2017/12/11 07:40:19} Capturing image {2017/12/11 07:40:22} Capturing image {2017/12/11 07:40:25} Capturing image {2017/12/11 07:40:28} Capturing image {2017/12/11 07:40:31} Capturing image {2017/12/11 07:40:34} Capturing image {2017/12/11 07:40:37} Capturing image {2017/12/11 07:40:40} Capturing image {2017/12/11 07:40:43} Capturing image {2017/12/11 07:40:46} Capturing image {2017/12/11 07:40:49} Capturing image {2017/12/11 07:40:52} Capturing image {2017/12/11 07:40:55} Capturing image {2017/12/11 07:40:58} send smd 0 [2017/12/11 07:41:00] Stop capture requested [2017/12/11 07:41:00] Send ca 0 {2017/12/11 07:41:00} Capturing image {2017/12/11 07:41:00} Already capturing. Ignore {2017/12/11 07:41:03} Capturing image {2017/12/11 07:41:06} Capturing image {2017/12/11 07:41:09} Capturing image {2017/12/11 07:49:16} send smd 1 [2017/12/11 07:49:16] Start capture requested from Pipe [2017/12/11 07:49:16] Send ca 1 {2017/12/11 07:49:16} Already capturing. Ignore [2017/12/11 07:51:18] Maximum Capture reached. Sending off command [2017/12/11 07:51:18] Send ca 0 {2017/12/11 07:51:18} Capturing stopped {2017/12/11 07:51:18} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_0908_20171211_074008.mp4" {2017/12/11 07:52:37} send smd 0

I'm still using macros for doing the mp4 creation to also include the audio. Also I'm doing always some image captures also on motion trigger. And I'm running inside Docker. But I haven't changed any configuration and it was working before.

But: I have 5 cameras and checked now all of them in details and found this behaviour only on one of it. Still strange, still investigating.

roberttidey commented 6 years ago

It sounds like it might be associated with a timing issue which may be exposed because you have lots of other stuff in the background and docker may slow things down a bit.

There is definitely something strange in the log around 07:40:58. Motion detection has signalled a stop and this is correctly translated into a request to stop video. However, it produces a Already capturing. Ignore message which should only happen when a request to start a video is received and it is already recording. So I don't understand how that could have happened.

What is controlling the image capture? Why does it stop at 07:41:09. Is it controlled by start_vid.sh?

Is anything else sending commands into the FIFO? That can cause command corruption. There are multiple FIFOs that can be set up and used so this can't happen.

konstantinj commented 6 years ago

Hi, it happened again on another camera. I got a file vi_3051_20180115_211635 with more than 800mb (~32min). Surprisingly it was properly boxed with mp3 - I mean that process must have run for a long time. And I wonder y it finally stopped. Here's the log:

{2018/01/15 21:15:42} send smd 1 [2018/01/15 21:15:42] Start capture requested from Pipe [2018/01/15 21:15:42] Send ca 1 {2018/01/15 21:15:42} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2853_20180115_211542.mp4" & {2018/01/15 21:15:42} Capturing started {2018/01/15 21:15:43} Capturing image {2018/01/15 21:15:46} Capturing image {2018/01/15 21:15:49} Capturing image {2018/01/15 21:15:52} Capturing image {2018/01/15 21:15:55} Capturing image {2018/01/15 21:15:58} Capturing image {2018/01/15 21:16:01} Capturing image {2018/01/15 21:16:04} Capturing image {2018/01/15 21:16:07} Capturing image {2018/01/15 21:16:10} Capturing image {2018/01/15 21:16:12} send smd 0 [2018/01/15 21:16:12] Stop capture requested [2018/01/15 21:16:12] Send ca 0 {2018/01/15 21:16:12} Capturing stopped {2018/01/15 21:16:12} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2853_20180115_211542.mp4" {2018/01/15 21:16:34} send smd 1 [2018/01/15 21:16:34] Start capture requested from Pipe [2018/01/15 21:16:34] Send ca 1 {2018/01/15 21:16:35} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2854_20180115_211635.mp4" & {2018/01/15 21:16:35} Capturing started {2018/01/15 21:16:36} Capturing image {2018/01/15 21:16:39} Capturing image {2018/01/15 21:16:42} Capturing image {2018/01/15 21:16:45} Capturing image {2018/01/15 21:16:48} Capturing image {2018/01/15 21:16:51} Capturing image {2018/01/15 21:16:56} Capturing image {2018/01/15 21:17:00} Capturing image {2018/01/15 21:17:03} Capturing image {2018/01/15 21:17:06} Capturing image {2018/01/15 21:17:09} Capturing image {2018/01/15 21:17:15} send smd 0 [2018/01/15 21:17:15] Stop capture requested [2018/01/15 21:17:15] Send ca 0 {2018/01/15 21:17:17} Capturing image {2018/01/15 21:17:18} Capturing image {2018/01/15 21:17:19} Already capturing. Ignore {2018/01/15 21:17:20} Capturing image {2018/01/15 21:17:23} Capturing image {2018/01/15 21:17:26} Capturing image {2018/01/15 21:17:29} Capturing image {2018/01/15 21:17:32} Capturing image {2018/01/15 21:17:37} Capturing image {2018/01/15 21:17:39} Capturing image [2018/01/15 21:29:57] Scheduled management tasks. Next at 1516051797 {2018/01/15 21:48:42} send smd 1 [2018/01/15 21:48:42] Start capture requested from Pipe [2018/01/15 21:48:42] Send ca 1 {2018/01/15 21:48:42} Already capturing. Ignore {2018/01/15 21:49:00} send smd 0 [2018/01/15 21:49:00] Stop capture requested [2018/01/15 21:49:00] Send ca 0 {2018/01/15 21:49:00} Capturing stopped {2018/01/15 21:49:00} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2854_20180115_211635.mp4" {2018/01/15 21:57:10} send smd 1 [2018/01/15 21:57:32] Start capture requested from Pipe [2018/01/15 21:57:32] Send ca 1 {2018/01/15 21:57:33} send smd 0 [2018/01/15 21:57:35] Stop capture requested [2018/01/15 21:57:35] Send ca 0 {2018/01/15 21:57:48} send smd 1 [2018/01/15 21:58:08] Start capture requested from Pipe [2018/01/15 21:58:08] Send ca 1 {2018/01/15 21:58:51} send smd 0 [2018/01/15 21:58:51] Stop capture requested [2018/01/15 21:58:51] Send ca 0 {2018/01/15 21:59:01} send smd 1 [2018/01/15 21:59:01] Start capture requested from Pipe [2018/01/15 21:59:01] Send ca 1 [2018/01/15 22:01:03] Maximum Capture reached. Sending off command [2018/01/15 22:01:12] Send ca 0 {2018/01/15 22:01:16} send smd 0 [2018/01/15 22:01:16] Stop capture request ignored, already stopped {2018/01/15 22:02:26} send smd 1 [2018/01/15 22:02:26] Start capture requested from Pipe [2018/01/15 22:02:26] Send ca 1 {2018/01/15 22:03:19} send smd 0 [2018/01/15 22:03:22] Stop capture requested [2018/01/15 22:03:22] Send ca 0 {2018/01/15 22:07:16} send smd 1 [2018/01/15 22:07:16] Start capture requested from Pipe [2018/01/15 22:07:16] Send ca 1 {2018/01/15 22:07:38} send smd 0 [2018/01/15 22:07:38] Stop capture requested [2018/01/15 22:07:38] Send ca 0 {2018/01/15 22:08:27} send smd 1 [2018/01/15 22:08:27] Start capture requested from Pipe [2018/01/15 22:08:27] Send ca 1 {2018/01/15 22:08:49} send smd 0 [2018/01/15 22:08:49] Stop capture requested [2018/01/15 22:08:49] Send ca 0 {2018/01/15 22:09:50} send smd 1 [2018/01/15 22:09:50] Start capture requested from Pipe [2018/01/15 22:09:50] Send ca 1 {2018/01/15 22:11:19} send smd 0 [2018/01/15 22:11:52] Maximum Capture reached. Sending off command [2018/01/15 22:11:56] Send ca 0 [2018/01/15 22:11:58] Stop capture request ignored, already stopped {2018/01/15 22:13:57} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2855_20180115_221357.mp4" & {2018/01/15 22:13:57} Capturing started {2018/01/15 22:13:57} Capturing stopped {2018/01/15 22:13:57} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2855_20180115_221357.mp4" {2018/01/15 22:14:03} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2856_20180115_221403.mp4" & {2018/01/15 22:14:03} Capturing started {2018/01/15 22:14:04} Capturing stopped {2018/01/15 22:14:04} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2856_20180115_221403.mp4" {2018/01/15 22:14:07} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2857_20180115_221407.mp4" & {2018/01/15 22:14:07} Capturing started {2018/01/15 22:14:08} Capturing stopped {2018/01/15 22:14:08} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2857_20180115_221407.mp4" {2018/01/15 22:14:11} Executing macro /var/www/html/macros/start_vid.sh "/var/www/html/media/vi_2858_20180115_221411.mp4" & {2018/01/15 22:14:11} Capturing started {2018/01/15 22:14:11} Already capturing. Ignore {2018/01/15 22:14:12} Capturing image {2018/01/15 22:14:15} Capturing image {2018/01/15 22:14:18} Capturing image {2018/01/15 22:14:32} Capturing image {2018/01/15 22:14:33} send smd 1 [2018/01/15 22:14:33] Start capture requested from Pipe [2018/01/15 22:14:33] Send ca 1 {2018/01/15 22:14:33} Already capturing. Ignore {2018/01/15 22:14:35} Capturing image {2018/01/15 22:14:38} Capturing image {2018/01/15 22:14:41} Capturing image {2018/01/15 22:14:48} Capturing image {2018/01/15 22:14:51} Capturing image {2018/01/15 22:14:54} Capturing image {2018/01/15 22:14:57} Capturing image {2018/01/15 22:15:00} Capturing image {2018/01/15 22:15:03} Capturing image {2018/01/15 22:15:11} Capturing image {2018/01/15 22:15:14} Capturing image {2018/01/15 22:15:17} Capturing image {2018/01/15 22:15:20} Capturing image {2018/01/15 22:15:23} Capturing image {2018/01/15 22:15:26} Capturing image {2018/01/15 22:15:29} Capturing image {2018/01/15 22:15:43} send smd 0 [2018/01/15 22:15:43] Stop capture requested [2018/01/15 22:15:43] Send ca 0 {2018/01/15 22:15:53} Capturing stopped {2018/01/15 22:15:53} Executing macro /var/www/html/macros/end_vid.sh "/var/www/html/media/vi_2858_20180115_221411.mp4"

Yes, the start_vid.sh macro also starts capturing images for 60 seconds every 2 seconds. In background. So in parallel to the video capture. What I find weird is that the numbers of the videos/images does not correspond to the numbers mentioned in the log. In the log I can see vi28xx... etc while in the UI and the actual files are at vi_3051_20180115_211635 and so on. Same time. Also there are images and videos with the same numbers. I can't remember if this was the case before. When I select the "Videos & Images" Option in the dropdown I can only see the videos but no images. Image I can only see with "Only Images". I guess because of the same number (Haven't checked php files yet).

So after all I still guess this might be related to usage of macros and / or docker. But - it was working with the previous version ;-)

Can I somewhere see what was changed in the c code of the raspimjpeg bin (it feels lie I've asked that before)?

roberttidey commented 6 years ago

I'll look at this and that log next weekend when I have some time.

The source files are on my github at https://github.com/roberttidey/userland

The raspimpjeg files are under host_applications/linux/apps/raspicam and all start RaspiM*

The easiest way of seeing the changes is to click on the commits tab at the top level. All these commits just refer to changes to raspimjpeg.