-get IBAN test to pass again

10 files changed, 143 insertions, 81 deletions

diff --git a/src/authorization/anastasis_authorization_plugin_iban.c b/src/authorization/anastasis_authorization_plugin_iban.c
index b48aa56..92b4565 100644
--- a/src/authorization/anastasis_authorization_plugin_iban.c
+++ b/src/authorization/anastasis_authorization_plugin_iban.c
@@ -293,6 +293,8 @@ bank_event_cb (void *cls,
     }
     GNUNET_free (amount_s);
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "IBAN event triggers resumption of request handling\n");
   MHD_resume_connection (as->connection);
   as->trigger (as->trigger_cls);
 }
@@ -370,6 +372,8 @@ test_wire_transfers (struct ANASTASIS_AUTHORIZATION_State *as)
   struct GNUNET_TIME_Timestamp limit;
 
   now = GNUNET_TIME_absolute_get ();
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Testing for wire transfers\n");
   limit = GNUNET_TIME_absolute_to_timestamp (
     GNUNET_TIME_absolute_subtract (now,
                                    CODE_VALIDITY_PERIOD));
@@ -395,8 +399,6 @@ test_wire_transfers (struct ANASTASIS_AUTHORIZATION_State *as)
   case GNUNET_DB_STATUS_SUCCESS_ONE_RESULT:
     break;
   }
