From 0238c37f1991c9ba7c46485ef3a16b896fb9c55f Mon Sep 17 00:00:00 2001
From: =?utf8?q?Marek=20Vavru=C5=A1a?= <marek.vavrusa@nic.cz>
Date: Thu, 26 Nov 2015 18:10:12 +0100
Subject: [PATCH] daemon: verbose debug logs on -DDEBUG

---
 daemon/worker.c | 44 +++++++++++++++++++++++++++++++++++---------
 1 file changed, 35 insertions(+), 9 deletions(-)

diff --git a/daemon/worker.c b/daemon/worker.c
index 9ffbe5aa3..d1af7db4d 100644
--- a/daemon/worker.c
+++ b/daemon/worker.c
@@ -42,6 +42,13 @@ struct ioreq
 /** @internal Number of request within timeout window. */
 #define MAX_PENDING (KR_NSREP_MAXADDR + (KR_NSREP_MAXADDR / 2))
 
+/** @internal Debugging facility. */
+#ifdef DEBUG
+#define DEBUG_MSG(fmt...) printf("[daem] " fmt)
+#else
+#define DEBUG_MSG(fmt...)
+#endif
+
 /** @internal Query resolution task. */
 struct qr_task
 {
@@ -322,6 +329,7 @@ static void on_timeout(uv_timer_t *req)
 {
 	struct qr_task *task = req->data;
 	if (!uv_is_closing((uv_handle_t *)req)) {
+		DEBUG_MSG("ioreq timeout %p", req);
 		qr_task_step(task, NULL, NULL);
 	}
 }
@@ -332,6 +340,8 @@ static int qr_task_on_send(struct qr_task *task, uv_handle_t *handle, int status
 	if (!task->finished) {
 		if (status == 0 && handle) {
 			io_start_read(handle); /* Start reading answer */
+		} else {
+			DEBUG_MSG("ioreq send_done %p => %d, %s", handle, status, uv_strerror(status));
 		}
 	} else {
 		/* Close retry timer (borrows task) */
@@ -395,6 +405,7 @@ static int qr_task_send(struct qr_task *task, uv_handle_t *handle, struct sockad
 	if (ret == 0) {
 		qr_task_ref(task); /* Pending ioreq on current task */
 	} else {
+		DEBUG_MSG("ioreq send_start %p => %d, %s", send_req, ret, uv_strerror(ret));
 		ioreq_release(task->worker, send_req);
 	}
 
@@ -424,6 +435,7 @@ static void on_connect(uv_connect_t *req, int status)
 		if (status == 0) {
 			qr_task_send(task, (uv_handle_t *)handle, (struct sockaddr *)&addr, task->pktbuf);
 		} else {
+			DEBUG_MSG("ioreq conn_done %p => %d, %s", req, status, uv_strerror(status));
 			qr_task_step(task, (struct sockaddr *)&addr, NULL);
 		}
 	}
@@ -431,22 +443,30 @@ static void on_connect(uv_connect_t *req, int status)
 	ioreq_release(worker, (struct ioreq *)req);
 }
 
-static void on_retransmit(uv_timer_t *req)
+static bool retransmit(struct qr_task *task)
 {
-	struct qr_task *task = req->data;
-	/* Create connection for iterative query */
-	if (!uv_is_closing((uv_handle_t *)req) && task->addrlist) {
+	if (task && task->addrlist) {
 		uv_handle_t *subreq = ioreq_spawn(task, SOCK_DGRAM);
-		if (subreq) {
+		if (subreq) { /* Create connection for iterative query */
 			struct sockaddr_in6 *choice = &((struct sockaddr_in6 *)task->addrlist)[task->addrlist_turn];
 			if (qr_task_send(task, subreq, (struct sockaddr *)choice, task->pktbuf) == 0) {
 				task->addrlist_turn = (task->addrlist_turn + 1) % task->addrlist_count; /* Round robin */
-				return;
+				return true;
 			}
 		}
 	}
-	/* Not possible to spawn request, stop trying */
-	uv_timer_stop(req);
+	return false;
+}
+
+static void on_retransmit(uv_timer_t *req)
+{
+	if (uv_is_closing((uv_handle_t *)req))
+		return;
+	if (!retransmit(req->data)) {
+		/* Not possible to spawn request, stop trying */
+		DEBUG_MSG("ioreq retransmit %p => failed", req);
+		uv_timer_stop(req);
+	}
 }
 
 static int qr_task_finalize(struct qr_task *task, int state)
@@ -474,6 +494,7 @@ static int qr_task_step(struct qr_task *task, const struct sockaddr *packet_sour
 	while (state == KNOT_STATE_PRODUCE) {
 		state = kr_resolve_produce(&task->req, &task->addrlist, &sock_type, task->pktbuf);
 		if (unlikely(++task->iter_count > KR_ITER_LIMIT)) {
+			DEBUG_MSG("task iter_limit %p", task);
 			return qr_task_finalize(task, KNOT_STATE_FAIL);
 		}
 	}
@@ -494,7 +515,8 @@ static int qr_task_step(struct qr_task *task, const struct sockaddr *packet_sour
 
 	/* Start fast retransmit with UDP, otherwise connect. */
 	if (sock_type == SOCK_DGRAM) {
-		uv_timer_start(&task->retry, on_retransmit, 0, KR_CONN_RETRY);
+		if (retransmit(task))
+			uv_timer_start(&task->retry, on_retransmit, KR_CONN_RETRY, KR_CONN_RETRY);
 	} else {
 		struct ioreq *conn = ioreq_take(task->worker);
 		if (!conn) {
@@ -507,6 +529,7 @@ static int qr_task_step(struct qr_task *task, const struct sockaddr *packet_sour
 		}
 		conn->as.connect.data = task;
 		if (uv_tcp_connect(&conn->as.connect, (uv_tcp_t *)client, task->addrlist, on_connect) != 0) {
+			DEBUG_MSG("task conn_start %p => failed", task);
 			ioreq_release(task->worker, conn);
 			return qr_task_step(task, NULL, NULL);
 		}
@@ -550,6 +573,7 @@ int worker_exec(struct worker_ctx *worker, uv_handle_t *handle, knot_pkt_t *quer
 	if (is_master_socket) {
 		/* Ignore badly formed queries or responses. */
 		if (ret != 0 || knot_wire_get_qr(query->wire)) {
+			DEBUG_MSG("task bad_query %p => %d, %s", task, ret, kr_strerror(ret));
 			return kr_error(EINVAL); /* Ignore. */
 		}
 		task = qr_task_create(worker, handle, query, addr);
@@ -667,3 +691,5 @@ void worker_reclaim(struct worker_ctx *worker)
 	mp_delete(worker->pkt_pool.ctx);
 	worker->pkt_pool.ctx = NULL;
 }
+
+#undef DEBUG_MSG
-- 
2.47.2