I'm running FastAPI application in Docker on Kubernetes. It restarts all the time with Uvicorn. Therefore as the official guide suggested, I used gunicorn with UvicornWorker. CMD ["gunicorn", "API:app", "-w", "5", "-k", "uvicorn.workers.UvicornH11Worker", "-b", "0.0.0.0:5099", "--preload" And all the logs are duplicated (even triplicated for some reason). These are kubernetes readiness check GET requests, which are useless. But this is what I'm seeing.
[2021-02-08 15:25:10 +0000] [1] [INFO] Starting gunicorn 20.0.4
[2021-02-08 15:25:10 +0000] [1] [INFO] Listening at: http://0.0.0.0:5099 (1)
[2021-02-08 15:25:10 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornH11Worker
[2021-02-08 15:25:10 +0000] [91] [INFO] Booting worker with pid: 91
[2021-02-08 15:25:10 +0000] [92] [INFO] Booting worker with pid: 92
[2021-02-08 15:25:10 +0000] [91] [INFO] Started server process [91]
[2021-02-08 15:25:10,696] [91] [INFO] [uvicorn.error] Started server process [91]
[2021-02-08 15:25:10 +0000] [91] [INFO] Waiting for application startup.
[2021-02-08 15:25:10,696] [91] [INFO] [uvicorn.error] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [91] [INFO] Application startup complete.
[2021-02-08 15:25:10,697] [91] [INFO] [uvicorn.error] Application startup complete.
[2021-02-08 15:25:10 +0000] [93] [INFO] Booting worker with pid: 93
[2021-02-08 15:25:10 +0000] [92] [INFO] Started server process [92]
[2021-02-08 15:25:10,750] [92] [INFO] [uvicorn.error] Started server process [92]
[2021-02-08 15:25:10 +0000] [92] [INFO] Waiting for application startup.
[2021-02-08 15:25:10,751] [92] [INFO] [uvicorn.error] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [92] [INFO] Application startup complete.
[2021-02-08 15:25:10,751] [92] [INFO] [uvicorn.error] Application startup complete.
[2021-02-08 15:25:10 +0000] [94] [INFO] Booting worker with pid: 94
[2021-02-08 15:25:10 +0000] [93] [INFO] Started server process [93]
[2021-02-08 15:25:10,787] [93] [INFO] [uvicorn.error] Started server process [93]
[2021-02-08 15:25:10 +0000] [93] [INFO] Waiting for application startup.
[2021-02-08 15:25:10,787] [93] [INFO] [uvicorn.error] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [93] [INFO] Application startup complete.
[2021-02-08 15:25:10,787] [93] [INFO] [uvicorn.error] Application startup complete.
[2021-02-08 15:25:10 +0000] [95] [INFO] Booting worker with pid: 95
[2021-02-08 15:25:10 +0000] [94] [INFO] Started server process [94]
[2021-02-08 15:25:10,849] [94] [INFO] [uvicorn.error] Started server process [94]
[2021-02-08 15:25:10 +0000] [94] [INFO] Waiting for application startup.
[2021-02-08 15:25:10,849] [94] [INFO] [uvicorn.error] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [94] [INFO] Application startup complete.
[2021-02-08 15:25:10,850] [94] [INFO] [uvicorn.error] Application startup complete.
[2021-02-08 15:25:10 +0000] [95] [INFO] Started server process [95]
[2021-02-08 15:25:10,886] [95] [INFO] [uvicorn.error] Started server process [95]
[2021-02-08 15:25:10,887] [95] [INFO] [uvicorn.error] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [95] [INFO] Waiting for application startup.
[2021-02-08 15:25:10 +0000] [95] [INFO] Application startup complete.
[2021-02-08 15:25:10,887] [95] [INFO] [uvicorn.error] Application startup complete.
[2021-02-08 15:25:20 +0000] [91] [INFO] 100.100.2.1:59104 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:20,570] [91] [INFO] [uvicorn.error] 100.100.2.1:59104 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:30 +0000] [93] [INFO] 100.100.2.1:59150 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:30,571] [93] [INFO] [uvicorn.error] 100.100.2.1:59150 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:40 +0000] [93] [INFO] 100.100.2.1:59194 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:40,569] [93] [INFO] [uvicorn.error] 100.100.2.1:59194 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:50 +0000] [92] [INFO] 100.100.2.1:59240 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:25:50,571] [92] [INFO] [uvicorn.error] 100.100.2.1:59240 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:26:00 +0000] [94] [INFO] 100.100.2.1:59284 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:26:00,571] [94] [INFO] [uvicorn.error] 100.100.2.1:59284 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:26:10 +0000] [94] [INFO] 100.100.2.1:59328 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:26:10,570] [94] [INFO] [uvicorn.error] 100.100.2.1:59328 - "GET /ready/ HTTP/1.1" 200
[2021-02-08 15:26:20 +0000] [94] [INFO] 100.100.2.1:59374 - "GET /ready/ HTTP/1.1" 200
As I understand, the +0000 logs are from Gunicorn, but doesn't have a module name for some reason. And the uvicorn.error are from the UvicornWorker, they print the same thing twice. I need zero, especially the GET requests from kubernetes.
My code looks like this
uvicorn.config.LOGGING_CONFIG['loggers']['uvicorn.error']['level']='WARNING'
uvicorn.config.LOGGING_CONFIG['']['uvicorn.error']['level']='WARNING'
I've also tried in vain the following
logging.getLogger('uvicorn.error').setLevel(logging.WARNING)
and
class readinessFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
return record.getMessage().find("/ready") == -1
logger=logging.getLogger(__name__)
logger.addFilter(readinessFilter())
This is truly frustrating. Can someone help me with the underlying logic of what's controlling the logging output?