-  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-              "Marking IBAN challenge as satisfied!\n");
   qs = db->mark_challenge_code_satisfied (
     db->cls,
     &as->truth_uuid,
@@ -523,7 +525,6 @@ iban_solve (struct ANASTASIS_AUTHORIZATION_State *as,
   struct ANASTASIS_DatabasePlugin *db = ctx->ac->db;
   MHD_RESULT mres;
   enum GNUNET_DB_QueryStatus qs;
-  struct MHD_Response *resp;
   struct GNUNET_TIME_Absolute now = GNUNET_TIME_absolute_get ();
   struct GNUNET_TIME_Timestamp after;
 
@@ -535,10 +536,6 @@ iban_solve (struct ANASTASIS_AUTHORIZATION_State *as,
       .code = GNUNET_htonll (as->code)
     };
 
-    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                "Subscribing to events for code %llu from %s\n",
-                (unsigned long long) as->code,
-                as->iban_number);
     GNUNET_CRYPTO_hash (as->iban_number,
                         strlen (as->iban_number),
                         &espec.debit_iban_hash);
@@ -560,12 +557,10 @@ iban_solve (struct ANASTASIS_AUTHORIZATION_State *as,
   {
   case GNUNET_DB_STATUS_HARD_ERROR:
   case GNUNET_DB_STATUS_SOFT_ERROR:
-    resp = TALER_MHD_make_error (TALER_EC_ANASTASIS_TRUTH_AUTH_TIMEOUT,
-                                 "IBAN payment not yet received");
-    mres = MHD_queue_response (connection,
-                               MHD_HTTP_INTERNAL_SERVER_ERROR,
-                               resp);
-    MHD_destroy_response (resp);
+    mres = TALER_MHD_reply_with_error (connection,
+                                       MHD_HTTP_INTERNAL_SERVER_ERROR,
+                                       TALER_EC_GENERIC_DB_FETCH_FAILED,
+                                       "test challenge code satisfied");
     if (MHD_YES != mres)
       return ANASTASIS_AUTHORIZATION_SRES_FAILED_REPLY_FAILED;
     return ANASTASIS_AUTHORIZATION_SRES_FAILED;
@@ -585,17 +580,20 @@ iban_solve (struct ANASTASIS_AUTHORIZATION_State *as,
     }
     if (GNUNET_TIME_absolute_is_future (timeout))
     {
+      GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                  "Suspending IBAN check until %s\n",
+                  GNUNET_TIME_absolute2s (timeout));
       as->connection = connection;
       MHD_suspend_connection (connection);
       return ANASTASIS_AUTHORIZATION_SRES_SUSPENDED;
     }
-
-    resp = TALER_MHD_make_error (TALER_EC_GENERIC_DB_FETCH_FAILED,
-                                 NULL);
-    mres = MHD_queue_response (connection,
-                               MHD_HTTP_FORBIDDEN,
-                               resp);
-    MHD_destroy_response (resp);
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Timeout reached at %s, failing request\n",
+                GNUNET_TIME_absolute2s (timeout));
+    mres = TALER_MHD_reply_with_error (connection,
+                                       MHD_HTTP_FORBIDDEN,
+                                       TALER_EC_ANASTASIS_IBAN_MISSING_TRANSFER,
+                                       NULL);
     if (MHD_YES != mres)
       return ANASTASIS_AUTHORIZATION_SRES_FAILED_REPLY_FAILED;
     return ANASTASIS_AUTHORIZATION_SRES_FAILED;
diff --git a/src/backend/anastasis-httpd_truth-challenge.c b/src/backend/anastasis-httpd_truth-challenge.c
index 9d2429d..30379a7 100644
--- a/src/backend/anastasis-httpd_truth-challenge.c
+++ b/src/backend/anastasis-httpd_truth-challenge.c
@@ -911,7 +911,9 @@ run_authorization_process (struct MHD_Connection *connection,
   case ANASTASIS_AUTHORIZATION_CRES_SUCCESS:
     /* Challenge sent successfully */
     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                "Authorization request sent successfully\n");
+                "Authorization request %llu for %s sent successfully\n",
+                (unsigned long long) gc->code,
+                TALER_B2S (&gc->truth_uuid));
     qs = db->mark_challenge_sent (db->cls,
                                   &gc->payment_identifier,
                                   &gc->truth_uuid,
diff --git a/src/backend/anastasis-httpd_truth-solve.c b/src/backend/anastasis-httpd_truth-solve.c
index 5e72e42..8133cc9 100644
--- a/src/backend/anastasis-httpd_truth-solve.c
+++ b/src/backend/anastasis-httpd_truth-solve.c
@@ -755,6 +755,8 @@ return_key_share (
 static void
 gc_suspended (struct SolveContext *gc)
 {
+  GNUNET_assert (NULL == gc->hn);
+  GNUNET_assert (! gc->suspended);
   gc->suspended = true;
   if (NULL == AH_to_heap)
     AH_to_heap = GNUNET_CONTAINER_heap_create (
@@ -885,6 +887,8 @@ rate_limit (struct SolveContext *gc)
            ? GNUNET_NO
            : GNUNET_SYSERR;
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Using intentionally wrong answer to produce rate-limiting\n");
   /* decrement trial counter */
   ANASTASIS_hash_answer (code + 1,      /* always use wrong answer */
                          &hc);
@@ -968,8 +972,8 @@ handle_security_question (struct SolveContext *gc,
 
 /**
  * Handle special case of an answer being directly checked by the
- * plugin and not by our database. Rate limits answers against brute
- * forcing.
+ * plugin and not by our database.  Also ensures that the
+ * request is rate-limited.
  *
  * @param[in,out] gc request to handle
  * @param decrypted_truth hash to check against
@@ -983,11 +987,11 @@ direct_validation (struct SolveContext *gc,
 {
   /* Non-random code, call plugin directly! */
   enum ANASTASIS_AUTHORIZATION_SolveResult aar;
-  enum GNUNET_GenericReturnValue res;
+  enum GNUNET_GenericReturnValue ret;
 
-  res = rate_limit (gc);
-  if (GNUNET_OK != res)
-    return (GNUNET_NO == res) ? MHD_YES : MHD_NO;
+  ret = rate_limit (gc);
+  if (GNUNET_OK != ret)
+    return (GNUNET_NO == ret) ? MHD_YES : MHD_NO;
   gc->as = gc->authorization->start (gc->authorization->cls,
                                      &AH_trigger_daemon,
                                      NULL,
@@ -1012,7 +1016,7 @@ direct_validation (struct SolveContext *gc,
                                        "solve method not implemented for authorization method");
   }
   aar = gc->authorization->solve (gc->as,
-                                  GNUNET_TIME_UNIT_ZERO_ABS,
+                                  gc->timeout,
                                   &gc->challenge_response,
                                   gc->connection);
   switch (aar)
@@ -1020,6 +1024,74 @@ direct_validation (struct SolveContext *gc,
   case ANASTASIS_AUTHORIZATION_SRES_FAILED:
     return MHD_YES;
   case ANASTASIS_AUTHORIZATION_SRES_SUSPENDED:
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Suspending request handling\n");
+    gc_suspended (gc);
+    return MHD_YES;
+  case ANASTASIS_AUTHORIZATION_SRES_FAILED_REPLY_FAILED:
+    return MHD_NO;
+  case ANASTASIS_AUTHORIZATION_SRES_FINISHED:
+    return return_key_share (&gc->truth_uuid,
+                             gc->connection);
+  }
+  GNUNET_break (0);
+  return MHD_NO;
+}
+
+
+/**
+ * Handle special case of an answer being checked
+ * by the plugin asynchronously (IBAN) after we inverted
+ * the hash using the database.
+ *
+ * @param[in,out] gc request to handle
+ * @param code validation code provided by the client
+ * @param decrypted_truth hash to check against
+ * @param decrypted_truth_size number of bytes in @a decrypted_truth
+ * @return MHD status code
+ */
+static MHD_RESULT
+iban_validation (struct SolveContext *gc,
+                 uint64_t code,
+                 const void *decrypted_truth,
+                 size_t decrypted_truth_size)
+{
+  enum ANASTASIS_AUTHORIZATION_SolveResult aar;
+
+  gc->as = gc->authorization->start (gc->authorization->cls,
+                                     &AH_trigger_daemon,
+                                     NULL,
+                                     &gc->truth_uuid,
+                                     code,
+                                     decrypted_truth,
+                                     decrypted_truth_size);
+  if (NULL == gc->as)
+  {
+    GNUNET_break (0);
+    return TALER_MHD_reply_with_error (gc->connection,
+                                       MHD_HTTP_INTERNAL_SERVER_ERROR,
+                                       TALER_EC_ANASTASIS_TRUTH_AUTHORIZATION_START_FAILED,
+                                       NULL);
+  }
+  if (NULL == gc->authorization->solve)
+  {
+    GNUNET_break (0);
+    return TALER_MHD_reply_with_error (gc->connection,
+                                       MHD_HTTP_INTERNAL_SERVER_ERROR,
+                                       TALER_EC_ANASTASIS_TRUTH_AUTHORIZATION_START_FAILED,
+                                       "solve method not implemented for authorization method");
+  }
+  aar = gc->authorization->solve (gc->as,
+                                  gc->timeout,
+                                  &gc->challenge_response,
+                                  gc->connection);
+  switch (aar)
+  {
+  case ANASTASIS_AUTHORIZATION_SRES_FAILED:
+    return MHD_YES;
+  case ANASTASIS_AUTHORIZATION_SRES_SUSPENDED:
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Suspending request handling\n");
     gc_suspended (gc);
     return MHD_YES;
   case ANASTASIS_AUTHORIZATION_SRES_FAILED_REPLY_FAILED:
@@ -1121,7 +1193,6 @@ AH_handler_truth_solve (
       GNUNET_assert (! gc->suspended);
       return run_authorization_process (connection,
                                         gc);
-
     }
     /* We get here if the async check for payment said this request
        was indeed paid! */
@@ -1353,9 +1424,11 @@ AH_handler_truth_solve (
       if (GNUNET_TIME_absolute_is_past (gc->timeout))
       {
         GNUNET_free (decrypted_truth);
+        GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                    "Timeout with user provided code\n");
         return TALER_MHD_reply_with_error (connection,
                                            MHD_HTTP_FORBIDDEN,
-                                           TALER_EC_ANASTASIS_TRUTH_AUTH_TIMEOUT,
+                                           TALER_EC_ANASTASIS_IBAN_MISSING_TRANSFER,
                                            "timeout awaiting validation");
       }
       res = direct_validation (gc,
@@ -1391,21 +1464,24 @@ AH_handler_truth_solve (
                                          "verify_challenge_code");
     case ANASTASIS_DB_CODE_STATUS_NO_RESULTS:
       GNUNET_free (decrypted_truth);
+      GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                  "Specified challenge code %s was not issued\n",
+                  GNUNET_h2s (&gc->challenge_response));
       return TALER_MHD_reply_with_error (connection,
-                                         MHD_HTTP_NOT_FOUND,
+                                         MHD_HTTP_FORBIDDEN,
                                          TALER_EC_ANASTASIS_TRUTH_CHALLENGE_UNKNOWN,
-                                         NULL);
+                                         "specific challenge code was not issued");
     case ANASTASIS_DB_CODE_STATUS_VALID_CODE_STORED:
-      GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                  "Response code valid (%s)\n",
-                  satisfied ? "satisfied" : "unsatisfied");
       if (! satisfied)
       {
+        MHD_RESULT res;
+
+        res = iban_validation (gc,
+                               code,
+                               decrypted_truth,
+                               decrypted_truth_size);
         GNUNET_free (decrypted_truth);
-        return TALER_MHD_reply_with_error (connection,
-                                           MHD_HTTP_NOT_FOUND,
-                                           TALER_EC_ANASTASIS_TRUTH_CHALLENGE_UNKNOWN,
-                                           NULL);
+        return res;
       }
       GNUNET_free (decrypted_truth);
       return return_key_share (&gc->truth_uuid,
diff --git a/src/cli/test_iban.sh b/src/cli/test_iban.sh
index a5e33f4..fcf932f 100755
--- a/src/cli/test_iban.sh
+++ b/src/cli/test_iban.sh
@@ -1,7 +1,7 @@
 #!/bin/bash
 
 set -eu
-set -x
+#set -x
 
 # Exit, with status code "skip" (no 'real' failure)
 function exit_skip() {
@@ -463,7 +463,7 @@ anastasis-reducer \
 AMOUNT=`jq -r -e .challenge_feedback.\"$IBAN_UUID\".challenge_amount < $R1FILE`
 SUBJECT=`jq -r -e .challenge_feedback.\"$IBAN_UUID\".wire_transfer_subject < $R1FILE`
 
-echo -n "Performing authorization wire transfer ..."
+echo -n "Performing authorization wire transfer ${SUBJECT} ..."
 wire_transfer_to_anastasis "${AMOUNT}" "${SUBJECT}"
 
 echo " OK"
@@ -474,7 +474,7 @@ echo " OK"
 
 # Now we should get the secret...
 echo -n "Polling for recovery ..."
-anastasis-reducer poll < $R2FILE > $R1FILE
+anastasis-reducer poll -L INFO < $R2FILE > $R1FILE
 echo " OK"
 
 echo -n "Checking recovered secret ..."
diff --git a/src/include/anastasis.h b/src/include/anastasis.h
index 473756f..fd1275c 100644
--- a/src/include/anastasis.h
+++ b/src/include/anastasis.h
@@ -278,15 +278,7 @@ enum ANASTASIS_ChallengeAnswerStatus
   /**
    * The rate limit for solving the challenge was exceeded.
    */
-  ANASTASIS_CHALLENGE_ANSWER_STATUS_RATE_LIMIT_EXCEEDED,
-
-  /**
-   * The user did not satisfy the (external) authentication
-   * challenge in time. The request should be repeated
-   * later and may then succeed.
-   */
-  ANASTASIS_CHALLENGE_ANSWER_STATUS_AUTH_TIMEOUT
-
+  ANASTASIS_CHALLENGE_ANSWER_STATUS_RATE_LIMIT_EXCEEDED
 
 };
 
diff --git a/src/lib/anastasis_recovery.c b/src/lib/anastasis_recovery.c
index a9b8b31..c9f8c0e 100644
--- a/src/lib/anastasis_recovery.c
+++ b/src/lib/anastasis_recovery.c
@@ -549,6 +549,9 @@ ANASTASIS_challenge_answer (
   struct GNUNET_HashCode hashed_answer;
 
   GNUNET_free (c->answer);
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Answer to challenge is `%s'\n",
+              answer_str);
   c->answer = GNUNET_strdup (answer_str);
   ANASTASIS_CRYPTO_secure_answer_hash (answer_str,
                                        &c->ci.uuid,
@@ -573,6 +576,9 @@ ANASTASIS_challenge_answer2 (struct ANASTASIS_Challenge *c,
 {
   struct GNUNET_HashCode answer_s;
 
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Answer to challenge is %llu\n",
+              (unsigned long long) answer);
   ANASTASIS_hash_answer (answer,
                          &answer_s);
   return ANASTASIS_challenge_answer3 (c,
diff --git a/src/reducer/anastasis_api_recovery_redux.c b/src/reducer/anastasis_api_recovery_redux.c
index de4df1b..b438afe 100644
--- a/src/reducer/anastasis_api_recovery_redux.c
+++ b/src/reducer/anastasis_api_recovery_redux.c
@@ -1035,31 +1035,6 @@ answer_feedback_cb (
               sctx->state);
     sctx_free (sctx);
     return;
-  case ANASTASIS_CHALLENGE_ANSWER_STATUS_AUTH_TIMEOUT:
-    // FIXME: check if this status code is even properly generated!
-    {
-      json_t *err;
-
-      err = GNUNET_JSON_PACK (
-        GNUNET_JSON_pack_string ("state",
-                                 "authentication-timeout"),
-        GNUNET_JSON_pack_string ("display_hint",
-                                 _ ("Challenge not yet satisfied")),
-        GNUNET_JSON_pack_uint64 ("error_code",
-                                 TALER_EC_ANASTASIS_TRUTH_AUTH_TIMEOUT));
-      GNUNET_assert (0 ==
-                     json_object_set_new (feedback,
-                                          uuid,
-                                          err));
-    }
-    GNUNET_break_op (0);
-    set_state (sctx->state,
-               ANASTASIS_RECOVERY_STATE_CHALLENGE_SELECTING);
-    sctx->cb (sctx->cb_cls,
-              TALER_EC_ANASTASIS_TRUTH_AUTH_TIMEOUT,
-              sctx->state);
-    sctx_free (sctx);
-    return;
   }
   GNUNET_break (0);
   ANASTASIS_redux_fail_ (sctx->cb,
diff --git a/src/stasis/plugin_anastasis_postgres.c b/src/stasis/plugin_anastasis_postgres.c
index 709228f..3b1136d 100644
--- a/src/stasis/plugin_anastasis_postgres.c
+++ b/src/stasis/plugin_anastasis_postgres.c
@@ -2459,6 +2459,10 @@ check_valid_code (void *cls,
       cvc->db_failure = true;
       return;
     }
+    GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                "Found issued challenge %llu (client: %s)\n",
+                (unsigned long long) server_code,
+                GNUNET_h2s (cvc->hashed_code));
     {
       struct GNUNET_HashCode shashed_code;
 
@@ -2468,6 +2472,9 @@ check_valid_code (void *cls,
           GNUNET_memcmp (&shashed_code,
                          cvc->hashed_code))
       {
+        GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+                    "Challenge is valid challenge (%s)\n",
+                    (0 != sat) ? "satisfied" : "not satisfied");
         cvc->valid = true;
         cvc->code = server_code;
         cvc->satisfied = (0 != sat);
@@ -2769,13 +2776,14 @@ postgres_create_challenge_code (
           rollback (pg);
           GNUNET_log (GNUNET_ERROR_TYPE_INFO,
                       "Active challenge %llu has zero tries left, refusing to create another one\n",
-                      (unsigned long long) code);
+                      (unsigned long long) *code);
           return GNUNET_DB_STATUS_SUCCESS_NO_RESULTS;
         }
         rollback (pg);
         GNUNET_log (GNUNET_ERROR_TYPE_INFO,
-                    "Active challenge has %u tries left, returning old challenge\n",
-                    (unsigned int) old_retry_counter);
+                    "Active challenge has %u tries left, returning old challenge %llu\n",
+                    (unsigned int) old_retry_counter,
+                    (unsigned long long) *code);
         return qs;
       }
     }
@@ -2862,6 +2870,9 @@ postgres_mark_challenge_sent (
     if (qs <= 0)
       return qs;
   }
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Marking challenge %llu as issued\n",
+              (unsigned long long) code);
   {
     struct GNUNET_PQ_QueryParam params[] = {
       GNUNET_PQ_query_param_auto_from_type (truth_uuid),
diff --git a/src/testing/testing_cmd_challenge_answer.c b/src/testing/testing_cmd_challenge_answer.c
index 3472793..8e5e2d8 100644
--- a/src/testing/testing_cmd_challenge_answer.c
+++ b/src/testing/testing_cmd_challenge_answer.c
@@ -173,8 +173,6 @@ challenge_answer_cb (void *af_cls,
     return;
   case ANASTASIS_CHALLENGE_ANSWER_STATUS_RATE_LIMIT_EXCEEDED:
     break;
-  case ANASTASIS_CHALLENGE_ANSWER_STATUS_AUTH_TIMEOUT:
-    break;
   }
   TALER_TESTING_interpreter_next (cs->is);
 }
diff --git a/src/util/anastasis_crypto.c b/src/util/anastasis_crypto.c
index b4b87da..3ab8227 100644
--- a/src/util/anastasis_crypto.c
+++ b/src/util/anastasis_crypto.c
@@ -41,6 +41,10 @@ ANASTASIS_hash_answer (uint64_t code,
   GNUNET_CRYPTO_hash (cbuf,
                       strlen (cbuf),
                       hashed_code);
+  GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+              "Hashed answer %llu to %s\n",
+              (unsigned long long) code,
+              GNUNET_h2s (hashed_code));
 }