ISSUE-185: Output most detailed error messages for each version tested

[ottobackwards]

When zkq was running tests for each version, if a version failed, it was printing an error without context of the test dir and clone dir, and continuing.

It looks however that the code was meant to not continue after that first error check, but after the subsequent error, that sets all passed and prints the more detailed message.

I have changed the behavior to not continue at the first check, and added
the version under test to the more detailed message.

[ottobackwards]

@ckreibich I resolved the merge conflicts, is there something we are waiting on me to do?

[bbannier]

I resolved the merge conflicts, is there something we are waiting on me to do?

AFAICT this patch only adds version numbers to log lines and does not address #185 at all. To address that issue I would have expected something showing (a possibly abbreviated version of) the test output, e.g., here

package-manager/zeekpkg/manager.py

Lines 2684 to 2689 in bdc15fa

	if rc != 0:
	return (
	f"test_command failed with exit code {rc}",
	False,
	stage.state_dir,
	)

I am not sure this patch is that useful as is.

[ottobackwards]

@bbannier I think this helps, after last commit.

[ckreibich]

Thanks @ottobackwards. I just played with this a bit and it's headed in the right direction. A few things:

1. We can be more specific about those files — currently, they are always going to be exactly at <zkgdir>/testing/<package>/clones/<package>/zkg.test_command.{stdout,stderr}. It would be better to point the user specifically at them, since the most likely step is for the user to cut'n'paste that filename directly into the shell or an editor.
2. But! I noticed there's a nascent feature in zkg of supporting a directory of logs. This is currently only used for build logs — the build log for a given package ends up in <zkgdir>/logs/<package>-build.log. I think this is clearly superior, and inconsistent with the approach to test logs. We should align these — it's much easier to remember <zkgdir>/logs/<package>-test.{stdout,stderr}.log. The code change would be minor since the process invocations already work the same, and it's also nicer that zkg doesn't pollute the clone.
3. I think we should add a command line option --show-logs at the toplevel. It would apply to any command that invokes stuff and captures output in logs. It could support always (the default) and error as optional arguments, to indicate whether such logs should show automatically at all times, or only when the corresponding command failed. This would be handy in CI, for example.
4. This leaves one challenge: the test logs don't necessarily let you dig into the details of the tests — for example, in the case of btest the logs will report the test results, but you sometimes need to check the raw test files in .tmp to figure things out. I could see us adding a log message at INFO level (one -v) to make that clear — it's currently visible but a bit buried at the DEBUG level (-vv). We could also prefix the logs with a comment that indicates these.
5. You added this for the test command, but that's partial. This also affects install and upgrade.

I apologize for dumping all this on you at this stage, not in #185 itself — I hadn't looked over the code in sufficient detail at that point. If you don't have cycles for the above, just let us know and we'll take it from here. If you want to make this a minimally useful PR that we can merge, I'd say implement points 1 and 5, and we can then iterate on it in a subsequent PR.

(Btw — the paths are so complicated because testing can theoretically involve pulling in a bunch of dependencies at specific versions, and all of that needs to go somewhere. Hence the <package>/clones/<package> structure.)

[ottobackwards]

@ckreibich thanks for the feedback:
re:

1. understood
2. so you are saying that a goal should be to have as many things as possible log to zig_dir/logs the way the build logs do? And that way the clone is cleaner. My question would be how would this be named when there are multiple versions being tested etc? pkgname-version/package-build.log?
3. --show-logs is interesting for ci, but I think some kind of --show-results that outputs json with the complete output and status of all the "commands" and is consumable by ci or build scripts is an interesting idea
4. This seems to me, though not an sme, like something that could go in the zkg metadata. maybe you could say what logs you produce, or some pattern for for those logs for build/test, and or maybe when zkg builds something, it can define some env variable or ??? and things that support zkgmeta building / testing with zkg can just read that and output all the stuff to the log dir anyways. That may change the thinking across this though.
5. Yeah, there is a pattern used and duplicated for the three spots in the code that can be de-duped for sure

[ckreibich]

so you are saying that a goal should be to have as many things as possible log to zig_dir/logs the way the build logs do And that way the clone is cleaner.

I do think it's cleaner, yeah. Regarding "as many as possible" — for now the two natural applications are build logs and test logs. We could also consider zkg's operation itself, though that's for sure a separate issue.

My question would be how would this be named when there are multiple versions being tested etc? pkgname-version/package-build.log?

Ah, good question. I don't think this matters? The common pattern for build and test logs is that you try to install package, and if it bombs, you check the logs. You can't install multiple versions in parallel anyway, and one also cannot currently keep multiple test artifacts in parallel (at least when using btest).

Do you have a use-case that would require multiple-version logs to remain available?

This seems to me, though not an sme, like something that could go in the zkg metadata.

I didn't word that point well. I think zkg can do better at reporting where it invokes the test_command, because that's currently a bit buried, and it's always up to zkg to do this, not metadata. Currently when you say -vv and you install a package with test cases, you'll eventually see something like this:

2024-05-21 14:36:00 DEBUG    running test_command for hello-world with cwd="/home/christian/.zkg/testing/hello-world/clones/hello-world", PATH="/home/christian/.zkg/testing/hello-world/bin:/home/christian/inst/opt/zeek/bin:/home/christian/inst/opt/override/bin:/usr/lib64/qt-3.3/bin:/usr/share/Modules/bin:/usr/lib64/ccache:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/christian/inst/bin:/home/christian/devel/scripts:/home/christian/inst/opt/suricata/bin:/home/christian/inst/opt/processing:/home/christian/inst/opt/ruby-gems/bin:/home/christian/inst/opt/spicy/bin", and ZEEKPATH="/home/christian/.zkg/testing/hello-world/scripts:.:/home/christian/inst/opt/zeek/share/zeek:/home/christian/inst/opt/zeek/share/zeek/policy:/home/christian/inst/opt/zeek/share/zeek/site:/home/christian/inst/opt/zeek/share/zeek/builtin-plugins": cd testing && btest -c btest.cfg

I'm saying it would help to make that first part more accessible. A preamble in the resulting logs could simply indicate in which directory zkg invoked the commands — then there's no need to tinker with output verbosity.

Does that make sense? Let me know how you'd like to proceed with your PR.

[ottobackwards]

RE: multiple versions
I was going by the code in test which is looping through names and versions. I didn't see where would make it so they were all unique and keep you from building / testing the same package with different versions

RE: metadata
What I am saying is that you could put in the metadata patterns for your log files for test and build etc and then zkg can just get the logs from those

RE: other
Another idea would be to set the log target directory in the env or pass it to the build and have the build just log there automatically