Subprocess log file setting issue

[wssf812]

This is my configuration file
[program:xxxx]
command=cmd.exe xxxxx
autostart=true
autorestart=true
startretries=3
stdout_logfile=NONE
stderr_logfile=xx/xxx.log

I set the standard output log to empty and prevent it from entering relevant logs. But how can there be [info] level logs in the error log file?
My loglevel=error

By the way, if the sub process frequently outputs logs, will it affect the performance of superviosr and cause blocking? This question is very important. Please answer it. Thank you

[luolingchun]

Same problem +1

use redirect_stderr=true, but no error logs in stdout_logfile.

[alexsilva]

@luolingchun

Same problem +1

use redirect_stderr=true, but no error logs in stdout_logfile.

What version of Python were you using when you did this test? I have noticed that version 3.10.11-amd64 is experiencing several instability issues.

[luolingchun]

@alexsilva

Python 3.8.5-amd64

OS: Windows 11

[luolingchun]

I did a more detailed test, and when Flask Debug mode is started, the print log will be output the next time the service is restarted (Debug mode).

1. First step:

@app.route("/")
def index():
    print(111111111)
    print("test中文test")
    return "ok"


if __name__ == "__main__":
    app.run("0.0.0.0", 5001, debug=True)

Log out after sending two requests:

* Serving Flask app 'app'
 * Debug mode: on
WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.
 * Running on all addresses (0.0.0.0)
 * Running on http://127.0.0.1:5001
 * Running on http://10.0.7.217:5001
Press CTRL+C to quit
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 283-907-158
127.0.0.1 - - [06/Nov/2023 10:58:40] "GET / HTTP/1.1" 200 -
127.0.0.1 - - [06/Nov/2023 10:58:45] "GET / HTTP/1.1" 200 -

1. Second step:
   Add print(222222222)

@app.route("/")
def index():
    print(111111111)
    print("test中文test")
    print(222222222)
    return "ok"

Log out:

You can see that the log has been refreshed.

But I have same issue with #49 (log missed 中文) and it is correct for me to go back to version 4.5.0.

...
127.0.0.1 - - [06/Nov/2023 11:07:02] "GET / HTTP/1.1" 200 -
127.0.0.1 - - [06/Nov/2023 11:07:04] "GET / HTTP/1.1" 200 -
 * Detected change in 'D:\\workspace\\xxx\\xxx-server\\src\\wsgi.py', reloading
111111111
testtest
111111111
testtest
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 283-907-158

Complete configuration file:

[supervisord]
nodaemon=false

[inet_http_server]
port=*:9001

[supervisorctl]

[program:app-win1]
command=D:\\workspace\\xxx\\xxx-server\\venv\\Scripts\\python.exe D:\\workspace\\xxx\\xxx-server\\src\\wsgi.py
autostart=true
autorestart=true
# 将stderr的日志写入stdout日志文件中
redirect_stderr=true
stdout_logfile=D:\workspace\xxx\xxx-server\logs\app1.log
stdout_logfile_maxbytes=10MB
stdout_logfile_backups=5
# 杀死进程组包括子进程
stopasgroup=true
killasgroup=true

[alexsilva]

I did a more detailed test, and when Flask Debug mode is started, the print log will be output the next time the service is restarted (Debug mode).

1. First step:

@app.route("/")
def index():
    print(111111111)
    print("test中文test")
    return "ok"


if __name__ == "__main__":
    app.run("0.0.0.0", 5001, debug=True)

Log out after sending two requests:

* Serving Flask app 'app'
 * Debug mode: on
WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.
 * Running on all addresses (0.0.0.0)
 * Running on http://127.0.0.1:5001
 * Running on http://10.0.7.217:5001
Press CTRL+C to quit
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 283-907-158
127.0.0.1 - - [06/Nov/2023 10:58:40] "GET / HTTP/1.1" 200 -
127.0.0.1 - - [06/Nov/2023 10:58:45] "GET / HTTP/1.1" 200 -

1. Second step:
   Add print(222222222)

@app.route("/")
def index():
    print(111111111)
    print("test中文test")
    print(222222222)
    return "ok"

Log out:

You can see that the log has been refreshed.

But I have same issue with #49 (log missed 中文) and it is correct for me to go back to version 4.5.0.

...
127.0.0.1 - - [06/Nov/2023 11:07:02] "GET / HTTP/1.1" 200 -
127.0.0.1 - - [06/Nov/2023 11:07:04] "GET / HTTP/1.1" 200 -
 * Detected change in 'D:\\workspace\\xxx\\xxx-server\\src\\wsgi.py', reloading
111111111
testtest
111111111
testtest
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 283-907-158

Complete configuration file:

[supervisord]
nodaemon=false

[inet_http_server]
port=*:9001

[supervisorctl]

[program:app-win1]
command=D:\\workspace\\xxx\\xxx-server\\venv\\Scripts\\python.exe D:\\workspace\\xxx\\xxx-server\\src\\wsgi.py
autostart=true
autorestart=true
# 将stderr的日志写入stdout日志文件中
redirect_stderr=true
stdout_logfile=D:\workspace\xxx\xxx-server\logs\app1.log
stdout_logfile_maxbytes=10MB
stdout_logfile_backups=5
# 杀死进程组包括子进程
stopasgroup=true
killasgroup=true

What encoding is used in the script to print "test中文test"?

Does configuring python encoding before initializing it solve the problem?

set PYTHONIOENCODING=utf8

[luolingchun]

@alexsilva Thanks, it's worked.

[supervisord]
nodaemon=false
environment=PYTHONIOENCODING="utf8"

...

Is there a solution to the problem of delayed printing of logs?

[luolingchun]

I got it.

PYTHONIOENCODING=utf8 for correct encoding and PYTHONUNBUFFERED=1 for correct logs.

[supervisord]
nodaemon=false
environment=PYTHONIOENCODING=utf8,PYTHONUNBUFFERED=1

...

[alexsilva]

Recently I introduced a new concept and it serves to control the time that the process is idle. The more processing there is, the more the sleep time tends to zero. This will help with log processing as well.

@wssf812 @luolingchun time machine