Truncated Video Export from zmvideo.pl

[martian_tom]

Hi,

I'm running Zoneminder 1.28.1 on Xubuntu 15.10, and have it set up to automatically generate a video and email it to me immediately after it's detected an event. I've noticed that some of these videos are truncated, i.e. the video ends before the end of the event: they have fewer frames in than the actual event. Approximately 10% of videos are affected, the rest have the correct length.

I'm using the following for FFMPEG_OUTPUT_OPTIONS:

Code: Select all

-c:v libx264 -preset fast -crf 38 -vf hqdn3d=8:6:12

I can see a variety of errors in the ffmpeg.out file for the videos that are affected. Always ffmpeg has detected the correct number of input frames, sometimes the ffmpeg outputs looks normal and just seems to end encoding prematurely, but sometimes there are strange errors. In the following example ffmpeg has correctly detected 81 input frames (input duration 3.24s at an assumed rate of 25fps), but stops encoding at frame 39 just after the "enter command" and "parse error" lines.

Code: Select all

ffmpeg version 2.7.3-0ubuntu0.15.10.1 Copyright (c) 2000-2015 the FFmpeg developers
  built with gcc 5.2.1 (Ubuntu 5.2.1-22ubuntu2) 20151010
  configuration: --prefix=/usr --extra-version=0ubuntu0.15.10.1 --build-suffix=-ffmpeg --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --enable-gpl --enable-shared --disable-stripping --enable-avresample --enable-avisynth --enable-frei0r --enable-gnutls --enable-ladspa --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libmodplug --enable-libmp3lame --enable-libopenjpeg --enable-openal --enable-libopus --enable-libpulse --enable-librtmp --enable-libschroedinger --enable-libshine --enable-libspeex --enable-libtheora --enable-libtwolame --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libxvid --enable-libzvbi --enable-opengl --enable-x11grab --enable-libdc1394 --enable-libiec61883 --enable-libzmq --enable-libssh --enable-libsoxr --enable-libx264 --enable-libopencv --enable-libx265
  libavutil      54. 27.100 / 54. 27.100
  libavcodec     56. 41.100 / 56. 41.100
  libavformat    56. 36.100 / 56. 36.100
  libavdevice    56.  4.100 / 56.  4.100
  libavfilter     5. 16.101 /  5. 16.101
  libavresample   2.  1.  0 /  2.  1.  0
  libswscale      3.  1.101 /  3.  1.101
  libswresample   1.  2.100 /  1.  2.100
  libpostproc    53.  3.100 / 53.  3.100
[mjpeg @ 0x2326260] Changeing bps to 8
Input #0, image2, from '%05d-capture.jpg':
  Duration: 00:00:03.24, start: 0.000000, bitrate: N/A
    Stream #0:0: Video: mjpeg, yuvj420p(pc, bt470bg/unknown/unknown), 1280x800 [SAR 1:1 DAR 8:5], 25 fps, 25 tbr, 25 tbn, 25 tbc
No pixel format specified, yuvj420p for H.264 encoding chosen.
Use -pix_fmt yuv420p for compatibility with outdated media players.
[libx264 @ 0x2327860] using SAR=1/1
[libx264 @ 0x2327860] using cpu capabilities: MMX2 SSE2Slow SlowCTZ
[libx264 @ 0x2327860] profile High, level 3.2
[libx264 @ 0x2327860] 264 - core 146 r2555 0c21480 - H.264/MPEG-4 AVC codec - Copyleft 2003-2015 - http://www.videolan.org/x264.html - options: cabac=1 ref=2 deblock=1:0:0 analyse=0x3:0x113 me=hex subme=6 psy=1 psy_rd=1.00:0.00 mixed_ref=1 me_range=16 chroma_me=1 trellis=1 8x8dct=1 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=-2 threads=3 lookahead_threads=1 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=3 b_pyramid=2 b_adapt=1 b_bias=0 direct=1 weightb=1 open_gop=0 weightp=1 keyint=250 keyint_min=4 scenecut=40 intra_refresh=0 rc_lookahead=30 rc=crf mbtree=1 crf=38.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 ip_ratio=1.40 aq=1:1.00
Output #0, mp4, to 'Event-71448-r1-s1.mp4':
  Metadata:
    encoder         : Lavf56.36.100
    Stream #0:0: Video: h264 (libx264) ([33][0][0][0] / 0x0021), yuvj420p(pc), 1280x800 [SAR 1:1 DAR 8:5], q=-1--1, 4.96 fps, 15872 tbn, 4.96 tbc
    Metadata:
      encoder         : Lavc56.41.100 libx264
Stream mapping:
  Stream #0:0 -> #0:0 (mjpeg (native) -> h264 (libx264))
