work on #7965: better exchange /keys handling

2 files changed, 130 insertions, 62 deletions

diff --git a/src/backend/taler-merchant-httpd_exchanges.c b/src/backend/taler-merchant-httpd_exchanges.c
index 0ac2234c..c9b6cc70 100644
--- a/src/backend/taler-merchant-httpd_exchanges.c
+++ b/src/backend/taler-merchant-httpd_exchanges.c
@@ -37,8 +37,13 @@
 #define RETRY_BACKOFF_THRESHOLD GNUNET_TIME_relative_multiply ( \
     GNUNET_TIME_UNIT_SECONDS, 60)
 
-#define FAST_FAIL_THRESHOLD GNUNET_TIME_relative_multiply ( \
-    GNUNET_TIME_UNIT_SECONDS, 2)
+/**
+ * This is how long /keys long-polls for, so we should
+ * allow this time between requests if there is no
+ * answer. See exchange_api_handle.c.
+ */
+#define LONG_POLL_THRESHOLD GNUNET_TIME_relative_multiply ( \
+    GNUNET_TIME_UNIT_SECONDS, 120)
 
 
 /**
@@ -283,6 +288,47 @@ struct TMH_Exchange
   struct GNUNET_SCHEDULER_Task *retry_task;
 
   /**
+   * What state is this exchange in?
+   */
+  enum
+  {
+
+    /**
+     * Downloading /keys failed.
+     */
+    ESTATE_FAILED = -1,
+
+    /**
+     * Nothing was ever done.
+     */
+    ESTATE_INIT = 0,
+
+    /**
+     * We are actively downloading /keys for the first time.
+     */
+    ESTATE_DOWNLOADING_FIRST = 1,
+
+    /**
+     * We finished downloading /keys and the exchange is
+     * ready.
+     */
+    ESTATE_DOWNLOADED = 2,
+
+    /**
+     * We are downloading /keys again after a previous
+     * success.
+     */
+    ESTATE_REDOWNLOADING_SUCCESS = 3,
+
+    /**
+     * We are downloading /keys again after a previous
+     * failure.
+     */
+    ESTATE_REDOWNLOADING_FAILURE = 4
+
+  } state;
+
+  /**
    * true if this exchange is from our configuration and
    * explicitly trusted, false if we need to check each
    * key to be sure it is trusted.
@@ -409,9 +455,12 @@ lookup_exchange (const char *exchange_url)
                                      exchange->url,
                                      &exchange->keys);
   GNUNET_break (qs >= 0);
+  if (qs > 0)
+    exchange->state = ESTATE_DOWNLOADED;
   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
-              "The exchange `%s' is new\n",
-              exchange_url);
+              "The exchange `%s' is new (%d)\n",
+              exchange_url,
+              exchange->state);
   return exchange;
 }
 
@@ -549,8 +598,9 @@ process_find_operations (struct TMH_Exchange *exchange)
 
     kon = NULL;
     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                "Processing find operations for `%s'\n",
-                exchange->url);
+                "Processing find operations for `%s' (%d)\n",
+                exchange->url,
+                exchange->state);
     for (struct TMH_EXCHANGES_KeysOperation *ko = exchange->keys_head;
          NULL != ko;
          ko = kon)
@@ -710,11 +760,33 @@ retry_exchange (void *cls)
   exchange->retry_delay
     = GNUNET_TIME_randomized_backoff (exchange->retry_delay,
                                       RETRY_BACKOFF_THRESHOLD);
+  /* Block for the duration of the long-poller */
   exchange->first_retry
-    = GNUNET_TIME_relative_to_absolute (exchange->retry_delay);
+    = GNUNET_TIME_relative_to_absolute (LONG_POLL_THRESHOLD);
   GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Fetching /keys from exchange %s in retry_exchange()\n",
               exchange->url);
