tests(*): match_error_log block and match_error_log_grep modifier

[hishamhm]

Many of our tests are too lenient on checking the ordering and number of occurrences of expected log messages. grep_error_log_out makes it possible to avoid the problems of error_log_out, but it is tricky to get it right.

For example, this entry is still too lenient, because the .* entries between lines can consume additional lines and miss unordered repeats.

Getting more robust entries using grep_error_log_out is possible, at the cost of readability — but even this example is still not enough (spot the use of .*?)... This comes closer ...but are we sure it's right?

This PR introduces a new block handler, match_error_log, where you give it an array of plain substrings (not regexes), and the test passes if and only if all occurrences of the given substrings in the error log match the given list in the exact order, including repeats.

This makes it easy to write more solid tests:

• unexpected repeats are caught
• entries out of order are caught
• regex mistakes due to special characters are avoided

The subset of relevant lines to be checked can be filtered by a regex using match_error_log_grep. If not given, the entire error.log is checked. Filtering makes it easier to test for things like ["[info]", "my message", "[info]", "another message"] (ensuring there are no other [info] entries in between), but then the usual concerns about crafting careful regexes in match_error_log_grep to avoid undesired lines applies.

This PR includes the implementation commit, intended to be cherry-picked, and an example commit showcasing the use with and without the filtering.

[hishamhm]

@thibaultcha I wrote this on top of feat/ffi-properties-code-review but that shouldn't matter — it was just so I could showcase the block using tests from that PR. The relevant commits are the last two.

[thibaultcha]

A note on --- grep_error_log with [^#*]* and co: These can easily be avoided if the extracting regex does not match .* at the end. Most likely, many of these regexes could be changed to capture lines in some other way, perhaps until the Nginx-injected comma , or something else.

Will --- match_error_log also catch extraneous matching lines before or after the test substrings and not just in-between? For example, I consider --- grep_error_log the most thorough testing method when used with a good extraction regex and a delimited matching regex with \A ... \Z limits. See for example recent connection drop tests in which this pattern caught false-positive test cases with other similar lines that were initially left-out by grep_error_log_out. I have seen many unexpected lines show before and after the matching --- grep_error_log_out regex recently, and wanted to bring this up eventually. So, unless --- match_error_log with --- match_error_log_grep can also do this, --- grep_error_log might still have an important edge for critical or existing test cases.

[hishamhm]

These can easily be avoided if the extracting regex does not match .* at the end.

A bunch of the regexes in tests have .* in the middle though ([info] .* something something) and grep_error_log will happily match that across two different log lines. We'd need to change every .* to something like [^\n]*, etc. Gets annoying and error-prone fast.

Will --- match_error_log also catch extraneous matching lines before or after the test substrings and not just in-between?

Yes. It checks before, after and in-between. If you put 4 items in the substring list, the whole match (or the whole file if not using match_error_log_grep) must contain exactly 4 occurrences of those substrings, in the given order.

[thibaultcha]

After playing with it a little, I am not convinced by --- match_error_log and still think grep_error_log is superior in most if not all cases.

A bunch of the regexes in tests have . in the middle though ([info] . something something) and grep_error_log will happily match that across two different log lines. We'd need to change every . to something like [^\n], etc. Gets annoying and error-prone fast.

Right; my point is that we don't really care about checking for [info] (but if we do we can still craft the proper regexes for it), and should write grep_error_log_out regexes without checking for the log level, and without catch-all checks.

I updated --- match_error_log to accept a plain string (or \n-separated array).

Firstly, I find that the failure case is more difficult to debug than --- grep_error_log_out which will print the full string and a diff with the subject, while match_error_log wants me to count n lines and find the difference by myself (excess occurrence of 18th substring "wasmx.empty_dyn_property: string """ was found in error.log:301).

Secondly, I remove a line in the middle of match_error_log:

diff --git a/t/04-openresty/ffi/304-proxy_wasm_set_property_getter.t b/t/04-openresty/ffi/304-proxy_wasm
_set_property_getter.t
index 65f04b0a..ae99dd11 100644
--- a/t/04-openresty/ffi/304-proxy_wasm_set_property_getter.t
+++ b/t/04-openresty/ffi/304-proxy_wasm_set_property_getter.t
@@ -517,8 +517,8 @@ ok
     }
 --- response_body
 ok
---- grep_error_log eval: qr/(getting\s)?wasmx\.\S+property.*?(?=while)/
---- grep_error_log_out
+--- match_error_log_grep eval: qr/(getting\s)?wasmx\.\S+property.*?(?=while)/
+--- match_error_log
 getting wasmx.const_property counter: 1
 wasmx.const_property: string "1"
 getting wasmx.dyn_property counter: 2
@@ -530,7 +530,6 @@ getting wasmx.nil_const_property counter: 4
 wasmx.nil_const_property: nil "nil"
 getting wasmx.nil_dyn_property counter: 5
 wasmx.nil_dyn_property: nil "nil"
-wasmx.nil_const_property: nil "nil"
 getting wasmx.nil_dyn_property counter: 6
 wasmx.nil_dyn_property: nil "nil"
 getting wasmx.empty_const_property counter: 7

And the test still passes, as a false-positive that grep_error_log would have caught.

Given match_error_log also needs a filter regex to perform two thirds of what grep_error_log already does, I am not convinced. So far I think I will update the property getter/setter tests to grep_error_log instead of match, and am not in favor of merging this, rather in favor of improving our existing grep_error_log test cases instead. It is more thorough and more rewarding, perhaps at a slightly higher effort cost, sure, just like all good things in life.

[hishamhm]

@thibaultcha That's thoughtful feedback, thank you!

my point is that we don't really care about checking for [info]

Ah, I wasn't aware — I thought it was a requirement.

