Disable Logging of All But Some Messages

Disable Logging of All But Some Messages

Motivation

Logging is a useful tool for testing. It can be used for different purposes throughout a test: outputting properties of a GUI object, tracking the current executed step, debugging which particular code path is being followed, and why, and much more. However, tests tend to grow either in length or number to cover more cases, verify bug fixes or other similar use cases, and this can lead to test output containing so much logged data that it can be hard to dissect. Using test.startSection()/endSection() can help to improve the readability, as can the use of testSettings.silentVerifications to some extent, but it would sometimes be preferable to log only certain specific log messages (think about debug for example).

What we propose in this article is an example that demonstrates how to modify Squish functions and in particular test.log() so only some messages get logged. While the snippet is in Python, the same could be done in other supported scripting languages.

An Example

def main():
    startApplication("addressbook")


    # Define alternative log() function:
    def test_log_only_prio1(msg, detail=None, priority=None):
        if priority is None or "PRIO1" not in priority:
            return
        if detail is None:
            test.log_original(msg)
        else:
            test.log_original(msg, detail)
    # Install alternative log() function:
    test.log_original = test.log
    test.log = test_log_only_prio1


    for i in range(10):
        test.log("Before action", priority=["PRIO1"])
        test.log("This is a debug log", priority=["DEBUG"])
        test.log("After action", priority=["PRIO1"])

The test result for this test case will not show any log of what we described as “DEBUG” logging. We could do the opposite and have a function that would log only “DEBUG” messages and so on, based on our needs.

What’s Next

This technique could be used in conjunction with the one presented in this other article in order to have, for example, real-time logging of debug information for long-running tests. We also made the example deliberately simpler by choosing to write which new log function to use, but it is possible to think about having this choice made dynamically based on some environment variable for example so that there is no need to change the test manually.

3 Comments

  1. Jörg Gerlach 1 month ago

    Hello Thomas,

    I have implemented a similar approach for my tests. It is basically the same but I didn’t replace the original test.log instead refactored my tests to use my log method instead.
    This does shorten the log amount for automatic test execution where it only logs errors and warnings and for manually test execution it logs info/debug messages as well. So I can better find/see what was executed.

    So far so good but it cancels out a nice aspect of the default method, which also logs the file and line number where the log was called. All entries have now the same file and line number associated with them.
    As workaround, I added this to the log message itself. Just to have it. But for example the SquishIde uses this to jump to the error or when clicking on the entry in the result view.

    Is there a way to restore that behavior?

Leave a reply

Your email address will not be published. Required fields are marked *

*