[Enhancement] Regularize logging messages

[lstein]

Intro

This commit adds invokeai.backend.util.logging, which provides support for formatted console and logfile messages that follow the status reporting conventions of earlier InvokeAI versions:

 ### A critical error
 *** A non-fatal error
 ** A warning
  >> Informational message
        | Debugging message

Internally, the invokeai logging module creates a new default logger named "invokeai" so that its logging does not interfere with other module's use of the vanilla logging module. So logging.error("foo") will go through the regular logging path and not add InvokeAI's informational message decorations, while ialog.error("foo") will add the decorations.

Usage:

This is a thin wrapper around the standard Python logging module. It can be used in several ways:

Module-level logging style

This style logs everything through a single default logging object and is identical to using Python's logging module. The commonly-used module-level logging functions are implemented as simple pass-thrus to logging:

      import invokeai.backend.util.logging as logger
    
      logger.debug('this is a debugging message')
      logger.info('this is a informational message')
      logger.log(level=logging.CRITICAL, 'get out of dodge')

      logger.disable(level=logging.INFO)
      logger.basicConfig(filename='/var/log/invokeai.log')
      logger.error('this will be logged to console and to invokeai.log')

Internally these functions all go through a custom logging object named "invokeai". You can access it to perform additional customization in either of these ways:

logger = logger.getLogger()
logger = logger.getLogger('invokeai')

Object-oriented style

For more control, the logging module's object-oriented logging style is also supported. The API is identical to the vanilla logging usage. In fact, the only thing that has changed is that the getLogger() method adds a custom formatter to the log messages.

     import logging
     from invokeai.backend.util.logging import InvokeAILogger
    
     logger = InvokeAILogger.getLogger(__name__)
     fh = logging.FileHandler('/var/invokeai.log')
     logger.addHandler(fh)
     logger.critical('this will be logged to both the console and the log file')

Within the nodes API

From within the nodes API, the logger module is stored in the logger slot of InvocationServices during dependency initialization. For example, in a router, the idiom is:

from ..dependencies import ApiDependencies
logger = ApiDependencies.invoker.services.logger
logger.warning('uh oh')

