New command logger logcm as a replacement of print calls (updated)

[t-woerner]

New command logger logcm as a replacement of print calls

The use of print calls in the installer parts are resulting in the need to
redirect stdout using redirect_stdout in ansible-freeipa. redirect_stdout
is creating a new scope.

The CommandOutput type is a wrapper for a logger instance. It marks log
calls to be printed out on stdout using logger.INFO level. The extra
argument { "cmd_output": True } is set to make sure that a filter could
be used to filter this out for the installer log files.

Usage:

import logging
from ipapython.ipa_log_manager import CommandOutput

logger = logging.getLogger(__name__)
logcm = CommandOutput(logger)

def install():
    logcm("Installing ...")

Design note

The command logger instance is called logcm, because the name has the
same length as the print function. It may not be the prettiest name,
but it avoids code reformatting and therefore merge conflicts.

At first we considered to add a log_cmd method to all loggers.
The logging.setLoggerClass is the public function to set a new logger
class. To make it work, is has to be called before the first logger
objects is instantiated. It's not appropriate to modify the logger
early in ipalib, because ipalib is also designed to get embedded
into applications. And monkey-patching the logging.Logger class is
a hack.

The log format for CommandOutput is defined in LOGGING_FORMAT_CMD_OUTPUT
and is applied with the extended Formatter class for the log level INFO
only.

[abbra]

@t-woerner thanks for the patch. I have one small suggestion: in order to simplify maintenance backports, please split commits that convert individual files to separate commits. This way, for example, a commit that changes ipaserver/install/server/upgrade.py wouldn't create a conflict for changes in ipaserver/install/dsinstance.py and so on. With smaller commits backports will be automatic.

[tiran]

For this kind of stuff it should be possible to increase the log level to WARNING.

[t-woerner]

I think this should be an extra commit.

[tiran]

@t-woerner thanks for the patch. I have one small suggestion: in order to simplify maintenance backports, please split commits that convert individual files to separate commits. This way, for example, a commit that changes ipaserver/install/server/upgrade.py wouldn't create a conflict for changes in ipaserver/install/dsinstance.py and so on. With smaller commits backports will be automatic.

I don't understand how this approach is going to reduce the amount of merge conflicts in backports. How do multiple commits reduce the amount of conflicts when none of the commits are cherry-picked into the backport branch?

[tiran]

May I propose a slightly different approach that avoids monkey patching of classes and reduces the amount of code reformatting?

import logging

class CommandOutput:
    """Command output -- log and print to user

    The CommandOutput type is a wrapper for a logger instance. It
    marks log calls to be printed out on stdout.

    Usage:

        import logging
        from ipapython.ipa_log_manager import CommandOutput

        logger = logging.getLogger(__name__)
        logcm = CommandOutput(logger)

        def install():
            logcm("Installing ...")

    Design note
    -----------

    The command logger instance is called ``logcm``, because the name has the
    same length as the ``print`` function. It may not be the prettiest name,
    but it avoids code reformatting and therefore merge conflicts.

    At first we considered to add a ``log_cmd`` method to all loggers.
    The ``logging.setLoggerClass`` is the public function to set a new logger
    class. To make it work, is has to be called before the first logger
    objects is instantiated. It's not appropriate to modify the logger
    early in ``ipalib``, because ``ipalib`` is also designed to get embedded
    into applications. And monkey-patching the ``logging.Logger`` class is
    a hack.
    """
    __slots__ = ('_logger',)

    def __init__(self, logger):
        self._logger = logger

    def __call__(self, msg, *args, **kwargs):
        if 'extra' not in kwargs:
            kwargs["extra"] = {"cmd_output": True}
        else:
            kwargs["extra"]["cmd_output"] = True
        level = kwargs.pop("level", logging.INFO)
        self._logger.log(level, msg, *args, **kwargs)

[tiran]

Please only modify the installer code and unpatch the following files.

ipalib/cli.py
ipalib/messages.py
ipaserver/dnssec/ldapkeydb.py
ipaserver/dnssec/localhsm.py

ipalib.cli implements the ipa command. With the current state, ipa does not print anything. The other modules use print() in __main__ blocks, which are only used for development and debugging.

[abbra]

I don't understand how this approach is going to reduce the amount of merge conflicts in backports. How do multiple commits reduce the amount of conflicts when none of the commits are cherry-picked into the backport branch?

Suppose you have to backport a fix that was committed after these changes landed, in a proximity of the changes. When the changes split into smaller commits, a backport would result in porting a smaller base commit that adds logging support and the small patch from the affected area. If this would have been a single commit that touches multiple files, you would have to create a manual backport that will involve quite a lot of effort to make sure all pieces are not conflicting with something else.

[tiran]

There should be no no calls to .format() or % in logcm(). I marked some of the calls, but there are many more.

[abbra]

Same here

[abbra]

Same here

[abbra]

same here

[abbra]

Same here

[abbra]

same here

[abbra]

And these two lines

[abbra]

Same here

[abbra]

Same here

[abbra]

Same here

[abbra]

@t-woerner I found a bunch of same type conversion errors that need to be fixed.

[tiran]

@t-woerner I found a bunch of same type conversion errors that need to be fixed.

The code is correct and uses the preferred format for logging. The logger does not perform string formatting by itself. The format message and arguments are passed to handlers and then formatted inside the handler's log formatter.

[abbra]

@t-woerner @tiran my fault (too late after work, you know..) So please ignore it. ;) LGTM

