Save all warnings encountered in a warnings file

[LecrisUT]

---

Pull Request Checklist

• implement the feature
  • Save warning messages into a file
  • Allow warnings to define where they come from
  • Define a schema for the warnings file
• write the documentation
• extend the test coverage
• update the specification
• adjust plugin docstring
• modify the json schema
• mention the version
• include a release note

Fixes #4618

[gemini-code-assist]

Code Review

This pull request introduces a feature to save all encountered warnings into a warnings.yaml file. However, it introduces several critical security and stability risks. A critical initialization order flaw in the Run class and a missing import in tmt/log.py will cause the application to crash immediately. Furthermore, an unsafe assert statement in the logging path poses a Denial of Service risk, and the lack of synchronization when writing to the warnings file introduces a race condition that could lead to data loss. The current implementation also suffers from inefficiency due to frequent file I/O.

[happz]

My two cents noone asked for: have you considered using a logging handler, similar to LogfileHandler, with custom emit() method? That would be my first choice for this endeavor, because AFAICT, if the idea is to direct warnings into one extra file with special log format, it'd be pretty much the job for logging handler.

The handler could be attached to the run logger (like a logfile is attached to the root logger via add_logfile_handler(), ), and that would be it. The handler would then receive all warnings emitted from loggers below it, as all loggers propagate their messages upward (to get them logged into a logfile). Channeling the records into new file would then happen there rather than in the warning() method which in your draft has two jobs instead of one: not just emitting the record, but also route the record into a logfile, which is exactly what handlers are for.

[LecrisUT]

have you considered using a logging handler, similar to LogfileHandler, with custom emit() method?

Ah you mean to reuse that class as the file handler, yeah, sounds reasonable.

Right now I am at the stage to check if the run logger is propagated consistently. Stuff like tmt show I expect to fail, but I want to get a list of all the failure points right now to see what opt-out to use for those.

The handler would then receive all warnings emitted from loggers below it, as all loggers propagate their messages upward (to get them logged into a logfile). Channeling the records into new file would then happen there rather than in the warning() method

This part I need more eyes on the code to figure out what you mean here

[happz]

have you considered using a logging handler, similar to LogfileHandler, with custom emit() method?

Ah you mean to reuse that class as the file handler, yeah, sounds reasonable.

Well, not really reuse the class we have, but adding a new one, as the format of the file would be different, plus the filtering is needed. But following the same concept of using a logging handler for this job, yes. The separation of "what to log" and "where it should go". We may decide to sent all warnings and errors to a Sentry instance, for that we would add another handler, with filtering and Sentry API client, and attach it to the root logger, rather than touching error() and warning() implementation.

The handler would then receive all warnings emitted from loggers below it, as all loggers propagate their messages upward (to get them logged into a logfile). Channeling the records into new file would then happen there rather than in the warning() method

This part I need more eyes on the code to figure out what you mean here

Nothing exceptional there, just loggers sending their records upward to their parent. Usually with the logging subsystem, if there are multiple loggers, they tend to have their own handlers, for various reasons. In our case, console handler and logfile handler are attached to the root logger, it's there where records are emitted and filtering happens. This is to make sure all logging lands in the log file, attaching log file to every single logger in the tree would be, hm, impractical, to say at least. Loggers spawned in runtime attach the right verbosity and labels and so on to records, and let them bubble up to the root. Perfectly valid setup per logging docs.

In your scenario, you would introduce new handler, I am just not sure whether it should be attached to the root logger, or to the run-level one. Probably the run, bit may miss some warnings emitted before workdir is created, for example. On the other hand, where would such warning be saved by the handler, when there's no workdir yet to host the warnings.yaml file?

[LecrisUT]

Probably the run, bit may miss some warnings emitted before workdir is created, for example.

Is there a reason we cannot move the run workdir creation as early as needed?

On the other hand, where would such warning be saved by the handler, when there's no workdir yet to host the warnings.yaml file?

For the case where we know it should not have a run_workdir, e.g. tmt show then we should skip that. For cases where it has, but it was not created yet, we need to check the context and figure out if we should be deferring them. Ideally we should not have any imo, but we need to look more carefully with more context on those.

Usually with the logging subsystem, if there are multiple loggers, they tend to have their own handlers, for various reasons. In our case, console handler and logfile handler are attached to the root logger, it's there where records are emitted and filtering happens.

