improved logging for eval tool

fix for proportional solver: reset calculated quota after assigning

2 files changed, 62 insertions, 16 deletions

diff --git a/src/ats/gnunet-ats-solver-eval.c b/src/ats/gnunet-ats-solver-eval.c
index 7a74833e8..c1ab82991 100644
--- a/src/ats/gnunet-ats-solver-eval.c
+++ b/src/ats/gnunet-ats-solver-eval.c
@@ -230,7 +230,7 @@ GNUNET_ATS_solver_logging_now (struct LoggingHandle *l)
       }
       GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "\t Active = %i\n", log_a->active);
       GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "\t BW in = %llu\n", ntohl(log_a->assigned_bw_in.value__));
-      GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "\t BW out = %llu\n", ntohl(log_a->assigned_bw_out.value__));
+      GNUNET_log (GNUNET_ERROR_TYPE_INFO, "\t BW out = %llu\n", ntohl(log_a->assigned_bw_out.value__));
 
       GNUNET_CONTAINER_DLL_insert_tail (log_p->addr_head, log_p->addr_tail, log_a);
     }
@@ -345,22 +345,22 @@ GNUNET_ATS_solver_logging_write_to_disk (struct LoggingHandle *l, int add_time_s
           cur->pid = log_p->id;
 
           if (GNUNET_YES == add_time_stamp)
-            GNUNET_asprintf (&filename, "%s%s%s_%s_%u_%u_%llu.log",
+            GNUNET_asprintf (&filename, "%s%s%s_%s_p%u_a%u_%llu.log",
                 (GNUNET_YES == use_dir) ? output_dir : "",
                 (GNUNET_YES == use_dir) ? DIR_SEPARATOR_STR : "",
                 e->log_prefix,
                 opt_solver,
-                cur->aid,
                 cur->pid,
+                cur->aid,
                 l->head->timestamp.abs_value_us);
           else
-            GNUNET_asprintf (&filename, "%s%s%s_%s_%u_%u.log",
+            GNUNET_asprintf (&filename, "%s%s%s_%s_p%u_a%u.log",
                 (GNUNET_YES == use_dir) ? output_dir : "",
                 (GNUNET_YES == use_dir) ? DIR_SEPARATOR_STR : "",
                 e->log_prefix,
                 opt_solver,
-                cur->aid,
-                cur->pid);
+                cur->pid,
+                cur->aid);
 
           fprintf (stderr, "Add writing log data for peer %llu address %llu to file `%s'\n",
               cur->pid, cur->aid, filename);
@@ -2131,13 +2131,19 @@ enforce_del_address (struct GNUNET_ATS_TEST_Operation *op)
     GNUNET_ATS_solver_generate_property_stop (pg);
   }
 
-  GNUNET_CONTAINER_DLL_remove(p->addr_head, p->addr_tail, a);
   GNUNET_CONTAINER_multipeermap_remove (sh->addresses, &p->peer_id, a->ats_addr);
 
   GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Removing address %u for peer %u\n",
       op->address_id, op->peer_id);
 
   sh->env.sf.s_del (sh->solver, a->ats_addr, GNUNET_NO);
+
+  if (NULL != l)
+  {
+    GNUNET_ATS_solver_logging_now (l);
+  }
+  GNUNET_CONTAINER_DLL_remove(p->addr_head, p->addr_tail, a);
+
   GNUNET_free_non_null(a->ats_addr->atsi);
   GNUNET_free (a->ats_addr);
   GNUNET_free (a);
@@ -2252,10 +2258,12 @@ enforce_start_request (struct GNUNET_ATS_TEST_Operation *op)
   res = sh->env.sf.s_get (sh->solver, &p->peer_id);
   if (NULL != res)
   {
-    GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Requesting address for peer %u: %llu %llu\n",
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Suggested address for peer %u: %llu %llu\n",
         op->peer_id,
         ntohl(res->assigned_bw_in.value__),
         ntohl(res->assigned_bw_out.value__));
