commit 92e1a4ebf55100e9b831ac621b3c9c4ae83511d6
parent 55cf983d4b53dbd4c6d0b9494cb37ed8ec4b9998
Author: Florian Dold <dold@taler.net>
Date: Wed, 26 Aug 2026 01:56:13 +0200
payment: retry merchant lookups and report HTTP status
Diffstat:
5 files changed, 280 insertions(+), 82 deletions(-)
diff --git a/NEWS b/NEWS
@@ -1,4 +1,11 @@
Unreleased:
+ - Payment confirmation retries an order-status GET once when the merchant
+ connection fails before returning any HTTP response. The retry stays
+ within the original five-second deadline, preventing a stale pooled
+ connection from intermittently turning a completed payment into error
+ 9801. Merchant-related error JSON now includes `merchant_http_status',
+ with zero meaning that no HTTP response was received.
+
- High-load operation is now fail-fast and bounded. CONNECTION_LIMIT
defaults to 384 and may not exceed the select()-safe descriptor budget;
PAYMENT_CONNECTION_LIMIT reserves 32 request slots for redemptions, and
diff --git a/src/backend/paivana-httpd_pay.c b/src/backend/paivana-httpd_pay.c
@@ -66,6 +66,13 @@ struct PayRequest;
#define MERCHANT_ORDER_TIMEOUT \
GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_SECONDS, 5)
+/**
+ * Do not start a retry when too little of #MERCHANT_ORDER_TIMEOUT remains to
+ * make another connection useful.
+ */
+#define MERCHANT_RETRY_MIN_BUDGET \
+ GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_MILLISECONDS, 250)
+
/**
* Handle for processing actual payment.
@@ -114,6 +121,14 @@ struct PayRequest
struct GNUNET_TIME_Absolute merchant_request_started;
/**
+ * Number of merchant lookup attempts started for this redemption. A GET
+ * that fails before receiving any HTTP response is retried once: the
+ * merchant connection pool can otherwise turn one stale idle connection
+ * into a user-visible payment failure.
+ */
+ unsigned int merchant_lookup_attempts;
+
+ /**
* Response to return, NULL if not yet determined.
*/
struct MHD_Response *response;
@@ -428,6 +443,120 @@ under_our_base_url (const char *website)
}
+static void
+order_status_cb (struct PayRequest *ph,
+ const struct TALER_MERCHANT_GetPrivateOrderResponse *osr);
+
+
+/**
+ * Start one attempt to retrieve the order from the merchant backend.
+ *
+ * The caller owns the request's DLL membership and suspended MHD connection.
+ * On failure this function leaves @e ph->co NULL.
+ *
+ * @param ph payment request
+ * @param timeout remaining overall timeout for this attempt
+ * @return #TALER_EC_NONE on success, an error code otherwise
+ */
+static enum TALER_ErrorCode
+start_merchant_order_lookup (struct PayRequest *ph,
+ struct GNUNET_TIME_Relative timeout)
+{
+ char *paivana_id;
+ enum GNUNET_GenericReturnValue ret;
+ enum TALER_ErrorCode ec;
+
+ GNUNET_assert (NULL == ph->co);
+ ph->co = TALER_MERCHANT_get_private_order_create (PH_merchant_ctx,
+ PH_merchant_base_url,
+ ph->order_id);
+ if (NULL == ph->co)
+ return TALER_EC_GENERIC_INTERNAL_INVARIANT_FAILURE;
+ paivana_id = PAIVANA_HTTPD_compute_paivana_id (ph->expiration,
+ ph->website,
+ &ph->nonce);
+ ret = TALER_MERCHANT_get_private_order_set_options (
+ ph->co,
+ TALER_MERCHANT_get_private_order_option_session_id (paivana_id),
+ TALER_MERCHANT_get_private_order_option_timeout (timeout));
+ GNUNET_free (paivana_id);
+ if (GNUNET_OK != ret)
+ {
+ TALER_MERCHANT_get_private_order_cancel (ph->co);
+ ph->co = NULL;
+ return TALER_EC_GENERIC_INTERNAL_INVARIANT_FAILURE;
+ }
+ ec = TALER_MERCHANT_get_private_order_start (ph->co,
+ &order_status_cb,
+ ph);
+ if (TALER_EC_NONE != ec)
+ {
+ TALER_MERCHANT_get_private_order_cancel (ph->co);
+ ph->co = NULL;
+ return ec;
+ }
+ ph->merchant_lookup_attempts++;
+ return TALER_EC_NONE;
+}
+
+
+/**
+ * Build a Paivana error response caused by a merchant order lookup.
+ *
+ * Keep the standard Taler error shape and its existing @e detail while adding
+ * the status of the merchant request. A zero status explicitly says that no
+ * HTTP response was received.
+ *
+ * @param ec Taler error code
+ * @param detail optional error detail
+ * @param merchant_http_status HTTP status returned by the merchant, or zero
+ * @return MHD response
+ */
+static struct MHD_Response *
+make_merchant_error (enum TALER_ErrorCode ec,
+ const char *detail,
+ unsigned int merchant_http_status)
+{
+ return TALER_MHD_MAKE_JSON_PACK (
+ TALER_MHD_PACK_EC (ec),
+ GNUNET_JSON_pack_conditional (
+ NULL != detail,
+ GNUNET_JSON_pack_string ("detail",
+ detail)),
+ GNUNET_JSON_pack_uint64 ("merchant_http_status",
+ merchant_http_status));
+}
+
+
+/**
+ * Queue a Paivana error caused before a merchant lookup returned.
+ *
+ * @param connection client connection
+ * @param http_status status to return to the client
+ * @param ec Taler error code
+ * @param detail optional error detail
+ * @return MHD result
+ */
+static enum MHD_Result
+reply_with_merchant_error (struct MHD_Connection *connection,
+ unsigned int http_status,
+ enum TALER_ErrorCode ec,
+ const char *detail)
+{
+ struct MHD_Response *response;
+ enum MHD_Result ret;
+
+ response = make_merchant_error (ec,
+ detail,
+ 0);
+ ret = MHD_queue_response (connection,
+ http_status,
+ response);
+ MHD_destroy_response (response);
+ return ret;
+}
+
+
/**
* Check that the @a contract that was paid is reasonable for the
* request in @a ph, that is that we would indeed consider this
@@ -479,8 +608,9 @@ check_contract (struct PayRequest *ph,
fields is already what GNUNET_JSON_parse() does; a failure here
means a field we do look at was malformed. */
GNUNET_break_op (0);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_WRONG_ORDER,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_WRONG_ORDER,
+ ph->order_id,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_CONFLICT;
return false;
}
@@ -489,8 +619,9 @@ check_contract (struct PayRequest *ph,
ph->website)) )
{
GNUNET_break_op (0);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_WRONG_ORDER,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_WRONG_ORDER,
+ ph->order_id,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_CONFLICT;
return false;
}
@@ -502,8 +633,9 @@ check_contract (struct PayRequest *ph,
the target given is not from our domain or not a well-formed
URL. Reject hard. */
GNUNET_break_op (0);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_INVALID_TARGET,
- ph->website);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_INVALID_TARGET,
+ ph->website,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_CONFLICT;
return false;
}
@@ -512,8 +644,9 @@ check_contract (struct PayRequest *ph,
max_time))
{
GNUNET_break_op (0);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_TOO_LATE,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_TOO_LATE,
+ ph->order_id,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_GONE;
return false;
}
@@ -548,6 +681,51 @@ order_status_cb (struct PayRequest *ph,
true));
active_lookups = active_merchant_lookups;
ph->co = NULL;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Merchant order lookup attempt %u for `%s' completed with"
+ " HTTP status %u after %s\n",
+ ph->merchant_lookup_attempts,
+ ph->order_id,
+ osr->hr.http_status,
+ elapsed_s);
+ if ( (0 == osr->hr.http_status) &&
+ (NULL == osr->hr.reply) &&
+ (1 == ph->merchant_lookup_attempts) &&
+ GNUNET_TIME_relative_cmp (elapsed,
+ <,
+ MERCHANT_ORDER_TIMEOUT) )
+ {
+ struct GNUNET_TIME_Relative remaining
+ = GNUNET_TIME_relative_subtract (MERCHANT_ORDER_TIMEOUT,
+ elapsed);
+
+ if (GNUNET_TIME_relative_cmp (remaining,
+ >=,
+ MERCHANT_RETRY_MIN_BUDGET))
+ {
+ enum TALER_ErrorCode ec;
+
+ ec = start_merchant_order_lookup (ph,
+ remaining);
+ if (TALER_EC_NONE == ec)
+ {
+ GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+ "Merchant order lookup for `%s' received no HTTP"
+ " response on its first attempt after %s; retrying once"
+ " within the original %s deadline\n",
+ ph->order_id,
+ elapsed_s,
+ timeout_s);
+ GNUNET_free (elapsed_s);
+ GNUNET_free (timeout_s);
+ return;
+ }
+ GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
+ "Could not start the retry of merchant order `%s': %d\n",
+ ph->order_id,
+ (int) ec);
+ }
+ }
GNUNET_CONTAINER_DLL_remove (ph_head,
ph_tail,
ph);
@@ -555,12 +733,6 @@ order_status_cb (struct PayRequest *ph,
active_merchant_lookups--;
MHD_resume_connection (ph->connection);
TALER_MHD_daemon_trigger ();
- GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
- "Merchant order lookup for `%s' completed with HTTP status"
- " %u after %s\n",
- ph->order_id,
- osr->hr.http_status,
- elapsed_s);
if (0 != osr->hr.http_status)
{
unsigned int suppressed = reset_merchant_failure_logs ();
@@ -590,8 +762,9 @@ order_status_cb (struct PayRequest *ph,
(osr->details.ok.details.paid.refund_pending) )
{
GNUNET_break_op (0);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_PAYMENT_MISSING,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_PAYMENT_MISSING,
+ ph->order_id,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_CONFLICT;
}
else
@@ -623,9 +796,10 @@ order_status_cb (struct PayRequest *ph,
&ca_len))
{
GNUNET_break (0);
- ph->response = TALER_MHD_make_error (
+ ph->response = make_merchant_error (
TALER_EC_GENERIC_INTERNAL_INVARIANT_FAILURE,
- ph->order_id);
+ ph->order_id,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_INTERNAL_SERVER_ERROR;
break;
}
@@ -661,9 +835,10 @@ order_status_cb (struct PayRequest *ph,
GNUNET_break (0);
MHD_destroy_response (resp);
GNUNET_free (cookie);
- ph->response = TALER_MHD_make_error (
+ ph->response = make_merchant_error (
TALER_EC_GENERIC_INTERNAL_INVARIANT_FAILURE,
- ph->website);
+ ph->website,
+ MHD_HTTP_OK);
ph->response_status = MHD_HTTP_INTERNAL_SERVER_ERROR;
break;
}
@@ -696,13 +871,15 @@ order_status_cb (struct PayRequest *ph,
" %u); check MERCHANT_ACCESS_TOKEN\n",
PH_merchant_base_url,
osr->hr.http_status);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_BACKEND_REFUSED,
- NULL);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_BACKEND_REFUSED,
+ NULL,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_INTERNAL_SERVER_ERROR;
break;
case MHD_HTTP_NOT_FOUND:
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_ORDER_UNKNOWN,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_ORDER_UNKNOWN,
+ ph->order_id,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_NOT_FOUND;
break;
case 0:
@@ -727,8 +904,9 @@ order_status_cb (struct PayRequest *ph,
elapsed_s,
suppressed,
(1 == suppressed) ? "" : "s");
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_BACKEND_ERROR,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_BACKEND_ERROR,
+ ph->order_id,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_BAD_GATEWAY;
break;
}
@@ -763,8 +941,9 @@ order_status_cb (struct PayRequest *ph,
}
/* GENERIC_TIMEOUT's hint ("trying again might help") is the one
that is true once our own deadline was actually reached. */
- ph->response = TALER_MHD_make_error (TALER_EC_GENERIC_TIMEOUT,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_GENERIC_TIMEOUT,
+ ph->order_id,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_GATEWAY_TIMEOUT;
}
else
@@ -799,8 +978,9 @@ order_status_cb (struct PayRequest *ph,
suppressed,
(1 == suppressed) ? "" : "s");
}
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_BACKEND_REFUSED,
- ph->order_id);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_BACKEND_REFUSED,
+ ph->order_id,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_BAD_GATEWAY;
}
break;
@@ -815,8 +995,9 @@ order_status_cb (struct PayRequest *ph,
sizeof (code),
"%u",
osr->hr.http_status);
- ph->response = TALER_MHD_make_error (TALER_EC_PAIVANA_BACKEND_ERROR,
- code);
+ ph->response = make_merchant_error (TALER_EC_PAIVANA_BACKEND_ERROR,
+ code,
+ osr->hr.http_status);
ph->response_status = MHD_HTTP_BAD_GATEWAY;
}
break;
@@ -909,34 +1090,6 @@ PAIVANA_HTTPD_payment_handle (struct PayRequest *ph,
"expiration");
}
}
- GNUNET_assert (NULL == ph->co);
- ph->co = TALER_MERCHANT_get_private_order_create (PH_merchant_ctx,
- PH_merchant_base_url,
- ph->order_id);
- if (NULL == ph->co)
- {
- GNUNET_break (0);
- return TALER_MHD_reply_with_error (ph->connection,
- MHD_HTTP_INTERNAL_SERVER_ERROR,
- TALER_EC_PAIVANA_GET_ORDER_FAILED,
- ph->order_id);
- }
- {
- char *paivana_id;
-
- paivana_id = PAIVANA_HTTPD_compute_paivana_id (ph->expiration,
- ph->website,
- &ph->nonce);
- GNUNET_assert (
- GNUNET_OK ==
- TALER_MERCHANT_get_private_order_set_options (
- ph->co,
- TALER_MERCHANT_get_private_order_option_session_id (
- paivana_id),
- TALER_MERCHANT_get_private_order_option_timeout (
- MERCHANT_ORDER_TIMEOUT)));
- GNUNET_free (paivana_id);
- }
GNUNET_CONTAINER_DLL_insert (ph_head,
ph_tail,
ph);
@@ -946,9 +1099,8 @@ PAIVANA_HTTPD_payment_handle (struct PayRequest *ph,
enum TALER_ErrorCode ec;
ph->merchant_request_started = GNUNET_TIME_absolute_get ();
- ec = TALER_MERCHANT_get_private_order_start (ph->co,
- &order_status_cb,
- ph);
+ ec = start_merchant_order_lookup (ph,
+ MERCHANT_ORDER_TIMEOUT);
if (TALER_EC_NONE != ec)
{
/* Everything the callee can fail on here is a resource failure
@@ -963,12 +1115,10 @@ PAIVANA_HTTPD_payment_handle (struct PayRequest *ph,
GNUNET_assert (active_merchant_lookups > 0);
active_merchant_lookups--;
MHD_resume_connection (ph->connection);
- TALER_MERCHANT_get_private_order_cancel (ph->co);
- ph->co = NULL;
- return TALER_MHD_reply_with_error (ph->connection,
- MHD_HTTP_INTERNAL_SERVER_ERROR,
- TALER_EC_PAIVANA_GET_ORDER_FAILED,
- ph->order_id);
+ return reply_with_merchant_error (ph->connection,
+ MHD_HTTP_INTERNAL_SERVER_ERROR,
+ TALER_EC_PAIVANA_GET_ORDER_FAILED,
+ ph->order_id);
}
}
return MHD_YES;
diff --git a/src/tests/README b/src/tests/README
@@ -902,14 +902,17 @@ Payment-backend failure diagnostics
-----------------------------------
`test_payment_backend_failure.sh` starts paivana against a small Python
-merchant stub, lets template loading finish, and then stops the stub. A
-redemption against the now-refused port must return promptly as 502 / error
-9801, with the elapsed time and active/consecutive lookup counts in the log;
-it must not claim that the five-second deadline elapsed. The stub is then
-restarted to prove that a real HTTP response resets the consecutive-failure
-count, and finally holds an order lookup open long enough to verify the true
-timeout path remains 504 / error 11. It needs neither PostgreSQL nor a full
-Taler deployment.
+merchant stub and first drops an order lookup before sending any HTTP
+response. Paivana must retry that idempotent GET once within its original
+five-second budget and return the second attempt's response. The test then
+stops the stub: a redemption against the now-refused port must return promptly
+as 502 / error 9801, with the elapsed time and active/consecutive lookup counts
+in the log and `merchant_http_status: 0' in the error JSON; it must not claim
+that the five-second deadline elapsed. The 404 cases likewise assert the
+actual merchant status in that field. The stub is restarted to prove that a
+real HTTP response resets the consecutive-failure count, and finally holds an
+order lookup open long enough to verify the true timeout path remains 504 /
+error 11. It needs neither PostgreSQL nor a full Taler deployment.
The paywall suite
diff --git a/src/tests/payment_backend_stub.py b/src/tests/payment_backend_stub.py
@@ -17,6 +17,8 @@ CONTRACT_PADDING = int(os.environ.get("PAIVANA_STUB_CONTRACT_PADDING", "0"))
DETAIL_DELAY = float(os.environ.get("PAIVANA_STUB_DETAIL_DELAY", "0"))
detail_lock = threading.Lock()
active_details = 0
+retry_order_dropped = False
+retry_order_lock = threading.Lock()
def template_ids():
@@ -98,6 +100,24 @@ class Handler(BaseHTTPRequestHandler):
time.sleep(10)
self.reply(404, {"code": 2906, "hint": "late test reply"})
return
+ if path == "/private/orders/retry-order":
+ global retry_order_dropped
+ with retry_order_lock:
+ drop = not retry_order_dropped
+ retry_order_dropped = True
+ if drop:
+ # Simulate a pooled connection that the backend closed while
+ # it was idle: the request reached the server, but no HTTP
+ # response reached Paivana. The idempotent lookup should be
+ # retried once on another connection.
+ print("dropping first /private/orders/retry-order request",
+ flush=True)
+ self.close_connection = True
+ self.connection.shutdown(2)
+ self.connection.close()
+ return
+ self.reply(404, {"code": 2906, "hint": "unknown test order"})
+ return
if path.startswith("/private/orders/"):
self.reply(404, {"code": 2906, "hint": "unknown test order"})
return
diff --git a/src/tests/test_payment_backend_failure.sh b/src/tests/test_payment_backend_failure.sh
@@ -83,8 +83,9 @@ function redeem() {
}
function expect_error() {
- local want_code="$1" want_detail="$2"
- python3 - "$SCRATCH/response.json" "$want_code" "$want_detail" <<'PY'
+ local want_code="$1" want_detail="$2" want_merchant_status="$3"
+ python3 - "$SCRATCH/response.json" "$want_code" "$want_detail" \
+ "$want_merchant_status" <<'PY'
import json
import sys
@@ -94,6 +95,11 @@ if body.get("code") != int(sys.argv[2]):
raise SystemExit(f"error code {body.get('code')}, want {sys.argv[2]}: {body}")
if body.get("detail") != sys.argv[3]:
raise SystemExit(f"detail {body.get('detail')!r}, want {sys.argv[3]!r}")
+if body.get("merchant_http_status") != int(sys.argv[4]):
+ raise SystemExit(
+ f"merchant_http_status {body.get('merchant_http_status')!r}, "
+ f"want {sys.argv[4]}: {body}"
+ )
PY
}
@@ -134,6 +140,18 @@ start_stub
PAIVANA_PID=$!
wait_for_port "$PAIVANA_PORT" "$PAIVANA_PID" || fail "paivana did not start"
+# Losing a merchant connection before any response is safe to retry because
+# the order lookup is a GET. The stub drops retry-order's first lookup and
+# answers its second, reproducing the stale-idle-connection failure seen in
+# production without making the test depend on a TCP keepalive timeout.
+read -r status elapsed < <(redeem retry-order)
+[ "$status" = "404" ] || fail "retried merchant lookup returned HTTP $status"
+expect_error 9802 retry-order 404 || fail "unexpected retry response JSON"
+grep -q "retrying once within the original 5 s deadline" \
+ "$SCRATCH/paivana.log" || fail "merchant retry diagnostic missing"
+[ "$(grep -c '/private/orders/retry-order' "$SCRATCH/merchant.log")" = 2 ] || \
+ fail "merchant lookup was not attempted exactly twice"
+
# A refused connection completes immediately. It must no longer be
# presented as a five-second timeout.
kill -TERM "$STUB_PID"
@@ -141,7 +159,7 @@ wait "$STUB_PID" || true
STUB_PID=""
read -r status elapsed < <(redeem transport-failure)
[ "$status" = "502" ] || fail "early transport failure returned HTTP $status"
-expect_error 9801 transport-failure || fail "unexpected early-failure JSON"
+expect_error 9801 transport-failure 0 || fail "unexpected early-failure JSON"
python3 - "$elapsed" <<'PY' || fail "early failure took $elapsed seconds"
import sys
raise SystemExit(0 if float(sys.argv[1]) < 2.0 else 1)
@@ -156,7 +174,7 @@ grep -q "1 concurrent merchant lookup including this one" "$SCRATCH/paivana.log"
start_stub
read -r status elapsed < <(redeem recovered-order)
[ "$status" = "404" ] || fail "recovered backend returned HTTP $status"
-expect_error 9802 recovered-order || fail "unexpected recovery JSON"
+expect_error 9802 recovered-order 404 || fail "unexpected recovery JSON"
grep -q 'answered order .*recovered-order.* after 1 consecutive lookup' \
"$SCRATCH/paivana.log" || fail "recovery diagnostic missing from log"
@@ -164,7 +182,7 @@ grep -q 'answered order .*recovered-order.* after 1 consecutive lookup' \
# genuine timeout and must retain the 504/code-11 response.
read -r status elapsed < <(redeem timeout-order)
[ "$status" = "504" ] || fail "elapsed deadline returned HTTP $status"
-expect_error 11 timeout-order || fail "unexpected timeout JSON"
+expect_error 11 timeout-order 0 || fail "unexpected timeout JSON"
python3 - "$elapsed" <<'PY' || fail "timeout returned after only $elapsed seconds"
import sys
raise SystemExit(0 if float(sys.argv[1]) >= 4.5 else 1)