Isn't this something we do not have right now? A logger with multiple sub-loggers/drivers? Our descend just creates a new logger, and I don't think that part is intended to be used to have hierarchical connection right?

The idea is sound, but how do we do the separation inside the Logger? My view would be that it should own a list of logging drivers that would specify where it should emit to. Though I would do it in a subsequent PR.

Loggers spawned in runtime attach the right verbosity and labels and so on to records, and let them bubble up to the root.

This part you lost me again because we do not have a design that bubbles up the logging right? Would need a sketch to figure out the refactoring idea of that.

[happz]

Probably the run, bit may miss some warnings emitted before workdir is created, for example.

Is there a reason we cannot move the run workdir creation as early as needed?

Just the complexity and technical debt. I have some ideas about how workdirs should be handled in the code, but it's just so painful to start something as it takes ages to get it in, and touching complex topics like this spells a hell of a rebase along the road.

Some commands have no need for it, e.g. tmt * show and tmt * ls, it's tied to tmt run and Run class, but because of history, it's not straightforward.

On the other hand, where would such warning be saved by the handler, when there's no workdir yet to host the warnings.yaml file?

For the case where we know it should not have a run_workdir, e.g. tmt show then we should skip that. For cases where it has, but it was not created yet, we need to check the context and figure out if we should be deferring them. Ideally we should not have any imo, but we need to look more carefully with more context on those.

Ideally once in a run context, we should have a workdir and a place to write warnings into.

Usually with the logging subsystem, if there are multiple loggers, they tend to have their own handlers, for various reasons. In our case, console handler and logfile handler are attached to the root logger, it's there where records are emitted and filtering happens.

Isn't this something we do not have right now? A logger with multiple sub-loggers/drivers? Our descend just creates a new logger, and I don't think that part is intended to be used to have hierarchical connection right?

# in Logger.descend():

actual_logger = self._normalize_logger(self._logger.getChild(logger_name))

Newly created logging.Logger is a child of the logging.Logger wrapped by tmt.log.Logger. So we do have this tree in place.

    @staticmethod
    def _normalize_logger(logger: logging.Logger) -> logging.Logger:
        """
        Reset properties of a given :py:class:`logging.Logger` instance
        """

        logger.propagate = True
        logger.level = logging.DEBUG

        logger.handlers = []

        return logger

Every logger is set to propagate its records to its parent, have the lowest loglevel possible, and have no handlers - the root one gets handlers attached later.

Loggers spawned in runtime attach the right verbosity and labels and so on to records, and let them bubble up to the root.

This part you lost me again because we do not have a design that bubbles up the logging right? Would need a sketch to figure out the refactoring idea of that.

We do :)

[LecrisUT]

There is a big complication with the order of how run_workdir is handled and the order of initialization, so even for my debugging I have to go with something more polished and seems like I would go with a deferred logger writing to the warnings file as soon as it is available. Custom handler it is.

    @staticmethod
    def _normalize_logger(logger: logging.Logger) -> logging.Logger:
        """
        Reset properties of a given :py:class:`logging.Logger` instance
        """

        logger.propagate = True
        logger.level = logging.DEBUG

        logger.handlers = []

        return logger

This thing is puzzling me though. If we are nuking the logger.hanlders in the .descend how are those messages appearing? I do not see that add_console_handler is called on anything other then bootstraplogger and the root one :/

[happz]

    @staticmethod
    def _normalize_logger(logger: logging.Logger) -> logging.Logger:
        """
        Reset properties of a given :py:class:`logging.Logger` instance
        """

        logger.propagate = True
        logger.level = logging.DEBUG

        logger.handlers = []

        return logger

This thing is puzzling me though. If we are nuking the logger.hanlders in the .descend how are those messages appearing? I do not see that add_console_handler is called on anything other then bootstraplogger and the root one :/

logger.propagate does the trick. By default, no logger in our tree has any handler at all, and propagates its messages to whichever logger is its parent. Thanks to descend(), all records bubble up to the root logger. Handlers are attached to that one. If we attach e.g. a logfile handler to more than one logger, for the same logfile, we would need to start worrying about propagation because suddenly a single record would appear in the file multiple times.

Attaching a warning-file handler to the run-level logger should work like this: all records travel to root logger, they must pass through the run-level logger, which would sent them to its warning-file handler as well as to its parent, to end up in the logfile and on console.

