fix issue with sending BROKEN timeouts early due to wrong timeout calculation

diff --git a/src/cadet/cadet_api.c b/src/cadet/cadet_api.c
index 366e31405a8903c43a28a28a8fb8e827c9675a25..497c9a4f0ba887216a28e21a182d7344ab08d9b1 100644 (file)
--- a/src/cadet/cadet_api.c
+++ b/src/cadet/cadet_api.c
@@ -391,6 +391,8 @@ destroy_channel_on_reconnect_cb (void *cls,
   /* struct GNUNET_CADET_Handle *handle = cls; */
   struct GNUNET_CADET_Channel *ch = value;
 
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+             "Destroying channel due to reconnect\n");
   destroy_channel (ch);
   return GNUNET_OK;
 }
@@ -1197,6 +1199,8 @@ destroy_channel_cb (void *cls,
          "channel %X not destroyed\n",
          ntohl (ch->ccn.channel_of_client));
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+             "Destroying channel due to GNUNET_CADET_disconnect()\n");
   destroy_channel (ch);
   return GNUNET_OK;
 }
@@ -1311,6 +1315,8 @@ GNUNET_CADET_channel_destroy (struct GNUNET_CADET_Channel *channel)
     GNUNET_MQ_send (h->mq,
                     env);
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+             "Destroying channel due to GNUNET_CADET_channel_destroy()\n");
   destroy_channel (channel);
 }
 

diff --git a/src/cadet/gnunet-service-cadet_core.c b/src/cadet/gnunet-service-cadet_core.c
index 99957d8a11af09ee2b8697fab7243c54beff568b..84aff1857eeb155eeaa7f018466366ca1cdf0ea0 100644 (file)
--- a/src/cadet/gnunet-service-cadet_core.c
+++ b/src/cadet/gnunet-service-cadet_core.c
@@ -623,7 +623,7 @@ timeout_cb (void *cls)
   {
     exp = GNUNET_TIME_absolute_add (r->last_use,
                                     linger);
-    if (0 != GNUNET_TIME_absolute_get_duration (exp).rel_value_us)
+    if (0 != GNUNET_TIME_absolute_get_remaining (exp).rel_value_us)
     {
       /* Route not yet timed out, wait until it does. */
       timeout_task = GNUNET_SCHEDULER_add_at (exp,
@@ -631,6 +631,11 @@ timeout_cb (void *cls)
                                               NULL);
       return;
     }
+    GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+               "Sending BROKEN due to timeout (%s was last use, %s linger)\n",
+               GNUNET_STRINGS_absolute_time_to_string (r->last_use),
+               GNUNET_STRINGS_relative_time_to_string (linger,
+                                                       GNUNET_YES));
     send_broken (&r->prev,
                  &r->cid,
                  NULL,
@@ -688,6 +693,8 @@ dir_ready_cb (void *cls,
     return;
   }
   odir = (dir == &route->next) ? &route->prev : &route->next;
+  GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+             "Sending BROKEN due to MQ going down\n");
   send_broken (&route->next,
                &route->cid,
                GCP_get_id (odir->hop),

diff --git a/src/cadet/test_cadet.c b/src/cadet/test_cadet.c
index bc441405401cf8d8c8dfcd7d237d2716808804a1..5cc9706d7cb0acd8c4d20fee403a098a51d27706 100644 (file)
--- a/src/cadet/test_cadet.c
+++ b/src/cadet/test_cadet.c
@@ -274,12 +274,20 @@ show_end_data (void)
 
   end_time = GNUNET_TIME_absolute_get ();
   total_time = GNUNET_TIME_absolute_get_difference (start_time, end_time);
-  FPRINTF (stderr, "\nResults of test \"%s\"\n", test_name);
-  FPRINTF (stderr, "Test time %s\n",
+  FPRINTF (stderr,
+          "\nResults of test \"%s\"\n",
+          test_name);
+  FPRINTF (stderr,
+          "Test time %s\n",
            GNUNET_STRINGS_relative_time_to_string (total_time, GNUNET_YES));
-  FPRINTF (stderr, "Test bandwidth: %f kb/s\n", 4 * total_packets * 1.0 / (total_time.rel_value_us / 1000));    // 4bytes * ms
-  FPRINTF (stderr, "Test throughput: %f packets/s\n\n", total_packets * 1000.0 / (total_time.rel_value_us / 1000));     // packets * ms
-  GAUGER ("CADET", test_name,
+  FPRINTF (stderr,
+          "Test bandwidth: %f kb/s\n",
+          4 * total_packets * 1.0 / (total_time.rel_value_us / 1000));    // 4bytes * ms
+  FPRINTF (stderr,
+          "Test throughput: %f packets/s\n\n",
+          total_packets * 1000.0 / (total_time.rel_value_us / 1000));     // packets * ms
+  GAUGER ("CADET",
+         test_name,
           total_packets * 1000.0 / (total_time.rel_value_us / 1000),
           "packets/s");
 }
@@ -295,13 +303,12 @@ static void
 disconnect_cadet_peers (void *cls)
 {
   long line = (long) cls;
-  unsigned int i;
 
   disconnect_task = NULL;
   GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "disconnecting cadet service of peers, called from line %ld\n",
               line);
-  for (i = 0; i < 2; i++)
+  for (unsigned int i = 0; i < 2; i++)
   {
     GNUNET_TESTBED_operation_done (t_op[i]);
   }
@@ -329,7 +336,8 @@ disconnect_cadet_peers (void *cls)
 static void
 shutdown_task (void *cls)
 {
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Ending test.\n");
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+             "Ending test.\n");
   if (NULL != send_next_msg_task)
   {
     GNUNET_SCHEDULER_cancel (send_next_msg_task);
@@ -344,7 +352,8 @@ shutdown_task (void *cls)
   {
     GNUNET_SCHEDULER_cancel (disconnect_task);
     disconnect_task =
-        GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers, (void *) __LINE__);
+        GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers,
+                                 (void *) __LINE__);
   }
 }
 
