adding DEBUG logic for #3863

5 files changed, 143 insertions, 57 deletions

diff --git a/src/core/gnunet-service-core.h b/src/core/gnunet-service-core.h
index a95dc561f..15e995921 100644
--- a/src/core/gnunet-service-core.h
+++ b/src/core/gnunet-service-core.h
@@ -67,6 +67,11 @@ struct GSC_ClientActiveRequest
   struct GNUNET_PeerIdentity target;
 
   /**
+   * At what time did we first see this request?
+   */
+  struct GNUNET_TIME_Absolute received_time;
+
+  /**
    * By what time would the client want to see this message out?
    */
   struct GNUNET_TIME_Absolute deadline;
diff --git a/src/core/gnunet-service-core_clients.c b/src/core/gnunet-service-core_clients.c
index e90d91529..57a5d5826 100644
--- a/src/core/gnunet-service-core_clients.c
+++ b/src/core/gnunet-service-core_clients.c
@@ -29,6 +29,7 @@
 #include "gnunet_transport_service.h"
 #include "gnunet-service-core.h"
 #include "gnunet-service-core_clients.h"
+#include "gnunet-service-core_neighbours.h"
 #include "gnunet-service-core_sessions.h"
 #include "gnunet-service-core_typemap.h"
 #include "core.h"
