daemon, lib: use query uid in log instead of msg id

diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua
index 7d06d2003f9208aa159c0cde6724210f692d2a0b..ef12802c65054bfb31297a98622e0f8c897762c7 100644 (file)
--- a/daemon/lua/kres-gen.lua
+++ b/daemon/lua/kres-gen.lua
@@ -195,6 +195,7 @@ struct kr_request {
        trace_callback_f trace_finish;
        int vars_ref;
        knot_mm_t pool;
+       unsigned int uid;
 };
 enum kr_rank {KR_RANK_INITIAL, KR_RANK_OMIT, KR_RANK_TRY, KR_RANK_INDET = 4, KR_RANK_BOGUS, KR_RANK_MISMATCH, KR_RANK_MISSING, KR_RANK_INSECURE, KR_RANK_AUTH = 16, KR_RANK_SECURE = 32};
 struct kr_cache {

diff --git a/daemon/worker.c b/daemon/worker.c
index da74ea520666f7294c1a79fd3902b58b387c7272..fccfc274816eff6abbddae508a46b134721d357f 100644 (file)
--- a/daemon/worker.c
+++ b/daemon/worker.c
@@ -268,7 +268,8 @@ static int subreq_key(char *dst, knot_pkt_t *pkt)
  */
 static struct request_ctx *request_create(struct worker_ctx *worker,
                                          uv_handle_t *handle,
-                                         const struct sockaddr *addr)
+                                         const struct sockaddr *addr,
+                                         uint32_t uid)
 {
        knot_mm_t pool = {
                .ctx = pool_borrow(worker),
@@ -295,6 +296,7 @@ static struct request_ctx *request_create(struct worker_ctx *worker,
        struct kr_request *req = &ctx->req;
        req->pool = pool;
        req->vars_ref = LUA_NOREF;
+       req->uid = uid;
 
        /* Remember query source addr */
        if (!addr || (addr->sa_family != AF_INET && addr->sa_family != AF_INET6)) {
@@ -600,7 +602,7 @@ static int qr_task_send(struct qr_task *task, struct session *session,
                pkt = worker_task_get_pktbuf(task);
        }
 
-       if (session_flags(session)->outgoing) {
+       if (session_flags(session)->outgoing && handle->type == UV_TCP) {
                size_t try_limit = session_tasklist_get_len(session) + 1;
                uint16_t msg_id = knot_wire_get_id(pkt->wire);
                size_t try_count = 0;
@@ -1432,7 +1434,8 @@ int worker_submit(struct session *session, knot_pkt_t *query)
        struct sockaddr *addr = NULL;
        if (!is_outgoing) { /* request from a client */
                struct request_ctx *ctx = request_create(worker, handle,
-                                                        session_get_peer(session));
+                                                        session_get_peer(session),
+                                                        knot_wire_get_id(query->wire));
                if (!ctx) {
                        return kr_error(ENOMEM);
                }
@@ -1625,7 +1628,8 @@ struct qr_task *worker_resolve_start(struct worker_ctx *worker, knot_pkt_t *quer
                return NULL;
        }
 
-       struct request_ctx *ctx = request_create(worker, NULL, NULL);
+
+       struct request_ctx *ctx = request_create(worker, NULL, NULL, worker->next_request_uid);
        if (!ctx) {
                return NULL;
        }
@@ -1648,6 +1652,11 @@ struct qr_task *worker_resolve_start(struct worker_ctx *worker, knot_pkt_t *quer
                return NULL;
        }
 
+       worker->next_request_uid += 1;
+       if (worker->next_request_uid == 0) {
+               worker->next_request_uid = UINT16_MAX + 1;
+       }
+
        /* Set options late, as qr_task_start() -> kr_resolve_begin() rewrite it. */
        kr_qflags_set(&task->ctx->req.options, options);
        return task;
@@ -1803,6 +1812,7 @@ struct worker_ctx *worker_create(struct engine *engine, knot_mm_t *pool,
        worker->id = worker_id;
        worker->count = worker_count;
        worker->engine = engine;
+       worker->next_request_uid = UINT16_MAX + 1;
        worker_reserve(worker, MP_FREELIST_SIZE);
        worker->out_addr4.sin_family = AF_UNSPEC;
        worker->out_addr6.sin6_family = AF_UNSPEC;

diff --git a/daemon/worker.h b/daemon/worker.h
index 89d157f1b0db4272d9de2e3cf9a29e50ca706dcb..8e838ce49c1b596c303442c1913991817c22bcad 100644 (file)
--- a/daemon/worker.h
+++ b/daemon/worker.h
@@ -160,6 +160,7 @@ struct worker_ctx {
        trie_t *subreq_out;
        mp_freelist_t pool_mp;
        knot_mm_t pkt_pool;
+       unsigned int next_request_uid;
 };
 
 /** @endcond */

diff --git a/lib/cache/api.c b/lib/cache/api.c
index df9b439152fdcb8f7085aada6258a98eef4112b1..de0aef9164c72685d266fabcb69b5aa78a3f0a76 100644 (file)
--- a/lib/cache/api.c
+++ b/lib/cache/api.c
@@ -614,7 +614,8 @@ static int stash_rrarray_entry(ranked_rr_array_t *arr, int arr_i,
        ssize_t written = stash_rrset(cache, qry, rr, rr_sigs, qry->timestamp.tv_sec,
                                        entry->rank, nsec_pmap, has_optout);
        if (written < 0) {
-               kr_log_error("[%5hu][cach] stash failed, ret = %d\n", qry->id, ret);
+               kr_log_error("[%i.%i][cach] stash failed, ret = %d\n", qry->request->uid,
+                            qry->uid, ret);
                return (int) written;
        }
 

diff --git a/lib/layer.h b/lib/layer.h
index 227ff99aabd7a56feeff34448fbf1d6c25278260..31125d888369112c1bd0656b9fc31872e442bea0 100644 (file)
--- a/lib/layer.h
+++ b/lib/layer.h
@@ -27,9 +27,10 @@
         kr_log_trace(q, cls, fmt, ##  __VA_ARGS__); \
     } else WITH_VERBOSE(q) { \
         unsigned _ind = 0; \
-        uint16_t _id = q ? q->id : 0; \
+        uint32_t _q_uid = q ? q->uid : 0; \
+        uint32_t _req_uid = q && q->request ? q->request->uid : 0; \
         for (; q; q = q->parent, _ind += 2); \
-        kr_log_verbose("[%5hu][%s] %*s" fmt, _id, cls, _ind, "", ##  __VA_ARGS__); \
+        kr_log_verbose("[%i.%i][%s] %*s" fmt, _req_uid, _q_uid, cls, _ind, "", ##  __VA_ARGS__); \
     } \
 }
 #else

diff --git a/lib/layer/iterate.c b/lib/layer/iterate.c
index e094dbb6181241b9c7dbebb3988fd499426dccd0..95133b612ac5796ca8673d9b3c457535511574d0 100644 (file)
--- a/lib/layer/iterate.c
+++ b/lib/layer/iterate.c
@@ -910,15 +910,18 @@ int kr_make_query(struct kr_query *query, knot_pkt_t *pkt)
 
        /* Query built, expect answer. */
        uint32_t rnd = kr_rand_uint(0);
+       /* We must respect https://tools.ietf.org/html/rfc7766#section-6.2.1
+        * -  When sending multiple queries over a TCP connection, clients MUST NOT
+        *    reuse the DNS Message ID of an in-flight query on that connection.
+        *
+        * So, if query is going to be sent over TCP connection
+        * this id can be changed to avoid duplication with query that already was sent
+        * but didn't receive answer yet.
+        */
        query->id = rnd ^ (rnd >> 16); /* cheap way to strengthen unpredictability */
        knot_wire_set_id(pkt->wire, query->id);
        pkt->parsed = pkt->size;
-       WITH_VERBOSE(query) {
-               KR_DNAME_GET_STR(name_str, query->sname);
-               KR_RRTYPE_GET_STR(type_str, query->stype);
-               QVERBOSE_MSG(query, "'%s' type '%s' id was assigned, parent id %u\n",
-                           name_str, type_str, query->parent ? query->parent->id : 0);
-       }
+
        return kr_ok();
 }
 
@@ -937,6 +940,14 @@ static int prepare_query(kr_layer_t *ctx, knot_pkt_t *pkt)
                return KR_STATE_FAIL;
        }
 
+       WITH_VERBOSE(query) {
+               KR_DNAME_GET_STR(name_str, query->sname);
+               KR_RRTYPE_GET_STR(type_str, query->stype);
+               QVERBOSE_MSG(query, "'%s' type '%s' new uid was assigned %u, parent uid %u\n",
+                           name_str, type_str, req->rplan.next_uid,
+                           query->parent ? query->parent->uid : 0);
+       }
+
        query->uid = req->rplan.next_uid;
        req->rplan.next_uid += 1;
 

diff --git a/lib/resolve.c b/lib/resolve.c
index 7e027d3a6f9123adcfbe329ae8ff2d6d7b252aab..0e4bd75d49b2cb4f41964bd1fd6c314957554ca0 100644 (file)
--- a/lib/resolve.c
+++ b/lib/resolve.c
@@ -1581,8 +1581,10 @@ int kr_resolve_checkout(struct kr_request *request, struct sockaddr *src,
                }
                inet_ntop(addr->sa_family, kr_inaddr(&qry->ns.addr[i].ip), ns_str, sizeof(ns_str));
                VERBOSE_MSG(qry,
-                       "=> querying: '%s' score: %u zone cut: '%s' qname: '%s' qtype: '%s' proto: '%s'\n",
-                       ns_str, qry->ns.score, zonecut_str, qname_str, type_str, (qry->flags.TCP) ? "tcp" : "udp");
+                       "=> id: '%u' querying: '%s' score: %u zone cut: '%s' "
+                       "qname: '%s' qtype: '%s' proto: '%s'\n",
+                       qry->id, ns_str, qry->ns.score, zonecut_str,
+                       qname_str, type_str, (qry->flags.TCP) ? "tcp" : "udp");
                break;
        }}
 

diff --git a/lib/resolve.h b/lib/resolve.h
index 1b8647ef5c913429cf014fb2edcaf304af5265a5..d1b6da04279596aa777202f999f374313b0ecbfd 100644 (file)
--- a/lib/resolve.h
+++ b/lib/resolve.h
@@ -227,6 +227,7 @@ struct kr_request {
        trace_callback_f trace_finish; /**< Request finish tracepoint */
        int vars_ref; /**< Reference to per-request variable table. LUA_NOREF if not set. */
        knot_mm_t pool;
+       unsigned int uid; /** for logging purposes only */
 };
 
 /** Initializer for an array of *_selected. */

diff --git a/lib/rplan.c b/lib/rplan.c
index 51973d1f53ddd1db41c76283e9e87b6211308484..88b4bd805bf3c70760440039fdb1fdba02cced00 100644 (file)
--- a/lib/rplan.c
+++ b/lib/rplan.c
@@ -207,7 +207,8 @@ struct kr_query *kr_rplan_push_empty(struct kr_rplan *rplan, struct kr_query *pa
        }
 
        WITH_VERBOSE(qry) {
-       VERBOSE_MSG(qry, "plan '%s' type '%s'\n", "", "");
+       VERBOSE_MSG(qry, "plan '%s' type '%s'  uid [%i.%i]\n", "", "",
+                   qry->request ? qry->request->uid : 0, qry->uid);
        }
        return qry;
 }
@@ -230,7 +231,9 @@ struct kr_query *kr_rplan_push(struct kr_rplan *rplan, struct kr_query *parent,
        WITH_VERBOSE(qry) {
        KR_DNAME_GET_STR(name_str, name);
        KR_RRTYPE_GET_STR(type_str, type);
-       VERBOSE_MSG(parent, "plan '%s' type '%s'\n", name_str, type_str);
+       VERBOSE_MSG(parent, "plan '%s' type '%s' uid [%i.%i]\n",
+                   name_str, type_str,
+                   qry->request ? qry->request->uid : 0, qry->uid);
        }
        return qry;
 }