From 0580168c0e546a7a224c1e9f19e7b526f84cfa2a Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Sun, 11 Jun 2017 17:04:54 +0200 Subject: [PATCH] automated refunds of expired reserves now work and tested, fixes #4956 --- ChangeLog | 4 + src/bank-lib/fakebank.c | 15 ++ src/exchange/taler-exchange-aggregator.c | 99 ++++++++---- src/exchange/taler-exchange-wirewatch.c | 6 +- src/exchange/test_taler_exchange_wirewatch.c | 161 +++++++++++++++++-- src/exchangedb/plugin_exchangedb_postgres.c | 5 + 6 files changed, 242 insertions(+), 48 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); } - TALER_EXCHANGEDB_plugin_unload (db_plugin); - while (NULL != (wp = wp_head)) + if (NULL != ctc) { - 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); + 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); + + { + 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; @@ -740,6 +761,16 @@ static void 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. * @@ -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 @@ -1257,16 +1306,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. * @@ -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 = "expect-deposit-1", + .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 = "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-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-on-start" + .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)