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.

added 7 commits

• 2050b7a4 - 1 commit from branch code-coverage
• 595819b8 - daemon: added callback for resolve() query initialisation
• 6f16cd1e - daemon: fixed memory leaking from wrk_resolve on some input errors
• 3a3fc5b6 - lib/resolve: add support for per-request logging
• bb7ad614 - lib/rplan: remember request context in each query
• 0e1957cb - lib: added support for trace_log for verbose messages
• 0137369b - http: added /trace endpoint for request log tracing, added tests

Compare with previous version

added 1 commit

• 17f98432 - modules/http: added /trace endpoint for request log tracing, added tests

Compare with previous version

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

added 9 commits

• a0bb3a9a - priming: implement priming queries as module
• 571457f1 - priming: enable module by default
• 54bc830e - daemon: added callback for resolve() query initialisation
• 5386edd2 - daemon: fixed memory leaking from wrk_resolve on some input errors
• 67041a3d - lib/resolve: add support for per-request logging
• 7b2157f0 - lib/rplan: remember request context in each query
• 864f27b6 - lib: added support for trace_log for verbose messages
• 0b5808d3 - modules/http: added /trace endpoint for request log tracing, added tests
• f7cb907c - modules/http: updated format of the /trace log

Compare with previous version

added 1 commit

• 34f113aa - clean up on module test success, fix priming query failing predict test

Compare with previous version

added 1 commit

• c626a65e - ci: added lua-http dependency to build, fixed test for http

Compare with previous version

added 2 commits

• 0be3bdb8 - ci: added lua-http dependency to build, fixed test for http
• 4832e213 - main: close loop after it's finished to please valgrind

Compare with previous version

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

added 1 commit

• f7ddaae4 - main: close loop after it's finished to please valgrind

Compare with previous version

added 2 commits

• 38af534d - kres: added support for NULL type
• cf14cfa5 - modules/http: added selected records to /trace endpoint

Compare with previous version

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

@vcunat Ok, after you figure out the order of merges, can you write a checklist of things to fix before it can be merged?

added 17 commits

• 30b4baa3...b18846d9 - 5 commits from branch master
• bb2f1c46 - daemon: added callback for resolve() query initialisation
• 00cb5245 - daemon: fixed memory leaking from wrk_resolve on some input errors
• b88714db - lib/resolve: add support for per-request logging
• 80abd563 - lib/rplan: remember request context in each query
• 937ec9a6 - lib: added support for trace_log for verbose messages
• 17d9bd86 - modules/http: added /trace endpoint for request log tracing, added tests
• 3f56c970 - modules/http: updated format of the /trace log
• 6f750103 - clean up on module test success, fix priming query failing predict test
• 6cc0b704 - ci: added lua-http dependency to build, fixed test for http
• 98f3284a - main: close loop after it's finished to please valgrind
• 07ef83cb - kres: added support for NULL type
• d66d1563 - modules/http: added selected records to /trace endpoint

Compare with previous version

mentioned in commit d02a6718

added 42 commits

• d66d1563...07ff6fda - 29 commits from branch master
• bb9c2e89 - daemon: added callback for resolve() query initialisation
• 92f80d79 - daemon: fixed memory leaking from wrk_resolve on some input errors
• 0a04428e - lib/resolve: add support for per-request logging
• 26adb0b0 - lib/rplan: remember request context in each query
• 393b738a - lib: added support for trace_log for verbose messages
• 5e7e4c1e - modules/http: added /trace endpoint for request log tracing, added tests
• 02809b8c - modules/http: updated format of the /trace log
• adbd8e55 - clean up on module test success, fix priming query failing predict test
• f1539c74 - ci: added lua-http dependency to build, fixed test for http
• 875e02b2 - main: close loop after it's finished to please valgrind
• 0a891eb6 - kres: added support for NULL type
• eba7b1ac - modules/http: added selected records to /trace endpoint
• c75b1176 - fixup after rebase from master

Compare with previous version

added 1 commit

• a3d38b58 - Revert "kres: added support for NULL type"

Compare with previous version

@vavrusam: (merge order), now that we have f4e78b04, I believe this MR can get rebased, cleaned, reviewed (by me) and merged, if you like.

