Verified Commit 9c2de036 authored by Grigorii Demidov's avatar Grigorii Demidov Committed by Vladimír Čunát

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

parent 2d9ddd8d
......@@ -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 {
......
......@@ -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;
......
......@@ -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 */
......
......@@ -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;
}
......
......@@ -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
......
......@@ -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;
......
......@@ -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;
}}
......
......@@ -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. */
......
......@@ -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;
}
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment