Composite conditions: log failling condition

[DemianTinkiel]

I think it would be really useful to log which condition is failing the rule as a whole. For example, lets say I have

URI uri = UriBuilder.fromUri("http://localhost:{PORT}/authzforce-ce/domains").port(port).build();
        whenHttp(server)
                .match(
                        get(f.toString()),
                        parameter("externalId", domain))
                .then(ok());

and fails when I do GET http://localhost:8080/authzforce-ce/domains?externalId=1
but if I have

URI uri = UriBuilder.fromUri("http://localhost:{PORT}/authzforce-ce/domains").port(port).build();
        whenHttp(server)
                .match(
    //                    get(f.toString()),
                        parameter("externalId", domain))
                .then(ok());

it succeeds. Then I'd want to know what part is causing it to fail.

NOTE: this is a hypothetical simple case, I only put it as an example (in reality I get 200 😛) but in more complex cases like POST with multiple conditions it would be useful

[mkotsur]

Hi @DemianTinkiel . Thanks for looking into that. I must say, I suffer from this myself sometimes, especially when the condition is complex. I looked into this something about a year ago, and couldn't find an easy and elegant way of generating a textual representation of conditions. Will look into this again ASAP (hopefully this weekend).

[DemianTinkiel]

I get you @mkotsur. I've been looking into it and I could find a simple solution either. I thought in Stub#isApplicable do some aspect interceptor to log or maybe something like https://stackoverflow.com/questions/50953859/logging-the-conditional-outcome-in-java8-predicate-in-a-concise-manner

Thanks for the effort!

[mkotsur]

Thanks for the link. I think I understand the approach suggested in the SO answer, and kind of imagine how would aspect interceptors do it (don't have that much experience with AOP).

The main problem, though, IMO, is that all predicates are fused together at Condition:264 and when the check is happening there is no chance to know which of them actually didn't work...

A smaller problem: Conditions (or predicates) should be able to hold labels attached to them.

So, I see two options:

1. Use aspects somehow to intercept the moment when actual java.util.function.Predicate is being tested, and somehow find the associated label and output it.
2. Don't merge predicates, keep them as a tree inside the condition and implement test function myself. That will also allow to show if there is more than one failed predicate.

Or am I missing something... 🤔

[mkotsur]

WIP on branch

[DemianTinkiel]

@mkotsur I think I was looking at an older version so I didn't take into account the predicate fusion. I don't have my dev machine available now but i will tomorrow and I'll be able to look at it in more detail then. Perhaps an extension of your 2nd choice would be cleaner than 1st ( at leas for debugging, trust me aop is powerful but hell to debug): extend the Predicate interface with a default implementation that just logs and calls super.test(). This idea is based on just the code reading i'm doing in github on my phone which is bad:P. I might have a better idea tomorrow

[DemianTinkiel]

@mkotsur if you brought back v0.8.2 of Predicates#apply, I think that would be the perfect hook point for the approach in stack overflow

[mkotsur]

Hey @DemianTinkiel! So, I'm at the point, where this code:

        whenHttp(server).match(
                get("/test"),
                withHeader("foo", "bar"),
                parameter("foo", "42")
        ).then(ok(), stringContent("Hello"));
        expect().body(containsString("Hello")).when().get("/test");

would produce this output:

[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer - GET Request to URL: http://localhost:36942/test of type null
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Header [host] with value: [localhost:36942]
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Header [connection] with value: [Keep-Alive]
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Header [accept-encoding] with value: [gzip,deflate]
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Header [accept] with value: [*/*]
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Header [user-agent] with value: [Apache-HttpClient/4.5.3 (Java/12.0.1)]
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  --> Body: 
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer - 
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  ⚠ Reason for not applying stub: Condition `null@1844959558` failed.
[Grizzly-worker(1)] INFO com.xebialabs.restito.server.StubServer -  ⚠ Reason for not applying stub: Condition `parameter==[42]@2126554684` failed.
[Grizzly-worker(1)] WARN com.xebialabs.restito.server.StubServer - Request /test hasn't been covered by any of 1 stubs.

There is still some work to be done: label all out-of-the box conditions, change methods for creating custom conditions so that it's possible to label them easily, review the code and write some more tests.

The approach I've finally decided to take a bit different from suggested on Stack Overflow. I'm a Functional Programming geek, and it would hurt my feelings a lot to add code, which produces output directly into the place, where conditions are being checked. Just doesn't feel right 🤷‍♂️. Instead, what I did (at least the main idea of it) is changed some contracts so that when a condition is validated, not only true/false is returned into the calling function, but also a list of invalidity reasons. Those reasons bubble up this way to the top of the program, where I output them.

My question to you is: what's the best way of outputting the information about conditions that didn't pass? Is it OK how I presented it, or something else would be better?

[DemianTinkiel]

Hey sorry for the delay.
If I was debugging my test I'd like to see something like
Reason for not applying stub: Condition parameter foo==42 failed. Got foo==43

I imagine Reason for not applying stub: Condition null@1844959558 failed refers to the fact that there was no field foo in the header, right?
The logs for request and header are perfect

P.s. 👍 for Functional Programming geekiness 😄