All gunicorn accesslogs are going to stderr

[paul121]

@mstenta noticed that the Docker container_id-json.log file shows all logs as being streamed to "stream":"stderr". These should only be going to stdout except for true gunicorn errors.

Trying to track this down, but having a hard finding the issue. The backend uses this base Docker image: uvicorn-gunicorn-docker. This handles some default configuration for running the FastAPI app with uvicorn for development (for live reloading) and gunicorn for production (gunicorn creates multiple uvicorn workers for production).

There is an option to pass provide a gunicorn_conf.py file in the /app/app directory to override the default gunicorn_conf.py config from the image. It seems like we need to do something with that, but I'm not having any luck..

From the gunicorn settings it looks like accesslog is disabled by default, while errorlog outputs to stderr by default. I'm seeing that both the accesslog and errorlog are outputting to stderr.

This example shows this, the DEBUG logs are from the FastAPI app, while the nicely formatted are from gunicorn accesslog (I believe):

{"log":"DEBUG:multipart.multipart:Calling on_end with no data\n","stream":"stdout","time":"2020-03-16T20:21:02.298346494Z"}
{"log":"DEBUG:passlib.handlers.bcrypt:detected 'bcrypt' backend, version '3.1.7'\n","stream":"stdout","time":"2020-03-16T20:21:02.319356265Z"}
{"log":"DEBUG:passlib.handlers.bcrypt:'bcrypt' backend lacks $2$ support, enabling workaround\n","stream":"stdout","time":"2020-03-16T20:21:02.319405556Z"}
{"log":"DEBUG:app.api.api_v1.endpoints.login:New user login with scopes: ['farm:create', 'farm:read', 'farm:update', 'farm:delete', 'farm:authorize', 'farm.info']\n","stream":"stdout","time":"2020-03-16T20:21:02.587861771Z"}
{"log":"[2020-03-16 20:21:02 +0000] [14] [INFO] ('172.18.0.6', 32838) - \"POST /api/v1/login/access-token HTTP/1.0\" 200\n","stream":"stderr","time":"2020-03-16T20:21:02.590120544Z"}
{"log":"[2020-03-16 20:21:02 +0000] [13] [INFO] ('172.18.0.6', 32842) - \"GET /api/v1/users/me HTTP/1.0\" 200\n","stream":"stderr","time":"2020-03-16T20:21:02.619220417Z"}
{"log":"{\"loglevel\": \"info\", \"workers\": 4, \"bind\": \"0.0.0.0:80\", \"workers_per_core\": 1.0, \"host\": \"0.0.0.0\", \"port\": \"80\"}\n","stream":"stdout","time":"2020-03-16T20:21:05.183688428Z"}

[paul121]

@mstenta could you check if you are still seeing this?

I just took a quick look at this again. It seems like requests are being logged to stdout (this is from my container-id-json.log file):

{"log":"INFO:     Finished server process [17]\n","stream":"stderr","time":"2020-04-29T15:39:00.303217848Z"}
{"log":"INFO:     Started server process [38]\n","stream":"stderr","time":"2020-04-29T15:39:01.503224153Z"}
{"log":"INFO:     Waiting for application startup.\n","stream":"stderr","time":"2020-04-29T15:39:01.503292153Z"}
{"log":"INFO:     Application startup complete.\n","stream":"stderr","time":"2020-04-29T15:39:01.503477589Z"}
{"log":"INFO:     172.22.0.5:44768 - \"GET /api/v1/users/me HTTP/1.0\" 200 OK\n","stream":"stdout","time":"2020-04-29T15:43:12.941822001Z"}
{"log":"INFO:     172.22.0.5:44772 - \"GET /api/v1/users/me HTTP/1.0\" 200 OK\n","stream":"stdout","time":"2020-04-29T15:43:13.038199502Z"}
{"log":"INFO:     172.22.0.5:44776 - \"GET /api/v1/farms/ HTTP/1.0\" 200 OK\n","stream":"stdout","time":"2020-04-29T15:43:13.341616122Z"}
{"log":"INFO:     172.22.0.5:44790 - \"GET /api/v1/farms/ HTTP/1.0\" 200 OK\n","stream":"stdout","time":"2020-04-29T15:43:16.544842708Z"}

The first few logs going to stderr are from the app startup.. these logs are created before the FastAPI app has started. As they are set as log: INFO I think they should go to stdout as well... but perhaps that is OK?

[mstenta]

Hmm I am still seeing them going to stderr on v0.9.5:

Have you made any changes that are not part of that release? Or could this potentially be a difference in gunicorn config between dev and prod deployments?