Firstly, I find that the failure case is more difficult to debug than --- grep_error_log_out which will print the full string and a diff with the subject

(Pedantic correction: when using regexes, it produces not a diff but the full string and the regex — I've always found these long error dumps hard to read, but...) ...that's a great point. My error output was lazy there (typical mistake of making them correct-but-not-very-readable); in fact I think that with substring matching we can make the error messages better than grep_error_log_out and produce actual visual diffs.

More generally, your examples brought the point home to me about what my main gripe with grep_error_log really is: it does one big multi-line regex in grep_error_log_out (bad), even though it does per-line filtering in grep_error_log (good). That is the single thing that makes it difficult to write correct regexes with it.

Your example about removing the line also suggests that, when a grep-filter is applied to match_error_log, a more interesting behavior (perhaps even the expected one) is that all filter-matched lines should contain at least one matched substring. That would require grep filters to not be too wide, but since we're using extended-regexps with |-alternatives, it's easy to combine multiple simple specific ones.

Requiring one match per filtered line would not only cover the scenario you mentioned but make the "hardened" test matching the default behavior if the test author does nothing special and just writes a basic grep regex and a plain substring.

perhaps at a slightly higher effort cost, sure, just like all good things in life.

Not everyone is a mountain climber, though, so our notions of effort are calibrated at different levels. :)

Joke aside, I'll still disagree about the effort cost given that, looking at the current state of the main branch, I don't think none of us have been able to write a single bullet-proof regex using grep_error_log in the existing test cases; both my and your examples of hardening them all have some fault or another that I could identify. Of course it's not impossible to do it, but you know me: I'm always one for improving the tooling to make the more obvious path the correct one rather than painstakingly improving everyone's "crafting" by trial and error — even if that requires me to *gasp*, write some Perl. :)

I still think we will find grep_error_log to be useful in specific scenarios, but I think it's also worth building the cable-car that takes us effortlessly to the top of the mountain. :)

Fine by me if we continue moving the property setters/getters forward with grep_error_log, but I'll still give this PR another spin to address the points above.

[thibaultcha]

I don't think that it is worth spending time on --- match_error_log; the getter/setter PR will have simple and reliable perfect grep matching and that is the pattern we should follow going forward. If we make filtering mandatory then it's kind of the same thing as --- grep_error_log, except less powerful. That said, there are many, many things with getter/setter that I don't think are fully finished either, so also working on that...

[hishamhm]

I've pushed an updated version of the block in this PR. I think it addresses all issues you raised and provides (IMO) better diagnostics than grep_error_log. Filtering with match_error_log_grep is now mandatory, in order to produce sensible error messages. That's as far as I intend to take this, so it's up to you if you think it's worth picking it up.

That said, there are many, many things with getter/setter that I don't think are fully finished either, so also working on that...

Let me know if there's any way I can help. You asked me to stop pushing on that branch so I did not make any further changes, but you did get my comment with the diff with the set_r fix, right? Did that stop the crashes on your end?

[thibaultcha]

Oh yes, the set_r fix is good no worries there!

Since I am not sure I will be done today I'll list the main things that were holding this for me:

• At first I went through test cases to use --- grep_error_log, and doing so, found double-logging errors in the return nil, err tests: an error in Lua and another in the filter hostcall. I now moved the return nil, err message into a wasm trap when in hostcalls: we want a stacktrace and we want to avoid double-errors in the logs when possible, so this design results in much more concise/actionable error logs.
• In tests, I added many more scenarios I found necessary (this is when the set_r fix came in handy), and asserted the yielding behavior too.
• While updating tests, I have also found that getter tests were going through the wasm filter loop (t/get_property), while the setter tests were mostly going through the FFI API (proxy_wasm.set_property()). For now I am also working on fixing this disparity in the testing symmetry (existing tests assumed both execute the same underlying code), and ensuring errors from the wasm filters throw a trap (and backtrace), while errors from the FFI API are returned as a string in the nil, error signature.

I will push a merge PR with the updates before merging anything.

[thibaultcha]

Still looking at it; I think it does fix my above concerns on the subject matching. It feels a little easier to use than --- grep for tests with a small number of lines in the subject, but very noisy and way harder to read than the no_long_string diff output for tests with a lot of lines. But if you think you can make good use of it, I think it's fine to have and also a good template to have to further extend Test::Nginx if needed again.

[thibaultcha]

Although one more thing: unless I am mistaken, now that --- match_error_log_grep is mandatory the main difference it has with --- grep_error_log is the way it treats the subject patterns (as plain substrings). Otherwise it works the same way: 1) extracts a pattern (the --- grep), test the pattern (the --- grep_out). May I suggest we rename --- match_error_log to something that better reflects its main difference from --- grep_error_log? Maybe --- fgrep_error_log, --- fgrep_error_log_out (fgrep like grep -F)? Or something more verbose, I don't mind, like --- plain_grep_error_log or --- grep_error_log_plain. Bust mostly keeping the same terminology: --- block, --- block_out?

[hishamhm]

I think that if we don't need to match multiple substrings within the same line (e.g. [info] and relevant text), then the benefit of match_error_log becomes truly marginal. I was basically operating under a different set of assumptions.

Adopting plaintext mode of grep_error_log_out whenever possible addresses my main concern about having big multiline regexes everywhere. I agree that the diff output in plaintext grep_error_log_out is nicer, too. The only other thing still going for match_error_log then, besides the support for multiple matches per line, would be that the filtering regex is easier to write (because you can match the whole line and then it does substring search), but that doesn't make it worth it, IMO.

If we needed multiple substrings matched in order per line, this would've been a big boost for test readability/reliability. But given our actual requirements, I'm happy to close down this one and follow the patterns from your latest tests!