diff --git a/universalClient/chains/svm/event_listener.go b/universalClient/chains/svm/event_listener.go index aff9f027..6c229258 100644 --- a/universalClient/chains/svm/event_listener.go +++ b/universalClient/chains/svm/event_listener.go @@ -295,9 +295,29 @@ func (el *EventListener) processSignatureBatch( continue } - // Process each log in the transaction + // Process each log in the transaction. + // getSignaturesForAddress returns any tx that merely references the + // gateway in accountKeys, and a discriminator is a schema tag rather than + // an authenticator. So track the invocation stack and accept a + // "Program data:" line only while the gateway is the executing program; + // otherwise any program could emit a forged gateway event. if tx != nil && tx.Meta != nil && len(tx.Meta.LogMessages) > 0 { + // Surface truncation loudly: a gateway event may have been dropped and + // is unrecoverable from RPC, so the deposit needs manual reconciliation. + // Visible logs are still processed, since events before the cut are real. + if logsTruncated(tx.Meta.LogMessages) { + el.logger.Error(). + Str("signature", sig.Signature.String()). + Uint64("slot", sig.Slot). + Msg("solana log buffer truncated; a gateway event may have been dropped and needs manual review") + } + + fromGateway := gatewayEmittedLogs(tx.Meta.LogMessages, el.gatewayAddress) for logIndex, log := range tx.Meta.LogMessages { + if !fromGateway[logIndex] { + continue + } + // Determine event type based on discriminator eventType := el.determineEventType(log) if eventType == "" { @@ -395,6 +415,98 @@ func (el *EventListener) getPollingInterval() time.Duration { return 5 * time.Second // default } +// invokedProgram returns the program ID from a "Program invoke []" +// runtime log. Programs cannot emit these: sol_log and sol_log_data are always +// prefixed with "Program log: " / "Program data: ", so the invoke and exit lines +// are runtime-generated and safe to build an attribution stack from. +func invokedProgram(log string) (string, bool) { + const prefix = "Program " + if !strings.HasPrefix(log, prefix) { + return "", false + } + rest := log[len(prefix):] + idx := strings.Index(rest, " invoke [") + if idx <= 0 { + return "", false + } + programID := rest[:idx] + if _, err := solana.PublicKeyFromBase58(programID); err != nil { + return "", false + } + return programID, true +} + +// gatewayEmittedLogs returns the indexes of "Program data:" lines emitted while +// gatewayAddress was the executing program, walking the invoke/exit stack. +// Lines emitted by any other program are excluded: a discriminator identifies an +// encoding schema, not the emitter, so without this any program could log a +// well-formed gateway event and have it observed as a real deposit. +func gatewayEmittedLogs(logs []string, gatewayAddress string) map[int]bool { + emitted := make(map[int]bool) + var stack []string + for i, log := range logs { + if programID, ok := invokedProgram(log); ok { + stack = append(stack, programID) + continue + } + if isProgramExit(log) { + if len(stack) > 0 { + stack = stack[:len(stack)-1] + } + continue + } + if !strings.HasPrefix(log, "Program data: ") { + continue + } + if len(stack) > 0 && stack[len(stack)-1] == gatewayAddress { + emitted[i] = true + } + } + return emitted +} + +// logsTruncated reports whether the runtime dropped part of this transaction's +// log buffer. Programs can only emit "Program log:" and "Program data:" lines, +// so a bare line is runtime-generated and cannot be spoofed. Matching on the +// word rather than one exact literal keeps this working if the wording changes. +// +// It matters because gateway events are emitted with sol_log_data: once the +// buffer overflows the event line is gone, and no RPC call can recover it. The +// deposit would otherwise be missed in silence. +func logsTruncated(logs []string) bool { + for _, log := range logs { + if strings.HasPrefix(log, "Program ") { + continue + } + if strings.Contains(strings.ToLower(log), "truncated") { + return true + } + } + return false +} + +// isProgramExit reports whether log ends an invocation frame, i.e. +// "Program success" or "Program failed: ...". +// The program ID must parse as a pubkey: otherwise a program logging "success" +// emits "Program log: success", which would pop a frame it does not own and let +// a later log be attributed to its caller. +func isProgramExit(log string) bool { + const prefix = "Program " + if !strings.HasPrefix(log, prefix) { + return false + } + rest := log[len(prefix):] + sp := strings.IndexByte(rest, ' ') + if sp <= 0 { + return false + } + if _, err := solana.PublicKeyFromBase58(rest[:sp]); err != nil { + return false + } + tail := rest[sp+1:] + return tail == "success" || strings.HasPrefix(tail, "failed") +} + // determineEventType determines the event type based on the log discriminator func (el *EventListener) determineEventType(log string) string { if !strings.HasPrefix(log, "Program data: ") { diff --git a/universalClient/chains/svm/event_listener_test.go b/universalClient/chains/svm/event_listener_test.go index 62065a9b..84c20e36 100644 --- a/universalClient/chains/svm/event_listener_test.go +++ b/universalClient/chains/svm/event_listener_test.go @@ -15,6 +15,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/pushchain/push-chain-node/universalClient/chains/common" "github.com/pushchain/push-chain-node/universalClient/db" uregistrytypes "github.com/pushchain/push-chain-node/x/uregistry/types" ) @@ -676,3 +677,317 @@ func TestEventListener_StartWhileRunning(t *testing.T) { cancel() el.wg.Wait() } + +const ( + testGatewayProgram = "CFVSincHYbETh2k7w6u1ENEkjbSLtveRCEBupKidw2VS" + testAttackerProgram = "AttackerProgram1111111111111111111111111111" +) + +// getSignaturesForAddress returns any tx that merely references the gateway in +// accountKeys, and a discriminator is a schema tag, not an authenticator. So a +// gateway-shaped log must only be trusted when the gateway is the executing +// program. Otherwise any program can forge a deposit that every honest UV +// deterministically votes for. +func TestGatewayEmittedLogs(t *testing.T) { + const data = "Program data: q83vEjRWeJA=" + + t.Run("accepts log emitted by the gateway", func(t *testing.T) { + logs := []string{ + "Program " + testGatewayProgram + " invoke [1]", + data, + "Program " + testGatewayProgram + " success", + } + assert.Equal(t, map[int]bool{1: true}, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + // The reported attack: attacker program lists the gateway as an unused + // read-only account and emits a correctly encoded gateway event. + t.Run("rejects forged log from an attacker program", func(t *testing.T) { + logs := []string{ + "Program " + testAttackerProgram + " invoke [1]", + data, + "Program " + testAttackerProgram + " success", + } + assert.Empty(t, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + t.Run("accepts gateway frame reached via CPI", func(t *testing.T) { + logs := []string{ + "Program " + testAttackerProgram + " invoke [1]", + "Program " + testGatewayProgram + " invoke [2]", + data, + "Program " + testGatewayProgram + " success", + "Program " + testAttackerProgram + " success", + } + assert.Equal(t, map[int]bool{2: true}, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + // After the gateway frame exits, control is back with the caller, so a log + // there is not the gateway's. + t.Run("rejects log emitted after the gateway frame exits", func(t *testing.T) { + logs := []string{ + "Program " + testAttackerProgram + " invoke [1]", + "Program " + testGatewayProgram + " invoke [2]", + "Program " + testGatewayProgram + " success", + data, + "Program " + testAttackerProgram + " success", + } + assert.Empty(t, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + t.Run("rejects log from a failed gateway invocation's caller", func(t *testing.T) { + logs := []string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program " + testGatewayProgram + " failed: custom program error: 0x1", + data, + } + assert.Empty(t, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + // A program can only emit "Program log: ..." or "Program data: ...", so it + // cannot fake an invoke line to push a gateway frame onto the stack. + t.Run("cannot spoof an invoke line via program log", func(t *testing.T) { + logs := []string{ + "Program " + testAttackerProgram + " invoke [1]", + "Program log: Program " + testGatewayProgram + " invoke [1]", + data, + "Program " + testAttackerProgram + " success", + } + assert.Empty(t, gatewayEmittedLogs(logs, testGatewayProgram)) + }) + + // A callee that logs "success" emits "Program log: success". If that were + // treated as a frame exit it would pop its own frame and the next data log + // would be attributed to its caller, the gateway. + t.Run("callee cannot pop its frame by logging success", func(t *testing.T) { + logs := []string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program " + testAttackerProgram + " invoke [2]", + "Program log: success", + data, + "Program " + testAttackerProgram + " success", + "Program " + testGatewayProgram + " success", + } + assert.Empty(t, gatewayEmittedLogs(logs, testGatewayProgram), + "data logged inside the callee must not be attributed to the gateway") + }) + + t.Run("no logs or no invocation yields nothing", func(t *testing.T) { + assert.Empty(t, gatewayEmittedLogs(nil, testGatewayProgram)) + assert.Empty(t, gatewayEmittedLogs([]string{data}, testGatewayProgram)) + }) + + // Unbalanced logs are reachable: truncation can cut a frame's exit line, and + // the parser must not underflow or start attributing to a frame nobody owns. + t.Run("more exits than invokes does not underflow", func(t *testing.T) { + assert.Empty(t, gatewayEmittedLogs([]string{ + "Program " + testGatewayProgram + " success", + "Program " + testGatewayProgram + " success", + data, + }, testGatewayProgram)) + + assert.Empty(t, gatewayEmittedLogs([]string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program " + testGatewayProgram + " success", + "Program " + testGatewayProgram + " success", + data, + }, testGatewayProgram)) + }) + + t.Run("attacker exits cannot expose an outer gateway frame", func(t *testing.T) { + // Gateway CPIs into the attacker, who emits surplus exits hoping to pop + // back to the gateway frame and have its own data log attributed to it. + assert.Empty(t, gatewayEmittedLogs([]string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program " + testAttackerProgram + " invoke [2]", + "Program " + testAttackerProgram + " success", + "Program " + testGatewayProgram + " success", + data, + }, testGatewayProgram)) + }) + + t.Run("gateway frame left open still attributes", func(t *testing.T) { + // What a mid-frame truncation looks like: the exit line never arrives. + assert.Equal(t, map[int]bool{1: true}, gatewayEmittedLogs([]string{ + "Program " + testGatewayProgram + " invoke [1]", + data, + }, testGatewayProgram)) + }) + + t.Run("unrelated runtime lines do not disturb the stack", func(t *testing.T) { + logs := []string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program log: Instruction: SendFunds", + "Program return: " + testGatewayProgram + " AQID", + "Program " + testGatewayProgram + " consumed 12345 of 200000 compute units", + data, + "Program " + testGatewayProgram + " success", + } + assert.Equal(t, map[int]bool{4: true}, gatewayEmittedLogs(logs, testGatewayProgram)) + }) +} + +func TestInvokedProgramAndExit(t *testing.T) { + id, ok := invokedProgram("Program " + testGatewayProgram + " invoke [1]") + assert.True(t, ok) + assert.Equal(t, testGatewayProgram, id) + + _, ok = invokedProgram("Program log: hello") + assert.False(t, ok) + _, ok = invokedProgram("Program data: AQID") + assert.False(t, ok) + + assert.True(t, isProgramExit("Program "+testGatewayProgram+" success")) + assert.True(t, isProgramExit("Program "+testGatewayProgram+" failed: custom program error: 0x1")) + assert.False(t, isProgramExit("Program log: success")) + assert.False(t, isProgramExit("Program data: AQID")) + assert.False(t, isProgramExit("Program "+testGatewayProgram+" consumed 1 of 2 compute units")) +} + +// forgeryRPC serves one transaction whose logs the test controls. +type forgeryRPC struct { + slot uint64 + sig solana.Signature + logs []string +} + +func (m *forgeryRPC) GetLatestSlot(context.Context) (uint64, error) { return m.slot, nil } + +func (m *forgeryRPC) GetSignaturesForAddress(context.Context, solana.PublicKey, solana.Signature) ([]*solanarpc.TransactionSignature, error) { + return []*solanarpc.TransactionSignature{{Signature: m.sig, Slot: m.slot}}, nil +} + +func (m *forgeryRPC) GetTransaction(context.Context, solana.Signature) (*solanarpc.GetTransactionResult, error) { + return &solanarpc.GetTransactionResult{ + Slot: m.slot, + Meta: &solanarpc.TransactionMeta{LogMessages: m.logs}, + }, nil +} + +// End-to-end proof that the listener drops a forged event. The same valid +// send_funds payload is served twice: emitted by an attacker program it must be +// ignored, emitted by the gateway it must be stored. Running both with one +// payload shows attribution is what rejects it, not a decode failure. +func TestProcessSignatureBatch_RejectsForgedGatewayEvent(t *testing.T) { + discriminator := "0000000000000000" // buildSendFundsPayload zeroes the discriminator + payload := buildSendFundsPayload( + [32]byte{1}, [20]byte{2}, [32]byte{3}, 1_000_000, + nil, [32]byte{4}, 0, nil, false, + ) + dataLog := "Program data: " + base64.StdEncoding.EncodeToString(payload) + + run := func(t *testing.T, logs []string) int { + t.Helper() + database, err := db.OpenInMemoryDB(true) + require.NoError(t, err) + t.Cleanup(func() { database.Close() }) + + methods := []*uregistrytypes.GatewayMethods{ + {Name: EventTypeSendFunds, EventIdentifier: discriminator}, + } + rpc := &forgeryRPC{slot: 100, sig: mkSig(7), logs: logs} + el, err := NewEventListener(rpc, testGatewayProgram, "solana:test", methods, database, 10, nil, zerolog.Nop()) + require.NoError(t, err) + + _, err = el.processSignatureBatch(context.Background(), []*solanarpc.TransactionSignature{ + {Signature: mkSig(7), Slot: 100}, + }, 0, 200) + require.NoError(t, err) + + events, err := common.NewChainStore(database).GetPendingEvents(100) + require.NoError(t, err) + return len(events) + } + + t.Run("forged by attacker program is not stored", func(t *testing.T) { + stored := run(t, []string{ + "Program " + testAttackerProgram + " invoke [1]", + dataLog, + "Program " + testAttackerProgram + " success", + }) + assert.Zero(t, stored, "forged gateway event must not become an inbound") + }) + + t.Run("same payload from the gateway is stored", func(t *testing.T) { + stored := run(t, []string{ + "Program " + testGatewayProgram + " invoke [1]", + dataLog, + "Program " + testGatewayProgram + " success", + }) + assert.Equal(t, 1, stored, "genuine gateway event must be observed") + }) +} + +// Gateway events are emitted with sol_log_data, so once the runtime truncates +// the log buffer the event line is gone and no RPC call recovers it. Detect it +// so a missed deposit is alertable instead of silent. +func TestLogsTruncated(t *testing.T) { + t.Run("detects the runtime marker", func(t *testing.T) { + assert.True(t, logsTruncated([]string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program log: Instruction: SendFunds", + "Log truncated", + })) + }) + + t.Run("matches wording variants and case", func(t *testing.T) { + assert.True(t, logsTruncated([]string{"log truncated"})) + assert.True(t, logsTruncated([]string{"Log Truncated"})) + }) + + t.Run("normal logs are not flagged", func(t *testing.T) { + assert.False(t, logsTruncated([]string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program log: Instruction: SendFunds", + "Program data: q83vEjRWeJA=", + "Program " + testGatewayProgram + " success", + })) + assert.False(t, logsTruncated(nil)) + }) + + // A program cannot emit a bare line, so it cannot fake the marker. Its own + // output is always prefixed and must not trip detection. + t.Run("program cannot spoof the marker", func(t *testing.T) { + assert.False(t, logsTruncated([]string{ + "Program " + testAttackerProgram + " invoke [1]", + "Program log: Log truncated", + "Program data: dHJ1bmNhdGVk", + "Program " + testAttackerProgram + " success", + })) + }) +} + +// Truncation must not discard the events that did survive: anything logged +// before the cut is genuine and attributable. +func TestProcessSignatureBatch_TruncatedLogsStillStoreVisibleEvents(t *testing.T) { + discriminator := "0000000000000000" + payload := buildSendFundsPayload( + [32]byte{1}, [20]byte{2}, [32]byte{3}, 1_000_000, + nil, [32]byte{4}, 0, nil, false, + ) + + database, err := db.OpenInMemoryDB(true) + require.NoError(t, err) + defer database.Close() + + methods := []*uregistrytypes.GatewayMethods{ + {Name: EventTypeSendFunds, EventIdentifier: discriminator}, + } + rpc := &forgeryRPC{slot: 100, sig: mkSig(9), logs: []string{ + "Program " + testGatewayProgram + " invoke [1]", + "Program data: " + base64.StdEncoding.EncodeToString(payload), + "Program " + testGatewayProgram + " success", + "Log truncated", + }} + el, err := NewEventListener(rpc, testGatewayProgram, "solana:test", methods, database, 10, nil, zerolog.Nop()) + require.NoError(t, err) + + _, err = el.processSignatureBatch(context.Background(), []*solanarpc.TransactionSignature{ + {Signature: mkSig(9), Slot: 100}, + }, 0, 200) + require.NoError(t, err) + + events, err := common.NewChainStore(database).GetPendingEvents(100) + require.NoError(t, err) + assert.Len(t, events, 1, "events logged before the cut must still be stored") +}