Assertj-core: Implement an event handling mechanism

[martinschneider]

Summary

There should be an option to add a hook to the check of an assertion and execute custom code.

Use-case:
I want to log the result and description of an assertion every time it is checked (and not just when it fails). The descriptive nature of AssertJ tests would be an ideal base to create a test protocol. Right now, this information is not used to its fullest potential.

Example

assertThat(frodo.getAge()).as("check %s's age", frodo.getName()).isEqualTo(33);
assertThat(frodo.getAge()).as("check %s's age", bilbo.getName()).isEqualTo(-1);

From the above checks, I would like to create a log output which reads like this:

check frodo's age passed
check bilbo's age failed

I suggest implementing some sort of event handling. For example, an event handler could register to an assertionChecked event and process the result and details. IMO, this would be a powerful addition to AssertJ.

[abogdanov37]

In my case I want to integrate AssertJ with Vert.x tests.
To do this I need a handler in which I process AssertError and fail Vert.x context

[joel-costigliola]

@abogdanov37 is that the same feature ? can you give an example ? have you tried using soft assertions ?

[rnorth]

I'd be very much in favour of this. I have a (less sophisticated) assertion library that I use on a few projects but frankly would like to retire in deference to assertj.

I'm sure some people will take an opposite view, but I find logging of assertions to be just a _nice thing_, particularly in longer running integration tests, etc.

@joel-costigliola, would you be willing to look at a contribution for this? Would you have any specific guidelines on how you'd like it to be implemented?

[manolkalinov]

I'd be willing to help on this, if such a need arises.

In my opinion, especially for UI automation, logging assertion results is a must - PASS or FAIL.

Maybe something along the lines of
assertThat(frodo.getAge()) .logAs("check %s's age", frodo.getName()) .isEqualTo(33)

I'm not, however, sure how the logging provider can be setup, since most assertion usages are static.

[joel-costigliola]

@rnorth @manolkalinov sorry for the late reply. Yes I see the value of logging what assertions were performed.

I think this issue needs a spike to explore the different implementation options.

One option to try is to use the AssertionInfo that contains the assertion description users provide with the as() method. When an assertion fails, an AssertionError is created using AssertionInfo in the Failures.failure method(s), that would be a good place to publish the event indicating a failure.
The challenge here is that there is no way of knowing that an assertion succeeded, the absence of failure indicates a success, said otherwise there is no hook for when an assertion succeeds.
One obvious way would to publish an event in each assertion method but that's too much work.
Thinking out loud, whenever AssertionInfo has a non empty description we could register a success event in advance and replace it by a failure one if it turned out the assertion failed. To do so would require to wait at the end of the test to publish the registered events. This can be done automatically using JUnit hooks but not with AssertJ itself as it is not aware of the tests lifecycle.

Another option would be to use proxy mechanism (similar to soft assertions) but this need to be technically demonstrated and will certainly have complications if combined to soft assertions.

[ebundy]

Hello all,

A contradictory view here.

Is someone could present or even better detail a real and clear use case where adding logs for successful AssertJ assertions could be useful ?

For example why I would log hundred or thousands of individual assertions (which some could be redundant besides) :

check frodo's age passed
check bilbo's age failed

I'm sure some people will take an opposite view, but I find logging of assertions to be just a nice
thing, particularly in longer running integration tests, etc.

I am not sure to see the value to log both successful and failed assertions.
Logging the failed assertions (with a custom message or not) makes sense because it allows to give useful information to fix these.
But why would I log successful assertions ?
In real and big projects, I have hundreds or thousands of these.
I don't see why and how to exploit it manually these logs and I don't see why and how to exploit in a automatic way neither. Besides, that kind of feature could slow down the application builds.

In my opinion, especially for UI automation, logging assertion results is a must - PASS or FAIL.
For UI tests,

Why do you need to log everything?
To have a description of the UI steps with their status (failure or success) in an explicit form I use Cucumber for the layout/runner/pretty form that I combine with JUnit/AssertJ .

[abogdanov37]

@joel-costigliola sorry for long response. I found solution in Vert.x. It has function context.verify(lambda)
java-doc. But in my opinion AssertJ should have a handler to get verification exception.
String format case example assertThat(frodo.getAge()).isEqualTo(33).exceptionally(t -> { System.out.println(t.getMessage())});
My case example assertThat(frodo.getAge()).isEqualTo(33).exceptionally(t -> { throw new MyCustomException(t)});
And many other processing

[manolkalinov]

Hey, @ebundy,

My goal is to have the option to either turn on PASS logging for select verifications, or at least get the result of the Verification back from AssertJ for logging purposes so that I do not have to assume the PASS result. My issue with assuming the PASS is that I am, in a way, subverting the Verification Authority (AssertJ), instead of getting the result directly from it.

I am not sure to see the value to log both successful and failed assertions.
Logging the failed assertions (with a custom message or not) makes sense because it allows to give useful information to fix these.
But why would I log successful assertions ?

Two reasons:

