redefining core message timeout semantics and core-core-API messaging to address (hypothetical?) stalls which may explain #3863. This kind-of breaks the API in that the timeout now has a different semantic -- it's an advisory as to when the app would like the message transmitted, the transmission will no longer actually time out. However, that was the documented semantics before, just not the actual behavior. Most applications didn't rely on it, and tests still pass, so I didn't break too much...

5 files changed, 143 insertions, 195 deletions

diff --git a/src/core/core_api.c b/src/core/core_api.c
index 2d7d71c48..7338672d6 100644
--- a/src/core/core_api.c
+++ b/src/core/core_api.c
@@ -63,9 +63,15 @@ struct GNUNET_CORE_TransmitHandle
   void *get_message_cls;
 
   /**
-   * Timeout for this handle.
+   * Deadline for the transmission (the request does not get cancelled
+   * at this time, this is merely how soon the application wants this out).
    */
-  struct GNUNET_TIME_Absolute timeout;
+  struct GNUNET_TIME_Absolute deadline;
+
+  /**
+   * When did this request get queued?
+   */
+  struct GNUNET_TIME_Absolute request_time;
 
   /**
    * How important is this message?
@@ -127,15 +133,9 @@ struct PeerRecord
   struct GNUNET_PeerIdentity peer;
 
   /**
-   * ID of timeout task for the 'pending_head' handle
-   * which is the one with the smallest timeout.
-   */
-  struct GNUNET_SCHEDULER_Task * timeout_task;
-
-  /**
-   * ID of task to run 'next_request_transmission'.
+   * ID of task to run #next_request_transmission().
    */
-  struct GNUNET_SCHEDULER_Task * ntr_task;
+  struct GNUNET_SCHEDULER_Task *ntr_task;
 
   /**
    * SendMessageRequest ID generator for this peer.
@@ -369,11 +369,6 @@ disconnect_and_free_peer_entry (void *cls,
   struct GNUNET_CORE_TransmitHandle *th;
   struct PeerRecord *pr = value;
 
-  if (NULL != pr->timeout_task)
-  {
-    GNUNET_SCHEDULER_cancel (pr->timeout_task);
-    pr->timeout_task = NULL;
-  }
   if (NULL != pr->ntr_task)
   {
     GNUNET_SCHEDULER_cancel (pr->ntr_task);
@@ -401,7 +396,6 @@ disconnect_and_free_peer_entry (void *cls,
   GNUNET_assert (GNUNET_YES ==
                  GNUNET_CONTAINER_multipeermap_remove (h->peers, key, pr));
   GNUNET_assert (pr->ch == h);
-  GNUNET_assert (NULL == pr->timeout_task);
   GNUNET_assert (NULL == pr->ntr_task);
   GNUNET_free (pr);
   return GNUNET_YES;
@@ -471,18 +465,6 @@ trigger_next_request (struct GNUNET_CORE_Handle *h,
 
 
 /**
- * The given request hit its timeout.  Remove from the
- * doubly-linked list and call the respective continuation.
- *
- * @param cls the transmit handle of the request that timed out
- * @param tc context, can be NULL (!)
- */
-static void
-transmission_timeout (void *cls,
-                      const struct GNUNET_SCHEDULER_TaskContext *tc);
-
-
-/**
  * Send a control message to the peer asking for transmission
  * of the message in the given peer record.
  *
@@ -496,25 +478,16 @@ request_next_transmission (struct PeerRecord *pr)
   struct SendMessageRequest *smr;
   struct GNUNET_CORE_TransmitHandle *th;
 
-  if (pr->timeout_task != NULL)
-  {
-    GNUNET_SCHEDULER_cancel (pr->timeout_task);
-    pr->timeout_task = NULL;
-  }
   th = &pr->th;
   if (NULL == th->peer)
   {
     trigger_next_request (h, GNUNET_NO);
     return;
   }
-  if (th->cm != NULL)
+  if (NULL != th->cm)
     return;                     /* already done */