+    if (NULL != l)
+      GNUNET_ATS_solver_logging_now (l);
   }
 }
 
@@ -2276,6 +2284,12 @@ enforce_stop_request (struct GNUNET_ATS_TEST_Operation *op)
       op->peer_id);
 
   sh->env.sf.s_get_stop (sh->solver, &p->peer_id);
+
+  if (NULL != l)
+  {
+    GNUNET_ATS_solver_logging_now (l);
+  }
+
 }
 
 static void enforce_episode (struct Episode *ep)
@@ -2782,10 +2796,13 @@ solver_bandwidth_changed_cb (void *cls, struct ATS_Address *address)
               "Bandwidth changed addresses %s %p to %u Bps out / %u Bps in\n",
               GNUNET_i2s (&address->peer),
               address,
-              (unsigned int) ntohl (address->assigned_bw_out.value__),
+              (unsigned int) ntohl  (address->assigned_bw_out.value__),
               (unsigned int) ntohl (address->assigned_bw_in.value__));
   /*if (GNUNET_YES == ph.bulk_running)
     GNUNET_break (0);*/
+  if (NULL != l)
+    GNUNET_ATS_solver_logging_now (l);
+
   return;
 }
 
diff --git a/src/ats/plugin_ats_proportional.c b/src/ats/plugin_ats_proportional.c
index 77c7315aa..5798fd82e 100644
--- a/src/ats/plugin_ats_proportional.c
+++ b/src/ats/plugin_ats_proportional.c
@@ -573,13 +573,15 @@ distribute_bandwidth (struct GAS_PROPORTIONAL_Handle *s,
   unsigned long long assigned_quota_out = 0;
 
 
-  LOG(GNUNET_ERROR_TYPE_DEBUG,
+  LOG(GNUNET_ERROR_TYPE_INFO,
       "Recalculate quota for network type `%s' for %u addresses (in/out): %llu/%llu \n",
       net->desc, net->active_addresses, net->total_quota_in,
       net->total_quota_in);
 
   if (net->active_addresses == 0)
+  {
     return; /* no addresses to update */
+  }
 
   /* Idea
    * Assign every peer in network minimum Bandwidth
@@ -641,7 +643,7 @@ distribute_bandwidth (struct GAS_PROPORTIONAL_Handle *s,
       assigned_quota_out = min_bw
           + ((cur_pref / total_prefs) * remaining_quota_out);
 
-      LOG(GNUNET_ERROR_TYPE_DEBUG,
+      LOG (GNUNET_ERROR_TYPE_INFO,
           "New quota for peer `%s' with preference (cur/total) %.3f/%.3f (in/out): %llu / %llu\n",
           GNUNET_i2s (&cur->addr->peer), cur_pref, total_prefs,
           assigned_quota_in, assigned_quota_out);
@@ -829,7 +831,20 @@ propagate_bandwidth (struct GAS_PROPORTIONAL_Handle *s,
            (cur->addr->assigned_bw_out.value__ != asi->calculated_quota_out_NBO) )
       {
         cur->addr->assigned_bw_in.value__ = asi->calculated_quota_in_NBO;
-        cur->addr->assigned_bw_out.value__ = asi->calculated_quota_in_NBO;
+        cur->addr->assigned_bw_out.value__ = asi->calculated_quota_out_NBO;
+
+        /* Reset for next iteration */
+        asi->calculated_quota_in_NBO = htonl (0);
+        asi->calculated_quota_out_NBO = htonl (0);
+
+        LOG (GNUNET_ERROR_TYPE_DEBUG,
+            "Bandwidth for %s address %p for peer `%s' changed to %u/%u\n",
+            (GNUNET_NO == cur->addr->active) ? "inactive" : "active",
+            cur->addr,
+            GNUNET_i2s (&cur->addr->peer),
+            ntohl (cur->addr->assigned_bw_in.value__),
+            ntohl (cur->addr->assigned_bw_out.value__ ));
+
         /* Notify on change */
         if ((GNUNET_YES == cur->addr->active) && (cur->addr != address_except))
           s->bw_changed (s->bw_changed_cls, cur->addr);
@@ -856,6 +871,11 @@ distribute_bandwidth_in_network (struct GAS_PROPORTIONAL_Handle *s,
 
   if (NULL != n)
   {
+    LOG (GNUNET_ERROR_TYPE_INFO,
+        "Redistributing bandwidth in network %s with %u active and %u total addresses\n",
+        GNUNET_ATS_print_network_type(n->type),
+        n->active_addresses, n->total_addresses);
+
     if (NULL != s->env->info_cb)
       s->env->info_cb(s->env->info_cb_cls, GAS_OP_SOLVE_START,
           GAS_STAT_SUCCESS, GAS_INFO_PROP_SINGLE);
@@ -1174,6 +1194,7 @@ GAS_proportional_get_preferred_address (void *solver,
     prev->active = GNUNET_NO; /* No active any longer */
     prev->assigned_bw_in = BANDWIDTH_ZERO; /* no bandwidth assigned */
     prev->assigned_bw_out = BANDWIDTH_ZERO; /* no bandwidth assigned */
+
     if (GNUNET_SYSERR == addresse_decrement (s, net_prev, GNUNET_NO, GNUNET_YES))
       GNUNET_break(0);
     distribute_bandwidth_in_network (s, net_prev, NULL);
@@ -1212,18 +1233,24 @@ GAS_proportional_stop_get_preferred_address (void *solver,
     GNUNET_assert (GNUNET_OK == GNUNET_CONTAINER_multipeermap_remove (s->requests, peer,
                                           NULL));
 
-  cur = get_active_address (s,
-                            s->addresses, peer);
+  cur = get_active_address (s, s->addresses, peer);
   if (NULL != cur)
   {
+    LOG(GNUNET_ERROR_TYPE_INFO,
+        "Disabling %s address %p for peer `%s'\n",
+        (GNUNET_NO == cur->active) ? "inactive" : "active", cur,
+        GNUNET_i2s (&cur->peer));
+
     /* Disabling current address */
     asi = cur->solver_information;
     cur_net = asi->network ;
     cur->active = GNUNET_NO; /* No active any longer */
     cur->assigned_bw_in = BANDWIDTH_ZERO; /* no bandwidth assigned */
     cur->assigned_bw_out = BANDWIDTH_ZERO; /* no bandwidth assigned */
+
     if (GNUNET_SYSERR == addresse_decrement (s, cur_net, GNUNET_NO, GNUNET_YES))
       GNUNET_break(0);
+
     distribute_bandwidth_in_network (s, cur_net, NULL );
   }
   return;
@@ -1304,6 +1331,8 @@ GAS_proportional_address_delete (void *solver, struct ATS_Address *address,
     address->active = GNUNET_NO;
     address->assigned_bw_in = BANDWIDTH_ZERO;
     address->assigned_bw_out = BANDWIDTH_ZERO;
+    asi->calculated_quota_in_NBO = htonl (0);
+    asi->calculated_quota_out_NBO = htonl (0);
 
     if (GNUNET_SYSERR == addresse_decrement (s, net, GNUNET_NO, GNUNET_YES))
       GNUNET_break(0);
@@ -1604,8 +1633,8 @@ GAS_proportional_address_add (void *solver, struct ATS_Address *address,
 
   asi = GNUNET_new (struct AddressSolverInformation);
   asi->network = net;
-  asi->calculated_quota_in_NBO = 0;
-  asi->calculated_quota_out_NBO = 0;
+  asi->calculated_quota_in_NBO = htonl (0);
+  asi->calculated_quota_out_NBO = htonl (0);
   aw->addr->solver_information = asi;
 
   if (GNUNET_YES == GNUNET_CONTAINER_multipeermap_contains (s->requests, &address->peer))