automated refunds of expired reserves now work and tested, fixes #4956

6 files changed, 241 insertions, 47 deletions

diff --git a/ChangeLog b/ChangeLog
index 05b2428c2..c161addcf 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,7 @@
+Sun Jun 11 17:03:56 CEST 2017
+	Finish implementation and testing of automated refunding
+	of expired reserves (#4956). -CG
+
 Tue Jun  6 13:53:34 CEST 2017
 	Releasing taler-exchange 0.3.0. -CG
 
diff --git a/src/bank-lib/fakebank.c b/src/bank-lib/fakebank.c
index 037698c35..268924151 100644
--- a/src/bank-lib/fakebank.c
+++ b/src/bank-lib/fakebank.c
@@ -507,6 +507,12 @@ handle_history (struct TALER_FAKEBANK_Handle *h,
     GNUNET_break (0);
     return MHD_NO;
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Client asked for up to %lld results of type %s for account %llu starting at %s\n",
+              count,
+              dir,
+              (unsigned long long) account_number,
+              start);
   if (NULL == dir)
     direction = TALER_BANK_DIRECTION_BOTH;
   else if (0 == strcasecmp (dir,
@@ -544,6 +550,7 @@ handle_history (struct TALER_FAKEBANK_Handle *h,
     /* list is empty */
     pos = NULL;
   }
+
   history = json_array ();
   while ( (NULL != pos) &&
           (0 != count) )
@@ -551,6 +558,12 @@ handle_history (struct TALER_FAKEBANK_Handle *h,
     json_t *trans;
     char *subject;
 
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Found transaction over %s from %llu to %llu\n",
+                TALER_amount2s (&pos->amount),
+                (unsigned long long) pos->debit_account,
+                (unsigned long long) pos->credit_account);
+
     if (! ( ( (account_number == pos->debit_account) &&
               (0 != (direction & TALER_BANK_DIRECTION_DEBIT)) ) ||
             ( (account_number == pos->credit_account) &&
@@ -595,6 +608,8 @@ handle_history (struct TALER_FAKEBANK_Handle *h,
     struct MHD_Response *resp;
 
     json_decref (history);
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Returning empty transaction history\n");
     resp = MHD_create_response_from_buffer (0,
                                             "",
                                             MHD_RESPMEM_PERSISTENT);
diff --git a/src/exchange/taler-exchange-aggregator.c b/src/exchange/taler-exchange-aggregator.c
index b3711358c..89f72dea5 100644
--- a/src/exchange/taler-exchange-aggregator.c
+++ b/src/exchange/taler-exchange-aggregator.c
@@ -196,6 +196,11 @@ struct CloseTransferContext
    * Wire transfer method.
    */
   char *type;
+
+  /**
+   * Wire plugin used for closing the reserve.
+   */
+  struct WirePlugin *wp;
 };
 
 
@@ -428,8 +433,8 @@ find_plugin (const char *type)
 static void
 shutdown_task (void *cls)
 {
-  struct WirePlugin *wp;
-
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Running shutdown\n");
   if (NULL != task)
   {
     GNUNET_SCHEDULER_cancel (task);
@@ -464,16 +469,32 @@ shutdown_task (void *cls)
     au = NULL;
     GNUNET_free (au);
   }
+  if (NULL != ctc)
+  {
+    ctc->wp->wire_plugin->prepare_wire_transfer_cancel (ctc->wp->wire_plugin->cls,
+                                                        ctc->ph);
+    ctc->ph = NULL;
+    db_plugin->rollback (db_plugin->cls,
+                         ctc->session);
+    GNUNET_free (ctc->type);
+    GNUNET_free (ctc);
+    ctc = NULL;
+  }
   TALER_EXCHANGEDB_plugin_unload (db_plugin);
-  while (NULL != (wp = wp_head))
+
   {
-    GNUNET_CONTAINER_DLL_remove (wp_head,
-                                 wp_tail,
-                                 wp);
-    TALER_WIRE_plugin_unload (wp->wire_plugin);
-    TALER_EXCHANGEDB_fees_free (wp->af);
-    GNUNET_free (wp->type);
-    GNUNET_free (wp);
+    struct WirePlugin *wp;
+
+    while (NULL != (wp = wp_head))
+    {
+      GNUNET_CONTAINER_DLL_remove (wp_head,
+                                   wp_tail,
+                                   wp);
+      TALER_WIRE_plugin_unload (wp->wire_plugin);
+      TALER_EXCHANGEDB_fees_free (wp->af);
+      GNUNET_free (wp->type);
+      GNUNET_free (wp);
+    }
   }
   GNUNET_CONFIGURATION_destroy (cfg);
   cfg = NULL;
@@ -741,6 +762,16 @@ run_aggregation (void *cls);
 
 
 /**
+ * Execute the wire transfers that we have committed to
+ * do.
+ *
+ * @param cls pointer to an `int` which we will return from main()
+ */
+static void
+run_transfers (void *cls);
+
+
+/**
  * Perform a database commit. If it fails, print a warning.
  *
  * @param session session to perform the commit for.
@@ -777,6 +808,9 @@ prepare_close_cb (void *cls,
 		  size_t buf_size)
 {
   GNUNET_assert (cls == ctc);
+
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Prepared for reserve closing\n");
   ctc->ph = NULL;
   if (NULL == buf)
   {
@@ -817,7 +851,9 @@ prepare_close_cb (void *cls,
   GNUNET_free (ctc->type);
   GNUNET_free (ctc);
   ctc = NULL;
-  task = GNUNET_SCHEDULER_add_now (&run_aggregation,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Reserve closure committed, running transfer\n");
+  task = GNUNET_SCHEDULER_add_now (&run_transfers,
 				   NULL);
 }
 
@@ -923,6 +959,12 @@ expired_reserve_cb (void *cls,
 					   &wtid,
 					   left,
 					   closing_fee);
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Closing reserve %s over %s (%d, %d)\n",
+              TALER_B2S (reserve_pub),
+              TALER_amount2s (left),
+              ret,
+              iret);
   if ( (GNUNET_OK == ret) &&
        (GNUNET_OK == iret) )
   {
@@ -939,11 +981,12 @@ expired_reserve_cb (void *cls,
       return GNUNET_SYSERR;
     }
     ctc = GNUNET_new (struct CloseTransferContext);
+    ctc->wp = wp;
     ctc->session = session;
     ctc->type = GNUNET_strdup (type);
     ctc->ph
       = wp->wire_plugin->prepare_wire_transfer (wp->wire_plugin->cls,
-						au->wire,
+						account_details,
 						&amount_without_fee,
 						exchange_base_url,
 						&wtid,
@@ -973,6 +1016,8 @@ expired_reserve_cb (void *cls,
     return GNUNET_SYSERR;
   }
   /* Reserve balance was almost zero; just commit */
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Reserve was virtually empty, moving on\n");
   (void) commit_or_warn (session);
   task = GNUNET_SCHEDULER_add_now (&run_reserve_closures,
 				   NULL);
@@ -998,7 +1043,7 @@ run_reserve_closures (void *cls)
   tc = GNUNET_SCHEDULER_get_task_context ();
   if (0 != (tc->reason & GNUNET_SCHEDULER_REASON_SHUTDOWN))
     return;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Checking for reserves to close\n");
   if (NULL == (session = db_plugin->get_session (db_plugin->cls)))
   {
@@ -1034,6 +1079,8 @@ run_reserve_closures (void *cls)
   }
   if (GNUNET_NO == ret)
   {
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "No more idle reserves, going back to aggregation\n");
     reserves_idle = GNUNET_YES;
     db_plugin->rollback (db_plugin->cls,
                          session);
@@ -1063,13 +1110,13 @@ run_aggregation (void *cls)
   tc = GNUNET_SCHEDULER_get_task_context ();
   if (0 != (tc->reason & GNUNET_SCHEDULER_REASON_SHUTDOWN))
     return;
- if (0 == (++swap % 2))
+  if (0 == (++swap % 2))
   {
     task = GNUNET_SCHEDULER_add_now (&run_reserve_closures,
 				     NULL);
     return;
   }
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Checking for ready deposits to aggregate\n");
   if (NULL == (session = db_plugin->get_session (db_plugin->cls)))
   {
@@ -1111,9 +1158,10 @@ run_aggregation (void *cls)
       GNUNET_SCHEDULER_shutdown ();
       return;
     }
-    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
                 "No more ready deposits, going to sleep\n");
-    if (GNUNET_YES == test_mode)
+    if ( (GNUNET_YES == test_mode) &&
+         (swap >= 2) )
     {
       /* in test mode, shutdown if we end up being idle */
       GNUNET_SCHEDULER_shutdown ();
@@ -1121,7 +1169,8 @@ run_aggregation (void *cls)
     else
     {
       /* nothing to do, sleep for a minute and try again */
-      if (GNUNET_NO == reserves_idle)
+      if ( (GNUNET_NO == reserves_idle) ||
+           (GNUNET_YES == test_mode) )
 	task = GNUNET_SCHEDULER_add_now (&run_reserve_closures,
 					 NULL);
       else
@@ -1258,16 +1307,6 @@ run_aggregation (void *cls)
 
 
 /**
- * Execute the wire transfers that we have committed to
- * do.
- *
- * @param cls pointer to an `int` which we will return from main()
- */
-static void
-run_transfers (void *cls);
-
-
-/**
  * Function to be called with the prepared transfer data.
  *
  * @param cls NULL
@@ -1518,7 +1557,7 @@ run_transfers (void *cls)
   const struct GNUNET_SCHEDULER_TaskContext *tc;
 
   task = NULL;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Checking for pending wire transfers\n");
   tc = GNUNET_SCHEDULER_get_task_context ();
   if (0 != (tc->reason & GNUNET_SCHEDULER_REASON_SHUTDOWN))
diff --git a/src/exchange/taler-exchange-wirewatch.c b/src/exchange/taler-exchange-wirewatch.c
index 0a7923a11..f019f9bcc 100644
--- a/src/exchange/taler-exchange-wirewatch.c
+++ b/src/exchange/taler-exchange-wirewatch.c
@@ -229,7 +229,7 @@ history_cb (void *cls,
   {
     hh = NULL;
 
-    GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
                 "End of list. Committing progress!\n");
     ret = db_plugin->commit (db_plugin->cls,
 			     session);
@@ -254,7 +254,7 @@ history_cb (void *cls,
 				       NULL);
     return GNUNET_OK; /* will be ignored anyway */
   }
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Adding wire transfer over %s with subject `%s'\n",
               TALER_amount2s (&details->amount),
               TALER_B2S (&details->reserve_pub));
@@ -301,7 +301,7 @@ find_transfers (void *cls)
   int ret;
 
   task = NULL;
-  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Checking for incoming wire transfers\n");
 
   if (NULL == (session = db_plugin->get_session (db_plugin->cls)))
diff --git a/src/exchange/test_taler_exchange_wirewatch.c b/src/exchange/test_taler_exchange_wirewatch.c
index f47a126b6..69502d9d4 100644
--- a/src/exchange/test_taler_exchange_wirewatch.c
+++ b/src/exchange/test_taler_exchange_wirewatch.c
@@ -155,7 +155,12 @@ struct Command
       /**
        * Subject of the transfer, set by the command.
        */
-      const char *wtid;
+      const char *subject;
+
+      /**
+       * Serial ID of the wire transfer as assigned by the bank.
+       */
+      uint64_t serial_id;
 
     } run_transfer;
 
@@ -262,7 +267,11 @@ interpreter (void *cls);
 static void
 next_command (struct State *state)
 {
+  GNUNET_assert (NULL == int_task);
   state->ioff++;
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Advancing to command %s\n",
+              state->commands[state->ioff].label);
   int_task = GNUNET_SCHEDULER_add_now (&interpreter,
                                        state);
 }
@@ -274,6 +283,7 @@ next_command (struct State *state)
 static void
 fail (struct Command *cmd)
 {
+  GNUNET_assert (NULL == int_task);
   fprintf (stderr,
            "Testcase failed at command `%s'\n",
            cmd->label);
@@ -308,6 +318,8 @@ shutdown_action (void *cls)
 {
   struct State *state = cls;
 
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Running shutdown\n");
   if (NULL != timeout_task)
   {
     GNUNET_SCHEDULER_cancel (timeout_task);
@@ -364,10 +376,6 @@ shutdown_action (void *cls)
     case OPCODE_RUN_TRANSFER:
       break;
     case OPCODE_WAIT:
-      state->ioff++;
-      int_task = GNUNET_SCHEDULER_add_delayed (cmd->details.wait_delay,
-                                               &interpreter,
-                                               state);
       break;
     case OPCODE_EXPECT_TRANSFER:
       GNUNET_free_non_null (cmd->details.expect_transfer.subject);
@@ -396,6 +404,9 @@ maint_child_death (void *cls)
   struct Command *cmd = &state->commands[state->ioff];
   char c[16];
 
+  GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+              "Child process died for command %s\n",
+              cmd->label);
   pr = GNUNET_DISK_pipe_handle (sigpipe,
                                 GNUNET_DISK_PIPE_END_READ);
   GNUNET_break (0 < GNUNET_DISK_file_read (pr,
@@ -404,12 +415,14 @@ maint_child_death (void *cls)
   switch (cmd->opcode)
   {
   case OPCODE_RUN_AGGREGATOR:
+    GNUNET_assert (NULL != cmd->details.aggregator.child_death_task);
     cmd->details.aggregator.child_death_task = NULL;
     GNUNET_OS_process_wait (cmd->details.aggregator.aggregator_proc);
     GNUNET_OS_process_destroy (cmd->details.aggregator.aggregator_proc);
     cmd->details.aggregator.aggregator_proc = NULL;
     break;
   case OPCODE_RUN_WIREWATCH:
+    GNUNET_assert (NULL != cmd->details.wirewatch.child_death_task);
     cmd->details.wirewatch.child_death_task = NULL;
     GNUNET_OS_process_wait (cmd->details.wirewatch.wirewatch_proc);
     GNUNET_OS_process_destroy (cmd->details.wirewatch.wirewatch_proc);
@@ -423,7 +436,6 @@ maint_child_death (void *cls)
 }
 
 
-
 /**
  * Interprets the commands from the test program.
  *
@@ -435,6 +447,7 @@ interpreter (void *cls)
   struct State *state = cls;
   struct Command *cmd = &state->commands[state->ioff];
 
+  GNUNET_assert (NULL != int_task);
   int_task = NULL;
   GNUNET_log (GNUNET_ERROR_TYPE_INFO,
               "Running command %u (%s)\n",
@@ -499,10 +512,34 @@ interpreter (void *cls)
     }
     return;
   case OPCODE_RUN_TRANSFER:
-    GNUNET_break (0); // FIXME: not implemented!
-    return;
+    {
+      struct TALER_Amount amount;
+
+      if (GNUNET_OK !=
+          TALER_string_to_amount (cmd->details.run_transfer.amount,
+                                  &amount))
+      {
+        GNUNET_break (0);
+        fail (cmd);
+        return;
+      }
+      GNUNET_assert (NULL != cmd->details.run_transfer.subject);
+      cmd->details.run_transfer.serial_id
+        = TALER_FAKEBANK_make_transfer (fb,
+                                        cmd->details.run_transfer.debit_account,
+                                        cmd->details.run_transfer.credit_account,
+                                        &amount,
+                                        cmd->details.run_transfer.subject,
+                                        "https://exchange.taler.net/");
+      next_command (state);
+      return;
+    }
   case OPCODE_WAIT:
-    next_command (state);
+    state->ioff++;
+    GNUNET_assert (NULL == int_task);
+    int_task = GNUNET_SCHEDULER_add_delayed (cmd->details.wait_delay,
+                                             &interpreter,
+                                             state);
     return;
   case OPCODE_EXPECT_TRANSFER:
     {
@@ -537,7 +574,7 @@ interpreter (void *cls)
       return;
     }
     next_command (state);
-    break;
+    return;
   case OPCODE_TERMINATE_SUCCESS:
     result = 0;
     GNUNET_SCHEDULER_shutdown ();
@@ -572,22 +609,100 @@ run (void *cls)
       .opcode = OPCODE_EXPECT_TRANSFERS_EMPTY,
       .label = "expect-empty-transactions-after-dry-run"
     },
+    /* fill exchange's reserve at bank */
     {
-      .opcode = OPCODE_TERMINATE_SUCCESS,
-      .label = "testcase-complete-terminating-with-success"
+      .opcode = OPCODE_RUN_TRANSFER,
+      .label = "run-transfer-good-to-exchange",
+      .details.run_transfer.debit_account = 4,
+      .details.run_transfer.credit_account = 3,
+      .details.run_transfer.subject = "SRB8VQHNTNJWSSG7BXT24Z063ZSXN7T0MHCQCBAFC1V17BZH10D0",
+      .details.run_transfer.amount = "EUR:5.00"
+    },
+    /* creates reserve */
+    {
+      .opcode = OPCODE_RUN_WIREWATCH,
+      .label = "run-wirewatch-on-good-transfer"
+    },
+    /* clear first transfer from DLL */
+    {
+      .opcode = OPCODE_EXPECT_TRANSFER,
+      .label = "clear-good-transfer-to-exchange",
+      .details.expect_transfer.debit_account = 4,
+      .details.expect_transfer.credit_account = 3,
+      .details.expect_transfer.exchange_base_url = "https://exchange.taler.net/",
+      .details.expect_transfer.amount = "EUR:5.00"
+    },
+    /* should do NOTHING, it is too early... */
+    {
+      .opcode = OPCODE_RUN_AGGREGATOR,
+      .label = "run-aggregator-non-expired-reserve"
+    },
+    /* check nothing happened */
+    {
+      .opcode = OPCODE_EXPECT_TRANSFERS_EMPTY,
+      .label = "expect-empty-transactions-1"
     },
+    /* Configuration says reserves expire after 5s! */
+    {
+      .opcode = OPCODE_WAIT,
+      .label = "wait (5s)",
+      .details.wait_delay = { 1000LL * 1000 * 6 } /* 6s */
+    },
+    /* This time the reserve expired, so the money should go back... */
+    {
+      .opcode = OPCODE_RUN_AGGREGATOR,
+      .label = "run-aggregator-non-expired-reserve"
+    },
+    /* Check exchange sent money back, minus closing fee of EUR:0.01  */
     {
       .opcode = OPCODE_EXPECT_TRANSFER,
-      .label = "expect-deposit-1",
+      .label = "check-reserve-expiration-transfer",
       .details.expect_transfer.debit_account = 3,
       .details.expect_transfer.credit_account = 4,
       .details.expect_transfer.exchange_base_url = "https://exchange.taler.net/",
-      .details.expect_transfer.amount = "EUR:0.89"
+      .details.expect_transfer.amount = "EUR:4.99"
     },
+    /* check nothing else happened */
     {
       .opcode = OPCODE_EXPECT_TRANSFERS_EMPTY,
-      .label = "expect-empty-transactions-on-start"
+      .label = "expect-empty-transactions-1"
+    },
+    /* This cannot work unless #5077 is implemented. */
+#if TEST_5077
+    {
+      .opcode = OPCODE_RUN_TRANSFER,
+      .label = "run-transfer-bad-to-exchange",
+      .details.run_transfer.debit_account = 4,
+      .details.run_transfer.credit_account = 3,
+      .details.run_transfer.subject = "random junk",
+      .details.run_transfer.amount = "EUR:5.00"
+    },
+    {
+      .opcode = OPCODE_RUN_WIREWATCH,
+      .label = "run-wirewatch-on-bad-transfer"
+    },
+    {
+      .opcode = OPCODE_EXPECT_TRANSFER,
+      .label = "expect-bad-transfer-to-exchange",
+      .details.expect_transfer.debit_account = 4,
+      .details.expect_transfer.credit_account = 3,
+      .details.expect_transfer.exchange_base_url = "https://exchange.taler.net/",
+      .details.expect_transfer.amount = "EUR:5.00"
+    },
+    {
+      .opcode = OPCODE_EXPECT_TRANSFER,
+      .label = "expect-rewire-transfer-from-exchange",
+      .details.expect_transfer.debit_account = 3,
+      .details.expect_transfer.credit_account = 4,
+      .details.expect_transfer.exchange_base_url = "https://exchange.taler.net/",
+      .details.expect_transfer.amount = "EUR:5.00"
+    },
+    {
+      .opcode = OPCODE_EXPECT_TRANSFERS_EMPTY,
+      .label = "expect-empty-transactions-1"
     },
+#endif
+
     {
       .opcode = OPCODE_TERMINATE_SUCCESS,
       .label = "testcase-complete-terminating-with-success"
@@ -679,6 +794,22 @@ main (int argc,
   }
   GNUNET_OS_process_wait (proc);
   GNUNET_OS_process_destroy (proc);
+  proc = GNUNET_OS_start_process (GNUNET_NO,
+                                  GNUNET_OS_INHERIT_STD_ALL,
+                                  NULL, NULL, NULL,
+                                  "taler-exchange-dbinit",
+                                  "taler-exchange-dbinit",
+                                  "-c", config_filename,
+                                  "-r",
+                                  NULL);
+  if (NULL == proc)
+  {
+    GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
+		"Failed to run `taler-exchange-keyup`, is your PATH correct?\n");
+    return 77;
+  }
+  GNUNET_OS_process_wait (proc);
+  GNUNET_OS_process_destroy (proc);
   if (GNUNET_OK !=
       GNUNET_NETWORK_test_port_free (IPPROTO_TCP,
 				     8082))
diff --git a/src/exchangedb/plugin_exchangedb_postgres.c b/src/exchangedb/plugin_exchangedb_postgres.c
index 929d982f8..2eac21ca7 100644
--- a/src/exchangedb/plugin_exchangedb_postgres.c
+++ b/src/exchangedb/plugin_exchangedb_postgres.c
@@ -2087,6 +2087,11 @@ postgres_reserves_in_insert (void *cls,
     */
   }
 
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Creating reserve %s with expiration in %s\n",
+              TALER_B2S (reserve_pub),
+              GNUNET_STRINGS_relative_time_to_string (pg->idle_reserve_expiration_time,
+                                                      GNUNET_NO));
   expiry = GNUNET_TIME_absolute_add (execution_time,
                                      pg->idle_reserve_expiration_time);
   if (GNUNET_DB_STATUS_SUCCESS_NO_RESULTS == reserve_exists)