Misleading exception message in corner cases

[Ádám Zovits]

Hi!

I have discovered an explanation for a problem that has been haunting us for a few months, although very unregularly.

The problem consisted of failed Awaitility (3.0.0) checks with such messages: 

org.awaitility.core.ConditionTimeoutException: our.company.and.packages.SUT.getSignals() expected <[41]> but was <[41]> within 5 seconds.

The expected and actual values are both of HashSet<Integer> type, so the usual suspects (rounding, different instances with the same "face value", bugs in the equals() methods being used) were quickly eliminated.

Upon analyzing the timing in the following log lines the cause seems to be clear:

05:26:38.941 [INFO] [main] SipViaIPVA->testcase - checkLimipSignalsAtWorkspace[1] :: Speaker[1] = [[41]]

05:26:39.051 [INFO] [awaitility-thread] our.company.and.packages.SUT - checking if signaling speaker is in state 'RECEIVING'

05:26:39.181 [INFO] [awaitility-thread] our.company.and.packages.SUT - getting signals of speaker at index [1]

...snip...

05:26:43.966 [INFO] [awaitility-thread] our.company.and.packages.SUT - getting signals of speaker at index [1]

05:26:43.978 [INFO] [awaitility-thread] our.company.and.packages.SUT - signals are [[]]

05:26:44.078 [INFO] [awaitility-thread] our.company.and.packages.SUT - getting signals of speaker at index [1]

05:26:44.093 [INFO] [awaitility-thread] our.company.and.packages.SUT - signals are [[41]]

05:26:44.094 [ERROR] [main] our.company.and.packages.TestCaseListener - FAILURE - TAF.TESTCASE - our.company.and.packages.TestClass.testcase

org.awaitility.core.ConditionTimeoutException: our.company.and.packages.SUT.getSignals() expected <[41]> but was <[41]> within 5 seconds.

It looks like the Awaitility check starts at 39.051, then during all checks except the last the expected signal is not there. But during the last check at 44.093 (5 seconds and 42 milliseconds later) the signal arrives, thereby updating the lastResult variable in the ConditionAwaiter class, but then the evaluationDuration is calculated and so succeededBeforeTimeout is set to be false.

All this results in a ConditionTimeoutException which may or may not be correct since it is impossible to determine when the signal really arrived between the last two checks, but then the given error message is really misleading.

Is this behaviour intended or could it be improved upon?

Thanks,

Adam

[Johan Haleby]

What does your test look like? Are you saying something like await().atMost(5, SECONDS)? If so then isn't it correct?

--
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+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ádám Zovits]

Yes, the call looks like this: await().atMost(5, SECONDS).untilCall(to(SUT).getSignals(), is(equalTo(expectedSignals)));

I'm not debating whether the failure is correct or not, just saying that the error message presented in this rare case (last check still inside the time window is unsuccessful but the first one after the timeout is successful) is misleading since it says the expected and received values are the same, while the important part is the timeout itself.

After looking at the relevant code part in Awaitility, I as a developer can see why it works the way it does, but I can also see why a tester would be confounded by the "Expected X but was X" error message.

My suggestion would be to change the while loop in the ConditonAwaiter, so that if the check of the evaluationDuration results in a timeout then the error message should be composed based on the previous execution of the condition. This way the error message would contain the result of the last check that was still performed during the specified wait time and not a result that came after the timeout was already encountered.

To unsubscribe from this group and stop receiving emails from it, send an email to awaitility+...@googlegroups.com.

[Johan Haleby]

On Fri, Mar 2, 2018 at 11:26 AM, Ádám Zovits <zov...@gmail.com> wrote:

Yes, the call looks like this: await().atMost(5, SECONDS).untilCall(to(SUT).getSignals(), is(equalTo(expectedSignals)));

I'm not debating whether the failure is correct or not, just saying that the error message presented in this rare case (last check still inside the time window is unsuccessful but the first one after the timeout is successful) is misleading since it says the expected and received values are the same, while the important part is the timeout itself.

After looking at the relevant code part in Awaitility, I as a developer can see why it works the way it does, but I can also see why a tester would be confounded by the "Expected X but was X" error message.

My suggestion would be to change the while loop in the ConditonAwaiter, so that if the check of the evaluationDuration results in a timeout then the error message should be composed based on the previous execution of the condition. This way the error message would contain the result of the last check that was still performed during the specified wait time and not a result that came after the timeout was already encountered.

I agree! Could you please add this as an issue?
 

To unsubscribe from this group and stop receiving emails from it, send an email to awaitility+unsubscribe@googlegroups.com.

[Ádám Zovits]

I see you have already seen it, but for future reference: https://github.com/awaitility/awaitility/issues/109

Thank you!