From: Marek VavruĊĦa Date: Tue, 15 Sep 2015 14:37:19 +0000 (+0200) Subject: daemon: '-v' turns verbose log, debug messages built in by default X-Git-Tag: v1.0.0-beta1~53^2~80 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=004eabcf9e5deaca33f9d3f0bdd3b7336d22d33f;p=thirdparty%2Fknot-resolver.git daemon: '-v' turns verbose log, debug messages built in by default previously, debug messages were optional with -DWITH_DEBUG now the debug messages are built in (unless compiled with -DNDEBUG), but disabled by default verbose output can be enabled by '-v' or '--verbose' CLI option or interactively by 'verbose(true|false)' (or in config) --- diff --git a/daemon/README.rst b/daemon/README.rst index c9a0309e8..7ac1c3ab1 100644 --- a/daemon/README.rst +++ b/daemon/README.rst @@ -12,12 +12,11 @@ Requirements Running ======= -There is a separate resolver library in the `lib` directory, and a minimalistic daemon in -the `daemon` directory. +There is a separate resolver library in the `lib` directory, and a server in the `daemon` directory. .. code-block:: bash - $ ./daemon/kresd -h + $ kresd -h Interacting with the daemon --------------------------- @@ -60,6 +59,16 @@ of running processes, and you can test the process for liveliness by connecting .. warning:: This is very basic way to orchestrate multi-core deployments and doesn't scale in multi-node clusters. Keep an eye on the prepared ``hive`` module that is going to automate everything from service discovery to deployment and consistent configuration. +Verbose output +-------------- + +If the debug logging is compiled in, you can turn on verbose tracing of server operation with the ``-v`` option. +You can also toggle it on runtime with ``verbose(true|false)`` command. + +.. code-block:: bash + + $ kresd -v + Configuration ============= @@ -241,6 +250,10 @@ Environment :return: Machine hostname. +.. function:: verbose(true | false) + + :return: Toggle verbose logging. + Network configuration ^^^^^^^^^^^^^^^^^^^^^ diff --git a/daemon/engine.c b/daemon/engine.c index d94d5423e..47de46590 100644 --- a/daemon/engine.c +++ b/daemon/engine.c @@ -52,6 +52,7 @@ static int l_help(lua_State *L) "help()\n show this help\n" "quit()\n quit\n" "hostname()\n hostname\n" + "verbose(true|false)\n toggle verbose mode\n" "option(opt[, new_val])\n get/set server option\n" ; lua_pushstring(L, help_str); @@ -61,12 +62,20 @@ static int l_help(lua_State *L) /** Quit current executable. */ static int l_quit(lua_State *L) { - /* Stop engine */ engine_stop(engine_luaget(L)); - /* No results */ return 0; } +/** Toggle verbose mode. */ +static int l_verbose(lua_State *L) +{ + if (lua_isboolean(L, 1) || lua_isnumber(L, 1)) { + log_debug_enable(lua_toboolean(L, 1)); + } + lua_pushboolean(L, log_debug_status()); + return 1; +} + /** Return hostname. */ static int l_hostname(lua_State *L) { @@ -96,7 +105,7 @@ static int l_option(lua_State *L) } } /* Get or set */ - if (lua_isboolean(L, 2)) { + if (lua_isboolean(L, 2) || lua_isnumber(L, 2)) { if (lua_toboolean(L, 2)) { engine->resolver.options |= opt_code; } else { @@ -284,10 +293,12 @@ static int init_state(struct engine *engine) lua_setglobal(engine->L, "help"); lua_pushcfunction(engine->L, l_quit); lua_setglobal(engine->L, "quit"); - lua_pushcfunction(engine->L, l_option); - lua_setglobal(engine->L, "option"); lua_pushcfunction(engine->L, l_hostname); lua_setglobal(engine->L, "hostname"); + lua_pushcfunction(engine->L, l_verbose); + lua_setglobal(engine->L, "verbose"); + lua_pushcfunction(engine->L, l_option); + lua_setglobal(engine->L, "option"); lua_pushlightuserdata(engine->L, engine); lua_setglobal(engine->L, "__engine"); return kr_ok(); diff --git a/daemon/main.c b/daemon/main.c index 616a5dea9..4bc141c0f 100644 --- a/daemon/main.c +++ b/daemon/main.c @@ -124,7 +124,8 @@ static void help(int argc, char *argv[]) printf("\nParameters:\n" " -a, --addr=[addr] Server address (default: localhost#53).\n" " -f, --forks=N Start N forks sharing the configuration.\n" - " -v, --version Print version of the server.\n" + " -v, --verbose Run in verbose mode.\n" + " -V, --version Print version of the server.\n" " -h, --help Print help and usage.\n" "Options:\n" " [rundir] Path to the working directory (default: .)\n"); @@ -201,11 +202,12 @@ int main(int argc, char **argv) struct option opts[] = { {"addr", required_argument, 0, 'a'}, {"forks",required_argument, 0, 'f'}, - {"version", no_argument, 0, 'v'}, + {"verbose", no_argument, 0, 'v'}, + {"version", no_argument, 0, 'V'}, {"help", no_argument, 0, 'h'}, {0, 0, 0, 0} }; - while ((c = getopt_long(argc, argv, "a:f:vh", opts, &li)) != -1) { + while ((c = getopt_long(argc, argv, "a:f:vVh", opts, &li)) != -1) { switch (c) { case 'a': @@ -215,12 +217,15 @@ int main(int argc, char **argv) g_interactive = 0; forks = atoi(optarg); if (forks == 0) { - fprintf(stderr, "[system] error '-f' requires number, not '%s'\n", optarg); + log_error("[system] error '-f' requires number, not '%s'\n", optarg); return EXIT_FAILURE; } break; case 'v': - printf("%s, version %s\n", "Knot DNS Resolver", PACKAGE_VERSION); + log_debug_enable(true); + break; + case 'V': + log_info("%s, version %s\n", "Knot DNS Resolver", PACKAGE_VERSION); return EXIT_SUCCESS; case 'h': case '?': @@ -236,12 +241,12 @@ int main(int argc, char **argv) if (optind < argc) { const char *rundir = argv[optind]; if (access(rundir, W_OK) != 0) { - fprintf(stderr, "[system] rundir '%s': not writeable\n", rundir); + log_error("[system] rundir '%s': not writeable\n", rundir); return EXIT_FAILURE; } ret = chdir(rundir); if (ret != 0) { - fprintf(stderr, "[system] rundir '%s': %s\n", rundir, strerror(errno)); + log_error("[system] rundir '%s': %s\n", rundir, strerror(errno)); return EXIT_FAILURE; } } @@ -277,20 +282,20 @@ int main(int argc, char **argv) struct engine engine; ret = engine_init(&engine, &pool); if (ret != 0) { - fprintf(stderr, "[system] failed to initialize engine: %s\n", kr_strerror(ret)); + log_error("[system] failed to initialize engine: %s\n", kr_strerror(ret)); return EXIT_FAILURE; } /* Create worker */ struct worker_ctx *worker = init_worker(loop, &engine, &pool, forks); if (!worker) { - fprintf(stderr, "[system] not enough memory\n"); + log_error("[system] not enough memory\n"); return EXIT_FAILURE; } /* Bind to sockets and run */ if (addr != NULL) { ret = network_listen(&engine.net, addr, (uint16_t)port, NET_UDP|NET_TCP); if (ret != 0) { - fprintf(stderr, "[system] bind to '%s#%d' %s\n", addr, port, knot_strerror(ret)); + log_error("[system] bind to '%s#%d' %s\n", addr, port, knot_strerror(ret)); ret = EXIT_FAILURE; } } diff --git a/doc/build.rst b/doc/build.rst index 32e04d5a2..aeb56714a 100644 --- a/doc/build.rst +++ b/doc/build.rst @@ -85,7 +85,7 @@ When you have all the dependencies ready, you can build and install. $ make PREFIX="/usr/local" $ make install -.. note:: Always build with ``PREFIX`` if you want to install, as it is hardcoded in the executable for module search path. +.. note:: Always build with ``PREFIX`` if you want to install, as it is hardcoded in the executable for module search path. If you build the binary with ``-DNDEBUG``, verbose logging will be disabled as well. Alternatively you can build only specific parts of the project, i.e. ``library``. @@ -96,17 +96,6 @@ Alternatively you can build only specific parts of the project, i.e. ``library`` .. note:: Documentation is not built by default, run ``make doc`` to build it. -Debug build ------------ - -For debugging or tinkering purposes, it's useful to build the daemon with the debug messages enabled. - -.. code-block:: bash - - $ CFLAGS="-O0 -g -DWITH_DEBUG" make - -.. warning:: If you want to track specific things like i.e. number of subrequests for given zone in production, use Lua modules or write custom layers rather then depending on debug output. - Building dependencies ~~~~~~~~~~~~~~~~~~~~~ diff --git a/lib/dnssec/ta.c b/lib/dnssec/ta.c index aebb4bf8f..9fabfb35d 100644 --- a/lib/dnssec/ta.c +++ b/lib/dnssec/ta.c @@ -427,12 +427,6 @@ int kr_ta_parse(knot_rrset_t **rr, const char *ds_str, mm_ctx_t *pool) *rr = ds_set; ds_set = NULL; -#ifdef WITH_DEBUG -// char buff[1024]; -// knot_rrset_txt_dump(*rr, buff, 1024, &KNOT_DUMP_STYLE_DEFAULT); -// fprintf(stderr, "%s() '%s'\n", __func__, buff); -#endif - fail: knot_rrset_free(&ds_set, pool); mm_free(pool, rdata); diff --git a/lib/layer.h b/lib/layer.h index db358c7e9..827118dfe 100644 --- a/lib/layer.h +++ b/lib/layer.h @@ -17,15 +17,15 @@ #pragma once #include "lib/defines.h" +#include "lib/utils.h" #include "lib/resolve.h" -#ifdef WITH_DEBUG -/** @internal Print a debug message related to resolution. */ +#ifndef NDEBUG + /** @internal Print a debug message related to resolution. */ #define QRDEBUG(query, cls, fmt, ...) do { \ unsigned _ind = 0; \ for (struct kr_query *q = (query); q; q = q->parent, _ind += 2); \ - fprintf(stdout, "[%s] %*s" fmt, cls, _ind, "", ## __VA_ARGS__); \ - fflush(stdout); \ + log_debug("[%s] %*s" fmt, cls, _ind, "", ## __VA_ARGS__); \ } while (0) #else #define QRDEBUG(query, cls, fmt, ...) diff --git a/lib/layer/iterate.c b/lib/layer/iterate.c index 1a1ff08f5..b5c9cea24 100644 --- a/lib/layer/iterate.c +++ b/lib/layer/iterate.c @@ -474,7 +474,7 @@ static int resolve(knot_layer_t *ctx, knot_pkt_t *pkt) return KNOT_STATE_DONE; } -#ifdef WITH_DEBUG +#ifndef NDEBUG lookup_table_t *rcode = lookup_by_id(knot_rcode_names, knot_wire_get_rcode(pkt->wire)); #endif diff --git a/lib/resolve.c b/lib/resolve.c index f67d36a11..ac023361a 100644 --- a/lib/resolve.c +++ b/lib/resolve.c @@ -308,7 +308,7 @@ int kr_resolve(struct kr_context* ctx, knot_pkt_t *answer, request.pool = pool; kr_resolve_begin(&request, ctx, answer); request.options |= options; -#ifdef WITH_DEBUG +#ifndef NDEBUG struct kr_rplan *rplan = &request.rplan; /* for DEBUG_MSG */ #endif /* Resolve query, iteratively */ @@ -574,15 +574,16 @@ ns_election: return KNOT_STATE_FAIL; } -#ifdef WITH_DEBUG + WITH_DEBUG { char qname_str[KNOT_DNAME_MAXLEN], zonecut_str[KNOT_DNAME_MAXLEN], ns_str[SOCKADDR_STRLEN], type_str[16]; knot_dname_to_str(qname_str, knot_pkt_qname(packet), sizeof(qname_str)); struct sockaddr *addr = &qry->ns.addr.ip; inet_ntop(addr->sa_family, kr_nsrep_inaddr(qry->ns.addr), ns_str, sizeof(ns_str)); knot_dname_to_str(zonecut_str, qry->zone_cut.name, sizeof(zonecut_str)); knot_rrtype_to_string(knot_pkt_qtype(packet), type_str, sizeof(type_str)); - DEBUG_MSG("=> querying: '%s' score: %u zone cut: '%s' m12n: '%s' type: '%s'\n", ns_str, qry->ns.score, zonecut_str, qname_str, type_str); -#endif + DEBUG_MSG("=> querying: '%s' score: %u zone cut: '%s' m12n: '%s' type: '%s'\n", + ns_str, qry->ns.score, zonecut_str, qname_str, type_str); + } gettimeofday(&qry->timestamp, NULL); *dst = &qry->ns.addr.ip; @@ -592,9 +593,8 @@ ns_election: int kr_resolve_finish(struct kr_request *request, int state) { -#ifdef WITH_DEBUG +#ifndef NDEBUG struct kr_rplan *rplan = &request->rplan; - DEBUG_MSG("finished: %d, mempool: %zu B\n", state, (size_t) mp_total_size(request->pool.ctx)); #endif /* Finalize answer */ if (answer_finalize(request, state) != 0) { @@ -607,7 +607,9 @@ int kr_resolve_finish(struct kr_request *request, int state) knot_wire_set_rcode(answer->wire, KNOT_RCODE_SERVFAIL); } } + ITERATE_LAYERS(request, finish); + DEBUG_MSG("finished: %d, mempool: %zu B\n", state, (size_t) mp_total_size(request->pool.ctx)); return KNOT_STATE_DONE; } diff --git a/lib/rplan.c b/lib/rplan.c index 8aa640ef6..71c76e51c 100644 --- a/lib/rplan.c +++ b/lib/rplan.c @@ -123,12 +123,12 @@ struct kr_query *kr_rplan_push(struct kr_rplan *rplan, struct kr_query *parent, add_tail(&rplan->pending, &qry->node); kr_zonecut_init(&qry->zone_cut, (const uint8_t *)"", rplan->pool); -#ifdef WITH_DEBUG + WITH_DEBUG { char name_str[KNOT_DNAME_MAXLEN], type_str[16]; knot_dname_to_str(name_str, name, sizeof(name_str)); knot_rrtype_to_string(type, type_str, sizeof(type_str)); DEBUG_MSG(parent, "plan '%s' type '%s'\n", name_str, type_str); -#endif + } return qry; } diff --git a/lib/utils.c b/lib/utils.c index 5d9373ece..b2779f61c 100644 --- a/lib/utils.c +++ b/lib/utils.c @@ -28,6 +28,9 @@ #include "lib/generic/array.h" #include "lib/nsrep.h" +/* Logging & debugging */ +bool _env_debug = false; + /** @internal CSPRNG context */ static isaac_ctx ISAAC; static bool isaac_seeded = false; diff --git a/lib/utils.h b/lib/utils.h index c122e580f..ab1fa264a 100644 --- a/lib/utils.h +++ b/lib/utils.h @@ -34,8 +34,27 @@ extern void _cleanup_fclose(FILE **p); /* @endcond */ /* - * Defines. + * Logging and debugging. */ +#define log_info(fmt, ...) printf((fmt), ## __VA_ARGS__) +#define log_error(fmt, ...) fprintf(stderr, (fmt), ## __VA_ARGS__) +#ifndef NDEBUG +extern bool _env_debug; /* @internal cond variable */ +/* Toggle debug messages */ +#define log_debug_enable(x) _env_debug = (x) +#define log_debug_status() _env_debug +/* Message logging */ +#define log_debug(fmt, ...) do { \ + if (_env_debug) { printf((fmt), ## __VA_ARGS__); fflush(stdout); } \ + } while (0) +/* Debug block */ +#define WITH_DEBUG if(__builtin_expect(_env_debug, 0)) +#else +#define log_debug_status() false +#define log_debug_enable(x) +#define log_debug(fmt, ...) +#define WITH_DEBUG if(0) +#endif /** Return time difference in miliseconds. * @note based on the _BSD_SOURCE timersub() macro */