Support for tracing query execution logs, added /trace endpoint

Currently there is a policy.QTRACE to print out messages relevant to matching policy filter. This is nice for tracing specific names in the background, but not very useful for ad-hoc troubleshooting.

This MR adds support for per-request tracing of query execution, so it's possible to install a callback function to the request structure, and it will get called for each log message (regardless of whether verbose logging to stdout is enabled or not). This by itself isn't super helpful in C modules. It also changes the way how verbose logging was done before, from:

WITH_VERBOSE {
    VERBOSE_MSG(qry, "hello");
}

To:

WITH_VERBOSE(qry) {
    VERBOSE_MSG(qry, "hello");
}

The second part of the MR adds a new endpoint /trace to the HTTP module to trace execution of individual requests. It looks sort of like this:

   $ curl http://localhost:8080/trace/e.root-servers.net
   iter | 'e.root-servers.net.' type 'A' created outbound query, parent id 0
    rc  | => rank: 020, lowest 020, e.root-servers.net. A
    rc  | => satisfied from cache
   iter | <= answer received:
   ;; ->>HEADER<<- opcode: QUERY; status: NOERROR; id: 14771
   ;; Flags: qr aa  QUERY: 1; ANSWER: 0; AUTHORITY: 0; ADDITIONAL: 0

   ;; QUESTION SECTION
   e.root-servers.net.		A

   ;; ANSWER SECTION
   e.root-servers.net. 	3599821	A	192.203.230.10

   iter | <= rcode: NOERROR
   resl | finished: 4, queries: 1, mempool: 81952 B

This is nice for troubleshooting problems with a specific resolver instance, or to generate test files (as it writes out answers received).

I'm planning to add more tracepoints next, more specifically to add a timeline of request processing events (function calls, or layer executions) to show where the time is spent for given request, but this will be more invasive, so it should probably be done in a separate set of patches.

Also added basic tests for this endpoint and the rest in the http module.

Do I understand correctly that all this is to enable 'verbose log for single request'?

In general I can see the value but I need to think about the approach.

Two things I noticed:

• log format returned from /trace HTTP endpoint should be the same as for normal verbose logging - especially the column with IDs should be present othrwise it will be impossible to trace complicated setups
• this functionality should be exposed also outside of HTTP module, it would be super-valuable to have it available form built-in Lua (e.g. resolve(..., ..., ..., bleh.TRACE))

changed the description

changed target branch from code-coverage to master

Yes, it's about logging events for a single request. It's already supported in resolve(), that's how the http module implements it, see https://gitlab.labs.nic.cz/knot/knot-resolver/blob/4832e2130ed273bd746d6f8d4bd5aa1557db982d/modules/http/http_trace.lua#L43

I'll update the log format.

added 22 commits

• 17f98432...9e6666a4 - 14 commits from branch master
• 67d5016e - ci: add luacov and lcov to build image dependencies
• 601f690f - daemon: added callback for resolve() query initialisation
• 2aec949d - daemon: fixed memory leaking from wrk_resolve on some input errors
• c62954ac - lib/resolve: add support for per-request logging
• a9425fd1 - lib/rplan: remember request context in each query
• 87c7bde1 - lib: added support for trace_log for verbose messages
• 43b2157d - modules/http: added /trace endpoint for request log tracing, added tests
• c0d5b1f0 - modules/http: updated format of the /trace log

Compare with previous version

@pspacek Dockerfile needs more dependencies to be able to test modules that are optional, can you rebuild it again?

added 25 commits

• cf14cfa5...9bdfbdd8 - 13 commits from branch master
• 3310b7d7 - daemon: added callback for resolve() query initialisation
• ad049a9c - daemon: fixed memory leaking from wrk_resolve on some input errors
• 38b0108d - lib/resolve: add support for per-request logging
• 003a0f77 - lib/rplan: remember request context in each query
• ad49b870 - lib: added support for trace_log for verbose messages
• b26241c3 - modules/http: added /trace endpoint for request log tracing, added tests
• dc8691dc - modules/http: updated format of the /trace log
• 1f05014d - clean up on module test success, fix priming query failing predict test
• 293f4d37 - ci: added lua-http dependency to build, fixed test for http
• d9f8841f - main: close loop after it's finished to please valgrind
• c4e1b5c6 - kres: added support for NULL type
• 30b4baa3 - modules/http: added selected records to /trace endpoint

Compare with previous version

I like this MR, at least in principle. It will need some re-check (and conflict resolution) with two larger WIPs scheduled to be merged soon (hopefully, for 2.0.0). I'm not sure which merge order to choose; it shouldn't be complicated in any order.

assigned to @vcunat

Okay, I will leave the decision what needs further polishing and what gets merged when on @vcunat . You have my trust in this.

added feature label