Adding events through logger

Signed-off-by: Alexandros Filios <alexandros.filios@ibm.com>

Author: alexandrosfilios

integration/token/fungible/views/balance.go

@@ -17,7 +17,6 @@ import (
 	"github.com/hyperledger-labs/fabric-token-sdk/token/services/ttx/multisig"
 	token2 "github.com/hyperledger-labs/fabric-token-sdk/token/token"
 	"github.com/pkg/errors"
-	"go.opentelemetry.io/otel/trace"
 )
 
 type BalanceQuery struct {
@@ -38,17 +37,13 @@ type BalanceView struct {
 }
 
 func (b *BalanceView) Call(context view.Context) (interface{}, error) {
-	span := trace.SpanFromContext(context.Context())
-	defer span.AddEvent("end_balance_view")
-	span.AddEvent("start_balance_view")
 	tms := token.GetManagementService(context, ServiceOpts(b.TMSID)...)
 	wallet := tms.WalletManager().OwnerWallet(context.Context(), b.Wallet)
 	if wallet == nil {
 		return nil, fmt.Errorf("wallet %s not found", b.Wallet)
 	}
 
-	span.AddEvent("start_sum_calculation_unspent")
-	unspentTokens, err := wallet.ListUnspentTokensIterator(token.WithType(b.Type))
+	unspentTokens, err := wallet.ListUnspentTokensIterator(token.WithType(b.Type), token.WithContext(context.Context()))
 	if err != nil {
 		return nil, errors.Wrapf(err, "failed listing unspent tokens")
 	}
@@ -57,7 +52,6 @@ func (b *BalanceView) Call(context view.Context) (interface{}, error) {
 	if err != nil {
 		return nil, err
 	}
-	span.AddEvent("end_sum_calculation_unspent")
 
 	// co-owned
 	multisigWallet := multisig.Wallet(context, wallet)
@@ -67,12 +61,10 @@ func (b *BalanceView) Call(context view.Context) (interface{}, error) {
 	assert.NoError(err, "failed to compute the sum of the co-owned tokens")
 
 	if !b.SkipCheck {
-		span.AddEvent("start_sum_calculation")
 		balance, err := wallet.Balance(context.Context(), token.WithType(b.Type))
 		if err != nil {
 			return nil, err
 		}
-		span.AddEvent("end_sum_calculation")
 		if sum.ToBigInt().Uint64() != balance {
 			return nil, errors.Errorf("balance doesn't match [%d]!=[%d]", balance, sum.ToBigInt().Uint64())
 		}

integration/token/fungible/views/transfer.go

@@ -19,7 +19,6 @@ import (
 	token2 "github.com/hyperledger-labs/fabric-token-sdk/token"
 	"github.com/hyperledger-labs/fabric-token-sdk/token/services/ttx"
 	"github.com/hyperledger-labs/fabric-token-sdk/token/token"
-	"go.opentelemetry.io/otel/trace"
 )
 
 // TransferAction defines a transfer action
@@ -76,19 +75,16 @@ type TransferView struct {
 }
 
 func (t *TransferView) Call(context view.Context) (txID interface{}, err error) {
-	span := trace.SpanFromContext(context.Context())
 
 	// As a first step operation, the sender contacts the recipient's FSC node
 	// to ask for the identity to use to assign ownership of the freshly created token.
 	// Notice that, this step would not be required if the sender knew already which
 	// identity the recipient wants to use.
 	// If t.RecipientData is different from nil, then this recipient data will be advertised to the recipient
 	// to make sure the recipient is aware of this identity the will be used to transfer tokens to
-	span.AddEvent("receive_recipient_identity")
 	recipient, err := ttx.RequestRecipientIdentity(context, t.Recipient, ServiceOpts(t.TMSID, ttx.WithRecipientData(t.RecipientData), ttx.WithRecipientWalletID(t.RecipientWalletID))...)
 	assert.NoError(err, "failed getting recipient")
 
-	span.AddEvent("add_additional_recipients")
 	wm := token2.GetManagementService(context, ServiceOpts(t.TMSID)...).WalletManager()
 	// if there are more recipients, ask for their recipient identity
 	var additionalRecipients []view.Identity
@@ -111,7 +107,7 @@ func (t *TransferView) Call(context view.Context) (txID interface{}, err error)
 	// and specify the auditor that must be contacted to approve the operation.
 	var tx *ttx.Transaction
 	txOpts := TxOpts(t.TMSID, ttx.WithAuditor(view2.GetIdentityProvider(context).Identity(t.Auditor)))
-	span.AddEvent("create_transfer")
+	logger.DebugfContext(context.Context(), "Create transfer")
 	if !t.NotAnonymous {
 		// create an anonymous transaction (this means that the resulting Fabric transaction will be signed using idemix, for example),
 		tx, err = ttx.NewAnonymousTransaction(context, txOpts...)
@@ -139,7 +135,7 @@ func (t *TransferView) Call(context view.Context) (txID interface{}, err error)
 	// selector.Select(wallet, amount, tokenType)
 	// It is also possible to pass a custom token selector to the Transfer function by using the relative opt:
 	// token2.WithTokenSelector(selector).
-	span.AddEvent("append_transfer")
+	logger.DebugfContext(context.Context(), "Append transfer")
 	err = tx.Transfer(
 		senderWallet,
 		t.Type,
@@ -151,7 +147,7 @@ func (t *TransferView) Call(context view.Context) (txID interface{}, err error)
 	assert.NoError(err, "failed adding transfer action [%d:%s]", t.Amount, t.Recipient)
 
 	// add additional transfers
-	span.AddEvent("add_additional_transfers")
+	logger.DebugfContext(context.Context(), "Append additional actions")
 	for i, action := range t.TransferAction {
 		err = tx.Transfer(
 			senderWallet,
@@ -184,26 +180,24 @@ func (t *TransferView) Call(context view.Context) (txID interface{}, err error)
 		stream := view4.GetStream(context)
 		endorserOpts = append(endorserOpts, ttx.WithExternalWalletSigner(t.Wallet, ttx.NewStreamExternalWalletSignerServer(stream)))
 	}
-	span.AddEvent("collect_endorsements")
+
 	_, err = context.RunView(ttx.NewCollectEndorsementsView(tx, endorserOpts...))
 	assert.NoError(err, "failed to sign transaction [<<<%s>>>]", tx.ID())
 
 	// Sanity checks:
 	// - the transaction is in pending state
-	span.AddEvent("verify_owner")
+	logger.DebugfContext(context.Context(), "Verify owner")
 	owner := ttx.NewOwner(context, tx.TokenService())
 	vc, _, err := owner.GetStatus(context.Context(), tx.ID())
 	assert.NoError(err, "failed to retrieve status for transaction [%s]", tx.ID())
 	assert.Equal(ttx.Pending, vc, "transaction [%s] should be in busy state", tx.ID())
 
 	// Send to the ordering service and wait for finality
-	span.AddEvent("ask_ordering_finality")
 	_, err = context.RunView(ttx.NewOrderingAndFinalityView(tx))
 	assert.NoError(err, "failed asking ordering")
 
 	// Sanity checks:
 	// - the transaction is in confirmed state
-	span.AddEvent("verify_tx_status")
 	vc, _, err = owner.GetStatus(context.Context(), tx.ID())
 	assert.NoError(err, "failed to retrieve status for transaction [%s]", tx.ID())
 	assert.Equal(ttx.Confirmed, vc, "transaction [%s] should be in valid state", tx.ID())

integration/token/fungible/views/upgrade.go

@@ -18,7 +18,6 @@ import (
 	"github.com/hyperledger-labs/fabric-token-sdk/token/services/tokens"
 	"github.com/hyperledger-labs/fabric-token-sdk/token/services/ttx"
 	token2 "github.com/hyperledger-labs/fabric-token-sdk/token/token"
-	"go.opentelemetry.io/otel/trace"
 )
 
 type TokensUpgrade struct {
@@ -41,8 +40,6 @@ type TokensUpgradeInitiatorView struct {
 }
 
 func (i *TokensUpgradeInitiatorView) Call(context view.Context) (interface{}, error) {
-	span := trace.SpanFromContext(context.Context())
-
 	// First, the initiator selects the tokens to upgrade, namely those that are unsupported.
 	tms := token.GetManagementService(context, token.WithTMSID(i.TMSID))
 	assert.NotNil(tms, "failed getting token management service for [%s]", i.TMSID)
@@ -66,7 +63,6 @@ func (i *TokensUpgradeInitiatorView) Call(context view.Context) (interface{}, er
 		// First register it locally
 		assert.NoError(w.RegisterRecipient(context.Context(), i.RecipientData), "failed to register remote recipient")
 		// Then request upgrade
-		span.AddEvent("request_upgrade_for_recipient")
 		id, session, err = ttx.RequestTokensUpgradeForRecipient(
 			context,
 			view.Identity(i.Issuer),
@@ -77,7 +73,6 @@ func (i *TokensUpgradeInitiatorView) Call(context view.Context) (interface{}, er
 			token.WithTMSID(tms.ID()),
 		)
 	} else {
-		span.AddEvent("request_upgrade")
 		id, session, err = ttx.RequestTokensUpgrade(
 			context,
 			view.Identity(i.Issuer),
@@ -96,8 +91,6 @@ func (i *TokensUpgradeInitiatorView) Call(context view.Context) (interface{}, er
 	// This is a trick to the reuse the same API independently of the role a party plays.
 	return context.RunView(nil, view.AsResponder(session), view.WithViewCall(
 		func(context view.Context) (interface{}, error) {
-			span := trace.SpanFromContext(context.Context())
-
 			// At some point, the recipient receives the token transaction that in the meantime has been assembled
 			tx, err := ttx.ReceiveTransaction(context)
 			assert.NoError(err, "failed to receive tokens")
@@ -116,12 +109,10 @@ func (i *TokensUpgradeInitiatorView) Call(context view.Context) (interface{}, er
 			// If everything is fine, the recipient accepts and sends back her signature.
 			// Notice that, a signature from the recipient might or might not be required to make the transaction valid.
 			// This depends on the driver implementation.
-			span.AddEvent("accept_upgrade")
 			_, err = context.RunView(ttx.NewAcceptView(tx))
 			assert.NoError(err, "failed to accept new tokens")
 
 			// Before completing, the recipient waits for finality of the transaction
-			span.AddEvent("ask_for_finality")
 			_, err = context.RunView(ttx.NewFinalityView(tx, ttx.WithTimeout(1*time.Minute)))
 			assert.NoError(err, "new tokens were not committed")
 

integration/token/fungible/views/withdraw.go

@@ -16,7 +16,6 @@ import (
 	"github.com/hyperledger-labs/fabric-token-sdk/token"
 	"github.com/hyperledger-labs/fabric-token-sdk/token/services/ttx"
 	token2 "github.com/hyperledger-labs/fabric-token-sdk/token/token"
-	"go.opentelemetry.io/otel/trace"
 )
 
 type Withdrawal struct {
@@ -41,8 +40,6 @@ type WithdrawalInitiatorView struct {
 }
 
 func (i *WithdrawalInitiatorView) Call(context view.Context) (interface{}, error) {
-	span := trace.SpanFromContext(context.Context())
-
 	// First the initiator send a withdrawal request to the issuer.
 	// If the initiator has already some recipient data, it uses that directly
 	var id view.Identity
@@ -55,10 +52,8 @@ func (i *WithdrawalInitiatorView) Call(context view.Context) (interface{}, error
 		assert.NotNil(w, "cannot find wallet [%s:%s]", i.TMSID, i.Wallet)
 		assert.NoError(w.RegisterRecipient(context.Context(), i.RecipientData), "failed to register remote recipient")
 		// Then request withdrawal
-		span.AddEvent("request_withdrawal_for_recipient")
 		id, session, err = ttx.RequestWithdrawalForRecipient(context, view.Identity(i.Issuer), i.Wallet, i.TokenType, i.Amount, i.NotAnonymous, i.RecipientData, token.WithTMSID(i.TMSID))
 	} else {
-		span.AddEvent("request_withdrawal")
 		id, session, err = ttx.RequestWithdrawal(context, view.Identity(i.Issuer), i.Wallet, i.TokenType, i.Amount, i.NotAnonymous, token.WithTMSID(i.TMSID))
 	}
 	// Request withdrawal
@@ -69,8 +64,6 @@ func (i *WithdrawalInitiatorView) Call(context view.Context) (interface{}, error
 	// This is a trick to the reuse the same API independently of the role a party plays.
 	return context.RunView(nil, view.AsResponder(session), view.WithViewCall(
 		func(context view.Context) (interface{}, error) {
-			span := trace.SpanFromContext(context.Context())
-
 			// At some point, the recipient receives the token transaction that in the meantime has been assembled
 			tx, err := ttx.ReceiveTransaction(context)
 			assert.NoError(err, "failed to receive tokens")
@@ -88,12 +81,10 @@ func (i *WithdrawalInitiatorView) Call(context view.Context) (interface{}, error
 			// If everything is fine, the recipient accepts and sends back her signature.
 			// Notice that, a signature from the recipient might or might not be required to make the transaction valid.
 			// This depends on the driver implementation.
-			span.AddEvent("accept_withdrawal")
 			_, err = context.RunView(ttx.NewAcceptView(tx))
 			assert.NoError(err, "failed to accept new tokens")
 
 			// Before completing, the recipient waits for finality of the transaction
-			span.AddEvent("ask_for_finality")
 			_, err = context.RunView(ttx.NewFinalityView(tx, ttx.WithTimeout(1*time.Minute)))
 			assert.NoError(err, "new tokens were not committed")
 

token/core/common/loaders.go

@@ -17,6 +17,8 @@ import (
 	"go.opentelemetry.io/otel/trace"
 )
 
+var logger = logging.MustGetLogger()
+
 type TokenVault interface {
 	IsPending(ctx context.Context, id *token.ID) (bool, error)
 	GetTokenOutputsAndMeta(ctx context.Context, ids []*token.ID) ([][]byte, [][]byte, []token.Format, error)
@@ -66,13 +68,8 @@ func NewLedgerTokenLoader[T any](logger logging.Logger, _ trace.TracerProvider,
 
 // GetTokenOutputs takes an array of token identifiers (txID, index) and returns the corresponding token outputs
 func (s *VaultLedgerTokenLoader[T]) GetTokenOutputs(ctx context.Context, ids []*token.ID) (map[string]T, error) {
-	span := trace.SpanFromContext(ctx)
-	span.AddEvent("start_get_token_outputs")
-	defer span.AddEvent("end_get_token_outputs")
-
 	var err error
 	for i := 0; i < s.NumRetries; i++ {
-		span.AddEvent("try_fetch")
 		tokens := make(map[string]T, len(ids))
 		counter := 0
 		err = s.TokenVault.GetTokenOutputs(ctx, ids, func(id *token.ID, bytes []byte) error {
@@ -95,7 +92,6 @@ func (s *VaultLedgerTokenLoader[T]) GetTokenOutputs(ctx context.Context, ids []*
 
 		// check if there is any token id whose corresponding transaction is pending
 		// if there is, then wait a bit and retry to load the outputs
-		span.AddEvent("check_any_pending")
 		anyPending, anyError := s.isAnyPending(ctx, ids...)
 		if anyError != nil {
 			err = anyError
@@ -144,14 +140,13 @@ func NewVaultLedgerTokenAndMetadataLoader[T any, M any](tokenVault TokenVault, d
 // tokens in clear text and the identities of their owners
 // LoadToken returns an error in case of failure
 func (s *VaultLedgerTokenAndMetadataLoader[T, M]) LoadTokens(ctx context.Context, ids []*token.ID) ([]LoadedToken[T, M], error) {
-	span := trace.SpanFromContext(ctx)
 	// return token outputs and the corresponding opening
 	outputs, metadata, types, err := s.TokenVault.GetTokenOutputsAndMeta(ctx, ids)
 	if err != nil {
 		return nil, err
 	}
 
-	span.AddEvent("iterate_tokens")
+	logger.DebugfContext(ctx, "Deserialize %d tokens", len(ids))
 	result := make([]LoadedToken[T, M], len(ids))
 	for i, id := range ids {
 		if len(outputs[i]) == 0 {
@@ -160,12 +155,10 @@ func (s *VaultLedgerTokenAndMetadataLoader[T, M]) LoadTokens(ctx context.Context
 		if len(metadata[i]) == 0 {
 			return nil, errors.Errorf("failed getting state for id [%v], nil info value", id)
 		}
-		span.AddEvent("deserialize_token")
 		tok, err := s.Deserializer.DeserializeToken(outputs[i])
 		if err != nil {
 			return nil, errors.Wrapf(err, "failed deserializing token for id [%v][%s]", id, string(outputs[i]))
 		}
-		span.AddEvent("deserialize_metadata")
 		meta, err := s.Deserializer.DeserializeMetadata(metadata[i])
 		if err != nil {
 			return nil, errors.Wrapf(err, "failed deserializeing token info for id [%v]", id)

token/core/common/validator.go

@@ -83,6 +83,7 @@ func NewValidator[P driver.PublicParameters, T any, TA driver.TransferAction, IA
 }
 
 func (v *Validator[P, T, TA, IA, DS]) VerifyTokenRequestFromRaw(ctx context.Context, getState driver.GetStateFnc, anchor string, raw []byte) ([]interface{}, driver.ValidationAttributes, error) {
+	logger.DebugfContext(ctx, "Verify token request from raw")
 	if len(raw) == 0 {
 		return nil, nil, errors.New("empty token request")
 	}

token/core/zkatdlog/nogh/v1/audit/auditor.go

@@ -140,17 +140,14 @@ func (a *Auditor) Check(
 	txID string,
 ) error {
 	// TODO: inputTokens should be checked against the actions
-	span := trace.SpanFromContext(ctx)
-	span.AddEvent("start_check")
-	defer span.AddEvent("end_check")
 	// De-obfuscate issue requests
-	span.AddEvent("get_issue_audit_info")
+	a.Logger.DebugfContext(ctx, "Get audit info for %d issues", len(tokenRequest.Issues))
 	outputsFromIssue, identitiesFromIssue, err := a.GetAuditInfoForIssues(tokenRequest.Issues, tokenRequestMetadata.Issues)
 	if err != nil {
 		return errors.Wrapf(err, "failed getting audit info for issues for [%s]", txID)
 	}
 	// check validity of issue requests
-	span.AddEvent("check_issue_requests")
+	a.Logger.DebugfContext(ctx, "Check %d issue outputs", len(outputsFromIssue))
 	err = a.CheckIssueRequests(outputsFromIssue, txID)
 	if err != nil {
 		return errors.Wrapf(err, "failed checking issues for [%s]", txID)
@@ -162,13 +159,13 @@ func (a *Auditor) Check(
 		}
 	}
 	// De-obfuscate transfer requests
-	span.AddEvent("get_transfer_audit_info")
+	a.Logger.DebugfContext(ctx, "Get audit info for %d transfers", len(tokenRequest.Transfers))
 	auditableInputs, outputsFromTransfer, err := a.GetAuditInfoForTransfers(tokenRequest.Transfers, tokenRequestMetadata.Transfers, inputTokens)
 	if err != nil {
 		return errors.Wrapf(err, "failed getting audit info for transfers for [%s]", txID)
 	}
 	// check validity of transfer requests
-	span.AddEvent("check_transfer_requests")
+	a.Logger.DebugfContext(ctx, "Check %d transfer outputs", len(outputsFromTransfer))
 	if err := a.CheckTransferRequests(auditableInputs, outputsFromTransfer, txID); err != nil {
 		return errors.Wrapf(err, "failed checking transfers [%s]", txID)
 	}

token/core/zkatdlog/nogh/v1/auditor.go

@@ -56,10 +56,7 @@ func NewAuditorService(
 
 // AuditorCheck verifies if the passed tokenRequest matches the tokenRequestMetadata
 func (s *AuditorService) AuditorCheck(ctx context.Context, request *driver.TokenRequest, metadata *driver.TokenRequestMetadata, txID string) error {
-	span := trace.SpanFromContext(ctx)
-	span.AddEvent("start_auditor_check")
-	defer span.AddEvent("end_auditor_check")
-	s.Logger.Debugf("[%s] check token request validity, number of transfer actions [%d]...", txID, len(metadata.Transfers))
+	s.Logger.DebugfContext(ctx, "[%s] check token request validity, number of transfer actions [%d]...", txID, len(metadata.Transfers))
 
 	actionDes := &validator.ActionDeserializer{
 		PublicParams: s.PublicParametersManager.PublicParams(ctx),
@@ -75,17 +72,16 @@ func (s *AuditorService) AuditorCheck(ctx context.Context, request *driver.Token
 		tokenIDs = append(tokenIDs, transfer.TokenIDs()...)
 	}
 
-	span.AddEvent("load_token_outputs")
 	// tokenMap, err := s.TokenCommitmentLoader.GetTokenOutputs(ctx, tokenIDs)
 	// if err != nil {
 	// 	return errors.Wrapf(err, "failed getting token outputs to perform auditor check")
 	// }
-	s.Logger.Debugf("loaded [%d] corresponding inputs for TX [%s]", len(tokenIDs), txID)
+	s.Logger.DebugfContext(ctx, "loaded [%d] corresponding inputs for TX [%s]", len(tokenIDs), txID)
 
 	inputTokens := make([][]*token.Token, len(metadata.Transfers))
 	for i, transfer := range transfers {
 		if err := transfer.Validate(); err != nil {
-			span.AddEvent("failed_to_validate_transfer")
+			s.Logger.ErrorfContext(ctx, "failed to validate transfer: %v", err)
 			return errors.Wrapf(err, "failed to validate transfer")
 		}
 		inputTokens[i] = make([]*token.Token, len(transfer.Inputs))
@@ -94,11 +90,9 @@ func (s *AuditorService) AuditorCheck(ctx context.Context, request *driver.Token
 		}
 	}
 
-	span.AddEvent("load_public_params")
 	pp := s.PublicParametersManager.PublicParams(ctx)
-	span.AddEvent("create_new_auditor")
 	auditor := audit.NewAuditor(s.Logger, s.tracer, s.Deserializer, pp.PedersenGenerators, nil, math.Curves[pp.Curve])
-	span.AddEvent("start_auditor_check")
+	s.Logger.DebugfContext(ctx, "Start auditor check")
 	err = auditor.Check(
 		ctx,
 		request,