[tiran]

This logic should not be in the formatter but rather in the handler's formatter configuration. With this approach the debug logs will miss context and time information for logcm events. Please use a different formatter for log files and stdout logging here:

freeipa/ipapython/ipa_log_manager.py

Lines 166 to 179 in b79ea6a

	file_handler.setLevel(logging.DEBUG)
	file_handler.setFormatter(Formatter(LOGGING_FORMAT_STANDARD_FILE))
	root_logger.addHandler(file_handler)
	level = logging.ERROR
	if verbose:
	level = logging.INFO
	if debug:
	level = logging.DEBUG
	console_handler = logging.StreamHandler()
	console_handler.setLevel(level)
	console_handler.setFormatter(Formatter(console_format))
	root_logger.addHandler(console_handler)

freeipa/ipalib/plugable.py

Lines 450 to 522 in b79ea6a

	root_logger = logging.getLogger()
	# If logging has already been configured somewhere else (like in the
	# installer), don't add handlers or change levels:
	if root_logger.handlers or self.env.validate_api:
	return
	if self.env.debug:
	level = logging.DEBUG
	else:
	level = logging.INFO
	root_logger.setLevel(level)
	for attr in self.env:
	match = re.match(r'^log_logger_level_'
	r'(debug|info|warn|warning|error|critical|\d+)$',
	attr)
	if not match:
	continue
	level = ipa_log_manager.convert_log_level(match.group(1))
	value = getattr(self.env, attr)
	regexps = re.split('\s*,\s*', value)
	# Add the regexp, it maps to the configured level
	for regexp in regexps:
	root_logger.addFilter(ipa_log_manager.Filter(regexp, level))
	# Add stderr handler:
	level = logging.INFO
	if self.env.debug:
	level = logging.DEBUG
	else:
	if self.env.context == 'cli':
	if self.env.verbose > 0:
	level = logging.INFO
	else:
	level = logging.WARNING
	handler = logging.StreamHandler()
	handler.setLevel(level)
	handler.setFormatter(ipa_log_manager.Formatter(LOGGING_FORMAT_STDERR))
	root_logger.addHandler(handler)
	# check after logging is set up but before we create files.
	fse = sys.getfilesystemencoding()
	if fse.lower() not in {'utf-8', 'utf8'}:
	raise errors.SystemEncodingError(encoding=fse)
	# Add file handler:
	if self.env.mode in ('dummy', 'unit_test'):
	return # But not if in unit-test mode
	if self.env.log is None:
	return
	log_dir = path.dirname(self.env.log)
	if not path.isdir(log_dir):
	try:
	os.makedirs(log_dir)
	except OSError:
	logger.error('Could not create log_dir %r', log_dir)
	return
	level = logging.INFO
	if self.env.debug:
	level = logging.DEBUG
	try:
	handler = logging.FileHandler(self.env.log)
	except IOError as e:
	logger.error('Cannot open log file %r: %s', self.env.log, e)
	return
	handler.setLevel(level)
	handler.setFormatter(ipa_log_manager.Formatter(LOGGING_FORMAT_FILE))
	root_logger.addHandler(handler)

[tiran]

This is the wrong approach, see flow diagram. The logic should be in the handler configuration. You have to use multiple handlers:

1. One stdout handler with a filter for cmd_output records, a filter for level < WARNING records, and a cmd_output_format formatter.
2. One stderr handler with a filter for cmd_output records, a filter for level >= WARNING records, and a cmd_output_format formatter.
3. One stdout handler with a filter for non-cmd_output records and console_format formatter.

Handler 3 could be split into two separate handlers. I think it would be a good idea to not print a full traceback in cmd_output_formatter (see formatException).

[tiran]

Why do you add the filter to the file logger instead of the console logger? Isn't the filter suppose to filter which events end up in stdout?

[t-woerner]

Adding the filter to the installation log fil e handler makes sure that the print output is not in the log file (like it has been up to now) and is by default in the normal installer (log) output. This makes sure that an existing application using FreeIPA parts does not need to enable this explicitly.

[tiran]

I think we have some kind of misunderstanding. Having the output in the log files is one of the benefits for me. It makes it easier to correlate debug logs with installer console output.

I proposed the cmd_output flag to mark log entries that also land on stdout (console logger).

[t-woerner]

This is behavior change that needs to be verified also in all the tests.

[tiran]

ipapython.admintool also performs logger configuration. I think you need to address setup_logging, too.

[t-woerner]

ipapython.admintool also performs logger configuration. I think you need to address setup_logging, too.

ipapython.admintool._setup_logging, which is used in ipapython.admintool.setup_logging is using standard_logging_setup. Therefore it should not be needed to do further changes here.

[tiran]

There are still a bunch of print() calls in the installer code.

logcm("WARNING: ...") and print(file=sys.stderr) should be replaced with logcm(..., level=logging.WARNING) and a proper formatter/handler combination. The formatter could prepend WARN.

[tiran]

This is the wrong approach, see flow diagram. The logic should be in the handler configuration. You have to use multiple handlers:

1. One stdout handler with a filter for cmd_output records, a filter for level < WARNING records, and a cmd_output_format formatter.
2. One stderr handler with a filter for cmd_output records, a filter for level >= WARNING records, and a cmd_output_format formatter.
3. One stdout handler with a filter for non-cmd_output records and console_format formatter.

Handler 3 could be split into two separate handlers. I think it would be a good idea to not print a full traceback in cmd_output_formatter (see formatException).