more logging, minor bugfixes / renames

11 files changed, 295 insertions, 143 deletions

diff --git a/src/cadet/cadet_protocol.h b/src/cadet/cadet_protocol.h
index 3a70758d9..24145a008 100644
--- a/src/cadet/cadet_protocol.h
+++ b/src/cadet/cadet_protocol.h
@@ -87,7 +87,7 @@ struct GNUNET_CADET_ConnectionCreateMessage
 /**
  * Message for ack'ing a connection
  */
-struct GNUNET_CADET_ConnectionCreateMessageAckMessage
+struct GNUNET_CADET_ConnectionCreateAckMessage
 {
   /**
    * Type: #GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE_ACK
diff --git a/src/cadet/gnunet-service-cadet-new_channel.c b/src/cadet/gnunet-service-cadet-new_channel.c
index e64e66dfa..a3ab07c3c 100644
--- a/src/cadet/gnunet-service-cadet-new_channel.c
+++ b/src/cadet/gnunet-service-cadet-new_channel.c
@@ -44,7 +44,7 @@
 #include "gnunet-service-cadet-new_peer.h"
 #include "gnunet-service-cadet-new_paths.h"
 
-#define LOG(level,...) GNUNET_log_from (level,"cadet-channel",__VA_ARGS__)
+#define LOG(level,...) GNUNET_log_from (level,"cadet-chn",__VA_ARGS__)
 
 /**
  * How long do we initially wait before retransmitting?
@@ -405,7 +405,7 @@ channel_destroy (struct CadetChannel *ch)
  * @param cls Channel for which to send.
  */
 static void
-send_create (void *cls);
+send_channel_open (void *cls);
 
 
 /**
@@ -415,25 +415,25 @@ send_create (void *cls);
  * @param cls our `struct CadetChannel`.
  */
 static void
-create_sent_cb (void *cls)
+channel_open_sent_cb (void *cls)
 {
   struct CadetChannel *ch = cls;
 
   ch->last_control_qe = NULL;
   ch->retry_time = GNUNET_TIME_STD_BACKOFF (ch->retry_time);
   ch->retry_task = GNUNET_SCHEDULER_add_delayed (ch->retry_time,
-                                                 &send_create,
+                                                 &send_channel_open,
                                                  ch);
 }
 
 
 /**
- * Send a channel create message.
+ * Send a channel open message.
  *
  * @param cls Channel for which to send.
  */
 static void
-send_create (void *cls)
+send_channel_open (void *cls)
 {
   struct CadetChannel *ch = cls;
   struct GNUNET_CADET_ChannelOpenMessage msgcc;
@@ -454,8 +454,11 @@ send_create (void *cls)
   ch->state = CADET_CHANNEL_CREATE_SENT;
   ch->last_control_qe = GCT_send (ch->t,
                                   &msgcc.header,
-                                  &create_sent_cb,
+                                  &channel_open_sent_cb,
                                   ch);
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Sending CHANNEL_OPEN message for channel %s\n",
+       GCCH_2s (ch));
 }
 
 
@@ -491,7 +494,7 @@ GCCH_channel_local_new (struct CadetClient *owner,
   ch->ctn = GCT_add_channel (ch->t,
                               ch);
   ch->retry_time = CADET_INITIAL_RETRANSMIT_TIME;
-  ch->retry_task = GNUNET_SCHEDULER_add_now (&send_create,
+  ch->retry_task = GNUNET_SCHEDULER_add_now (&send_channel_open,
                                              ch);
   GNUNET_STATISTICS_update (stats,
                             "# channels",
@@ -611,7 +614,7 @@ send_ack_cb (void *cls)
  * @param ch channel to send the ACK for
  */
 static void
-send_channel_ack (struct CadetChannel *ch)
+send_channel_data_ack (struct CadetChannel *ch)
 {
   struct GNUNET_CADET_ChannelDataAckMessage msg;
 
@@ -641,7 +644,7 @@ send_connect_ack (void *cls)
   struct CadetChannel *ch = cls;
 
   ch->retry_task = NULL;
-  send_channel_ack (ch);
+  send_channel_data_ack (ch);
 }
 
 
@@ -792,7 +795,7 @@ GCCH_channel_incoming_destroy (struct CadetChannel *ch)
  * @param ch channel to destroy
  */
 void
-GCCH_handle_channel_create_ack (struct CadetChannel *ch)
+GCCH_handle_channel_open_ack (struct CadetChannel *ch)
 {
   switch (ch->state)
   {
@@ -807,6 +810,9 @@ GCCH_handle_channel_create_ack (struct CadetChannel *ch)
       GNUNET_break_op (0);
       return;
     }
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Received channel OPEN_ACK for waiting channel %s, entering READY state\n",
+         GCCH_2s (ch));
     ch->state = CADET_CHANNEL_READY;
     /* On first connect, send client as many ACKs as we allow messages
        to be buffered! */
@@ -816,6 +822,9 @@ GCCH_handle_channel_create_ack (struct CadetChannel *ch)
     break;
   case CADET_CHANNEL_READY:
     /* duplicate ACK, maybe we retried the CREATE. Ignore. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Received duplicate channel OPEN_ACK for channel %s\n",
+         GCCH_2s (ch));
     GNUNET_STATISTICS_update (stats,
                               "# duplicate CREATE_ACKs",
                               1,
@@ -876,6 +885,10 @@ GCCH_handle_channel_plaintext_data (struct CadetChannel *ch,
   size_t payload_size;
 
   payload_size = ntohs (msg->header.size) - sizeof (*msg);
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Receicved %u bytes of application data on channel %s\n",
+       (unsigned int) payload_size,
+       GCCH_2s (ch));
   env = GNUNET_MQ_msg_extra (ld,
                              payload_size,
                              GNUNET_MESSAGE_TYPE_CADET_LOCAL_DATA);
@@ -966,7 +979,7 @@ GCCH_handle_channel_plaintext_data_ack (struct CadetChannel *ch,
     /* ACK for message we already dropped, might have been a
        duplicate ACK? Ignore. */
     GNUNET_STATISTICS_update (stats,
-                              "# duplicate CHANNEL_DATA_ACKs",
+                              "# duplicate DATA_ACKs",
                               1,
                               GNUNET_NO);
     return;
@@ -995,6 +1008,9 @@ GCCH_handle_remote_destroy (struct CadetChannel *ch)
   struct GNUNET_MQ_Envelope *env;
   struct GNUNET_CADET_LocalChannelDestroyMessage *tdm;
 
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Received remote channel DESTROY for channel %s\n",
+       GCCH_2s (ch));
   ch->destroy = GNUNET_YES;
   env = GNUNET_MQ_msg (tdm,
                        GNUNET_MESSAGE_TYPE_CADET_LOCAL_CHANNEL_DESTROY);
@@ -1255,7 +1271,7 @@ send_client_buffered_data (struct CadetChannel *ch)
                 "Sender on channel %s likely blocked on flow-control, sending ACK now.\n",
                 GCCH_2s (ch));
     if (GNUNET_YES == ch->reliable)
-      send_channel_ack (ch);
+      send_channel_data_ack (ch);
   }
 
   if (NULL != ch->head_recv)