BTW, CI hangs for some reason. (I haven't looked properly.)

added 71 commits

• a3d38b58...f4e78b04 - 55 commits from branch master
• 2ed6860a - daemon: added callback for resolve() query initialisation
• 047150b5 - daemon: fixed memory leaking from wrk_resolve on some input errors
• 66a1dcd6 - lib/resolve: add support for per-request logging
• 3d6381e7 - lib/rplan: remember request context in each query
• 329ae907 - lib: added support for trace_log for verbose messages
• 87de7dc5 - modules/http: added /trace endpoint for request log tracing, added tests
• 2631fbf8 - modules/http: updated format of the /trace log
• a0dc6c82 - clean up on module test success, fix priming query failing predict test
• 6c2c1229 - ci: added lua-http dependency to build, fixed test for http
• 60ed952e - main: close loop after it's finished to please valgrind
• fb117b21 - kres: added support for NULL type
• d71017e0 - modules/http: added selected records to /trace endpoint
• deb9de82 - fixup after rebase from master
• 9fac3e05 - Revert "kres: added support for NULL type"
• 0a1d373c - removed dead code, fixed up rebase
• a1c56f8f - add -Werror to daemon/lib to prevent builds with dead code

Compare with previous version

added 19 commits

• bb9c2e89 - daemon: added callback for resolve() query initialisation
• 92f80d79 - daemon: fixed memory leaking from wrk_resolve on some input errors
• 0a04428e - lib/resolve: add support for per-request logging
• 26adb0b0 - lib/rplan: remember request context in each query
• 393b738a - lib: added support for trace_log for verbose messages
• 5e7e4c1e - modules/http: added /trace endpoint for request log tracing, added tests
• 02809b8c - modules/http: updated format of the /trace log
• adbd8e55 - clean up on module test success, fix priming query failing predict test
• f1539c74 - ci: added lua-http dependency to build, fixed test for http
• 875e02b2 - main: close loop after it's finished to please valgrind
• 0a891eb6 - kres: added support for NULL type
• eba7b1ac - modules/http: added selected records to /trace endpoint
• c75b1176 - fixup after rebase from master
• a3d38b58 - Revert "kres: added support for NULL type"
• 5cd07091 - daemon/worker: allow large responses for outbound over TCP
• 90ad2406 - daemon: unified query completion callback with trace callback in resolve
• 6aace305 - lib: added kr_rplan_last() function to get last processed query
• d63a89d4 - tests/config: all tests can now be asynchronous with worker.coroutine
• 6500ed98 - add -Werror to daemon/lib to prevent builds with dead code

Compare with previous version

I've reverted the rebase to master and will try to merge master into this branch instead, there's too many conflicts.

CI hang: this is fixed in !406 (merged), so what I'm going to do instead is cherry-pick minimal changes from that MR and then merge master into this MR, which should hopefully make the conflict resolution sane.

added 6 commits

• 8fa95978 - Implement worker coroutines for asynchronous background processing
• e25358d4 - daemon/worker: allow large responses for outbound over TCP
• 7afffaa9 - daemon: unified query completion callback with trace callback in resolve
• 96a4d0fa - tests/config: all tests can now be asynchronous with worker.coroutine
• 8f31e3ac - lib: added kr_rplan_last() function to get last processed query
• 9ca537e8 - add -Werror to daemon/lib to prevent builds with dead code

Compare with previous version

CI build is now fixed, merging master branch.

added 56 commits

• 9ca537e8...f4e78b04 - 55 commits from branch master
• 79628be3 - Merge remote-tracking branch 'origin/master' into query-trace

Compare with previous version

added 1 commit

• ab4fb466 - Merge remote-tracking branch 'origin/master' into query-trace

Compare with previous version

added 1 commit

• a732fca8 - Merge remote-tracking branch 'origin/master' into query-trace

Compare with previous version

added 1 commit

• 97729953 - Merge remote-tracking branch 'origin/master' into query-trace

Compare with previous version

added 2 commits

• 2c6e0e48 - Revert "add -Werror to daemon/lib to prevent builds with dead code"
• 5f0b840d - removed lua-http installed through luarocks as it's installed in packages

Compare with previous version

mentioned in merge request !432 (merged)

resolved all discussions

mentioned in commit 960c89017c76c66f6dff2259a1582e08f6ee6dbe

added 98 commits

• 5f0b840d...f72c889c - 96 commits from branch master
• 6949f514 - Merge branch 'master'
• 960c8901 - nitpicks from review of !405 (merged): query-trace

Compare with previous version

mentioned in commit f348b4bf498be48b7a52819bac868d50579206bb

added 1 commit

• f348b4bf - nitpicks from review of !405 (merged): query-trace

Compare with previous version

mentioned in commit be2d760f7de0ca7053a37509868bbb8433e756a2

added 2 commits

• be2d760f - nitpicks from review of !405 (merged): query-trace
• 5de04a32 - http module: rename after 2702e041

Compare with previous version

mentioned in commit f705c82a

added 5 commits

• 5de04a32...446343ee - 2 commits from branch master
• 1f0a0f6c - Merge branch 'master'
• f705c82a - nitpicks from review of !405 (merged): query-trace
• a006e7f4 - http module: rename after 2702e041

Compare with previous version

enabled an automatic merge when the pipeline for a006e7f4 succeeds

merged