Add a KServe module level logger

[cmaddalozzo]

Tell uvicorn not to disable existing loggers

What this PR does / why we need it:

Which issue(s) this PR fixes :
Fixes #2851

Type of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to not work as expected)
• This change requires a documentation update

Use module level logger in Python model server

[yuzisun]

So here we can then use environment variable to set the log level right? Let’s add the documentation for this here https://kserve.github.io/website/master/modelserving/v1beta1/custom/custom_model/#environment-variables

[hjweide]

Hi @cmaddalozzo, I hope you don't mind me jumping into this PR. We rely extensively on KServe in our applications and would like to share some knowledge about how to configure loggers for libraries to ensure that the library's loggers do not interfere with application code.

First, please note that a library should ideally not be configuring its own logging, and definitely not be adding its own handlers. The "Note" warnings in the documentation explain the reasoning: https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library This was the cause of the original problem where KServe's logging configuration was taking over the logging configuration of our application code, which caused our logs to disappear. (Some of our logs are monitored for critical system health, so we rely on them extensively.)

Instead, the way it's typically done is shown in this StackOverflow post.

Concretely, the library code defines module-level loggers like this:

# my_library_class.py
import logging
# Note that no logging configuration is done here.
# This is critically important. This logger will inherit its configuration from the application code's configuration.
logger = logging.getLogger(__name__)

class MyLibraryClass:
    def work(self) -> None:
        logger.info("Logging message")

and the application code defines the logging configuration:

# main.py
import logging

def main() -> None:
    start_application()

if __name__ == "__main__":
    # This is where the application code will define its own logging configuration
    # This includes the logging configuration for any libraries that it uses
    logging.basicConfig(....)
    main()

The way this PR is currently written, we have this line:

from .logging import logger

that is causing all of this logging configuration to be executed when ModelServer is imported into application code. This is what causes problems for downstream application developers, because they do not expect a library that they import to change their existing logging configuration. The same concept applies elsewhere; for example, there is more logging configuration done here that also affects downstream application developers.

Of course, sometimes it is necessary for a library to configure a logger for debugging or testing purposes. That is fine, but when that is necessary, the logging configuration should be kept entirely separate from the code that is exposed to downstream application developers.

[cmaddalozzo]

Hi @hjweide,

You input is most welcome. We want to make sure we get this right so it stops causing issues for our users.

It seems a lot of popular web server libraries do configure their own logging (e.g. Uvicorn, Flask) despite the best practice outlined in the docs you shared. They do all seem to provide an easy way to override this functionality though. Your point about configuring the logger on import is well taken and I agree we should change this behavior.

Based on what you outlined I think it makes sense to remove the logging config from module import level and put it in a function (e.g. .logging.configure). We can then add a configure_logging flag to the ModelServer class that allows users to disable logging config. Does that work for your use case?

[Yucao42]

Thanks @cmaddalozzo for the reply! I think there might be 2 ways to move forward following different conventions:

1. Do not setup logging inside the library

• Where we can have setup_logging function that takes a log_config as a dict which has the default value we have here.

2. Follow the uvicorn or flask server paradigm to 1)setup logging in lib and 2)allow user to pass log_config to the server instance to configure for logging. Indeed they configure logging in the library & they have provided easy way to configure custom logging.

• We can also change kserve's ModelServer and UvicornServer to be like the original UvicornServer where a default log_config is provided but it is easily overwriteable.

Currently the kserve's ModelServer's UvicornServer has no way to overwrite the log_config with a dict. Also the current default log_config file is wrong without this line.

[Yucao42]

Thanks @cmaddalozzo for making the change! If I understand correctly that now we default to configure the logging by KSERVE_LOG_CONFIG and provide options for developer to either disable log_config or passing log_config of their own. I saw that is consistent with what the UvicornServer does. And it makes sense to me.

[cmaddalozzo]

hey @Yucao42, that's correct. We are basically relying on Uvicorn to configure all logging (both its own and KServe's) while giving the developer the option to disable this behavior by passing log_config=None or provide their own config by passing log_config='path_to_log_config.[yaml|json]' or log_config=log_config_dict.

I don't love relying on Uvicorn to configure logging but it's convenient since they allow providing the config as either a path to the log config or a dictionary containing the config. One downside is that all logs output by the KServe logger will have the default configuration until the Uvicorn server is instantiated and the logging is configured.

[elukey]

@Yucao42 hi! All the conversation makes sense, I am wondering if you could give me your opinion about the recent work that was added to allow Kserve to have a good access log format. Due to limitations in Uvicorn and ASGI specs (see encode/uvicorn#947 (comment)) I added a specific option to use asgi-logger and be able to add fields like User Agent etc.. to the access log format (otherwise it seems not possible with the default Uvicorn's config). The library creates its own handler and is able to allow a custom format like Gunicorn's one. The complete change is #2782. Do you think it is ok to keep it? Or do you have an alternative suggestion about how to customize the access logs? Thanks!

[Yucao42]

@elukey Hello! I skimmed over the PR. I think there are two things that are fixed in this PR: 1) the default config value disables all other loggings, 2) we could preserve the UvicornServer's API of passing config of our own (either Dict or str as a json file). How do we do 2) might be a little discussion: currently we add another variable of log_config as Dict. I advocate for using log_config as both types like UvicornServer here, but current code(adding logging_config) in this PR makes sense too. I appreciate both your efforts! @cmaddalozzo @elukey !

[Yucao42]

Thanks @cmaddalozzo for making the change! This makes sense to me! One nit: shall we rename this log_config arg name to log_config_dict to clearly indicate the diff between this and log_config_file?

[Yucao42]

Or we can align with the UvicornServer's __init__ where we just allow passing log_config which could either be dict or str(and defaulted to KSERVE_LOG_CONFIG) so that we can use only 1 argument. Also the code here can be simplified to

if configure_logging:
    self.log_config = log_config

But I understand that might change the function signature, so the decision is yours:) IMHO, having one arg is 1)simper, 2)aligns better with UvicornServer.

[yuzisun]

@elukey Can you help review this change as you originally added the log_config_file? We are trying to align with Uvicorn here.

[elukey]

@yuzisun the change looks good to me, I'll test it in my settings to see if it all works but on paper I am +1

[elukey]

Test went fine, asgi-logger worked as expected.

[yuzisun]

Thanks everyone @cmaddalozzo @Yucao42 @hjweide and @elukey for the nice collaborations on the PR!

/lgtm
/apprrove

[yuzisun]

/lgtm
/approve

[kserve-oss-bot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: cmaddalozzo, yuzisun

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• python/kserve/OWNERS [yuzisun]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment