emrgnt-cmplxty / automata

Automata: A self-coding agent
Apache License 2.0
615 stars 100 forks source link

Fix inconsistent logging behavior by setting proper handlers #474

Closed NolanTrem closed 1 year ago

NolanTrem commented 1 year ago

There was an issue with how logging was being handled in scripts, leading to some unpredictable behaviors across the project. This was the result of how the logging library works, and in particular how handlers are set for the logger. Before changes in the CLI, there was a logger configuration defined in automata/core/utils.py. This get_logging_config function is maintained in this PR. For logging to correctly display as we would expect it, a handler must be set. This can be set upstream, in functions that a script may rely on—simply importing these functions is enough for the logger library to correctly inherit the context of how to set this handler.

This can lead to some confusing behaviors, where in some scripts you can create a logger, and simply change its logging level by setting logger.setLevel(logging.LEVEL)—and this will work as expected. In other scripts that don't inherit this context from upstream, creating a logger and setting its level leads to an unexpected output—in most cases no output.

This PR addresses the problem by ensuring that the proper handler is set: that defined for the project in automata/core/utils.py. It explicitly sets the handler in places where it may have been previously passed from upstream and introduces the handler where it was missing. It also switches the print statements that were used temporarily for the agent to the logger.

Correctly adding logging to a script is done like so:

import logging
import logging.config

from automata.core.utils import get_logging_config

logger = logging.getLogger(__name__)
logging.config.dictConfig(get_logging_config())

# We can either inherit the base level from the hander or redefine the level for this logger
logger.setLevel(logging.DEBUG)

The demonstration below illustrates this behavior in both the Automata projects and a separate repo for demonstration purposes.

Screenshot 2023-08-09 at 9 53 41 PM
import logging
import logging.config

from automata.core.utils import get_logging_config

logger_1 = logging.getLogger(__name__)
logger_1.setLevel(logging.INFO) # <--- We can attempt to set the level here, but we haven't set a handler yet

print("Testing configuration without setting the logging configuration:")
logger_1.setLevel(logging.DEBUG)
logger_1.debug('debug message')
logger_1.info('info message')

logger_1.setLevel(logging.INFO)
logger_1.debug('debug message')
logger_1.info('info message')

logger_2 = logging.getLogger(__name__)
logging.config.dictConfig(get_logging_config()) # <--- This line was in run_agent_config_validation.py and a few others

print("Testing configuration while setting the logging configuration")
logger_2.setLevel(logging.DEBUG)
logger_2.debug('debug message')
logger_2.info('info message')

logger_2.setLevel(logging.INFO)
logger_2.debug('debug message')
logger_2.info('info message')

logger_3 = logging.getLogger(__name__)
logger_3.setLevel(logging.INFO) # <--- We havent set a handler yet, but since we did above, it will carry the context to this logger!

print("Testing configuration while setting the logging configuration")
logger_3.setLevel(logging.DEBUG)
logger_3.debug('debug message')
logger_3.info('info message')

logger_3.setLevel(logging.INFO)
logger_3.debug('debug message')
logger_3.info('info message')
Screenshot 2023-08-09 at 10 04 04 PM
import logging

logger = logging.getLogger(__name__)

logger.setLevel(logging.DEBUG) # <--- Simply setting this won't allow for output to console

logger.info('info message from root logger')
logger.debug('debug message from root logger')

Updated output on the Agent after moving print statements to logger:

Screenshot 2023-08-09 at 10 57 51 PM