Logging intermediary actual values for CallableHamcrestCondition

[Maciej Gawinecki]

I would like CallableHamcrestCondition to return not only timeout message, but also to log intermediary results of the matcher result and remaining time to timeout. For instance,

  expected <HotelBookingProcessed> but was <NotReceived> (remaining time 525ms)

  expected <HotelBookingProcessed> but was <NotReceived> (remaining time 412ms)

  expected <HotelBookingProcessed> but was <Received> (remaining time 363ms)

  expected <HotelBookingProcessed> but was <StartedToProcess> (remaining time 221ms)

  expected <HotelBookingProcessed> but was <StartedToProcess> (remaining time 104ms)

  com.jayway.awaitility.core.ConditionTimeoutException: tdp.core.SimpleTest.callable Callable expected <HotelBookingProcessed> but was <StartedToProcess> within 5 seconds.

at com.jayway.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:93)

at com.jayway.awaitility.core.AbstractHamcrestCondition.await(AbstractHamcrestCondition.java:62)

at com.jayway.awaitility.core.ConditionFactory.until(ConditionFactory.java:559)

at com.jayway.awaitility.core.ConditionFactory.until(ConditionFactory.java:377)

at tdp.core.SimpleTest.callable(SimpleTest.java:49)

For more complex matchers and changing state of actual value, having intermediary results would help a lot in troubleshooting test failure.

How could I add this to your library?

[Johan Haleby]

Hi, 

Interesting proposal. Perhaps it would be possible to make it configurable, for example using something like "with().intermediateLoggingEnabled().await(). .." or statically using Awaitility.intermediateLoggingEnabled(). If it's enabled each "poll" could store the non-matching result into an ArrayList in memory. If the test fails then the contents of the list could be used to construct the error message.

Regards,

/Johan

--
You received this message because you are subscribed to the Google Groups "Awaitility" group.
To unsubscribe from this group and stop receiving emails from it, send an email to awaitility+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Maciej Gawinecki]

Hi,

Thanks for sketching the approach. I will try to implement a patch with a solution. 

One comment only. You suggested to buffer intermediary results and report them all together at the end. I instead was thinking about reporting them on a way, because comparing remaining time with actual result of assertion (progress) can be sometimes more valuable than waiting to the end just to see what were the timeouts. To implement that I'm thinking about providing callback mechanisms where callback method be called for each "poll", e.g., 

  with().intermediateResultLogger(new ResultLogger() {

     @Override

     public void log(String mismatchDescription, Duration remainingTime) {

             // Up to the user, e.g. using log4j logger

     }

  }).await()...

Obviously, if one would like to buffer intermediary results, callback method could be used for that as well. 

Regards,

Maciej

--
You received this message because you are subscribed to a topic in the Google Groups "Awaitility" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/awaitility/AebI58y6VoU/unsubscribe.
To unsubscribe from this group and all its topics, send an email to awaitility+...@googlegroups.com.

[Johan Haleby]

That's an even better approach. Just wondering on how you can make it print only on timeout (I suspect that some users would like this). Try to make "ResultLogger" an implicit functional interface (i.e. not using a @FunctionalInterface annotation) so that it can be used as a lambda function in Java 8 but still be used as an anonymous inner class in legacy java versions.

Regards

/Johan

[Maciej Gawinecki]

I forked, pushed changes and create a pull request. Just curious if you got it?

Regards,

Maciej

[Johan Haleby]

I'll look into it as soon as I can. Thank you!

[Johan Haleby]

Hi, 

I've look into it a little bit I think it's a great contribution to the library. I've change a couple of things:

1. I've renamed the static method "handleIntermediaryResultsWith" to "setDefaultIntermediaryResultHandler" in the Awaitilty class in order to be more consistent with the other default methods.
2. I've renamed method "handleIntermediaryResultsWith" to "intermediaryResultHandler". I think this reads better, for example with(). intermediaryResultHandler(..) instead of with(). handleIntermediaryResultsWith(..).
3. I've replaced "Long" as the type for the "remainingTimeMs" attribute with primitive long in IntermediaryResultHandler. This is so so that you don't require an if statement to avoid NPE for every instance of IntermediaryResultHandler. Instead I pass in Long.MAX_VALUE if duration is set to INFINITE. If we would support Java 8 only then using Optional would probably be a best approach.

What do you think about these changes? Are you ok with that?

I've pushed the changes as a new snapshot release. Try it out by depending on version 1.6.1-SNAPSHOT after having added the following repo:

<repositories>

        <repository>

            <id>sonatype</id>

            <url>https://oss.sonatype.org/content/repositories/snapshots/</url>

            <snapshots />

        </repository>

</repositories>

I'm also wondering if the result handler really should be just an "intermediary". Perhaps the final result should be included as well when the test finally pass? I suspect that this could be of interest for some people. What are your thoughts on this?

Thanks a lot for your contributions so far!

Regards,

/Johan

[Maciej Gawinecki]

Hi,

Thanks for merging!

Agreed with 1, 2 and 3. Optional would be definitely semantically more clear. I may add Java 8 version with Optional, but I would like first to wait to see whether IntermediaryResultHandler is helpful to anyone else. 

