[GNUnet-SVN] [gnunet] branch master updated: complete TNG logging

[gnunet]

This is an automated email from the git hooks/post-receive script.

grothoff pushed a commit to branch master
in repository gnunet.

The following commit(s) were added to refs/heads/master by this push:
     new da604c171 complete TNG logging
da604c171 is described below

commit da604c171418b64fcd37a46c4526ba97b6ee47dc
Author: Christian Grothoff <address@hidden>
AuthorDate: Sat May 11 15:11:52 2019 +0200

    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,

-- 
To stop receiving notification emails like this one, please contact
address@hidden