From da604c171418b64fcd37a46c4526ba97b6ee47dc Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Sat, 11 May 2019 15:11:52 +0200 Subject: [PATCH] complete TNG logging --- src/transport/gnunet-service-tng.c | 155 +++++++++++++++++++++++++---- 1 file changed, 133 insertions(+), 22 deletions(-) diff --git a/src/transport/gnunet-service-tng.c b/src/transport/gnunet-service-tng.c index 2141bc8e1..08a8ec893 100644 --- a/src/transport/gnunet-service-tng.c +++ b/src/transport/gnunet-service-tng.c @@ -24,7 +24,6 @@ * * TODO: * Implement next: - * - add (more) logging (beyond line ~7500) * - properly encrypt *all* DV traffic, not only backchannel; * rename BackchannelEncapsulation logic to DVEncapsulation! * - realize transport-to-transport flow control (needed in case @@ -1958,6 +1957,12 @@ struct PendingMessage */ struct MessageUUIDP msg_uuid; + /** + * UUID we use to identify this message in our logs. + * Generated by incrementing the "logging_uuid_gen". + */ + unsigned long long logging_uuid; + /** * Type of the pending message. */ @@ -2544,6 +2549,11 @@ static struct PendingAcknowledgement *pa_head; */ static struct PendingAcknowledgement *pa_tail; +/** + * Generator of `logging_uuid` in `struct PendingMessage`. + */ +static unsigned long long logging_uuid_gen; + /** * Number of entries in the #pa_head/#pa_tail DLL. Used to * limit the size of the data structure. @@ -3117,7 +3127,8 @@ schedule_transmit_on_queue (struct Queue *queue, int inside_job) { GNUNET_log ( GNUNET_ERROR_TYPE_DEBUG, - "Schedule transmission on queue %llu of %s decides to run immediately\n", + "Schedule transmission <%llu> on queue %llu of %s decides to run immediately\n", + pm->logging_uuid, (unsigned long long) queue->qid, GNUNET_i2s (&n->pid)); return; /* we should run immediately! */ @@ -3127,12 +3138,14 @@ schedule_transmit_on_queue (struct Queue *queue, int inside_job) GNUNET_SCHEDULER_add_delayed (out_delay, &transmit_on_queue, queue); if (out_delay.rel_value_us > DELAY_WARN_THRESHOLD.rel_value_us) GNUNET_log (GNUNET_ERROR_TYPE_WARNING, - "Next transmission on queue `%s' in %s (high delay)\n", + "Next transmission <%llu> on queue `%s' in %s (high delay)\n", + pm->logging_uuid, queue->address, GNUNET_STRINGS_relative_time_to_string (out_delay, GNUNET_YES)); else GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Next transmission on queue `%s' in %s\n", + "Next transmission <%llu> on queue `%s' in %s\n", + pm->logging_uuid, queue->address, GNUNET_STRINGS_relative_time_to_string (out_delay, GNUNET_YES)); } @@ -3573,7 +3586,8 @@ client_send_response (struct PendingMessage *pm) env = GNUNET_MQ_msg (som, GNUNET_MESSAGE_TYPE_TRANSPORT_SEND_OK); som->peer = target->pid; GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Confirming transmission to %s\n", + "Confirming transmission of <%llu> to %s\n", + pm->logging_uuid, GNUNET_i2s (&pm->target->pid)); GNUNET_MQ_send (tc->mq, env); } @@ -3773,11 +3787,6 @@ handle_client_send (void *cls, const struct OutboundMessage *obm) else dv = NULL; GNUNET_assert ((NULL != target) || (NULL != dv)); - GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Sending %u bytes to %s using %s\n", - bytes_msg, - GNUNET_i2s (&obm->peer), - (NULL == target) ? "distance vector path" : "direct queue"); if (NULL == target) { unsigned int res; @@ -3807,6 +3816,7 @@ handle_client_send (void *cls, const struct OutboundMessage *obm) was_empty = (NULL == target->pending_msg_head); pm = GNUNET_malloc (sizeof (struct PendingMessage) + payload_size); + pm->logging_uuid = logging_uuid_gen++; pm->prefs = pp; pm->client = tc; pm->target = target; @@ -3815,6 +3825,12 @@ handle_client_send (void *cls, const struct OutboundMessage *obm) GNUNET_free_non_null (dvb); dvb = NULL; pm->dvh = dvh; + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Sending %u bytes as <%llu> to %s using %s\n", + bytes_msg, + pm->logging_uuid, + GNUNET_i2s (&obm->peer), + (NULL == target) ? "distance vector path" : "direct queue"); if (NULL != dvh) { GNUNET_CONTAINER_MDLL_insert (dvh, @@ -4140,11 +4156,13 @@ queue_send_msg (struct Queue *queue, struct GNUNET_TRANSPORT_SendMessageTo *smt; struct GNUNET_MQ_Envelope *env; - GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Queueing %u bytes of payload for transmission on queue %llu to %s\n", - (unsigned int) payload_size, - (unsigned long long) queue->qid, - GNUNET_i2s (&queue->neighbour->pid)); + GNUNET_log ( + GNUNET_ERROR_TYPE_DEBUG, + "Queueing %u bytes of payload for transmission <%llu> on queue %llu to %s\n", + (unsigned int) payload_size, + pm->logging_uuid, + (unsigned long long) queue->qid, + GNUNET_i2s (&queue->neighbour->pid)); env = GNUNET_MQ_msg_extra (smt, payload_size, GNUNET_MESSAGE_TYPE_TRANSPORT_SEND_MSG); @@ -7566,9 +7584,6 @@ set_pending_message_uuid (struct PendingMessage *pm) } -// FIXME: add logging logic from here! - - /** * Setup data structure waiting for acknowledgements. * @@ -7604,6 +7619,10 @@ prepare_pending_acknowledgement (struct Queue *queue, GNUNET_CONTAINER_MDLL_insert (dvh, dvh->pa_head, dvh->pa_tail, pa); pa->transmission_time = GNUNET_TIME_absolute_get (); pa->message_size = pm->bytes_msg; + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Waiting for ACKnowledgment `%s' for <%llu>\n", + GNUNET_sh2s (&pa->ack_uuid.value), + pm->logging_uuid); return pa; } @@ -7628,11 +7647,17 @@ fragment_message (struct Queue *queue, struct PendingMessage *ff; uint16_t mtu; - pa = prepare_pending_acknowledgement (queue, dvh, pm); mtu = (0 == queue->mtu) ? UINT16_MAX - sizeof (struct GNUNET_TRANSPORT_SendMessageTo) : queue->mtu; set_pending_message_uuid (pm); + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Fragmenting message %llu <%llu> to %s for MTU %u\n", + (unsigned long long) pm->msg_uuid.uuid, + pm->logging_uuid, + GNUNET_i2s (&pm->target->pid), + (unsigned int) mtu); + pa = prepare_pending_acknowledgement (queue, dvh, pm); /* This invariant is established in #handle_add_queue_message() */ GNUNET_assert (mtu > sizeof (struct TransportFragmentBoxMessage)); @@ -7676,6 +7701,7 @@ fragment_message (struct Queue *queue, frag = GNUNET_malloc (sizeof (struct PendingMessage) + sizeof (struct TransportFragmentBoxMessage) + fragsize); + frag->logging_uuid = logging_uuid_gen++; frag->target = pm->target; frag->frag_parent = ff; frag->timeout = pm->timeout; @@ -7744,10 +7770,16 @@ reliability_box_message (struct Queue *queue, client_send_response (pm); return NULL; } + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Preparing reliability box for message <%llu> to %s on queue %s\n", + pm->logging_uuid, + GNUNET_i2s (&pm->target->pid), + queue->address); pa = prepare_pending_acknowledgement (queue, dvh, pm); bpm = GNUNET_malloc (sizeof (struct PendingMessage) + sizeof (rbox) + pm->bytes_msg); + bpm->logging_uuid = logging_uuid_gen++; bpm->target = pm->target; bpm->frag_parent = pm; GNUNET_CONTAINER_MDLL_insert (frag, pm->head_frag, pm->tail_frag, bpm); @@ -7783,6 +7815,11 @@ update_pm_next_attempt (struct PendingMessage *pm, struct Neighbour *neighbour = pm->target; pm->next_attempt = next_attempt; + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Next attempt for message <%llu> set to %s\n", + pm->logging_uuid, + GNUNET_STRINGS_absolute_time_to_string (next_attempt)); + if (NULL == pm->frag_parent) { struct PendingMessage *pos; @@ -7843,17 +7880,32 @@ transmit_on_queue (void *cls) if (NULL == (pm = n->pending_msg_head)) { /* no message pending, nothing to do here! */ + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "No messages waiting on queue %s to %s, going to sleep\n", + queue->address, + GNUNET_i2s (&n->pid)); return; } if (NULL != pm->qe) { /* message still pending with communciator! - LOGGING-FIXME: Use stats? logging? Should this not be rare? */ + LOGGING-FIXME: Use stats? Should this not be rare? */ + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Waiting on communicator for queue %s to %s, going to sleep\n", + queue->address, + GNUNET_i2s (&n->pid)); return; } schedule_transmit_on_queue (queue, GNUNET_YES); if (NULL != queue->transmit_task) + { + GNUNET_log ( + GNUNET_ERROR_TYPE_DEBUG, + "Scheduled transmission on queue %s to %s for later, going to sleep\n", + queue->address, + GNUNET_i2s (&n->pid)); return; /* do it later */ + } overhead = 0; if (GNUNET_TRANSPORT_CC_RELIABLE != queue->tc->details.communicator.cc) overhead += sizeof (struct TransportReliabilityBoxMessage); @@ -7868,6 +7920,11 @@ transmit_on_queue (void *cls) if (NULL == s) { /* Fragmentation failed, try next message... */ + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Fragmentation failed queue %s to %s for <%llu>, trying again\n", + queue->address, + GNUNET_i2s (&n->pid), + pm->logging_uuid); schedule_transmit_on_queue (queue, GNUNET_NO); return; } @@ -7877,11 +7934,22 @@ transmit_on_queue (void *cls) if (NULL == s) { /* Reliability boxing failed, try next message... */ + GNUNET_log ( + GNUNET_ERROR_TYPE_DEBUG, + "Reliability boxing failed queue %s to %s for <%llu>, trying again\n", + queue->address, + GNUNET_i2s (&n->pid), + pm->logging_uuid); schedule_transmit_on_queue (queue, GNUNET_NO); return; } /* Pass 's' for transission to the communicator */ + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Passing message <%llu> to queue %s for peer %s\n", + s->logging_uuid, + queue->address, + GNUNET_i2s (&n->pid)); queue_send_msg (queue, s, &s[1], s->bytes_msg); // FIXME: do something similar to the logic below // in defragmentation / reliability ACK handling! @@ -7971,6 +8039,10 @@ handle_del_queue_message (void *cls, if ((dqm->qid != queue->qid) || (0 != GNUNET_memcmp (&dqm->receiver, &neighbour->pid))) continue; + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Dropped queue %s to peer %s\n", + queue->address, + GNUNET_i2s (&neighbour->pid)); free_queue (queue); GNUNET_SERVICE_client_continue (tc->client); return; @@ -8030,6 +8102,12 @@ handle_send_message_ack (void *cls, qe); qe->queue->queue_length--; tc->details.communicator.total_queue_length--; + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Received ACK on queue %s to peer %s (new length: %u/%u)\n", + qe->queue->address, + GNUNET_i2s (&qe->queue->neighbour->pid), + qe->queue->queue_length, + tc->details.communicator.total_queue_length); GNUNET_SERVICE_client_continue (tc->client); /* if applicable, resume transmissions that waited on ACK */ @@ -8078,7 +8156,8 @@ handle_send_message_ack (void *cls, { GNUNET_log ( GNUNET_ERROR_TYPE_INFO, - "Queue failed in transmission, will try retransmission immediately\n"); + "Queue failed in transmission <%llu>, will try retransmission immediately\n", + pm->logging_uuid); update_pm_next_attempt (pm, GNUNET_TIME_UNIT_ZERO_ABS); } } @@ -8200,6 +8279,10 @@ suggest_to_connect (const struct GNUNET_PeerIdentity *pid, const char *address) "# Suggestions ignored due to missing communicator", 1, GNUNET_NO); + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Cannot connect to %s at `%s', no matching communicator present\n", + GNUNET_i2s (pid), + address); return; } /* forward suggestion for queue creation to communicator */ @@ -8237,6 +8320,10 @@ validation_transmit_on_queue (struct Queue *q, struct ValidationState *vs) tvc.reserved = htonl (0); tvc.challenge = vs->challenge; tvc.sender_time = GNUNET_TIME_absolute_hton (vs->last_challenge_use); + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Sending address validation challenge %s to %s\n", + GNUNET_sh2s (&tvc.challenge.value), + GNUNET_i2s (&q->neighbour->pid)); queue_send_msg (q, NULL, &tvc, sizeof (tvc)); } @@ -8264,8 +8351,12 @@ validation_start_cb (void *cls) vs = GNUNET_CONTAINER_heap_peek (validation_heap); } if (NULL == vs) + { + GNUNET_log (GNUNET_ERROR_TYPE_INFO, + "Address validation task not scheduled anymore, nothing to do\n"); return; /* woopsie, no more addresses known, should only happen if we're really a lonely peer */ + } q = find_queue (&vs->pid, vs->address); if (NULL == q) { @@ -8278,6 +8369,10 @@ validation_start_cb (void *cls) vs->challenge_backoff = GNUNET_TIME_randomized_backoff (vs->challenge_backoff, MAX_VALIDATION_CHALLENGE_FREQ); + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Address validation task will run again in %s\n", + GNUNET_STRINGS_relative_time_to_string (vs->challenge_backoff, + GNUNET_YES)); update_next_challenge_time (vs, GNUNET_TIME_relative_to_absolute ( vs->challenge_backoff)); @@ -8385,6 +8480,10 @@ start_dv_learn (void *cls) /* scale our retries by how far we are above the threshold */ factor = qqc.quality_count / DV_LEARN_QUALITY_THRESHOLD; delay = GNUNET_TIME_relative_multiply (DV_LEARN_BASE_FREQUENCY, factor); + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "At connection quality %u, will launch DV learn in %s\n", + qqc.quality_count, + GNUNET_STRINGS_relative_time_to_string (delay, GNUNET_YES)); dvlearn_task = GNUNET_SCHEDULER_add_delayed (delay, &start_dv_learn, NULL); return; } @@ -8405,6 +8504,9 @@ start_dv_learn (void *cls) GNUNET_CRYPTO_random_block (GNUNET_CRYPTO_QUALITY_NONCE, &lle->challenge, sizeof (lle->challenge)); + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Starting launch DV learn with challenge %s\n", + GNUNET_sh2s (&lle->challenge.value)); GNUNET_CONTAINER_DLL_insert (lle_head, lle_tail, lle); GNUNET_break (GNUNET_YES == GNUNET_CONTAINER_multishortmap_put ( @@ -8568,7 +8670,11 @@ handle_add_queue_message (void *cls, } addr_len = ntohs (aqm->header.size) - sizeof (*aqm); addr = (const char *) &aqm[1]; - + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "New queue %s to %s available with QID %llu\n", + addr, + GNUNET_i2s (&aqm->receiver), + (unsigned long long) aqm->qid); queue = GNUNET_malloc (sizeof (struct Queue) + addr_len); queue->tc = tc; queue->address = (const char *) &queue[1]; @@ -8788,6 +8894,11 @@ start_address_validation (const struct GNUNET_PeerIdentity *pid, &vs->challenge, sizeof (vs->challenge)); vs->address = GNUNET_strdup (address); + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Starting address validation `%s' of peer %s using challenge %s\n", + address, + GNUNET_i2s (pid), + GNUNET_sh2s (&vs->challenge.value)); GNUNET_assert (GNUNET_YES == GNUNET_CONTAINER_multipeermap_put ( validation_map, -- 2.25.1