Regarding including the final result when the test finally pass. Yes, I think that could useful for the user to see the test passed "after %d seconds of waiting". I could think of two handling methods: handleMismatch() and handleFinalMatch(). Will try to implement that in the coming week.

I have also run my home project with the snapshot you've provided. In my home project I have matchers operating on objects more complex than just integers so I got quite ambiguous information about actual value

   tdp.example.shop.matcher.util.OrderStateSupplier expected Order has been processed but was <tdp.example.shop.common.OrderDbEntity@59360c> (elapsed time 1s, remaining time 298s)

because AbstractHamcrestCondition relies on toString() method of lastResult object:

   private String getMessage(Callable<T> supplier, Matcher<? super T> matcher) {

        return String.format("%s expected %s but was <%s>", getCallableDescription(supplier), HamcrestToStringFilter.filter(matcher), lastResult);

    }

I haven't implemented toString() for lastResult, but I implemented matcher.describeMismatch() method. Why don't use it in message reporting?

Often a matcher checks only one of the fields of the actual object (state of OrderDbEntity in my case), so printing the whole actual object (lastResult here) may make no sense. And actually only the matcher knows what it checks. But maybe there are scenarios whether toString() method is more commonly implemented than describeMismatch().... What are your thoughts on that?

Regards,

Maciej

[Johan Haleby]

Hi, 

I've changed the interface of IntermediaryResultHandler to also include the actual Hamcrest matcher used and the value itself. This allows for more functionality and also the ability to construct other messages than the default one. I've also included a default implementation com.jayway.awaitility.resulthandler.LoggingIntermediaryResultHandler that prints the results to the console. The match message has also been changed slightly. Please try it out!

Regarding the mismatch value that I thought that I liked at first I'm not quite sure anymore :) Take for example AwaitilityTest#awaitWithAliasDisplaysAliasWhenConditionTimeoutExceptionAndConditionIsCallTo. Before the error message looked like this:

"Condition with alias 'test' didn't complete within 120 milliseconds because com.jayway.awaitility.classes.FakeRepositoryImpl.getValue() expected a value greater than <0> but was <0>."

but with your change it would look like this:

"Condition with alias 'test' didn't complete within 120 milliseconds because com.jayway.awaitility.classes.FakeRepositoryImpl.getValue() expected a value greater than <0> but <0> was equal to <0>."

To me the latter one is more confusing than first one.

Regards,

/Johan

[Maciej Gawinecki]

Hi,

I was quite busy. Sorry for a late response.

I agree making it more configurable make it useful in a wider set of cases. 

I also like your new solution to treat it as a listener. Nice.

One thing I found confusing is what EvaluatedCondition.getDescription() returns. One it is match message, another time it is mismatch message. Very first idea to improve that is to say that explicitly in documentation. Something like

 "a match message or mismatch message from a matcher, depending on what isSatisfied() method returns".

Regards,

Maciej

1) Move the field out of the condition class and pass it a sesson 

Descriptive message of the Hamcrest matcher.

[Dzianis Shkindzerau]

Hi,

I have the same problem. 

I made my matcher and get the following error description when test was failed:

com.epam.e3s.it.common.matchers.ImportLogMatchersTest.verifyMessageForCountSuccessDocMatcher_2 Callable expected Count success docs for "ImportLogEntity" equal to <5>. but was a <4> (elapsed time 1 seconds, remaining time 4 seconds)

com.jayway.awaitility.core.ConditionTimeoutException: com.epam.e3s.it.common.matchers.ImportLogMatchersTest.verifyMessageForCountSuccessDocMatcher Callable expected Count success docs for "ImportLogEntity" equal to <5>. but was <com.epam.e3s.core.importing.log.ImportLogEntity@7e377d5> within 5 seconds.

at com.jayway.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:93)

I expected to see it: 

...but was a <4>

But I sow:

...but was <com.epam.e3s.core.importing.log.ImportLogEntity@7a792ec3> within 5 seconds.

Maybe it makes sense to return the message via getMismatchMessage(supplier, matcher) by default? 

        conditionAwaiter = new ConditionAwaiter(callable, settings) {

            @Override

            protected String getTimeoutMessage() {

                // Use "return getMismatchMessage(supplier, matcher);" to more descriptive message

                return String.format("%s expected %s but was <%s>", getCallableDescription(supplier), HamcrestToStringFilter.filter(matcher), lastResult);

            }

        };

Or how I can return more descriptive message?

Regards,

Den

[Maciej Gawinecki]

Hi Dzianis,

Apologies for a late reply. The reason for not using
getMismatchDescription() in timeout messages as defualt was that it
sometimes resulted in confusing messages like:

"Condition with alias 'test' didn't complete within 120 milliseconds
because com.jayway.awaitility.classes.FakeRepositoryImpl.getValue()
expected a value greater than <0> but <0> was equal to <0>."

Another way would be to generate more descriptive messages yourself.
ConditionEvaluationListener provides instance of EvaluatedCondition,
that gives you access to the currentConditionValue, matcher and
matcher's methods like mismatchDescription() and description().
Unfortunately, it doesn't give you a way to override final timeout
message, only intermediary ones.

Hmm, a longrn soltion would be to collect a small but representative
sample of different matchers and find some win-win solution for
timeout messages for all of them. If you could provide a sample of
such tests in pull request, that would be a good starting point to
improve the situation,

Regards,
Maciej