Uploaded image for project: 'Solr'
  1. Solr
  2. SOLR-15629

Improve the way we "expect" ERROR messages in tests

Details

    • Improvement
    • Status: Open
    • Major
    • Resolution: Unresolved
    • None
    • None
    • None
    • None

    Description

      The original goal of this Jira is now tracked in the SOLR-15697 subtask.

       

      At a broader level this Jira is looking a ways to make it possible for tests to intercept & inspect log messages produced by SOlr during the test, and make assertions about them.

      Ideally we should reach the point where any ERROR or WARN message logged by a test that isn't explicitly "expected" would cause a test failure.

      Attachments

        1. SOLR-15629.patch
          34 kB
          Chris M. Hostetter

        Issue Links

          Activity

            Strawman idea of what this might look like from an API standpoint:

            • new abstract FilterOutLogMessagesTestRule class included in test-framework
            • deals with managing the lifecycle of a dynamically created Filter on the root loger
            • includes static helper methods for creating instances of this new Rule using simple input to indicate which log messages should be ignored.
              • CharSequence for simple substring, vs Pattern for regex, vs Function for fine grain control
            • Filter could use it's own Logger for INFO level summary of what it's ignore
              • with obvious check to prevent infinite loop
            • Maybe even support options to expect some number of matches against Filter - to allow tests to start asserting that certain WARN/ERROR are logged?
              • base class can handle counting how many LogEvents it rejects
              • Some public method (that can be chained) to take in a count (or lambda) to specify/validate the number of matching messages (and fail the test otherwise) once the test is complete
            // what the usage might look like...
            
            @Rule public TestRule logMsgSubString1 = FilterOutLogMessagesTestRule.error("ignoreMe");
            @Rule public TestRule logMsgSubstring2 = FilterOutLogMessagesTestRule.warn("ignoreMe");
            
            // applies to any log level, only looks at Throwable
            @Rule public TestRule throwableMsg = FilterOutLogMessagesTestRule.throwable(Pattern.compile("foo.*bar"));
            
            // super generic...
            @Rule public TestRule custom = FilterOutLogMessagesTestRule.custom(logEvent -> {
              return logEvent.getContextData().get("collection").equals("foo")
                && logEvent.getMessage().contains("bar") });
            
            // fail the test if we don't see this many matching messages...
            @Rule public TestRule logMsgSubString3 = FilterOutLogMessagesTestRule.error("ignoreMe").expect(5);
            @Rule public TestRule logMsgSubstring4 = FilterOutLogMessagesTestRule.warn("ignoreMe").expect(actual -> {
               return actual == this.numTimesWeRandomlyTriggeredBadBeavior });
            
            

            (If/when we do this, we could potentially make SolrTestCase start to fail if ANY unexpected ERROR/WARN makes it past the configured filters)

            hossman Chris M. Hostetter added a comment - Strawman idea of what this might look like from an API standpoint: new abstract FilterOutLogMessagesTestRule class included in test-framework deals with managing the lifecycle of a dynamically created Filter on the root loger includes static helper methods for creating instances of this new Rule using simple input to indicate which log messages should be ignored. CharSequence for simple substring, vs Pattern for regex, vs Function for fine grain control Filter could use it's own Logger for INFO level summary of what it's ignore with obvious check to prevent infinite loop Maybe even support options to expect some number of matches against Filter - to allow tests to start asserting that certain WARN/ERROR are logged? base class can handle counting how many LogEvents it rejects Some public method (that can be chained) to take in a count (or lambda) to specify/validate the number of matching messages (and fail the test otherwise) once the test is complete // what the usage might look like... @Rule public TestRule logMsgSubString1 = FilterOutLogMessagesTestRule.error( "ignoreMe" ); @Rule public TestRule logMsgSubstring2 = FilterOutLogMessagesTestRule.warn( "ignoreMe" ); // applies to any log level, only looks at Throwable @Rule public TestRule throwableMsg = FilterOutLogMessagesTestRule.throwable(Pattern.compile( "foo.*bar" )); // super generic ... @Rule public TestRule custom = FilterOutLogMessagesTestRule.custom(logEvent -> { return logEvent.getContextData().get( "collection" ).equals( "foo" ) && logEvent.getMessage().contains( "bar" ) }); // fail the test if we don't see this many matching messages... @Rule public TestRule logMsgSubString3 = FilterOutLogMessagesTestRule.error( "ignoreMe" ).expect(5); @Rule public TestRule logMsgSubstring4 = FilterOutLogMessagesTestRule.warn( "ignoreMe" ).expect(actual -> { return actual == this .numTimesWeRandomlyTriggeredBadBeavior }); (If/when we do this, we could potentially make SolrTestCase start to fail if ANY unexpected ERROR/WARN makes it past the configured filters)

            Thinking a little bit more about when/where/how SolrTestCaseJ4.ignoreException() is currently used, a TestRUle might not make that much sense – because it would be kind of coarse grained as far as when/where to expect the log messages to be generated.  We currently have difernet test methods in test classes (and different snippets of code in individual test methods) that want to ignore differnet log messages.

            a "lambda wrapper" (similar to how expectException(...) works) would probably make more sense...

            // mute & record any ERROR messages, then inspect them...
            List<LogEvent> actualErrorLogs = LoggerIntercepter.muteError( () -> {
              // test logic that will cause some ERROR logging
            });
            // assert that the actualErrorLogs only contain what we expect
            
            // mute and record ERROR messages matching a substring...
            List<LogEvent> actualErrorLogs = LoggerIntercepter.muteError("ignoreMe", () -> {
              // test logic that will cause two ERROR log msgs matching the substring 'ignoreMe' to occur
            });
            assert(2, actualErrorLogs.size());
            
            // etc... 

             

            ...If we had something like that, it could do the heavy lifiting to implement TestRules like i described above (if we decide we wanted them)

            hossman Chris M. Hostetter added a comment - Thinking a little bit more about when/where/how SolrTestCaseJ4.ignoreException() is currently used, a TestRUle might not make that much sense – because it would be kind of coarse grained as far as when/where to expect the log messages to be generated.  We currently have difernet test methods in test classes (and different snippets of code in individual test methods) that want to ignore differnet log messages. a "lambda wrapper" (similar to how expectException(...) works) would probably make more sense... // mute & record any ERROR messages, then inspect them... List<LogEvent> actualErrorLogs = LoggerIntercepter.muteError( () -> { // test logic that will cause some ERROR logging }); // assert that the actualErrorLogs only contain what we expect // mute and record ERROR messages matching a substring... List<LogEvent> actualErrorLogs = LoggerIntercepter.muteError( "ignoreMe" , () -> { // test logic that will cause two ERROR log msgs matching the substring 'ignoreMe' to occur }); assert (2, actualErrorLogs.size()); // etc...   ...If we had something like that, it could do the heavy lifiting to implement TestRules like i described above (if we decide we wanted them)

            a "lambda wrapper" (similar to how expectException(...) works) would probably make more sense...

            I briefly toyed with this, but quickly realized it was actaully a big pain in the ass, because there's no easy way for a method like this to propogate any Throwable thrown by the wrapped lambda w/o just delcaring "throws Throwable" (not an issue for expectException(...) because by design it wants to catch exceptions and it wants to "fail" if a different type of exception is thrown)

            I realized what makes a lot more sense is a LogInterceptor implements AutoClosable that sets up the log Filter in it's constructor/factory method, and removes the interception in it's close() method – that way you can use a "try-with-resources" to wrap the code you want to ignore exceptions in.

            A Pro/Con of this approach is that you can call methods on the LogInterceptor to "inspect" the intercepted log messages inside the try block, w/o needing to wait until all of the logic in the block is done ... the "Con" part being that you MUST call at least some method on the LogInterceptor inside the try block, or the compiler warn/fails tha it's unused. (Which i think is actually a "Pro": If a test wants to expect/ignore some ERROR message logs, it should assert something about them)

            The attached patch implements this idea – but I should note that I decided pretty quickly that because of how log4j (and it's APIs) work, just having each LogInterceptor add a Filter on the root logger ddin't seem like it would really cut it if we also wanted to support "inspection"; because if we wanted to have multiple LogInterceptor 's in use at the same time, each interceptor/Filter could potentially get in each others way. It seems cleaner to ask you what logger to "inspect" and use an Appender there with a Filter that only ACCEPTs the LogEvents you are interested in, while also adding a Filter to the ROOT logger to prevent those ERRORs from making it to the log file.

            The patch works, and you can see from the tests what it might look like if we started using it – but the more i've been working on it, the more disatisfied i've become with the both the surface API and a llot of the implementation details.

            I won't elaborate too much here in jira – it's pretty thoroughly spelled out in nocommit comments in the patch, where i also flesh out what i think would be better – for now i'll just point out:

            • I do plan to keep working on this
            • If i get hit by a bus and never finish this, please remember:
              • a lot of complexity in the current patch (and in the suggestions in the nocommit comments) comes from wanting to implement something BETTER then the existing SolrTestCaseJ4.ignoreException functionality
                • I'd really like us to be able write better tests that are more strict about if/when they expect an ERROR (or a WARN) to be logged
                • ideally even start failing the build if any test causes solr to log an ERROR that isn't expected
              • The original idea of just (temporarily) adding a Filter to the ROOT logger (that DENY's an ERROR log matching the Pattern or (sub)String) is still very viable and would be simple to implement as an alternative if someone is interested.
            hossman Chris M. Hostetter added a comment - a "lambda wrapper" (similar to how expectException(...) works) would probably make more sense... I briefly toyed with this, but quickly realized it was actaully a big pain in the ass, because there's no easy way for a method like this to propogate any Throwable thrown by the wrapped lambda w/o just delcaring "throws Throwable" (not an issue for expectException(...) because by design it wants to catch exceptions and it wants to "fail" if a different type of exception is thrown) I realized what makes a lot more sense is a LogInterceptor implements AutoClosable that sets up the log Filter in it's constructor/factory method, and removes the interception in it's close() method – that way you can use a "try-with-resources" to wrap the code you want to ignore exceptions in. A Pro/Con of this approach is that you can call methods on the LogInterceptor to "inspect" the intercepted log messages inside the try block, w/o needing to wait until all of the logic in the block is done ... the "Con" part being that you MUST call at least some method on the LogInterceptor inside the try block, or the compiler warn/fails tha it's unused. (Which i think is actually a "Pro": If a test wants to expect/ignore some ERROR message logs, it should assert something about them) The attached patch implements this idea – but I should note that I decided pretty quickly that because of how log4j (and it's APIs) work, just having each LogInterceptor add a Filter on the root logger ddin't seem like it would really cut it if we also wanted to support "inspection"; because if we wanted to have multiple LogInterceptor 's in use at the same time, each interceptor/Filter could potentially get in each others way. It seems cleaner to ask you what logger to "inspect" and use an Appender there with a Filter that only ACCEPTs the LogEvents you are interested in, while also adding a Filter to the ROOT logger to prevent those ERRORs from making it to the log file. The patch works, and you can see from the tests what it might look like if we started using it – but the more i've been working on it, the more disatisfied i've become with the both the surface API and a llot of the implementation details. I won't elaborate too much here in jira – it's pretty thoroughly spelled out in nocommit comments in the patch, where i also flesh out what i think would be better – for now i'll just point out: I do plan to keep working on this If i get hit by a bus and never finish this, please remember: a lot of complexity in the current patch (and in the suggestions in the nocommit comments) comes from wanting to implement something BETTER then the existing SolrTestCaseJ4.ignoreException functionality I'd really like us to be able write better tests that are more strict about if/when they expect an ERROR (or a WARN) to be logged ideally even start failing the build if any test causes solr to log an ERROR that isn't expected The original idea of just (temporarily) adding a Filter to the ROOT logger (that DENY's an ERROR log matching the Pattern or (sub)String) is still very viable and would be simple to implement as an alternative if someone is interested.

            The original idea of just (temporarily) adding a Filter to the ROOT logger (that DENY's an ERROR log matching the Pattern or (sub)String) is still very viable and would be simple to implement as an alternative if someone is interested.

            About 10 seconds after I posted that commend, I realized i was forgetting the importance of "progress, not perfection" and trying to design & build a new race car instead of just replacing the flattires on the bicycle we have.

            I'm going to re-title this Jira to match the broader goal of giving tests a way to be very explicit about what ERROR (and ideally even WARN) log messages they expect and force tests to "expect" these ERRORs.. but in the meantime, i'm going to open a subtask that deals with the smaller scale objective that this issue originally tracked – which i have a decent little patch for already

            hossman Chris M. Hostetter added a comment - The original idea of just (temporarily) adding a Filter to the ROOT logger (that DENY's an ERROR log matching the Pattern or (sub)String) is still very viable and would be simple to implement as an alternative if someone is interested. About 10 seconds after I posted that commend, I realized i was forgetting the importance of "progress, not perfection" and trying to design & build a new race car instead of just replacing the flattires on the bicycle we have. I'm going to re-title this Jira to match the broader goal of giving tests a way to be very explicit about what ERROR (and ideally even WARN) log messages they expect and force tests to "expect" these ERRORs.. but in the meantime, i'm going to open a subtask that deals with the smaller scale objective that this issue originally tracked – which i have a decent little patch for already

            People

              hossman Chris M. Hostetter
              hossman Chris M. Hostetter
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 1h 10m
                  1h 10m