console log debug output clobbers progress output

[Roger Pack]

Summary of the bug: basically, in the presence of multiple log messages, the default "size out" gets lost:

How to reproduce:
Run a dshow capture session with a system under heavy load (or any system that can't keep up with the requested encoding in realtime):

ffmpeg -f dshow -i video="screen-capture-recorder":audio="Microphone (U
ffmpeg version N-61874-g57e939d Copyright (c) 2000-2014 the FFmpeg developers
  built on Mar 27 2014 12:40:59 with gcc 4.8.2 (GCC)
  configuration: --arch=x86 --target-os=mingw32 --cross-prefix=/home/rogerdpack
2- --pkg-config=pkg-config --enable-gpl --enable-libx264 --enable-avisynth --en
brtmp --enable-libvorbis --enable-libtheora --enable-libspeex --enable-libopenj
disable-w32threads --enable-frei0r --enable-filter=frei0r --enable-libvo-aacenc
libopencore-amrnb --enable-libopencore-amrwb --enable-libvo-amrwbenc --enable-l
v/ffmpeg-windows-build-helpers/sandbox/mingw-w64-i686/i686-w64-mingw32 --enable
s --enable-libutvideo --enable-libbluray --enable-iconv --enable-libtwolame --e
ibmodplug --extra-libs=-lstdc++ --extra-libs=-lpng --enable-libvidstab --extra-
  libavutil      52. 69.100 / 52. 69.100
  libavcodec     55. 55.100 / 55. 55.100
  libavformat    55. 35.101 / 55. 35.101
  libavdevice    55. 11.100 / 55. 11.100
  libavfilter     4.  3.100 /  4.  3.100
  libswscale      2.  5.102 /  2.  5.102
  libswresample   0. 18.100 /  0. 18.100
  libpostproc    52.  3.100 / 52.  3.100
Guessed Channel Layout for  Input Stream #0.1 : stereo
Input #0, dshow, from 'video=screen-capture-recorder:audio=Microphone (USB Audi
  Duration: N/A, start: 247589.073000, bitrate: N/A
    Stream #0:0: Video: rawvideo, bgr0, 654x290, 30 fps, 30 tbr, 10000k tbn, 30
    Stream #0:1: Audio: pcm_s16le, 44100 Hz, stereo, s16, 1411 kb/s
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
No pixel format specified, yuv444p for H.264 encoding chosen.
Use -pix_fmt yuv420p for compatibility with outdated media players.
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
    Last message repeated 1 times
[libx264 @ 043423e0] using cpu capabilities: MMX2 SSE2Fast LZCNT
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
    Last message repeated 1 times
[libx264 @ 043423e0] profile High 4:4:4 Predictive, level 3.0, 4:4:4 8-bit
[libx264 @ 043423e0] 264 - core 140 r2380 de0bc36 - H.264/MPEG-4 AVC codec - Co
3 deblock=1:0:0 analyse=0x3:0x113 me=hex subme=7 psy=1 psy_rd=1.00:0.00 mixed_r
kip=1 chroma_qp_offset=4 threads=3 lookahead_threads=1 sliced_threads=0 nr=0 de
d=2 b_adapt=1 b_bias=0 direct=1 weightb=1 open_gop=0 weightp=2 keyint=250 keyin
0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 ip_ratio=1.40 aq=1:1.00
Output #0, mp4, to 'yo.mp4':
  Metadata:
    encoder         : Lavf55.35.101
    Stream #0:0: Video: h264 (libx264) ([33][0][0][0] / 0x0021), yuv444p, 654x2
    Stream #0:1: Audio: aac (libvo_aacenc) ([64][0][0][0] / 0x0040), 44100 Hz,
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo -> libx264)
  Stream #0:1 -> #0:1 (pcm_s16le -> libvo_aacenc)
Press [q] to stop, [?] for help
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
    Last message repeated 1 times
[swscaler @ 043b7d00] Warning: data is not aligned! This can lead to a speedlos
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
[dshow @ 0267eda0] real-time buffer[0] too full (99% of size: 3041280)! frame d
    Last message repeated 1 times
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame
[dshow @ 0267eda0] real-time buffer[0] too full (99% of size: 3041280)! frame d
[dshow @ 0267eda0] real-time buffer[0] too full (99% of size: 3041280)! frame d
    Last message repeated 4 times
frame=  163 fps= 24 q=29.0 size=     148kB time=00:00:05.43 bitrate= 222.6kbits
[dshow @ 0267eda0] real-time buffer[0] too full (149% of size: 3041280)! frame

Notice that "frame= 163 fps= 24 q=29.0 size= 148kB time=00:00:05.43 bitrate= 222.6kbits" type messages are basically lost/obscured/being covered over by the warning messages being shown.

This can also lead to some odd concatenated lines being shown on the console, like this for instance (the "31 drop=0" are from the preceding).

"[dshow @ 0263eda0] real-time buffer[0] too full (99% of size: 3041280)! frame dropped!31 drop=0"

[Carl Eugen Hoyos]

Am I correct that the last line containing the final number of frames gets never clobbered?

[Roger Pack]

I think you're correct ("at the very end" it seems to spit out one good line).

While it's recording though...all you see is this, never any timestamps or frame counts:

[dshow @ 03f280e0] real-time buffer[virtual-audio-capturer] too full (67% of size: 3041280)! frame dropped!
[dshow @ 03f280e0] real-time buffer[screen-capture-recorder] too full (149% of size: 3041280)! frame dropped!
[dshow @ 03f280e0] real-time buffer[virtual-audio-capturer] too full (67% of size: 3041280)! frame dropped!
[dshow @ 03f280e0] real-time buffer[screen-capture-recorder] too full (149% of size: 3041280)! frame dropped!

Last message repeated 1 times

FWIW :)
Thanks!