diff --git a/src/cadet/gnunet-service-cadet-new_channel.h b/src/cadet/gnunet-service-cadet-new_channel.h
index 2e1eb4115..a479145aa 100644
--- a/src/cadet/gnunet-service-cadet-new_channel.h
+++ b/src/cadet/gnunet-service-cadet-new_channel.h
@@ -174,7 +174,7 @@ GCCH_handle_channel_plaintext_data_ack (struct CadetChannel *ch,
  * @param ch channel to destroy
  */
 void
-GCCH_handle_channel_create_ack (struct CadetChannel *ch);
+GCCH_handle_channel_open_ack (struct CadetChannel *ch);
 
 
 /**
diff --git a/src/cadet/gnunet-service-cadet-new_connection.c b/src/cadet/gnunet-service-cadet-new_connection.c
index 5eb6335a2..55b33e224 100644
--- a/src/cadet/gnunet-service-cadet-new_connection.c
+++ b/src/cadet/gnunet-service-cadet-new_connection.c
@@ -40,6 +40,9 @@
 #include "cadet_protocol.h"
 
 
+#define LOG(level, ...) GNUNET_log_from(level,"cadet-con",__VA_ARGS__)
+
+
 /**
  * All the states a connection can be in.
  */
@@ -158,6 +161,9 @@ GCC_destroy (struct CadetConnection *cc)
 {
   struct GNUNET_MQ_Envelope *env = NULL;
 
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Destroying connection %s\n",
+       GCC_2s (cc));
   if (CADET_CONNECTION_SENDING_CREATE != cc->state)
   {
     struct GNUNET_CADET_ConnectionDestroyMessage *destroy_msg;
@@ -201,8 +207,12 @@ GCC_get_ct (struct CadetConnection *cc)
  * @param cc the connection that got the ACK.
  */
 void
-GCC_handle_connection_ack (struct CadetConnection *cc)
+GCC_handle_connection_create_ack (struct CadetConnection *cc)
 {
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Received CREATE_ACK for connection %s in state %d\n",
+       GCC_2s (cc),
+       cc->state);
   if (NULL != cc->task)
   {
     GNUNET_SCHEDULER_cancel (cc->task);
@@ -234,7 +244,10 @@ GCC_handle_kx (struct CadetConnection *cc,
   {
     /* We didn't get the CREATE_ACK, but instead got payload. That's fine,
        clearly something is working, so pretend we got an ACK. */
-    GCC_handle_connection_ack (cc);
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Faking connection ACK for connection %s due to KX\n",
+         GCC_2s (cc));
+    GCC_handle_connection_create_ack (cc);
   }
   GCT_handle_kx (cc->ct,
                  msg);
@@ -255,7 +268,10 @@ GCC_handle_encrypted (struct CadetConnection *cc,
   {
     /* We didn't get the CREATE_ACK, but instead got payload. That's fine,
        clearly something is working, so pretend we got an ACK. */
-    GCC_handle_connection_ack (cc);
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Faking connection ACK for connection %s due to ENCRYPTED payload\n",
+         GCC_2s (cc));
+    GCC_handle_connection_create_ack (cc);
   }
   GCT_handle_encrypted (cc->ct,
                         msg);
@@ -287,6 +303,9 @@ send_create (void *cls)
   for (unsigned int i=0;i<path_length;i++)
     pids[i] = *GCP_get_id (GCPP_get_peer_at_offset (cc->path,
                                                     i));
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Sending CONNECTION_CREATE message for connection %s\n",
+       GCC_2s (cc));
   cc->env = env;
   cc->mqm_ready = GNUNET_NO;
   cc->state = CADET_CONNECTION_SENT;
@@ -304,22 +323,17 @@ static void
 send_create_ack (void *cls)
 {
   struct CadetConnection *cc = cls;
-  struct GNUNET_CADET_ConnectionCreateMessage *create_msg;
-  struct GNUNET_PeerIdentity *pids;
+  struct GNUNET_CADET_ConnectionCreateAckMessage *ack_msg;
   struct GNUNET_MQ_Envelope *env;
-  unsigned int path_length;
 
   cc->task = NULL;
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Sending CONNECTION_CREATE_ACK message for connection %s\n",
+       GCC_2s (cc));
   GNUNET_assert (GNUNET_YES == cc->mqm_ready);
-  path_length = GCPP_get_length (cc->path);
-  env = GNUNET_MQ_msg_extra (create_msg,
-                             path_length * sizeof (struct GNUNET_PeerIdentity),
-                             GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE);
-  create_msg->cid = cc->cid;
-  pids = (struct GNUNET_PeerIdentity *) &create_msg[1];
-  for (unsigned int i=0;i<path_length;i++)
-    pids[i] = *GCP_get_id (GCPP_get_peer_at_offset (cc->path,
-                                                    i));
+  env = GNUNET_MQ_msg (ack_msg,
+                       GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE_ACK);
+  ack_msg->cid = cc->cid;
   cc->env = env;
   cc->mqm_ready = GNUNET_NO;
   cc->state = CADET_CONNECTION_READY;
@@ -340,11 +354,13 @@ GCC_handle_duplicate_create (struct CadetConnection *cc)
 {
   if (GNUNET_YES == cc->mqm_ready)
   {
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Got duplicate CREATE for connection %s, scheduling another ACK\n",
+         GCC_2s (cc));
     /* Tell tunnel that we are not ready for transmission anymore
        (until CREATE_ACK is done) */
     cc->ready_cb (cc->ready_cb_cls,
                   GNUNET_NO);
-
     /* Revert back to the state of having only received the 'CREATE',
        and immediately proceed to send the CREATE_ACK. */
     cc->state = CADET_CONNECTION_CREATE_RECEIVED;
@@ -356,6 +372,9 @@ GCC_handle_duplicate_create (struct CadetConnection *cc)
     /* We are currently sending something else back, which
        can only be an ACK or payload, either of which would
        do. So actually no need to do anything. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Got duplicate CREATE for connection %s. MQ is busy, not queueing another ACK\n",
+         GCC_2s (cc));
   }
 }
 
@@ -379,6 +398,9 @@ manage_first_hop_mq (void *cls,
   if (GNUNET_YES != available)
   {
     /* Connection is down, for now... */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Core MQ for connection %s went down\n",
+         GCC_2s (cc));
     cc->mqm_ready = GNUNET_NO;
     cc->state = CADET_CONNECTION_NEW;
     cc->retry_delay = GNUNET_TIME_UNIT_ZERO;
@@ -393,6 +415,10 @@ manage_first_hop_mq (void *cls,
   }
 
   cc->mqm_ready = GNUNET_YES;
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Core MQ for connection %s became available in state %d\n",
+       GCC_2s (cc),
+       cc->state);
   switch (cc->state)
   {
   case CADET_CONNECTION_NEW:
@@ -479,6 +505,10 @@ connection_create (struct CadetPeer *destination,
   cc->mq_man = GCP_request_mq (first_hop,
                                &manage_first_hop_mq,
                                cc);
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Created connection %s using path %s\n",
+       GCC_2s (cc),
+       GCPP_2s (path));
   return cc;
 }
 
@@ -560,6 +590,9 @@ void
 GCC_transmit (struct CadetConnection *cc,
               struct GNUNET_MQ_Envelope *env)
 {
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Scheduling message for transmission on %s\n",
+       GCC_2s (cc));
   GNUNET_assert (GNUNET_YES == cc->mqm_ready);
   GNUNET_assert (CADET_CONNECTION_READY == cc->state);
   cc->mqm_ready = GNUNET_NO;
diff --git a/src/cadet/gnunet-service-cadet-new_connection.h b/src/cadet/gnunet-service-cadet-new_connection.h
index 31a2e80bb..efdf9929a 100644
--- a/src/cadet/gnunet-service-cadet-new_connection.h
+++ b/src/cadet/gnunet-service-cadet-new_connection.h
@@ -113,12 +113,12 @@ GCC_transmit (struct CadetConnection *cc,
 
 
 /**
- * An ACK was received for this connection, process it.
+ * A CREATE_ACK was received for this connection, process it.
  *
  * @param cc the connection that got the ACK.
  */
 void
-GCC_handle_connection_ack (struct CadetConnection *cc);
+GCC_handle_connection_create_ack (struct CadetConnection *cc);
 
 
 /**
diff --git a/src/cadet/gnunet-service-cadet-new_core.c b/src/cadet/gnunet-service-cadet-new_core.c
index a5d114b34..39a6a9296 100644
--- a/src/cadet/gnunet-service-cadet-new_core.c
+++ b/src/cadet/gnunet-service-cadet-new_core.c
@@ -477,7 +477,7 @@ handle_connection_create (void *cls,
  */
 static void
 handle_connection_create_ack (void *cls,
-                              const struct GNUNET_CADET_ConnectionCreateMessageAckMessage *msg)
+                              const struct GNUNET_CADET_ConnectionCreateAckMessage *msg)
 {
   struct CadetPeer *peer = cls;
   struct CadetConnection *cc;
@@ -498,7 +498,7 @@ handle_connection_create_ack (void *cls,
       GNUNET_break_op (0);
       return;
     }
-    GCC_handle_connection_ack (cc);
+    GCC_handle_connection_create_ack (cc);
     return;
   }
 
@@ -778,7 +778,7 @@ GCO_init (const struct GNUNET_CONFIGURATION_Handle *c)
                            NULL),
     GNUNET_MQ_hd_fixed_size (connection_create_ack,
                              GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE_ACK,
-                             struct GNUNET_CADET_ConnectionCreateMessageAckMessage,
+                             struct GNUNET_CADET_ConnectionCreateAckMessage,
                              NULL),
     GNUNET_MQ_hd_fixed_size (connection_broken,
                              GNUNET_MESSAGE_TYPE_CADET_CONNECTION_BROKEN,
diff --git a/src/cadet/gnunet-service-cadet-new_tunnels.c b/src/cadet/gnunet-service-cadet-new_tunnels.c
index cfdc4270a..535bd66a8 100644
--- a/src/cadet/gnunet-service-cadet-new_tunnels.c
+++ b/src/cadet/gnunet-service-cadet-new_tunnels.c
@@ -417,6 +417,37 @@ GCT_2s (const struct CadetTunnel *t)
 
 
 /**
+ * Get string description for tunnel encryption state.
+ *
+ * @param es Tunnel state.
+ *
+ * @return String representation.
+ */
+static const char *
+estate2s (enum CadetTunnelEState es)
+{
+  static char buf[32];
+
+  switch (es)
+  {
+    case CADET_TUNNEL_KEY_UNINITIALIZED:
+      return "CADET_TUNNEL_KEY_UNINITIALIZED";
+    case CADET_TUNNEL_KEY_SENT:
+      return "CADET_TUNNEL_KEY_SENT";
+    case CADET_TUNNEL_KEY_PING:
+      return "CADET_TUNNEL_KEY_PING";
+    case CADET_TUNNEL_KEY_OK:
+      return "CADET_TUNNEL_KEY_OK";
+    case CADET_TUNNEL_KEY_REKEY:
+      return "CADET_TUNNEL_KEY_REKEY";
+    default:
+      SPRINTF (buf, "%u (UNKNOWN STATE)", es);
+      return buf;
+  }
+}
+
+
+/**
  * Return the peer to which this tunnel goes.
  *
  * @param t a tunnel
@@ -1196,8 +1227,17 @@ send_kx (struct CadetTunnel *t,
 
   ct = get_ready_connection (t);
   if (NULL == ct)
+  {
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Wanted to send KX on tunnel %s, but no connection is ready, deferring\n",
+                GCT_2s (t));
     return;
+  }
   cc = ct->cc;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Sending KX on tunnel %s using connection %s\n",
+              GCT_2s (t),
+              GCC_2s (ct->cc));
 
   // GNUNET_assert (GNUNET_NO == GCT_is_loopback (t));
   env = GNUNET_MQ_msg (msg,
@@ -1327,6 +1367,10 @@ GCT_handle_kx (struct CadetTConnection *ct,
          " known handshake key, exit\n");
     return;
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Handling KX message for tunnel %s\n",
+              GCT_2s (t));
+
   ax->RK = keys[0];
   if (GNUNET_YES == am_I_alice)
   {
@@ -1428,6 +1472,10 @@ GCT_add_channel (struct CadetTunnel *t,
                                                       ntohl (ctn.cn),
                                                       ch,
                                                       GNUNET_CONTAINER_MULTIHASHMAPOPTION_UNIQUE_ONLY));
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Adding channel %s to tunnel %s\n",
+              GCCH_2s (ch),
+              GCT_2s (t));
   return ctn;
 }
 
@@ -1445,6 +1493,9 @@ destroy_tunnel (void *cls)
   struct CadetTunnelQueueEntry *tqe;
 
   t->destroy_task = NULL;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Destroying idle tunnel %s\n",
+              GCT_2s (t));
   GNUNET_assert (0 == GNUNET_CONTAINER_multihashmap32_size (t->channels));
   while (NULL != (ct = t->connection_head))
   {
@@ -1478,6 +1529,36 @@ destroy_tunnel (void *cls)
 
 
 /**
+ * Remove a channel from a tunnel.
+ *
+ * @param t Tunnel.
+ * @param ch Channel
+ * @param ctn unique number identifying @a ch within @a t
+ */
+void
+GCT_remove_channel (struct CadetTunnel *t,
+                    struct CadetChannel *ch,
+                    struct GNUNET_CADET_ChannelTunnelNumber ctn)
+{
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Removing channel %s from tunnel %s\n",
+              GCCH_2s (ch),
+              GCT_2s (t));
+  GNUNET_assert (GNUNET_YES ==
+                 GNUNET_CONTAINER_multihashmap32_remove (t->channels,
+                                                         ntohl (ctn.cn),
+                                                         ch));
+  if (0 ==
+      GNUNET_CONTAINER_multihashmap32_size (t->channels))
+  {
+    t->destroy_task = GNUNET_SCHEDULER_add_delayed (IDLE_DESTROY_DELAY,
+                                                    &destroy_tunnel,
+                                                    t);
+  }
+}
+
+
+/**
  * It's been a while, we should try to redo the KX, if we can.
  *
  * @param cls the `struct CadetTunnel` to do KX for.
@@ -1497,6 +1578,50 @@ retry_kx (void *cls)
 
 
 /**
+ * Send normal payload from queue in @a t via connection @a ct.
+ * Does nothing if our payload queue is empty.
+ *
+ * @param t tunnel to send data from
+ * @param ct connection to use for transmission (is ready)
+ */
+static void
+try_send_normal_payload (struct CadetTunnel *t,
+                         struct CadetTConnection *ct)
+{
+  struct CadetTunnelQueueEntry *tq;
+
+  GNUNET_assert (GNUNET_YES == ct->is_ready);
+  tq = t->tq_head;
+  if (NULL == tq)
+  {
+    /* no messages pending right now */
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Not sending payload of tunnel %s on ready connection %s (nothing pending)\n",
+                GCT_2s (t),
+                GCC_2s (ct->cc));
+    return;
+  }
+  /* ready to send message 'tq' on tunnel 'ct' */
+  GNUNET_assert (t == tq->t);
+  GNUNET_CONTAINER_DLL_remove (t->tq_head,
+                               t->tq_tail,
+                               tq);
+  if (NULL != tq->cid)
+    *tq->cid = *GCC_get_id (ct->cc);
+  ct->is_ready = GNUNET_NO;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Sending payload of tunnel %s on connection %s\n",
+              GCT_2s (t),
+              GCC_2s (ct->cc));
+  GCC_transmit (ct->cc,
+                tq->env);
+  if (NULL != tq->cont)
+    tq->cont (tq->cont_cls);
+  GNUNET_free (tq);
+}
+
+
+/**
  * A connection is @a is_ready for transmission.  Looks at our message
  * queue and if there is a message, sends it out via the connection.
  *
@@ -1510,14 +1635,22 @@ connection_ready_cb (void *cls,
 {
   struct CadetTConnection *ct = cls;
   struct CadetTunnel *t = ct->t;
-  struct CadetTunnelQueueEntry *tq = t->tq_head;
 
-  if (GNUNET_NO == ct->is_ready)
+  if (GNUNET_NO == is_ready)
   {
+    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+                "Connection %s no longer ready for tunnel %s\n",
+                GCC_2s (ct->cc),
+                GCT_2s (t));
     ct->is_ready = GNUNET_NO;
     return;
   }
   ct->is_ready = GNUNET_YES;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Connection %s now ready for tunnel %s in state %s\n",
+              GCC_2s (ct->cc),
+              GCT_2s (t),
+              estate2s (t->estate));
   switch (t->estate)
   {
   case CADET_TUNNEL_KEY_UNINITIALIZED:
@@ -1536,22 +1669,8 @@ connection_ready_cb (void *cls,
     }
     break;
   case CADET_TUNNEL_KEY_OK:
-    /* send normal payload */
-    if (NULL == tq)
-      return; /* no messages pending right now */
-    /* ready to send message 'tq' on tunnel 'ct' */
-    GNUNET_assert (t == tq->t);
-    GNUNET_CONTAINER_DLL_remove (t->tq_head,
-                                 t->tq_tail,
-                                 tq);
-    if (NULL != tq->cid)
-      *tq->cid = *GCC_get_id (ct->cc);
-    ct->is_ready = GNUNET_NO;
-    GCC_transmit (ct->cc,
-                  tq->env);
-    if (NULL != tq->cont)
-      tq->cont (tq->cont_cls);
-    GNUNET_free (tq);
+    try_send_normal_payload (t,
+                             ct);
     break;
   case CADET_TUNNEL_KEY_REKEY:
     send_kx (t,
@@ -1580,10 +1699,8 @@ trigger_transmissions (struct CadetTunnel *t)
   ct = get_ready_connection (t);
   if (NULL == ct)
     return; /* no connections ready */
-
-  /* FIXME: a bit hackish to do it like this... */
-  connection_ready_cb (ct,
-                       GNUNET_YES);
+  try_send_normal_payload (t,
+                           ct);
 }
 
 
