Skip to content

verification: Clean up logging when checking transaction IDs #440

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
bradtgmurray wants to merge 3 commits into
base: main
Choose a base branch
from
+71 −63
Open

verification: Clean up logging when checking transaction IDs #440

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
cf33f9d
verification: Clean up logging when checking transaction IDs
bradtgmurray Dec 8, 2025
e6d8ae8
Merge branch 'main' into verification-logging-cleanup
bradtgmurray Jan 6, 2026
818f8f4
Restore the event_type on the logger
bradtgmurray Jan 6, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
134 changes: 71 additions & 63 deletions crypto/verificationhelper/verificationhelper.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -141,6 +141,70 @@ func (vh *VerificationHelper) getLog(ctx context.Context) *zerolog.Logger {
return &logger
}

func (vh *VerificationHelper) checkTransactionID(ctx context.Context, evt *event.Event) *VerificationTransaction {
log := vh.getLog(ctx).With().
Str("verification_action", "check transaction ID").
Stringer("sender", evt.Sender).
Stringer("room_id", evt.RoomID).
Stringer("event_id", evt.ID).
Stringer("event_type", evt.Type).
Copy link
Member

@sumnerevans sumnerevans Dec 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just a note, this change looses the event_type key from the callback's logger. I'm not sure how useful it is (and it might be added to the context somewhere else).

Copy link
Contributor Author

@bradtgmurray bradtgmurray Jan 6, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, fixed!

Logger()
ctx = log.WithContext(ctx)

var transactionID id.VerificationTransactionID
if evt.ID != "" {
transactionID = id.VerificationTransactionID(evt.ID)
} else {
if txnID, ok := evt.Content.Parsed.(event.VerificationTransactionable); !ok {
log.Warn().Msg("Ignoring verification event without a transaction ID")
return nil
} else {
transactionID = txnID.GetTransactionID()
}
}
log = log.With().Stringer("transaction_id", transactionID).Logger()

vh.activeTransactionsLock.Lock()
defer vh.activeTransactionsLock.Unlock()
Copy link
Contributor Author

@bradtgmurray bradtgmurray Dec 8, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changing to use defer and changing this to return a *VerificationTransaction should be the only changes to this code after factoring it out.


txn, err := vh.store.GetVerificationTransaction(ctx, transactionID)
if err != nil && errors.Is(err, ErrUnknownVerificationTransaction) {
log.Err(err).Msg("failed to get verification transaction")
return nil
} else if errors.Is(err, ErrUnknownVerificationTransaction) {
// If it's a cancellation event for an unknown transaction, we
// can just ignore it.
if evt.Type == event.ToDeviceVerificationCancel || evt.Type == event.InRoomVerificationCancel {
log.Info().Msg("Ignoring verification cancellation event for an unknown transaction")
return nil
}

log.Warn().Msg("Sending cancellation event for unknown transaction ID")

// We have to create a fake transaction so that the call to
// cancelVerificationTxn works.
txn = VerificationTransaction{
ExpirationTime: jsontime.UnixMilli{Time: time.Now().Add(time.Minute * 10)},
RoomID: evt.RoomID,
TheirUserID: evt.Sender,
}
if transactionable, ok := evt.Content.Parsed.(event.VerificationTransactionable); ok {
txn.TransactionID = transactionable.GetTransactionID()
} else {
txn.TransactionID = id.VerificationTransactionID(evt.ID)
}
if fromDevice, ok := evt.Content.Raw["from_device"]; ok {
txn.TheirDeviceID = id.DeviceID(fromDevice.(string))
}

// Send a cancellation event.
vh.cancelVerificationTxn(ctx, txn, event.VerificationCancelCodeUnknownTransaction, "The transaction ID was not recognized.")
return nil
}

return &txn
}

// Init initializes the verification helper by adding the necessary event
// handlers to the syncer.
func (vh *VerificationHelper) Init(ctx context.Context) error {
Expand All @@ -165,78 +229,22 @@ func (vh *VerificationHelper) Init(ctx context.Context) error {
// and ignore the event if it isn't.
wrapHandler := func(callback func(context.Context, VerificationTransaction, *event.Event)) func(context.Context, *event.Event) {
return func(ctx context.Context, evt *event.Event) {
log := vh.getLog(ctx).With().
Str("verification_action", "check transaction ID").
Stringer("sender", evt.Sender).
Stringer("room_id", evt.RoomID).
Stringer("event_id", evt.ID).
Stringer("event_type", evt.Type).
Logger()
ctx = log.WithContext(ctx)

var transactionID id.VerificationTransactionID
if evt.ID != "" {
transactionID = id.VerificationTransactionID(evt.ID)
} else {
if txnID, ok := evt.Content.Parsed.(event.VerificationTransactionable); !ok {
log.Warn().Msg("Ignoring verification event without a transaction ID")
return
} else {
transactionID = txnID.GetTransactionID()
}
}
log = log.With().Stringer("transaction_id", transactionID).Logger()

vh.activeTransactionsLock.Lock()
txn, err := vh.store.GetVerificationTransaction(ctx, transactionID)
if err != nil && errors.Is(err, ErrUnknownVerificationTransaction) {
log.Err(err).Msg("failed to get verification transaction")
vh.activeTransactionsLock.Unlock()
txn := vh.checkTransactionID(ctx, evt)
if txn == nil {
return
} else if errors.Is(err, ErrUnknownVerificationTransaction) {
// If it's a cancellation event for an unknown transaction, we
// can just ignore it.
if evt.Type == event.ToDeviceVerificationCancel || evt.Type == event.InRoomVerificationCancel {
log.Info().Msg("Ignoring verification cancellation event for an unknown transaction")
vh.activeTransactionsLock.Unlock()
return
}

log.Warn().Msg("Sending cancellation event for unknown transaction ID")

// We have to create a fake transaction so that the call to
// cancelVerificationTxn works.
txn = VerificationTransaction{
ExpirationTime: jsontime.UnixMilli{Time: time.Now().Add(time.Minute * 10)},
RoomID: evt.RoomID,
TheirUserID: evt.Sender,
}
if transactionable, ok := evt.Content.Parsed.(event.VerificationTransactionable); ok {
txn.TransactionID = transactionable.GetTransactionID()
} else {
txn.TransactionID = id.VerificationTransactionID(evt.ID)
}
if fromDevice, ok := evt.Content.Raw["from_device"]; ok {
txn.TheirDeviceID = id.DeviceID(fromDevice.(string))
}

// Send a cancellation event.
vh.cancelVerificationTxn(ctx, txn, event.VerificationCancelCodeUnknownTransaction, "The transaction ID was not recognized.")
vh.activeTransactionsLock.Unlock()
return
} else {
vh.activeTransactionsLock.Unlock()
}

logCtx := log.With().
logCtx := vh.getLog(ctx).With().
Stringer("transaction_step", txn.VerificationState).
Stringer("sender", evt.Sender)
Stringer("sender", evt.Sender).
Stringer("event_type", evt.Type)
if evt.RoomID != "" {
logCtx = logCtx.
Stringer("room_id", evt.RoomID).
Stringer("event_id", evt.ID)
}
callback(logCtx.Logger().WithContext(ctx), txn, evt)

callback(logCtx.Logger().WithContext(ctx), *txn, evt)
}
}

Expand Down