Log file missing output

[philipstarkey]

I'm attempting to have supervisord manage an ffmpeg process and I've realised that the last output before exist/crash is not stored in the log file. I'm uncertain if this is a supervisor-win issue or an upstream issue as I don't have a linux machine to test on at the moment.

Example config

[inet_http_server]         ; inet (TCP) server disabled by default
port=127.0.0.1:9001        ; ip_address:port specifier, *:port for all iface
[supervisord]
logfile=%(ENV_TMP)s\\supervisord.log ; (main log file;default $CWD/supervisord.log)
logfile_maxbytes=50MB               ; (max main logfile bytes b4 rotation;default 50MB)
logfile_backups=10                  ; (num of main logfile rotation backups;default 10)
loglevel=blather                       ; (log level;default info; others: debug,warn,trace)
pidfile=%(ENV_TMP)s\\supervisord.pid ; (supervisord pidfile;default supervisord.pid)
nodaemon=false                      ; (start in foreground if true;default false)
silent=false                 ; no logs to stdout if true; default false
minfds=1024                         ; (min. avail startup file descriptors;default 1024)
minprocs=200                        ; (min. avail process descriptors;default 200)
delaysecs=0.02
[program:ffmpeg]
command=ffmpeg.exe -list_devices;
autostart=true
startsecs=0
autorestart=true
stopwaitsecs=1
redirect_stderr=true
stdout_logfile=%(ENV_TMP)s\\log.log
stdout_logfile_maxbytes=1MB
stdout_logfile_backups=10

The correct output from this (to store in the log) is

ffmpeg version 4.3.1 Copyright (c) 2000-2020 the FFmpeg developers
  built with gcc 10.2.1 (GCC) 20200726
  configuration: --enable-gpl --enable-version3 --enable-sdl2 --enable-fontconfig --enable-gnutls --enable-iconv --enable-libass --enable-libdav1d --enable-libbluray --enable-libfreetype --enable-libmp3lame --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-libopus --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libsrt --enable-libtheora --enable-libtwolame --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxml2 --enable-libzimg --enable-lzma --enable-zlib --enable-gmp --enable-libvidstab --enable-libvmaf --enable-libvorbis --enable-libvo-amrwbenc --enable-libmysofa --enable-libspeex --enable-libxvid --enable-libaom --enable-libgsm --enable-librav1e --disable-w32threads --enable-libmfx --enable-ffnvcodec --enable-cuda-llvm --enable-cuvid --enable-d3d11va --enable-nvenc --enable-nvdec --enable-dxva2 --enable-avisynth --enable-libopenmpt --enable-amf
  libavutil      56. 51.100 / 56. 51.100
  libavcodec     58. 91.100 / 58. 91.100
  libavformat    58. 45.100 / 58. 45.100
  libavdevice    58. 10.100 / 58. 10.100
  libavfilter     7. 85.100 /  7. 85.100
  libswscale      5.  7.100 /  5.  7.100
  libswresample   3.  7.100 /  3.  7.100
  libpostproc    55.  7.100 / 55.  7.100
Unrecognized option 'list_devices;'.
Error splitting the argument list: Option not found

But what I see in the log is just

ffmpeg version 4.3.1 Copyright (c) 2000-2020 the FFmpeg developers

which is only the first line of the message.

If I change delaysecs to 0.0002, then I see a bit more output, but still not the whole message.

It seems like supervisor is not reading the whole of the stdout pipe once it closes.

modifying supervisor.process.Subprocess.close_all_dispatchers to call self.dispatchers[fd].handle_read_event() repeatedly does result in the whole message being logged (although this is probably not the right solution as what I tried ultimately ended up in an infinite loop).

Does this seem like a windows/supervisor-win problem or is it an issue with the fact that supervisor appears to only read one line from stdout/err per loop of it's main function? (which seems to imply anything logging faster than one line per delaysecs will ultimately result in dropped log messages?)

[alexsilva]

This version of the supervisor reads one line at a time. supervisor/helpers

This is a known issue but I haven't been able to solve it yet.

Perhaps it will solve the problem.

nonblocking_subprocess

[alexsilva]

I made some changes that slightly improve data reading. Update and test.

[philipstarkey]

Thanks! This seems to have fixed the issue, at least for my specific usage. Much appreciated!

[alexsilva]

Using windows apis I have completely changed the way the process data is read / written. It gets better than the previous implementation because all the data will be read / written as precision. If you want to do a test, just update git again. With that this problem is solved.

[philipstarkey]

Checked the latest version too and it also works. Thanks again!