+  switch (exchange->state)
+  {
+  case ESTATE_FAILED:
+    exchange->state = ESTATE_REDOWNLOADING_FAILURE;
+    break;
+  case ESTATE_INIT:
+    exchange->state = ESTATE_DOWNLOADING_FIRST;
+    break;
+  case ESTATE_DOWNLOADING_FIRST:
+    GNUNET_break (0);
+    return;
+  case ESTATE_DOWNLOADED:
+    exchange->state = ESTATE_REDOWNLOADING_SUCCESS;
+    break;
+  case ESTATE_REDOWNLOADING_SUCCESS:
+    GNUNET_break (0);
+    return;
+  case ESTATE_REDOWNLOADING_FAILURE:
+    GNUNET_break (0);
+    return;
+  }
   exchange->conn
     = TALER_EXCHANGE_get_keys (
         TMH_curl_ctx,
@@ -800,11 +872,8 @@ TMH_EXCHANGES_keys4exchange (
     return fo;
   }
   if ( (NULL == exchange->conn) &&
-       (GNUNET_TIME_relative_cmp (
-          GNUNET_TIME_absolute_get_remaining (
-            exchange->first_retry),
-          >,
-          FAST_FAIL_THRESHOLD)) )
+       ( (ESTATE_FAILED == exchange->state) ||
+         (ESTATE_REDOWNLOADING_FAILURE == exchange->state) ) )
   {
     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
                 "Already waiting for `%skeys' for a while, failing query instantly\n",
@@ -815,7 +884,9 @@ TMH_EXCHANGES_keys4exchange (
     return fo;
   }
   GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-              "Next /keys request scheduled for %s\n",
+              "Next %skeys (%d) request scheduled for %s\n",
+              exchange->url,
+              exchange->state,
               GNUNET_TIME_absolute2s (
                 exchange->first_retry));
   /* No activity to launch, we are already doing so. */
@@ -893,9 +964,10 @@ free_exchange_entry (struct TMH_Exchange *exchange)
   struct FeesByWireMethod *f;
 
   GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-              "Releasing %s exchange %s\n",
+              "Releasing %s exchange %s (%d)\n",
               exchange->trusted ? "trusted" : "untrusted",
-              exchange->url);
+              exchange->url,
+              exchange->state);
   GNUNET_CONTAINER_DLL_remove (exchange_head,
                                exchange_tail,
                                exchange);
@@ -946,6 +1018,7 @@ fail_and_retry (struct TMH_Exchange *exchange)
 {
   struct TMH_EXCHANGES_KeysOperation *keys;
 
+  exchange->state = ESTATE_FAILED;
   while (NULL != (keys = exchange->keys_head))
   {
     keys->fc (keys->fc_cls,
@@ -1133,6 +1206,14 @@ keys_mgmt_cb (void *cls,
   exchange->conn = NULL;
   if (MHD_HTTP_OK != kr->hr.http_status)
   {
+    if (GNUNET_TIME_absolute_is_future (exchange->first_retry))
+    {
+      /* /keys failed *before* the long polling threshold.
+         We apply the exponential back-off from now. */
+      exchange->first_retry
+        = GNUNET_TIME_relative_to_absolute (
+            exchange->retry_delay);
+    }
     fail_and_retry (exchange);
     TALER_EXCHANGE_keys_decref (keys);
     return;
@@ -1140,7 +1221,7 @@ keys_mgmt_cb (void *cls,
   if (NULL == exchange->currency)
     exchange->currency = GNUNET_strdup (keys->currency);
   if (0 != strcmp (exchange->currency,
-                     keys->currency))
+                   keys->currency))
   {
     GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
                 "/keys response from `%s' is for currency `%s', but we expected `%s'\n",
@@ -1151,6 +1232,7 @@ keys_mgmt_cb (void *cls,
     TALER_EXCHANGE_keys_decref (keys);
     return;
   }
+  exchange->state = ESTATE_DOWNLOADED;
   TMH_db->preflight (TMH_db->cls);
   for (unsigned int r = 0; r<MAX_RETRIES; r++)
   {
@@ -1241,9 +1323,21 @@ TMH_exchange_check_debit (
 
     if (0 != strcmp (acc->wire_method,
                      wm->wire_method))
+    {
+      GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                  "Exchange %s wire method %s != %s\n",
+                  exchange->url,
+                  acc->wire_method,
+                  wm->wire_method);
       continue;
+    }
     if (NULL != acc->conversion_url)
+    {
+      GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                  "Exchange %s account requires currency conversion (not supported)\n",
+                  exchange->url);
       continue; /* never use accounts with conversion */
+    }
     for (struct Restriction *r = acc->d_head;
          NULL != r;
          r = r->next)
@@ -1256,12 +1350,21 @@ TMH_exchange_check_debit (
         break;
       case TALER_EXCHANGE_AR_DENY:
         ok = false;
+        GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                    "Exchange %s account is disabled\n",
+                    exchange->url);
         break;
       case TALER_EXCHANGE_AR_REGEX:
         if (0 != regexec (&r->details.regex.ex,
                           wm->payto_uri,
                           0, NULL, 0))
+        {
+          GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                      "Exchange %s account regex does not match %s\n",
+                      exchange->url,
+                      wm->payto_uri);
           ok = false;
+        }
         break;
       }
       if (! ok)
diff --git a/src/backend/taler-merchant-httpd_private-post-orders.c b/src/backend/taler-merchant-httpd_private-post-orders.c
index 7d9bc4f0..d46bfa85 100644
--- a/src/backend/taler-merchant-httpd_private-post-orders.c
+++ b/src/backend/taler-merchant-httpd_private-post-orders.c
@@ -39,11 +39,6 @@
 #define MAX_RETRIES 3
 
 /**
- * How long do we wait for /keys from the exchange?
- */
-#define KEYS_TIMEOUT GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_SECONDS, 2)
-
-/**
  * What is the label under which we find/place the merchant's
  * jurisdiction in the locations list by default?
  */
@@ -129,11 +124,6 @@ struct RekeyExchange
    */
   struct TMH_EXCHANGES_KeysOperation *fo;
 
-  /**
-   * Timeout task handle.
-   */
-  struct GNUNET_SCHEDULER_Task *tx;
- 
 };
 
 
@@ -429,7 +419,6 @@ clean_order (void *cls)
                                  oc->pending_reload_tail,
                                  rx);
     TMH_EXCHANGES_keys4exchange_cancel (rx->fo);
-    GNUNET_SCHEDULER_cancel (rx->tx);
     GNUNET_free (rx->url);
     GNUNET_free (rx);
   }