@@ -359,10 +368,14 @@ shutdown_task (void *cls)
  *          operation has executed successfully.
  */
 static void
-stats_cont (void *cls, struct GNUNET_TESTBED_Operation *op, const char *emsg)
+stats_cont (void *cls,
+           struct GNUNET_TESTBED_Operation *op,
+           const char *emsg)
 {
-  GNUNET_log (GNUNET_ERROR_TYPE_INFO, " KA sent: %u, KA received: %u\n",
-              ka_sent, ka_received);
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+             "KA sent: %u, KA received: %u\n",
+              ka_sent,
+             ka_received);
   if ((KEEPALIVE == test) && ((ka_sent < 2) || (ka_sent > ka_received + 1)))
   {
     GNUNET_break (0);
@@ -372,7 +385,8 @@ stats_cont (void *cls, struct GNUNET_TESTBED_Operation *op, const char *emsg)
 
   if (NULL != disconnect_task)
     GNUNET_SCHEDULER_cancel (disconnect_task);
-  disconnect_task = GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers, cls);
+  disconnect_task = GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers,
+                                             cls);
 }
 
 
@@ -443,7 +457,6 @@ gather_stats_and_exit (void *cls)
 }
 
 
-
 /**
  * Abort test: schedule disconnect and shutdown immediately
  *
@@ -455,9 +468,12 @@ abort_test (long line)
   if (NULL != disconnect_task)
   {
     GNUNET_SCHEDULER_cancel (disconnect_task);
-    GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Aborting test from %ld\n", line);
+    GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
+               "Aborting test from %ld\n",
+               line);
     disconnect_task =
-        GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers, (void *) line);
+        GNUNET_SCHEDULER_add_now (&disconnect_cadet_peers,
+                                 (void *) line);
   }
 }
 
@@ -579,7 +595,7 @@ reschedule_timeout_task (long line)
     if (NULL != disconnect_task)
     {
       GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-                  " reschedule timeout every 10 messages\n");
+                  "reschedule timeout every 10 messages\n");
       GNUNET_SCHEDULER_cancel (disconnect_task);
       disconnect_task = GNUNET_SCHEDULER_add_delayed (short_time,
                                                       &gather_stats_and_exit,
@@ -613,7 +629,8 @@ check_data (void *cls, const struct GNUNET_MessageHeader *message)
  * @param message the actual message
  */
 static void