@@ -149,7 +150,8 @@ find_client (struct GNUNET_SERVER_Client *client)
  */
 static void
 send_to_client (struct GSC_Client *client,
-                const struct GNUNET_MessageHeader *msg, int can_drop)
+                const struct GNUNET_MessageHeader *msg,
+                int can_drop)
 {
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
               "Preparing to send %u bytes of message of type %u to client.\n",
@@ -219,8 +221,10 @@ type_match (uint16_t type, struct GSC_Client *c)
  */
 static void
 send_to_all_clients (const struct GNUNET_PeerIdentity *partner,
-                     const struct GNUNET_MessageHeader *msg, int can_drop,
-                     uint32_t options, uint16_t type)
+                     const struct GNUNET_MessageHeader *msg,
+                     int can_drop,
+                     uint32_t options,
+                     uint16_t type)
 {
   struct GSC_Client *c;
   int tm;
@@ -399,6 +403,7 @@ handle_client_send_request (void *cls,
     GSC_SESSIONS_dequeue_request (car);
   }
   car->target = req->peer;
+  car->received_time = GNUNET_TIME_absolute_get ();
   car->deadline = GNUNET_TIME_absolute_ntoh (req->deadline);
   car->priority = (enum GNUNET_CORE_Priority) ntohl (req->priority);
   car->msize = ntohs (req->size);
@@ -441,7 +446,7 @@ struct TokenizerContext
 
 
 /**
- * Handle CORE_SEND request.
+ * Handle #GNUNET_MESSAGE_TYPE_CORE_CORE_SEND request.
  *
  * @param cls unused
  * @param client the client issuing the request
@@ -456,6 +461,7 @@ handle_client_send (void *cls,
   struct GSC_Client *c;
   struct TokenizerContext tc;
   uint16_t msize;
+  struct GNUNET_TIME_Relative delay;
 
   msize = ntohs (message->size);
   if (msize <
@@ -476,8 +482,9 @@ handle_client_send (void *cls,
     GNUNET_SERVER_receive_done (client, GNUNET_SYSERR);
     return;
   }
-  tc.car =
-      GNUNET_CONTAINER_multipeermap_get (c->requests, &sm->peer);
+  tc.car
+    = GNUNET_CONTAINER_multipeermap_get (c->requests,
+                                         &sm->peer);
   if (NULL == tc.car)
   {
     /* Must have been that we first approved the request, then got disconnected
@@ -489,28 +496,49 @@ handle_client_send (void *cls,
                               gettext_noop
                               ("# messages discarded (session disconnected)"),
                               1, GNUNET_NO);
-    GNUNET_SERVER_receive_done (client, GNUNET_OK);
+    GNUNET_SERVER_receive_done (client,
+                                GNUNET_OK);
     return;
   }
+  delay = GNUNET_TIME_absolute_get_duration (tc.car->received_time);
+  tc.cork = ntohl (sm->cork);
+  tc.priority = (enum GNUNET_CORE_Priority) ntohl (sm->priority);
+  if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us)
+    GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+                "Client waited %s for transmission of %u bytes to `%s'%s, CORE queue is %u entries\n",
+                GNUNET_STRINGS_relative_time_to_string (delay,
+                                                        GNUNET_YES),
+                msize,
+                GNUNET_i2s (&sm->peer),
+                tc.cork ? "" : " (corked)",
+                GSC_NEIGHBOURS_get_queue_size (&sm->peer));
+  else
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Client waited %s for transmission of %u bytes to `%s'%s, CORE queue is %u entries\n",
+                GNUNET_STRINGS_relative_time_to_string (delay,
+                                                        GNUNET_YES),
+                msize,
+                GNUNET_i2s (&sm->peer),
+                tc.cork ? "" : " (corked)",
+                GSC_NEIGHBOURS_get_queue_size (&sm->peer));
+
   GNUNET_assert (GNUNET_YES ==
                  GNUNET_CONTAINER_multipeermap_remove (c->requests,
                                                        &sm->peer,
                                                        tc.car));
-  tc.cork = ntohl (sm->cork);
-  tc.priority = (enum GNUNET_CORE_Priority) ntohl (sm->priority);
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Client asked for transmission of %u bytes to `%s' %s\n",
-              msize,
-              GNUNET_i2s (&sm->peer), tc.cork ? "now" : "");
   GNUNET_SERVER_mst_receive (client_mst, &tc,
-                             (const char *) &sm[1], msize,
-                             GNUNET_YES, GNUNET_NO);
+                             (const char *) &sm[1],
+                             msize,
+                             GNUNET_YES,
+                             GNUNET_NO);
   if (0 !=
-      memcmp (&tc.car->target, &GSC_my_identity,
+      memcmp (&tc.car->target,
+              &GSC_my_identity,
               sizeof (struct GNUNET_PeerIdentity)))
     GSC_SESSIONS_dequeue_request (tc.car);
   GNUNET_free (tc.car);
-  GNUNET_SERVER_receive_done (client, GNUNET_OK);
+  GNUNET_SERVER_receive_done (client,
+                              GNUNET_OK);
 }
 
 
@@ -525,7 +553,8 @@ handle_client_send (void *cls,
  * @param message the actual message
  */
 static int
-client_tokenizer_callback (void *cls, void *client,
+client_tokenizer_callback (void *cls,
+                           void *client,
                            const struct GNUNET_MessageHeader *message)
 {
   struct TokenizerContext *tc = client;
@@ -535,9 +564,13 @@ client_tokenizer_callback (void *cls, void *client,
   GNUNET_snprintf (buf, sizeof (buf),
                    gettext_noop ("# bytes of messages of type %u received"),
                    (unsigned int) ntohs (message->type));
-  GNUNET_STATISTICS_update (GSC_stats, buf, ntohs (message->size), GNUNET_NO);
+  GNUNET_STATISTICS_update (GSC_stats,
+                            buf,
+                            ntohs (message->size),
+                            GNUNET_NO);
   if (0 ==
-      memcmp (&car->target, &GSC_my_identity,
+      memcmp (&car->target,
+              &GSC_my_identity,
               sizeof (struct GNUNET_PeerIdentity)))
   {
     GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
@@ -618,7 +651,8 @@ handle_client_disconnect (void *cls,
   if (NULL == client)
     return;
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Client %p has disconnected from core service.\n", client);
+              "Client %p has disconnected from core service.\n",
+              client);
   c = find_client (client);
   if (c == NULL)
     return;                     /* client never sent INIT */
@@ -654,6 +688,8 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car)
 {
   struct GSC_Client *c;
   struct SendMessageReady smr;
+  struct GNUNET_TIME_Relative delay;
+  struct GNUNET_TIME_Relative left;
 
   c = car->client_handle;
   if (GNUNET_YES !=
@@ -662,12 +698,26 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car)
   {
     /* connection has gone down since, drop request */
     GNUNET_assert (0 !=
-                   memcmp (&car->target, &GSC_my_identity,
+                   memcmp (&car->target,
+                           &GSC_my_identity,
                            sizeof (struct GNUNET_PeerIdentity)));
     GSC_SESSIONS_dequeue_request (car);
     GSC_CLIENTS_reject_request (car);
     return;
   }
+  delay = GNUNET_TIME_absolute_get_duration (car->received_time);
+  left = GNUNET_TIME_absolute_get_remaining (car->deadline);
+  if ( (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us) ||
+       (0 == left.rel_value_us) )
+    GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+                "Client waited %s for permission to transmit to `%s'%s (priority %u)\n",
+                GNUNET_STRINGS_relative_time_to_string (delay,
+                                                        GNUNET_YES),
+                GNUNET_i2s (&car->target),
+                (0 == left.rel_value_us)
+                ? " (past deadline)"
+                : "",
+                car->priority);
   smr.header.size = htons (sizeof (struct SendMessageReady));
   smr.header.type = htons (GNUNET_MESSAGE_TYPE_CORE_SEND_READY);
   smr.size = htons (car->msize);
diff --git a/src/core/gnunet-service-core_neighbours.c b/src/core/gnunet-service-core_neighbours.c
index 5e5ed4db3..f89206dfe 100644
--- a/src/core/gnunet-service-core_neighbours.c
+++ b/src/core/gnunet-service-core_neighbours.c
@@ -57,9 +57,14 @@ struct NeighbourMessageEntry
   struct GNUNET_TIME_Absolute deadline;
 
   /**
-   * How long is the message? (number of bytes following the "struct
-   * MessageEntry", but not including the size of "struct
-   * MessageEntry" itself!)
+   * What time did we submit the request?
+   */
+  struct GNUNET_TIME_Absolute submission_time;
+
+  /**
+   * How long is the message? (number of bytes following the `struct
+   * MessageEntry`, but not including the size of `struct
+   * MessageEntry` itself!)
    */
   size_t size;
 
@@ -157,7 +162,7 @@ free_neighbour (struct Neighbour *n)
   struct NeighbourMessageEntry *m;
 
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Destroying neighbour entry for peer `%4s'\n",
+              "Destroying neighbour entry for peer `%s'\n",
               GNUNET_i2s (&n->peer));
   while (NULL != (m = n->message_head))
   {
@@ -227,6 +232,7 @@ transmit_ready (void *cls,
   struct NeighbourMessageEntry *m;
   size_t ret;
   char *cbuf;
+  struct GNUNET_TIME_Relative delay;
 
   n->th = NULL;
   m = n->message_head;
@@ -250,18 +256,31 @@ transmit_ready (void *cls,
     process_queue (n);
     return 0;
   }
+  delay = GNUNET_TIME_absolute_get_duration (m->submission_time);
   cbuf = buf;
   GNUNET_assert (size >= m->size);
   memcpy (cbuf,
           &m[1],
           m->size);
   ret = m->size;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Copied message of type %u and size %u into transport buffer for `%4s'\n",
+  if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us)
+  GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+              "Copied message of type %u and size %u into transport buffer for `%s' with delay of %s\n",
               (unsigned int)
               ntohs (((struct GNUNET_MessageHeader *) &m[1])->type),
               (unsigned int) ret,
-              GNUNET_i2s (&n->peer));
+              GNUNET_i2s (&n->peer),
+              GNUNET_STRINGS_relative_time_to_string (delay,
+                                                      GNUNET_YES));
+  else
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Copied message of type %u and size %u into transport buffer for `%s' with delay of %s\n",
+                (unsigned int)
+                ntohs (((struct GNUNET_MessageHeader *) &m[1])->type),
+                (unsigned int) ret,
+                GNUNET_i2s (&n->peer),
+                GNUNET_STRINGS_relative_time_to_string (delay,
+                                                        GNUNET_YES));
   GNUNET_free (m);
   n->has_excess_bandwidth = GNUNET_NO;
   process_queue (n);
@@ -295,11 +314,12 @@ process_queue (struct Neighbour *n)
     return;
   }
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Asking transport for transmission of %u bytes to `%4s' in next %s\n",
+              "Asking transport for transmission of %u bytes to `%s' in next %s\n",
               (unsigned int) m->size,
               GNUNET_i2s (&n->peer),
               GNUNET_STRINGS_relative_time_to_string (GNUNET_TIME_absolute_get_remaining (m->deadline),
                                                       GNUNET_NO));
+  m->submission_time = GNUNET_TIME_absolute_get ();
   n->th
     = GNUNET_TRANSPORT_notify_transmit_ready (transport,
                                               &n->peer,
diff --git a/src/core/gnunet-service-core_sessions.c b/src/core/gnunet-service-core_sessions.c
index 8706c873e..bbabf8866 100644
--- a/src/core/gnunet-service-core_sessions.c
+++ b/src/core/gnunet-service-core_sessions.c
@@ -125,12 +125,12 @@ struct Session
   /**
    * Task to transmit corked messages with a delay.
    */
-  struct GNUNET_SCHEDULER_Task * cork_task;
+  struct GNUNET_SCHEDULER_Task *cork_task;
 
   /**
    * Task to transmit our type map.
    */
-  struct GNUNET_SCHEDULER_Task * typemap_task;
+  struct GNUNET_SCHEDULER_Task *typemap_task;
 
   /**
    * Retransmission delay we currently use for the typemap
diff --git a/src/transport/transport_api.c b/src/transport/transport_api.c
index 8ebf82b8a..312762ba4 100644
--- a/src/transport/transport_api.c
+++ b/src/transport/transport_api.c
@@ -84,7 +84,7 @@ struct GNUNET_TRANSPORT_TransmitHandle
    * Task to trigger request timeout if the request is stalled due to
    * congestion.
    */
-  struct GNUNET_SCHEDULER_Task * timeout_task;
+  struct GNUNET_SCHEDULER_Task *timeout_task;
 
   /**
    * How many bytes is our notify callback waiting for?
@@ -171,7 +171,7 @@ struct GNUNET_TRANSPORT_GetHelloHandle
   /**
    * Task for calling the HelloUpdateCallback when we already have a HELLO
    */
-  struct GNUNET_SCHEDULER_Task * notify_task;
+  struct GNUNET_SCHEDULER_Task *notify_task;
 
   /**
    * Closure for @e rec.
@@ -422,7 +422,7 @@ struct GNUNET_TRANSPORT_Handle
    * Heap sorting peers with pending messages by the timestamps that
    * specify when we could next send a message to the respective peer.
    * Excludes control messages (which can always go out immediately).
-   * Maps time stamps to 'struct Neighbour' entries.
+   * Maps time stamps to `struct Neighbour` entries.
    */
   struct GNUNET_CONTAINER_Heap *ready_heap;
 
@@ -439,10 +439,10 @@ struct GNUNET_TRANSPORT_Handle
   /**
    * ID of the task trying to trigger transmission for a peer while
    * maintaining bandwidth quotas.  In use if there are no control
-   * messages and the smallest entry in the 'ready_heap' has a time
+   * messages and the smallest entry in the @e ready_heap has a time
    * stamp in the future.
    */
-  struct GNUNET_SCHEDULER_Task * quota_task;
+  struct GNUNET_SCHEDULER_Task *quota_task;
 
   /**
    * Delay until we try to reconnect.
@@ -515,7 +515,7 @@ outbound_bw_tracker_update (void *cls)
   delay = GNUNET_BANDWIDTH_tracker_get_delay (&n->out_tracker,
                                               n->th->notify_size + n->traffic_overhead);
   LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "New outbound delay %llu us\n",
+       "New outbound delay %s us\n",
        GNUNET_STRINGS_relative_time_to_string (delay,
                                                GNUNET_NO));
   GNUNET_CONTAINER_heap_update_cost (n->h->ready_heap,
@@ -554,7 +554,7 @@ neighbour_add (struct GNUNET_TRANSPORT_Handle *h,
   struct Neighbour *n;
 
   LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Creating entry for neighbour `%4s'.\n",
+       "Creating entry for neighbour `%s'.\n",
        GNUNET_i2s (pid));
   n = GNUNET_new (struct Neighbour);
   n->id = *pid;
@@ -664,7 +664,7 @@ demultiplexer (void *cls,
       break;
     }
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Receiving (my own) HELLO message (%u bytes), I am `%4s'.\n",
+         "Receiving (my own) HELLO message (%u bytes), I am `%s'.\n",
          (unsigned int) size,
          GNUNET_i2s (&me));
     GNUNET_free_non_null (h->my_hello);
@@ -698,7 +698,7 @@ demultiplexer (void *cls,
       break;
     }
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Receiving CONNECT message for `%4s'.\n",
+         "Receiving CONNECT message for `%s'.\n",
          GNUNET_i2s (&cim->id));
     n = neighbour_find (h, &cim->id);
     if (NULL != n)
@@ -709,7 +709,7 @@ demultiplexer (void *cls,
     n = neighbour_add (h,
                        &cim->id);
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Receiving CONNECT message for `%4s' with quota %u\n",
+         "Receiving CONNECT message for `%s' with quota %u\n",
          GNUNET_i2s (&cim->id),
          ntohl (cim->quota_out.value__));
     GNUNET_BANDWIDTH_tracker_update_quota (&n->out_tracker,
@@ -727,7 +727,7 @@ demultiplexer (void *cls,
     dim = (const struct DisconnectInfoMessage *) msg;
     GNUNET_break (ntohl (dim->reserved) == 0);
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Receiving DISCONNECT message for `%4s'.\n",
+         "Receiving DISCONNECT message for `%s'.\n",
          GNUNET_i2s (&dim->peer));
     n = neighbour_find (h, &dim->peer);
     if (NULL == n)
@@ -792,7 +792,7 @@ demultiplexer (void *cls,
       break;
     }
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Received message of type %u from `%4s'.\n",
+         "Received message of type %u from `%s'.\n",
          ntohs (imm->type), GNUNET_i2s (&im->peer));
     n = neighbour_find (h, &im->peer);
     if (NULL == n)
@@ -816,7 +816,7 @@ demultiplexer (void *cls,
     if (NULL == n)
       break;
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Receiving SET_QUOTA message for `%4s' with quota %u\n",
+         "Receiving SET_QUOTA message for `%s' with quota %u\n",
          GNUNET_i2s (&qm->peer),
          ntohl (qm->quota.value__));
     GNUNET_BANDWIDTH_tracker_update_quota (&n->out_tracker,
@@ -1262,7 +1262,7 @@ send_try_connect (void *cls,
   if (NULL == buf)
   {
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Discarding  `%s' request to `%4s' due to error in transport service connection.\n",
+         "Discarding  `%s' request to `%s' due to error in transport service connection.\n",
          "REQUEST_CONNECT",
          GNUNET_i2s (&tch->pid));
     if (NULL != tch->cb)
@@ -1272,7 +1272,7 @@ send_try_connect (void *cls,
     return 0;
   }
   LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Transmitting `%s' request with respect to `%4s'.\n",
+       "Transmitting `%s' request with respect to `%s'.\n",
        "REQUEST_CONNECT",
        GNUNET_i2s (&tch->pid));
   GNUNET_assert (size >= sizeof (struct TransportRequestConnectMessage));
@@ -1367,7 +1367,7 @@ send_try_disconnect (void *cls,
   if (NULL == buf)
   {
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Discarding  `%s' request to `%4s' due to error in transport service connection.\n",
+         "Discarding  `%s' request to `%s' due to error in transport service connection.\n",
          "REQUEST_DISCONNECT",
          GNUNET_i2s (&tdh->pid));
     if (NULL != tdh->cb)
@@ -1377,7 +1377,7 @@ send_try_disconnect (void *cls,
     return 0;
   }
   LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Transmitting `%s' request with respect to `%4s'.\n",
+       "Transmitting `%s' request with respect to `%s'.\n",
        "REQUEST_DISCONNECT",
        GNUNET_i2s (&tdh->pid));
   GNUNET_assert (size >= sizeof (struct TransportRequestDisconnectMessage));
@@ -1620,7 +1620,7 @@ GNUNET_TRANSPORT_offer_hello (struct GNUNET_TRANSPORT_Handle *handle,
   msg = GNUNET_malloc (size);
   memcpy (msg, hello, size);
   LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Offering `%s' message of `%4s' to transport for validation.\n", "HELLO",
+       "Offering HELLO message of `%s' to transport for validation.\n",
        GNUNET_i2s (&peer));
 
   ohh = GNUNET_new (struct GNUNET_TRANSPORT_OfferHelloHandle);
@@ -1638,7 +1638,7 @@ GNUNET_TRANSPORT_offer_hello (struct GNUNET_TRANSPORT_Handle *handle,
 /**
  * Cancel the request to transport to offer the HELLO message
  *
- * @param ohh the GNUNET_TRANSPORT_OfferHelloHandle to cancel
+ * @param ohh the handle for the operation to cancel
  */
 void
 GNUNET_TRANSPORT_offer_hello_cancel (struct GNUNET_TRANSPORT_OfferHelloHandle *ohh)
@@ -1716,7 +1716,9 @@ GNUNET_TRANSPORT_get_hello (struct GNUNET_TRANSPORT_Handle *handle,
   hwl->rec = rec;
   hwl->rec_cls = rec_cls;
   hwl->handle = handle;
-  GNUNET_CONTAINER_DLL_insert (handle->hwl_head, handle->hwl_tail, hwl);
+  GNUNET_CONTAINER_DLL_insert (handle->hwl_head,
+                               handle->hwl_tail,
+                               hwl);
   if (NULL != handle->my_hello)
     hwl->notify_task = GNUNET_SCHEDULER_add_now (&call_hello_update_cb_async,
                                                  hwl);
@@ -1928,11 +1930,20 @@ GNUNET_TRANSPORT_notify_transmit_ready (struct GNUNET_TRANSPORT_Handle *handle,
   n->traffic_overhead = 0;
   if (delay.rel_value_us > timeout.rel_value_us)
     delay.rel_value_us = 0;        /* notify immediately (with failure) */
-  LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Bandwidth tracker allows next transmission to peer %s in %s\n",
-       GNUNET_i2s (target),
-       GNUNET_STRINGS_relative_time_to_string (delay,
-                                               GNUNET_YES));
+  if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us)
+    LOG (GNUNET_ERROR_TYPE_WARNING,
+         "At bandwidth %u byte/s next transmission to %s in %s\n",
+         (unsigned int) n->out_tracker.available_bytes_per_s__,
+         GNUNET_i2s (target),
+         GNUNET_STRINGS_relative_time_to_string (delay,
+                                                 GNUNET_YES));
+  else
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "At bandwidth %u byte/s next transmission to %s in %s\n",
+         (unsigned int) n->out_tracker.available_bytes_per_s__,
+         GNUNET_i2s (target),
+         GNUNET_STRINGS_relative_time_to_string (delay,
+                                                 GNUNET_YES));
   n->hn = GNUNET_CONTAINER_heap_insert (handle->ready_heap,
                                         n,
                                         delay.rel_value_us);