From 753164f224dccf965508732ead39dd07982ef519 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Michael=20B=C3=B6ckli?= <42514703+boecklim@users.noreply.github.com> Date: Thu, 7 Nov 2024 08:44:39 +0100 Subject: [PATCH] feat(ARCO-276): Add traces & attributes (#633) --- cmd/arc/services/metamorph.go | 3 +- internal/blocktx/processor_opts.go | 5 ++ internal/blocktx/store/postgresql/postgres.go | 11 ++- internal/metamorph/grpc_callbacker.go | 7 +- internal/metamorph/processor_options.go | 12 ++- internal/metamorph/server.go | 5 ++ .../metamorph/store/postgresql/postgres.go | 3 + internal/tracing/helper.go | 25 ++++--- .../validator/default/default_validator.go | 22 ++++-- .../default/default_validator_test.go | 31 ++++---- internal/validator/default/helpers.go | 16 +++- .../{heleprs_test.go => helpers_test.go} | 9 ++- internal/validator/validator.go | 6 +- pkg/api/handler/default.go | 53 ++++++++++++- pkg/api/handler/default_test.go | 9 +-- .../internal/TxFinder/cached_tx_finder.go | 55 +++++++++++--- .../TxFinder/cached_tx_finder_test.go | 11 +-- .../handler/internal/TxFinder/tx_finder.go | 75 ++++++++++++++----- pkg/api/status.go | 10 +++ pkg/metamorph/client.go | 6 +- .../mocks/transaction_handler_mock.go | 50 ------------- 21 files changed, 279 insertions(+), 145 deletions(-) rename internal/validator/default/{heleprs_test.go => helpers_test.go} (98%) diff --git a/cmd/arc/services/metamorph.go b/cmd/arc/services/metamorph.go index ad514f302..31de26f1c 100644 --- a/cmd/arc/services/metamorph.go +++ b/cmd/arc/services/metamorph.go @@ -70,7 +70,8 @@ func StartMetamorph(logger *slog.Logger, arcConfig *config.ArcConfig, cacheStore } optsServer = append(optsServer, metamorph.WithTracer(arcConfig.Tracing.KeyValueAttributes...)) - callbackerOpts = append(callbackerOpts, metamorph.WithCallbackerTracer(arcConfig.Tracing.KeyValueAttributes...)) + callbackerOpts = append(callbackerOpts, metamorph.WithTracerCallbacker(arcConfig.Tracing.KeyValueAttributes...)) + processorOpts = append(processorOpts, metamorph.WithTracerProcessor(arcConfig.Tracing.KeyValueAttributes...)) } stopFn := func() { diff --git a/internal/blocktx/processor_opts.go b/internal/blocktx/processor_opts.go index 1a2a4c001..ed1141893 100644 --- a/internal/blocktx/processor_opts.go +++ b/internal/blocktx/processor_opts.go @@ -1,6 +1,7 @@ package blocktx import ( + "runtime" "time" "go.opentelemetry.io/otel/attribute" @@ -66,5 +67,9 @@ func WithTracer(attr ...attribute.KeyValue) func(s *Processor) { if len(attr) > 0 { p.tracingAttributes = append(p.tracingAttributes, attr...) } + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) + } } } diff --git a/internal/blocktx/store/postgresql/postgres.go b/internal/blocktx/store/postgresql/postgres.go index f0bde09f5..53fbf7b50 100644 --- a/internal/blocktx/store/postgresql/postgres.go +++ b/internal/blocktx/store/postgresql/postgres.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "errors" + "runtime" "time" _ "github.com/lib/pq" // nolint: revive // required for postgres driver @@ -32,10 +33,14 @@ func WithNow(nowFunc func() time.Time) func(*PostgreSQL) { } func WithTracer(attr ...attribute.KeyValue) func(s *PostgreSQL) { - return func(m *PostgreSQL) { - m.tracingEnabled = true + return func(p *PostgreSQL) { + p.tracingEnabled = true if len(attr) > 0 { - m.tracingAttributes = append(m.tracingAttributes, attr...) + p.tracingAttributes = append(p.tracingAttributes, attr...) + } + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) } } } diff --git a/internal/metamorph/grpc_callbacker.go b/internal/metamorph/grpc_callbacker.go index e86c2b5f7..e5235b2ad 100644 --- a/internal/metamorph/grpc_callbacker.go +++ b/internal/metamorph/grpc_callbacker.go @@ -3,6 +3,7 @@ package metamorph import ( "context" "log/slog" + "runtime" "go.opentelemetry.io/otel/attribute" @@ -19,12 +20,16 @@ type GrpcCallbacker struct { tracingAttributes []attribute.KeyValue } -func WithCallbackerTracer(attr ...attribute.KeyValue) func(*GrpcCallbacker) { +func WithTracerCallbacker(attr ...attribute.KeyValue) func(*GrpcCallbacker) { return func(p *GrpcCallbacker) { p.tracingEnabled = true if len(attr) > 0 { p.tracingAttributes = append(p.tracingAttributes, attr...) } + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) + } } } diff --git a/internal/metamorph/processor_options.go b/internal/metamorph/processor_options.go index e0efeb10a..b1b278bd1 100644 --- a/internal/metamorph/processor_options.go +++ b/internal/metamorph/processor_options.go @@ -2,8 +2,11 @@ package metamorph import ( "log/slog" + "runtime" "time" + "go.opentelemetry.io/otel/attribute" + "github.com/bitcoin-sv/arc/internal/blocktx/blocktx_api" "github.com/bitcoin-sv/arc/internal/metamorph/metamorph_api" ) @@ -134,8 +137,15 @@ func WithMinimumHealthyConnections(minimumHealthyConnections int) func(*Processo } } -func WithProcessorTracer() func(*Processor) { +func WithTracerProcessor(attr ...attribute.KeyValue) func(*Processor) { return func(p *Processor) { p.tracingEnabled = true + if len(attr) > 0 { + p.tracingAttributes = append(p.tracingAttributes, attr...) + } + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) + } } } diff --git a/internal/metamorph/server.go b/internal/metamorph/server.go index 14efa528d..add6e0700 100644 --- a/internal/metamorph/server.go +++ b/internal/metamorph/server.go @@ -5,6 +5,7 @@ import ( "encoding/hex" "errors" "log/slog" + "runtime" "strings" "sync" "time" @@ -81,6 +82,10 @@ func WithTracer(attr ...attribute.KeyValue) func(s *Server) { if len(attr) > 0 { s.tracingAttributes = append(s.tracingAttributes, attr...) } + _, file, _, ok := runtime.Caller(1) + if ok { + s.tracingAttributes = append(s.tracingAttributes, attribute.String("file", file)) + } } } diff --git a/internal/metamorph/store/postgresql/postgres.go b/internal/metamorph/store/postgresql/postgres.go index f63aa3d25..2165029bb 100644 --- a/internal/metamorph/store/postgresql/postgres.go +++ b/internal/metamorph/store/postgresql/postgres.go @@ -240,6 +240,9 @@ func (p *PostgreSQL) GetRawTxs(ctx context.Context, hashes [][]byte) ([][]byte, } func (p *PostgreSQL) GetMany(ctx context.Context, keys [][]byte) ([]*store.Data, error) { + ctx, span := tracing.StartTracing(ctx, "GetMany", p.tracingEnabled, p.tracingAttributes...) + defer tracing.EndTracing(span) + const q = ` SELECT stored_at diff --git a/internal/tracing/helper.go b/internal/tracing/helper.go index 3f76f9cb1..500ac89b2 100644 --- a/internal/tracing/helper.go +++ b/internal/tracing/helper.go @@ -9,22 +9,23 @@ import ( ) func StartTracing(ctx context.Context, spanName string, tracingEnabled bool, attributes ...attribute.KeyValue) (context.Context, trace.Span) { - if tracingEnabled { - var span trace.Span - tracer := otel.Tracer("") - if tracer == nil { - return ctx, nil - } + if !tracingEnabled { + return ctx, nil + } - if len(attributes) > 0 { - ctx, span = tracer.Start(ctx, spanName, trace.WithAttributes(attributes...)) - return ctx, span - } + var span trace.Span + tracer := otel.Tracer("") + if tracer == nil { + return ctx, nil + } - ctx, span = tracer.Start(ctx, spanName) + if len(attributes) > 0 { + ctx, span = tracer.Start(ctx, spanName, trace.WithAttributes(attributes...)) return ctx, span } - return ctx, nil + + ctx, span = tracer.Start(ctx, spanName) + return ctx, span } func EndTracing(span trace.Span) { diff --git a/internal/validator/default/default_validator.go b/internal/validator/default/default_validator.go index f53354ed2..fabd75fff 100644 --- a/internal/validator/default/default_validator.go +++ b/internal/validator/default/default_validator.go @@ -5,11 +5,14 @@ import ( "errors" "fmt" + sdkTx "github.com/bitcoin-sv/go-sdk/transaction" + "github.com/ordishs/go-bitcoin" + "go.opentelemetry.io/otel/attribute" + "github.com/bitcoin-sv/arc/internal/fees" + "github.com/bitcoin-sv/arc/internal/tracing" "github.com/bitcoin-sv/arc/internal/validator" "github.com/bitcoin-sv/arc/pkg/api" - sdkTx "github.com/bitcoin-sv/go-sdk/transaction" - "github.com/ordishs/go-bitcoin" ) var ( @@ -28,11 +31,14 @@ func New(policy *bitcoin.Settings, finder validator.TxFinderI) *DefaultValidator } } -func (v *DefaultValidator) ValidateTransaction(ctx context.Context, tx *sdkTx.Transaction, feeValidation validator.FeeValidation, scriptValidation validator.ScriptValidation) error { //nolint:funlen - mostly comments +func (v *DefaultValidator) ValidateTransaction(ctx context.Context, tx *sdkTx.Transaction, feeValidation validator.FeeValidation, scriptValidation validator.ScriptValidation, tracingEnabled bool, tracingAttributes ...attribute.KeyValue) error { //nolint:funlen - mostly comments + ctx, span := tracing.StartTracing(ctx, "ValidateTransaction", tracingEnabled, tracingAttributes...) + defer tracing.EndTracing(span) + // 0) Check whether we have a complete transaction in extended format, with all input information // we cannot check the satoshi input, OP_RETURN is allowed 0 satoshis if needsExtension(tx, feeValidation, scriptValidation) { - err := extendTx(ctx, v.txFinder, tx) + err := extendTx(ctx, v.txFinder, tx, tracingEnabled, tracingAttributes...) if err != nil { return validator.NewError(err, api.ErrStatusTxFormat) } @@ -52,7 +58,7 @@ func (v *DefaultValidator) ValidateTransaction(ctx context.Context, tx *sdkTx.Tr return err } case validator.CumulativeFeeValidation: - if err := cumulativeCheckFees(ctx, v.txFinder, tx, api.FeesToFeeModel(v.policy.MinMiningTxFee)); err != nil { + if err := cumulativeCheckFees(ctx, v.txFinder, tx, api.FeesToFeeModel(v.policy.MinMiningTxFee), tracingEnabled, tracingAttributes...); err != nil { return err } case validator.NoneFeeValidation: @@ -108,8 +114,10 @@ func standardCheckFees(tx *sdkTx.Transaction, feeModel sdkTx.FeeModel) *validato return nil } -func cumulativeCheckFees(ctx context.Context, txFinder validator.TxFinderI, tx *sdkTx.Transaction, feeModel *fees.SatoshisPerKilobyte) *validator.Error { - txSet, err := getUnminedAncestors(ctx, txFinder, tx) +func cumulativeCheckFees(ctx context.Context, txFinder validator.TxFinderI, tx *sdkTx.Transaction, feeModel *fees.SatoshisPerKilobyte, tracingEnabled bool, tracingAttributes ...attribute.KeyValue) *validator.Error { + ctx, span := tracing.StartTracing(ctx, "cumulativeCheckFees", tracingEnabled, tracingAttributes...) + defer tracing.EndTracing(span) + txSet, err := getUnminedAncestors(ctx, txFinder, tx, tracingEnabled, tracingAttributes...) if err != nil { e := fmt.Errorf("getting all unmined ancestors for CFV failed. reason: %w. found: %d", err, len(txSet)) return validator.NewError(e, api.ErrStatusCumulativeFees) diff --git a/internal/validator/default/default_validator_test.go b/internal/validator/default/default_validator_test.go index adf22dba5..62354e895 100644 --- a/internal/validator/default/default_validator_test.go +++ b/internal/validator/default/default_validator_test.go @@ -7,17 +7,18 @@ import ( "os" "testing" + "github.com/bitcoin-sv/go-sdk/script" + sdkTx "github.com/bitcoin-sv/go-sdk/transaction" + "github.com/ordishs/go-bitcoin" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "github.com/bitcoin-sv/arc/internal/fees" "github.com/bitcoin-sv/arc/internal/testdata" validation "github.com/bitcoin-sv/arc/internal/validator" fixture "github.com/bitcoin-sv/arc/internal/validator/default/testdata" "github.com/bitcoin-sv/arc/internal/validator/mocks" "github.com/bitcoin-sv/arc/pkg/api" - "github.com/bitcoin-sv/go-sdk/script" - sdkTx "github.com/bitcoin-sv/go-sdk/transaction" - "github.com/ordishs/go-bitcoin" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" ) var validLockingScript = &script.Script{ @@ -40,7 +41,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.NoError(t, actualError) @@ -54,7 +55,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.Error(t, actualError, "Validation should have returned an error") @@ -71,7 +72,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.Error(t, actualError) @@ -85,7 +86,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.NoError(t, actualError) @@ -107,7 +108,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.NoError(t, actualError, "Failed to validate tx %d", txIndex) @@ -141,7 +142,7 @@ func TestValidator(t *testing.T) { sut := New(policy, nil) // when - actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.NoError(t, actualError, "Failed to validate tx") @@ -161,7 +162,7 @@ func TestValidator(t *testing.T) { sut := New(getPolicy(5), &txFinder) // when - actualError := sut.ValidateTransaction(context.TODO(), rawTx, validation.StandardFeeValidation, validation.StandardScriptValidation) + actualError := sut.ValidateTransaction(context.TODO(), rawTx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then require.NoError(t, actualError) @@ -287,7 +288,7 @@ func BenchmarkValidator(b *testing.B) { sut := New(policy, nil) for i := 0; i < b.N; i++ { - _ = sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + _ = sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) } } @@ -299,7 +300,7 @@ func TestFeeCalculation(t *testing.T) { sut := New(policy, nil) // when - err = sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation) + err = sut.ValidateTransaction(context.TODO(), tx, validation.StandardFeeValidation, validation.StandardScriptValidation, false) // then t.Log(err) @@ -483,7 +484,7 @@ func TestCumulativeCheckFees(t *testing.T) { tx, _ := sdkTx.NewTransactionFromHex(tc.hex) // when - actualError := cumulativeCheckFees(context.TODO(), &txFinder, tx, tc.feeModel) + actualError := cumulativeCheckFees(context.TODO(), &txFinder, tx, tc.feeModel, false) // then if tc.expectedErr == nil { diff --git a/internal/validator/default/helpers.go b/internal/validator/default/helpers.go index 239f4f58f..b4fa54350 100644 --- a/internal/validator/default/helpers.go +++ b/internal/validator/default/helpers.go @@ -5,8 +5,11 @@ import ( "errors" "fmt" - "github.com/bitcoin-sv/arc/internal/validator" sdkTx "github.com/bitcoin-sv/go-sdk/transaction" + "go.opentelemetry.io/otel/attribute" + + "github.com/bitcoin-sv/arc/internal/tracing" + "github.com/bitcoin-sv/arc/internal/validator" ) var ( @@ -14,7 +17,10 @@ var ( ErrFailedToGetRawTxs = errors.New("failed to get raw transactions for parent") ) -func extendTx(ctx context.Context, f validator.TxFinderI, rawTx *sdkTx.Transaction) error { +func extendTx(ctx context.Context, f validator.TxFinderI, rawTx *sdkTx.Transaction, tracingEnabled bool, tracingAttributes ...attribute.KeyValue) error { + ctx, span := tracing.StartTracing(ctx, "extendTx", tracingEnabled, tracingAttributes...) + defer tracing.EndTracing(span) + // potential improvement: implement version for the rawTx with only one input // get distinct parents @@ -69,7 +75,9 @@ func extendTx(ctx context.Context, f validator.TxFinderI, rawTx *sdkTx.Transacti } // getUnminedAncestors returns unmined ancestors with data necessary to perform Deep Fee validation -func getUnminedAncestors(ctx context.Context, w validator.TxFinderI, tx *sdkTx.Transaction) (map[string]*sdkTx.Transaction, error) { +func getUnminedAncestors(ctx context.Context, w validator.TxFinderI, tx *sdkTx.Transaction, tracingEnabled bool, tracingAttributes ...attribute.KeyValue) (map[string]*sdkTx.Transaction, error) { + ctx, span := tracing.StartTracing(ctx, "getUnminedAncestors", tracingEnabled, tracingAttributes...) + defer tracing.EndTracing(span) unmindedAncestorsSet := make(map[string]*sdkTx.Transaction) // get distinct parents @@ -130,7 +138,7 @@ func getUnminedAncestors(ctx context.Context, w validator.TxFinderI, tx *sdkTx.T unmindedAncestorsSet[p.TxID] = bTx // get parent ancestors - parentAncestorsSet, err := getUnminedAncestors(ctx, w, bTx) + parentAncestorsSet, err := getUnminedAncestors(ctx, w, bTx, tracingEnabled, tracingAttributes...) for aID, aTx := range parentAncestorsSet { unmindedAncestorsSet[aID] = aTx } diff --git a/internal/validator/default/heleprs_test.go b/internal/validator/default/helpers_test.go similarity index 98% rename from internal/validator/default/heleprs_test.go rename to internal/validator/default/helpers_test.go index 536de354d..ba10dd6e4 100644 --- a/internal/validator/default/heleprs_test.go +++ b/internal/validator/default/helpers_test.go @@ -4,11 +4,12 @@ import ( "context" "testing" + sdkTx "github.com/bitcoin-sv/go-sdk/transaction" + "github.com/stretchr/testify/require" + "github.com/bitcoin-sv/arc/internal/validator" "github.com/bitcoin-sv/arc/internal/validator/default/testdata" "github.com/bitcoin-sv/arc/internal/validator/mocks" - sdkTx "github.com/bitcoin-sv/go-sdk/transaction" - "github.com/stretchr/testify/require" ) func TestDefaultValidator_helpers_extendTx(t *testing.T) { @@ -55,7 +56,7 @@ func TestDefaultValidator_helpers_extendTx(t *testing.T) { tx, _ := sdkTx.NewTransactionFromHex(tc.txHex) // when - err := extendTx(context.TODO(), &txFinder, tx) + err := extendTx(context.TODO(), &txFinder, tx, false) // then require.Equal(t, tc.expectedErr, err) @@ -153,7 +154,7 @@ func TestDefaultValidator_helpers_getUnminedAncestors(t *testing.T) { tx, _ := sdkTx.NewTransactionFromHex(tc.txHex) // when - res, err := getUnminedAncestors(context.TODO(), &txFinder, tx) + res, err := getUnminedAncestors(context.TODO(), &txFinder, tx, false) // then require.Equal(t, tc.expectedErr, err) diff --git a/internal/validator/validator.go b/internal/validator/validator.go index 5d916c8fd..b41586823 100644 --- a/internal/validator/validator.go +++ b/internal/validator/validator.go @@ -3,8 +3,10 @@ package validator import ( "context" - "github.com/bitcoin-sv/arc/internal/beef" sdkTx "github.com/bitcoin-sv/go-sdk/transaction" + "go.opentelemetry.io/otel/attribute" + + "github.com/bitcoin-sv/arc/internal/beef" ) type FeeValidation byte @@ -25,7 +27,7 @@ const ( ) type DefaultValidator interface { - ValidateTransaction(ctx context.Context, tx *sdkTx.Transaction, feeValidation FeeValidation, scriptValidation ScriptValidation) error + ValidateTransaction(ctx context.Context, tx *sdkTx.Transaction, feeValidation FeeValidation, scriptValidation ScriptValidation, tracingEnabled bool, tracingAttributes ...attribute.KeyValue) error } type BeefValidator interface { diff --git a/pkg/api/handler/default.go b/pkg/api/handler/default.go index 213386f68..ed4eddedb 100644 --- a/pkg/api/handler/default.go +++ b/pkg/api/handler/default.go @@ -7,6 +7,7 @@ import ( "log/slog" "net/http" "net/url" + "runtime" "strings" "time" @@ -75,6 +76,10 @@ func WithTracer(attr ...attribute.KeyValue) func(s *ArcDefaultHandler) { if len(attr) > 0 { a.tracingAttributes = append(a.tracingAttributes, attr...) } + _, file, _, ok := runtime.Caller(1) + if ok { + a.tracingAttributes = append(a.tracingAttributes, attribute.String("file", file)) + } } } @@ -96,7 +101,6 @@ func NewDefault( wocClient = woc_client.New(false) } - finder := txfinder.NewCached(transactionHandler, peerRPCConfig, wocClient, logger) mr := merkleverifier.New(merkleRootsVerifier) handler := &ArcDefaultHandler{ @@ -104,7 +108,6 @@ func NewDefault( NodePolicy: policy, logger: logger, now: time.Now, - txFinder: &finder, mrVerifier: mr, } @@ -112,6 +115,12 @@ func NewDefault( for _, opt := range opts { opt(handler) } + var finderOpts []func(f *txfinder.CachedFinder) + if handler.tracingEnabled { + finderOpts = append(finderOpts, txfinder.WithTracerCachedFinder(handler.tracingAttributes...)) + } + + handler.txFinder = txfinder.NewCached(transactionHandler, peerRPCConfig, wocClient, logger, finderOpts...) return handler, nil } @@ -188,12 +197,21 @@ func (m ArcDefaultHandler) POSTTransaction(ctx echo.Context, params api.POSTTran txHex, err := parseTransactionFromRequest(ctx.Request()) if err != nil { e := api.NewErrorFields(api.ErrStatusBadRequest, fmt.Sprintf("error parsing transaction from request: %s", err.Error())) + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } + return ctx.JSON(e.Status, e) } txs, successes, fails, e := m.processTransactions(reqCtx, txHex, transactionOptions) if e != nil { + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } // if an error is returned, the processing failed return ctx.JSON(e.Status, e) } @@ -201,6 +219,10 @@ func (m ArcDefaultHandler) POSTTransaction(ctx echo.Context, params api.POSTTran if len(fails) > 0 { // if a fail result is returned, the processing/validation failed e = fails[0] + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } @@ -208,6 +230,11 @@ func (m ArcDefaultHandler) POSTTransaction(ctx echo.Context, params api.POSTTran ctx.SetRequest(ctx.Request().WithContext(sizingCtx)) response := successes[0] + + if span != nil { + span.SetAttributes(attribute.String("status", string(response.TxStatus))) + } + return ctx.JSON(response.Status, response) } @@ -225,11 +252,19 @@ func (m ArcDefaultHandler) GETTransactionStatus(ctx echo.Context, id string) err } e := api.NewErrorFields(api.ErrStatusGeneric, err.Error()) + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } if tx == nil { e := api.NewErrorFields(api.ErrStatusNotFound, "failed to find transaction") + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } @@ -255,17 +290,29 @@ func (m ArcDefaultHandler) POSTTransactions(ctx echo.Context, params api.POSTTra transactionOptions, err := getTransactionsOptions(params, m.rejectedCallbackURLSubstrings) if err != nil { e := api.NewErrorFields(api.ErrStatusBadRequest, err.Error()) + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } txsHex, err := parseTransactionsFromRequest(ctx.Request()) if err != nil { e := api.NewErrorFields(api.ErrStatusBadRequest, fmt.Sprintf("error parsing transaction from request: %s", err.Error())) + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } txs, successes, fails, e := m.processTransactions(reqCtx, txsHex, transactionOptions) if e != nil { + if span != nil { + attr := e.GetSpanAttributes() + span.SetAttributes(attr...) + } return ctx.JSON(e.Status, e) } @@ -492,7 +539,7 @@ func (m ArcDefaultHandler) validateEFTransaction(ctx context.Context, txValidato feeOpts, scriptOpts := toValidationOpts(options) - if err := txValidator.ValidateTransaction(ctx, transaction, feeOpts, scriptOpts); err != nil { + if err := txValidator.ValidateTransaction(ctx, transaction, feeOpts, scriptOpts, m.tracingEnabled, m.tracingAttributes...); err != nil { statusCode, arcError := m.handleError(ctx, transaction, err) m.logger.ErrorContext(ctx, "failed to validate transaction", slog.String("id", transaction.TxID()), slog.Int("status", int(statusCode)), slog.String("err", err.Error())) return arcError diff --git a/pkg/api/handler/default_test.go b/pkg/api/handler/default_test.go index ac8828f07..3eb0630e4 100644 --- a/pkg/api/handler/default_test.go +++ b/pkg/api/handler/default_test.go @@ -7,7 +7,6 @@ import ( "encoding/json" "errors" "fmt" - defaultvalidator "github.com/bitcoin-sv/arc/internal/validator/default" "io" "log/slog" "net/http" @@ -17,6 +16,8 @@ import ( "testing" "time" + defaultvalidator "github.com/bitcoin-sv/arc/internal/validator/default" + sdkTx "github.com/bitcoin-sv/go-sdk/transaction" "github.com/labstack/echo/v4" "github.com/ordishs/go-bitcoin" @@ -800,9 +801,6 @@ func TestPOSTTransactions(t *testing.T) { //nolint:funlen GetTransactionsFunc: func(_ context.Context, _ []string) ([]*metamorph.Transaction, error) { return nil, metamorph.ErrTransactionNotFound }, - GetTransactionFunc: func(_ context.Context, _ string) ([]byte, error) { - return nil, metamorph.ErrTransactionNotFound - }, HealthFunc: func(_ context.Context) error { return nil @@ -1015,9 +1013,6 @@ func TestPOSTTransactions(t *testing.T) { //nolint:funlen }, }, nil }, - GetTransactionFunc: func(_ context.Context, _ string) ([]byte, error) { - return validTxParentBytes, nil - }, SubmitTransactionsFunc: func(_ context.Context, txs sdkTx.Transactions, _ *metamorph.TransactionOptions) ([]*metamorph.TransactionStatus, error) { var res []*metamorph.TransactionStatus diff --git a/pkg/api/handler/internal/TxFinder/cached_tx_finder.go b/pkg/api/handler/internal/TxFinder/cached_tx_finder.go index c99f115e7..86eba3719 100644 --- a/pkg/api/handler/internal/TxFinder/cached_tx_finder.go +++ b/pkg/api/handler/internal/TxFinder/cached_tx_finder.go @@ -3,13 +3,17 @@ package txfinder import ( "context" "log/slog" + "runtime" "time" + "github.com/patrickmn/go-cache" + "go.opentelemetry.io/otel/attribute" + "github.com/bitcoin-sv/arc/config" + "github.com/bitcoin-sv/arc/internal/tracing" "github.com/bitcoin-sv/arc/internal/validator" "github.com/bitcoin-sv/arc/internal/woc_client" "github.com/bitcoin-sv/arc/pkg/metamorph" - "github.com/patrickmn/go-cache" ) const ( @@ -18,25 +22,54 @@ const ( ) type CachedFinder struct { - f *Finder - s *cache.Cache + finder *Finder + cacheStore *cache.Cache + tracingEnabled bool + tracingAttributes []attribute.KeyValue } -func NewCached(th metamorph.TransactionHandler, pc *config.PeerRPCConfig, w *woc_client.WocClient, l *slog.Logger) CachedFinder { - f := New(th, pc, w, l) - return CachedFinder{ - f: &f, - s: cache.New(cacheExpiration, cacheCleanup), +func WithTracerCachedFinder(attr ...attribute.KeyValue) func(s *CachedFinder) { + return func(p *CachedFinder) { + p.tracingEnabled = true + if len(attr) > 0 { + p.tracingAttributes = append(p.tracingAttributes, attr...) + } + + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) + } } } +func NewCached(th metamorph.TransactionHandler, pc *config.PeerRPCConfig, w *woc_client.WocClient, l *slog.Logger, opts ...func(f *CachedFinder)) CachedFinder { + c := CachedFinder{ + cacheStore: cache.New(cacheExpiration, cacheCleanup), + } + + for _, opt := range opts { + opt(&c) + } + var finderOpts []func(f *Finder) + if c.tracingEnabled { + finderOpts = append(finderOpts, WithTracerFinder(c.tracingAttributes...)) + } + + c.finder = New(th, pc, w, l, finderOpts...) + + return c +} + func (f CachedFinder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, ids []string) ([]validator.RawTx, error) { + ctx, span := tracing.StartTracing(ctx, "CachedFinder_GetRawTxs", f.tracingEnabled, f.tracingAttributes...) + defer tracing.EndTracing(span) + cachedTxs := make([]validator.RawTx, 0, len(ids)) var toFindIDs []string // check cache for _, id := range ids { - value, found := f.s.Get(id) + value, found := f.cacheStore.Get(id) if found { cachedTxs = append(cachedTxs, value.(validator.RawTx)) } else { @@ -49,14 +82,14 @@ func (f CachedFinder) GetRawTxs(ctx context.Context, source validator.FindSource } // find txs - foundTxs, err := f.f.GetRawTxs(ctx, source, toFindIDs) + foundTxs, err := f.finder.GetRawTxs(ctx, source, toFindIDs) if err != nil { return nil, err } // update cache for _, tx := range foundTxs { - f.s.Set(tx.TxID, tx, cacheExpiration) + f.cacheStore.Set(tx.TxID, tx, cacheExpiration) } return append(cachedTxs, foundTxs...), nil diff --git a/pkg/api/handler/internal/TxFinder/cached_tx_finder_test.go b/pkg/api/handler/internal/TxFinder/cached_tx_finder_test.go index ed8a5e229..1d54f3fab 100644 --- a/pkg/api/handler/internal/TxFinder/cached_tx_finder_test.go +++ b/pkg/api/handler/internal/TxFinder/cached_tx_finder_test.go @@ -5,11 +5,12 @@ import ( "testing" "time" + "github.com/patrickmn/go-cache" + "github.com/stretchr/testify/require" + "github.com/bitcoin-sv/arc/internal/validator" "github.com/bitcoin-sv/arc/pkg/metamorph" "github.com/bitcoin-sv/arc/pkg/metamorph/mocks" - "github.com/patrickmn/go-cache" - "github.com/stretchr/testify/require" ) // Mocked data for RawTx @@ -52,10 +53,10 @@ func TestCachedFinder_GetRawTxs_AllFromCache(t *testing.T) { } sut := CachedFinder{ - f: &Finder{ - th: thMq, + finder: &Finder{ + transactionHandler: thMq, }, - s: c, + cacheStore: c, } // when diff --git a/pkg/api/handler/internal/TxFinder/tx_finder.go b/pkg/api/handler/internal/TxFinder/tx_finder.go index efc1a17e9..c1ea47228 100644 --- a/pkg/api/handler/internal/TxFinder/tx_finder.go +++ b/pkg/api/handler/internal/TxFinder/tx_finder.go @@ -7,22 +7,42 @@ import ( "fmt" "log/slog" "net/url" + "runtime" + + "github.com/ordishs/go-bitcoin" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/bitcoin-sv/arc/config" + "github.com/bitcoin-sv/arc/internal/tracing" "github.com/bitcoin-sv/arc/internal/validator" "github.com/bitcoin-sv/arc/internal/woc_client" "github.com/bitcoin-sv/arc/pkg/metamorph" - "github.com/ordishs/go-bitcoin" ) type Finder struct { - th metamorph.TransactionHandler - n *bitcoin.Bitcoind - w *woc_client.WocClient - l *slog.Logger + transactionHandler metamorph.TransactionHandler + bitcoinClient *bitcoin.Bitcoind + wocClient *woc_client.WocClient + logger *slog.Logger + tracingEnabled bool + tracingAttributes []attribute.KeyValue } -func New(th metamorph.TransactionHandler, pc *config.PeerRPCConfig, w *woc_client.WocClient, l *slog.Logger) Finder { +func WithTracerFinder(attr ...attribute.KeyValue) func(s *Finder) { + return func(p *Finder) { + p.tracingEnabled = true + if len(attr) > 0 { + p.tracingAttributes = append(p.tracingAttributes, attr...) + } + _, file, _, ok := runtime.Caller(1) + if ok { + p.tracingAttributes = append(p.tracingAttributes, attribute.String("file", file)) + } + } +} + +func New(th metamorph.TransactionHandler, pc *config.PeerRPCConfig, w *woc_client.WocClient, l *slog.Logger, opts ...func(f *Finder)) *Finder { l = l.With(slog.String("module", "tx-finder")) var n *bitcoin.Bitcoind @@ -39,22 +59,34 @@ func New(th metamorph.TransactionHandler, pc *config.PeerRPCConfig, w *woc_clien } } - return Finder{ - th: th, - n: n, - w: w, - l: l, + f := &Finder{ + transactionHandler: th, + bitcoinClient: n, + wocClient: w, + logger: l, + } + + for _, opt := range opts { + opt(f) } + + return f } func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, ids []string) ([]validator.RawTx, error) { + ctx, span := tracing.StartTracing(ctx, "Finder_GetRawTxs", f.tracingEnabled, f.tracingAttributes...) + defer tracing.EndTracing(span) + // NOTE: we can ignore ALL errors from providers, if one returns err we go to another foundTxs := make([]validator.RawTx, 0, len(ids)) var remainingIDs []string // first get transactions from the handler if source.Has(validator.SourceTransactionHandler) { - txs, thErr := f.th.GetTransactions(ctx, ids) + var thGetRawTxSpan trace.Span + ctx, thGetRawTxSpan = tracing.StartTracing(ctx, "TransactionHandler_GetRawTxs", f.tracingEnabled, f.tracingAttributes...) + txs, thErr := f.transactionHandler.GetTransactions(ctx, ids) + tracing.EndTracing(thGetRawTxSpan) for _, tx := range txs { rt := validator.RawTx{ TxID: tx.TxID, @@ -68,7 +100,7 @@ func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, // add remaining ids remainingIDs = outerRightJoin(foundTxs, ids) if len(remainingIDs) > 0 || thErr != nil { - f.l.WarnContext(ctx, "couldn't find transactions in TransactionHandler", slog.Any("ids", remainingIDs), slog.Any("source-err", thErr)) + f.logger.WarnContext(ctx, "couldn't find transactions in TransactionHandler", slog.Any("ids", remainingIDs), slog.Any("source-err", thErr)) } ids = remainingIDs[:] @@ -76,10 +108,13 @@ func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, } // try to get remaining txs from the node - if source.Has(validator.SourceNodes) && f.n != nil { + if source.Has(validator.SourceNodes) && f.bitcoinClient != nil { var nErr error for _, id := range ids { - nTx, err := f.n.GetRawTransaction(id) + var bitcoinGetRawTxSpan trace.Span + ctx, bitcoinGetRawTxSpan = tracing.StartTracing(ctx, "Bitcoind_GetRawTxs", f.tracingEnabled, f.tracingAttributes...) + nTx, err := f.bitcoinClient.GetRawTransaction(id) + tracing.EndTracing(bitcoinGetRawTxSpan) if err != nil { nErr = errors.Join(nErr, fmt.Errorf("%s: %w", id, err)) } @@ -96,7 +131,7 @@ func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, } if len(remainingIDs) > 0 || nErr != nil { - f.l.WarnContext(ctx, "couldn't find transactions in node", slog.Any("ids", remainingIDs), slog.Any("source-error", nErr)) + f.logger.WarnContext(ctx, "couldn't find transactions in node", slog.Any("ids", remainingIDs), slog.Any("source-error", nErr)) } ids = remainingIDs[:] @@ -105,7 +140,11 @@ func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, // at last try the WoC if source.Has(validator.SourceWoC) && len(ids) > 0 { - wocTxs, wocErr := f.w.GetRawTxs(ctx, ids) + var wocSpan trace.Span + ctx, wocSpan = tracing.StartTracing(ctx, "WocClient_GetRawTxs", f.tracingEnabled, f.tracingAttributes...) + wocTxs, wocErr := f.wocClient.GetRawTxs(ctx, ids) + defer tracing.EndTracing(wocSpan) + for _, wTx := range wocTxs { if wTx.Error != "" { wocErr = errors.Join(wocErr, fmt.Errorf("returned error data tx %s: %s", wTx.TxID, wTx.Error)) @@ -123,7 +162,7 @@ func (f Finder) GetRawTxs(ctx context.Context, source validator.FindSourceFlag, // add remaining ids remainingIDs = outerRightJoin(foundTxs, ids) if len(remainingIDs) > 0 || wocErr != nil { - f.l.WarnContext(ctx, "couldn't find transactions in WoC", slog.Any("ids", remainingIDs), slog.Any("source-error", wocErr)) + f.logger.WarnContext(ctx, "couldn't find transactions in WoC", slog.Any("ids", remainingIDs), slog.Any("source-error", wocErr)) } } diff --git a/pkg/api/status.go b/pkg/api/status.go index fb29e8393..ff8a3fc25 100644 --- a/pkg/api/status.go +++ b/pkg/api/status.go @@ -2,6 +2,8 @@ package api import ( "strconv" + + "go.opentelemetry.io/otel/attribute" ) type StatusCode int @@ -29,6 +31,14 @@ const ( ErrStatusTxSize StatusCode = 474 ) +func (e *ErrorFields) GetSpanAttributes() []attribute.KeyValue { + attr := []attribute.KeyValue{attribute.Int("code", e.Status)} + if e.ExtraInfo != nil { + attr = append(attr, attribute.String("extraInfo", *e.ExtraInfo)) + } + return attr +} + func NewErrorFields(status StatusCode, extraInfo string) *ErrorFields { emptyString := "" errFields := ErrorFields{ diff --git a/pkg/metamorph/client.go b/pkg/metamorph/client.go index f352691d7..10364ce6f 100644 --- a/pkg/metamorph/client.go +++ b/pkg/metamorph/client.go @@ -5,6 +5,7 @@ import ( "errors" "log/slog" "os" + "runtime" "strings" "time" @@ -26,7 +27,6 @@ var ( type TransactionHandler interface { Health(ctx context.Context) error - GetTransaction(ctx context.Context, txID string) ([]byte, error) GetTransactions(ctx context.Context, txIDs []string) ([]*Transaction, error) GetTransactionStatus(ctx context.Context, txID string) (*TransactionStatus, error) SubmitTransaction(ctx context.Context, tx *sdkTx.Transaction, options *TransactionOptions) (*TransactionStatus, error) @@ -84,6 +84,10 @@ func WithTracer(attr ...attribute.KeyValue) func(s *Metamorph) { if len(attr) > 0 { m.tracingAttributes = append(m.tracingAttributes, attr...) } + _, file, _, ok := runtime.Caller(1) + if ok { + m.tracingAttributes = append(m.tracingAttributes, attribute.String("file", file)) + } } } diff --git a/pkg/metamorph/mocks/transaction_handler_mock.go b/pkg/metamorph/mocks/transaction_handler_mock.go index d7ead0d97..d0a4d8a2e 100644 --- a/pkg/metamorph/mocks/transaction_handler_mock.go +++ b/pkg/metamorph/mocks/transaction_handler_mock.go @@ -20,9 +20,6 @@ var _ metamorph.TransactionHandler = &TransactionHandlerMock{} // // // make and configure a mocked metamorph.TransactionHandler // mockedTransactionHandler := &TransactionHandlerMock{ -// GetTransactionFunc: func(ctx context.Context, txID string) ([]byte, error) { -// panic("mock out the GetTransaction method") -// }, // GetTransactionStatusFunc: func(ctx context.Context, txID string) (*metamorph.TransactionStatus, error) { // panic("mock out the GetTransactionStatus method") // }, @@ -45,9 +42,6 @@ var _ metamorph.TransactionHandler = &TransactionHandlerMock{} // // } type TransactionHandlerMock struct { - // GetTransactionFunc mocks the GetTransaction method. - GetTransactionFunc func(ctx context.Context, txID string) ([]byte, error) - // GetTransactionStatusFunc mocks the GetTransactionStatus method. GetTransactionStatusFunc func(ctx context.Context, txID string) (*metamorph.TransactionStatus, error) @@ -65,13 +59,6 @@ type TransactionHandlerMock struct { // calls tracks calls to the methods. calls struct { - // GetTransaction holds details about calls to the GetTransaction method. - GetTransaction []struct { - // Ctx is the ctx argument value. - Ctx context.Context - // TxID is the txID argument value. - TxID string - } // GetTransactionStatus holds details about calls to the GetTransactionStatus method. GetTransactionStatus []struct { // Ctx is the ctx argument value. @@ -110,7 +97,6 @@ type TransactionHandlerMock struct { Options *metamorph.TransactionOptions } } - lockGetTransaction sync.RWMutex lockGetTransactionStatus sync.RWMutex lockGetTransactions sync.RWMutex lockHealth sync.RWMutex @@ -118,42 +104,6 @@ type TransactionHandlerMock struct { lockSubmitTransactions sync.RWMutex } -// GetTransaction calls GetTransactionFunc. -func (mock *TransactionHandlerMock) GetTransaction(ctx context.Context, txID string) ([]byte, error) { - if mock.GetTransactionFunc == nil { - panic("TransactionHandlerMock.GetTransactionFunc: method is nil but TransactionHandler.GetTransaction was just called") - } - callInfo := struct { - Ctx context.Context - TxID string - }{ - Ctx: ctx, - TxID: txID, - } - mock.lockGetTransaction.Lock() - mock.calls.GetTransaction = append(mock.calls.GetTransaction, callInfo) - mock.lockGetTransaction.Unlock() - return mock.GetTransactionFunc(ctx, txID) -} - -// GetTransactionCalls gets all the calls that were made to GetTransaction. -// Check the length with: -// -// len(mockedTransactionHandler.GetTransactionCalls()) -func (mock *TransactionHandlerMock) GetTransactionCalls() []struct { - Ctx context.Context - TxID string -} { - var calls []struct { - Ctx context.Context - TxID string - } - mock.lockGetTransaction.RLock() - calls = mock.calls.GetTransaction - mock.lockGetTransaction.RUnlock() - return calls -} - // GetTransactionStatus calls GetTransactionStatusFunc. func (mock *TransactionHandlerMock) GetTransactionStatus(ctx context.Context, txID string) (*metamorph.TransactionStatus, error) { if mock.GetTransactionStatusFunc == nil {