-  GNUNET_assert (pr->prev == NULL);
-  GNUNET_assert (pr->next == NULL);
-  pr->timeout_task
-    = GNUNET_SCHEDULER_add_delayed (GNUNET_TIME_absolute_get_remaining (th->timeout),
-                                    &transmission_timeout,
-                                    pr);
+  GNUNET_assert (NULL == pr->prev);
+  GNUNET_assert (NULL == pr->next);
   cm = GNUNET_malloc (sizeof (struct ControlMessage) +
                       sizeof (struct SendMessageRequest));
   th->cm = cm;
@@ -523,7 +496,7 @@ request_next_transmission (struct PeerRecord *pr)
   smr->header.type = htons (GNUNET_MESSAGE_TYPE_CORE_SEND_REQUEST);
   smr->header.size = htons (sizeof (struct SendMessageRequest));
   smr->priority = htonl ((uint32_t) th->priority);
-  smr->deadline = GNUNET_TIME_absolute_hton (th->timeout);
+  smr->deadline = GNUNET_TIME_absolute_hton (th->deadline);
   smr->peer = pr->peer;
   smr->reserved = htonl (0);
   smr->size = htons (th->msize);
@@ -538,56 +511,6 @@ request_next_transmission (struct PeerRecord *pr)
 
 
 /**
- * The given request hit its timeout.  Remove from the
- * doubly-linked list and call the respective continuation.
- *
- * @param cls the transmit handle of the request that timed out
- * @param tc context, can be NULL (!)
- */
-static void
-transmission_timeout (void *cls,
-                      const struct GNUNET_SCHEDULER_TaskContext *tc)
-{
-  struct PeerRecord *pr = cls;
-  struct GNUNET_CORE_Handle *h = pr->ch;
-  struct GNUNET_CORE_TransmitHandle *th;
-
-  pr->timeout_task = NULL;
-  if (NULL != pr->ntr_task)
-  {
-    GNUNET_SCHEDULER_cancel (pr->ntr_task);
-    pr->ntr_task = NULL;
-  }
-  th = &pr->th;
-  th->peer = NULL;
-  if ( (NULL != pr->prev) ||
-       (NULL != pr->next) ||
-       (pr == h->ready_peer_head) )
-  {
-    /* the request that was 'approved' by core was
-     * canceled before it could be transmitted; remove
-     * us from the 'ready' list */
-    GNUNET_CONTAINER_DLL_remove (h->ready_peer_head,
-                                 h->ready_peer_tail,
-                                 pr);
-  }
-  if (NULL != th->cm)
-  {
-     /* we're currently in the control queue, remove */
-    GNUNET_CONTAINER_DLL_remove (h->control_pending_head,
-                                 h->control_pending_tail, th->cm);
-    GNUNET_free (th->cm);
-  }
-  LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Signalling timeout of request for transmission to peer `%s' via CORE\n",
-       GNUNET_i2s (&pr->peer));
-  trigger_next_request (h, GNUNET_NO);
-
-  GNUNET_assert (0 == th->get_message (th->get_message_cls, 0, NULL));
-}
-
-
-/**
  * Transmit the next message to the core service.
  *
  * @param cls closure with the `struct GNUNET_CORE_Handle`
@@ -603,6 +526,8 @@ transmit_message (void *cls,
   struct GNUNET_CORE_Handle *h = cls;
   struct ControlMessage *cm;
   struct GNUNET_CORE_TransmitHandle *th;
+  struct GNUNET_TIME_Relative delay;
+  struct GNUNET_TIME_Relative overdue;
   struct PeerRecord *pr;
   struct SendMessage *sm;
   const struct GNUNET_MessageHeader *hdr;
@@ -657,11 +582,6 @@ transmit_message (void *cls,
                                h->ready_peer_tail,
                                pr);
   th->peer = NULL;
-  if (NULL != pr->timeout_task)
-  {
-    GNUNET_SCHEDULER_cancel (pr->timeout_task);
-    pr->timeout_task = NULL;
-  }
   LOG (GNUNET_ERROR_TYPE_DEBUG,
        "Transmitting SEND request to `%s' with %u bytes.\n",
        GNUNET_i2s (&pr->peer),
@@ -669,7 +589,7 @@ transmit_message (void *cls,
   sm = (struct SendMessage *) buf;
   sm->header.type = htons (GNUNET_MESSAGE_TYPE_CORE_SEND);
   sm->priority = htonl ((uint32_t) th->priority);
-  sm->deadline = GNUNET_TIME_absolute_hton (th->timeout);
+  sm->deadline = GNUNET_TIME_absolute_hton (th->deadline);
   sm->peer = pr->peer;
   sm->cork = htonl ((uint32_t) th->cork);
   sm->reserved = htonl (0);
@@ -677,24 +597,43 @@ transmit_message (void *cls,
     th->get_message (th->get_message_cls,
                      size - sizeof (struct SendMessage),
                      &sm[1]);
-
-  LOG (GNUNET_ERROR_TYPE_DEBUG,
-       "Transmitting SEND request to `%s' yielded %u bytes.\n",
-       GNUNET_i2s (&pr->peer),
-       ret);
-  if (0 == ret)
+  delay = GNUNET_TIME_absolute_get_duration (th->request_time);
+  overdue = GNUNET_TIME_absolute_get_duration (th->deadline);
+  if (overdue.rel_value_us > GNUNET_CONSTANTS_LATENCY_WARN.rel_value_us)
+    LOG (GNUNET_ERROR_TYPE_WARNING,
+         "Transmitting overdue %u bytes to `%s' at priority %u with %s delay%s\n",
+         ret,
+         GNUNET_i2s (&pr->peer),
+         (unsigned int) th->priority,
+         GNUNET_STRINGS_relative_time_to_string (delay,
+                                                 GNUNET_YES),
+         (th->cork) ? " (corked)" : "");
+  else
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Transmitting %u bytes to `%s' at priority %u with %s delay%s\n",
+         ret,
+         GNUNET_i2s (&pr->peer),
+         (unsigned int) th->priority,
+         GNUNET_STRINGS_relative_time_to_string (delay,
+                                                 GNUNET_YES),
+         (th->cork) ? " (corked)" : "");
+  if ( (0 == ret) &&
+       (GNUNET_CORE_PRIO_BACKGROUND == th->priority) )
   {
+    /* client decided to send nothing; as the priority was
+       BACKGROUND, we can just not send anything to core.
+       For higher-priority messages, we must give an
+       empty message to CORE so that it knows that this
+       message is no longer pending. */
     LOG (GNUNET_ERROR_TYPE_DEBUG,
          "Size of clients message to peer %s is 0!\n",
          GNUNET_i2s (&pr->peer));
-    /* client decided to send nothing! */
     request_next_transmission (pr);
     return 0;
   }
   LOG (GNUNET_ERROR_TYPE_DEBUG,
        "Produced SEND message to core with %u bytes payload\n",
        (unsigned int) ret);
-  GNUNET_assert (ret >= sizeof (struct GNUNET_MessageHeader));
   if (ret + sizeof (struct SendMessage) >= GNUNET_SERVER_MAX_MESSAGE_SIZE)
   {
     GNUNET_break (0);
@@ -932,7 +871,7 @@ main_notify_handler (void *cls,
     }
     em = (const struct GNUNET_MessageHeader *) &ntm[1];
     LOG (GNUNET_ERROR_TYPE_DEBUG,
-         "Received message of type %u and size %u from peer `%4s'\n",
+         "Received message of type %u and size %u from peer `%s'\n",
          ntohs (em->type), ntohs (em->size), GNUNET_i2s (&ntm->peer));
     if ((GNUNET_NO == h->inbound_hdr_only) &&
         (msize !=
@@ -951,7 +890,7 @@ main_notify_handler (void *cls,
       if ((mh->expected_size != ntohs (em->size)) && (mh->expected_size != 0))
       {
         LOG (GNUNET_ERROR_TYPE_ERROR,
-             "Unexpected message size %u for message of type %u from peer `%4s'\n",
+             "Unexpected message size %u for message of type %u from peer `%s'\n",
              htons (em->size), mh->type, GNUNET_i2s (&ntm->peer));
         GNUNET_break_op (0);
         continue;
@@ -1208,7 +1147,7 @@ GNUNET_CORE_connect (const struct GNUNET_CONFIGURATION_Handle *cfg,
   h->currently_down = GNUNET_YES;
   h->peers = GNUNET_CONTAINER_multipeermap_create (128, GNUNET_NO);
   if (NULL != handlers)
-    while (handlers[h->hcnt].callback != NULL)
+    while (NULL != handlers[h->hcnt].callback)
       h->hcnt++;
   GNUNET_assert (h->hcnt <
                  (GNUNET_SERVER_MAX_MESSAGE_SIZE -
@@ -1259,22 +1198,22 @@ GNUNET_CORE_disconnect (struct GNUNET_CORE_Handle *handle)
   GNUNET_CONTAINER_multipeermap_iterate (handle->peers,
                                          &disconnect_and_free_peer_entry,
                                          handle);
-  if (handle->reconnect_task != NULL)
+  if (NULL != handle->reconnect_task)
   {
     GNUNET_SCHEDULER_cancel (handle->reconnect_task);
     handle->reconnect_task = NULL;
   }
   GNUNET_CONTAINER_multipeermap_destroy (handle->peers);
   handle->peers = NULL;
-  GNUNET_break (handle->ready_peer_head == NULL);
+  GNUNET_break (NULL == handle->ready_peer_head);
   GNUNET_free (handle);
 }
 
 
 /**
- * Task that calls 'request_next_transmission'.
+ * Task that calls #request_next_transmission().
  *
- * @param cls the 'struct PeerRecord *'
+ * @param cls the `struct PeerRecord *`
  * @param tc scheduler context
  */
 static void
@@ -1357,7 +1296,11 @@ GNUNET_CORE_notify_transmit_ready (struct GNUNET_CORE_Handle *handle,
   th->peer = pr;
   th->get_message = notify;
   th->get_message_cls = notify_cls;
-  th->timeout = GNUNET_TIME_relative_to_absolute (maxdelay);
+  th->request_time = GNUNET_TIME_absolute_get ();
+  if (GNUNET_YES == cork)
+    th->deadline = GNUNET_TIME_relative_to_absolute (maxdelay);
+  else
+    th->deadline = th->request_time;
   th->priority = priority;
   th->msize = notify_size;
   th->cork = cork;
@@ -1373,7 +1316,7 @@ GNUNET_CORE_notify_transmit_ready (struct GNUNET_CORE_Handle *handle,
 /**
  * Cancel the specified transmission-ready notification.
  *
- * @param th handle that was returned by "notify_transmit_ready".
+ * @param th handle that was returned by #GNUNET_CORE_notify_transmit_ready().
  */
 void
 GNUNET_CORE_notify_transmit_ready_cancel (struct GNUNET_CORE_TransmitHandle *th)
diff --git a/src/core/gnunet-service-core_clients.c b/src/core/gnunet-service-core_clients.c
index 57a5d5826..3dff68528 100644
--- a/src/core/gnunet-service-core_clients.c
+++ b/src/core/gnunet-service-core_clients.c
@@ -462,10 +462,10 @@ handle_client_send (void *cls,
   struct TokenizerContext tc;
   uint16_t msize;
   struct GNUNET_TIME_Relative delay;
+  struct GNUNET_TIME_Relative overdue;
 
   msize = ntohs (message->size);
-  if (msize <
-      sizeof (struct SendMessage) + sizeof (struct GNUNET_MessageHeader))
+  if (msize < sizeof (struct SendMessage))
   {
     GNUNET_break (0);
     GNUNET_SERVER_receive_done (client, GNUNET_SYSERR);
@@ -501,9 +501,10 @@ handle_client_send (void *cls,
     return;
   }
   delay = GNUNET_TIME_absolute_get_duration (tc.car->received_time);
+  overdue = GNUNET_TIME_absolute_get_duration (tc.car->deadline);
   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)
+  if (overdue.rel_value_us > GNUNET_CONSTANTS_LATENCY_WARN.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,
@@ -531,11 +532,7 @@ handle_client_send (void *cls,
                              msize,
                              GNUNET_YES,
                              GNUNET_NO);
-  if (0 !=
-      memcmp (&tc.car->target,
-              &GSC_my_identity,
-              sizeof (struct GNUNET_PeerIdentity)))
-    GSC_SESSIONS_dequeue_request (tc.car);
+  GSC_SESSIONS_dequeue_request (tc.car);
   GNUNET_free (tc.car);
   GNUNET_SERVER_receive_done (client,
                               GNUNET_OK);
@@ -702,13 +699,13 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car)
                            &GSC_my_identity,
                            sizeof (struct GNUNET_PeerIdentity)));
     GSC_SESSIONS_dequeue_request (car);
-    GSC_CLIENTS_reject_request (car);
+    GSC_CLIENTS_reject_request (car,
+                                GNUNET_NO);
     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) )
+  left = GNUNET_TIME_absolute_get_duration (car->deadline);
+  if (left.rel_value_us > GNUNET_CONSTANTS_LATENCY_WARN.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,
@@ -728,21 +725,28 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car)
 
 
 /**
- * Tell a client that we will never be ready to receive the
- * given message in time (disconnect or timeout).
+ * We will never be ready to transmit the given message in (disconnect
+ * or invalid request).  Frees resources associated with @a car.  We
+ * don't explicitly tell the client, he'll learn with the disconnect
+ * (or violated the protocol).
  *
  * @param car request that now permanently failed; the
  *        responsibility for the handle is now returned
  *        to CLIENTS (SESSIONS is done with it).
+ * @param drop_client #GNUNET_YES if the client violated the protocol
+ *        and we should thus drop the connection
  */
 void
-GSC_CLIENTS_reject_request (struct GSC_ClientActiveRequest *car)
+GSC_CLIENTS_reject_request (struct GSC_ClientActiveRequest *car,
+                            int drop_client)
 {
   GNUNET_assert (GNUNET_YES ==
                  GNUNET_CONTAINER_multipeermap_remove (car->
                                                        client_handle->requests,
                                                        &car->target,
                                                        car));
+  if (GNUNET_YES == drop_client)
+    GNUNET_SERVER_client_disconnect (car->client_handle->client_handle);
   GNUNET_free (car);
 }
 
diff --git a/src/core/gnunet-service-core_clients.h b/src/core/gnunet-service-core_clients.h
index e39ce616f..a9d712442 100644
--- a/src/core/gnunet-service-core_clients.h
+++ b/src/core/gnunet-service-core_clients.h
@@ -107,15 +107,20 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car);
 
 
 /**
- * Tell a client that we will never be ready to receive the
- * given message in time (disconnect or timeout).
+ * We will never be ready to transmit the given message in (disconnect
+ * or invalid request).  Frees resources associated with @a car.  We
+ * don't explicitly tell the client, he'll learn with the disconnect
+ * (or violated the protocol).
  *
  * @param car request that now permanently failed; the
  *        responsibility for the handle is now returned
  *        to CLIENTS (SESSIONS is done with it).
+ * @param drop_client #GNUNET_YES if the client violated the protocol
+ *        and we should thus drop the connection
  */
 void
-GSC_CLIENTS_reject_request (struct GSC_ClientActiveRequest *car);
+GSC_CLIENTS_reject_request (struct GSC_ClientActiveRequest *car,
+                            int drop_client);
 
 
 /**
diff --git a/src/core/gnunet-service-core_sessions.c b/src/core/gnunet-service-core_sessions.c
index bbabf8866..b99fee272 100644
--- a/src/core/gnunet-service-core_sessions.c
+++ b/src/core/gnunet-service-core_sessions.c
@@ -229,7 +229,8 @@ GSC_SESSIONS_end (const struct GNUNET_PeerIdentity *pid)
   {
     GNUNET_CONTAINER_DLL_remove (session->active_client_request_head,
                                  session->active_client_request_tail, car);
-    GSC_CLIENTS_reject_request (car);
+    GSC_CLIENTS_reject_request (car,
+                                GNUNET_NO);
   }
   while (NULL != (sme = session->sme_head))
   {
@@ -486,13 +487,15 @@ GSC_SESSIONS_queue_request (struct GSC_ClientActiveRequest *car)
     GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
                 "Dropped client request for transmission (am disconnected)\n");
     GNUNET_break (0);           /* should have been rejected earlier */
-    GSC_CLIENTS_reject_request (car);
+    GSC_CLIENTS_reject_request (car,
+                                GNUNET_NO);
     return;
   }
   if (car->msize > GNUNET_CONSTANTS_MAX_ENCRYPTED_MESSAGE_SIZE)
   {
     GNUNET_break (0);
-    GSC_CLIENTS_reject_request (car);
+    GSC_CLIENTS_reject_request (car,
+                                GNUNET_YES);
     return;
   }
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
@@ -516,7 +519,8 @@ GSC_SESSIONS_dequeue_request (struct GSC_ClientActiveRequest *car)
   struct Session *session;
 
   if (0 ==
-      memcmp (&car->target, &GSC_my_identity,
+      memcmp (&car->target,
+              &GSC_my_identity,
               sizeof (struct GNUNET_PeerIdentity)))
     return;
   session = find_session (&car->target);
@@ -524,41 +528,10 @@ GSC_SESSIONS_dequeue_request (struct GSC_ClientActiveRequest *car)
   GNUNET_CONTAINER_DLL_remove (session->active_client_request_head,
                                session->active_client_request_tail,
                                car);
-}
-
-
-/**
- * Discard all expired active transmission requests from clients.
- *
- * @param session session to clean up
- */
-static void
-discard_expired_requests (struct Session *session)
-{
-  struct GSC_ClientActiveRequest *pos;
-  struct GSC_ClientActiveRequest *nxt;
-  struct GNUNET_TIME_Absolute now;
-
-  now = GNUNET_TIME_absolute_get ();
-  pos = NULL;
-  nxt = session->active_client_request_head;
-  while (NULL != nxt)
-  {
-    pos = nxt;
-    nxt = pos->next;
-    if ( (pos->deadline.abs_value_us < now.abs_value_us) &&
-         (GNUNET_YES != pos->was_solicited) )
-    {
-      GNUNET_STATISTICS_update (GSC_stats,
-                                gettext_noop
-                                ("# messages discarded (expired prior to transmission)"),
-                                1, GNUNET_NO);
-      GNUNET_CONTAINER_DLL_remove (session->active_client_request_head,
-                                   session->active_client_request_tail,
-                                   pos);
-      GSC_CLIENTS_reject_request (pos);
-    }
-  }
+  /* dequeueing of 'high' priority messages may unblock
+     transmission for lower-priority messages, so we also
+     need to try in this case. */
+  try_transmission (session);
 }
 
 
@@ -578,7 +551,6 @@ solicit_messages (struct Session *session,
   size_t so_size;
   enum GNUNET_CORE_Priority pmax;
 
-  discard_expired_requests (session);
   so_size = msize;
   pmax = GNUNET_CORE_PRIO_BACKGROUND;
   for (car = session->active_client_request_head; NULL != car; car = car->next)
@@ -599,6 +571,9 @@ solicit_messages (struct Session *session,
     if (GNUNET_YES == car->was_solicited)
       continue;
     car->was_solicited = GNUNET_YES;
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Soliciting message with priority %u\n",
+                car->priority);
     GSC_CLIENTS_solicit_request (car);
   }
 }
@@ -642,7 +617,11 @@ try_transmission (struct Session *session)
   int excess;
 
   if (GNUNET_YES != session->ready_to_transmit)
+  {
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Already ready to transmit, not evaluating queue\n");
     return;
+  }
   msize = 0;
   min_deadline = GNUNET_TIME_UNIT_FOREVER_ABS;
   /* if the peer has excess bandwidth, background traffic is allowed,
@@ -745,6 +724,11 @@ try_transmission (struct Session *session)
                                         &pop_cork_task,
                                         session);
     }
+    else
+    {
+      GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                  "Queue empty, waiting for solicitations\n");
+    }
     return;
   }
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
diff --git a/src/core/test_core_api_reliability.c b/src/core/test_core_api_reliability.c
index f2fadb59e..bd55565e3 100644
--- a/src/core/test_core_api_reliability.c
+++ b/src/core/test_core_api_reliability.c
@@ -41,7 +41,7 @@
 /**
  * How long until we give up on transmitting the message?
  */
-#define TIMEOUT GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_SECONDS, 6000)
+#define TIMEOUT GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_SECONDS, 600)
 
 /**
  * What delay do we request from the core service for transmission?
@@ -55,9 +55,9 @@ static unsigned long long total_bytes;
 
 static struct GNUNET_TIME_Absolute start_time;
 
-static struct GNUNET_SCHEDULER_Task * err_task;
+static struct GNUNET_SCHEDULER_Task *err_task;
 
-static struct GNUNET_SCHEDULER_Task * connect_task;
+static struct GNUNET_SCHEDULER_Task *connect_task;
 
 
 struct PeerContext
@@ -185,9 +185,9 @@ transmit_ready (void *cls, size_t size, void *buf)
   unsigned int ret;
 
   GNUNET_assert (size <= GNUNET_CONSTANTS_MAX_ENCRYPTED_MESSAGE_SIZE);
-  if (buf == NULL)
+  if (NULL == buf)
   {
-    if (p1.ch != NULL)
+    if (NULL != p1.ch)
       GNUNET_break (NULL !=
                     GNUNET_CORE_notify_transmit_ready (p1.ch, GNUNET_NO,
                                                        GNUNET_CORE_PRIO_BEST_EFFORT,
@@ -221,7 +221,8 @@ transmit_ready (void *cls, size_t size, void *buf)
   while (size - ret >= s);
   GNUNET_SCHEDULER_cancel (err_task);
   err_task =
-      GNUNET_SCHEDULER_add_delayed (TIMEOUT, &terminate_task_error, NULL);
+      GNUNET_SCHEDULER_add_delayed (TIMEOUT,
+                                    &terminate_task_error, NULL);
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
               "Returning total message block of size %u\n", ret);
   total_bytes += ret;
@@ -241,10 +242,10 @@ connect_notify (void *cls, const struct GNUNET_PeerIdentity *peer)
   if (pc == &p1)
   {
     GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-                "Encrypted connection established to peer `%4s'\n",
+                "Encrypted connection established to peer `%s'\n",
                 GNUNET_i2s (peer));
     GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-                "Asking core (1) for transmission to peer `%4s'\n",
+                "Asking core (1) for transmission to peer `%s'\n",
                 GNUNET_i2s (&p2.id));
     GNUNET_SCHEDULER_cancel (err_task);
     err_task =
@@ -268,7 +269,7 @@ disconnect_notify (void *cls, const struct GNUNET_PeerIdentity *peer)
   if (0 == memcmp (&pc->id, peer, sizeof (struct GNUNET_PeerIdentity)))
     return;
   pc->connect_status = 0;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Encrypted connection to `%4s' cut\n",
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Encrypted connection to `%s' cut\n",
               GNUNET_i2s (peer));
 }
 
@@ -278,7 +279,7 @@ inbound_notify (void *cls, const struct GNUNET_PeerIdentity *other,
                 const struct GNUNET_MessageHeader *message)
 {
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Core provides inbound data from `%4s'.\n", GNUNET_i2s (other));
+              "Core provides inbound data from `%s'.\n", GNUNET_i2s (other));
   return GNUNET_OK;
 }
 
@@ -288,7 +289,7 @@ outbound_notify (void *cls, const struct GNUNET_PeerIdentity *other,
                  const struct GNUNET_MessageHeader *message)
 {
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Core notifies about outbound data for `%4s'.\n",
+              "Core notifies about outbound data for `%s'.\n",
               GNUNET_i2s (other));
   return GNUNET_OK;
 }
@@ -299,7 +300,8 @@ transmit_ready (void *cls, size_t size, void *buf);
 
 
 static int
-process_mtype (void *cls, const struct GNUNET_PeerIdentity *peer,
+process_mtype (void *cls,
+               const struct GNUNET_PeerIdentity *peer,
                const struct GNUNET_MessageHeader *message)
 {
   static int n;
@@ -342,9 +344,11 @@ process_mtype (void *cls, const struct GNUNET_PeerIdentity *peer,
   {
     if (n == tr_n)
       GNUNET_break (NULL !=
-                    GNUNET_CORE_notify_transmit_ready (p1.ch, GNUNET_NO,
+                    GNUNET_CORE_notify_transmit_ready (p1.ch,
+                                                       GNUNET_NO /* no cork */,
                                                        GNUNET_CORE_PRIO_BEST_EFFORT,
-                                                       FAST_TIMEOUT, &p2.id,
+                                                       FAST_TIMEOUT /* ignored! */,
+                                                       &p2.id,
                                                        get_size (tr_n),
                                                        &transmit_ready, &p1));
   }
@@ -365,7 +369,7 @@ init_notify (void *cls,
   struct PeerContext *p = cls;
 
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "Connection to CORE service of `%4s' established\n",
+              "Connection to CORE service of `%s' established\n",
               GNUNET_i2s (my_identity));
   p->id = *my_identity;
   if (cls == &p1)
@@ -373,9 +377,13 @@ init_notify (void *cls,
     GNUNET_assert (ok == 2);
     OKPP;
     /* connect p2 */
-    GNUNET_assert (NULL != (p2.ch = GNUNET_CORE_connect (p2.cfg, &p2, &init_notify, &connect_notify,
-                         &disconnect_notify, &inbound_notify, GNUNET_YES,
-                         &outbound_notify, GNUNET_YES, handlers)));
+    GNUNET_assert (NULL != (p2.ch = GNUNET_CORE_connect (p2.cfg, &p2,
+                                                         &init_notify,
+                                                         &connect_notify,
+                                                         &disconnect_notify,
+                                                         &inbound_notify, GNUNET_YES,
+                                                         &outbound_notify, GNUNET_YES,
+                                                         handlers)));
   }
   else
   {
@@ -383,7 +391,7 @@ init_notify (void *cls,
     OKPP;
     GNUNET_assert (cls == &p2);
     GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-                "Asking transport (1) to connect to peer `%4s'\n",
+                "Asking transport (1) to connect to peer `%s'\n",
                 GNUNET_i2s (&p2.id));
     connect_task = GNUNET_SCHEDULER_add_now (&try_connect, NULL);
   }
@@ -443,9 +451,13 @@ run (void *cls, char *const *args, const char *cfgfile,
   err_task =
       GNUNET_SCHEDULER_add_delayed (TIMEOUT, &terminate_task_error, NULL);
 
-  GNUNET_assert (NULL != (p1.ch = GNUNET_CORE_connect (p1.cfg, &p1, &init_notify, &connect_notify,
-                       &disconnect_notify, &inbound_notify, GNUNET_YES,
-                       &outbound_notify, GNUNET_YES, handlers)));
+  GNUNET_assert (NULL != (p1.ch = GNUNET_CORE_connect (p1.cfg, &p1,
+                                                       &init_notify,
+                                                       &connect_notify,
+                                                       &disconnect_notify,
+                                                       &inbound_notify, GNUNET_YES,
+                                                       &outbound_notify, GNUNET_YES,
+                                                       handlers)));
 }
 
 
@@ -476,7 +488,7 @@ main (int argc, char *argv1[])
     GNUNET_GETOPT_OPTION_END
   };
   ok = 1;
-  GNUNET_log_setup ("test-core-api",
+  GNUNET_log_setup ("test-core-api-reliability",
                     "WARNING",
                     NULL);
   GNUNET_PROGRAM_run ((sizeof (argv) / sizeof (char *)) - 1, argv,