@@ -941,6 +930,10 @@ get_acceptable (void *cls,
 
   res = TMH_exchange_check_debit (exchange,
                                   oc->wm);
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Exchange %s evaluated at %d\n",
+              url,
+              res);
   switch (res)
   {
   case GNUNET_OK:
@@ -1016,8 +1009,6 @@ keys_cb (
     &oc->hc->instance->settings;
 
   rx->fo = NULL;
-  GNUNET_SCHEDULER_cancel (rx->tx);
-  rx->tx = NULL;
   GNUNET_CONTAINER_DLL_remove (oc->pending_reload_head,
                                oc->pending_reload_tail,
                                rx);
@@ -1029,6 +1020,9 @@ keys_cb (
   }
   else
   {
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Got response for %skeys\n",
+                rx->url);
     if ( (settings->use_stefan) &&
          (GNUNET_OK !=
           TALER_amount_is_valid (&oc->max_fee)) )
@@ -1047,32 +1041,6 @@ keys_cb (
 
 
 /**
- * A `/keys` request to an exchange is taking too
- * long, ignore the exchange for now.
- *
- * @param cls a `struct RekeyExchange *`
- */
-static void
-keys_timeout (void *cls)
-{
-  struct RekeyExchange *rx = cls;
-  struct OrderContext *oc = rx->oc;
-
-  rx->tx = NULL;
-  TMH_EXCHANGES_keys4exchange_cancel (rx->fo);
-  rx->fo = NULL;
-  GNUNET_CONTAINER_DLL_remove (oc->pending_reload_head,
-                               oc->pending_reload_tail,
-                               rx);
-  GNUNET_free (rx->url);
-  GNUNET_free (rx);
-  if (NULL != oc->pending_reload_head)
-    return;
-  resume_with_keys (oc);
-}
-
-
-/**
  * Force re-downloading of /keys from @a exchange,
  * we currently have no acceptable exchange, so we
  * should try to get one.
@@ -1095,17 +1063,14 @@ get_exchange_keys (void *cls,
   GNUNET_CONTAINER_DLL_insert (oc->pending_reload_head,
                                oc->pending_reload_tail,
                                rx);
-  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-              "Forcing download of %s/keys\n",
-              url);
+  if (oc->forced_reload)
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Forcing download of %skeys\n",
+                url);
   rx->fo = TMH_EXCHANGES_keys4exchange (url,
                                         oc->forced_reload,
                                         &keys_cb,
                                         rx);
-  rx->tx
-    = GNUNET_SCHEDULER_add_delayed (KEYS_TIMEOUT,
-                                    &keys_timeout,
-                                    rx);
 }