-handle_data (void *cls, const struct GNUNET_MessageHeader *message)
+handle_data (void *cls,
+            const struct GNUNET_MessageHeader *message)
 {
   struct CadetTestChannelWrapper *ch = cls;
   struct GNUNET_CADET_Channel *channel = ch->ch;
@@ -778,19 +795,21 @@ connect_handler (void *cls, struct GNUNET_CADET_Channel *channel,
  * @param channel Connection to the other end (henceforth invalid).
  */
 static void
-disconnect_handler (void *cls, const struct GNUNET_CADET_Channel *channel)
+disconnect_handler (void *cls,
+                   const struct GNUNET_CADET_Channel *channel)
 {
   struct CadetTestChannelWrapper *ch_w = cls;
 
-  GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Channel disconnected\n");
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+             "Channel disconnected at %d\n",
+             ok);
   GNUNET_assert (ch_w->ch == channel);
   if (channel == incoming_ch)
   {
     ok++;
     incoming_ch = NULL;
   }
-  else if (outgoing_ch == channel
-  )
+  else if (outgoing_ch == channel)
   {
     if (P2P_SIGNAL == test)
     {
@@ -799,14 +818,15 @@ disconnect_handler (void *cls, const struct GNUNET_CADET_Channel *channel)
     outgoing_ch = NULL;
   }
   else
-    GNUNET_log (GNUNET_ERROR_TYPE_WARNING, "Unknown channel! %p\n", channel);
-  GNUNET_log (GNUNET_ERROR_TYPE_INFO, " ok: %d\n", ok);
-
+    GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+               "Unknown channel! %p\n",
+               channel);
   if (NULL != disconnect_task)
   {
     GNUNET_SCHEDULER_cancel (disconnect_task);
     disconnect_task =
-        GNUNET_SCHEDULER_add_now (&gather_stats_and_exit, (void *) __LINE__);
+        GNUNET_SCHEDULER_add_now (&gather_stats_and_exit,
+                                 (void *) __LINE__);
   }
 }
 
@@ -887,25 +907,34 @@ start_test (void *cls)
  *             NULL if the operation is successfull
  */
 static void
-pi_cb (void *cls, struct GNUNET_TESTBED_Operation *op,
-       const struct GNUNET_TESTBED_PeerInformation *pinfo, const char *emsg)
+pi_cb (void *cls,
+       struct GNUNET_TESTBED_Operation *op,
+       const struct GNUNET_TESTBED_PeerInformation *pinfo,
+       const char *emsg)
 {
   long i = (long) cls;
 
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "ID callback for %ld\n", i);
-
-  if ((NULL == pinfo) || (NULL != emsg))
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+             "ID callback for %ld\n",
+             i);
+  if ( (NULL == pinfo) ||
+       (NULL != emsg) )
   {
-    GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "pi_cb: %s\n", emsg);
+    GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
+               "pi_cb: %s\n",
+               emsg);
     abort_test (__LINE__);
     return;
   }
   p_id[i] = pinfo->result.id;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "  id: %s\n", GNUNET_i2s (p_id[i]));
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+             "id: %s\n",
+             GNUNET_i2s (p_id[i]));
   p_ids++;
   if (p_ids < 2)
     return;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Got all IDs, starting test\n");
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+             "Got all IDs, starting test\n");
   test_task = GNUNET_SCHEDULER_add_now (&start_test, NULL);
 }
 
@@ -937,7 +966,8 @@ tmain (void *cls,
   disconnect_task = GNUNET_SCHEDULER_add_delayed (short_time,
                                                   &disconnect_cadet_peers,
                                                   (void *) __LINE__);
-  GNUNET_SCHEDULER_add_shutdown (&shutdown_task, NULL);
+  GNUNET_SCHEDULER_add_shutdown (&shutdown_task,
+                                NULL);
   t_op[0] = GNUNET_TESTBED_peer_get_information (peers[0],
                                                  GNUNET_TESTBED_PIT_IDENTITY,
                                                  &pi_cb,