Press [q] to stop, [?] for help
frame=   13 fps=0.0 q=0.0 size=       0kB time=00:00:00.00 bitrate=N/A    
frame=   27 fps= 26 q=0.0 size=       0kB time=00:00:00.00 bitrate=N/A    
frame=   37 fps= 22 q=0.0 size=       0kB time=00:00:00.00 bitrate=N/A    
Enter command: <target>|all <time>|-1 <command>[ <argument>]
Parse error, at least 3 arguments were expected, only 1 given in string '?Ï.s•oA³{€%ñC?îj¢)Ü`ã«?h@?ê€???Zԋ?Lèõ^QÞªõ~·ÊF^ÛÉ}	%}ª|E蜜&¿šÒݙøøkóI'
frame=   39 fps=4.7 q=-1.0 Lsize=     528kB time=00:00:07.45 bitrate= 580.3kbits/s    
video:527kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.185708%
[libx264 @ 0x2327860] frame I:2     Avg QP:37.83  size: 51490
[libx264 @ 0x2327860] frame P:37    Avg QP:39.28  size: 11795
[libx264 @ 0x2327860] mb I  I16..4:  2.5% 95.3%  2.2%
[libx264 @ 0x2327860] mb P  I16..4:  0.1% 18.2%  0.1%  P16..4: 29.5%  3.8%  5.0%  0.0%  0.0%    skip:43.3%
[libx264 @ 0x2327860] 8x8 transform intra:98.2% inter:90.8%
[libx264 @ 0x2327860] coded y,uvDC,uvAC intra: 63.8% 59.5% 15.0% inter: 10.2% 26.9% 0.0%
[libx264 @ 0x2327860] i16 v,h,dc,p: 35% 27% 10% 28%
[libx264 @ 0x2327860] i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 22%  7% 38%  6%  4%  6%  4%  7%  6%
[libx264 @ 0x2327860] i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 24% 15% 31%  7%  5%  5%  4%  6%  4%
[libx264 @ 0x2327860] i8c dc,h,v,p: 83% 10%  6%  1%
[libx264 @ 0x2327860] Weighted P-Frames: Y:48.6% UV:43.2%
[libx264 @ 0x2327860] ref P L0: 67.8% 32.2%
[libx264 @ 0x2327860] kb/s:548.81

These errors take various forms, the above is just one example. I've added debug logging to zmvideo.pl which outputs the actual ffmpeg command run - if I run that separately then the video is invariable created properly and I don't see these errors.

Doing a Google search on the "enter command..." line brings up several forum posts including http://unix.stackexchange.com/questions ... -in-a-loop which implies that the error is caused by ffmpeg reading input from stdin which is in this case is presumably somehow being generated by one of the Zoneminder components. The solution in that post is to append "< /dev/null" to the ffmpeg command to stop it reading from stdin.

My question is, has anyone else noticed this behaviour in videos generated within Zoneminder? While trying to solve this problem I wrote a bash script to identify differences between the number of frames in the Zoneminder database and the number in the resulting video file. Edit the variables at the top appropriately - it will loop through events from startDate until present and will use ffprobe to get the number of frames in the video file (set pathRoot to the ZM events folder), it will print the number of frames from the ZM database and number in the video and put "*****" next to any events which have a mismatch. The script will also copy the ffmpeg.log files of all affected events to another folder for inspection, create it and set this in the logCopyPath variable.

Code: Select all

#!/bin/bash
#zmvideotest.sh

startDate="2016-01-09 00:00:00"
pathRoot="/nas/data/zoneminder/events"
logCopyPath="/home/myth/zmffmpeglogs"


monID=($(mysql -uzmuser -pzmpass -B -e "SELECT monitorid, Name, DATE_FORMAT(StartTime,'%y/%m/%d/%H/%i/%s'), Frames FROM zm.Events WHERE StartTime > '$startDate' ORDER BY StartTime;" | awk '{ print $1 }'))
name=($(mysql -uzmuser -pzmpass -B -e "SELECT monitorid, Name, DATE_FORMAT(StartTime,'%y/%m/%d/%H/%i/%s'), Frames FROM zm.Events WHERE StartTime > '$startDate' ORDER BY StartTime;" | awk '{ print $2 }'))
date=($(mysql -uzmuser -pzmpass -B -e "SELECT monitorid, Name, DATE_FORMAT(StartTime,'%y/%m/%d/%H/%i/%s'), Frames FROM zm.Events WHERE StartTime > '$startDate' ORDER BY StartTime;" | awk '{ print $3 }'))
DB_NUM_FRAMES=($(mysql -uzmuser -pzmpass -B -e "SELECT monitorid, Name, DATE_FORMAT(StartTime,'%y/%m/%d/%H/%i/%s'), Frames FROM zm.Events WHERE StartTime > '$startDate' ORDER BY StartTime;" | awk '{ print $4 }'))

numEvents=${#monID[@]}
echo "Number of selected events is $numEvents"
if [ "$numEvents" -gt 0 ]
then
    i=1     
    while [ $i -lt $numEvents ]
    do
        datePath="${date[$i]}"
        eventPath="$pathRoot/${monID[$i]}/$datePath/${name[$i]}-r1-s1.mp4"
        #echo $eventPath
        MP4_NUM_FRAMES=$(ffprobe -i "$eventPath" -select_streams 0 -show_streams 2> /dev/null | grep ^nb_frames= | awk -F = '{print $2}')
        if [ $MP4_NUM_FRAMES -ne ${DB_NUM_FRAMES[$i]} ]
        then        
            ALERT="*****"
            cp "$pathRoot/${monID[$i]}/$datePath/ffmpeg.log" "$logCopyPath/${name[$i]}.log"
        else
            ALERT=""
        fi

        echo "${date[$i]} | ${monID[$i]} | ${name[$i]} | ${DB_NUM_FRAMES[$i]} | $MP4_NUM_FRAMES | $ALERT"
        i=$(($i+1))
    done
fi

I have amended the ffmpeg command in /usr/bin/zmvideo.pl and placed "< /dev/null" at the end and so far (for the past 12 hours) all videos generated are the correct length. I'm not sure if this is the best way to solve the problem, but I'll report back in a few days when I'm sure whether it's solved it.

[martian_tom]

Well after 9 days and about 800 events later, not a single video is truncated, all of them have the same number of frames as the original event, and the addition of "< /dev/null" after the ffmpeg command doesn't seem to have adversely affected the operation of zmvideo.pl.

Problem solved!