diff --git a/CHANGELOG.md b/CHANGELOG.md index 14ec6dcfa5..739d919ce8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,6 +31,12 @@ read every section between yours and the target. ### Breaking +- **Go integrations: `FilterConflictingDuplicateSpendClaims` is replaced by `ProcessSpendBatch` + with a `SpendBatchHandler`.** Out-of-tree callers must migrate; omit `SameChecks` to disable + local result reuse. The `teranode_aerospike_utxo_spend_batch` and `..._size` histograms now + count one batcher batch, however many backend parts it needs, and + `teranode_{aerospike,sql}_utxo_spend_abort_in_flight` counts started inputs handed to the + orphan rollback, no longer dangling ones. (#2036) - **`grpc_admin_api_key` is required.** Blockchain refuses to start if it is empty, a placeholder or under 16 characters, and every RPC but `HealthGRPC` needs it. Give every client service the same key and upgrade Blockchain last, or restart them together. (#1755) diff --git a/Makefile b/Makefile index 30df9b4788..dce5e57a2d 100644 --- a/Makefile +++ b/Makefile @@ -177,7 +177,7 @@ install-tools: .PHONY: test test: @command -v gotestsum >/dev/null 2>&1 || { echo "gotestsum not found. Installing..."; $(MAKE) install-tools; } - SETTINGS_CONTEXT=test $$(go env GOPATH)/bin/gotestsum --format pkgname -- -race -tags "testtxmetacache" -count=1 -timeout=10m -coverprofile=coverage.out -coverpkg=./... $$(go list ./... | grep -v github.com/bsv-blockchain/teranode/test/ | sort) + SETTINGS_CONTEXT=test $$(go env GOPATH)/bin/gotestsum --format pkgname -- -race -tags "testtxmetacache" -count=1 -timeout=20m -coverprofile=coverage.out -coverpkg=./... $$(go list ./... | grep -v github.com/bsv-blockchain/teranode/test/ | sort) # run the tests too slow for `make test` under -race and coverage (TERANODE_HEAVY_TESTS), without -race. # The PR test job runs it after `make test`. diff --git a/docs/references/settings/stores/utxo_settings.md b/docs/references/settings/stores/utxo_settings.md index 431cf69b65..b02cb72ea8 100644 --- a/docs/references/settings/stores/utxo_settings.md +++ b/docs/references/settings/stores/utxo_settings.md @@ -16,6 +16,7 @@ | SpendBatcherSize | int | 100 | utxostore_spendBatcherSize | Spend operation batch size | | SpendBatcherConcurrency | int | 32 | utxostore_spendBatcherConcurrency | SQL per-transaction input-spend cap (`SpendBatcherSize` × this); also caps quick-validation concurrent transactions (`SpendBatcherSize` × this × 2) | | SpendWaitTimeout | time.Duration | 30s | utxostore_spendWaitTimeout | Spend operation wait timeout | +| SpendRollbackTimeout | time.Duration | 120s | utxostore_spendRollbackTimeout | Budget that starts when a failed Spend gives up: a courtesy wait of at most a quarter of it for started inputs, then the partial-spend rollback on the rest, so a failed Spend holds its caller for at most `SpendWaitTimeout` + this value. A started input still unpublished after the wait is rolled back by whoever completes it, with no time bound | | SpendCircuitBreakerFailureCount | int | 10 | utxostore_spendCircuitBreakerFailureCount | Circuit breaker failure threshold (infrastructure-level errors only — see "Spend Circuit Breaker Trigger Set" below) | | SpendCircuitBreakerCooldown | time.Duration | 30s | utxostore_spendCircuitBreakerCooldown | Circuit breaker cooldown period | | SpendCircuitBreakerHalfOpenMax | int | 4 | utxostore_spendCircuitBreakerHalfOpenMax | Circuit breaker half-open max | diff --git a/errors/error_data_utxo_invalid_spend.go b/errors/error_data_utxo_invalid_spend.go new file mode 100644 index 0000000000..7b57917d86 --- /dev/null +++ b/errors/error_data_utxo_invalid_spend.go @@ -0,0 +1,54 @@ +package errors + +import ( + "encoding/json" + "fmt" + + spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" +) + +// UtxoInvalidSpendErrData is the error data of a replayed spend that the store +// rejects as invalid. SpendingData is the stored owner, which equals the claim +// that was rejected. +type UtxoInvalidSpendErrData struct { + SpendingData *spendpkg.SpendingData `json:"spending_data"` +} + +// SetData sets the data for the UtxoInvalidSpendErrData structure. +func (e *UtxoInvalidSpendErrData) SetData(key string, value interface{}) { + if key == "spending_data" { + e.SpendingData, _ = value.(*spendpkg.SpendingData) + } +} + +// GetData retrieves the data for the UtxoInvalidSpendErrData structure based on the key. +func (e *UtxoInvalidSpendErrData) GetData(key string) interface{} { + if key == "spending_data" { + return e.SpendingData + } + + return nil +} + +// Error returns a string representation of the UtxoInvalidSpendErrData error. +func (e *UtxoInvalidSpendErrData) Error() string { + return fmt.Sprintf("invalid spend, stored owner %v", e.SpendingData) +} + +// EncodeErrorData encodes the UtxoInvalidSpendErrData to a byte slice using JSON encoding. +func (e *UtxoInvalidSpendErrData) EncodeErrorData() []byte { + data, err := json.Marshal(e) + if err != nil { + return []byte{} + } + + return data +} + +// NewUtxoInvalidSpendError creates a UTXO error that carries the stored owner of the outpoint. +func NewUtxoInvalidSpendError(spendingData *spendpkg.SpendingData, message string, params ...interface{}) *Error { + invalidSpendError := NewUtxoError(message, params...) + invalidSpendError.data = &UtxoInvalidSpendErrData{SpendingData: spendingData} + + return invalidSpendError +} diff --git a/errors/error_data_utxo_spent_test.go b/errors/error_data_utxo_spent_test.go index 0b3e2c1e8f..01d786974b 100644 --- a/errors/error_data_utxo_spent_test.go +++ b/errors/error_data_utxo_spent_test.go @@ -242,3 +242,27 @@ func TestUtxoSpentErrorMessageCarriesNoCodeRendering(t *testing.T) { require.NotContains(t, err.Error(), "UTXO_SPENT") require.Contains(t, err.Error(), "70: ") } + +func TestNewUtxoInvalidSpendError(t *testing.T) { + txID := chainhash.HashH([]byte("spender")) + owner := spendpkg.NewSpendingData(&txID, 3) + + err := NewUtxoInvalidSpendError(owner, "replay of %s", "owner") + require.ErrorIs(t, err, ErrUtxoError) + require.NotErrorIs(t, err, ErrSpent) + + var data *UtxoInvalidSpendErrData + require.True(t, AsData(err, &data)) + require.Equal(t, owner.Bytes(), data.SpendingData.Bytes()) + require.Equal(t, owner, data.GetData("spending_data")) + require.Nil(t, data.GetData("other")) + + var decoded UtxoInvalidSpendErrData + require.NoError(t, json.Unmarshal(data.EncodeErrorData(), &decoded)) + require.Equal(t, owner.Bytes(), decoded.SpendingData.Bytes()) + + var set UtxoInvalidSpendErrData + set.SetData("spending_data", owner) + require.Equal(t, owner, set.SpendingData) + require.Contains(t, set.Error(), "invalid spend") +} diff --git a/settings/settings_doc_test.go b/settings/settings_doc_test.go index cb76e0c4a1..f472a0e99d 100644 --- a/settings/settings_doc_test.go +++ b/settings/settings_doc_test.go @@ -914,7 +914,7 @@ var checkedRowsPerDoc = map[string]int{ "validator_settings.md": 18, "aerospike_settings.md": 13, "blob_settings.md": 1, - "utxo_settings.md": 43, + "utxo_settings.md": 44, } // exampleKeyRe matches a `key = value` or `key=value` assignment inside the diff --git a/settings/utxostore_settings.go b/settings/utxostore_settings.go index 8f3a239953..82b88e1bd7 100644 --- a/settings/utxostore_settings.go +++ b/settings/utxostore_settings.go @@ -44,7 +44,7 @@ type UtxoStoreSettings struct { OutpointBatcherGreedyAccumulate bool `key:"utxostore_outpointBatcherGreedyAccumulate" desc:"Enable greedy accumulate for outpoint batcher" default:"false" category:"UtxoStore" usage:"Greedy accumulate for previous-outputs decorate operations" type:"bool" longdesc:"### Purpose\nEnables go-batcher greedy-accumulate mode for the outpoint (PreviousOutputsDecorate) batcher independently of other batchers.\n\n### How It Works\nAfter receiving an item the worker opportunistically drains any additional items already waiting on the channel (up to the size cap) into the SAME batch. Never fires early (unlike drain mode).\n\n### Values\n- **Default false** - Behaviour unchanged\n- **true** - Cheaper per-item receive under bursts\n\n### Note\nMutually exclusive with drain mode; enabling both leaves greedy on and rejects drain with a warning."` GetBatcherSize int `key:"utxostore_getBatcherSize" desc:"Batch size for get operations" default:"1" category:"UtxoStore" usage:"Number of get operations per batch" type:"int" longdesc:"### Purpose\nControls the batch size for transaction metadata Get() operations.\n\n### How It Works\n**Special case:** Default 1 effectively disables batching. Get() operations typically isolated (not concurrent) - batching adds latency without benefit.\n\n### Values\n- **Default 1** - Immediate execution without waiting\n- **100-500** - Only if application makes many concurrent Get() calls (e.g., Asset Server bulk transaction queries)\n\n### Behavior\nHigher values wait for multiple concurrent requests or GetBatcherDurationMillis timeout."` GetBatcherDurationMillis int `key:"utxostore_getBatcherDurationMillis" desc:"Batching window for get operations in milliseconds" default:"10" category:"UtxoStore" usage:"Time to accumulate get operations" type:"int" longdesc:"### Purpose\nSets the batching window in milliseconds for Get operations.\n\n### How It Works\nWorks with GetBatcherSize to accumulate concurrent Get() requests.\n\n### Values\n- **Default 10ms** - Quick batching if GetBatcherSize increased\n\n### Note\nWith default GetBatcherSize=1, this setting has minimal effect as requests execute immediately. Relevant only when GetBatcherSize >1 for applications with concurrent Get() patterns."` - SpendRollbackTimeout time.Duration `key:"utxostore_spendRollbackTimeout" desc:"Timeout for rolling back the partial spends of a failed spend batch" default:"120s" category:"UtxoStore" usage:"Budget for the partial-spend rollback, which is len(spends) sequential unspends" type:"duration" longdesc:"### Purpose\nBounds the partial-spend rollback that runs when a batched Spend fails (see #1214). The rollback reverts the spends that already succeeded so no parent is left naming a transaction whose record was never created.\n\n### Why it is separate from SpendWaitTimeout\nSpendWaitTimeout is the end-to-end budget for ONE batched spend. The rollback is len(spentSpends) sequential single-record unspends plus an existence probe, so borrowing that budget truncates the rollback at an input-count-dependent point on wide transactions — and a truncated rollback leaves exactly the dangling spender references it exists to prevent.\n\n### Values\n- **Default 120s** - four times SpendWaitTimeout, so a wide consolidation transaction can complete its rollback\n- **Higher** - if utxo_spend_rollback_failed shows truncation on wide transactions\n\n### Note\nOn overrun the loop aborts and the remaining spends stay applied, counted by utxo_spend_rollback_failed. Batching the unspend removes the need to tune this.\n\n### Also bounds caller latency\nThe rollback runs synchronously on the abort path, so this is additionally the longest a failed or cancelled Spend can block its caller goroutine. Lower it if that latency matters more than rollback completeness."` + SpendRollbackTimeout time.Duration `key:"utxostore_spendRollbackTimeout" desc:"Timeout for rolling back the partial spends of a failed spend batch" default:"120s" category:"UtxoStore" usage:"Budget for the partial-spend rollback, which is len(spends) sequential unspends" type:"duration" longdesc:"### Purpose\nBounds the partial-spend rollback that runs when a batched Spend fails (see #1214). The rollback reverts the spends that already succeeded so no parent is left naming a transaction whose record was never created.\n\n### Why it is separate from SpendWaitTimeout\nSpendWaitTimeout is the end-to-end budget for ONE batched spend. The rollback is len(spentSpends) sequential single-record unspends plus an existence probe, so borrowing that budget truncates the rollback at an input-count-dependent point on wide transactions — and a truncated rollback leaves exactly the dangling spender references it exists to prevent.\n\n### Values\n- **Default 120s** - four times SpendWaitTimeout, so a wide consolidation transaction can complete its rollback\n- **Higher** - if utxo_spend_rollback_failed shows truncation on wide transactions\n\n### Note\nOn overrun the loop aborts and the remaining spends stay applied, counted by utxo_spend_rollback_failed. Batching the unspend removes the need to tune this.\n\n### Also bounds caller latency\nAfter a failed or cancelled Spend gives up, one budget of this length starts. A courtesy wait for inputs the backend already started takes at most a quarter of it, and the rollback runs on the rest, so a failed Spend holds its caller for at most SpendWaitTimeout plus this value. A started input still unpublished when the courtesy wait ends is marked orphaned, and whoever completes it rolls its spend back with no time bound, so the caller does not wait for it. Lower this value if that latency matters more than rollback completeness."` DBTimeout time.Duration `key:"utxostore_dbTimeoutDuration" desc:"Database operation timeout" default:"5s" category:"UtxoStore" usage:"Increase for slow database connections" type:"duration" longdesc:"### Purpose\nSets the timeout duration for individual database operations (Get/Put/Delete/Batch/Query).\n\n### Scope\nApplies to Aerospike and PostgreSQL operations.\n\n### Values\n- **Default 5s** - Suitable for local/datacenter deployments\n- **10-30s** - For high network latency, during catchup with heavy load, overloaded database cluster, or slow queries with large result sets\n- **1-2s** - For ultra-low latency requirements (may cause spurious timeouts)\n\n### Important Distinction\nDifferent from **SpendWaitTimeout** (end-to-end spend operation) - this is per-operation timeout.\n\n### Note\nTimeout failures may trigger circuit breaker if frequent."` UseExternalTxCache bool `key:"utxostore_useExternalTxCache" desc:"Use external transaction cache" default:"true" category:"UtxoStore" usage:"Improves transaction lookup performance" type:"bool" longdesc:"### Purpose\nEnables a 10-second expiring concurrent cache for external transactions (>32KB stored in blob storage).\n\n### Why It Matters\nExternal transactions benefit greatly: large transaction with 100,000 outputs being spent simultaneously - first read fetches from blob storage (50-200ms), next 99,999 reads from cache (<1ms). Provides 100,000x reduction in blob storage calls.\n\n### Values\n- **Default true** - ALWAYS keep enabled in production\n- **false** - Only for testing/debugging external storage behavior\n\n### Details\n- Cache lifetime is 10 seconds (hardcoded)\n- Cache stored in memory - monitor memory usage for workloads with many large concurrent transactions"` ExternalTxCacheMaxItems int `key:"utxostore_externalTxCacheMaxItems" desc:"Maximum entries per external transaction cache" default:"1024" category:"UtxoStore" usage:"0 = unbounded, otherwise max entries in each of the two external caches" type:"int" longdesc:"### Purpose\nBounds each of the two external transaction caches enabled by **UseExternalTxCache**.\n\n### Why It Matters\nThe caches hold whole transactions, and external storage is the path taken by the largest ones (>32KB, often far larger). Unbounded, a burst of distinct external transactions inside one 10-second window is retained in full, twice over: the full-transaction cache and the outpoint-reconstruction cache are separate instances by design and hold separate copies of the same output vector.\n\n### How It Works\nThe cap is on entry COUNT, not bytes. At capacity, inserting a new key evicts the oldest by insertion time. An evicted key is refetched from blob storage on its next read, so the cap trades reads for a memory ceiling. In-flight coalescing is unaffected: concurrent readers of the same txid still share one fetch regardless of what has been evicted.\n\n### Values\n- **Default 1024** - Well above the concurrent-spend pattern the cache exists for (one entry serves all readers of a txid), while keeping the worst case bounded\n- **0** - Unbounded, the pre-cap behaviour\n- **Higher** - Only if blob-store read volume shows eviction thrashing on workloads with very many distinct large transactions per 10s window\n\n### Note\nSize the cap against the largest transactions you expect: 1024 entries of a 1MB transaction is ~1GB per cache."` diff --git a/stores/utxo/aerospike/aerospike.go b/stores/utxo/aerospike/aerospike.go index 80db16b755..33ff0292bc 100644 --- a/stores/utxo/aerospike/aerospike.go +++ b/stores/utxo/aerospike/aerospike.go @@ -289,6 +289,10 @@ type Store struct { // result before giving up, so a wedged dispatch fn can never park a caller // for the life of the process. Computed once from the batch policy. batcherWait time.Duration + + // beforeSpendPart runs before each backend part of a spend batch. Tests use it + // to hold a part after its items started. + beforeSpendPart func(part []*batchSpend) } // batchOperate runs a batch through the underlying Aerospike client, honouring diff --git a/stores/utxo/aerospike/circuit_breaker.go b/stores/utxo/aerospike/circuit_breaker.go index fa52368d64..93b14ba419 100644 --- a/stores/utxo/aerospike/circuit_breaker.go +++ b/stores/utxo/aerospike/circuit_breaker.go @@ -25,7 +25,7 @@ // // It WILL trigger on: // - Aerospike connection failures -// - Batch operation errors +// - Batch operation errors, whether they fail the whole batch or one record // - Timeout errors at the database level // // Data-state result codes (KEY_NOT_FOUND_ERROR, FILTERED_OUT, etc.) are @@ -164,6 +164,17 @@ type circuitBreaker struct { halfOpenAttempts int consecutiveSuccess int nextAttempt time.Time + + // halfOpenEpoch advances on every entry to half-open and every trip, so a + // slot handed out in one half-open epoch cannot be released into another. + halfOpenEpoch uint64 +} + +// breakerSlot records whether an admission took a half-open probe slot and the +// half-open epoch it took it in. The zero value took no slot. +type breakerSlot struct { + epoch uint64 + taken bool } func newCircuitBreaker(failureThreshold, halfOpenMax int, cooldown time.Duration) *circuitBreaker { @@ -185,9 +196,12 @@ func newCircuitBreaker(failureThreshold, halfOpenMax int, cooldown time.Duration } } -func (cb *circuitBreaker) Allow() bool { +// Admit reports whether a request may proceed. The slot is taken only when the +// admission consumed a half-open probe slot. Pass it to RecordSuccess or +// RecordFailure when the request reports an outcome, or to Release when it never will. +func (cb *circuitBreaker) Admit() (bool, breakerSlot) { if cb == nil { - return true + return true, breakerSlot{} } cb.mu.Lock() @@ -197,27 +211,69 @@ func (cb *circuitBreaker) Allow() bool { switch cb.state { case cbStateClosed: - return true + return true, breakerSlot{} case cbStateOpen: if now.After(cb.nextAttempt) { - cb.state = cbStateHalfOpen - cb.halfOpenAttempts = 1 - cb.consecutiveSuccess = 0 - return true + cb.enterHalfOpen(now) + return true, breakerSlot{epoch: cb.halfOpenEpoch, taken: true} } - return false + return false, breakerSlot{} case cbStateHalfOpen: if cb.halfOpenAttempts >= cb.halfOpenMax { - return false + // Backstop: a probe that never reports must not hold half-open + // shut for ever. One cooldown after entry, probe again. + if now.After(cb.nextAttempt.Add(cb.cooldown)) { + cb.enterHalfOpen(now) + return true, breakerSlot{epoch: cb.halfOpenEpoch, taken: true} + } + return false, breakerSlot{} } cb.halfOpenAttempts++ - return true + return true, breakerSlot{epoch: cb.halfOpenEpoch, taken: true} default: - return true + return true, breakerSlot{} } } -func (cb *circuitBreaker) RecordSuccess() { +// enterHalfOpen starts a new probe epoch. consecutiveSuccess is kept: one epoch +// admits halfOpenMax inputs but a probe that gets no usable answer is released +// rather than counted, and a probe that never completes holds its slot until the +// backstop, so an epoch can report fewer successes than slots. Only a trip or a +// reset zeroes the count, so the successes of several epochs add up and the +// breaker closes. +func (cb *circuitBreaker) enterHalfOpen(now time.Time) { + cb.state = cbStateHalfOpen + cb.halfOpenEpoch++ + // Probes of the previous epoch may still be in flight, so more than halfOpenMax + // probes can reach an unhealthy backend at once. The overlap is bounded by the + // request timeout. Accepted: this is a backstop, and the outcomes of those + // probes no longer apply here. + cb.halfOpenAttempts = 1 + cb.nextAttempt = now +} + +// Release gives back a half-open probe slot taken by Admit for a request that +// will never report an outcome. It does nothing for a slot that was not taken +// or that belongs to an earlier half-open epoch. +func (cb *circuitBreaker) Release(slot breakerSlot) { + if cb == nil || !slot.taken { + return + } + + cb.mu.Lock() + defer cb.mu.Unlock() + + if cb.state == cbStateHalfOpen && slot.epoch == cb.halfOpenEpoch && cb.halfOpenAttempts > 0 { + cb.halfOpenAttempts-- + } +} + +// RecordSuccess reports a successful outcome of the request admitted with slot. +// In the closed state it resets the failure count. In the half-open state it +// counts toward closing only when slot is a probe slot of the current half-open +// epoch; an outcome of a request admitted while closed, or in an earlier epoch, +// is ignored. +func (cb *circuitBreaker) RecordSuccess(slot breakerSlot) { if cb == nil { return } @@ -229,6 +285,10 @@ func (cb *circuitBreaker) RecordSuccess() { case cbStateClosed: cb.consecutiveFailures = 0 case cbStateHalfOpen: + if !cb.currentProbe(slot) { + return + } + cb.consecutiveSuccess++ if cb.consecutiveSuccess >= cb.halfOpenMax { cb.reset() @@ -236,7 +296,19 @@ func (cb *circuitBreaker) RecordSuccess() { } } -func (cb *circuitBreaker) RecordFailure() { +// RecordFailure reports an infrastructure failure of the request admitted with +// slot. See RecordBatchFailure. +func (cb *circuitBreaker) RecordFailure(slot breakerSlot) { + cb.RecordBatchFailure([]breakerSlot{slot}) +} + +// RecordBatchFailure reports one infrastructure failure that covers the requests +// admitted with slots, for example the batch they travelled in. In the closed +// state it counts once toward tripping, whatever the slots. In the half-open +// state it trips the breaker when any slot is a probe slot of the current epoch, +// and is ignored otherwise. The success count is zeroed only when the breaker +// trips or resets, never by an ignored or closed-state failure. +func (cb *circuitBreaker) RecordBatchFailure(slots []breakerSlot) { if cb == nil { return } @@ -244,8 +316,6 @@ func (cb *circuitBreaker) RecordFailure() { cb.mu.Lock() defer cb.mu.Unlock() - cb.consecutiveSuccess = 0 - switch cb.state { case cbStateClosed: cb.consecutiveFailures++ @@ -253,15 +323,27 @@ func (cb *circuitBreaker) RecordFailure() { cb.trip() } case cbStateHalfOpen: - cb.trip() + for _, slot := range slots { + if cb.currentProbe(slot) { + cb.trip() + return + } + } } } +// currentProbe reports whether slot is a probe slot of the current half-open epoch. +func (cb *circuitBreaker) currentProbe(slot breakerSlot) bool { + return slot.taken && slot.epoch == cb.halfOpenEpoch +} + func (cb *circuitBreaker) trip() { cb.state = cbStateOpen + cb.halfOpenEpoch++ cb.nextAttempt = time.Now().Add(cb.cooldown) cb.consecutiveFailures = 0 cb.halfOpenAttempts = 0 + cb.consecutiveSuccess = 0 } func (cb *circuitBreaker) reset() { @@ -270,3 +352,82 @@ func (cb *circuitBreaker) reset() { cb.halfOpenAttempts = 0 cb.consecutiveSuccess = 0 } + +// spendBreakerOutcome coalesces repeated expression outcomes across parts until +// an opposite outcome is recorded. An uninterrupted run of expression timeouts +// counts once per batcher batch, but a success re-arms failure recording so a +// later timeout cannot disappear after the breaker was reset. Outcomes are +// recorded before Lua retries, preserving their processing order. +// Lua records always count, even when a later part reuses the same record key. +// An outcome that carries half-open probe slots is never coalesced, because +// each probe must report. +type spendBreakerOutcome struct { + success bool + failure bool +} + +func (o *spendBreakerOutcome) recordExpressions(cb *circuitBreaker, success, failure bool, successSlots, failureSlots []breakerSlot) { + if success && (!o.success || len(successSlots) > 0) { + o.record(cb, true, successSlots...) + o.success = true + } + + if failure && (!o.failure || len(failureSlots) > 0) { + o.record(cb, false, failureSlots...) + o.failure = true + } +} + +// record also re-arms the opposite expression outcome: a Lua success resets +// the breaker, so a subsequent expression failure must count again (and vice versa). +// A success reports once per slot, or once without a slot when none is given. A +// failure reports once for the whole batch, with all its slots; in half-open it +// trips if any slot is a current-epoch probe. +func (o *spendBreakerOutcome) record(cb *circuitBreaker, success bool, slots ...breakerSlot) { + if success { + o.failure = false + + if len(slots) == 0 { + cb.RecordSuccess(breakerSlot{}) + } + + for _, slot := range slots { + cb.RecordSuccess(slot) + } + + return + } + + o.success = false + + cb.RecordBatchFailure(slots) +} + +// serverAnswerResultCodes are the ResultCodes that prove the server evaluated +// the request and answered with data state. A half-open probe that gets one of +// them counts as a success. Any other non-infrastructure error is weak evidence +// of health: DEVICE_OVERLOAD is owned by the overload-retry layer, and client +// side errors (PARAMETER_ERROR, SERIALIZE_ERROR, a canceled context) never +// reached a healthy server, so those probes release their slot instead. +var serverAnswerResultCodes = []types.ResultCode{ + types.KEY_NOT_FOUND_ERROR, + types.KEY_EXISTS_ERROR, + types.GENERATION_ERROR, + types.BIN_EXISTS_ERROR, + types.BIN_TYPE_ERROR, + types.BIN_NOT_FOUND, + types.RECORD_TOO_BIG, + types.OP_NOT_APPLICABLE, + types.FAIL_ELEMENT_NOT_FOUND, + types.FAIL_ELEMENT_EXISTS, + types.FILTERED_OUT, + types.LOST_CONFLICT, + types.UDF_BAD_RESPONSE, +} + +// isServerAnswer reports whether err is a data-state answer from the server. +func isServerAnswer(err error) bool { + var aErr aerospike.Error + + return errors.As(err, &aErr) && aErr.Matches(serverAnswerResultCodes...) +} diff --git a/stores/utxo/aerospike/circuit_breaker_test.go b/stores/utxo/aerospike/circuit_breaker_test.go index fafa8d4ff4..ff7b438174 100644 --- a/stores/utxo/aerospike/circuit_breaker_test.go +++ b/stores/utxo/aerospike/circuit_breaker_test.go @@ -85,18 +85,18 @@ func TestCircuitBreakerNilSafety(t *testing.T) { var cb *circuitBreaker t.Run("AllowWithNilCircuitBreaker", func(t *testing.T) { - allowed := cb.Allow() + allowed, _ := cb.Admit() assert.True(t, allowed, "nil circuit breaker should always allow") }) t.Run("RecordSuccessWithNilCircuitBreaker", func(t *testing.T) { // Should not panic - cb.RecordSuccess() + cb.RecordSuccess(breakerSlot{}) }) t.Run("RecordFailureWithNilCircuitBreaker", func(t *testing.T) { // Should not panic - cb.RecordFailure() + cb.RecordFailure(breakerSlot{}) }) } @@ -105,9 +105,9 @@ func TestCircuitBreakerClosedState(t *testing.T) { cb := newCircuitBreaker(3, 2, 100*time.Millisecond) require.NotNil(t, cb) - assert.True(t, cb.Allow(), "should allow in closed state") - assert.True(t, cb.Allow(), "should allow in closed state") - assert.True(t, cb.Allow(), "should allow in closed state") + assert.True(t, admitted(cb), "should allow in closed state") + assert.True(t, admitted(cb), "should allow in closed state") + assert.True(t, admitted(cb), "should allow in closed state") }) t.Run("RecordSuccessResetsFailureCount", func(t *testing.T) { @@ -115,12 +115,12 @@ func TestCircuitBreakerClosedState(t *testing.T) { require.NotNil(t, cb) // Record 2 failures - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, 2, cb.consecutiveFailures) // Success should reset counter - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, 0, cb.consecutiveFailures) assert.Equal(t, cbStateClosed, cb.state) }) @@ -130,11 +130,11 @@ func TestCircuitBreakerClosedState(t *testing.T) { require.NotNil(t, cb) // Record failures up to threshold - cb.RecordFailure() // 1 + cb.RecordFailure(currentProbe(cb)) // 1 assert.Equal(t, cbStateClosed, cb.state) - cb.RecordFailure() // 2 + cb.RecordFailure(currentProbe(cb)) // 2 assert.Equal(t, cbStateClosed, cb.state) - cb.RecordFailure() // 3 - should trip + cb.RecordFailure(currentProbe(cb)) // 3 - should trip assert.Equal(t, cbStateOpen, cb.state) }) } @@ -145,13 +145,13 @@ func TestCircuitBreakerOpenState(t *testing.T) { require.NotNil(t, cb) // Trip the circuit - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) // Should reject requests - assert.False(t, cb.Allow(), "should reject in open state") - assert.False(t, cb.Allow(), "should reject in open state") + assert.False(t, admitted(cb), "should reject in open state") + assert.False(t, admitted(cb), "should reject in open state") }) t.Run("TransitionsToHalfOpenAfterCooldown", func(t *testing.T) { @@ -159,18 +159,18 @@ func TestCircuitBreakerOpenState(t *testing.T) { require.NotNil(t, cb) // Trip the circuit - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) // Should reject before cooldown - assert.False(t, cb.Allow()) + assert.False(t, admitted(cb)) // Wait for cooldown time.Sleep(60 * time.Millisecond) // Next Allow() should transition to half-open - allowed := cb.Allow() + allowed := admitted(cb) assert.True(t, allowed, "should allow first request after cooldown") assert.Equal(t, cbStateHalfOpen, cb.state) }) @@ -181,8 +181,8 @@ func TestCircuitBreakerOpenState(t *testing.T) { require.NotNil(t, cb) before := time.Now() - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) after := time.Now() assert.Equal(t, cbStateOpen, cb.state) @@ -198,21 +198,21 @@ func TestCircuitBreakerHalfOpenState(t *testing.T) { require.NotNil(t, cb) // Trip to open - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) // Wait for cooldown to transition to half-open time.Sleep(60 * time.Millisecond) - assert.True(t, cb.Allow()) // First attempt transitions to half-open + assert.True(t, admitted(cb)) // First attempt transitions to half-open // Should allow halfOpenMax attempts for i := 1; i < halfOpenMax; i++ { - allowed := cb.Allow() + allowed := admitted(cb) assert.True(t, allowed, "should allow attempt %d/%d in half-open", i+1, halfOpenMax) } // Should reject after reaching limit - assert.False(t, cb.Allow(), "should reject after reaching halfOpenMax") + assert.False(t, admitted(cb), "should reject after reaching halfOpenMax") }) t.Run("SuccessfulAttemptsCloseCircuit", func(t *testing.T) { @@ -221,14 +221,14 @@ func TestCircuitBreakerHalfOpenState(t *testing.T) { require.NotNil(t, cb) // Trip to open, then transition to half-open - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) time.Sleep(60 * time.Millisecond) - cb.Allow() // Transition to half-open + admitted(cb) // Transition to half-open // Record successes equal to halfOpenMax for i := 0; i < halfOpenMax; i++ { - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) if i < halfOpenMax-1 { assert.Equal(t, cbStateHalfOpen, cb.state, "should stay half-open until all successes recorded") } @@ -246,17 +246,17 @@ func TestCircuitBreakerHalfOpenState(t *testing.T) { require.NotNil(t, cb) // Trip to open, then transition to half-open - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) time.Sleep(60 * time.Millisecond) - cb.Allow() // Transition to half-open + admitted(cb) // Transition to half-open // Record one success - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, cbStateHalfOpen, cb.state) // Record failure - should trip back to open - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) }) @@ -265,19 +265,19 @@ func TestCircuitBreakerHalfOpenState(t *testing.T) { require.NotNil(t, cb) // Trip to open, then transition to half-open - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) time.Sleep(60 * time.Millisecond) - cb.Allow() + admitted(cb) // Record partial successes - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, 1, cb.consecutiveSuccess) - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, 2, cb.consecutiveSuccess) // Failure should reset consecutive success count - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, 0, cb.consecutiveSuccess) assert.Equal(t, cbStateOpen, cb.state) }) @@ -299,11 +299,11 @@ func TestCircuitBreakerConcurrency(t *testing.T) { go func(id int) { defer wg.Done() for j := 0; j < iterations; j++ { - cb.Allow() + admitted(cb) if j%2 == 0 { - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) } else { - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) } } }(i) @@ -327,7 +327,7 @@ func TestCircuitBreakerConcurrency(t *testing.T) { for i := 0; i < 10; i++ { go func() { defer wg.Done() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) }() } wg.Wait() @@ -345,7 +345,7 @@ func TestCircuitBreakerConcurrency(t *testing.T) { for i := 0; i < 10; i++ { go func() { defer wg.Done() - if cb.Allow() { + if admitted(cb) { mu.Lock() allowCount++ mu.Unlock() @@ -366,27 +366,27 @@ func TestCircuitBreakerFullCycle(t *testing.T) { // Start in closed state assert.Equal(t, cbStateClosed, cb.state) - assert.True(t, cb.Allow()) + assert.True(t, admitted(cb)) // Trip to open - cb.RecordFailure() - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) - assert.False(t, cb.Allow(), "should reject in open state") + assert.False(t, admitted(cb), "should reject in open state") // Wait for cooldown time.Sleep(110 * time.Millisecond) // Transition to half-open - assert.True(t, cb.Allow(), "should allow after cooldown") + assert.True(t, admitted(cb), "should allow after cooldown") assert.Equal(t, cbStateHalfOpen, cb.state) // Succeed to close circuit - cb.RecordSuccess() - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, cbStateClosed, cb.state) - assert.True(t, cb.Allow(), "should allow in closed state") + assert.True(t, admitted(cb), "should allow in closed state") }) t.Run("MultipleOpenClosesCycles", func(t *testing.T) { @@ -395,17 +395,17 @@ func TestCircuitBreakerFullCycle(t *testing.T) { for cycle := 0; cycle < 3; cycle++ { // Closed -> Open - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state, "cycle %d: should be open", cycle) // Open -> Half-Open time.Sleep(60 * time.Millisecond) - cb.Allow() + admitted(cb) assert.Equal(t, cbStateHalfOpen, cb.state, "cycle %d: should be half-open", cycle) // Half-Open -> Closed - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, cbStateClosed, cb.state, "cycle %d: should be closed", cycle) } }) @@ -417,16 +417,16 @@ func TestCircuitBreakerEdgeCases(t *testing.T) { require.NotNil(t, cb) // Single failure should trip - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) // Very short cooldown time.Sleep(2 * time.Millisecond) - assert.True(t, cb.Allow()) + assert.True(t, admitted(cb)) assert.Equal(t, cbStateHalfOpen, cb.state) // Single success should close - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, cbStateClosed, cb.state) }) @@ -436,10 +436,10 @@ func TestCircuitBreakerEdgeCases(t *testing.T) { // Should take 100 failures to trip for i := 0; i < 99; i++ { - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateClosed, cb.state, "should stay closed until 100 failures") } - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) }) @@ -447,19 +447,19 @@ func TestCircuitBreakerEdgeCases(t *testing.T) { cb := newCircuitBreaker(3, 2, 50*time.Millisecond) require.NotNil(t, cb) - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, 2, cb.consecutiveFailures) // Interleaved success - cb.RecordSuccess() + cb.RecordSuccess(currentProbe(cb)) assert.Equal(t, 0, cb.consecutiveFailures) // Need 3 more failures to trip now - cb.RecordFailure() - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateClosed, cb.state) - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) assert.Equal(t, cbStateOpen, cb.state) }) } @@ -571,12 +571,12 @@ func TestCircuitBreaker_KeyNotFoundDoesNotTrip(t *testing.T) { // Simulate the gated call site: only record failure if the error is infra. for i := 0; i < 1000; i++ { if isInfrastructureFailure(keyNotFound) { - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) } } require.Equal(t, cbStateClosed, cb.state, "breaker must stay closed under KEY_NOT_FOUND flood") - require.True(t, cb.Allow(), "breaker must still allow requests") + require.True(t, admitted(cb), "breaker must still allow requests") } // TestCircuitBreaker_InfraErrorStillTrips ensures the safety net still works: @@ -589,14 +589,371 @@ func TestCircuitBreaker_InfraErrorStillTrips(t *testing.T) { for i := 0; i < 3; i++ { if isInfrastructureFailure(timeout) { - cb.RecordFailure() + cb.RecordFailure(currentProbe(cb)) } } require.Equal(t, cbStateOpen, cb.state, "breaker must trip on 3 consecutive infra failures") - require.False(t, cb.Allow(), "breaker must reject while open") + require.False(t, admitted(cb), "breaker must reject while open") } // ensure net.Error interface assertions compile (linter hint). var _ net.Error = fakeTimeoutNetErr{} var _ net.Error = fakeNonTimeoutNetErr{} + +func TestCircuitBreakerRelease(t *testing.T) { + t.Run("nil breaker", func(t *testing.T) { + var cb *circuitBreaker + require.NotPanics(t, func() { cb.Release(breakerSlot{taken: true}) }) + }) + + t.Run("closed state is unchanged", func(t *testing.T) { + cb := newCircuitBreaker(2, 2, time.Hour) + cb.Release(breakerSlot{taken: true}) + require.Equal(t, cbStateClosed, cb.state) + require.Equal(t, 0, cb.halfOpenAttempts) + }) + + t.Run("open state is unchanged", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Hour) + cb.RecordFailure(currentProbe(cb)) + cb.Release(breakerSlot{epoch: cb.halfOpenEpoch, taken: true}) + require.Equal(t, cbStateOpen, cb.state) + require.Equal(t, 0, cb.halfOpenAttempts) + require.False(t, admitted(cb)) + }) + + t.Run("half-open gives back one slot and never goes below zero", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Hour) + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + allowed, slot := cb.Admit() + require.True(t, allowed) + require.True(t, slot.taken) + require.True(t, admitted(cb)) + require.False(t, admitted(cb)) + + cb.Release(slot) + require.Equal(t, 1, cb.halfOpenAttempts) + require.True(t, admitted(cb)) + require.False(t, admitted(cb)) + + cb.Release(slot) + cb.Release(slot) + cb.Release(slot) + require.Equal(t, 0, cb.halfOpenAttempts) + require.Equal(t, cbStateHalfOpen, cb.state) + }) + + t.Run("a slot that was not taken is never released", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Hour) + + allowed, closedSlot := cb.Admit() + require.True(t, allowed) + require.False(t, closedSlot.taken, "a closed breaker hands out no slot") + + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + allowed, _ = cb.Admit() + require.True(t, allowed) + allowed, _ = cb.Admit() + require.True(t, allowed) + require.False(t, admitted(cb)) + + cb.Release(closedSlot) + require.Equal(t, 2, cb.halfOpenAttempts) + require.False(t, admitted(cb), "releasing an item admitted while closed must not admit another probe") + }) + + t.Run("a slot from an earlier half-open epoch is ignored after backstop re-entry", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Minute) + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + allowed, oldSlot := cb.Admit() + require.True(t, allowed) + require.True(t, admitted(cb)) + require.False(t, admitted(cb)) + + cb.mu.Lock() + cb.nextAttempt = time.Now().Add(-2 * time.Minute) + cb.mu.Unlock() + + allowed, newSlot := cb.Admit() + require.True(t, allowed, "the backstop re-enters half-open") + require.True(t, newSlot.taken) + require.NotEqual(t, oldSlot.epoch, newSlot.epoch) + require.True(t, admitted(cb)) + require.False(t, admitted(cb)) + require.Equal(t, 2, cb.halfOpenAttempts) + + cb.Release(oldSlot) + require.Equal(t, 2, cb.halfOpenAttempts, "the new epoch's count is untouched") + require.False(t, admitted(cb), "the new epoch still refuses after halfOpenMax probes") + + cb.Release(newSlot) + require.Equal(t, 1, cb.halfOpenAttempts, "a slot of the current epoch is still released") + }) + + t.Run("a slot from before a trip is ignored in the next half-open epoch", func(t *testing.T) { + cb := newCircuitBreaker(1, 1, time.Hour) + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + allowed, oldSlot := cb.Admit() + require.True(t, allowed) + + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + allowed, _ = cb.Admit() + require.True(t, allowed) + require.False(t, admitted(cb)) + + cb.Release(oldSlot) + require.Equal(t, 1, cb.halfOpenAttempts) + require.False(t, admitted(cb)) + }) +} + +func expireCooldown(cb *circuitBreaker) { + cb.mu.Lock() + defer cb.mu.Unlock() + + cb.nextAttempt = time.Now().Add(-time.Millisecond) +} + +func TestCircuitBreakerHalfOpenBackstop(t *testing.T) { + cb := newCircuitBreaker(1, 1, 50*time.Millisecond) + cb.RecordFailure(currentProbe(cb)) + time.Sleep(60 * time.Millisecond) + + require.True(t, admitted(cb), "enters half-open") + require.False(t, admitted(cb), "the only probe slot is taken") + + time.Sleep(120 * time.Millisecond) + require.True(t, admitted(cb), "a probe that never reported must not hold half-open shut") + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, 1, cb.halfOpenAttempts) + require.Equal(t, 0, cb.consecutiveSuccess) + require.False(t, admitted(cb)) + + cb.RecordSuccess(currentProbe(cb)) + require.Equal(t, cbStateClosed, cb.state) +} + +// A probe epoch admits halfOpenMax inputs but can report fewer successes, for +// example one Lua record for a tx whose inputs spend one parent. The successes +// of successive backstop epochs must add up, or the breaker stays half-open. +func TestCircuitBreakerClosesAcrossBackstopEpochs(t *testing.T) { + cb := newCircuitBreaker(1, 4, time.Minute) + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + for epoch := 1; epoch <= 4; epoch++ { + allowed, _ := cb.Admit() + require.True(t, allowed, "epoch %d must admit a probe", epoch) + + for range 3 { + require.True(t, admitted(cb)) + } + + require.False(t, admitted(cb), "epoch %d is full", epoch) + + cb.RecordSuccess(currentProbe(cb)) + + if epoch < 4 { + cb.mu.Lock() + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, epoch, cb.consecutiveSuccess) + cb.nextAttempt = time.Now().Add(-2 * time.Minute) + cb.mu.Unlock() + } + } + + cb.mu.Lock() + defer cb.mu.Unlock() + + require.Equal(t, cbStateClosed, cb.state, "four successes over four epochs must close the breaker") + require.Zero(t, cb.consecutiveSuccess) +} + +func TestCircuitBreakerTripZeroesHalfOpenSuccesses(t *testing.T) { + cb := newCircuitBreaker(1, 4, time.Minute) + cb.RecordFailure(currentProbe(cb)) + expireCooldown(cb) + + require.True(t, admitted(cb)) + cb.RecordSuccess(currentProbe(cb)) + cb.RecordSuccess(currentProbe(cb)) + cb.RecordFailure(currentProbe(cb)) + + cb.mu.Lock() + require.Equal(t, cbStateOpen, cb.state) + require.Zero(t, cb.consecutiveSuccess, "a trip must drop the successes of the failed probe round") + cb.mu.Unlock() + + expireCooldown(cb) + require.True(t, admitted(cb)) + cb.RecordSuccess(currentProbe(cb)) + + cb.mu.Lock() + defer cb.mu.Unlock() + + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, 1, cb.consecutiveSuccess) +} + +func TestCircuitBreakerHalfOpenOutcomesAreTiedToProbeSlots(t *testing.T) { + t.Run("every probe reporting a success with its slot closes the breaker", func(t *testing.T) { + cb := newCircuitBreaker(1, 3, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + slots := make([]breakerSlot, 3) + for i := range slots { + allowed, slot := cb.Admit() + require.True(t, allowed) + require.True(t, slot.taken) + + slots[i] = slot + } + + for i, slot := range slots { + require.Equal(t, cbStateHalfOpen, cb.state, "still half-open before success %d", i+1) + cb.RecordSuccess(slot) + } + + require.Equal(t, cbStateClosed, cb.state) + }) + + t.Run("a success without a taken slot does not count", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + allowed, _ := cb.Admit() + require.True(t, allowed) + + cb.RecordSuccess(breakerSlot{}) + cb.RecordSuccess(breakerSlot{epoch: cb.halfOpenEpoch}) + require.Equal(t, 0, cb.consecutiveSuccess) + require.Equal(t, cbStateHalfOpen, cb.state) + }) + + t.Run("a success from an earlier epoch does not count", func(t *testing.T) { + cb := newCircuitBreaker(1, 2, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + allowed, oldSlot := cb.Admit() + require.True(t, allowed) + + cb.RecordFailure(oldSlot) + expireCooldown(cb) + + allowed, newSlot := cb.Admit() + require.True(t, allowed) + require.NotEqual(t, oldSlot.epoch, newSlot.epoch) + + cb.RecordSuccess(oldSlot) + require.Equal(t, 0, cb.consecutiveSuccess) + + cb.RecordSuccess(newSlot) + require.Equal(t, 1, cb.consecutiveSuccess) + }) + + t.Run("a failure from a current-epoch probe trips", func(t *testing.T) { + cb := newCircuitBreaker(1, 3, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + allowed, slot := cb.Admit() + require.True(t, allowed) + + cb.RecordSuccess(slot) + require.Equal(t, 1, cb.consecutiveSuccess) + + cb.RecordFailure(slot) + require.Equal(t, cbStateOpen, cb.state) + require.Equal(t, 0, cb.consecutiveSuccess) + }) + + t.Run("a failure from a non-probe or stale slot is ignored while half-open", func(t *testing.T) { + cb := newCircuitBreaker(1, 3, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + allowed, slot := cb.Admit() + require.True(t, allowed) + + cb.RecordSuccess(slot) + cb.RecordFailure(breakerSlot{}) + cb.RecordFailure(breakerSlot{epoch: slot.epoch - 1, taken: true}) + + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, 1, cb.consecutiveSuccess) + }) +} + +func TestCircuitBreakerBatchFailure(t *testing.T) { + t.Run("trips when any slot is a current probe", func(t *testing.T) { + cb := newCircuitBreaker(1, 1, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + _, stale := cb.Admit() + cb.mu.Lock() + cb.nextAttempt = time.Now().Add(-2 * time.Hour) + cb.mu.Unlock() + + _, current := cb.Admit() + require.NotEqual(t, stale.epoch, current.epoch) + + cb.RecordBatchFailure([]breakerSlot{stale, current}) + require.Equal(t, cbStateOpen, cb.state) + }) + + t.Run("ignored when every slot is stale or untaken", func(t *testing.T) { + cb := newCircuitBreaker(1, 3, time.Hour) + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + _, slot := cb.Admit() + cb.RecordBatchFailure([]breakerSlot{{}, {epoch: slot.epoch - 1, taken: true}}) + require.Equal(t, cbStateHalfOpen, cb.state) + }) + + t.Run("counts once in the closed state however many slots", func(t *testing.T) { + cb := newCircuitBreaker(3, 1, time.Hour) + + cb.RecordBatchFailure([]breakerSlot{{epoch: 1, taken: true}, {epoch: 2, taken: true}, {epoch: 3, taken: true}}) + require.Equal(t, 1, cb.consecutiveFailures) + require.Equal(t, cbStateClosed, cb.state) + }) +} + +func TestIsServerAnswer(t *testing.T) { + require.True(t, isServerAnswer(&aerospike.AerospikeError{ResultCode: types.KEY_NOT_FOUND_ERROR})) + require.True(t, isServerAnswer(&aerospike.AerospikeError{ResultCode: types.FILTERED_OUT})) + require.False(t, isServerAnswer(&aerospike.AerospikeError{ResultCode: types.DEVICE_OVERLOAD})) + require.False(t, isServerAnswer(&aerospike.AerospikeError{ResultCode: types.PARAMETER_ERROR})) + require.False(t, isServerAnswer(&aerospike.AerospikeError{ResultCode: types.TIMEOUT})) + require.False(t, isServerAnswer(context.Canceled)) + require.False(t, isServerAnswer(nil)) +} + +func currentProbe(cb *circuitBreaker) breakerSlot { + cb.mu.Lock() + defer cb.mu.Unlock() + + return breakerSlot{epoch: cb.halfOpenEpoch, taken: true} +} + +func admitted(cb *circuitBreaker) bool { + allowed, _ := cb.Admit() + + return allowed +} diff --git a/stores/utxo/aerospike/metrics.go b/stores/utxo/aerospike/metrics.go index fe6823d72e..9fdd3de892 100644 --- a/stores/utxo/aerospike/metrics.go +++ b/stores/utxo/aerospike/metrics.go @@ -318,7 +318,7 @@ func _initPrometheusMetrics() { Namespace: "teranode", Subsystem: "aerospike", Name: "utxo_spend_abort_in_flight", - Help: "Spend items still in flight when the batch aborted, excluded from the rollback set and applied by the dispatcher afterwards (residual dangling-ref window, see #1291)", + Help: "Spend items a backend part had started and not published when their caller gave up, each rolled back by whoever completes it if it succeeds, unless a transient lock suppresses the batch rollback and leaves it applied (residual window see #1291)", }, ) diff --git a/stores/utxo/aerospike/native_op_coverage_test.go b/stores/utxo/aerospike/native_op_coverage_test.go index 2da66413eb..74fbc51626 100644 --- a/stores/utxo/aerospike/native_op_coverage_test.go +++ b/stores/utxo/aerospike/native_op_coverage_test.go @@ -5,6 +5,7 @@ import ( aerospike "github.com/bsv-blockchain/aerospike-client-go/v8" "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/bsv-blockchain/teranode/errors" "github.com/bsv-blockchain/teranode/stores/utxo" "github.com/bsv-blockchain/teranode/ulogger" "github.com/stretchr/testify/require" @@ -224,3 +225,18 @@ func TestCreateSpendErrorHandlesNilBatchItem(t *testing.T) { require.Error(t, err) require.Contains(t, err.Error(), "nil batch item") } + +// An INVALID_SPEND whose spending data does not parse is a plain utxo error: it +// carries no invalid-spend data, so no caller treats it as a replay verdict. +func TestCreateSpendErrorInvalidSpendWithMalformedSpendingData(t *testing.T) { + s := &Store{} + txID := &chainhash.Hash{0x02} + item := &batchSpend{spend: &utxo.Spend{TxID: txID, Vout: 1, UTXOHash: &chainhash.Hash{0x03}}} + + err := s.createSpendError(LuaErrorInfo{ErrorCode: LuaErrorCodeInvalidSpend, Message: "detail", SpendingData: "not-spending-data"}, item, txID) + + require.ErrorIs(t, err, errors.ErrUtxoError) + + var data *errors.UtxoInvalidSpendErrData + require.False(t, errors.AsData(err, &data), "malformed spending data must not produce invalid-spend error data") +} diff --git a/stores/utxo/aerospike/pruner_replay_protection_test.go b/stores/utxo/aerospike/pruner_replay_protection_test.go index 67b6c8419c..ab34339777 100644 --- a/stores/utxo/aerospike/pruner_replay_protection_test.go +++ b/stores/utxo/aerospike/pruner_replay_protection_test.go @@ -84,6 +84,10 @@ func TestPrunerReplayProtection(t *testing.T) { // check in teranode.lua rather than any spend failure. require.Contains(t, err.Error(), "invalid spend") + var invalidSpend *errors.UtxoInvalidSpendErrData + require.True(t, errors.AsData(err, &invalidSpend), "the replay error must carry the stored owner") + require.Equal(t, child.TxIDChainHash().String(), invalidSpend.SpendingData.TxID.String()) + // The symptom in #1701 is the child being recreated as unmined with empty // blockIDs, so a rejected replay that still wrote the record must fail here. exists, err = client.Exists(nil, childKey) diff --git a/stores/utxo/aerospike/respend_behind_loser_test.go b/stores/utxo/aerospike/respend_behind_loser_test.go new file mode 100644 index 0000000000..66f6c46534 --- /dev/null +++ b/stores/utxo/aerospike/respend_behind_loser_test.go @@ -0,0 +1,115 @@ +package aerospike_test + +import ( + "testing" + "time" + + "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/go-bt/v2/bscript" + "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + "github.com/bsv-blockchain/teranode/ulogger" + "github.com/bsv-blockchain/teranode/util/test" + "github.com/stretchr/testify/require" +) + +// TestRespendBehindLoserInSameBatch pins the Aerospike half of the respend-behind-loser behaviour. +// +// S0 already owns both parent outputs. A batch then carries a double-spend +// attempt on output 0 AHEAD of S0's idempotent re-spend. The filter used to +// award the outpoint by batch position, so the legitimate re-spend was refused +// with ErrSpent naming the double-spend attempt, which itself was refused by the +// backend as already spent -- both claims lost, each blamed on the other. +// +// A test-only adapter supplies an exact batch to both backend paths. +func TestRespendBehindLoserInSameBatch(t *testing.T) { + cases := []struct { + name string + utxoBatchSize int + enableExpressions bool + }{ + {name: "lua", utxoBatchSize: 128, enableExpressions: false}, + {name: "expressions", utxoBatchSize: 1, enableExpressions: true}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + tSettings := test.CreateBaseTestSettings(t) + tSettings.UtxoStore.UtxoBatchSize = tc.utxoBatchSize + tSettings.UtxoStore.SpendBatcherSize = 1 + tSettings.UtxoStore.SpendBatcherDurationMillis = 1 + tSettings.UtxoStore.SpendWaitTimeout = 30 * time.Second + tSettings.Aerospike.EnableSpendFilterExpressions = tc.enableExpressions + + client, store, storeCtx, deferFn := initAerospike(t, tSettings, ulogger.NewErrorTestLogger(t)) + t.Cleanup(deferFn) + cleanDB(t, client) + require.NoError(t, store.SetBlockHeight(2)) + + parent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte("4934-as-" + tc.name)) + require.NoError(t, parent.From(prev.String(), 0, + "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 2000)) + _, err := store.Create(storeCtx, parent, 1) + require.NoError(t, err) + + spendOf := func(lockTime uint32, vouts ...uint32) *bt.Tx { + tx := bt.NewTx() + for _, v := range vouts { + require.NoError(t, tx.From(parent.TxIDChainHash().String(), v, + parent.Outputs[v].LockingScript.String(), parent.Outputs[v].Satoshis)) + } + require.NoError(t, tx.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + tx.LockTime = lockTime + + return tx + } + + respend := spendOf(1, 0, 1) // legitimate spender of both outputs + loser := spendOf(2, 0) // double-spend attempt on output 0 + + _, err = store.Spend(storeCtx, respend, 2) + require.NoError(t, err, "initial spend must succeed") + + spends, err := utxo.GetSpends(respend) + require.NoError(t, err) + require.Len(t, spends, 2) + loserSpends, err := utxo.GetSpends(loser) + require.NoError(t, err) + store.SendSpendBatchForTest(t, []*utxo.Spend{loserSpends[0], spends[0], spends[1]}, 2) + require.NoError(t, spends[0].Err, "the persisted owner must be accepted") + require.NoError(t, spends[1].Err) + require.ErrorIs(t, loserSpends[0].Err, errors.ErrSpent) + require.Contains(t, loserSpends[0].Err.Error(), respend.TxID()) + + for _, sp := range spends { + resp, getErr := store.GetSpend(storeCtx, sp) + require.NoError(t, getErr) + t.Logf("output %d: status=%v spendingData=%v", sp.Vout, resp.Status, resp.SpendingData) + + require.Equal(t, int(utxo.Status_SPENT), resp.Status, + "output %d that S0 legitimately spent went back to unspent", sp.Vout) + require.NotNil(t, resp.SpendingData, "output %d must name its spender", sp.Vout) + require.Equal(t, respend.TxID(), resp.SpendingData.TxID.String(), + "output %d is owned by %s, not by S0", sp.Vout, resp.SpendingData.TxID) + } + // Neither claim matches the stored owner. Both errors must name it. + first, err := utxo.GetSpends(spendOf(3, 0)) + require.NoError(t, err) + second, err := utxo.GetSpends(spendOf(4, 0)) + require.NoError(t, err) + store.SendSpendBatchForTest(t, []*utxo.Spend{first[0], second[0]}, 2) + for _, sp := range []*utxo.Spend{first[0], second[0]} { + require.ErrorIs(t, sp.Err, errors.ErrSpent) + var data *errors.UtxoSpentErrData + require.True(t, errors.AsData(sp.Err, &data)) + require.Equal(t, respend.TxID(), data.SpendingData.TxID.String()) + } + + }) + } +} diff --git a/stores/utxo/aerospike/spend.go b/stores/utxo/aerospike/spend.go index 0dc442af88..fcf0ee4e1e 100644 --- a/stores/utxo/aerospike/spend.go +++ b/stores/utxo/aerospike/spend.go @@ -100,6 +100,8 @@ const maxAggregatedSpendErrs = 10 // batchSpend represents a single UTXO spend request in a batch type batchSpend struct { + admission utxo.SpendAdmission + requestCtx context.Context spend *utxo.Spend // UTXO to spend blockHeight uint32 // Current block height group *completion.Group @@ -108,12 +110,60 @@ type batchSpend struct { // acquire-loading it on the abort path synchronizes-with that write and can // then safely read the slot (see resolveSpendCompletions). completed alone // cannot serve this role: it is set by the CAS, i.e. BEFORE the slot write. - published atomic.Bool + published atomic.Bool + // done is closed by complete after published is stored. It is nil for items + // nobody awaits individually. + done chan struct{} ignoreConflicting bool ignoreLocked bool + // breakerSlot is the half-open probe slot Admit gave the item, if any, so a + // release only returns a slot the item took in the epoch it took it. It has + // one owner at a time: the batcher once Start won, otherwise whoever won + // the Abandon. No other goroutine may read or write it. + breakerSlot breakerSlot // requireParentOutput turns off the "already blessed" fallback for this item; // see utxo.IgnoreFlags.RequireParentOutputs. requireParentOutput bool + // err is the answer complete stored. The batcher goroutine reads it, and so + // does the caller after it observes published, because the caller may + // rewrite spend.Err once the group completes. + err error + // orphan decides who rolls back this item's spend when its caller gave up + // while the backend had already started it. onOrphan performs that rollback. + orphan utxo.SpendOrphan + onOrphan func(item *batchSpend) +} + +// markOrphaned records that the caller gave up on an item the backend had +// started. Spend calls it only when the batch rollback is not suppressed, so a +// late success is unspent exactly when the batch rollback would be. If the +// item has already published a success the caller rolls the spend back; +// otherwise complete does when the item publishes. +func (b *batchSpend) markOrphaned() { + b.orphan.Mark() + b.rollbackIfOrphaned() +} + +// rollbackIfOrphaned starts the rollback of this item's spend, on a detached +// goroutine, when its caller gave up and the item published a success. Both +// complete and markOrphaned call it, and the claim lets exactly one of them +// start the rollback whichever runs first. +func (b *batchSpend) rollbackIfOrphaned() { + if b.onOrphan != nil && b.published.Load() && b.err == nil && b.orphan.Claim() { + go b.onOrphan(b) + } +} + +// releaseBreakerSlot returns the half-open probe slot of an item that will never +// reach the backend. The caller must have won the abandonment of the item, which +// makes it the only owner of the slot. An item the batcher started, or one whose +// abandonment another party won, must not be passed here. +func (s *Store) releaseBreakerSlot(item *batchSpend) { + if item.breakerSlot.taken { + slot := item.breakerSlot + item.breakerSlot = breakerSlot{} + s.spendCircuitBreaker.Release(slot) + } } // complete writes err into the item's result slot (spend.Err) and marks the @@ -132,9 +182,16 @@ type batchSpend struct { // the slot write) would NOT establish that happens-before edge. func (b *batchSpend) complete(err error) { if b.completed.CompareAndSwap(false, true) { + b.err = err b.spend.Err = err b.published.Store(true) + + if b.done != nil { + close(b.done) + } + b.group.Done() + b.rollbackIfOrphaned() } } @@ -444,6 +501,13 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore return nil, err } + spendTimeout := s.settings.UtxoStore.SpendWaitTimeout + if spendTimeout <= 0 { + spendTimeout = 30 * time.Second + } + requestCtx, cancel := context.WithCancelCause(ctx) + defer cancel(nil) + items := make([]*batchSpend, len(spends)) group := completion.NewGroup(int32(len(spends))) @@ -472,11 +536,15 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore ignoreConflicting: useIgnoreConflicting, ignoreLocked: useIgnoreLocked, requireParentOutput: useRequireParentOutputs, + requestCtx: requestCtx, + done: make(chan struct{}), + onOrphan: s.rollbackOrphanedSpend, } items[idx] = item // Fast-fail check: if circuit breaker is already open, reject immediately. - if s.spendCircuitBreaker != nil && !s.spendCircuitBreaker.Allow() { + admitted, slot := s.spendCircuitBreaker.Admit() + if !admitted { // First rejection: every earlier item was accepted, so items[:idx] is // exactly the accepted prefix. Tracked with a bool rather than a nil // test on toEnqueue, because make([]T, 0, n) is non-nil and a nil test @@ -491,6 +559,8 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore continue } + item.breakerSlot = slot + if filtered { toEnqueue = append(toEnqueue, item) } @@ -502,20 +572,31 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore // rejected send rejects every item — complete all of them and let the // resolveSpendCompletions path below report it, instead of parking on // group.Wait for the full spendTimeout and reporting a bogus timeout. + // + // The enqueue runs on the caller's context and the wait budget starts after + // it returns, so a send that blocks on a full batcher channel does not use + // up the budget. requestCtx is created before the enqueue only because the + // batcher reads it from each item; the timer below ends it. if enqueueErr := safeBatcherPutBatchCtx(s.spendBatcher, ctx, toEnqueue, "spend"); enqueueErr != nil { for _, item := range toEnqueue { item.complete(enqueueErr) } } - // One shared wait for the whole batch, instead of one goroutine + timer - // per input. spendTimeout mirrors the previous per-item fallback. - spendTimeout := s.settings.UtxoStore.SpendWaitTimeout - if spendTimeout <= 0 { - spendTimeout = 30 * time.Second - } + waitTimer := time.AfterFunc(spendTimeout, func() { cancel(context.DeadlineExceeded) }) + defer waitTimer.Stop() + + if waitErr := group.Wait(requestCtx, 0); waitErr != nil { + giveUp := time.Now() + callerDone := ctx.Err() != nil + + for _, item := range items { + if item.admission.Abandon() { + s.releaseBreakerSlot(item) + } + } - if waitErr := group.Wait(ctx, spendTimeout); waitErr != nil { + s.awaitStartedSpends(items, giveUp) // The group did not complete within budget (context canceled, or the // dispatcher took longer than spendTimeout). Some items may already // have finished before the abort — resolveSpendCompletions(onlyCompleted=true) @@ -524,16 +605,24 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore // untouched, since the dispatcher may still be writing to it. result := s.resolveSpendCompletions(ctx, tx, items, true) - // Roll back the spends we know completed. This is the WEAKEST case for - // the atomicity contract, not the strictest: onlyCompleted=true above - // excludes every item whose published flag is not yet set, but the - // dispatcher runs on s.ctx (not this now-dead caller ctx) and keeps - // writing to those items after we return here, so a straggler that later - // succeeds is never rolled back by this call. prometheusUtxoSpendAbortInFlight - // counts those skipped items so this residual window is measurable - // rather than invisible; closing it needs attempt identity or - // create-before-spend ordering, tracked in #1291. - s.rollbackPartialSpends(tx, result, "batched mode, after wait error") + // Roll back the spends we know completed. onlyCompleted=true above skips + // every item whose published flag is not yet set, but the dispatcher runs + // on s.ctx for items already admitted to a backend part before + // abandonment, so those can still write after we return. resolveSpendCompletions + // collects them, and unless the transient-window gate suppresses the + // rollback they are marked orphaned below, so whoever completes one + // rolls its spend back with no time bound. A suppressed batch leaves + // them applied, like the batch's own spends. + // prometheusUtxoSpendAbortInFlight counts them either way. The remaining + // window is the one rollbackPartialSpends documents, closed only by + // attempt identity or create-before-spend ordering, tracked in #1291. + if !result.suppressesRollback() { + for _, item := range result.orphans { + item.markOrphaned() + } + } + + s.rollbackPartialSpends(tx, result, "batched mode, after wait error", giveUp.Add(s.spendRollbackBound())) // Do NOT return the live spends slice on the abort path: items still // in-flight are owned by the dispatcher goroutine, which will keep @@ -543,7 +632,7 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore // race, and an in-flight item still reads Err==nil (misclassified as a // successful spend). A Wait error means the whole operation failed; // callers must treat it as such and not inspect per-item slots. - if errors.Is(waitErr, context.Canceled) || errors.Is(waitErr, context.DeadlineExceeded) { + if callerDone { return nil, errors.NewContextCanceledError("[SPEND] context canceled while waiting for batch response: %s", waitErr) } @@ -559,7 +648,7 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore result := s.resolveSpendCompletions(ctx, tx, items, false) if len(spends) != len(result.spentSpends) { // there must have been failures - s.rollbackPartialSpends(tx, result, "batched mode") + s.rollbackPartialSpends(tx, result, "batched mode", time.Now().Add(s.spendRollbackBound())) // Aggregate with a hard cap. The failure count scales with the tx's // input count (a mass DEVICE_OVERLOAD on a 50k-input consolidation tx @@ -583,6 +672,59 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore return spends, nil } +// spendRollbackBound is the longest a failed Spend holds its caller after the +// caller gave up: the courtesy wait for started items and the rollback share +// this one budget, which starts when the caller gives up. Together with +// SpendWaitTimeout it is the documented bound on a Spend call. +func (s *Store) spendRollbackBound() time.Duration { + if d := s.settings.UtxoStore.SpendRollbackTimeout; d > 0 { + return d + } + + return 120 * time.Second +} + +// awaitStartedSpends waits, on a context detached from the caller, for every +// item that a backend part already started and that is not yet published, so a +// prompt success joins the rollback with the other spends. The wait ends at a +// quarter of spendRollbackBound after giveUp, which leaves the rest of the +// budget to the rollback. It is a courtesy only: an item still unpublished +// when it ends is marked orphaned by resolveSpendCompletions, and whoever +// completes it rolls its spend back with no time bound. Items that never +// started are not awaited. The caller must have abandoned every queued item +// first. +func (s *Store) awaitStartedSpends(items []*batchSpend, giveUp time.Time) { + var waitCtx context.Context + + for _, item := range items { + if item.published.Load() || !item.admission.Started() { + continue + } + + if waitCtx == nil { + var cancel context.CancelFunc + + waitCtx, cancel = context.WithDeadline(context.Background(), giveUp.Add(s.spendRollbackBound()/4)) + defer cancel() + } + + select { + case <-item.done: + case <-waitCtx.Done(): + return + } + } +} + +// rollbackOrphanedSpend reverts the spend of one item whose caller gave up +// while the backend had started it and which then succeeded. It applies the +// same spender-existence rule as rollbackPartialSpends: a spender with a record +// owns the spend, an indeterminate probe skips it, and otherwise the spend is +// unspent. +func (s *Store) rollbackOrphanedSpend(item *batchSpend) { + s.rollbackDanglingSpends(item.spend.SpendingData.TxID, []*utxo.Spend{item.spend}, "orphaned spend", time.Now().Add(s.spendRollbackBound())) +} + // spendCompletionResult is the outcome of resolveSpendCompletions: which // spends succeeded, plus a memo of the "does the spending tx already have a // record?" lookup used only by resolveSpendCompletions' own loop, so a @@ -618,6 +760,20 @@ type spendCompletionResult struct { // Create either, meaning nobody can be a legitimate owner of the partial // spends and the rollback is both safe and required (#1214). sawUnwinnable bool + + // orphans are the items a backend part had started and not published when + // resolveSpendCompletions ran. Spend marks them orphaned only when + // suppressesRollback is false. + orphans []*batchSpend +} + +// suppressesRollback reports whether a concurrent attempt at the same txid may +// own the spends: a transient lock or creating window was seen and nothing +// proves the txid unwinnable. rollbackPartialSpends and the orphan hand-off in +// Spend both use it, so a late success is rolled back exactly when the batch +// rollback would be. +func (r *spendCompletionResult) suppressesRollback() bool { + return (r.sawTransientLock || r.sawTransientCreating) && !r.sawUnwinnable } // rollbackDecision is what the spender-existence probe implies for the spends @@ -711,7 +867,7 @@ func decideRollback(getErr error) rollbackDecision { // surviving dangling ref is at least detectable afterwards via the // "indeterminate" outcome on prometheusUtxoPartialSpendRollbacks below — no // automated detector for it exists yet. -func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, phase string) { +func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, phase string, deadline time.Time) { if len(result.spentSpends) == 0 { return } @@ -743,7 +899,7 @@ func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, // would cover it by letting the ownership check tell two attempts apart. // Neither belongs in an error-path rollback. Mirrors the sql store's // hasTransientLockFailure/hasUnwinnableFailure doc comments — keep in step. - if (result.sawTransientLock || result.sawTransientCreating) && !result.sawUnwinnable { + if result.suppressesRollback() { // When both transient signals fire in the same batch, report // transient_lock: it is the flavour with an existing dashboard history // and the more commonly hit window today (creating only shows up on @@ -761,6 +917,14 @@ func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, return } + s.rollbackDanglingSpends(tx.TxIDChainHash(), result.spentSpends, phase, deadline) +} + +// rollbackDanglingSpends probes whether the spending tx has a record and, only +// when it has none, unspends spends. The probe and the unspend share one +// context that ends at deadline. rollbackPartialSpends and the orphan rollback +// both end here, so the two paths apply one rule. +func (s *Store) rollbackDanglingSpends(spenderID *chainhash.Hash, spends []*utxo.Spend, phase string, deadline time.Time) { // Always probe fresh here rather than reusing resolveSpendCompletions' // memo: that memo answers a different question (the ErrTxNotFound // "already blessed" fallback), taken under a different ctx, potentially @@ -777,22 +941,18 @@ func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, // shutdown races in-flight spends. Cleanup of writes we already made has to // outlive the store's own context; the timeout is what keeps that bounded. // - // Deliberately SpendRollbackTimeout, not SpendWaitTimeout: SpendWaitTimeout - // is the end-to-end budget for ONE batched spend, but this rollback is - // len(spentSpends) sequential single-record Unspend calls plus the probe - // above — on a wide transaction it needs a multiple of that budget, not the - // same one. On overrun the loop aborts and every spend past that point - // stays applied (a bounded truncation, not a full revert), counted by - // utxo_spend_rollback_failed. - rbTimeout := s.settings.UtxoStore.SpendRollbackTimeout - if rbTimeout <= 0 { - rbTimeout = 120 * time.Second - } - - rbCtx, cancel := context.WithTimeout(context.Background(), rbTimeout) + // The deadline comes from SpendRollbackTimeout, not SpendWaitTimeout: + // SpendWaitTimeout is the end-to-end budget for ONE batched spend, but this + // rollback is len(spends) sequential single-record Unspend calls plus the + // probe above — on a wide transaction it needs a multiple of that budget, + // not the same one. The abort path passes the end of the budget it shares + // with the courtesy wait for started items. On overrun the loop aborts and + // every spend past that point stays applied (a bounded truncation, not a + // full revert), counted by utxo_spend_rollback_failed. + rbCtx, cancel := context.WithDeadline(context.Background(), deadline) defer cancel() - _, getErr := s.Get(rbCtx, tx.TxIDChainHash(), fields.Fee) + _, getErr := s.Get(rbCtx, spenderID, fields.Fee) decision := decideRollback(getErr) @@ -805,7 +965,7 @@ func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, return case rollbackSkipIndeterminate: s.logger.Errorf("[SPEND][%s] cannot determine whether spender exists, skipping rollback of %d partial spend(s) (%s): %v", - tx.TxID(), len(result.spentSpends), phase, getErr) + spenderID.String(), len(spends), phase, getErr) return case rollbackFire: @@ -825,19 +985,19 @@ func (s *Store) rollbackPartialSpends(tx *bt.Tx, result *spendCompletionResult, // means the same thing as the sql store's counter of the same name. Aggregating // calls on one backend and dangling refs on the other would be exactly the // per-backend drift the shared outcome labels exist to prevent. - unspendFailed, unspendErr := s.unspend(rbCtx, result.spentSpends) + unspendFailed, unspendErr := s.unspend(rbCtx, spends) if unspendErr != nil { if prometheusUtxoSpendRollbackFailed != nil { prometheusUtxoSpendRollbackFailed.Add(float64(unspendFailed)) } s.logger.Errorf("[SPEND][%s] rolled back %d of %d partial spend(s), %d left dangling (%s): %v", - tx.TxID(), len(result.spentSpends)-unspendFailed, len(result.spentSpends), unspendFailed, phase, unspendErr) + spenderID.String(), len(spends)-unspendFailed, len(spends), unspendFailed, phase, unspendErr) return } - s.logger.Warnf("[SPEND][%s] rolled back %d partial spend(s) (%s)", tx.TxID(), len(result.spentSpends), phase) + s.logger.Warnf("[SPEND][%s] rolled back %d partial spend(s) (%s)", spenderID.String(), len(spends), phase) } // resolveSpendCompletions applies the ErrTxNotFound "already blessed" @@ -885,8 +1045,12 @@ func (s *Store) resolveSpendCompletions(ctx context.Context, tx *bt.Tx, items [] // needs attempt identity (#1291) or create-before-spend ordering // (#1355); prometheusUtxoSpendAbortInFlight counts how often the // window is entered at all. - if prometheusUtxoSpendAbortInFlight != nil { - prometheusUtxoSpendAbortInFlight.Inc() + if item.admission.Started() { + if prometheusUtxoSpendAbortInFlight != nil { + prometheusUtxoSpendAbortInFlight.Inc() + } + + result.orphans = append(result.orphans, item) } continue @@ -999,40 +1163,77 @@ func (s *Store) sendSpendBatchLua(batch []*batchSpend) { }) }() - batch = utxo.FilterConflictingDuplicateSpendClaims(batch, - func(item *batchSpend) *utxo.Spend { + _, _, deferFn := tracing.Tracer("aerospike").Start(s.ctx, "sendSpendBatch", + tracing.WithHistogram(prometheusUtxoSpendBatch), + ) + defer func() { + prometheusUtxoSpendBatchSize.Observe(float64(len(batch))) + deferFn() + }() + + defer s.releaseUnsettledSlots(batch) + + // Repeated expression outcomes are coalesced across parts until an opposite + // outcome occurs. Lua records always count, in processing order. + var outcome spendBreakerOutcome + + utxo.ProcessSpendBatch(batch, utxo.SpendBatchHandler[*batchSpend]{ + Start: func(item *batchSpend) error { + if item == nil { + return nil + } + if item.requestCtx != nil && item.requestCtx.Err() != nil { + if item.admission.Abandon() { + s.releaseBreakerSlot(item) + } + + return item.admission.Start(item.requestCtx) + } + + return item.admission.Start(nil) + }, + Spend: func(item *batchSpend) *utxo.Spend { if item == nil { return nil } return item.spend }, - func(item *batchSpend, err error) { + Process: func(part []*batchSpend) { + if s.beforeSpendPart != nil { + s.beforeSpendPart(part) + } + + if s.useExpressionSpend() { + s.SpendMultiWithExpressions(s.ctx, part, &outcome) + } else { + s.executeLuaSpendBatch(part, &outcome) + } + }, + Result: func(item *batchSpend) (error, bool) { + if item == nil || !item.published.Load() { + return nil, false + } + return item.err, true + }, + Reject: func(item *batchSpend, err error) { item.complete(err) }, - ) - if len(batch) == 0 { - return - } - - // Use expression-based implementation only when each Aerospike record holds a single - // UTXO (utxoBatchSize == 1). With multiple UTXOs per record, the expression cannot - // byte-compare the specific UTXO hash at a list offset, so we fall back to Lua which - // performs the strict precondition check inside the UDF. - if s.useExpressionSpend() { - s.SpendMultiWithExpressions(s.ctx, batch) - return - } - - s.executeLuaSpendBatch(batch) + SameChecks: func(a, b *batchSpend) bool { + return a.blockHeight == b.blockHeight && + a.ignoreConflicting == b.ignoreConflicting && + a.ignoreLocked == b.ignoreLocked && + utxo.SameUTXOHash(a.spend, b.spend) + }, + }) } // executeLuaSpendBatch runs the Lua UDF spend pipeline for the provided batch. It is the // shared backend used by sendSpendBatchLua's Lua route and by the expression path's -// retry-through-Lua handler. Callers MUST have already run any duplicate-claim -// filtering, since this method does not re-run it and assumes every item still expects -// exactly one response on its errCh. -func (s *Store) executeLuaSpendBatch(batch []*batchSpend) { - s.executeLuaSpendBatchContext(s.ctx, batch) +// retry-through-Lua handler. Callers must supply a batch without conflicting claims +// on the same outpoint. This method does not split batches itself. +// A panic reaches sendSpendBatchLua, which answers the parts that did not run. +func (s *Store) executeLuaSpendBatch(batch []*batchSpend, outcome *spendBreakerOutcome) { + s.runLuaSpendBatch(s.ctx, batch, outcome) } // executeLuaSpendBatchContext keeps recovery writes synchronous and bounds the network request @@ -1047,6 +1248,13 @@ func (s *Store) executeLuaSpendBatchContext(parentCtx context.Context, batch []* } }) }() + + defer s.releaseUnsettledSlots(batch) + + s.runLuaSpendBatch(parentCtx, batch, &spendBreakerOutcome{}) +} + +func (s *Store) runLuaSpendBatch(parentCtx context.Context, batch []*batchSpend, outcome *spendBreakerOutcome) { if len(batch) == 0 { return } @@ -1056,13 +1264,8 @@ func (s *Store) executeLuaSpendBatchContext(parentCtx context.Context, batch []* ctx, _, deferFn := tracing.Tracer("aerospike").Start(parentCtx, "sendSpendBatchLua", tracing.WithParentStat(stat), - tracing.WithHistogram(prometheusUtxoSpendBatch), ) - - defer func() { - prometheusUtxoSpendBatchSize.Observe(float64(len(batch))) - deferFn() - }() + defer deferFn() batchID := s.batchID.Add(1) s.logSpendBatchStart(batchID, len(batch)) @@ -1075,10 +1278,14 @@ func (s *Store) executeLuaSpendBatchContext(parentCtx context.Context, batch []* batchRecords, batchRecordKeys := s.createBatchRecords(batchesByKey) if err := s.executeSpendBatchContext(ctx, batchRecords, batch, batchID); err != nil { + if isInfrastructureFailure(err) { + outcome.record(s.spendCircuitBreaker, false, batchProbeSlots(batchesByKey, batch)...) + } + return } - s.processSpendBatchResults(ctx, batchRecords, batchRecordKeys, batchesByKey, batch, batchID) + s.processSpendBatchResults(ctx, batchRecords, batchRecordKeys, batchesByKey, batch, batchID, outcome) stat.NewStat("postBatchOperate").AddTime(start) } @@ -1209,7 +1416,7 @@ func (s *Store) executeSpendBatchContext(ctx context.Context, batchRecords []aer } // processSpendBatchResults processes the results of the batch operation -func (s *Store) processSpendBatchResults(ctx context.Context, batchRecords []aerospike.BatchRecordIfc, batchRecordKeys []keyIgnoreLocked, batchesByKey map[keyIgnoreLocked][]aerospike.MapValue, batch []*batchSpend, batchID uint64) { +func (s *Store) processSpendBatchResults(ctx context.Context, batchRecords []aerospike.BatchRecordIfc, batchRecordKeys []keyIgnoreLocked, batchesByKey map[keyIgnoreLocked][]aerospike.MapValue, batch []*batchSpend, batchID uint64, outcome *spendBreakerOutcome) { for batchIdx, batchRecord := range batchRecords { key := batchRecordKeys[batchIdx] batchByKey, ok := batchesByKey[key] @@ -1219,7 +1426,7 @@ func (s *Store) processSpendBatchResults(ctx context.Context, batchRecords []aer } txID := batch[batchByKey[0]["idx"].(int)].spend.TxID - s.processSingleBatchResult(ctx, batchRecord, batchByKey, batch, txID, key.blockHeight, batchID) + s.processSingleBatchResult(ctx, batchRecord, batchByKey, batch, txID, key.blockHeight, batchID, outcome) } if s.settings.UtxoStore.VerboseDebug { @@ -1228,22 +1435,38 @@ func (s *Store) processSpendBatchResults(ctx context.Context, batchRecords []aer } // processSingleBatchResult processes a single batch record result -func (s *Store) processSingleBatchResult(ctx context.Context, batchRecord aerospike.BatchRecordIfc, batchByKey []aerospike.MapValue, batch []*batchSpend, txID *chainhash.Hash, thisBlockHeight uint32, batchID uint64) { +func (s *Store) processSingleBatchResult(ctx context.Context, batchRecord aerospike.BatchRecordIfc, batchByKey []aerospike.MapValue, batch []*batchSpend, txID *chainhash.Hash, thisBlockHeight uint32, batchID uint64, outcome *spendBreakerOutcome) { batchErr := batchRecord.BatchRec().Err if batchErr != nil { s.handleBatchError(batchByKey, batch, thisBlockHeight, batchID, batchErr) + // Only infrastructure failures count toward the circuit breaker. Per-record + // data-state errors (e.g. KEY_NOT_FOUND_ERROR from missing parents during + // catch-up sync) must not trip it — issue #953. They still prove the + // backend answered, so they count as a success for half-open probes. + switch { + case isInfrastructureFailure(batchErr): + outcome.record(s.spendCircuitBreaker, false, takeProbeSlots(batchByKey, batch)...) + case isServerAnswer(batchErr): + if slots := takeProbeSlots(batchByKey, batch); len(slots) > 0 { + outcome.record(s.spendCircuitBreaker, true, slots...) + } + default: + s.releaseProbeSlots(batchByKey, batch) + } return } response := batchRecord.BatchRec().Record if response == nil || response.Bins == nil || response.Bins[LuaSuccess.String()] == nil { s.handleMissingResponse(batchByKey, batch, txID) + s.releaseProbeSlots(batchByKey, batch) return } res, parseErr := s.ParseLuaMapResponse(response.Bins[LuaSuccess.String()]) if parseErr != nil { s.handleParseError(batchByKey, batch, txID, parseErr) + s.releaseProbeSlots(batchByKey, batch) return } @@ -1256,11 +1479,89 @@ func (s *Store) processSingleBatchResult(ctx context.Context, batchRecord aerosp switch res.Status { case LuaStatusOK: s.handleSuccessfulSpends(batchByKey, batch) + outcome.record(s.spendCircuitBreaker, true, takeProbeSlots(batchByKey, batch)...) case LuaStatusError: s.handleErrorSpends(res, batchByKey, batch, txID, thisBlockHeight, batchID) + + if slots := takeProbeSlots(batchByKey, batch); len(slots) > 0 { + outcome.record(s.spendCircuitBreaker, true, slots...) + } + default: + for _, batchItem := range batchByKey { + idx := batchItem["idx"].(int) + batch[idx].complete(errors.NewProcessingError("[SPEND_BATCH_LUA][%s] unknown response status %q", txID.String(), res.Status)) + } + + s.releaseProbeSlots(batchByKey, batch) + } +} + +// takeSlot hands over the half-open probe slot of an item and clears it, so a +// slot is recorded or released exactly once. Only the batcher that won Start owns +// the slot of a dispatched item, so an item that is not started yields no slot: +// its caller or the batcher that won its Abandon already settled it. +func takeSlot(item *batchSpend) breakerSlot { + if item == nil || !item.admission.Started() { + return breakerSlot{} + } + + slot := item.breakerSlot + item.breakerSlot = breakerSlot{} + + return slot +} + +// takeProbeSlots takes the half-open probe slots held by the items of one batch record. +func takeProbeSlots(batchByKey []aerospike.MapValue, batch []*batchSpend) []breakerSlot { + var slots []breakerSlot + + for _, batchItem := range batchByKey { + if slot := takeSlot(batch[batchItem["idx"].(int)]); slot.taken { + slots = append(slots, slot) + } + } + + return slots +} + +// releaseProbeSlots gives back the probe slots of items whose response carried +// no evidence about the health of the backend. +func (s *Store) releaseProbeSlots(batchByKey []aerospike.MapValue, batch []*batchSpend) { + for _, slot := range takeProbeSlots(batchByKey, batch) { + s.spendCircuitBreaker.Release(slot) } } +// releaseUnsettledSlots gives back every probe slot in batch that no outcome has +// consumed: items completed before reaching the backend, responses with an +// unknown status, a non-infrastructure whole-batch error, or a panic part way +// through the results. A started item is released by the batcher that started it. +// An item still queued at this point will never be dispatched, so the sweep +// claims it by winning its Abandon. An item whose caller won the Abandon is +// skipped, because the caller releases its slot. +func (s *Store) releaseUnsettledSlots(batch []*batchSpend) { + for _, item := range batch { + if item != nil && !item.admission.Started() && item.admission.Abandon() { + s.releaseBreakerSlot(item) + } + + if slot := takeSlot(item); slot.taken { + s.spendCircuitBreaker.Release(slot) + } + } +} + +// batchProbeSlots takes the probe slots of the items of every record in batchesByKey. +func batchProbeSlots(batchesByKey map[keyIgnoreLocked][]aerospike.MapValue, batch []*batchSpend) []breakerSlot { + slots := make([]breakerSlot, 0, len(batchesByKey)) + + for _, batchByKey := range batchesByKey { + slots = append(slots, takeProbeSlots(batchByKey, batch)...) + } + + return slots +} + // handleBatchError handles errors from batch operations func (s *Store) handleBatchError(batchByKey []aerospike.MapValue, batch []*batchSpend, thisBlockHeight uint32, batchID uint64, err error) { s.demoteNativeOnUnsupported(err) @@ -1282,12 +1583,6 @@ func (s *Store) handleBatchError(batchByKey []aerospike.MapValue, batch []*batch idx := batchItem["idx"].(int) batch[idx].complete(errors.NewStorageError("[SPEND_BATCH_LUA][%s] error in aerospike spend batch record, blockHeight %d: %d", batch[idx].spend.TxID.String(), thisBlockHeight, batchID, err)) } - // Only count infrastructure failures toward the circuit breaker. - // Per-record data-state errors (e.g. KEY_NOT_FOUND_ERROR from missing - // parents during catch-up sync) must not trip the breaker — issue #953. - if s.spendCircuitBreaker != nil && isInfrastructureFailure(err) { - s.spendCircuitBreaker.RecordFailure() - } } // handleMissingResponse handles missing response from batch operation @@ -1340,10 +1635,6 @@ func (s *Store) handleSuccessfulSpends(batchByKey []aerospike.MapValue, batch [] idx := batchItem["idx"].(int) batch[idx].complete(nil) } - // Record successful batch operation for circuit breaker - if s.spendCircuitBreaker != nil { - s.spendCircuitBreaker.RecordSuccess() - } } // handleErrorSpends handles error responses from spend operations @@ -1432,6 +1723,12 @@ func (s *Store) createSpendError(errMsg LuaErrorInfo, batchItem *batchSpend, txI return errors.NewStorageError("[SPEND_BATCH_LUA][%s] UTXO already spent but no spending data provided", txID.String()) case LuaErrorCodeInvalidSpend: + if errMsg.SpendingData != "" { + if spendingData, parseErr := spendpkg.NewSpendingDataFromString(errMsg.SpendingData); parseErr == nil { + return errors.NewUtxoInvalidSpendError(spendingData, "[SPEND_BATCH_LUA][%s] invalid spend for vout %d: %s", txID.String(), batchItem.spend.Vout, errMsg.Message) + } + } + return errors.NewUtxoError("[SPEND_BATCH_LUA][%s] invalid spend for vout %d: %s", txID.String(), batchItem.spend.Vout, errMsg.Message) case LuaErrorCodeFrozen: diff --git a/stores/utxo/aerospike/spend_abort_test.go b/stores/utxo/aerospike/spend_abort_test.go index 42ab01a6b9..aea3af5004 100644 --- a/stores/utxo/aerospike/spend_abort_test.go +++ b/stores/utxo/aerospike/spend_abort_test.go @@ -1,10 +1,17 @@ package aerospike_test import ( + "context" "testing" "time" + "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/go-bt/v2/bscript" + "github.com/bsv-blockchain/go-bt/v2/chainhash" "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + teranode_aerospike "github.com/bsv-blockchain/teranode/stores/utxo/aerospike" + spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" "github.com/bsv-blockchain/teranode/ulogger" "github.com/bsv-blockchain/teranode/util/test" "github.com/stretchr/testify/require" @@ -48,3 +55,328 @@ func TestStore_Spend_AbortReturnsNilSlice(t *testing.T) { "abort must surface a service-unavailable/context error, got: %v", err) require.Nil(t, spends, "Spend must not return the live spends slice on the abort path") } + +// A claim that started before its caller gave up and finishes after it must +// settle before the caller returns, and its spend must be rolled back, because +// the caller got an error and no spender record is ever created. The second +// shape is a claim with the wrong UTXO hash ahead of a claim with the right +// hash, so the right claim runs in a later backend part. +func TestSpendAwaitsAdmittedClaimThatFinishesAfterCallerGaveUp(t *testing.T) { + for _, expressions := range []bool{false, true} { + for _, shape := range []string{"single claim", "wrong hash claim first"} { + for _, cancelCaller := range []bool{false, true} { + name := shape + " lua" + if expressions { + name = shape + " expressions" + } + + wantClass := errors.ErrServiceUnavailable + if cancelCaller { + name += " cancellation" + wantClass = errors.ErrContextCanceled + } else { + name += " timeout" + } + + t.Run(name, func(t *testing.T) { + tSettings := test.CreateBaseTestSettings(t) + tSettings.UtxoStore.SpendWaitTimeout = 300 * time.Millisecond + tSettings.Aerospike.EnableSpendFilterExpressions = expressions + + client, store, storeCtx, deferFn := initAerospike(t, tSettings, ulogger.NewErrorTestLogger(t)) + t.Cleanup(deferFn) + cleanDB(t, client) + require.NoError(t, store.SetBlockHeight(2)) + + parent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte("late-" + name)) + require.NoError(t, parent.From(prev.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + _, err := store.Create(storeCtx, parent, 1) + require.NoError(t, err) + + laterTx := bt.NewTx() + require.NoError(t, laterTx.From(parent.TxID(), 0, parent.Outputs[0].LockingScript.String(), parent.Outputs[0].Satoshis)) + require.NoError(t, laterTx.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + laterTx.LockTime = 2 + + var before []*utxo.Spend + + if shape == "wrong hash claim first" { + wrongHash := chainhash.Hash{99} + owner := chainhash.Hash{7} + before = []*utxo.Spend{{ + TxID: parent.TxIDChainHash(), Vout: 0, UTXOHash: &wrongHash, + SpendingData: spendpkg.NewSpendingData(&owner, 0), + }} + } + + callerCtx, cancel := context.WithCancel(storeCtx) + defer cancel() + + inFlight := teranode_aerospike.SpendAbortInFlightForTest(t) + entered, release := make(chan struct{}), make(chan struct{}) + + result, done, err := store.SpendHeldForTest(callerCtx, laterTx, 2, before, entered, release) + require.NoError(t, err) + + select { + case <-entered: + case <-time.After(5 * time.Second): + t.Fatal("claim part did not start") + } + + if cancelCaller { + cancel() + } + + select { + case err := <-result: + t.Fatalf("caller returned %v while its admitted claim was still running", err) + case <-time.After(800 * time.Millisecond): + } + + close(release) + + select { + case err := <-result: + require.ErrorIs(t, err, wantClass) + case <-time.After(10 * time.Second): + t.Fatal("caller did not return after the claim settled") + } + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("batch did not complete") + } + + laterSpends, err := utxo.GetSpends(laterTx) + require.NoError(t, err) + + stored, err := store.GetSpend(storeCtx, laterSpends[0]) + require.NoError(t, err) + require.Equal(t, int(utxo.Status_OK), stored.Status, "the late claim's spend was left on the outpoint") + require.Nil(t, stored.SpendingData) + require.Equal(t, inFlight, teranode_aerospike.SpendAbortInFlightForTest(t), "a claim that settled inside the bound must not count as in flight") + }) + } + } + } +} + +func prepareHeldSpend(t *testing.T, name string, wait, bound time.Duration) (store *teranode_aerospike.Store, storeCtx context.Context, laterTx *bt.Tx, before []*utxo.Spend) { + t.Helper() + + tSettings := test.CreateBaseTestSettings(t) + tSettings.UtxoStore.SpendWaitTimeout = wait + tSettings.UtxoStore.SpendRollbackTimeout = bound + + client, store, storeCtx, deferFn := initAerospike(t, tSettings, ulogger.NewErrorTestLogger(t)) + t.Cleanup(deferFn) + cleanDB(t, client) + require.NoError(t, store.SetBlockHeight(2)) + + parent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte(name)) + require.NoError(t, parent.From(prev.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + _, err := store.Create(storeCtx, parent, 1) + require.NoError(t, err) + + laterTx = bt.NewTx() + require.NoError(t, laterTx.From(parent.TxID(), 0, parent.Outputs[0].LockingScript.String(), parent.Outputs[0].Satoshis)) + require.NoError(t, laterTx.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + laterTx.LockTime = 2 + + wrongHash := chainhash.Hash{99} + owner := chainhash.Hash{7} + before = []*utxo.Spend{{ + TxID: parent.TxIDChainHash(), Vout: 0, UTXOHash: &wrongHash, + SpendingData: spendpkg.NewSpendingData(&owner, 0), + }} + + return store, storeCtx, laterTx, before +} + +func outpointIsUnspent(ctx context.Context, store *teranode_aerospike.Store, laterTx *bt.Tx) bool { + laterSpends, err := utxo.GetSpends(laterTx) + if err != nil { + return false + } + + stored, err := store.GetSpend(ctx, laterSpends[0]) + + return err == nil && stored.Status == int(utxo.Status_OK) && stored.SpendingData == nil +} + +// A claim that started before its caller gave up and finishes after the +// courtesy wait ends must be rolled back by whoever completes it, with no time +// bound, because the caller got an error and no spender record is ever created. +func TestSpendRollsBackClaimThatFinishesAfterAwaitBound(t *testing.T) { + store, storeCtx, laterTx, before := prepareHeldSpend(t, "orphan-after-bound", 300*time.Millisecond, 4*time.Second) + inFlight := teranode_aerospike.SpendAbortInFlightForTest(t) + entered, release := make(chan struct{}), make(chan struct{}) + + result, done, err := store.SpendHeldForTest(storeCtx, laterTx, 2, before, entered, release) + require.NoError(t, err) + + select { + case <-entered: + case <-time.After(5 * time.Second): + t.Fatal("claim part did not start") + } + + select { + case err := <-result: + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + case <-time.After(5 * time.Second): + t.Fatal("caller did not return while its started claim was still held") + } + + select { + case <-done: + t.Fatal("the claim finished before the caller returned, so the late path was not exercised") + default: + } + + require.Equal(t, inFlight+1, teranode_aerospike.SpendAbortInFlightForTest(t), "the claim the caller gave up on must count as in flight") + + close(release) + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("batch did not complete") + } + + require.Eventually(t, func() bool { return outpointIsUnspent(storeCtx, store, laterTx) }, 10*time.Second, 50*time.Millisecond, + "the late claim's spend was left on the outpoint") +} + +// A claim whose success was published before its caller gave up on it must be +// rolled back by the caller's side of the hand-off. +func TestSpendRollsBackClaimPublishedBeforeItsCallerGaveUp(t *testing.T) { + store, storeCtx, laterTx, _ := prepareHeldSpend(t, "orphan-after-publish", 300*time.Millisecond, 30*time.Second) + + laterSpends, err := utxo.GetSpends(laterTx) + require.NoError(t, err) + + orphan := store.SpendPublishedForTest(t, laterSpends[0], 2) + require.False(t, outpointIsUnspent(storeCtx, store, laterTx), "the claim must have spent the outpoint") + + orphan() + + require.Eventually(t, func() bool { return outpointIsUnspent(storeCtx, store, laterTx) }, 10*time.Second, 50*time.Millisecond, + "a claim published before its caller gave up was left on the outpoint") +} + +// The courtesy wait for a started claim and the rollback share one budget, so a +// failed Spend returns within SpendWaitTimeout plus SpendRollbackTimeout. The +// courtesy wait is only a quarter of that budget, so with a claim held past it +// the caller returns well before the whole budget is gone. +func TestSpendCallerBoundHoldsWhileStartedClaimIsHeld(t *testing.T) { + const ( + wait = 300 * time.Millisecond + bound = 2 * time.Second + ) + + store, storeCtx, laterTx, before := prepareHeldSpend(t, "caller-bound", wait, bound) + entered, release := make(chan struct{}), make(chan struct{}) + started := time.Now() + + result, done, err := store.SpendHeldForTest(storeCtx, laterTx, 2, before, entered, release) + require.NoError(t, err) + + select { + case <-entered: + case <-time.After(5 * time.Second): + t.Fatal("claim part did not start") + } + + select { + case err := <-result: + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + case <-time.After(wait + bound + 2*time.Second): + t.Fatal("caller did not return within the documented bound") + } + + elapsed := time.Since(started) + require.LessOrEqual(t, elapsed, wait+bound+500*time.Millisecond, "caller held longer than SpendWaitTimeout plus SpendRollbackTimeout") + require.Less(t, elapsed, wait+bound/2, "the courtesy wait must take a quarter of the budget, not all of it") + + close(release) + <-done +} + +// A blocking enqueue on a full batcher channel must not use up the wait budget: +// the budget starts when the enqueue returns. +func TestSpendWaitBudgetStartsAfterEnqueueOnSaturatedBatcher(t *testing.T) { + store, storeCtx, laterTx, _ := prepareHeldSpend(t, "saturated", 300*time.Millisecond, 30*time.Second) + release := make(chan struct{}) + + result := store.SpendSaturatedForTest(storeCtx, laterTx, 2, release) + + time.Sleep(800 * time.Millisecond) + close(release) + + select { + case err := <-result: + require.NoError(t, err, "a spend that waited for room in the batcher longer than SpendWaitTimeout must still succeed") + case <-time.After(10 * time.Second): + t.Fatal("Spend did not return after the batcher drained") + } + + require.False(t, outpointIsUnspent(storeCtx, store, laterTx), "the spend must have been applied") +} + +// When a completed spend of the same tx failed with ErrTxLocked and nothing +// proves the tx unwinnable, a concurrent attempt at the same txid may own the +// spends, so the batch rollback is suppressed. The late claim must then be left +// as the batch's own spends are, not unspent. +func TestSpendDoesNotRollBackLateClaimWhenTransientLockSuppressesRollback(t *testing.T) { + store, storeCtx, laterTx, _ := prepareHeldSpend(t, "orphan-suppressed", 300*time.Millisecond, 4*time.Second) + + lockedParent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte("orphan-suppressed-locked")) + require.NoError(t, lockedParent.From(prev.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + lockedParent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, lockedParent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + _, err := store.Create(storeCtx, lockedParent, 1, utxo.WithLocked(true)) + require.NoError(t, err) + + twoInputs := bt.NewTx() + require.NoError(t, twoInputs.From(lockedParent.TxID(), 0, lockedParent.Outputs[0].LockingScript.String(), lockedParent.Outputs[0].Satoshis)) + require.NoError(t, twoInputs.From(laterTx.Inputs[0].PreviousTxIDStr(), laterTx.Inputs[0].PreviousTxOutIndex, laterTx.Inputs[0].PreviousTxScript.String(), laterTx.Inputs[0].PreviousTxSatoshis)) + require.NoError(t, twoInputs.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + twoInputs.LockTime = 2 + + inFlight := teranode_aerospike.SpendAbortInFlightForTest(t) + entered, release := make(chan struct{}), make(chan struct{}) + + result, done, err := store.SpendHeldAfterFailureForTest(storeCtx, twoInputs, 2, entered, release) + require.NoError(t, err) + + select { + case <-entered: + case <-time.After(5 * time.Second): + t.Fatal("claim part did not start") + } + + select { + case err := <-result: + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + case <-time.After(5 * time.Second): + t.Fatal("caller did not return while its started claim was still held") + } + + require.Equal(t, inFlight+1, teranode_aerospike.SpendAbortInFlightForTest(t), "a suppressed late claim still counts as in flight") + + close(release) + <-done + + require.Never(t, func() bool { return outpointIsUnspent(storeCtx, store, laterTx) }, 3*time.Second, 50*time.Millisecond, + "the late claim was rolled back although a transient lock suppressed the batch rollback") +} diff --git a/stores/utxo/aerospike/spend_batch_export_test.go b/stores/utxo/aerospike/spend_batch_export_test.go new file mode 100644 index 0000000000..0f5776e75c --- /dev/null +++ b/stores/utxo/aerospike/spend_batch_export_test.go @@ -0,0 +1,184 @@ +package aerospike + +import ( + "context" + "testing" + "time" + + "github.com/bsv-blockchain/go-batcher/v2" + "github.com/bsv-blockchain/go-batcher/v2/completion" + "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + dto "github.com/prometheus/client_model/go" + "github.com/stretchr/testify/require" +) + +// SendSpendBatchForTest drives an exact batch through the real backend. It is +// compiled only for tests so external-package integration tests need no sleeps +// to establish batch membership or ordering. +func (s *Store) SendSpendBatchForTest(t *testing.T, spends []*utxo.Spend, height uint32) { + t.Helper() + group := completion.NewGroup(int32(len(spends))) + batch := make([]*batchSpend, len(spends)) + for i, spend := range spends { + batch[i] = &batchSpend{spend: spend, blockHeight: height, group: group} + } + s.sendSpendBatchLua(batch) + require.NoError(t, group.Wait(context.Background(), time.Second), "all batch claims must complete") +} + +// SpendHeldForTest runs Spend for tx with a batcher that hands the store's claim +// back, then dispatches before followed by that claim as one batch. The part that +// carries the claim closes entered once it started and then waits for release. +// It returns the channel that receives Spend's error and the channel closed when +// the batch has finished. +func (s *Store) SpendHeldForTest(ctx context.Context, tx *bt.Tx, height uint32, before []*utxo.Spend, entered chan<- struct{}, release <-chan struct{}) (<-chan error, <-chan struct{}, error) { + queued := make(chan *batchSpend, 1) + s.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + + result := make(chan error, 1) + go func() { _, err := s.Spend(ctx, tx, height); result <- err }() + + var claim *batchSpend + + select { + case claim = <-queued: + case <-time.After(3 * time.Second): + return nil, nil, errors.NewProcessingError("claim not queued") + } + + group := completion.NewGroup(int32(len(before))) + batch := make([]*batchSpend, 0, len(before)+1) + + for _, spend := range before { + batch = append(batch, &batchSpend{spend: spend, blockHeight: height, group: group}) + } + + batch = append(batch, claim) + + s.beforeSpendPart = func(part []*batchSpend) { + for _, item := range part { + if item == claim { + close(entered) + <-release + + return + } + } + } + + done := make(chan struct{}) + go func() { defer close(done); s.sendSpendBatchLua(batch) }() + + return result, done, nil +} + +// SpendAbortInFlightForTest reports the in-flight abort counter. +func SpendAbortInFlightForTest(t *testing.T) float64 { + t.Helper() + + var metric dto.Metric + require.NoError(t, prometheusUtxoSpendAbortInFlight.Write(&metric)) + + return metric.GetCounter().GetValue() +} + +// SpendPublishedForTest spends one claim through the real backend, as a claim +// that has already published its success, and returns a func that marks the +// claim orphaned, as a caller that gave up after the publish would. +func (s *Store) SpendPublishedForTest(t *testing.T, spend *utxo.Spend, height uint32) (orphan func()) { + t.Helper() + + group := completion.NewGroup(1) + item := &batchSpend{spend: spend, blockHeight: height, group: group, done: make(chan struct{}), onOrphan: s.rollbackOrphanedSpend} + + s.sendSpendBatchLua([]*batchSpend{item}) + require.NoError(t, group.Wait(context.Background(), time.Second), "the claim must have completed") + require.NoError(t, item.err, "the claim must have succeeded for this test to exercise the orphan path") + + return item.markOrphaned +} + +// SpendSaturatedForTest runs Spend for tx against a spend batcher whose channel +// is full and whose callback blocks until release is closed, then dispatches +// every real claim through the backend. It returns the channel that receives +// Spend's error. +func (s *Store) SpendSaturatedForTest(ctx context.Context, tx *bt.Tx, height uint32, release <-chan struct{}) <-chan error { + s.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { + <-release + + real := make([]*batchSpend, 0, len(items)) + + for _, item := range items { + if item.group != nil { + real = append(real, item) + } + } + + if len(real) > 0 { + s.sendSpendBatchLua(real) + } + }, false) + + for i := 0; i < 1000; i++ { + go s.spendBatcher.Put(&batchSpend{spend: &utxo.Spend{}}) + } + + time.Sleep(300 * time.Millisecond) + + result := make(chan error, 1) + go func() { _, err := s.Spend(ctx, tx, height); result <- err }() + + return result +} + +// SpendHeldAfterFailureForTest runs Spend for a tx of two inputs. The first +// input's claim is dispatched alone and completes at once, and the second +// input's claim is dispatched alone with its part held until release is closed. +// The part closes entered once it started. It returns the channel that receives +// Spend's error and the channel closed when the held claim has finished. +func (s *Store) SpendHeldAfterFailureForTest(ctx context.Context, tx *bt.Tx, height uint32, entered chan<- struct{}, release <-chan struct{}) (<-chan error, <-chan struct{}, error) { + queued := make(chan *batchSpend, 4) + s.spendBatcher = batcher.NewWithPool(2, time.Millisecond, func(items []*batchSpend) { + for _, item := range items { + queued <- item + } + }, false) + + result := make(chan error, 1) + go func() { _, err := s.Spend(ctx, tx, height); result <- err }() + + var first, claim *batchSpend + + for i := 0; i < 2; i++ { + select { + case item := <-queued: + if first == nil { + first = item + } else { + claim = item + } + case <-time.After(3 * time.Second): + return nil, nil, errors.NewProcessingError("claims not queued") + } + } + + s.sendSpendBatchLua([]*batchSpend{first}) + + s.beforeSpendPart = func(part []*batchSpend) { + for _, item := range part { + if item == claim { + close(entered) + <-release + + return + } + } + } + + done := make(chan struct{}) + go func() { defer close(done); s.sendSpendBatchLua([]*batchSpend{claim}) }() + + return result, done, nil +} diff --git a/stores/utxo/aerospike/spend_enqueue_alias_test.go b/stores/utxo/aerospike/spend_enqueue_alias_test.go index d244daee9b..ee6d983d00 100644 --- a/stores/utxo/aerospike/spend_enqueue_alias_test.go +++ b/stores/utxo/aerospike/spend_enqueue_alias_test.go @@ -7,9 +7,13 @@ import ( "testing" "time" + "github.com/bsv-blockchain/go-batcher/v2/completion" "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/go-bt/v2/chainhash" "github.com/bsv-blockchain/go-chaincfg" "github.com/bsv-blockchain/teranode/settings" + "github.com/bsv-blockchain/teranode/stores/utxo" + spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" "github.com/bsv-blockchain/teranode/ulogger" "github.com/stretchr/testify/require" ) @@ -146,7 +150,7 @@ func TestSpend_EnqueuesOnlyAcceptedItemsWhenBreakerHalfOpen(t *testing.T) { cb := newCircuitBreaker(1, 1, time.Millisecond) require.NotNil(t, cb) - cb.RecordFailure() // trips the breaker open + cb.RecordFailure(currentProbe(cb)) // trips the breaker open time.Sleep(20 * time.Millisecond) // let the cooldown elapse so the next Allow half-opens @@ -179,7 +183,7 @@ func TestSpend_FiltersFromTheFirstInputWhenBreakerFullyOpen(t *testing.T) { cb := newCircuitBreaker(1, 1, time.Hour) require.NotNil(t, cb) - cb.RecordFailure() // trips the breaker open, cooldown will not elapse + cb.RecordFailure(currentProbe(cb)) // trips the breaker open, cooldown will not elapse s.spendCircuitBreaker = cb @@ -219,3 +223,156 @@ func TestSpend_CompletesEveryEnqueuedItemWhenSendRejected(t *testing.T) { require.Contains(t, spend.Err.Error(), "shutting down") } } + +// silentSpendBatcher accepts items and never completes them, so Spend waits +// until its caller gives up. +type silentSpendBatcher struct{ recordingSpendBatcher } + +func (r *silentSpendBatcher) PutBatchCtx(context.Context, []*batchSpend, ...int) {} + +// halfOpenBreaker returns a breaker in the open state whose next Admit half-opens it. +func halfOpenBreaker(t *testing.T) *circuitBreaker { + t.Helper() + + cb := newCircuitBreaker(1, 1, time.Hour) + require.NotNil(t, cb) + + cb.RecordFailure(currentProbe(cb)) + + cb.mu.Lock() + cb.nextAttempt = time.Now().Add(-time.Millisecond) + cb.mu.Unlock() + + return cb +} + +func TestSpend_AbandonedRequestReleasesHalfOpenSlot(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + s.spendBatcher = &silentSpendBatcher{} + s.spendCircuitBreaker = halfOpenBreaker(t) + + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + + _, err := s.Spend(ctx, txWithInputs(t, 1), 100) + require.Error(t, err) + require.True(t, admitted(s.spendCircuitBreaker), "the abandoned probe must give its slot back") +} + +// breakerMovingBatcher swallows the items and, on enqueue, trips the breaker, +// lets its cooldown elapse and takes the only half-open probe, so the items +// Spend admitted while the breaker was closed are abandoned after half-open. +type breakerMovingBatcher struct { + silentSpendBatcher + cb *circuitBreaker +} + +func (b *breakerMovingBatcher) PutBatchCtx(context.Context, []*batchSpend, ...int) { + b.cb.RecordFailure(currentProbe(b.cb)) + expireCooldown(b.cb) + admitted(b.cb) +} + +func TestSpend_AbandoningAnItemAdmittedWhileClosedDoesNotFreeAHalfOpenSlot(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + cb := newCircuitBreaker(1, 1, time.Hour) + require.NotNil(t, cb) + + s.spendCircuitBreaker = cb + s.spendBatcher = &breakerMovingBatcher{cb: cb} + + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + + _, err := s.Spend(ctx, txWithInputs(t, 1), 100) + require.Error(t, err) + + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, 1, cb.halfOpenAttempts) + require.False(t, admitted(cb), "the abandoned item took no slot, so none may be freed for another probe") +} + +func TestSpend_DispatchRejectReleasesHalfOpenSlot(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + cb := halfOpenBreaker(t) + s.spendCircuitBreaker = cb + + allowed, slot := cb.Admit() + require.True(t, allowed, "the request takes the only half-open slot") + require.False(t, admitted(cb)) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + parent, utxoHash, spender := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3} + item := &batchSpend{ + spend: &utxo.Spend{TxID: &parent, UTXOHash: &utxoHash, SpendingData: spendpkg.NewSpendingData(&spender, 0)}, + group: completion.NewGroup(1), + requestCtx: ctx, + breakerSlot: slot, + } + + s.sendSpendBatchLua([]*batchSpend{item}) + + require.True(t, item.completed.Load()) + require.Error(t, item.err) + require.True(t, admitted(cb), "an item rejected at dispatch must give its slot back") + require.False(t, admitted(cb), "and only once") +} + +func probeItem(slot breakerSlot, ctx context.Context) *batchSpend { + parent, utxoHash, spender := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3} + + return &batchSpend{ + spend: &utxo.Spend{TxID: &parent, UTXOHash: &utxoHash, SpendingData: spendpkg.NewSpendingData(&spender, 0)}, + group: completion.NewGroup(1), + requestCtx: ctx, + breakerSlot: slot, + } +} + +func TestSpend_DispatchSweepLeavesTheSlotOfAnItemItsCallerAbandoned(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + cb := halfOpenBreaker(t) + s.spendCircuitBreaker = cb + + allowed, slot := cb.Admit() + require.True(t, allowed) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + item := probeItem(slot, ctx) + + require.True(t, item.admission.Abandon(), "the caller wins the abandonment and now owns the slot") + cancel() + + s.sendSpendBatchLua([]*batchSpend{item}) + + require.True(t, item.completed.Load()) + require.True(t, item.breakerSlot.taken, "the batcher must not touch the slot its caller owns") + require.False(t, admitted(cb), "the slot stays held until its owner releases it") + + s.releaseBreakerSlot(item) + + require.True(t, admitted(cb), "the owner's release frees the slot") + require.False(t, admitted(cb), "and it is freed exactly once") +} + +func TestSpend_DispatchSweepReleasesTheSlotOfAnItemItNeverStarted(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + cb := halfOpenBreaker(t) + s.spendCircuitBreaker = cb + + allowed, slot := cb.Admit() + require.True(t, allowed) + + item := probeItem(slot, context.Background()) + + s.releaseUnsettledSlots([]*batchSpend{item}) + s.releaseUnsettledSlots([]*batchSpend{item}) + + require.False(t, item.breakerSlot.taken) + require.True(t, admitted(cb), "the sweep owns an item that was never started") + require.False(t, admitted(cb), "and releases it exactly once") +} diff --git a/stores/utxo/aerospike/spend_expressions.go b/stores/utxo/aerospike/spend_expressions.go index 757a758d10..942d328d56 100644 --- a/stores/utxo/aerospike/spend_expressions.go +++ b/stores/utxo/aerospike/spend_expressions.go @@ -285,15 +285,16 @@ func (s *Store) buildSpendOperations( // SpendMultiWithExpressions processes multiple spend requests using Aerospike expressions. // Unlike the Lua-based spendMulti which handles multiple spends per transaction in a single UDF call, // this creates individual batch operations for each spend but executes them in a single batch. -func (s *Store) SpendMultiWithExpressions(ctx context.Context, batch []*batchSpend) { +// +// Records the expression outcome on `outcome`, which coalesces repeated +// expression outcomes across the parts of one batcher batch until an opposite +// outcome is recorded. +func (s *Store) SpendMultiWithExpressions(ctx context.Context, batch []*batchSpend, outcome *spendBreakerOutcome) { start := time.Now() - _, _, deferFn := tracing.Tracer("aerospike").Start(ctx, "SpendMultiWithExpressions", - tracing.WithHistogram(prometheusUtxoSpendBatch), - ) - defer func() { - prometheusUtxoSpendBatchSize.Observe(float64(len(batch))) - deferFn() - }() + _, _, deferFn := tracing.Tracer("aerospike").Start(ctx, "SpendMultiWithExpressions") + defer deferFn() + + defer s.releaseUnsettledSlots(batch) batchID := s.batchID.Add(1) s.logSpendBatchStart(batchID, len(batch)) @@ -357,6 +358,18 @@ func (s *Store) SpendMultiWithExpressions(ctx context.Context, batch []*batchSpe batchPolicy := util.GetAerospikeBatchPolicy(s.settings) if err := s.batchOperate(batchPolicy, batchRecords); err != nil { + if isInfrastructureFailure(err) { + var slots []breakerSlot + + for _, bItem := range spendIndex { + if slot := takeSlot(bItem); slot.taken { + slots = append(slots, slot) + } + } + + outcome.recordExpressions(s.spendCircuitBreaker, false, true, nil, slots) + } + // complete is CAS-guarded: items already completed above (key-creation/ // validation failures) are no-ops here, so this safely covers every // remaining item without racing or double-signalling. @@ -367,7 +380,7 @@ func (s *Store) SpendMultiWithExpressions(ctx context.Context, batch []*batchSpe } // Process results - s.processSpendBatchResultsExpressions(ctx, batchRecords, spendIndex, batchID, start) + s.processSpendBatchResultsExpressions(ctx, batchRecords, spendIndex, batchID, start, outcome) } // processSpendBatchResultsExpressions processes the results from expression-based spend operations. @@ -385,6 +398,7 @@ func (s *Store) processSpendBatchResultsExpressions( spendIndex map[int]*batchSpend, batchID uint64, start time.Time, + outcome *spendBreakerOutcome, ) { okCount := 0 errCount := 0 @@ -393,6 +407,13 @@ func (s *Store) processSpendBatchResultsExpressions( // (missing parent during catch-up) or FILTERED_OUT — issue #953. infraErrCount := 0 + // Half-open probe slots of the items answered, by outcome. A completed round + // trip, even one that carries a data-state error, proves the backend is + // healthy. A response that cannot be parsed proves nothing, so its slot is + // released. + var successSlots []breakerSlot + var failureSlots []breakerSlot + // Collect follow-up actions. Extra-record increments are grouped by the spend's // block height so each tx's delete-at-height is stamped from its own spend // height (a single batch may aggregate spends from different blocks). @@ -419,6 +440,9 @@ func (s *Store) processSpendBatchResultsExpressions( if aErr.ResultCode == types.KEY_NOT_FOUND_ERROR { bItem.complete(errors.NewTxNotFoundError("transaction not found: %s", bItem.spend.TxID.String())) errCount++ + + successSlots = appendTaken(successSlots, bItem) + continue } @@ -436,9 +460,17 @@ func (s *Store) processSpendBatchResultsExpressions( bItem.complete(errors.NewStorageError("spend error for %s:%d", bItem.spend.TxID.String(), bItem.spend.Vout, batchRec.Err)) errCount++ - if isInfrastructureFailure(batchRec.Err) { + + switch { + case isInfrastructureFailure(batchRec.Err): infraErrCount++ + failureSlots = appendTaken(failureSlots, bItem) + case isServerAnswer(batchRec.Err): + successSlots = appendTaken(successSlots, bItem) + default: + s.releaseUnsettledSlots([]*batchSpend{bItem}) } + continue } @@ -446,6 +478,9 @@ func (s *Store) processSpendBatchResultsExpressions( if batchRec.Record == nil || batchRec.Record.Bins == nil { bItem.complete(nil) okCount++ + + successSlots = appendTaken(successSlots, bItem) + continue } @@ -453,6 +488,8 @@ func (s *Store) processSpendBatchResultsExpressions( if err != nil { bItem.complete(errors.NewProcessingError("failed to parse spend state", err)) errCount++ + s.releaseUnsettledSlots([]*batchSpend{bItem}) + continue } @@ -474,20 +511,15 @@ func (s *Store) processSpendBatchResultsExpressions( bItem.complete(nil) okCount++ + + successSlots = appendTaken(successSlots, bItem) } // Record circuit-breaker outcome. Only count true infrastructure errors; // data-state errors (KEY_NOT_FOUND_ERROR, FILTERED_OUT) take their own // per-record branches above and are deliberately excluded from // infraErrCount — issue #953. - if s.spendCircuitBreaker != nil { - if okCount > 0 { - s.spendCircuitBreaker.RecordSuccess() - } - if infraErrCount > 0 { - s.spendCircuitBreaker.RecordFailure() - } - } + outcome.recordExpressions(s.spendCircuitBreaker, okCount > 0 || len(successSlots) > 0, infraErrCount > 0, successSlots, failureSlots) prometheusUtxoMapSpend.Add(float64(okCount)) if errCount > 0 { @@ -531,6 +563,15 @@ func (s *Store) processSpendBatchResultsExpressions( prometheusUtxoSpendExpressionLuaRetry.Inc() prometheusUtxoSpendExpressionLuaRetryN.Add(float64(len(retryThroughLua))) - s.executeLuaSpendBatch(retryThroughLua) + s.executeLuaSpendBatch(retryThroughLua, outcome) + } +} + +// appendTaken takes the probe slot of item and appends it to slots when it holds one. +func appendTaken(slots []breakerSlot, item *batchSpend) []breakerSlot { + if slot := takeSlot(item); slot.taken { + return append(slots, slot) } + + return slots } diff --git a/stores/utxo/aerospike/spend_expressions_doublespend_test.go b/stores/utxo/aerospike/spend_expressions_doublespend_test.go index 6142d029f7..46ab4d681c 100644 --- a/stores/utxo/aerospike/spend_expressions_doublespend_test.go +++ b/stores/utxo/aerospike/spend_expressions_doublespend_test.go @@ -58,7 +58,7 @@ func readSingleUtxoRecord(t *testing.T, client *uaerospike.Client, tSettings *se // batch therefore passed the filter and silently replaced the first-seen spender. // // Each spend below goes through Spend() in its own call (a distinct batch), so the -// in-batch FilterConflictingDuplicateSpendClaims guard does not apply — the store +// in-batch ProcessSpendBatch ordering does not apply — the store // itself must reject the double-spend. func TestStore_SpendExpressions_CrossBatchDoubleSpend(t *testing.T) { cases := []struct { diff --git a/stores/utxo/aerospike/spend_probe_outcome_test.go b/stores/utxo/aerospike/spend_probe_outcome_test.go new file mode 100644 index 0000000000..6ea38a4b5e --- /dev/null +++ b/stores/utxo/aerospike/spend_probe_outcome_test.go @@ -0,0 +1,350 @@ +package aerospike + +import ( + "testing" + "time" + + "github.com/bsv-blockchain/aerospike-client-go/v8" + "github.com/bsv-blockchain/aerospike-client-go/v8/types" + "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/stretchr/testify/require" +) + +func probeBreaker(t *testing.T, halfOpenMax int) *circuitBreaker { + t.Helper() + + cb := newCircuitBreaker(1, halfOpenMax, time.Hour) + require.NotNil(t, cb) + + cb.RecordFailure(breakerSlot{}) + expireCooldown(cb) + + return cb +} + +func admitProbes(t *testing.T, cb *circuitBreaker, batch []*batchSpend) { + t.Helper() + + for _, item := range batch { + allowed, slot := cb.Admit() + require.True(t, allowed) + require.True(t, slot.taken) + + item.breakerSlot = slot + } +} + +func distinctParents(n int) []*chainhash.Hash { + parents := make([]*chainhash.Hash, n) + for i := range parents { + parents[i] = &chainhash.Hash{byte(i + 1)} + } + + return parents +} + +func TestSpend_HalfOpenProbesAnsweredWithBusinessErrorCloseTheBreaker(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 3) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(3)...) + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + for _, record := range records { + record.BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{ + "status": "ERROR", + "errorCode": "SPENT", + "message": "utxo already spent", + }, + }} + } + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + for _, item := range batch { + require.Error(t, item.spend.Err) + } + + require.True(t, admitted(cb), "probes answered with a business error must not hold half-open shut") + require.Equal(t, cbStateClosed, cb.state, "three answered probes close the breaker") +} + +func TestSpend_HalfOpenProbeWithoutUsableResponseReleasesItsSlot(t *testing.T) { + responses := map[string]*aerospike.Record{ + "missing": nil, + "unparsable": {Bins: aerospike.BinMap{LuaSuccess.String(): "not a map"}}, + } + + for name, response := range responses { + t.Run(name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + admitProbes(t, cb, batch) + require.False(t, admitted(cb), "the only probe slot is taken") + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + for _, record := range records { + record.BatchRec().Record = response + } + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Error(t, batch[0].spend.Err) + require.Equal(t, cbStateHalfOpen, cb.state, "no evidence either way, so no close and no trip") + require.True(t, admitted(cb), "the released slot must admit another probe") + }) + } +} + +func TestSpend_HalfOpenProbeAnsweredWithDataStateErrorCountsAsSuccess(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + for _, record := range records { + record.BatchRec().Err = &aerospike.AerospikeError{ResultCode: types.KEY_NOT_FOUND_ERROR} + } + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Error(t, batch[0].spend.Err) + require.Equal(t, cbStateClosed, cb.state) +} + +func timeoutBatch(_ *aerospike.BatchPolicy, _ []aerospike.BatchRecordIfc) aerospike.Error { + return &aerospike.AerospikeError{ResultCode: types.TIMEOUT} +} + +func TestSpend_WholeBatchInfrastructureErrorTripsClosedBreaker(t *testing.T) { + for _, expressions := range []bool{false, true} { + t.Run(pathName(expressions), func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + cb := newCircuitBreaker(1, 1, time.Hour) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(2)...) + s.batchOperateFn = timeoutBatch + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateOpen, cb.state, "one whole-batch TIMEOUT reaches threshold 1") + }) + } +} + +func TestSpend_WholeBatchInfrastructureErrorTripsHalfOpenProbe(t *testing.T) { + for _, expressions := range []bool{false, true} { + t.Run(pathName(expressions), func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + cb := probeBreaker(t, 2) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(2)...) + admitProbes(t, cb, batch) + s.batchOperateFn = timeoutBatch + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateOpen, cb.state, "a probe whose batch times out trips the breaker") + }) + } +} + +func TestSpend_WholeBatchNonInfrastructureErrorReleasesProbeSlots(t *testing.T) { + for _, expressions := range []bool{false, true} { + t.Run(pathName(expressions), func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + cb := probeBreaker(t, 2) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(2)...) + admitProbes(t, cb, batch) + s.batchOperateFn = func(_ *aerospike.BatchPolicy, _ []aerospike.BatchRecordIfc) aerospike.Error { + return &aerospike.AerospikeError{ResultCode: types.PARAMETER_ERROR} + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateHalfOpen, cb.state) + require.Equal(t, 0, cb.halfOpenAttempts) + }) + } +} + +func TestSpend_HalfOpenProbeRecordOutcomesByResultCode(t *testing.T) { + cases := []struct { + name string + code types.ResultCode + wantState cbState + wantSlots int + }{ + {"key not found counts as success", types.KEY_NOT_FOUND_ERROR, cbStateClosed, 0}, + {"device overload releases the slot", types.DEVICE_OVERLOAD, cbStateHalfOpen, 0}, + {"client side error releases the slot", types.PARAMETER_ERROR, cbStateHalfOpen, 0}, + {"timeout trips", types.TIMEOUT, cbStateOpen, 0}, + } + + for _, expressions := range []bool{false, true} { + for _, tc := range cases { + t.Run(pathName(expressions)+"/"+tc.name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + for _, record := range records { + record.BatchRec().Err = &aerospike.AerospikeError{ResultCode: tc.code} + } + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, tc.wantState, cb.state) + require.Equal(t, tc.wantSlots, cb.halfOpenAttempts) + }) + } + } +} + +func TestSpend_HalfOpenProbeWithUnknownStatusReleasesItsSlot(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + for _, record := range records { + record.BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "WEIRD"}, + }} + } + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.ErrorContains(t, batch[0].spend.Err, `unknown response status "WEIRD"`) + + require.Equal(t, cbStateHalfOpen, cb.state) + require.True(t, admitted(cb), "the slot of an unknown status must be released") +} + +func TestSpend_HalfOpenProbeCompletedBeforeTheBackendReleasesItsSlot(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + batch[0].spend.SpendingData = nil + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, _ []aerospike.BatchRecordIfc) aerospike.Error { + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Error(t, batch[0].spend.Err) + require.Equal(t, 0, cb.halfOpenAttempts) + require.True(t, admitted(cb)) +} + +func TestSpend_HalfOpenProbeReleasedWhenTheBatchPanics(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + batch, group := competingSpendBatch(distinctParents(1)...) + admitProbes(t, cb, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, _ []aerospike.BatchRecordIfc) aerospike.Error { + panic("client failed") + } + + require.NotPanics(t, func() { s.sendSpendBatchLua(batch) }) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 0, cb.halfOpenAttempts) + require.True(t, admitted(cb)) +} + +func TestSpend_MixedEpochProbesInOneRecordTripOnInfrastructureError(t *testing.T) { + for _, expressions := range []bool{false, true} { + t.Run(pathName(expressions), func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + s.utxoBatchSize = 128 + cb := probeBreaker(t, 1) + s.spendCircuitBreaker = cb + + _, stale := cb.Admit() + cb.mu.Lock() + cb.nextAttempt = time.Now().Add(-2 * time.Hour) + cb.mu.Unlock() + + allowed, current := cb.Admit() + require.True(t, allowed) + require.NotEqual(t, stale.epoch, current.epoch) + + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent) + batch[1].spend.Vout = 1 + batch[0].breakerSlot = stale + batch[1].breakerSlot = current + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + failRecords(records) + + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateOpen, cb.state, "the current probe must trip even when a stale probe shares the batch") + }) + } +} + +func pathName(expressions bool) string { + if expressions { + return "expressions" + } + + return "lua" +} diff --git a/stores/utxo/aerospike/spend_split_completion_test.go b/stores/utxo/aerospike/spend_split_completion_test.go new file mode 100644 index 0000000000..552d0058f3 --- /dev/null +++ b/stores/utxo/aerospike/spend_split_completion_test.go @@ -0,0 +1,582 @@ +package aerospike + +import ( + "context" + "testing" + "time" + + "github.com/bsv-blockchain/aerospike-client-go/v8" + "github.com/bsv-blockchain/aerospike-client-go/v8/types" + "github.com/bsv-blockchain/go-batcher/v2" + "github.com/bsv-blockchain/go-batcher/v2/completion" + "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" + dto "github.com/prometheus/client_model/go" + "github.com/stretchr/testify/require" +) + +func TestSpendSplitCompletesAllClaimsOnBackendFailure(t *testing.T) { + for _, expressions := range []bool{false, true} { + name := "lua" + if expressions { + name = "expressions" + } + t.Run(name, func(t *testing.T) { + for _, panicSecond := range []bool{false, true} { + scenario := "errors" + if panicSecond { + scenario = "panic after first part" + } + t.Run(scenario, func(t *testing.T) { + s := newTestStoreForGet(t) + s.utxoBatchSize = 1 + s.settings.Aerospike.EnableSpendFilterExpressions = expressions + group := completion.NewGroup(3) + parent, hash := chainhash.Hash{1}, chainhash.Hash{2} + batch := make([]*batchSpend, 3) + for i := range batch { + spender := chainhash.Hash{byte(i + 3)} + batch[i] = &batchSpend{spend: &utxo.Spend{ + TxID: &parent, UTXOHash: &hash, + SpendingData: spendpkg.NewSpendingData(&spender, 0), + }, blockHeight: 100 + uint32(i), group: group} + } + calls := 0 + fail := errorOperate() + s.batchOperateFn = func(policy *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if panicSecond && calls == 2 { + panic("second part failed") + } + return fail(policy, records) + } + require.NotPanics(t, func() { s.sendSpendBatchLua(batch) }) + requireGroupCompleted(t, group, time.Second) + expectedCalls := 3 + if panicSecond { + expectedCalls = 2 + } + require.Equal(t, expectedCalls, calls) + for _, item := range batch { + require.Error(t, item.spend.Err) + require.NotErrorIs(t, item.spend.Err, errors.ErrSpent) + } + }) + } + }) + } +} + +// Metrics count one batcher batch. Expression failures count once across parts, +// while Lua counts every failed record, even when the record key repeats. +func TestSpendSplitRecordsBreakerOutcomesAndOneMetricSample(t *testing.T) { + for _, expressions := range []bool{false, true} { + name := "lua" + if expressions { + name = "expressions" + } + t.Run(name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent, &parent) + for i, item := range batch { + item.blockHeight += uint32(i) + } + + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + failRecords(records) + return nil + } + + samplesBefore := spendBatchSizeSamples(t) + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 3, calls, "different checks still require backend decisions") + if expressions { + require.Equal(t, cbStateClosed, s.spendCircuitBreaker.state) + require.Equal(t, 1, s.spendCircuitBreaker.consecutiveFailures) + } else { + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state, "each Lua record failure must count") + } + require.Equal(t, samplesBefore+1, spendBatchSizeSamples(t)) + }) + } +} + +// The Lua path counts each distinct record key, as before. +func TestSpendLuaBreakerCountsDistinctKeys(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + first, second := chainhash.Hash{1}, chainhash.Hash{9} + batch, group := competingSpendBatch(&first, &second) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + failRecords(records) + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state, "two failed record keys reach threshold 2") +} + +// One tx spending two outputs of the same parent gives two Lua records on the +// same key, because each input carries its own TxID pointer. Without a split, +// both still count, as before the batch could split. +func TestSpendLuaBreakerCountsUnsplitRecordsAsBefore(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + s.utxoBatchSize = 128 + group := completion.NewGroup(2) + hash, spender := chainhash.Hash{2}, chainhash.Hash{3} + batch := make([]*batchSpend, 2) + for vout := range batch { + parent := chainhash.Hash{1} + batch[vout] = &batchSpend{spend: &utxo.Spend{ + TxID: &parent, Vout: uint32(vout), UTXOHash: &hash, + SpendingData: spendpkg.NewSpendingData(&spender, vout), + }, blockHeight: 100, group: group} + } + + records := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, batchRecords []aerospike.BatchRecordIfc) aerospike.Error { + records += len(batchRecords) + failRecords(batchRecords) + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 2, records) + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state, "two failed records reach threshold 2") +} + +// The Lua path records each result in the order the records come back. In +// half-open state a failure first trips the breaker, and a later success in +// open state does not close it. +func TestSpendLuaBreakerRecordsInOrder(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + s.spendCircuitBreaker = newCircuitBreaker(2, 1, time.Minute) + s.spendCircuitBreaker.state = cbStateHalfOpen + first, second := chainhash.Hash{1}, chainhash.Hash{9} + batch, group := competingSpendBatch(&first, &second) + markProbes(s.spendCircuitBreaker, batch) + + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + require.Len(t, records, 2) + failRecords(records[:1]) + records[1].BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state) +} + +// A panic in a later part must not drop the breaker failure of an earlier part. +func TestSpendSplitPanicKeepsEarlierBreakerFailures(t *testing.T) { + for _, expressions := range []bool{false, true} { + name := "lua" + if expressions { + name = "expressions" + } + t.Run(name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + s.spendCircuitBreaker = newCircuitBreaker(5, 1, time.Minute) + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent) + batch[1].blockHeight++ + + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if calls == 2 { + panic("second part failed") + } + failRecords(records) + return nil + } + + require.NotPanics(t, func() { s.sendSpendBatchLua(batch) }) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 2, calls) + require.Equal(t, 1, s.spendCircuitBreaker.consecutiveFailures) + }) + } +} + +// A Lua success after the split resets the breaker failure count once. +func TestSpendLuaBreakerRecordsSuccessForSplitBatch(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + s.spendCircuitBreaker.RecordFailure(currentProbe(s.spendCircuitBreaker)) + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent) + + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + for _, record := range records { + record.BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + } + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 1, calls, "the second claim is refused locally once the first one owns the outpoint") + require.NoError(t, batch[0].spend.Err) + require.ErrorIs(t, batch[1].spend.Err, errors.ErrSpent) + require.Equal(t, 0, s.spendCircuitBreaker.consecutiveFailures) +} + +func markProbes(cb *circuitBreaker, batch []*batchSpend) { + for _, item := range batch { + item.breakerSlot = currentProbe(cb) + } +} + +func newSpendBreakerTestStore(t *testing.T, expressions bool) *Store { + t.Helper() + + s := newTestStoreForGet(t) + s.utxoBatchSize = 1 + s.settings.Aerospike.EnableSpendFilterExpressions = expressions + s.spendCircuitBreaker = newCircuitBreaker(2, 1, time.Minute) + + return s +} + +// competingSpendBatch builds one claim per parent on output 0, each from a +// different spending tx. +func competingSpendBatch(parents ...*chainhash.Hash) ([]*batchSpend, *completion.Group) { + group := completion.NewGroup(int32(len(parents))) + hash := chainhash.Hash{2} + batch := make([]*batchSpend, len(parents)) + for i, parent := range parents { + spender := chainhash.Hash{byte(i + 3)} + batch[i] = &batchSpend{spend: &utxo.Spend{ + TxID: parent, UTXOHash: &hash, + SpendingData: spendpkg.NewSpendingData(&spender, 0), + }, blockHeight: 100, group: group} + } + + return batch, group +} + +func failRecords(records []aerospike.BatchRecordIfc) { + for _, record := range records { + record.BatchRec().Err = &aerospike.AerospikeError{ResultCode: types.TIMEOUT} + } +} + +func spendBatchSizeSamples(t *testing.T) uint64 { + t.Helper() + + var metric dto.Metric + require.NoError(t, prometheusUtxoSpendBatchSize.Write(&metric)) + + return metric.GetHistogram().GetSampleCount() +} + +// A competing claim with other ignore flags than the claim that showed the +// owner goes to the backend, because the backend could answer it differently. +func TestSpendSplitSendsClaimWithOtherChecksToBackend(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent, &parent) + batch[1].ignoreConflicting = true + + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + for _, record := range records { + record.BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + } + return nil + } + + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + + require.Equal(t, 2, calls, "the claim with ignoreConflicting reaches the backend, the plain one is refused locally") + require.ErrorIs(t, batch[2].spend.Err, errors.ErrSpent) +} + +// Expression decisions must reach the breaker before any Lua retry, including +// when the retry panics. Otherwise a successful retry can hide a failed probe. +func TestSpendExpressionBreakerBeforeLuaRetry(t *testing.T) { + for _, state := range []cbState{cbStateClosed, cbStateHalfOpen} { + for _, split := range []bool{false, true} { + for _, panicRetry := range []bool{false, true} { + name := string(state) + "/success" + if panicRetry { + name = string(state) + "/panic" + } + if split { + name += "/split" + } + t.Run(name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, true) + s.spendCircuitBreaker.state = state + s.spendCircuitBreaker.consecutiveFailures = 1 + first, second := chainhash.Hash{1}, chainhash.Hash{9} + parents := []*chainhash.Hash{&first, &second} + if split { + parents = append(parents, &first) + } + batch, group := competingSpendBatch(parents...) + if state == cbStateHalfOpen { + markProbes(s.spendCircuitBreaker, batch) + } + if split { + batch[2].blockHeight++ + } + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if calls == 1 { + require.Len(t, records, 2) + failRecords(records[:1]) + records[1].BatchRec().Err = &aerospike.AerospikeError{ResultCode: types.FILTERED_OUT} + return nil + } + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state, "the expression failure must count before Lua starts") + if panicRetry { + panic("Lua retry failed") + } + require.Len(t, records, 1) + records[0].BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + return nil + } + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + wantCalls := 2 + if split && !panicRetry { + wantCalls = 3 + } + require.Equal(t, wantCalls, calls) + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state) + require.Error(t, batch[0].spend.Err) + if panicRetry { + require.Error(t, batch[1].spend.Err) + } else { + require.NoError(t, batch[1].spend.Err) + } + }) + } + } + } +} + +// A successful record cannot suppress a later failure merely because the two +// operations share a parent record. Different flags force both claims to run. +func TestSpendLuaBreakerCountsLaterPartFailure(t *testing.T) { + s := newSpendBreakerTestStore(t, false) + s.spendCircuitBreaker = newCircuitBreaker(1, 1, time.Minute) + s.utxoBatchSize = 128 + parent, sameParent := chainhash.Hash{1}, chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent, &sameParent) + batch[1].ignoreLocked = true + batch[2].spend.Vout = 1 + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if calls == 1 { + require.Len(t, records, 2) + for _, record := range records { + record.BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + } + } else { + require.Len(t, records, 1) + failRecords(records) + } + return nil + } + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + require.Equal(t, 2, calls) + require.Equal(t, cbStateOpen, s.spendCircuitBreaker.state) +} + +func TestSpendExpressionSuccessBeforeLuaFailure(t *testing.T) { + for _, state := range []cbState{cbStateClosed, cbStateHalfOpen} { + t.Run(string(state), func(t *testing.T) { + s := newSpendBreakerTestStore(t, true) + s.spendCircuitBreaker.state = state + s.spendCircuitBreaker.consecutiveFailures = 1 + first, second := chainhash.Hash{1}, chainhash.Hash{9} + batch, group := competingSpendBatch(&first, &second) + if state == cbStateHalfOpen { + markProbes(s.spendCircuitBreaker, batch) + } + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if calls == 1 { + require.Len(t, records, 2) + records[1].BatchRec().Err = &aerospike.AerospikeError{ResultCode: types.FILTERED_OUT} + return nil + } + require.Equal(t, cbStateClosed, s.spendCircuitBreaker.state) + require.Zero(t, s.spendCircuitBreaker.consecutiveFailures, "expression success precedes Lua failure") + failRecords(records) + return nil + } + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + require.Equal(t, 2, calls) + require.Equal(t, cbStateClosed, s.spendCircuitBreaker.state) + require.Equal(t, 1, s.spendCircuitBreaker.consecutiveFailures) + require.NoError(t, batch[0].spend.Err) + require.Error(t, batch[1].spend.Err) + }) + } +} + +// Coalescing repeated expression failures must stop at a recovery signal. A +// later timeout is new evidence after the success reset consecutiveFailures. +func TestSpendExpressionBreakerCountsFailureAfterRecovery(t *testing.T) { + for _, luaRecovery := range []bool{false, true} { + name := "expression recovery" + if luaRecovery { + name = "Lua recovery" + } + t.Run(name, func(t *testing.T) { + s := newSpendBreakerTestStore(t, true) + parent := chainhash.Hash{1} + batch, group := competingSpendBatch(&parent, &parent, &parent) + batch[1].ignoreLocked = true + batch[2].ignoreConflicting = true + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + require.Len(t, records, 1) + switch { + case calls == 2 && luaRecovery: + records[0].BatchRec().Err = &aerospike.AerospikeError{ResultCode: types.FILTERED_OUT} + case calls == 2: + // Successful expression record, without follow-up bins. + case calls == 3 && luaRecovery: + records[0].BatchRec().Record = &aerospike.Record{Bins: aerospike.BinMap{ + LuaSuccess.String(): map[interface{}]interface{}{"status": "OK"}, + }} + default: + failRecords(records) + } + return nil + } + s.sendSpendBatchLua(batch) + requireGroupCompleted(t, group, time.Second) + wantCalls := 3 + if luaRecovery { + wantCalls++ + } + require.Equal(t, wantCalls, calls) + require.Equal(t, cbStateClosed, s.spendCircuitBreaker.state) + require.Equal(t, 1, s.spendCircuitBreaker.consecutiveFailures, "the final timeout must count after recovery") + require.Error(t, batch[0].spend.Err) + require.NoError(t, batch[1].spend.Err) + require.Error(t, batch[2].spend.Err) + }) + } +} + +func TestSpendSplitDoesNotDispatchAfterCallerReturns(t *testing.T) { + for _, expressions := range []bool{false, true} { + name := "lua" + if expressions { + name = "expressions" + } + t.Run(name, func(t *testing.T) { + for _, cancelCaller := range []bool{false, true} { + mode := "timeout" + if cancelCaller { + mode = "cancellation" + } + t.Run(mode, func(t *testing.T) { + s := newSpendBreakerTestStore(t, expressions) + s.settings.UtxoStore.SpendWaitTimeout = 200 * time.Millisecond + parent := chainhash.Hash{1} + tx := bt.NewTx() + require.NoError(t, tx.From(parent.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1000)) + require.NoError(t, tx.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + queued := make(chan *batchSpend, 1) + s.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + defer s.spendBatcher.Close() + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + result := make(chan error, 1) + go func() { _, err := s.Spend(ctx, tx, 2); result <- err }() + var later *batchSpend + select { + case later = <-queued: + case <-time.After(3 * time.Second): + t.Fatal("claim not queued") + } + firstBatch, _ := competingSpendBatch(&parent) + first := firstBatch[0] + first.spend.UTXOHash = later.spend.UTXOHash + // Different height bypasses failure reuse, so admission itself + // must prevent the second backend call after timeout. + first.blockHeight = 1 + entered, release := make(chan struct{}), make(chan struct{}) + calls := 0 + s.batchOperateFn = func(_ *aerospike.BatchPolicy, records []aerospike.BatchRecordIfc) aerospike.Error { + calls++ + if calls == 1 { + close(entered) + <-release + failRecords(records) + } + return nil + } + done := make(chan struct{}) + go func() { defer close(done); s.sendSpendBatchLua([]*batchSpend{first, later}) }() + select { + case <-entered: + case <-time.After(3 * time.Second): + t.Fatal("first part not started") + } + if cancelCaller { + cancel() + } + select { + case err := <-result: + require.Error(t, err) + case <-time.After(3 * time.Second): + t.Fatal("caller did not stop waiting") + } + close(release) + select { + case <-done: + case <-time.After(3 * time.Second): + t.Fatal("batch did not finish") + } + require.Equal(t, 1, calls, "an abandoned claim must never start another write") + require.True(t, later.published.Load()) + require.Error(t, later.err) + }) + } + }) + } +} diff --git a/stores/utxo/aerospike/spend_wait_cancel_test.go b/stores/utxo/aerospike/spend_wait_cancel_test.go index 8bafe97454..f1b2c809fd 100644 --- a/stores/utxo/aerospike/spend_wait_cancel_test.go +++ b/stores/utxo/aerospike/spend_wait_cancel_test.go @@ -218,3 +218,47 @@ func TestIncrementSpentRecords_TimeoutIsNotRelabelledByACancelledStoreContext(t require.Equal(t, before+1, batchTimeoutCounter("IncrementSpentRecords"), "a genuine timeout must still bump BatchTimeout exactly once") } + +// cancelledWhenCtx reports Canceled once cancelled returns true, and never +// closes Done, so only a caller that asks Err sees the cancellation. +type cancelledWhenCtx struct { + context.Context + cancelled func() bool +} + +func (c *cancelledWhenCtx) Done() <-chan struct{} { return nil } + +func (c *cancelledWhenCtx) Err() error { + if c.cancelled() { + return context.Canceled + } + + return nil +} + +func TestSpend_TimeoutIsNotRelabelledByACancellationDuringRollback(t *testing.T) { + s := newTestStoreForSpendEnqueue(t) + s.settings.UtxoStore.SpendWaitTimeout = 20 * time.Millisecond + s.spendBatcher = &silentSpendBatcher{} + + cb := halfOpenBreaker(t) + s.spendCircuitBreaker = cb + + abandoned := func() bool { + cb.mu.Lock() + defer cb.mu.Unlock() + + return cb.halfOpenAttempts == 0 + } + + before := batchTimeoutCounter("Spend") + + _, err := s.Spend(&cancelledWhenCtx{Context: context.Background(), cancelled: abandoned}, txWithInputs(t, 1), 100) + require.Error(t, err) + require.Contains(t, err.Error(), "timed out after") + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + require.NotErrorIs(t, err, errors.ErrContextCanceled, + "a timeout whose caller cancels during rollback must stay a timeout") + require.Equal(t, before+1, batchTimeoutCounter("Spend"), + "the timeout must bump BatchTimeout exactly once") +} diff --git a/stores/utxo/duplicate_spend.go b/stores/utxo/duplicate_spend.go index 920049a048..6a18b901b2 100644 --- a/stores/utxo/duplicate_spend.go +++ b/stores/utxo/duplicate_spend.go @@ -2,9 +2,11 @@ package utxo import ( "bytes" + "context" "github.com/bsv-blockchain/go-bt/v2/chainhash" "github.com/bsv-blockchain/teranode/errors" + spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" ) type spendOutpointKey struct { @@ -12,62 +14,286 @@ type spendOutpointKey struct { vout uint32 } -// FilterConflictingDuplicateSpendClaims removes later same-outpoint spend claims -// with different spending data from a backend batch and rejects them as ErrSpent. -func FilterConflictingDuplicateSpendClaims[T any]( - items []T, - spendForItem func(T) *Spend, - rejectItem func(T, error), -) []T { - firstByOutpoint := make(map[spendOutpointKey]*Spend, len(items)) - filtered := make([]T, 0, len(items)) +// SpendBatchHandler connects ProcessSpendBatch to one backend. +type SpendBatchHandler[T any] struct { + // Start optionally reserves an item for dispatch immediately before its part + // runs. An error rejects only that item and is never reused for another caller. + Start func(T) error + // Spend returns the claim of an item, or nil for an item the backend must reject. + Spend func(T) *Spend + // Process runs one part against the backend and answers every item in it + // before it returns. + Process func([]T) + // Result returns the answer Process gave an item, and false when there is none. + Result func(T) (error, bool) + // Reject answers an item that ProcessSpendBatch decides without the backend. + Reject func(T, error) + // SameChecks reports whether the backend runs the same checks for two claims + // on one outpoint, apart from the spending data: the same UTXO hash, block + // height and ignore flags. If nil, backend results are not reused locally. + SameChecks func(a, b T) bool +} - for _, item := range items { - spend := spendForItem(item) - if spend == nil || spend.TxID == nil { - filtered = append(filtered, item) - continue +// spendFailure is a backend failure reusable for claims with identical checks. +type spendFailure[T any] struct { + err error + decider T +} + +// spendOwner is the stored owner and the claim whose answer showed it. +type spendOwner[T any] struct { + data *spendpkg.SpendingData + decider T +} + +// ProcessSpendBatch submits items to the backend in order, so the stored owner +// decides competing claims on the same outpoint. +// +// A batch without different claims on one outpoint sends its admitted items +// to Process in one call. An entirely abandoned batch makes no backend call. +// Otherwise a claim that competes with a pending claim on its outpoint is +// carried over to the next part, and the current part keeps filling with the +// claims that do not compete. Once a claim on an outpoint is carried, every +// later claim on that outpoint is carried too, so the earlier claim on an +// outpoint is always dispatched in an earlier part. The number of parts is at most +// the largest number of claims on one outpoint, not the number of competitions. +// After each part, the answers tell the stored owner: +// - success names the claim itself; +// - UTXO_SPENT names the owner in its data, unless that data is the claim's own; +// - INVALID_SPEND proves the owner is the claim itself; +// - any other error leaves the owner unknown. +// +// Carried claims are checked again against what the part showed, in their +// original order, before the next part is built. A later claim with different +// data than a known owner is rejected locally with UTXO_SPENT naming that +// owner, but only when SameChecks holds against the claim that showed the owner. +// That claim passed every check before the spent check, so the backend would +// answer the later claim with the same UTXO_SPENT. A claim with other checks, +// or one that matches the owner, still goes to the backend. +// Backend failures that do not depend on the claimant (see reusableFailure) are +// also reused for later claims with the same checks. This keeps an outage from +// turning N competing claims into N serial backend calls. Different checks +// still require a backend decision; unknown-owner UTXO_SPENT errors are never +// copied to another spending claim. +// Start is checked at dispatch, including for items carried over from a previous +// part. Admission failures belong to one caller and are never reused. +// +// The local answer reflects the stored state when its part finished. It is an +// answer the backend could also give, because the claim was waiting the whole +// time. The backend must still enforce ownership atomically against concurrent +// batches. In particular, Aerospike does not promise an order for batch +// operations on one key (including Lua calls with different heights or flags), +// and PostgreSQL UPDATE ... FROM does not choose predictably between source +// rows matching the same output. Do not rely on observed backend ordering to +// combine competing claims into one part. +func ProcessSpendBatch[T any](items []T, h SpendBatchHandler[T]) { + if len(items) == 0 { + return + } + + process := func(part []T) []T { + if h.Start != nil { + var ready []T + filtered := false + for i, item := range part { + if err := h.Start(item); err != nil { + if !filtered { + ready = append(make([]T, 0, len(part)), part[:i]...) + filtered = true + } + h.Reject(item, err) + } else if filtered { + ready = append(ready, item) + } + } + if filtered { + part = ready + } + } + if len(part) > 0 { + h.Process(part) } + return part + } + + if !hasCompetingClaims(items, h.Spend) { + process(items) + return + } + + owners := make(map[spendOutpointKey]spendOwner[T]) + failures := make(map[spendOutpointKey][]spendFailure[T]) - key := spendOutpointKey{ - txID: *spend.TxID, - vout: spend.Vout, + record := func(part []T) { + if len(part) == 0 { + return } - first, ok := firstByOutpoint[key] - if !ok { - firstByOutpoint[key] = spend - filtered = append(filtered, item) - continue + + for _, item := range process(part) { + learnOwner(owners, item, h) + spend := h.Spend(item) + if spend == nil || spend.TxID == nil || spend.SpendingData == nil || spend.SpendingData.TxID == nil { + continue + } + if err, answered := h.Result(item); answered && reusableFailure(err) { + key := spendOutpointKey{txID: *spend.TxID, vout: spend.Vout} + failures[key] = append(failures[key], spendFailure[T]{err: err, decider: item}) + } + } + } + + rejectedByResult := func(item T, spend *Spend, key spendOutpointKey) bool { + if h.SameChecks != nil && spend.SpendingData != nil && spend.SpendingData.TxID != nil { + for _, failure := range failures[key] { + if h.SameChecks(failure.decider, item) { + h.Reject(item, failure.err) + return true + } + } + } + owner, known := owners[key] + if !known || sameSpendingData(owner.data, spend.SpendingData) || h.SameChecks == nil || !h.SameChecks(owner.decider, item) { + return false } - if sameSpendingData(first, spend) { - filtered = append(filtered, item) + h.Reject(item, errors.NewUtxoSpentError(key.txID, key.vout, hashValue(spend.UTXOHash), owner.data)) + + return true + } + + queue := items + + for len(queue) > 0 { + var part, carried []T + + pending := make(map[spendOutpointKey]*spendpkg.SpendingData) + blocked := make(map[spendOutpointKey]struct{}) + + for _, item := range queue { + spend := h.Spend(item) + if spend == nil || spend.TxID == nil { + part = append(part, item) + continue + } + + key := spendOutpointKey{txID: *spend.TxID, vout: spend.Vout} + if rejectedByResult(item, spend, key) { + continue + } + + if _, found := blocked[key]; found { + carried = append(carried, item) + continue + } + + if claim, found := pending[key]; found && !sameSpendingData(claim, spend.SpendingData) { + blocked[key] = struct{}{} + carried = append(carried, item) + + continue + } + + pending[key] = spend.SpendingData + part = append(part, item) + } + + record(part) + + queue = carried + } +} + +// reusableFailure reports whether a backend failure may be copied to a later +// claim on the same outpoint with the same checks. Only failures that do not +// depend on who claims the outpoint qualify: storage, availability and context +// failures, and the parent or UTXO state errors the backend raises before it +// looks at the stored owner. Anything else, including the generic UTXO error, +// can depend on the claimant, for example a replay of the stored owner that a +// competing claim would not share, so each claim needs its own backend answer. +func reusableFailure(err error) bool { + if err == nil { + return false + } + + return errors.Is(err, errors.ErrStorageError) || + errors.Is(err, errors.ErrServiceUnavailable) || + errors.Is(err, errors.ErrContextCanceled) || + errors.Is(err, context.Canceled) || + errors.Is(err, context.DeadlineExceeded) || + errors.Is(err, errors.ErrTxNotFound) || + errors.Is(err, errors.ErrTxLocked) || + errors.Is(err, errors.ErrTxCreating) || + errors.Is(err, errors.ErrTxConflicting) || + errors.Is(err, errors.ErrUtxoHashMismatch) || + errors.Is(err, errors.ErrFrozen) || + errors.Is(err, errors.ErrTxCoinbaseImmature) +} + +func hasCompetingClaims[T any](items []T, spendForItem func(T) *Spend) bool { + claims := make(map[spendOutpointKey]*spendpkg.SpendingData, len(items)) + + for _, item := range items { + spend := spendForItem(item) + if spend == nil || spend.TxID == nil { continue } - rejectItem(item, errors.NewUtxoSpentError(key.txID, key.vout, spendHashValue(spend.UTXOHash), first.SpendingData)) + key := spendOutpointKey{txID: *spend.TxID, vout: spend.Vout} + if claim, found := claims[key]; found && !sameSpendingData(claim, spend.SpendingData) { + return true + } + + claims[key] = spend.SpendingData } - return filtered + return false } -func sameSpendingData(first *Spend, next *Spend) bool { - var firstBytes []byte - if first != nil && first.SpendingData != nil { - firstBytes = first.SpendingData.Bytes() +func learnOwner[T any](owners map[spendOutpointKey]spendOwner[T], item T, h SpendBatchHandler[T]) { + spend := h.Spend(item) + if spend == nil || spend.TxID == nil || spend.SpendingData == nil { + return + } + + err, answered := h.Result(item) + if !answered { + return } - var nextBytes []byte - if next != nil && next.SpendingData != nil { - nextBytes = next.SpendingData.Bytes() + key := spendOutpointKey{txID: *spend.TxID, vout: spend.Vout} + + if err == nil { + owners[key] = spendOwner[T]{data: spend.SpendingData, decider: item} + return } - return bytes.Equal(firstBytes, nextBytes) + var spentData *errors.UtxoSpentErrData + if errors.Is(err, errors.ErrSpent) && errors.AsData(err, &spentData) && + spentData.SpendingData != nil && !sameSpendingData(spentData.SpendingData, spend.SpendingData) { + owners[key] = spendOwner[T]{data: spentData.SpendingData, decider: item} + + return + } + + var invalidData *errors.UtxoInvalidSpendErrData + if errors.AsData(err, &invalidData) && invalidData.SpendingData != nil { + owners[key] = spendOwner[T]{data: spend.SpendingData, decider: item} + } +} + +func sameSpendingData(first, next *spendpkg.SpendingData) bool { + return bytes.Equal(first.Bytes(), next.Bytes()) } -func spendHashValue(hash *chainhash.Hash) chainhash.Hash { +// SameUTXOHash reports whether two claims carry the same UTXO hash. +func SameUTXOHash(a, b *Spend) bool { + return hashValue(a.UTXOHash) == hashValue(b.UTXOHash) +} + +func hashValue(hash *chainhash.Hash) chainhash.Hash { if hash == nil { return chainhash.Hash{} } + return *hash } diff --git a/stores/utxo/duplicate_spend_test.go b/stores/utxo/duplicate_spend_test.go index 13a75c6edf..47fb0165a2 100644 --- a/stores/utxo/duplicate_spend_test.go +++ b/stores/utxo/duplicate_spend_test.go @@ -1,68 +1,462 @@ package utxo import ( + "context" "testing" "github.com/bsv-blockchain/go-bt/v2/chainhash" - terrors "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/errors" spendpkg "github.com/bsv-blockchain/teranode/stores/utxo/spend" "github.com/stretchr/testify/require" ) -type duplicateSpendTestItem struct { - spend *Spend - err error +type batchTestItem struct { + spend *Spend + ignoreConflicting bool + err error + answered bool + local bool } -func TestFilterConflictingDuplicateSpendClaims(t *testing.T) { - parentTxID := chainhash.HashH([]byte("parent")) - utxoHash := chainhash.HashH([]byte("utxo")) - winnerTxID := chainhash.HashH([]byte("winner")) - loserTxID := chainhash.HashH([]byte("loser")) - - winner := &duplicateSpendTestItem{ - spend: &Spend{ - TxID: &parentTxID, - Vout: 3, - UTXOHash: &utxoHash, - SpendingData: spendpkg.NewSpendingData(&winnerTxID, 0), +type batchTestBackend struct { + start func(*batchTestItem) error + parts [][]*batchTestItem + answer func(*Spend) error +} + +func (b *batchTestBackend) run(items []*batchTestItem) { + ProcessSpendBatch(items, SpendBatchHandler[*batchTestItem]{ + Start: b.start, + Spend: func(item *batchTestItem) *Spend { + if item == nil { + return nil + } + return item.spend }, - } - idempotentDuplicate := &duplicateSpendTestItem{ - spend: &Spend{ - TxID: &parentTxID, - Vout: 3, - UTXOHash: &utxoHash, - SpendingData: spendpkg.NewSpendingData(&winnerTxID, 0), + Process: func(part []*batchTestItem) { + b.parts = append(b.parts, part) + for _, item := range part { + if item == nil { + continue + } + item.err = b.answer(item.spend) + item.answered = true + } + }, + Result: func(item *batchTestItem) (error, bool) { + if item == nil { + return nil, false + } + return item.err, item.answered + }, + Reject: func(item *batchTestItem, err error) { + item.err = err + item.answered = true + item.local = true + }, + SameChecks: func(a, b *batchTestItem) bool { + return a.ignoreConflicting == b.ignoreConflicting && SameUTXOHash(a.spend, b.spend) }, + }) +} + +func requireSpentBy(t *testing.T, err error, owner *spendpkg.SpendingData) { + t.Helper() + require.ErrorIs(t, err, errors.ErrSpent) + + var data *errors.UtxoSpentErrData + require.True(t, errors.AsData(err, &data)) + require.Equal(t, owner.Bytes(), data.SpendingData.Bytes()) +} + +func TestProcessSpendBatch(t *testing.T) { + parent := chainhash.HashH([]byte("parent")) + utxoHash := chainhash.HashH([]byte("utxo")) + a := chainhash.HashH([]byte("a")) + b := chainhash.HashH([]byte("b")) + c := chainhash.HashH([]byte("c")) + claim := func(vout uint32, txID *chainhash.Hash) *batchTestItem { + return &batchTestItem{spend: &Spend{ + TxID: &parent, Vout: vout, UTXOHash: &utxoHash, + SpendingData: spendpkg.NewSpendingData(txID, 0), + }} + } + ownerA := spendpkg.NewSpendingData(&a, 0) + ownerB := spendpkg.NewSpendingData(&b, 0) + storedOwner := func(owner *spendpkg.SpendingData) func(*Spend) error { + return func(spend *Spend) error { + if sameSpendingData(owner, spend.SpendingData) { + return nil + } + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, owner) + } } - loser := &duplicateSpendTestItem{ - spend: &Spend{ - TxID: &parentTxID, - Vout: 3, - UTXOHash: &utxoHash, - SpendingData: spendpkg.NewSpendingData(&loserTxID, 0), + + t.Run("a batch without competing claims is one call", func(t *testing.T) { + items := []*batchTestItem{claim(0, &a), claim(0, &a), claim(1, &b)} + backend := &batchTestBackend{answer: storedOwner(ownerA)} + backend.run(items) + + require.Len(t, backend.parts, 1) + require.Equal(t, items, backend.parts[0]) + }) + + t.Run("alternating claims cost two calls and name the stored owner", func(t *testing.T) { + items := make([]*batchTestItem, 0, 17) + for range 8 { + items = append(items, claim(0, &a), claim(0, &b)) + } + items = append(items, claim(1, &c)) + + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(ownerB, spend.SpendingData) { + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, ownerA) + } + return nil + }} + backend.run(items) + + require.Len(t, backend.parts, 2) + for _, item := range items { + require.True(t, item.answered) + if sameSpendingData(ownerB, item.spend.SpendingData) { + require.True(t, item.local) + requireSpentBy(t, item.err, ownerA) + continue + } + require.False(t, item.local) + require.NoError(t, item.err) + } + }) + + t.Run("an owner re-spend behind a losing claim succeeds", func(t *testing.T) { + loser, owner := claim(0, &b), claim(0, &a) + backend := &batchTestBackend{answer: storedOwner(ownerA)} + backend.run([]*batchTestItem{loser, owner}) + + require.Equal(t, [][]*batchTestItem{{loser}, {owner}}, backend.parts) + require.NoError(t, owner.err) + requireSpentBy(t, loser.err, ownerA) + require.False(t, loser.local) + }) + + t.Run("UTXO_SPENT naming the claim itself leaves the owner unknown", func(t *testing.T) { + first, second, third := claim(0, &a), claim(0, &b), claim(0, &c) + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(ownerA, spend.SpendingData) { + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, spend.SpendingData) + } + return nil + }} + backend.run([]*batchTestItem{first, second, third}) + + require.Equal(t, [][]*batchTestItem{{first}, {second}}, backend.parts) + require.False(t, second.local) + require.NoError(t, second.err) + require.True(t, third.local) + requireSpentBy(t, third.err, ownerB) + }) + + t.Run("a failure without an owner is reused for matching checks", func(t *testing.T) { + items := []*batchTestItem{claim(0, &a), claim(0, &b), claim(0, &a)} + backend := &batchTestBackend{answer: func(*Spend) error { + return errors.NewStorageError("backend down") + }} + backend.run(items) + + require.Equal(t, [][]*batchTestItem{{items[0]}}, backend.parts) + for i, item := range items { + require.Equal(t, i > 0, item.local) + require.ErrorIs(t, item.err, errors.ErrStorageError) + } + }) + + t.Run("a claim matching a known owner still reaches the backend", func(t *testing.T) { + first, loser, again := claim(0, &a), claim(0, &c), claim(0, &a) + backend := &batchTestBackend{answer: storedOwner(ownerA)} + backend.run([]*batchTestItem{first, loser, again}) + + require.Equal(t, [][]*batchTestItem{{first}, {again}}, backend.parts) + require.True(t, loser.local) + requireSpentBy(t, loser.err, ownerA) + require.NoError(t, again.err) + }) + + t.Run("a claim with other checks than the decider reaches the backend", func(t *testing.T) { + winner, conflicting, plain := claim(0, &a), claim(0, &b), claim(0, &c) + winner.ignoreConflicting = true + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(ownerA, spend.SpendingData) { + return nil + } + if sameSpendingData(ownerB, spend.SpendingData) { + return errors.NewTxConflictingError("parent is conflicting") + } + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, ownerA) + }} + backend.run([]*batchTestItem{winner, conflicting, plain}) + + require.Equal(t, [][]*batchTestItem{{winner}, {conflicting}}, backend.parts) + require.False(t, conflicting.local) + require.ErrorIs(t, conflicting.err, errors.ErrTxConflicting) + require.True(t, plain.local) + require.ErrorIs(t, plain.err, errors.ErrTxConflicting) + }) + + t.Run("a claim with another UTXO hash reaches the backend", func(t *testing.T) { + otherHash := chainhash.HashH([]byte("other utxo")) + first, mismatch := claim(0, &a), claim(0, &b) + mismatch.spend.UTXOHash = &otherHash + backend := &batchTestBackend{answer: func(spend *Spend) error { + if *spend.UTXOHash == otherHash { + return errors.NewUtxoHashMismatchError("hash mismatch") + } + return storedOwner(ownerA)(spend) + }} + backend.run([]*batchTestItem{first, mismatch}) + + require.Equal(t, [][]*batchTestItem{{first}, {mismatch}}, backend.parts) + require.False(t, mismatch.local) + require.ErrorIs(t, mismatch.err, errors.ErrUtxoHashMismatch) + }) + + t.Run("invalid items reach the backend", func(t *testing.T) { + invalid := &batchTestItem{spend: &Spend{}} + first, other := claim(0, &a), claim(0, &b) + backend := &batchTestBackend{answer: func(spend *Spend) error { + if spend.TxID == nil { + return errors.NewProcessingError("invalid spend") + } + return storedOwner(ownerA)(spend) + }} + backend.run([]*batchTestItem{nil, invalid, first, other}) + + require.Equal(t, [][]*batchTestItem{{nil, invalid, first}}, backend.parts) + require.ErrorIs(t, invalid.err, errors.ErrProcessing) + require.True(t, other.local) + requireSpentBy(t, other.err, ownerA) + }) + + t.Run("empty", func(t *testing.T) { + backend := &batchTestBackend{answer: storedOwner(ownerA)} + backend.run(nil) + + require.Empty(t, backend.parts) + }) +} + +func TestProcessSpendBatchWithoutSameChecks(t *testing.T) { + parent, hash, a, b := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3}, chainhash.Hash{4} + first := &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&a, 0)} + second := &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&b, 0)} + var parts [][]*Spend + ProcessSpendBatch([]*Spend{first, second}, SpendBatchHandler[*Spend]{ + Spend: func(s *Spend) *Spend { return s }, + Process: func(part []*Spend) { + parts = append(parts, part) + for _, s := range part { + if s == second { + s.Err = errors.NewUtxoSpentError(parent, 0, hash, first.SpendingData) + } + } }, + Result: func(s *Spend) (error, bool) { return s.Err, true }, + Reject: func(*Spend, error) { t.Fatal("no checks supplied: the backend must decide") }, + }) + require.Equal(t, [][]*Spend{{first}, {second}}, parts) + require.NoError(t, first.Err) + requireSpentBy(t, second.Err, first.SpendingData) +} + +func TestSpendBatchFailureReuseBoundsBackendCalls(t *testing.T) { + for _, failure := range []error{ + errors.NewStorageError("backend timeout"), errors.NewTxNotFoundError("parent missing"), + errors.NewTxLockedError("parent locked"), errors.NewTxConflictingError("parent conflicting"), + errors.NewUtxoHashMismatchError("wrong hash"), + } { + t.Run(failure.Error(), func(t *testing.T) { + parent, hash := chainhash.Hash{1}, chainhash.Hash{2} + items := make([]*batchTestItem, 1024) + for i := range items { + spender := chainhash.Hash{byte(i%2 + 3)} + items[i] = &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&spender, 0)}} + } + backend := &batchTestBackend{answer: func(*Spend) error { return failure }} + backend.run(items) + require.Len(t, backend.parts, 1) + for _, item := range items { + require.Same(t, failure, item.err) + require.True(t, item.answered) + } + }) } +} - filtered := FilterConflictingDuplicateSpendClaims( - []*duplicateSpendTestItem{winner, idempotentDuplicate, loser}, - func(item *duplicateSpendTestItem) *Spend { - return item.spend +func TestSpendBatchAdmissionErrorIsNotReused(t *testing.T) { + parent, hash, a, b := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3}, chainhash.Hash{4} + first := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&a, 0)}} + second := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&b, 0)}} + backend := &batchTestBackend{ + start: func(item *batchTestItem) error { + if item == first { + return errors.NewServiceUnavailableError("caller expired") + } + return nil }, - func(item *duplicateSpendTestItem, err error) { - item.err = err + answer: func(*Spend) error { return nil }, + } + backend.run([]*batchTestItem{first, second}) + require.Equal(t, [][]*batchTestItem{{second}}, backend.parts) + require.Error(t, first.err) + require.NoError(t, second.err) + require.False(t, second.local) +} + +func TestSpendBatchRechecksAdmissionForCarriedClaim(t *testing.T) { + parent, hash, a, b := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3}, chainhash.Hash{4} + first := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&a, 0)}} + conflict := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&b, 0)}} + conflict.ignoreConflicting = true + abandoned := false + backend := &batchTestBackend{ + start: func(item *batchTestItem) error { + if abandoned && item == conflict { + return errors.NewServiceUnavailableError("caller expired") + } + return nil }, - ) - - require.Equal(t, []*duplicateSpendTestItem{winner, idempotentDuplicate}, filtered) - require.NoError(t, winner.err) - require.NoError(t, idempotentDuplicate.err) - require.ErrorIs(t, loser.err, terrors.ErrSpent) - - var errData *terrors.UtxoSpentErrData - var terr *terrors.Error - require.ErrorAs(t, loser.err, &terr) - require.True(t, terrors.AsData(terr, &errData)) - require.Equal(t, winner.spend.SpendingData.Bytes(), errData.SpendingData.Bytes()) + answer: func(*Spend) error { abandoned = true; return nil }, + } + backend.run([]*batchTestItem{first, conflict}) + require.Equal(t, [][]*batchTestItem{{first}}, backend.parts) + require.ErrorIs(t, conflict.err, errors.ErrServiceUnavailable) +} + +func TestSpendBatchPartCountIsBoundedPerOutpoint(t *testing.T) { + hash := chainhash.Hash{2} + a, b, c := chainhash.Hash{3}, chainhash.Hash{4}, chainhash.Hash{5} + + t.Run("interleaved pairs on independent outpoints cost two calls", func(t *testing.T) { + items := make([]*batchTestItem, 0, 1024) + for i := range 512 { + parent := chainhash.HashH([]byte{byte(i), byte(i >> 8)}) + first := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&a, 0)}} + second := &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(&b, 0)}, ignoreConflicting: true} + items = append(items, first, second) + } + + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(spendpkg.NewSpendingData(&b, 0), spend.SpendingData) { + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, spendpkg.NewSpendingData(&a, 0)) + } + return nil + }} + backend.run(items) + + require.Len(t, backend.parts, 2) + require.Len(t, backend.parts[0], 512) + require.Len(t, backend.parts[1], 512) + for i, item := range items { + require.True(t, item.answered) + require.Equal(t, i%2 == 1, item.err != nil) + } + }) + + t.Run("three claims on one outpoint cost three calls", func(t *testing.T) { + parent := chainhash.Hash{1} + mk := func(txID *chainhash.Hash, ignore bool) *batchTestItem { + return &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(txID, 0)}, ignoreConflicting: ignore} + } + first, second, third := mk(&a, false), mk(&b, true), mk(&c, false) + backend := &batchTestBackend{answer: func(*Spend) error { return errors.NewUtxoError("claimant dependent") }} + backend.run([]*batchTestItem{first, second, third}) + + require.Equal(t, [][]*batchTestItem{{first}, {second}, {third}}, backend.parts) + }) + + t.Run("owner learning rejects the third claim", func(t *testing.T) { + parent := chainhash.Hash{1} + mk := func(txID *chainhash.Hash, ignore bool) *batchTestItem { + return &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(txID, 0)}, ignoreConflicting: ignore} + } + first, second, third := mk(&a, false), mk(&b, true), mk(&c, false) + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(spendpkg.NewSpendingData(&a, 0), spend.SpendingData) { + return nil + } + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, spendpkg.NewSpendingData(&a, 0)) + }} + backend.run([]*batchTestItem{first, second, third}) + + require.Equal(t, [][]*batchTestItem{{first}, {second}}, backend.parts) + require.True(t, third.local) + requireSpentBy(t, third.err, spendpkg.NewSpendingData(&a, 0)) + }) + + t.Run("a claim behind a carried claim keeps its order", func(t *testing.T) { + parent := chainhash.Hash{1} + mk := func(txID *chainhash.Hash, ignore bool) *batchTestItem { + return &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: spendpkg.NewSpendingData(txID, 0)}, ignoreConflicting: ignore} + } + first, second, again := mk(&a, false), mk(&b, true), mk(&a, false) + backend := &batchTestBackend{answer: func(*Spend) error { return nil }} + backend.run([]*batchTestItem{first, second, again}) + + require.Equal(t, [][]*batchTestItem{{first}, {second}, {again}}, backend.parts) + }) +} + +func TestSpendBatchInvalidSpendProvesOwner(t *testing.T) { + parent, hash, a, b := chainhash.Hash{1}, chainhash.Hash{2}, chainhash.Hash{3}, chainhash.Hash{4} + ownerA, ownerB := spendpkg.NewSpendingData(&a, 0), spendpkg.NewSpendingData(&b, 0) + mk := func(owner *spendpkg.SpendingData) *batchTestItem { + return &batchTestItem{spend: &Spend{TxID: &parent, UTXOHash: &hash, SpendingData: owner}} + } + + t.Run("a replayed owner makes a competing claim UTXO_SPENT naming the owner", func(t *testing.T) { + replay, competing := mk(ownerA), mk(ownerB) + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(ownerA, spend.SpendingData) { + return errors.NewUtxoInvalidSpendError(ownerA, "replay after prune") + } + t.Fatal("the competing claim must be answered locally") + return nil + }} + backend.run([]*batchTestItem{replay, competing}) + + require.Equal(t, [][]*batchTestItem{{replay}}, backend.parts) + require.ErrorIs(t, replay.err, errors.ErrUtxoError) + require.True(t, competing.local) + requireSpentBy(t, competing.err, ownerA) + }) + + t.Run("a generic UTXO error is not reused for a competing claim", func(t *testing.T) { + first, competing := mk(ownerA), mk(ownerB) + backend := &batchTestBackend{answer: func(spend *Spend) error { + if sameSpendingData(ownerA, spend.SpendingData) { + return errors.NewUtxoError("claimant dependent") + } + return errors.NewUtxoSpentError(*spend.TxID, spend.Vout, *spend.UTXOHash, ownerA) + }} + backend.run([]*batchTestItem{first, competing}) + + require.Equal(t, [][]*batchTestItem{{first}, {competing}}, backend.parts) + require.False(t, competing.local) + requireSpentBy(t, competing.err, ownerA) + }) +} + +func TestReusableFailure(t *testing.T) { + for _, err := range []error{ + errors.NewStorageError("x"), errors.NewServiceUnavailableError("x"), errors.NewContextCanceledError("x"), + context.Canceled, context.DeadlineExceeded, errors.NewTxNotFoundError("x"), errors.NewTxLockedError("x"), + errors.NewTxCreatingError("x"), errors.NewTxConflictingError("x"), errors.NewUtxoHashMismatchError("x"), + errors.NewUtxoFrozenError("x"), errors.NewTxCoinbaseImmatureError("x"), + } { + require.True(t, reusableFailure(err), err.Error()) + } + + for _, err := range []error{nil, errors.NewUtxoError("x"), errors.NewProcessingError("x"), errors.NewUtxoSpentError(chainhash.Hash{}, 0, chainhash.Hash{}, nil)} { + require.False(t, reusableFailure(err)) + } } diff --git a/stores/utxo/spend_admission.go b/stores/utxo/spend_admission.go new file mode 100644 index 0000000000..01fefb8c90 --- /dev/null +++ b/stores/utxo/spend_admission.go @@ -0,0 +1,78 @@ +package utxo + +import ( + "context" + "sync/atomic" + + "github.com/bsv-blockchain/teranode/errors" +) + +const ( + spendQueued uint32 = iota + spendStarted + spendAbandoned +) + +// SpendAdmission arbitrates dispatch against caller abandonment. Its zero value +// is queued. It must not be copied after use. Starting wins responsibility for +// an in-flight operation; abandonment prevents an operation that is still queued +// from starting. It does not undo a backend write that has already started. +type SpendAdmission struct { + state atomic.Uint32 +} + +// Start reserves this item for a backend part, unless its caller has stopped +// waiting. The deadline check also handles a caller whose timeout handler has +// not been scheduled yet. A context ended with the cause context.DeadlineExceeded +// counts as expired, so a wait timer that cancels a context reads as a timeout. A nil context is allowed for internal synchronous use. +func (a *SpendAdmission) Start(ctx context.Context) error { + if ctx != nil && ctx.Err() != nil { + a.Abandon() + if errors.Is(context.Cause(ctx), context.DeadlineExceeded) { + return errors.NewServiceUnavailableError("spend expired before backend dispatch", ctx.Err()) + } + return errors.NewContextCanceledError("spend canceled before backend dispatch", ctx.Err()) + } + if !a.state.CompareAndSwap(spendQueued, spendStarted) { + return errors.NewServiceUnavailableError("spend is no longer queued for backend dispatch") + } + return nil +} + +// Abandon prevents future dispatch if Start has not already won the handoff. +// It reports whether abandonment won. The caller must abandon queued inputs +// before beginning rollback. +func (a *SpendAdmission) Abandon() bool { + return a.state.CompareAndSwap(spendQueued, spendAbandoned) +} + +// Started reports whether Start won the handoff for this item. Only then does +// the dispatching goroutine own the item's per-request state; an abandoned item +// belongs to whichever party won its Abandon. +func (a *SpendAdmission) Started() bool { + return a.state.Load() == spendStarted +} + +// SpendOrphan arbitrates who rolls back a spend whose caller stopped waiting +// for it after the backend had started it. The caller marks the item orphaned +// and the batcher publishes the item's result; each side then asks Claim, and +// exactly one of them wins the right to roll the spend back, whichever order +// the two happen in. The side that publishes must store its published flag +// before it calls Claim, and the caller must call Mark before it reads that +// flag, so at least one side sees the other. Callers mark an item only when the +// batch rollback is not suppressed. Its zero value is not orphaned. +type SpendOrphan struct { + orphaned atomic.Bool + claimed atomic.Bool +} + +// Mark records that the caller no longer waits for the item. +func (o *SpendOrphan) Mark() { + o.orphaned.Store(true) +} + +// Claim reports whether the caller of Claim must roll the spend back. It is +// true at most once, and only after Mark. +func (o *SpendOrphan) Claim() bool { + return o.orphaned.Load() && o.claimed.CompareAndSwap(false, true) +} diff --git a/stores/utxo/spend_admission_test.go b/stores/utxo/spend_admission_test.go new file mode 100644 index 0000000000..acdc158df2 --- /dev/null +++ b/stores/utxo/spend_admission_test.go @@ -0,0 +1,98 @@ +package utxo + +import ( + "context" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/bsv-blockchain/teranode/errors" + "github.com/stretchr/testify/require" +) + +func TestSpendAdmission(t *testing.T) { + t.Run("expired deadline before timeout handler runs", func(t *testing.T) { + ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(-time.Second)) + defer cancel() + var admission SpendAdmission + require.ErrorIs(t, admission.Start(ctx), errors.ErrServiceUnavailable) + require.ErrorIs(t, admission.Start(context.Background()), errors.ErrServiceUnavailable) + }) + t.Run("context cancelled with a deadline cause is a timeout", func(t *testing.T) { + ctx, cancel := context.WithCancelCause(context.Background()) + cancel(context.DeadlineExceeded) + var admission SpendAdmission + require.ErrorIs(t, admission.Start(ctx), errors.ErrServiceUnavailable) + }) + t.Run("cancelled context before dispatch", func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + var admission SpendAdmission + require.ErrorIs(t, admission.Start(ctx), errors.ErrContextCanceled) + require.False(t, admission.Abandon(), "the refused start already abandoned the item") + }) + t.Run("abandon before start", func(t *testing.T) { + var admission SpendAdmission + require.True(t, admission.Abandon()) + require.ErrorIs(t, admission.Start(context.Background()), errors.ErrServiceUnavailable) + }) + t.Run("started operation retains responsibility", func(t *testing.T) { + var admission SpendAdmission + require.NoError(t, admission.Start(context.Background())) + require.False(t, admission.Abandon()) + require.ErrorIs(t, admission.Start(context.Background()), errors.ErrServiceUnavailable) + }) + t.Run("racing dispatch and abandonment have exactly one winner", func(t *testing.T) { + for range 1000 { + var admission SpendAdmission + ready := make(chan struct{}) + started, abandoned := make(chan bool, 1), make(chan bool, 1) + go func() { <-ready; started <- admission.Start(context.Background()) == nil }() + go func() { <-ready; abandoned <- admission.Abandon() }() + close(ready) + require.NotEqual(t, <-started, <-abandoned) + } + }) +} + +func TestSpendAdmissionStarted(t *testing.T) { + var queued, started, abandoned SpendAdmission + + require.NoError(t, started.Start(context.Background())) + require.True(t, abandoned.Abandon()) + + require.False(t, queued.Started()) + require.True(t, started.Started()) + require.False(t, abandoned.Started()) +} + +func TestSpendOrphanClaimsExactlyOnce(t *testing.T) { + var unmarked SpendOrphan + require.False(t, unmarked.Claim(), "an item whose caller still waits must not be claimed") + + for i := 0; i < 200; i++ { + var ( + orphan SpendOrphan + wins atomic.Int32 + wg sync.WaitGroup + ) + + orphan.Mark() + + for j := 0; j < 8; j++ { + wg.Add(1) + + go func() { + defer wg.Done() + + if orphan.Claim() { + wins.Add(1) + } + }() + } + + wg.Wait() + require.Equal(t, int32(1), wins.Load(), "exactly one side must win the rollback") + } +} diff --git a/stores/utxo/sql/metrics.go b/stores/utxo/sql/metrics.go index c516b27fd0..1bbe69f4ee 100644 --- a/stores/utxo/sql/metrics.go +++ b/stores/utxo/sql/metrics.go @@ -128,17 +128,18 @@ func _initPrometheusMetrics() { }, ) - // Mirrors the aerospike counter of the same name: a give-up on a per-item - // wait (ctx.Done() or the per-item timer) inside the batched Spend leaves - // that item still enqueued in the batcher, so a straggler UPDATE can land - // after the rollback above has already run — the same #1214 dangling - // reference this rollback exists to prevent, just uncounted until now. + // Mirrors the aerospike counter of the same name. It counts inputs a backend + // part had started and not published when the courtesy wait for them ended + // inside the batched Spend. Unless a transient lock suppresses the batch + // rollback, each is marked orphaned and whoever completes it rolls its spend + // back if it succeeds, with no time bound. A suppressed batch leaves it + // applied. The counter measures such items, not dangling references. prometheusUtxoSpendAbortInFlight = promauto.NewCounter( prometheus.CounterOpts{ Namespace: "teranode", Subsystem: "sql", Name: "utxo_spend_abort_in_flight", - Help: "Spend items still in flight when the batch aborted, excluded from the rollback set and applied by the batcher afterwards (residual dangling-ref window, see #1291)", + Help: "Spend items a backend part had started and not published when their caller gave up, each rolled back by whoever completes it if it succeeds, unless a transient lock suppresses the batch rollback and leaves it applied (residual window see #1291)", }, ) diff --git a/stores/utxo/sql/respend_competing_claim_test.go b/stores/utxo/sql/respend_competing_claim_test.go new file mode 100644 index 0000000000..fffd45e60b --- /dev/null +++ b/stores/utxo/sql/respend_competing_claim_test.go @@ -0,0 +1,296 @@ +package sql + +import ( + "context" + "testing" + + "github.com/bsv-blockchain/go-bt/v2/bscript" + "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + "github.com/stretchr/testify/require" +) + +// assertRespendBehindLoserInSameBatch pins the respend-behind-loser behaviour at the +// in-batch filter, driving sendSpendBatch with an explicit batch so no timing +// is involved. +// +// S0 already owns both parent outputs. The batch then carries a double-spend +// attempt on output 0 AHEAD of S0's idempotent re-spend of output 0, plus +// S0's idempotent re-spend of output 1. +// +// Before the fix the filter handed output 0 to whoever arrived first, so the +// re-spend was refused with ErrSpent naming the double-spend attempt -- a tx +// that never spent anything -- while the attempt itself was refused by the +// backend as already spent. Both claims lost, each blamed on the other. +func assertRespendBehindLoserInSameBatch(t *testing.T, ctx context.Context, store *Store) { + t.Helper() + + parent := twoOutParent(ctx, t, store, "4934-batch") + + respend := spendOf(t, parent, 1, 0, 1) // S0: legitimate spender of outputs 0 and 1 + loser := spendOf(t, parent, 2, 0) // double-spend attempt on output 0 + + // S0 owns both outputs before the batch under test. + _, err := store.Spend(ctx, respend, 2) + require.NoError(t, err, "initial spend must succeed") + + respendSpends, err := utxo.GetSpends(respend) + require.NoError(t, err) + require.Len(t, respendSpends, 2) + + loserSpends, err := utxo.GetSpends(loser) + require.NoError(t, err) + require.Len(t, loserSpends, 1) + require.NotEqual(t, respendSpends[0].SpendingData.Bytes(), loserSpends[0].SpendingData.Bytes(), + "the two claims must differ, or this is not a conflict") + + height := store.GetBlockHeight() + 1 + chans := make([]chan error, 3) + for i := range chans { + chans[i] = make(chan error, 1) + } + + // One batch, loser first: exactly the ordering the filter used to obey. + store.sendSpendBatch([]*batchSpend{ + {spend: loserSpends[0], blockHeight: height, errCh: chans[0]}, + {spend: respendSpends[0], blockHeight: height, errCh: chans[1]}, + {spend: respendSpends[1], blockHeight: height, errCh: chans[2]}, + }) + + loserErr, respendOut0Err, respendOut1Err := <-chans[0], <-chans[1], <-chans[2] + t.Logf("loser err : %v", loserErr) + t.Logf("re-spend output 0 err : %v", respendOut0Err) + t.Logf("re-spend output 1 err : %v", respendOut1Err) + + // The idempotent re-spend must be accepted on both outputs. + require.NoError(t, respendOut0Err, + "idempotent re-spend of output 0 was refused -- the filter followed batch order, not persisted state") + require.NoError(t, respendOut1Err, "idempotent re-spend of output 1 must succeed") + + // The genuine double-spend is still refused, and now blamed on S0, the + // persisted spender, rather than on itself. This is the #825 guarantee. + require.Error(t, loserErr, "the double-spend attempt must still be refused") + require.True(t, errors.Is(loserErr, errors.ErrSpent), "expected ErrSpent for the loser, got: %v", loserErr) + + var terr *errors.Error + require.ErrorAs(t, loserErr, &terr) + + var errData *errors.UtxoSpentErrData + require.True(t, errors.AsData(terr, &errData), "expected the spent-error to carry the real spender") + require.NotNil(t, errData.SpendingData, "the loser must be told who owns the outpoint") + require.Equal(t, respendSpends[0].SpendingData.Bytes(), errData.SpendingData.Bytes(), + "the loser must be blamed on the persisted spender, not on itself") +} + +func TestRespendBehindLoserInSameBatchSQLite(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + store := setupSharedBatch(ctx, t, "4934batch-sqlite") + require.NoError(t, store.SetBlockHeight(2)) + + assertRespendBehindLoserInSameBatch(t, ctx, store) +} + +func TestRespendBehindLoserInSameBatchPostgresBulk(t *testing.T) { + if testing.Short() { + t.Skip("skipping Postgres integration test in short mode") + } + + store, ctx := setupPostgresStore(t) + store.settings.UtxoStore.BatchSQLOperations = true + require.NoError(t, store.SetBlockHeight(2)) + + assertRespendBehindLoserInSameBatch(t, ctx, store) +} + +// A stored owner need not be one of the requests in the batch. Both losing +// requests must name that owner, never each other. +func TestSpendBatchReportsPersistedOwnerOutsideBatch(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "4934-third-owner") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "4934-third-owner") + owner := spendOf(t, parent, 1, 0) + _, err := store.Spend(ctx, owner, 2) + require.NoError(t, err) + batch := make([]*batchSpend, 0, 2) + for _, lockTime := range []uint32{2, 3} { + spends, spendErr := utxo.GetSpends(spendOf(t, parent, lockTime, 0)) + require.NoError(t, spendErr) + batch = append(batch, &batchSpend{spend: spends[0], blockHeight: 2, errCh: make(chan error, 1)}) + } + store.sendSpendBatch(batch) + for _, item := range batch { + err := <-item.errCh + require.ErrorIs(t, err, errors.ErrSpent) + var data *errors.UtxoSpentErrData + require.True(t, errors.AsData(err, &data)) + require.Equal(t, owner.TxID(), data.SpendingData.TxID.String()) + } +} + +func TestSpendBatchStorageFailureDoesNotInventConflict(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "4934-read-failure") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "4934-read-failure") + owner := spendOf(t, parent, 1, 0, 1) + _, err := store.Spend(ctx, owner, 2) + require.NoError(t, err) + loserSpends, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + ownerSpends, err := utxo.GetSpends(owner) + require.NoError(t, err) + require.NoError(t, store.db.Close()) + batch := []*batchSpend{ + {spend: loserSpends[0], blockHeight: 2, errCh: make(chan error, 1)}, + {spend: ownerSpends[0], blockHeight: 2, errCh: make(chan error, 1)}, + {spend: ownerSpends[1], blockHeight: 2, errCh: make(chan error, 1)}, + } + store.sendSpendBatch(batch) + for _, item := range batch { + err := <-item.errCh + require.Error(t, err) + require.NotErrorIs(t, err, errors.ErrSpent, "storage failure is not evidence of a conflicting owner") + } +} + +// Alternating claims on one unspent outpoint: the first claim wins in the +// store, and every competing claim is refused naming it. +func TestSpendBatchAlternatingClaimsNameTheWinner(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "4934-alternating") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "4934-alternating") + winnerSpends, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + loserSpends, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + winners := make([]*batchSpend, 0, 4) + losers := make([]*batchSpend, 0, 4) + batch := make([]*batchSpend, 0, 8) + for range 4 { + winner := &batchSpend{spend: winnerSpends[0], blockHeight: 2, errCh: make(chan error, 1)} + loser := &batchSpend{spend: loserSpends[0], blockHeight: 2, errCh: make(chan error, 1)} + winners, losers = append(winners, winner), append(losers, loser) + batch = append(batch, winner, loser) + } + store.sendSpendBatch(batch) + + for _, item := range winners { + require.NoError(t, <-item.errCh) + } + for _, item := range losers { + err := <-item.errCh + require.ErrorIs(t, err, errors.ErrSpent) + var data *errors.UtxoSpentErrData + require.True(t, errors.AsData(err, &data)) + require.Equal(t, winnerSpends[0].SpendingData.Bytes(), data.SpendingData.Bytes()) + } +} + +// A panic in the first part must still answer every claim, including the +// claims of parts that never ran, exactly once. +func TestSpendBatchPanicAnswersEveryClaim(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "4934-panic") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "4934-panic") + firstSpends, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + laterSpends, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + batch := []*batchSpend{ + {spend: firstSpends[0], blockHeight: 2, errCh: make(chan error, 1)}, + {blockHeight: 2, errCh: make(chan error, 1)}, + {spend: laterSpends[0], blockHeight: 2, errCh: make(chan error, 1)}, + } + require.NotPanics(t, func() { store.sendSpendBatch(batch) }) + + for _, item := range batch { + select { + case err := <-item.errCh: + require.ErrorIs(t, err, errors.ErrProcessing) + default: + t.Fatal("a claim got no answer after the panic") + } + require.Empty(t, item.errCh, "a claim was answered twice") + } + + spent, err := store.Spend(ctx, spendOf(t, parent, 1, 0), 2) + require.NoError(t, err, "the panicked part must not leave output 0 spent") + require.Len(t, spent, 1) +} + +// Claims with different checks on one outpoint must not share a verdict. A +// refusal that only the first claim's checks produce is not evidence about the +// claim behind it. +func TestSpendBatchClaimWithoutHashCheckIsNotRefusedForAnotherClaimsHashMismatch(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "same-checks-hash") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "same-checks-hash") + + checked, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + unchecked, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + stale := chainhash.Hash{99} + checked[0].UTXOHash = &stale + unchecked[0].UTXOHash = &stale + + first := &batchSpend{spend: checked[0], blockHeight: 2, errCh: make(chan error, 1)} + second := &batchSpend{spend: unchecked[0], blockHeight: 2, skipUTXOHashCheck: true, errCh: make(chan error, 1)} + store.sendSpendBatch([]*batchSpend{first, second}) + + require.ErrorIs(t, <-first.errCh, errors.ErrUtxoHashMismatch) + require.NoError(t, <-second.errCh, "the claim that skips the hash check must not inherit the other claim's mismatch") + + probe, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + stored, err := store.GetSpend(ctx, probe[0]) + require.NoError(t, err) + require.Equal(t, int(utxo.Status_SPENT), stored.Status) + require.NotNil(t, stored.SpendingData) + require.Equal(t, unchecked[0].SpendingData.Bytes(), stored.SpendingData.Bytes()) +} + +func TestSpendBatchClaimIgnoringConflictingIsNotRefusedForAnotherClaimsConflictingVerdict(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + store := setupSharedBatch(ctx, t, "same-checks-conflicting") + require.NoError(t, store.SetBlockHeight(2)) + grandparent := twoOutParent(ctx, t, store, "same-checks-conflicting") + parent := spendOf(t, grandparent, 7, 0) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + _, err := store.Create(ctx, parent, 1, utxo.WithConflicting(true)) + require.NoError(t, err) + + strict, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + lenient, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + first := &batchSpend{spend: strict[0], blockHeight: 2, errCh: make(chan error, 1)} + second := &batchSpend{spend: lenient[0], blockHeight: 2, ignoreConflicting: true, errCh: make(chan error, 1)} + store.sendSpendBatch([]*batchSpend{first, second}) + + require.ErrorIs(t, <-first.errCh, errors.ErrTxConflicting) + require.NoError(t, <-second.errCh, "the claim that ignores conflicting must not inherit the other claim's verdict") + + stored, err := store.GetSpend(ctx, lenient[0]) + require.NoError(t, err) + require.NotNil(t, stored.SpendingData) + require.Equal(t, lenient[0].SpendingData.Bytes(), stored.SpendingData.Bytes()) +} diff --git a/stores/utxo/sql/respend_same_batch_ownership_test.go b/stores/utxo/sql/respend_same_batch_ownership_test.go new file mode 100644 index 0000000000..9be8b662a2 --- /dev/null +++ b/stores/utxo/sql/respend_same_batch_ownership_test.go @@ -0,0 +1,766 @@ +package sql + +import ( + "context" + "net/url" + "sync" + "testing" + "time" + + "github.com/bsv-blockchain/go-batcher/v2" + "github.com/bsv-blockchain/go-bt/v2" + "github.com/bsv-blockchain/go-bt/v2/bscript" + "github.com/bsv-blockchain/go-bt/v2/chainhash" + "github.com/bsv-blockchain/teranode/errors" + "github.com/bsv-blockchain/teranode/stores/utxo" + "github.com/bsv-blockchain/teranode/ulogger" + "github.com/bsv-blockchain/teranode/util/test" + dto "github.com/prometheus/client_model/go" + "github.com/stretchr/testify/require" +) + +// setupSharedBatch builds a store whose spend batcher actually accumulates more +// than one claim per batch, which the respend tests need. +// +// The package's setup() forces BatcherDrainMode=true so batch callbacks fire +// immediately and every batch holds one item. Here drain mode is off and the +// window is wide, so a Spend issued just before another lands in the SAME batch. +func setupSharedBatch(ctx context.Context, t *testing.T, dbName string) *Store { + t.Helper() + initPrometheusMetrics() + + tSettings := test.CreateBaseTestSettings(t) + tSettings.UtxoStore.DBTimeout = 30 * time.Second + tSettings.UtxoStore.SpendBatcherSize = 256 + tSettings.UtxoStore.SpendBatcherDurationMillis = 200 + tSettings.BatcherDrainMode = false + + utxoStoreURL, err := url.Parse("sqlitememory:///" + dbName) + require.NoError(t, err) + + store, err := New(ctx, ulogger.TestLogger{}, tSettings, utxoStoreURL) + require.NoError(t, err) + t.Cleanup(func() { _ = store.Close(context.Background()) }) + + return store +} + +// twoOutParent creates a parent with two outputs and returns it. +func twoOutParent(ctx context.Context, t *testing.T, store *Store, seed string) *bt.Tx { + t.Helper() + + parent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte(seed)) + require.NoError(t, parent.From(prev.String(), 0, + "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 2000)) + + _, err := store.Create(ctx, parent, 1) + require.NoError(t, err) + + return parent +} + +// spendOf builds a spend of the given vouts of parent, distinguished by lockTime +// so each variant carries different spending data. +func spendOf(t *testing.T, parent *bt.Tx, lockTime uint32, vouts ...uint32) *bt.Tx { + t.Helper() + + tx := bt.NewTx() + for _, v := range vouts { + require.NoError(t, tx.From(parent.TxIDChainHash().String(), v, + parent.Outputs[v].LockingScript.String(), parent.Outputs[v].Satoshis)) + } + require.NoError(t, tx.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + tx.LockTime = lockTime + + return tx +} + +// TestRespendBehindLoserInSameBatchKeepsLegitimateSpends reproduces the +// respend-behind-loser failure. +// +// S0 legitimately spends both of the parent's outputs. A later batch then +// carries a double-spend attempt S1 on output 0 AHEAD of an idempotent re-spend +// of S0. The former duplicate filter awarded the outpoint to the first +// claim in the batch without consulting the persisted spender, so S0's +// idempotent re-spend is rejected with ErrSpent naming S1 -- a transaction that +// never spent anything. Store.Spend then treats that ErrSpent as an unwinnable +// failure (hasUnwinnableFailure) and un-spends output 1, which S0 had already +// re-spent successfully in the same batch. +// +// The test checks both the result and stored state: +// - the re-spend must not be rejected (it matches the persisted spender); +// - output 1 must stay spent by S0 even if some other input is refused. +func TestRespendBehindLoserInSameBatchKeepsLegitimateSpends(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + store := setupSharedBatch(ctx, t, "4934respend") + require.NoError(t, store.SetBlockHeight(2)) + + parent := twoOutParent(ctx, t, store, "4934-parent") + + s0 := spendOf(t, parent, 1, 0, 1) // legitimate spender of both outputs + s1 := spendOf(t, parent, 2, 0) // double-spend attempt on output 0 + + // S0 spends both outputs up front. + _, err := store.Spend(ctx, s0, 2) + require.NoError(t, err, "initial S0 spend must succeed") + + // Capture the public Spend calls at the dispatch boundary. This fixes + // batch membership and order without relying on scheduler timing. + store.spendBatcher.Close() + queued := make(chan *batchSpend, 3) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { + queued <- items[0] + }, false) + next := func() *batchSpend { + t.Helper() + select { + case item := <-queued: + return item + case <-time.After(5 * time.Second): + t.Fatal("Spend did not enqueue its input") + return nil + } + } + errS1 := make(chan error, 1) + go func() { + _, e := store.Spend(ctx, s1, 2) + errS1 <- e + }() + loserItem := next() + errS0Ch := make(chan error, 1) + go func() { + _, e := store.Spend(ctx, s0, 2) + errS0Ch <- e + }() + first, second := next(), next() + if first.spend.Vout != 0 { + first, second = second, first + } + store.sendSpendBatch([]*batchSpend{loserItem, first, second}) + errS0 := <-errS0Ch + s1Err := <-errS1 + t.Logf("S1 err : %v", s1Err) + t.Logf("S0 re-spend err: %v", errS0) + + // Defect 1: an idempotent re-spend is a supported path and must succeed. + require.NoError(t, errS0, + "idempotent re-spend of S0 was rejected -- the in-batch filter handed the outpoint to S1") + + // The #825 guarantee must survive: the genuine double-spend loser is still + // refused in the same batch, and is now blamed on S0, the tx that really + // holds the outpoint, rather than on itself. + require.Error(t, s1Err, "the double-spend attempt on output 0 must still be refused") + require.True(t, errors.Is(s1Err, errors.ErrSpent), "expected ErrSpent for the loser, got: %v", s1Err) + require.Contains(t, s1Err.Error(), s0.TxID(), + "the loser must be blamed on S0, the persisted spender") + + // Defect 2: both outputs must remain spent by S0. Output 1 is the one the + // rollback clears, and it is a real consensus-state loss. + spends, err := utxo.GetSpends(s0) + require.NoError(t, err) + require.Len(t, spends, 2) + + for _, sp := range spends { + resp, getErr := store.GetSpend(ctx, sp) + require.NoError(t, getErr) + t.Logf("output %d: status=%v spendingData=%v", sp.Vout, resp.Status, resp.SpendingData) + + require.Equal(t, int(utxo.Status_SPENT), resp.Status, + "output %d that S0 legitimately spent went back to unspent", sp.Vout) + require.NotNil(t, resp.SpendingData, "output %d must name its spender", sp.Vout) + require.Equal(t, s0.TxID(), resp.SpendingData.TxID.String(), + "output %d is owned by %s, not by S0", sp.Vout, resp.SpendingData.TxID) + } +} + +// Hold the first part in a real SQLite connection checkout until the competing +// caller has returned. The invalid first claim leaves the output spendable, so +// dispatching the abandoned second claim would create a dangling spent output. +func TestSpendBatchDoesNotCommitAbandonedLaterClaim(t *testing.T) { + for _, cancelCaller := range []bool{false, true} { + name, wantClass := "timeout", errors.ErrServiceUnavailable + if cancelCaller { + name, wantClass = "cancellation", errors.ErrContextCanceled + } + t.Run(name, func(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "abandoned-"+name) + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, name) + first, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + wrongHash := chainhash.Hash{99} + first[0].UTXOHash = &wrongHash + firstItem := &batchSpend{spend: first[0], blockHeight: 2, errCh: make(chan error, 1)} + + store.spendBatcher.Close() + queued := make(chan *batchSpend, 1) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + store.settings.UtxoStore.SpendWaitTimeout = 200 * time.Millisecond + callerCtx, cancel := context.WithCancel(ctx) + defer cancel() + result := make(chan error, 1) + laterTx := spendOf(t, parent, 2, 0) + go func() { _, err := store.Spend(callerCtx, laterTx, 2); result <- err }() + var later *batchSpend + select { + case later = <-queued: + case <-time.After(3 * time.Second): + t.Fatal("claim not queued") + } + + store.db.SetMaxOpenConns(1) + held, err := store.db.Conn(ctx) + require.NoError(t, err) + t.Cleanup(func() { _ = held.Close() }) + waits := store.db.Stats().WaitCount + done := make(chan struct{}) + go func() { defer close(done); store.sendSpendBatch([]*batchSpend{firstItem, later}) }() + require.Eventually(t, func() bool { return store.db.Stats().WaitCount > waits }, time.Second, time.Millisecond) + if cancelCaller { + cancel() + } + select { + case err := <-result: + require.ErrorIs(t, err, wantClass) + case <-time.After(3 * time.Second): + t.Fatal("caller did not stop waiting") + } + require.NoError(t, held.Close()) + select { + case <-done: + case <-time.After(3 * time.Second): + t.Fatal("batch did not complete") + } + + require.ErrorIs(t, firstItem.err, errors.ErrUtxoHashMismatch) + stored, err := store.GetSpend(ctx, later.spend) + require.NoError(t, err) + require.Equal(t, int(utxo.Status_OK), stored.Status) + require.Nil(t, stored.SpendingData, "no transaction record exists for the abandoned caller") + require.ErrorIs(t, later.err, wantClass) + _, err = store.Get(ctx, later.spend.SpendingData.TxID) + require.ErrorIs(t, err, errors.ErrTxNotFound) + }) + } +} + +// A claim that started before its caller's deadline and finishes after it must +// settle before the caller returns, and its spend must be rolled back, because +// no spender record is ever created for a caller that got an error. The second +// shape is a claim with the wrong UTXO hash ahead of a claim with the right +// hash, so the right claim runs in a later backend part. +func TestSpendAwaitsAdmittedClaimThatFinishesAfterCallerDeadline(t *testing.T) { + for _, shape := range []string{"single claim", "wrong hash claim first"} { + for _, cancelCaller := range []bool{false, true} { + name, wantClass := shape+" timeout", errors.ErrServiceUnavailable + if cancelCaller { + name, wantClass = shape+" cancellation", errors.ErrContextCanceled + } + + t.Run(name, func(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "late-"+name) + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, name) + + store.spendBatcher.Close() + queued := make(chan *batchSpend, 1) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + store.settings.UtxoStore.SpendWaitTimeout = 200 * time.Millisecond + + callerCtx, cancel := context.WithCancel(ctx) + defer cancel() + + result := make(chan error, 1) + laterTx := spendOf(t, parent, 2, 0) + go func() { _, err := store.Spend(callerCtx, laterTx, 2); result <- err }() + + var later *batchSpend + select { + case later = <-queued: + case <-time.After(3 * time.Second): + t.Fatal("claim not queued") + } + + batch := []*batchSpend{later} + var firstItem *batchSpend + if shape == "wrong hash claim first" { + first, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + wrongHash := chainhash.Hash{99} + first[0].UTXOHash = &wrongHash + firstItem = &batchSpend{spend: first[0], blockHeight: 2, errCh: make(chan error, 1)} + batch = []*batchSpend{firstItem, later} + } + + entered := make(chan struct{}) + release := make(chan struct{}) + store.beforeSpendPart = func(part []*batchSpend) { + for _, item := range part { + if item == later { + close(entered) + <-release + + return + } + } + } + + done := make(chan struct{}) + go func() { defer close(done); store.sendSpendBatch(batch) }() + + select { + case <-entered: + case <-time.After(3 * time.Second): + t.Fatal("claim part did not start") + } + + require.True(t, later.admission.Started()) + + if cancelCaller { + cancel() + } + + select { + case err := <-result: + t.Fatalf("caller returned %v while its admitted claim was still running", err) + case <-time.After(500 * time.Millisecond): + } + + close(release) + + select { + case err := <-result: + require.ErrorIs(t, err, wantClass) + case <-time.After(5 * time.Second): + t.Fatal("caller did not return after the claim settled") + } + + select { + case <-done: + case <-time.After(3 * time.Second): + t.Fatal("batch did not complete") + } + + if firstItem != nil { + require.ErrorIs(t, firstItem.err, errors.ErrUtxoHashMismatch) + } + + require.NoError(t, later.err, "the claim must have run to completion for this test to exercise the late path") + + stored, err := store.GetSpend(ctx, later.spend) + require.NoError(t, err) + require.Equal(t, int(utxo.Status_OK), stored.Status, "the late claim's spend was left on the outpoint") + require.Nil(t, stored.SpendingData) + + store.beforeSpendPart = nil + store.spendBatcher.Close() + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, store.sendSpendBatch, false) + store.settings.UtxoStore.SpendWaitTimeout = 5 * time.Second + + _, err = store.Spend(ctx, spendOf(t, parent, 3, 0), 2) + require.NoError(t, err, "a fresh spend of the outpoint must not see the late claimant as its owner") + }) + } + } +} + +// The second claim differs from the first only in ignoreLocked, so the first +// claim's locked verdict says nothing about it. +func TestSpendBatchClaimIgnoringLockedIsNotRefusedForAnotherClaimsLockedVerdict(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "ignore-locked-verdict") + require.NoError(t, store.SetBlockHeight(2)) + + parent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte("ignore-locked-verdict")) + require.NoError(t, parent.From(prev.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + parent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, parent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + + _, err := store.Create(ctx, parent, 1, utxo.WithLocked(true)) + require.NoError(t, err) + + firstSpends, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + secondSpends, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + first := &batchSpend{spend: firstSpends[0], blockHeight: 2, errCh: make(chan error, 1)} + second := &batchSpend{spend: secondSpends[0], blockHeight: 2, ignoreLocked: true, errCh: make(chan error, 1)} + + store.sendSpendBatch([]*batchSpend{first, second}) + + require.ErrorIs(t, first.err, errors.ErrTxLocked) + require.NoError(t, second.err, "a claim that ignores the locked flag was refused with another claim's locked verdict") + + stored, err := store.GetSpend(ctx, second.spend) + require.NoError(t, err) + require.NotNil(t, stored.SpendingData) + require.Equal(t, second.spend.SpendingData.TxID.String(), stored.SpendingData.TxID.String()) +} + +// The second claim differs from the first only in block height. The first is +// below coinbase maturity and the second is at it, so the first claim's +// immature verdict says nothing about the second. +func TestSpendBatchClaimAtMatureHeightIsNotRefusedForAnotherClaimsImmatureVerdict(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "height-verdict") + require.NoError(t, store.SetBlockHeight(2)) + + maturity := uint32(store.settings.ChainCfgParams.CoinbaseMaturity) + require.Positive(t, maturity) + + const createHeight = uint32(100) + + coinbaseTx, err := bt.NewTxFromString("01000000010000000000000000000000000000000000000000000000000000000000000000ffffffff580320a107152f5669614254432f48656c6c6f20576f726c64212f2cfabe6d6dbcbb1b0222e1aeebaca2a9c905bb23a3ad0302898ec600a9033a87ec1645a446010000000000000010f829ba0b13a84def80c389cde9840000ffffffff0174fdaf4a000000001976a914f1c075a01882ae0972f95d3a4177c86c852b7d9188ac00000000") + require.NoError(t, err) + + _, err = store.Create(ctx, coinbaseTx, createHeight) + require.NoError(t, err) + + firstSpends, err := utxo.GetSpends(spendOf(t, coinbaseTx, 1, 0)) + require.NoError(t, err) + secondSpends, err := utxo.GetSpends(spendOf(t, coinbaseTx, 2, 0)) + require.NoError(t, err) + + first := &batchSpend{spend: firstSpends[0], blockHeight: createHeight + maturity - 1, ignoreLocked: true, errCh: make(chan error, 1)} + second := &batchSpend{spend: secondSpends[0], blockHeight: createHeight + maturity, ignoreLocked: true, errCh: make(chan error, 1)} + + store.sendSpendBatch([]*batchSpend{first, second}) + + require.ErrorIs(t, first.err, errors.ErrTxCoinbaseImmature) + require.NoError(t, second.err, "a claim at a mature height was refused with another claim's immature verdict") +} + +type heldClaim struct { + store *Store + parent *bt.Tx + later *batchSpend + result chan error + release chan struct{} + done chan struct{} +} + +// startHeldClaim runs Spend for a claim that sits behind a wrong hash claim and +// whose backend part is held until release is closed. It returns once that part +// has started. +func startHeldClaim(t *testing.T, name string, wait, bound time.Duration) *heldClaim { + t.Helper() + + ctx := context.Background() + store := setupSharedBatch(ctx, t, name) + require.NoError(t, store.SetBlockHeight(2)) + + parent := twoOutParent(ctx, t, store, name) + + store.spendBatcher.Close() + queued := make(chan *batchSpend, 1) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + store.settings.UtxoStore.SpendWaitTimeout = wait + store.settings.UtxoStore.SpendRollbackTimeout = bound + + held := &heldClaim{store: store, parent: parent, result: make(chan error, 1), release: make(chan struct{}), done: make(chan struct{})} + + go func() { _, err := store.Spend(ctx, spendOf(t, parent, 2, 0), 2); held.result <- err }() + + select { + case held.later = <-queued: + case <-time.After(3 * time.Second): + t.Fatal("claim not queued") + } + + first, err := utxo.GetSpends(spendOf(t, parent, 1, 0)) + require.NoError(t, err) + + wrongHash := chainhash.Hash{99} + first[0].UTXOHash = &wrongHash + firstItem := &batchSpend{spend: first[0], blockHeight: 2, errCh: make(chan error, 1)} + + entered := make(chan struct{}) + store.beforeSpendPart = func(part []*batchSpend) { + for _, item := range part { + if item == held.later { + close(entered) + <-held.release + + return + } + } + } + + go func() { defer close(held.done); store.sendSpendBatch([]*batchSpend{firstItem, held.later}) }() + + select { + case <-entered: + case <-time.After(3 * time.Second): + t.Fatal("claim part did not start") + } + + return held +} + +func abortInFlightCount(t *testing.T) float64 { + t.Helper() + + var metric dto.Metric + require.NoError(t, prometheusUtxoSpendAbortInFlight.Write(&metric)) + + return metric.GetCounter().GetValue() +} + +func outputIsUnspent(ctx context.Context, store *Store, spend *utxo.Spend) bool { + stored, err := store.GetSpend(ctx, spend) + + return err == nil && stored.Status == int(utxo.Status_OK) && stored.SpendingData == nil +} + +// A claim that started before its caller gave up and finishes after the +// courtesy wait ends must be rolled back by whoever completes it, with no time +// bound, because the caller got an error and no spender record is ever created. +func TestSpendRollsBackClaimThatFinishesAfterAwaitBound(t *testing.T) { + initPrometheusMetrics() + inFlight := abortInFlightCount(t) + held := startHeldClaim(t, "orphan-after-bound", 300*time.Millisecond, 4*time.Second) + + select { + case err := <-held.result: + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + case <-time.After(5 * time.Second): + t.Fatal("caller did not return while its started claim was still held") + } + + select { + case <-held.done: + t.Fatal("the claim finished before the caller returned, so the late path was not exercised") + default: + } + + require.Equal(t, inFlight+1, abortInFlightCount(t), "the claim the caller gave up on must count as in flight") + + close(held.release) + + select { + case <-held.done: + case <-time.After(5 * time.Second): + t.Fatal("batch did not complete") + } + + require.NoError(t, held.later.err, "the claim must have run to completion for this test to exercise the late path") + require.Eventually(t, func() bool { return outputIsUnspent(context.Background(), held.store, held.later.spend) }, 10*time.Second, 20*time.Millisecond, + "the late claim's spend was left on the outpoint") +} + +// A claim whose success was published before its caller gave up on it must be +// rolled back by the caller's side of the hand-off. +func TestSpendRollsBackClaimPublishedBeforeItsCallerGaveUp(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "orphan-after-publish") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "orphan-after-publish") + + spends, err := utxo.GetSpends(spendOf(t, parent, 2, 0)) + require.NoError(t, err) + + item := &batchSpend{spend: spends[0], blockHeight: 2, errCh: make(chan error, 1), rollbackOrphan: store.rollbackOrphanedSpend} + store.sendSpendBatch([]*batchSpend{item}) + require.NoError(t, item.err, "the claim must have succeeded for this test to exercise the orphan path") + require.False(t, outputIsUnspent(ctx, store, spends[0]), "the claim must have spent the output") + + item.markOrphaned() + + require.Eventually(t, func() bool { return outputIsUnspent(ctx, store, spends[0]) }, 10*time.Second, 20*time.Millisecond, + "a claim published before its caller gave up was left on the output") +} + +// The courtesy wait for a started claim and the rollback share one budget, so a +// failed Spend returns within SpendWaitTimeout plus SpendRollbackTimeout. The +// courtesy wait is only a quarter of that budget, so with a claim held past it +// the caller returns well before the whole budget is gone. +func TestSpendCallerBoundHoldsWhileStartedClaimIsHeld(t *testing.T) { + const ( + wait = 300 * time.Millisecond + bound = 2 * time.Second + ) + + started := time.Now() + held := startHeldClaim(t, "caller-bound", wait, bound) + + select { + case err := <-held.result: + require.ErrorIs(t, err, errors.ErrServiceUnavailable) + case <-time.After(wait + bound + 2*time.Second): + t.Fatal("caller did not return within the documented bound") + } + + elapsed := time.Since(started) + require.LessOrEqual(t, elapsed, wait+bound+500*time.Millisecond, "caller held longer than SpendWaitTimeout plus SpendRollbackTimeout") + require.Less(t, elapsed, wait+bound/2, "the courtesy wait must take a quarter of the budget, not all of it") + + close(held.release) + <-held.done +} + +// A blocking enqueue on a full batcher channel must not use up the wait budget: +// the budget starts when the enqueue returns. +func TestSpendWaitBudgetStartsAfterEnqueueOnSaturatedBatcher(t *testing.T) { + ctx := context.Background() + store := setupSharedBatch(ctx, t, "saturated-batcher") + require.NoError(t, store.SetBlockHeight(2)) + parent := twoOutParent(ctx, t, store, "saturated") + + store.spendBatcher.Close() + + release := make(chan struct{}) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { + <-release + + real := make([]*batchSpend, 0, len(items)) + + for _, item := range items { + if item.errCh != nil && item.spend.TxID != nil { + real = append(real, item) + } + } + + if len(real) > 0 { + store.sendSpendBatch(real) + } + }, false) + store.settings.UtxoStore.SpendWaitTimeout = 300 * time.Millisecond + + var puts sync.WaitGroup + + for i := 0; i < 1000; i++ { + puts.Add(1) + + go func() { + defer puts.Done() + store.spendBatcher.Put(&batchSpend{spend: &utxo.Spend{}}) + }() + } + + time.Sleep(300 * time.Millisecond) + + laterTx := spendOf(t, parent, 2, 0) + result := make(chan error, 1) + go func() { _, err := store.Spend(ctx, laterTx, 2); result <- err }() + + time.Sleep(800 * time.Millisecond) + close(release) + + select { + case err := <-result: + require.NoError(t, err, "a spend that waited for room in the batcher longer than SpendWaitTimeout must still succeed") + case <-time.After(10 * time.Second): + t.Fatal("Spend did not return after the batcher drained") + } + + puts.Wait() + + spends, err := utxo.GetSpends(laterTx) + require.NoError(t, err) + require.False(t, outputIsUnspent(ctx, store, spends[0]), "the spend must have been applied") +} + +// When a completed spend of the same tx failed with ErrTxLocked and nothing +// proves the tx unwinnable, a concurrent attempt at the same txid may own the +// spends, so the batch rollback is suppressed. The late claim must then be left +// as the batch's own spends are, not unspent. +func TestSpendDoesNotRollBackLateClaimWhenTransientLockSuppressesRollback(t *testing.T) { + initPrometheusMetrics() + ctx := context.Background() + store := setupSharedBatch(ctx, t, "orphan-suppressed") + require.NoError(t, store.SetBlockHeight(2)) + + parent := twoOutParent(ctx, t, store, "orphan-suppressed") + + lockedParent := bt.NewTx() + prev := chainhash.DoubleHashH([]byte("orphan-suppressed-locked")) + require.NoError(t, lockedParent.From(prev.String(), 0, "76a91471d7dd96d9edda09180fe9d57a477b5acc9cad1188ac", 1e8)) + lockedParent.Inputs[0].UnlockingScript = bscript.NewFromBytes([]byte{bscript.OpTRUE}) + require.NoError(t, lockedParent.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1000)) + _, err := store.Create(ctx, lockedParent, 1, utxo.WithLocked(true)) + require.NoError(t, err) + + twoInputs := bt.NewTx() + require.NoError(t, twoInputs.From(lockedParent.TxIDChainHash().String(), 0, lockedParent.Outputs[0].LockingScript.String(), lockedParent.Outputs[0].Satoshis)) + require.NoError(t, twoInputs.From(parent.TxIDChainHash().String(), 0, parent.Outputs[0].LockingScript.String(), parent.Outputs[0].Satoshis)) + require.NoError(t, twoInputs.PayToAddress("1BUBHgpCBWCsD2Ajbeu7ZgCgvMHsoYHm3W", 1)) + twoInputs.LockTime = 2 + + store.spendBatcher.Close() + queued := make(chan *batchSpend, 2) + store.spendBatcher = batcher.NewWithPool(1, time.Millisecond, func(items []*batchSpend) { queued <- items[0] }, false) + store.settings.UtxoStore.SpendWaitTimeout = 300 * time.Millisecond + store.settings.UtxoStore.SpendRollbackTimeout = 4 * time.Second + + inFlight := abortInFlightCount(t) + result := make(chan error, 1) + go func() { _, err := store.Spend(ctx, twoInputs, 2); result <- err }() + + var lockedItem, claim *batchSpend + + for i := 0; i < 2; i++ { + select { + case item := <-queued: + if item.spend.TxID.IsEqual(lockedParent.TxIDChainHash()) { + lockedItem = item + } else { + claim = item + } + case <-time.After(3 * time.Second): + t.Fatal("claims not queued") + } + } + + require.NotNil(t, lockedItem) + require.NotNil(t, claim) + + store.sendSpendBatch([]*batchSpend{lockedItem}) + require.ErrorIs(t, lockedItem.err, errors.ErrTxLocked) + + entered, release := make(chan struct{}), make(chan struct{}) + store.beforeSpendPart = func(part []*batchSpend) { + for _, item := range part { + if item == claim { + close(entered) + <-release + + return + } + } + } + + done := make(chan struct{}) + go func() { defer close(done); store.sendSpendBatch([]*batchSpend{claim}) }() + + select { + case <-entered: + case <-time.After(3 * time.Second): + t.Fatal("claim part did not start") + } + + select { + case err := <-result: + require.Error(t, err) + case <-time.After(5 * time.Second): + t.Fatal("caller did not return while its started claim was still held") + } + + require.Equal(t, inFlight+1, abortInFlightCount(t), "a suppressed late claim still counts as in flight") + + close(release) + <-done + require.NoError(t, claim.err) + + require.Never(t, func() bool { return outputIsUnspent(ctx, store, claim.spend) }, 2*time.Second, 20*time.Millisecond, + "the late claim was rolled back although a transient lock suppressed the batch rollback") +} diff --git a/stores/utxo/sql/spend_rollback.go b/stores/utxo/sql/spend_rollback.go index e5ee6eed6b..fd845215f8 100644 --- a/stores/utxo/sql/spend_rollback.go +++ b/stores/utxo/sql/spend_rollback.go @@ -4,6 +4,7 @@ import ( "context" "time" + "github.com/bsv-blockchain/go-bt/v2/chainhash" "github.com/bsv-blockchain/teranode/errors" "github.com/bsv-blockchain/teranode/stores/utxo" ) @@ -87,6 +88,64 @@ func (s *Store) rollbackSpendChunks(ctx context.Context, spentSpends []*utxo.Spe return reverted, firstErr } +// rollbackUnrecordedSpends reverts spends when the spending tx has no record. +// An existing record means the refs are not dangling and the spends belong to a +// live tx, and an indeterminate probe skips the rollback, because wrongly +// clearing a live spender's slot cannot be undone. The Spend abort path and +// rollbackOrphanedSpend both end here, so the two apply one rule. The probe is +// re-queried every time on purpose, see the comment in Spend. +func (s *Store) rollbackUnrecordedSpends(ctx context.Context, spenderID *chainhash.Hash, spends []*utxo.Spend) { + var spenderExists bool + if scanErr := s.db.QueryRowContext(ctx, "SELECT EXISTS(SELECT 1 FROM transactions WHERE hash = $1)", spenderID[:]).Scan(&spenderExists); scanErr != nil { + s.logger.Errorf("[SPEND][%s] cannot determine whether spender exists, skipping rollback of %d partial spend(s): %v", spenderID, len(spends), scanErr) + prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeIndeterminate).Inc() + + return + } + + if spenderExists { + prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeSpenderExists).Inc() + + return + } + + prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeFired).Inc() + + reverted, unspendErr := s.rollbackSpendChunks(ctx, spends) + if unspendErr != nil { + left := len(spends) - reverted + s.logger.Errorf("[SPEND][%s] error in sql unspend (batched mode): reverted %d of %d partial spend(s), %d left dangling: %v", + spenderID, reverted, len(spends), left, unspendErr) + // Counted per dangling spend left behind, not per call: with chunking, + // one failing chunk no longer means the whole rollback failed, so this + // is read as a ref count. + prometheusUtxoSpendRollbackFailed.Add(float64(left)) + + return + } + + s.logger.Warnf("[SPEND][%s] rolled back %d partial spend(s) (batched mode)", spenderID, reverted) +} + +// rollbackOrphanedSpend reverts the spend of one input whose caller gave up +// while the backend had started it and which then succeeded. The context is +// detached from the caller and from the store, as in Spend, and bounded by +// spendRollbackBound. +func (s *Store) rollbackOrphanedSpend(spend *utxo.Spend) { + ctx, cancel := context.WithTimeout(context.Background(), s.spendRollbackBound()) + defer cancel() + + s.rollbackUnrecordedSpends(ctx, spend.SpendingData.TxID, []*utxo.Spend{spend}) +} + +// rollbackSuppressed reports whether a concurrent attempt at the same txid may +// own the spends: a transient lock or creating window was seen and nothing +// proves the txid unwinnable. The Spend rollback and the orphan hand-off both +// use it, so a late success is unspent exactly when the batch rollback is. +func rollbackSuppressed(spends []*utxo.Spend) bool { + return (hasTransientLockFailure(spends) || hasTransientCreatingFailure(spends)) && !hasUnwinnableFailure(spends) +} + // hasTransientLockFailure reports whether any spend failed with ErrTxLocked. // // Mirrors the aerospike store's helper of the same name. Deliberately duplicated diff --git a/stores/utxo/sql/sql.go b/stores/utxo/sql/sql.go index 148e101269..60ef6993e6 100644 --- a/stores/utxo/sql/sql.go +++ b/stores/utxo/sql/sql.go @@ -92,12 +92,59 @@ const ( // batchSpend represents a single UTXO spend request in a batch. // Mirrors aerospike/spend.go batchSpend struct. type batchSpend struct { + admission utxo.SpendAdmission + requestCtx context.Context spend *utxo.Spend // UTXO to spend blockHeight uint32 // Current block height errCh chan error // Channel for completion notification ignoreConflicting bool ignoreLocked bool skipUTXOHashCheck bool + // delivered is read and written only on the batcher goroutine. err is + // written there before published is stored, and the caller reads it only + // after observing published. + delivered bool + err error + published atomic.Bool + // orphan decides who rolls back this item's spend when its caller gave up + // while the backend had already started it. rollbackOrphan performs that + // rollback. + orphan utxo.SpendOrphan + rollbackOrphan func(spend *utxo.Spend) +} + +// markOrphaned records that the caller gave up on an item the backend had +// started. Spend calls it only when the batch rollback is not suppressed, so a +// late success is unspent exactly when the batch rollback would be. If the +// item has already published a success the caller rolls the spend back; +// otherwise deliver does when the item publishes. +func (b *batchSpend) markOrphaned() { + b.orphan.Mark() + b.rollbackIfOrphaned() +} + +// rollbackIfOrphaned starts the rollback of this item's spend, on a detached +// goroutine, when its caller gave up and the item published a success. Both +// deliver and markOrphaned call it, and the claim lets exactly one of them +// start the rollback whichever runs first. +func (b *batchSpend) rollbackIfOrphaned() { + if b.rollbackOrphan != nil && b.published.Load() && b.err == nil && b.orphan.Claim() { + go b.rollbackOrphan(b.spend) + } +} + +// deliver answers the caller once. Later calls are no-ops, so the panic +// recovery in sendSpendBatch cannot block on a full errCh or answer twice. +func (b *batchSpend) deliver(err error) { + if b.delivered { + return + } + + b.delivered = true + b.err = err + b.errCh <- err + b.published.Store(true) + b.rollbackIfOrphaned() } // Store implements the UTXO store interface using a SQL database backend. @@ -126,6 +173,10 @@ type Store struct { // block-state methods. SetBlockHeight, SetMedianBlockTime and SetBlockState // are wrapped below to add a debug line. utxo.BlockStateFields + + // beforeSpendPart runs before each backend part of a spend batch. Tests use it + // to hold a part after its items started. + beforeSpendPart func(part []*batchSpend) } // batchUnlockItem represents a single SetLocked(false) request. @@ -2090,6 +2141,38 @@ func handleSpendPanic(recovered any, err *error, logger ulogger.Logger) { } } +// spendRollbackBound is the longest a failed Spend holds its caller after the +// caller gave up: the courtesy wait for started items and the rollback share +// this one budget, which starts when the first input gives up. Together with +// SpendWaitTimeout it is the documented bound on a Spend call. +func (s *Store) spendRollbackBound() time.Duration { + if d := s.settings.UtxoStore.SpendRollbackTimeout; d > 0 { + return d + } + + return 120 * time.Second +} + +// rollbackDeadline is the end of the budget for the rollback. A zero giveUp +// means no input gave up, so the rollback has a full bound. Otherwise the +// budget ends spendRollbackBound after giveUp, but never sooner than a quarter +// of the bound from now, so a wide transaction whose later inputs gave up late +// still gets a usable rollback. +func (s *Store) rollbackDeadline(giveUp time.Time) time.Time { + now := time.Now() + bound := s.spendRollbackBound() + + if giveUp.IsZero() { + return now.Add(bound) + } + + if floor := now.Add(bound / 4); giveUp.Add(bound).Before(floor) { + return floor + } + + return giveUp.Add(bound) +} + // Spend marks UTXOs as spent by updating their spending transaction ID. // It performs several validations: // - Checks if the UTXO exists @@ -2133,6 +2216,9 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore var ( mu sync.Mutex txAlreadyExists bool + timedOut bool + giveUp time.Time + orphans []*batchSpend spentSpends = make([]*utxo.Spend, 0, len(spends)) g errgroup.Group ) @@ -2163,50 +2249,88 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore handleSpendPanic(recover(), &spends[idx].Err, s.logger) }() + spendTimeout := s.settings.UtxoStore.SpendWaitTimeout + if spendTimeout <= 0 { + spendTimeout = 30 * time.Second + } + requestCtx, cancel := context.WithCancelCause(ctx) + defer cancel(nil) errCh := make(chan error, 1) - s.spendBatcher.PutCtx(ctx, &batchSpend{ + item := &batchSpend{ spend: spend, blockHeight: blockHeight, errCh: errCh, ignoreConflicting: useIgnoreConflicting, ignoreLocked: useIgnoreLocked, skipUTXOHashCheck: useSkipUTXOHashCheck, - }) - - // Wait for batch response with timeout to prevent indefinite blocking - spendTimeout := s.settings.UtxoStore.SpendWaitTimeout - if spendTimeout <= 0 { - spendTimeout = 30 * time.Second + requestCtx: requestCtx, + rollbackOrphan: s.rollbackOrphanedSpend, } + defer item.admission.Abandon() - timer := time.NewTimer(spendTimeout) - defer timer.Stop() + // The enqueue runs on the caller's context and the wait budget starts + // after it returns, so a send that blocks on a full batcher channel does + // not use up the budget. requestCtx exists before the enqueue only because + // the batcher reads it from the item; the timer below ends it. + s.spendBatcher.PutCtx(ctx, item) + + waitTimer := time.AfterFunc(spendTimeout, func() { cancel(context.DeadlineExceeded) }) + defer waitTimer.Stop() var batchErr error select { case batchErr = <-errCh: // Batch completed successfully or with error - case <-ctx.Done(): - // Known residual window (#1291, store-level atomic Spend / - // reverse-on-abort): this item is still enqueued in the batcher and - // will be committed by the callback under the store's own context, - // not this caller ctx. A straggler UPDATE can land after we give up - // here and after the rollback below has already run, leaving exactly - // the #1214 dangling ref. Not fixed here — counted below so it is - // at least observable. - prometheusUtxoSpendAbortInFlight.Inc() - spends[idx].Err = errors.NewContextCanceledError("[SPEND][%s:%d] context canceled while waiting for batch response", spend.TxID.String(), spend.Vout) - return nil - case <-timer.C: - // Known residual window (#1291, store-level atomic Spend / - // reverse-on-abort): same straggler risk as the ctx.Done() arm - // above — the item remains enqueued and can still commit under the - // store's own context after this per-item wait gives up and after - // the rollback below has run. Not fixed here — counted below so it - // is at least observable. - prometheusUtxoErrors.WithLabelValues("Spend", "BatchTimeout").Inc() - prometheusUtxoSpendAbortInFlight.Inc() - spends[idx].Err = errors.NewServiceUnavailableError("[SPEND][%s:%d] batch operation timed out after %s", spend.TxID.String(), spend.Vout, spendTimeout) + case <-requestCtx.Done(): + // Abandon first, so no further part of this item can start. An item + // that already started is awaited as a courtesy, on a detached context + // that ends a quarter of spendRollbackBound after the first caller gave + // up, and a prompt success joins spentSpends, so the rollback below + // covers it. An item still unpublished then is collected, and after + // g.Wait it is marked orphaned unless the transient-window gate + // suppresses the rollback, so whoever completes it rolls its spend + // back with no time bound. + started := !item.admission.Abandon() + + if ctx.Err() != nil { + spends[idx].Err = errors.NewContextCanceledError("[SPEND][%s:%d] context canceled while waiting for batch response", spend.TxID.String(), spend.Vout) + } else { + prometheusUtxoErrors.WithLabelValues("Spend", "BatchTimeout").Inc() + spends[idx].Err = errors.NewServiceUnavailableError("[SPEND][%s:%d] batch operation timed out after %s", spend.TxID.String(), spend.Vout, spendTimeout) + } + + mu.Lock() + timedOut = true + + if giveUp.IsZero() { + giveUp = time.Now() + } + + budgetStart := giveUp + mu.Unlock() + + if !started { + return nil + } + + lateCtx, lateCancel := context.WithDeadline(context.Background(), budgetStart.Add(s.spendRollbackBound()/4)) + defer lateCancel() + + select { + case lateErr := <-errCh: + if lateErr == nil { + mu.Lock() + spentSpends = append(spentSpends, spend) + mu.Unlock() + } + case <-lateCtx.Done(): + prometheusUtxoSpendAbortInFlight.Inc() + + mu.Lock() + orphans = append(orphans, item) + mu.Unlock() + } + return nil } @@ -2269,7 +2393,7 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore return nil, errors.NewError("error in sql spend (batched mode)", err) } - if len(spends) != len(spentSpends) { + if timedOut || len(spends) != len(spentSpends) { // Atomicity contract (mirrors aerospike/spend.go rollbackPartialSpends): // roll back the spends that succeeded, whatever the error class of the // ones that failed, so no parent is left naming a spender whose record is @@ -2299,7 +2423,15 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore sawTransientLock := hasTransientLockFailure(spends) sawTransientCreating := hasTransientCreatingFailure(spends) - if len(spentSpends) > 0 && (!(sawTransientLock || sawTransientCreating) || hasUnwinnableFailure(spends)) { + suppressed := rollbackSuppressed(spends) + + if !suppressed { + for _, item := range orphans { + item.markOrphaned() + } + } + + if len(spentSpends) > 0 && !suppressed { // Wrapped in a closure so rbCancel can be deferred: Spend has a parent // recover() (see the top of this function), and a panic between // context.WithTimeout and a bare inline rbCancel() call would unwind @@ -2307,8 +2439,6 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore // defer to this closure keeps the leak-proofing without extending // rbCtx's lifetime past this block, as a function-level defer would. func() { - rollback := false - // Detached from the caller's ctx (on the context-cancel path it is // already dead, and that is exactly a case where the partial spends // must still be cleaned up) but bounded, so a wedged database cannot @@ -2325,49 +2455,19 @@ func (s *Store) Spend(ctx context.Context, tx *bt.Tx, blockHeight uint32, ignore // getting it wrong is the failure mode we're rolling back to fix // (#1214). Do not "optimise" this back to the memo. // - // Uses SpendRollbackTimeout, not SpendWaitTimeout: SpendWaitTimeout - // is the end-to-end budget for ONE batched spend, while this budget - // covers the existence probe plus rollbackSpendChunks' sequence of - // chunked Unspend calls over spentSpends — a multiple of that - // single-spend cost on a wide transaction. On overrun the loop + // The deadline comes from SpendRollbackTimeout, not SpendWaitTimeout: + // SpendWaitTimeout is the end-to-end budget for ONE batched spend, + // while this budget covers the existence probe plus + // rollbackSpendChunks' sequence of chunked Unspend calls over + // spentSpends — a multiple of that single-spend cost on a wide + // transaction. It ends where the budget shared with the courtesy wait + // for started inputs ends (see rollbackDeadline). On overrun the loop // aborts and the remaining spends stay applied, counted via - // prometheusUtxoSpendRollbackFailed below. - rbTimeout := s.settings.UtxoStore.SpendRollbackTimeout - if rbTimeout <= 0 { - rbTimeout = 120 * time.Second - } - - rbCtx, rbCancel := context.WithTimeout(context.Background(), rbTimeout) + // prometheusUtxoSpendRollbackFailed. + rbCtx, rbCancel := context.WithDeadline(context.Background(), s.rollbackDeadline(giveUp)) defer rbCancel() - var spendingTxExists bool - if scanErr := s.db.QueryRowContext(rbCtx, "SELECT EXISTS(SELECT 1 FROM transactions WHERE hash = $1)", tx.TxIDChainHash()[:]).Scan(&spendingTxExists); scanErr != nil { - s.logger.Errorf("[SPEND][%s] cannot determine whether spender exists, skipping rollback of %d partial spend(s): %v", tx.TxID(), len(spentSpends), scanErr) - prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeIndeterminate).Inc() - } else { - rollback = !spendingTxExists - - if rollback { - prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeFired).Inc() - } else { - prometheusUtxoPartialSpendRollbacks.WithLabelValues(utxo.RollbackOutcomeSpenderExists).Inc() - } - } - - if rollback { - reverted, unspendErr := s.rollbackSpendChunks(rbCtx, spentSpends) - if unspendErr != nil { - left := len(spentSpends) - reverted - s.logger.Errorf("[SPEND][%s] error in sql unspend (batched mode): reverted %d of %d partial spend(s), %d left dangling: %v", - tx.TxID(), reverted, len(spentSpends), left, unspendErr) - // Counted per dangling spend left behind, not per call: with - // chunking, one failing chunk no longer means the whole - // rollback failed, so this is read as a ref count. - prometheusUtxoSpendRollbackFailed.Add(float64(left)) - } else { - s.logger.Warnf("[SPEND][%s] rolled back %d partial spend(s) (batched mode)", tx.TxID(), reverted) - } - } + s.rollbackUnrecordedSpends(rbCtx, tx.TxIDChainHash(), spentSpends) }() } else if len(spentSpends) > 0 { // Transient suppression: record the outcome so this store's dashboard @@ -2437,9 +2537,12 @@ func isDeadlock(err error) bool { return strings.Contains(msg, "database is locked") || strings.Contains(msg, "database table is locked") } -// sendSpendBatch is the batcher callback that processes a batch of spend operations -// in a single DB transaction. Called by the go-batcher when the batch is full or -// the timeout fires. Same SQL for both PostgreSQL and SQLite. +// sendSpendBatch is the batcher callback that processes a batch of spend operations. +// Called by the go-batcher when the batch is full or the timeout fires. Same SQL +// for both PostgreSQL and SQLite. A batch without competing claims on one outpoint +// runs in a single DB transaction. utxo.ProcessSpendBatch splits a batch with +// competing claims into ordered parts, one DB transaction each, and rejects a +// claim locally once the stored owner of its outpoint is known. // Mirrors aerospike/spend.go sendSpendBatchLua. // // Single-phase design: SELECT + UPDATE outputs (validates and marks each output as spent). @@ -2451,23 +2554,52 @@ func isDeadlock(err error) bool { // Aerospike doesn't need this because it uses optimistic single-key operations // without DB-level row locking. func (s *Store) sendSpendBatch(batch []*batchSpend) { - batch = utxo.FilterConflictingDuplicateSpendClaims(batch, - func(item *batchSpend) *utxo.Spend { + defer func() { + util.SignalBatchPanic(recover(), batch, "sendSpendBatch", s.logger, func(item *batchSpend, err error) { + if item != nil { + item.deliver(err) + } + }) + }() + + utxo.ProcessSpendBatch(batch, utxo.SpendBatchHandler[*batchSpend]{ + Start: func(item *batchSpend) error { if item == nil { return nil } - return item.spend + return item.admission.Start(item.requestCtx) }, - func(item *batchSpend, err error) { - item.errCh <- err + Spend: func(item *batchSpend) *utxo.Spend { + if item == nil { + return nil + } + return item.spend }, - ) - if len(batch) == 0 { - return - } + Process: func(part []*batchSpend) { + if s.beforeSpendPart != nil { + s.beforeSpendPart(part) + } - s.retrySpendBatch(batch, func(batch []*batchSpend) bool { - return s.trySendSpendBatch(s.ctx, batch) + s.retrySpendBatch(part, func(part []*batchSpend) bool { + return s.trySendSpendBatch(s.ctx, part) + }) + }, + Result: func(item *batchSpend) (error, bool) { + if item == nil || !item.delivered { + return nil, false + } + return item.err, true + }, + Reject: func(item *batchSpend, err error) { + item.deliver(err) + }, + SameChecks: func(a, b *batchSpend) bool { + return a.blockHeight == b.blockHeight && + a.ignoreConflicting == b.ignoreConflicting && + a.ignoreLocked == b.ignoreLocked && + a.skipUTXOHashCheck == b.skipUTXOHashCheck && + utxo.SameUTXOHash(a.spend, b.spend) + }, }) } @@ -2503,7 +2635,7 @@ func (s *Store) retrySpendBatchContext(ctx context.Context, batch []*batchSpend, select { case <-ctx.Done(): for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] deadlock retry cancelled", ctx.Err()) + item.deliver(errors.NewStorageError("[Spend] deadlock retry cancelled", ctx.Err())) } return @@ -2512,7 +2644,7 @@ func (s *Store) retrySpendBatchContext(ctx context.Context, batch []*batchSpend, } // Exhausted retries — send error to all items for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] deadlock persisted after %d retries", maxRetries) + item.deliver(errors.NewStorageError("[Spend] deadlock persisted after %d retries", maxRetries)) } } @@ -2565,7 +2697,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) txn, err := s.db.BeginTx(ctx, nil) if err != nil { for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed to begin transaction", err) + item.deliver(errors.NewStorageError("[Spend] failed to begin transaction", err)) } return false } @@ -2601,7 +2733,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: bulk SELECT outputs", err) + item.deliver(errors.NewStorageError("[Spend] failed: bulk SELECT outputs", err)) } return false } @@ -2617,7 +2749,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: scanning bulk SELECT results", err) + item.deliver(errors.NewStorageError("[Spend] failed: scanning bulk SELECT results", err)) } return false } @@ -2628,7 +2760,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: closing bulk SELECT results", err) + item.deliver(errors.NewStorageError("[Spend] failed: closing bulk SELECT results", err)) } return false } @@ -2871,9 +3003,9 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) } for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } else { - item.errCh <- errors.NewStorageError("[Spend] failed: bulk UPDATE outputs", err) + item.deliver(errors.NewStorageError("[Spend] failed: bulk UPDATE outputs", err)) } } return false @@ -2887,7 +3019,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: scanning bulk UPDATE results", err) + item.deliver(errors.NewStorageError("[Spend] failed: scanning bulk UPDATE results", err)) } return false } @@ -2898,7 +3030,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: closing bulk UPDATE results", err) + item.deliver(errors.NewStorageError("[Spend] failed: closing bulk UPDATE results", err)) } return false } @@ -2950,7 +3082,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: concurrent-idempotent re-check", err) + item.deliver(errors.NewStorageError("[Spend] failed: concurrent-idempotent re-check", err)) } return false } @@ -2962,7 +3094,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: scanning concurrent-idempotent re-check", err) + item.deliver(errors.NewStorageError("[Spend] failed: scanning concurrent-idempotent re-check", err)) } return false } @@ -2977,7 +3109,7 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) return true } for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed: closing concurrent-idempotent re-check", err) + item.deliver(errors.NewStorageError("[Spend] failed: closing concurrent-idempotent re-check", err)) } return false } @@ -3052,9 +3184,9 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) } for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } else { - item.errCh <- errors.NewStorageError("[Spend] failed to recompute DAH for bulk spend fallback", err) + item.deliver(errors.NewStorageError("[Spend] failed to recompute DAH for bulk spend fallback", err)) } } return false @@ -3069,9 +3201,9 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) } for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } else { - item.errCh <- errors.NewStorageError("[Spend] failed to commit transaction", err) + item.deliver(errors.NewStorageError("[Spend] failed to commit transaction", err)) } } return false @@ -3080,9 +3212,9 @@ func (s *Store) trySendSpendBatchBulk(ctx context.Context, batch []*batchSpend) // Signal results for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } else { - item.errCh <- nil // success + item.deliver(nil) // success } } return false @@ -3094,7 +3226,7 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend txn, err := s.db.BeginTx(ctx, nil) if err != nil { for _, item := range batch { - item.errCh <- errors.NewStorageError("[Spend] failed to begin transaction", err) + item.deliver(errors.NewStorageError("[Spend] failed to begin transaction", err)) } return false } @@ -3135,7 +3267,7 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend // Phase 1: SELECT + validate + UPDATE outputs for i, item := range batch { if aborted { - item.errCh <- errors.NewStorageError("[Spend] batch aborted due to previous DB error") + item.deliver(errors.NewStorageError("[Spend] batch aborted due to previous DB error")) continue } @@ -3164,7 +3296,7 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend if isDeadlock(err) { return true // retryable } - item.errCh <- errors.NewStorageError("[Spend] failed: SELECT output %s:%d - %v", spend.TxID, spend.Vout, err) + item.deliver(errors.NewStorageError("[Spend] failed: SELECT output %s:%d - %v", spend.TxID, spend.Vout, err)) aborted = true continue } @@ -3225,14 +3357,14 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend if isDeadlock(err) { return true // retryable } - item.errCh <- errors.NewStorageError("[Spend] failed: UPDATE outputs for %s:%d", spend.TxID, spend.Vout, err) + item.deliver(errors.NewStorageError("[Spend] failed: UPDATE outputs for %s:%d", spend.TxID, spend.Vout, err)) aborted = true continue } affected, err := result.RowsAffected() if err != nil { - item.errCh <- errors.NewStorageError("[Spend] failed getting affected rows for %s:%d", spend.TxID, spend.Vout, err) + item.deliver(errors.NewStorageError("[Spend] failed getting affected rows for %s:%d", spend.TxID, spend.Vout, err)) aborted = true continue } @@ -3261,13 +3393,13 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend if aborted { for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } // Items that already received errors via errCh (DB errors) or // successItems are handled: successItems get rollback error below } for _, item := range successItems { - item.errCh <- errors.NewStorageError("[Spend] batch rolled back due to DB error") + item.deliver(errors.NewStorageError("[Spend] batch rolled back due to DB error")) } return false } @@ -3292,11 +3424,11 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend } for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } } for _, item := range successItems { - item.errCh <- errors.NewStorageError("[Spend] failed to recompute DAH", err) + item.deliver(errors.NewStorageError("[Spend] failed to recompute DAH", err)) } return false } @@ -3309,11 +3441,11 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend } for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } } for _, item := range successItems { - item.errCh <- errors.NewStorageError("[Spend] failed to commit transaction", err) + item.deliver(errors.NewStorageError("[Spend] failed to commit transaction", err)) } return false } @@ -3321,11 +3453,11 @@ func (s *Store) trySendSpendBatchPerRow(ctx context.Context, batch []*batchSpend // Signal results: validation errors and successes for i, item := range batch { if valErr, ok := validationErrors[i]; ok { - item.errCh <- valErr + item.deliver(valErr) } } for _, item := range successItems { - item.errCh <- nil + item.deliver(nil) } return false }