Currently, to change the logger used by the API, one must change the logging module passed to ApiDependencies.initialize() in api_app.py. However, this will eventually be replaced with a method to select the preferred logging module using the configuration file (dependent on merging of PR #3221)

[Kyle0654]

Is there a way for the user to override the formats, or even just use standard Python formats? I can imagine there are tools out there that work really well with standard Python log formatting, and changing that might create extra work. In particular, I've seen log aggregators do well when the logging level is part of the message (e.g. they can automatically pick out WARN or ERR or INFO and identify those lines correctly).

[Kyle0654]

I'd maybe just import as log instead of ialog. Would read cleaner.

[lstein]

Is there a way for the user to override the formats, or even just use standard Python formats? I can imagine there are tools out there that work really well with standard Python log formatting, and changing that might create extra work. In particular, I've seen log aggregators do well when the logging level is part of the message (e.g. they can automatically pick out WARN or ERR or INFO and identify those lines correctly).

Absolutely. You can change the format using the same methods as you would
in the regular logging library (i.e. via BasicConfig, adding a custom
formatter, or resetting to the default formatter).

Really all the ialogger does is to change the default formatter.

You can also still import the standard logging library and use that. They
won't clash. Here's some code:

import invokeai.backend.util.logging as	ialog
import logging

logger = ialog.getLogger()
fh = logging.FileHandler('test.log')
fh.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
logger.addHandler(fh)

logger.info('testing, one two three')
logger.debug('this is a debugging statement')
logger.debug('this is another debugging statement')

Here's what appears on the console:

>> testing, one two three    
   | this is a debugging statement  
   | this is another debugging statement   

And here's what appears in the test.log logfile:

2023-04-11 18:21:38,293 - root - INFO - testing, one two three
2023-04-11 18:21:38,293 - root - DEBUG - this is a debugging statement
2023-04-11 18:21:38,293 - root - DEBUG - this is another debugging statement

[lstein]

I'd maybe just import as log instead of ialog. Would read cleaner.

You didn't get the joke? It's "dialog" without the "d", meaning a one-way conversation.

Oh well. New commit changes ialog->log

[Kyle0654]

You didn't get the joke? It's "dialog" without the "d", meaning a one-way conversation.
lol. drinks more tea

About the "user" changing the log format - I meant more the "end user" than the programmer. Can we set up configuration so the user can configure logging via command line flags / environment variables / config files?

[lstein]

Yes, that's coming with the configuration system. There will be "logging", "loglevel" and "log-format" options. "logging" will provide options for console, syslog, file and http log destinations.

BTW, if I use omegaconf for the configuration system, which I'm strongly considering doing, the command-line option format will change by default to foo=bar rather than --foo=bar. If necessary I could likely change it back with some pre-processing of sys.argv. What do you think?

[Kyle0654]

hrm... I don't know? I'm used to -- being for switches and - being for short switches, then the rest being for commands and subcommands. No way to configure omegaconf for that?

[lstein]

hrm... I don't know? I'm used to -- being for switches and - being for short switches, then the rest being for commands and subcommands. No way to configure omegaconf for that?

omegaconf doesn't seem to offer the option, but I could process sys.argv to remove -- before passing it to omegaconf. Support for short switches won't be as easy. So maybe a combination of omegaconf and argparse is the right thing to do.

I'm going to finish off replacing print() calls with log() calls and then do the system-wide configuration work, and will figure out a way to preserve argparse-style command-line arguments while supporting an omegaconf-style .yaml configuration file for user preferences.

[lstein]

The configuration system is coming along OK, and I'll be adding options to log to files, syslog and arbitrary http endpoints at that time.

[psychedelicious]

Looks good to me. I'm approving with two nice-to-haves:

1. There are a number of other useful subclasses of Handler (and it is possible to create a custom handler). It'd be nice to be able to dynamically add and remove handlers.

2. May also be nice to slot in a totally different logging module at some point.

[lstein]

Looks good to me. I'm approving with two nice-to-haves:

1. There are a number of other useful subclasses of Handler (and it is possible to create a custom handler). It'd be nice to be able to dynamically add and remove handlers.
2. May also be nice to slot in a totally different logging module at some point.

1. Thanks for the approval. Indeed, once the configuration system is merged in I'm going to come back to this and slot in support for multiple logging handlers, such as web and syslogging.
2. The various logging modules all seem to have similar APIs so that shouldn't be too difficult. Aside from the customization of the console error messages, this is just a vanilla Python logging module, so slotting in something different wouldn't be hard. Should I make this a service and create a slot for it in invocation_services?

[psychedelicious]

I think it makes sense to be a service. It would just make a lot of the code cleaner (ie you use the service to log within the nodes system rather than importing the module), and if we wanted to add out own logging service we could just swap the service.

@Kyle0654 & @ebr can answer better

[lstein]

@Kyle0654 @psychedelicious I've made the logging module into one of the customizable services provided by invoker and ApiDependencies. Could you check that I've done this in the right way? See the edited top-level PR comment for a quick summary of how it is intended to work.

[Kyle0654]

@Kyle0654 @psychedelicious I've made the logging module into one of the customizable services provided by invoker and ApiDependencies. Could you check that I've done this in the right way? See the edited top-level PR comment for a quick summary of how it is intended to work.

ApiDependencies is only for the API, so the CLI would need something too.

I'm very used to object-oriented approaches, and I know Python utilizes static approaches for a lot of things, so I'm not sure what the correct approach is here. I suspect it's to configure a logging module at startup and then just use that logging module everywhere else (as long as you can ensure it's been configured before use).

[ebr]

LGTM - does what it says on the tin. I was able to:

• easily add standardized logging everywhere in the web API by accessing invoker.services.logger
• customize the log format by getting a new logger
• use a different logger by importing it api_app.py

Regarding it being a service (addressing @psychedelicious' point) - we could add a wrapper under api/services so the logger class could be used as a fully fledged InvocationService. Right now it appears the logger is initialized differently. I believe that would be the correct pattern, but on the other hand, if we configure the logging module at startup, we could use it for FastAPI as well to uniformly format messages across the board. Anyway, this can all be improved later.

[hipsterusername]

@lstein - Think this is ready to merge after it gets updated w/ main. I'm hesitant to join in the fun and do that, as I'm not sure if it would result in needing new approvals.

[lstein]

LGTM - does what it says on the tin. I was able to:

• easily add standardized logging everywhere in the web API by accessing invoker.services.logger
• customize the log format by getting a new logger
• use a different logger by importing it api_app.py

Regarding it being a service (addressing @psychedelicious' point) - we could add a wrapper under api/services so the logger class could be used as a fully fledged InvocationService. Right now it appears the logger is initialized differently. I believe that would be the correct pattern, but on the other hand, if we configure the logging module at startup, we could use it for FastAPI as well to uniformly format messages across the board. Anyway, this can all be improved later.

That sounds good, but I'm really unfamiliar with FastAPI. Can you give me a hint on how to do this?

[ebr]

That sounds good, but I'm really unfamiliar with FastAPI. Can you give me a hint on how to do this?

I am pretty sure that last part might be as simple as setting app.logger = myCustomLogger. But that's just what I picked up from reading the docs and haven't tried it myself yet to be certain!