[LecrisUT]

logger.propagate does the trick. By default, no logger in our tree has any handler at all, and propagates its messages to whichever logger is its parent. Thanks to descend(), all records bubble up to the root logger. Handlers are attached to that one. If we attach e.g. a logfile handler to more than one logger, for the same logfile, we would need to start worrying about propagation because suddenly a single record would appear in the file multiple times.

Ok, that explains things. There are 2 options here then:

• Allow the Run logger to have its own handler and create it as soon as the workdir is available
• Create the handler at root level again, but navigate through the loggers until I find the root logger, get the warnings-file handler and inject the actual file path to write to

[happz]

logger.propagate does the trick. By default, no logger in our tree has any handler at all, and propagates its messages to whichever logger is its parent. Thanks to descend(), all records bubble up to the root logger. Handlers are attached to that one. If we attach e.g. a logfile handler to more than one logger, for the same logfile, we would need to start worrying about propagation because suddenly a single record would appear in the file multiple times.

Ok, that explains things. There are 2 options here then:

• Allow the Run logger to have its own handler and create it as soon as the workdir is available
• Create the handler at root level again, but navigate through the loggers until I find the root logger, get the warnings-file handler and inject the actual file path to write to

I believe the first option is the right way to go: once Run establishes its workdir, it should attach the "WarningFile" handler to its own logger, give it the path to the warning file. And that should be all.

[LecrisUT]

Ok, that explains things. There are 2 options here then:

• Allow the Run logger to have its own handler and create it as soon as the workdir is available
• Create the handler at root level again, but navigate through the loggers until I find the root logger, get the warnings-file handler and inject the actual file path to write to

I believe the first option is the right way to go: once Run establishes its workdir, it should attach the "WarningFile" handler to its own logger, give it the path to the warning file. And that should be all.

But that would miss the warnings in between the click code and creation of the run_workdir. With my debugger I was unable to find any of them that would realistically be encountered, e.g. even the schema validation which is done as part of an __init__ is emitted after the workdir was created. The only parts that I could otherwise find is if it is emitted inside Phase.command(), which is not a user warning, but still a relevant warning to be collected for testing-farm itself.

The only other thing is that it breaks the current state of handlers are only at the top-level, and it could open the gate for having some plugin-specific handlers. This would not be a negative IMO, just a new thing to be aware of.

[happz]

Ok, that explains things. There are 2 options here then:

• Allow the Run logger to have its own handler and create it as soon as the workdir is available
• Create the handler at root level again, but navigate through the loggers until I find the root logger, get the warnings-file handler and inject the actual file path to write to

I believe the first option is the right way to go: once Run establishes its workdir, it should attach the "WarningFile" handler to its own logger, give it the path to the warning file. And that should be all.

But that would miss the warnings in between the click code and creation of the run_workdir. With my debugger I was unable to find any of them that would realistically be encountered, e.g. even the schema validation which is done as part of an __init__ is emitted after the workdir was created. The only parts that I could otherwise find is if it is emitted inside Phase.command(), which is not a user warning, but still a relevant warning to be collected for testing-farm itself.

Correct, there would be this gap, a gap before the "run context" begins. For the first version, I for one would find it acceptable. To cover this gap, we could think about commands like tmt * show: if there are warnings happening when they run, should we also save them in some file, if so, which file? That could give us some guidance and idea how to handle pre-run warnings in tmt run.

The only other thing is that it breaks the current state of handlers are only at the top-level, and it could open the gate for having some plugin-specific handlers. This would not be a negative IMO, just a new thing to be aware of.

Yes. So far we had no use for them, the "save warnings that happened during run" use case calls for the change. I think it's the right approach, and if we discover there's a use case for discover/fmf to have a special handler, we would have some experience already.

[graphite-app]

Uses identity comparison (is) instead of equality comparison (==) for integer values. The is operator checks object identity, not value equality. While this might work for logging.WARNING (value 30) due to Python's integer caching for small numbers, it's incorrect and unreliable. This should be:

if record.levelno == logging.WARNING:

Without this fix, the filter may fail to capture warning messages, causing them not to be written to the warnings file.

Suggested change

	if record.levelno is logging.WARNING:
	if record.levelno == logging.WARNING:

Spotted by Graphite



Is this helpful? React 👍 or 👎 to let us know.