1. Just having an error such as "Button is Disabled, but should be Enabled" in a 10-step, 30-actions test is not enough to root-cause an issue, especially when you have hundreds of tests going through complex scenarios. You need to have the context of the previous steps, actions and verifications. If we have logging for everything except passed verifications (with the values), it seems we have missing context.

2. Usually, code verifications have a 1:1 relationship to a Verification in a test management platform (HP Quality Center, PractiTest, etc), which needs to be updated at the end of a run. Currently, I have to implicitly infer the PASS result and log it myself along with the parameters. You mentioned Cucumber. I am not using it, so my other option is to either manually log or use something like AspectJ to log around the assertions. In all cases, I have to assume the PASS result and introduce complexity around the verification code. Like this:

final String expectedButtonState = "disabled";
final String actualButtonState = getButtonState();
Assertions.assertThat(actualButtonState ).isEqualTo(expectedButtonState);
log.debug(String.format("I'm assuming the button is enabled, so I'm logging it as PASSED with actual data: '%s'", actualButtonState );

Here's a more coherent example. Let's say we have the following general test structure, where Test, Step, Action and Verification are followed by a short description, e.g. Action - "Click on the Next button":

Test ID(4815162342)
    Step 1
        Action 1
        Action 2
        Verification 1 (button is enabled)
        Action 3
        Verification 2 (value 1 is between 2 and 25)
        Verification 3 (value 2 is between 0 and 100)
    Step 2
        Action 1
        Action 2
        Verification 1 (item count is 5)
        Action 3
        Verification 2 (price is 550)
        Verification 3 (status is green)
        Verification 4 (text message is "Successful something or other")
        Action  
        Verification (text message is "Successful something or other")

What I'd like to have in the log file is this (regardless if AssertJ logs it for me, or it gives me a Y/N and I log it myself:

Test ID(4815162342)
    Step 1
        Action 1
        Action 2
        Verification 1 (button is enabled) PASS (enabled)
        Action 3
        Verification 2 (value is between 2 and 25) PASS (2)
        Verification 3 (value 2 is between 0 and 100) PASS (0)
    Step 2
        Action 1
        Action 2
        Verification 1 (item count is 5) PASS (5)
        Action 3
        Verification 2 (price is 550) FAIL (544)
        Verification 3 (status is green) PASS (green)
        Action 3
        Verification 4 (text message is "Successful something or other") PASS

Here I am assuming Soft Assertions were used. Hence the PASS after the FAIL.

This kind of logging can be used for:

1. Results Triage - is the Fail caused by Automation Error or is it a Product Bug?
2. Error root-causing - Maybe the "2" in Step 1 > Verification 2, and the "0" in Step 1 > Verification 3 combined caused the error in Step 2 > Verification 2. Yes, it does mean a wrong test, but such corner cases sometimes come up from automation. In order to reach a solution, you'd need all the context.

Footnote: This is my personal opinion, based on professional experience. I am open to discussions, suggestions, corrections, etc, in the name of improvement.

[ebundy]

Hi @manolkalinov

Thanks for this detailed use case. I appreciate.

About :

Results Triage - is the Fail caused by Automation Error or is it a Product Bug?
Error root-causing - Maybe the "2" in Step 1 > Verification 2, and the "0" in Step 1 > Verification 3 >combined caused the error in Step 2 > Verification 2. Yes, it does mean a wrong test, but such corner cases sometimes come up from automation. In order to reach a solution, you'd need all the context.

I understand your approach that is legit : making integration tests failure diagnostic more efficient/easy.
I am afraid that logging from the unit tests be not enough.
Having the assertions results may help to diagnostic but it may also give false positives.
I will reuse your example.
Suppose that the problem came from the step 1 - action 2 (or any action) that changes the state in a DB in an undesirable way and as a consequence makes the step 3 - verification 3 fails.
Trying to search the error cause in the assertions that accept a range of value will not help in this case and in many of others I assume.
For integration tests, there are often a lot of possibilities that may be at the origin of the failure : any side effects caused by any function previously called.
AssertJ will log only what you ask to log, not what your implementation does and the problem is often there.
To solve the issue : digging into the implementation of previous called functions is very often the way and to ease the task, having the possibility to enable exhaustive user event logs is often interesting.

So IHMO, for cases where integration tests/user scenario are very long, complex and hard to debug,
I would setup an on-demand user event logging with a verbose option that logs user actions but also performed side effects on the system to miss nothing.
The other advantage of this approach is that you can enable the user event logging for other needs such as :

• replay production issues on an integration environment by playing the scenario with the logs enabled
• understand an implementation issue in a current development

At last I am a very big fan of AssertJ but coupling the diagnostic traces to an assertion library may become a problem if tomorrow you need to use another assertion library for different reasons.

[joel-costigliola]

We have added support for consuming description (see https://assertj.github.io/doc/#assertj-core-assertion-description-consumer), is that addressing (at least partially) the issue?

[martinschneider]

This looks very promising, thanks for implementing it! I'm already trying it out.