@@ -1690,6 +1807,11 @@ consider_path_cb (void *cls,
                                t->connection_tail,
                                ct);
   t->num_connections++;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Found interesting path %s for tunnel %s, created connection %s\n",
+              GCPP_2s (path),
+              GCT_2s (t),
+              GCC_2s (ct->cc));
   return GNUNET_YES;
 }
 
@@ -1714,7 +1836,7 @@ GCT_consider_path (struct CadetTunnel *t,
 
 
 /**
- *
+ * NOT IMPLEMENTED.
  *
  * @param cls the `struct CadetTunnel` for which we decrypted the message
  * @param msg  the message we received on the tunnel
@@ -1764,6 +1886,10 @@ handle_plaintext_data (void *cls,
   {
     /* We don't know about such a channel, might have been destroyed on our
        end in the meantime, or never existed. Send back a DESTROY. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Receicved %u bytes of application data for unknown channel %u, sending DESTROY\n",
+         (unsigned int) (ntohs (msg->header.size) - sizeof (*msg)),
+         ntohl (msg->ctn.cn));
     GCT_send_channel_destroy (t,
                               msg->ctn);
     return;
@@ -1794,6 +1920,9 @@ handle_plaintext_data_ack (void *cls,
   {
     /* We don't know about such a channel, might have been destroyed on our
        end in the meantime, or never existed. Send back a DESTROY. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Receicved DATA_ACK for unknown channel %u, sending DESTROY\n",
+         ntohl (ack->ctn.cn));
     GCT_send_channel_destroy (t,
                               ack->ctn);
     return;
@@ -1811,13 +1940,17 @@ handle_plaintext_data_ack (void *cls,
  * @param cc the message we received on the tunnel
  */
 static void
-handle_plaintext_channel_create (void *cls,
-                                 const struct GNUNET_CADET_ChannelOpenMessage *cc)
+handle_plaintext_channel_open (void *cls,
+                               const struct GNUNET_CADET_ChannelOpenMessage *cc)
 {
   struct CadetTunnel *t = cls;
   struct CadetChannel *ch;
   struct GNUNET_CADET_ChannelTunnelNumber ctn;
 
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Receicved channel OPEN on port %s from peer %s\n",
+       GNUNET_h2s (&cc->port),
+       GCP_2s (GCT_get_destination (t)));
   ctn = get_next_free_ctn (t);
   ch = GCCH_channel_incoming_new (t,
                                   ctn,
@@ -1843,6 +1976,9 @@ GCT_send_channel_destroy (struct CadetTunnel *t,
 {
   struct GNUNET_CADET_ChannelManageMessage msg;
 
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Sending DESTORY message for channel ID %u\n",
+       ntohl (ctn.cn));
   msg.header.size = htons (sizeof (msg));
   msg.header.type = htons (GNUNET_MESSAGE_TYPE_CADET_CHANNEL_DESTROY);
   msg.reserved = htonl (0);
@@ -1863,8 +1999,8 @@ GCT_send_channel_destroy (struct CadetTunnel *t,
  * @param cm the message we received on the tunnel
  */
 static void
-handle_plaintext_channel_ack (void *cls,
-                              const struct GNUNET_CADET_ChannelManageMessage *cm)
+handle_plaintext_channel_open_ack (void *cls,
+                                   const struct GNUNET_CADET_ChannelManageMessage *cm)
 {
   struct CadetTunnel *t = cls;
   struct CadetChannel *ch;
@@ -1875,11 +2011,14 @@ handle_plaintext_channel_ack (void *cls,
   {
     /* We don't know about such a channel, might have been destroyed on our
        end in the meantime, or never existed. Send back a DESTROY. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Received channel OPEN_ACK for unknown channel, sending DESTROY\n",
+         GCCH_2s (ch));
     GCT_send_channel_destroy (t,
                               cm->ctn);
     return;
   }
-  GCCH_handle_channel_create_ack (ch);
+  GCCH_handle_channel_open_ack (ch);
 }
 
 
@@ -1895,10 +2034,20 @@ handle_plaintext_channel_destroy (void *cls,
                                   const struct GNUNET_CADET_ChannelManageMessage *cm)
 {
   struct CadetTunnel *t = cls;
-  struct CadetChannel *cc = lookup_channel (t,
-                                            cm->ctn);
+  struct CadetChannel *ch;
 
-  GCCH_handle_remote_destroy (cc);
+  ch = lookup_channel (t,
+                       cm->ctn);
+  if (NULL == ch)
+  {
+    /* We don't know about such a channel, might have been destroyed on our
+       end in the meantime, or never existed. */
+    LOG (GNUNET_ERROR_TYPE_DEBUG,
+         "Received channel DESTORY for unknown channel. Ignoring.\n",
+         GCCH_2s (ch));
+    return;
+  }
+  GCCH_handle_remote_destroy (ch);
 }
 
 
@@ -1960,11 +2109,11 @@ GCT_create_tunnel (struct CadetPeer *destination)
                              GNUNET_MESSAGE_TYPE_CADET_CHANNEL_APP_DATA_ACK,
                              struct GNUNET_CADET_ChannelDataAckMessage,
                              NULL),
-    GNUNET_MQ_hd_fixed_size (plaintext_channel_create,
+    GNUNET_MQ_hd_fixed_size (plaintext_channel_open,
                              GNUNET_MESSAGE_TYPE_CADET_CHANNEL_OPEN,
                              struct GNUNET_CADET_ChannelOpenMessage,
                              NULL),
-    GNUNET_MQ_hd_fixed_size (plaintext_channel_ack,
+    GNUNET_MQ_hd_fixed_size (plaintext_channel_open_ack,
                              GNUNET_MESSAGE_TYPE_CADET_CHANNEL_OPEN_ACK,
                              struct GNUNET_CADET_ChannelManageMessage,
                              NULL),
@@ -1999,32 +2148,6 @@ GCT_create_tunnel (struct CadetPeer *destination)
 
 
 /**
- * Remove a channel from a tunnel.
- *
- * @param t Tunnel.
- * @param ch Channel
- * @param gid unique number identifying @a ch within @a t
- */
-void
-GCT_remove_channel (struct CadetTunnel *t,
-                    struct CadetChannel *ch,
-                    struct GNUNET_CADET_ChannelTunnelNumber gid)
-{
-  GNUNET_assert (GNUNET_YES ==
-                 GNUNET_CONTAINER_multihashmap32_remove (t->channels,
-                                                         ntohl (gid.cn),
-                                                         ch));
-  if (0 ==
-      GNUNET_CONTAINER_multihashmap32_size (t->channels))
-  {
-    t->destroy_task = GNUNET_SCHEDULER_add_delayed (IDLE_DESTROY_DELAY,
-                                                    &destroy_tunnel,
-                                                    t);
-  }
-}
-
-
-/**
  * Add a @a connection to the @a tunnel.
  *
  * @param t a tunnel
@@ -2055,6 +2178,10 @@ GCT_add_inbound_connection (struct CadetTunnel *t,
                                t->connection_tail,
                                ct);
   t->num_connections++;
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Tunnel %s has new connection %s\n",
+       GCT_2s (t),
+       GCC_2s (ct->cc));
 }
 
 
@@ -2073,6 +2200,12 @@ GCT_handle_encrypted (struct CadetTConnection *ct,
   char cbuf [size] GNUNET_ALIGN;
   ssize_t decrypted_size;
 
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Tunnel %s received %u bytes of encrypted data in state %d\n",
+       GCT_2s (t),
+       (unsigned int) size,
+       t->estate);
+
   switch (t->estate)
   {
   case CADET_TUNNEL_KEY_UNINITIALIZED:
@@ -2110,17 +2243,14 @@ GCT_handle_encrypted (struct CadetTConnection *ct,
 
   if (-1 == decrypted_size)
   {
+    GNUNET_break_op (0);
+    LOG (GNUNET_ERROR_TYPE_WARNING,
+         "Tunnel %s failed to decrypt and validate encrypted data\n",
+         GCT_2s (t));
     GNUNET_STATISTICS_update (stats,
                               "# unable to decrypt",
                               1,
                               GNUNET_NO);
-    if (CADET_TUNNEL_KEY_PING <= t->estate)
-    {
-      GNUNET_break_op (0);
-      LOG (GNUNET_ERROR_TYPE_WARNING,
-           "Failed to decrypt message on tunnel %s\n",
-           GCT_2s (t));
-    }
     return;
   }
   if (CADET_TUNNEL_KEY_PING == t->estate)
@@ -2161,6 +2291,10 @@ GCT_send (struct CadetTunnel *t,
   struct GNUNET_CADET_TunnelEncryptedMessage *ax_msg;
 
   payload_size = ntohs (message->size);
+  LOG (GNUNET_ERROR_TYPE_DEBUG,
+       "Encrypting %u bytes of for tunnel %s\n",
+       (unsigned int) payload_size,
+       GCT_2s (t));
   env = GNUNET_MQ_msg_extra (ax_msg,
                              payload_size,
                              GNUNET_MESSAGE_TYPE_CADET_TUNNEL_ENCRYPTED);
@@ -2318,37 +2452,6 @@ debug_channel (void *cls,
 }
 
 
-/**
- * Get string description for tunnel encryption state.
- *
- * @param es Tunnel state.
- *
- * @return String representation.
- */
-static const char *
-estate2s (enum CadetTunnelEState es)
-{
-  static char buf[32];
-
-  switch (es)
-  {
-    case CADET_TUNNEL_KEY_UNINITIALIZED:
-      return "CADET_TUNNEL_KEY_UNINITIALIZED";
-    case CADET_TUNNEL_KEY_SENT:
-      return "CADET_TUNNEL_KEY_SENT";
-    case CADET_TUNNEL_KEY_PING:
-      return "CADET_TUNNEL_KEY_PING";
-    case CADET_TUNNEL_KEY_OK:
-      return "CADET_TUNNEL_KEY_OK";
-    case CADET_TUNNEL_KEY_REKEY:
-      return "CADET_TUNNEL_KEY_REKEY";
-    default:
-      SPRINTF (buf, "%u (UNKNOWN STATE)", es);
-      return buf;
-  }
-}
-
-
 #define LOG2(level, ...) GNUNET_log_from_nocheck(level,"cadet-tun",__VA_ARGS__)
 
 
diff --git a/src/cadet/gnunet-service-cadet-new_tunnels.h b/src/cadet/gnunet-service-cadet-new_tunnels.h
index 78c3cb6bb..3c88ae5f0 100644
--- a/src/cadet/gnunet-service-cadet-new_tunnels.h
+++ b/src/cadet/gnunet-service-cadet-new_tunnels.h
@@ -152,23 +152,23 @@ GCT_add_channel (struct CadetTunnel *t,
  *
  * @param t Tunnel.
  * @param ch Channel
- * @param gid unique number identifying @a ch within @a t
+ * @param ctn unique number identifying @a ch within @a t
  */
 void
 GCT_remove_channel (struct CadetTunnel *t,
                     struct CadetChannel *ch,
-                    struct GNUNET_CADET_ChannelTunnelNumber gid);
+                    struct GNUNET_CADET_ChannelTunnelNumber ctn);
 
 
 /**
  * Send a DESTROY message via the tunnel.
  *
  * @param t the tunnel to transmit over
- * @param chid ID of the channel to destroy
+ * @param ctn ID of the channel to destroy
  */
 void
 GCT_send_channel_destroy (struct CadetTunnel *t,
-                          struct GNUNET_CADET_ChannelTunnelNumber chid);
+                          struct GNUNET_CADET_ChannelTunnelNumber ctn);
 
 
 /**
diff --git a/src/cadet/gnunet-service-cadet_connection.c b/src/cadet/gnunet-service-cadet_connection.c
index c4802abde..af27647b3 100644
--- a/src/cadet/gnunet-service-cadet_connection.c
+++ b/src/cadet/gnunet-service-cadet_connection.c
@@ -1054,9 +1054,9 @@ static void
 send_connection_ack (struct CadetConnection *c, int fwd)
 {
   static struct CadetEncryptedMessageIdentifier zero;
-  struct GNUNET_CADET_ConnectionCreateMessageAckMessage msg;
+  struct GNUNET_CADET_ConnectionCreateAckMessage msg;
   struct CadetTunnel *t;
-  const uint16_t size = sizeof (struct GNUNET_CADET_ConnectionCreateMessageAckMessage);
+  const uint16_t size = sizeof (struct GNUNET_CADET_ConnectionCreateAckMessage);
   const uint16_t type = GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE_ACK;
 
   GCC_check_connections ();
@@ -2067,7 +2067,7 @@ GCC_handle_create (struct CadetPeer *peer,
  */
 void
 GCC_handle_confirm (struct CadetPeer *peer,
-                    const struct GNUNET_CADET_ConnectionCreateMessageAckMessage *msg)
+                    const struct GNUNET_CADET_ConnectionCreateAckMessage *msg)
 {
   static struct CadetEncryptedMessageIdentifier zero;
   struct CadetConnection *c;
diff --git a/src/cadet/gnunet-service-cadet_connection.h b/src/cadet/gnunet-service-cadet_connection.h
index 1c3160dfd..307cb42c2 100644
--- a/src/cadet/gnunet-service-cadet_connection.h
+++ b/src/cadet/gnunet-service-cadet_connection.h
@@ -136,7 +136,7 @@ GCC_handle_create (struct CadetPeer *peer,
  */
 void
 GCC_handle_confirm (struct CadetPeer *peer,
-                    const struct GNUNET_CADET_ConnectionCreateMessageAckMessage *msg);
+                    const struct GNUNET_CADET_ConnectionCreateAckMessage *msg);
 
 
 /**
diff --git a/src/cadet/gnunet-service-cadet_peer.c b/src/cadet/gnunet-service-cadet_peer.c
index 3f8b7bbb8..fa3f2be80 100644
--- a/src/cadet/gnunet-service-cadet_peer.c
+++ b/src/cadet/gnunet-service-cadet_peer.c
@@ -490,7 +490,7 @@ handle_create (void *cls, const struct GNUNET_CADET_ConnectionCreateMessage *msg
  * @param msg Message itself.
  */
 static void
-handle_confirm (void *cls, const struct GNUNET_CADET_ConnectionCreateMessageAckMessage *msg)
+handle_confirm (void *cls, const struct GNUNET_CADET_ConnectionCreateAckMessage *msg)
 {
     struct CadetPeer *peer = cls;
     GCC_handle_confirm (peer, msg);
@@ -628,7 +628,7 @@ connect_to_core (const struct GNUNET_CONFIGURATION_Handle *c)
                                NULL),
         GNUNET_MQ_hd_fixed_size (confirm,
                                  GNUNET_MESSAGE_TYPE_CADET_CONNECTION_CREATE_ACK,
-                                 struct GNUNET_CADET_ConnectionCreateMessageAckMessage,
+                                 struct GNUNET_CADET_ConnectionCreateAckMessage,
                                  NULL),
         GNUNET_MQ_hd_fixed_size (broken,
                                 GNUNET_MESSAGE_TYPE_CADET_CONNECTION_BROKEN,