bug: Custom logger not rotating files properly, resulting in overwriting of archived log files

[PenHsuanWang]

Describe the bug

I am using a custom logger, e.g. in the mylogger namespace, to isolate my custom message logging mechanism, with timed file rotation settings. Everything seems fine at first. However, I have noticed unexpected behavior after the log file is rotated. For example, I have set it to rotate daily. On the first day, every message is logged into the mylog.log file without any problem. Once it is rotated on the next day, there are two files

./logs
    |- mylog.log
    |- mylog.log.<first-day>

The issue is that the latest message will randomly be logging into one of them, and the previous message will be overwritten.

To reproduce

1. I used examples/pytorch_mnist as an example. and add the logger setting at service.py

...
# Logger setting
import logging
from logging.handlers import TimedRotatingFileHandler

logger = logging.getLogger('mylogger')

file_handler = TimedRotatingFileHandler(filename='./logs/mylog.log', when='M', interval=1, backupCount=60) # set 1 minute for demo
file_formatter = logging.Formatter("[%(levelname)s] - %(asctime)s - %(name)s: %(message)s")
file_handler.setFormatter(file_formatter)
logger.addHandler(file_handler)

logger.setLevel(logging.DEBUG)
## End of logger setting

mnist_runner = bentoml.pytorch.get("pytorch_mnist:latest").to_runner()
svc = bentoml.Service(name="pytorch_mnist_demo", runners=[mnist_runner])

@svc.api(input=Image(), output=NumpyNdarray(dtype="int64"))
async def predict_image(f: PILImage) -> NDArray[t.Any]:
    logger.debug("Testing Logger, running API logic")
...

And continuously sending requests to the API endpoint.

import requests
import time

url = "http://127.0.0.1:3000/predict_image"
headers = {}

while True:
    files = {'fileobj': ('2.png', open('samples/2.png', 'rb'), 'image/png')}
    response = requests.post(url, headers=headers, files=files)
    print(response.status_code, ' ', response.content)
    time.sleep(3)

Here, I am sending requests to the API endpoint every 3 seconds

2. run bentoml serve service.py:svc --production and run testing set.

3. Watch the log files.

Expected behavior

I am handling a custom logger to isolate it from the bentoml namespace logger, and logging custom messages with a timed file rotation mechanism.

Environment

bentoml: 1.0.20 python: 3.10.11 OS: MacOS: 13.3.1

[frostming]

This is a known issue with Python's TimedRotatingFileHandler that is not stable in multiprocess environment.

See this: https://docs.python.org/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes It also provides a workaround for this. I am going to close this issue now.

[PenHsuanWang]

Hi @frostming

Thank you for the information. Based on the Python Cookbook, I would like to set up the QueueHandler and QueueListener to handle the use case of multiprocessing.

According to the BentoML documentation, when using BentoML as a library, the entry point to implement custom logic is service.py, which is already within the scope of multiprocessing. However, I am confused about where I can properly set up the logger with QueueHandler. Is there a specific configuration file or location where I should do this?

Thanks

[frostming]

@PenHsuanWang Yes you are right, I didn't notice the workaround isn't applicable to the bento service file. Then I would suggest some other solutions:

• Use an external log rotator such as logrotate on Linux systems.
• Or, implement a multiprocess-safe rotation handler, using lock techniques or non copy-and-rename rotation.

[PenHsuanWang]

Hi @frostming

I think in many use cases, logging into a file and rotating it can be a practical pain point when using BentoML in production. I have an idea to implement a Queue and QueueHandler before the API server runs, and make it configurable in bentoml_configuration.yaml. Does this idea make sense to you? Would you mind if I open another issue for this feature request?

Thanks