From 18a677a335becdb59d22cc60a04253268ed2ecd6 Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Tue, 2 Jan 2018 01:22:04 +0100 Subject: fix issue with sending BROKEN timeouts early due to wrong timeout calculation --- src/cadet/cadet_api.c | 6 ++ src/cadet/gnunet-service-cadet_core.c | 9 ++- src/cadet/test_cadet.c | 100 ++++++++++++++++++++++------------ 3 files changed, 79 insertions(+), 36 deletions(-) (limited to 'src') diff --git a/src/cadet/cadet_api.c b/src/cadet/cadet_api.c index 366e31405..497c9a4f0 100644 --- 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 99957d8a1..84aff1857 100644 --- 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 bc4414054..5cc9706d7 100644 --- 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, -- cgit v1.2.3