No logs to stdout with custom sink function

[domevit]

I have a gunicorn+flask application and I'm trying to configure loguru to redirect webapp logs and logs of other libs (gunicorn+other) to the same format using loguru.

I run the application using this command ["gunicorn", "app:api_layer", "-c", "gunicorn_conf.py"] with Docker/docker-compose. Python version: 3.7.11; loguru version: 0.6.0

My app.py file is something like that:

# Init app
api_layer = Flask(__name__)
api_layer.config.from_mapping(config)

and my gunicorn_conf.py is something like that (see https://pawamoy.github.io/posts/unify-logging-for-a-gunicorn-uvicorn-app/)

import json

LOG_LEVEL = logging.getLevelName(os.environ.get("LOG_LEVEL", "INFO"))
class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1

        logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())

intercept_handler = InterceptHandler()
logging.root.setLevel(LOG_LEVEL)
done = set()
logger_names = [
    *logging.root.manager.loggerDict.keys(),
    "gunicorn",
    "gunicorn.access",
    "gunicorn.error"
]
for name in logger_names:
    if name not in done:
        done.add(name.split(".")[0])
        logging.getLogger(name).handlers = [intercept_handler]

logger.remove()
logger.add(sink=sys.stdout, serialize=True, enqueue=True)

class StubbedGunicornLogger(Logger):
    def setup(self, cfg):
        handler = logging.NullHandler()
        self.error_logger = logging.getLogger("gunicorn.error")
        self.error_logger.addHandler(handler)
        self.access_logger = logging.getLogger("gunicorn.access")
        self.access_logger.addHandler(handler)
        self.error_logger.setLevel(LOG_LEVEL)
        self.access_logger.setLevel(LOG_LEVEL)


errorlog = "-"
accesslog = "-"
logger_class = StubbedGunicornLogger

bind = ":8000"
workers = 2
timeout = 180

This code works pretty well but we need also to have a better serialization to show this logs to StackDriver (google cloud). We need to have logs from this format {"text":"some logs", "record":{...}} to this format {"message":"some logs", "record":{...}}

Using #203 I have added this code to the gunicorn_conf.py file:

...
logger.remove()
logger.add(sink=sys.stdout, serialize=True, enqueue=True)

def sink_serializer(message):
    record = message.record
    simplified = {
        "message": record["message"]
    }
    serialized = json.dumps(simplified,  default=str)
    print(serialized, file=sys.stdout)
logger.add(sink=sink_serializer, serialize=False, enqueue=True)

With this code I'm expecting to find two time the same log with two different format but this happen in a delayed way:

api-pod_1  | 2022-03-02 15:25:41.180 | INFO     | gunicorn.glogging:info:262 - Starting gunicorn 20.0.4
api-pod_1  | {"message": "Starting gunicorn 20.0.4"}
api-pod_1  | {"message": "Listening at: http://0.0.0.0:8000 (1)"}
api-pod_1  | {"message": "Using worker: sync"}
api-pod_1  | 2022-03-02 15:25:41.182 | INFO     | gunicorn.glogging:info:262 - Listening at: http://0.0.0.0:8000 (1)
api-pod_1  | 2022-03-02 15:25:41.183 | INFO     | gunicorn.glogging:info:262 - Using worker: sync
api-pod_1  | 2022-03-02 15:25:41.188 | INFO     | gunicorn.glogging:info:262 - Booting worker with pid: 11
api-pod_1  | {"message": "Booting worker with pid: 11"}
api-pod_1  | 2022-03-02 15:25:41.275 | INFO     | gunicorn.glogging:info:262 - Booting worker with pid: 12

As you can see the last log is not duplicate, but if I do a request to the server (for example a GET) the missing line{"message": "Booting worker with pid: 11"} appear. This happen with all gunicorn (gunicorn.glogging) logs. Other logs printed with loguru (logger.info()) are always correctly duplicated.

This is a strange behavior but luckily this is not what I'am searching for because I don't need the same log formatted in two different way. What I need is to have the logs formatted in the right way and if I remove the linelogger.add(sink=sys.stdout, serialize=True, enqueue=True) and I leave only the sink_serialized line no logs appear in sys.stdout

[Delgan]

Hey @domevit.

I tries to run the snippets you shared locally but I was not able to reproduce the issue you're facing. :confused:

Could that be related to the Flask config you're using? Could you share it please?

[mrkmcnamee]

The problem could be that the print function is buffering the output. Try:

print(serialized, file=sys.stdout, flush=True)