GetObservationsStdTx errors on redundant ObservedTx and doesn't report details
Context: this Discord discussion,
for many error logs of the below format, which did not indicate which transaction they were referring to.
{"level":"error","service":"bifrost","module":"observer","error":"fail to sign the tx: could not determine if this tx as inbound or outbound","time":"2023-10-07T14:34:55Z","caller":"/app/bifrost/observer/observe.go:224","message":"fail to send to THORChain"}
The first thing noticed is that the log gives no indication about what transaction THORChain is having trouble with,
but a greater concern was noted upon looking closer.
The ultimate source of the log is GetObservationsStdTx
here:
obAddr, err := tx.ObservedPubKey.GetAddress(chain)
if err != nil {
return nil, err
}
// for consolidate UTXO tx, both From & To address will be the asgard address
// thus here we need to make sure that one add to inbound , the other add to outbound
if tx.Tx.ToAddress.Equals(obAddr) && !inbound.Contains(tx) { // nolint
inbound = append(inbound, tx)
} else if tx.Tx.FromAddress.Equals(obAddr) && !outbound.Contains(tx) {
// for outbound transaction , there is no need to do confirmation counting
tx.FinaliseHeight = tx.BlockHeight
outbound = append(outbound, tx)
} else {
return nil, errors.New("could not determine if this tx as inbound or outbound")
}
Here GetObservationsStdTx
has received an array of ObservedTxs, and is going through them ObservedTx by ObservedTx.
If it reaches the "could not determine if this tx as inbound or outbound"
line, it returns an error for the entire array.
If GetObservationsStdTx
returns an error, signAndSendToThorchain
(the sole function that calls it) also returns an error.
msgs, err := o.thorchainBridge.GetObservationsStdTx(txs)
if err != nil {
return fmt.Errorf("fail to sign the tx: %w", err)
If signAndSendToThorchain
returns an error, chunkifyAndSendToThorchain
(the sole function that calls it) appends the ObservedTxs to the TxArray it returns.
https://gitlab.com/thorchain/thornode/-/blob/v1.121.1/bifrost/observer/observe.go#L223-239
If chunkifyAndSendToThorchain
returns ObservedTxs, sendDeck
(the sole function that calls it) appends them to the new deck to be set.
https://gitlab.com/thorchain/thornode/-/blob/v1.121.1/bifrost/observer/observe.go#L195-201
if len(result.TxArray) > 0 {
newTxIn.TxArray = append(newTxIn.TxArray, result.TxArray...)
}
}
if len(newTxIn.TxArray) > 0 {
newTxIn.Count = strconv.Itoa(len(newTxIn.TxArray))
newDeck = append(newDeck, newTxIn)
(ObservedTxs that aren't ConfirmationCountReady
are appended no matter what, with SentUnFinalised
set if sent.)
As #1682 (closed)
'UTXO getOutput can select outputs for which neither sender nor receiver is a vault address'
indicates
(perhaps fixed by the unmerged !3128 (merged)
'Ensure that getOutput only returns an output with a vault address as either the sender or receiver')
, there may occasionally be an ObservedTx reaching GetObservationsStdTx
for which neither the FromAddress nor ToAddress match the ObservedPubKey's address
(for instance from having selected a change Vout's ToAddress instead of a vault Vout's ToAddress for a non-vault FromAddress).
The concern then is that when GetObservationsStdTx
has received an ObservedTxs array containing observable transactions and one of these unobservable transactions,
it may reject the entire ObservedTxs array with an error,
and append them again to be retried later (and rejected again for the same reason),
cycling endlessly and blocking any observable ObservedTx in the same array from observation?
I thus propose that an unobservable ObservedTx prompt a log of the details of that unobserved transaction,
but not block the observation of the observable ObservedTxs in the same array.
Copying from my summarisation here:
If an ObservedTx has already been added to every (inbound/outbound) array it can be, then drop any duplicates.
If an ObservedTx's ToAddress and FromAddress both don't match the observed address, it's unobservable and should be dropped.
Either way, log details about what transaction it happened for (to look into how to prevent it happening in future).
Specifically:
obAddr, err := tx.ObservedPubKey.GetAddress(chain)
if err != nil {
return nil, err
}
vaultToAddress := tx.Tx.ToAddress.Equals(obAddr)
vaultFromAddress := tx.Tx.FromAddress.Equals(obAddr)
var inInboundArray, inOutboundArray bool
if vaultToAddress {
inInboundArray = inbound.Contains(tx)
}
if vaultFromAddress {
inOutboundArray = outbound.Contains(tx)
}
// for consolidate UTXO tx, both From & To address will be the asgard address
// thus here we need to make sure that one add to inbound , the other add to outbound
switch {
case !vaultToAddress && !vaultFromAddress:
// Neither ToAddress nor FromAddress matches obAddr, so drop it.
b.logger.Error().Msgf("chain (%s) tx (%s) observedaddress (%s) does not match its toaddress (%s) or fromaddress (%s)", tx.Tx.Chain, tx.Tx.ID, obAddr, tx.Tx.ToAddress, tx.Tx.FromAddress)
case vaultToAddress && !inInboundArray:
inbound = append(inbound, tx)
case vaultFromAddress && !inOutboundArray:
// for outbound transaction , there is no need to do confirmation counting
tx.FinaliseHeight = tx.BlockHeight
outbound = append(outbound, tx)
case inInboundArray && inOutboundArray:
// It's already in both arrays, so drop it.
b.logger.Error().Msgf("vault-to-vault chain (%s) tx (%s) is already in both inbound and outbound arrays", tx.Tx.Chain, tx.Tx.ID)
case !vaultFromAddress && inInboundArray:
// It's already in its only (inbound) array, so drop it.
b.logger.Error().Msgf("observed tx in for chain (%s) tx (%s) is already in the inbound array", tx.Tx.Chain, tx.Tx.ID)
case !vaultToAddress && inOutboundArray:
// It's already in its only (outbound) array, so drop it.
b.logger.Error().Msgf("observed tx out for chain (%s) tx (%s) is already in the outbound array", tx.Tx.Chain, tx.Tx.ID)
default:
// This should never happen; rather than dropping it, return an error.
return nil, fmt.Errorf("could not determine if chain (%s) tx (%s) was inbound or outbound", tx.Tx.Chain, tx.Tx.ID)
}
More specifically: !3173 (merged)
'Log and drop GetObservationsStdTx
unobservable ObservedTx'.