Consensus (bank hash) mismatch between v1.8.14 and v1.9.x/master (devnet)

[steviez]

Problem

A consensus failure was discovered between v1.8.14 and v1.9.x and master; a transaction that succeeds on v1.8.14 is failing on v1.9.x and master. The failing transaction is included in slot 114622493.

Transaction Details

I found the failing transaction by diffing the updated accounts; here are the details of the transaction in question:

    Transaction 0
      Recent Blockhash: 7pGgSK9YfVdWmXBpJ2Y1irYNLALWpsm4C5rkdyEJSuGy
      Signature 0: 4Bfz5Ecc2P2YdS97GWJfRgoj2b4ZJ6qeYXdCEvFZqeN3x8bfu6z1uRCGtPwaSMwk72HHjQMBiRHesa1qrrBDzXrM
      Account 0: srw- 3Jgcfv6MsEJwwcQUSqtZ1EjU7o6GJWJC9Ebeo9nww48q (fee payer)
      Account 1: -rw- 8GACwwyqUoHbBoSrVZNB7EFUb1RqbWZtJSBS25tzW357
      Account 2: -rw- FDiUfSWXRjXJVkuMPz1M8CrMvLiwoskay6TJtLcvHUHG
      Account 3: -rw- 8wndnSPMocSUuPkxbdtNpXKRnknsgjokMnGUM3xrPMZn
      Account 4: -rw- 8QGWaD9vMbw6hM1N5sK7UW3oNE5JRpNinghZhXvzWp7o
      Account 5: -rw- 4NfzL7wmepTag4n4zzmzjaNZAy4H8avBfLWS1DDyzfQW
      Account 6: -rw- mxyyZ3cxNUUJDq9JvdmXjiCfAm579Jbi6WJYAdQSGyD
      Account 7: -r-- Sysvar1nstructions1111111111111111111111111
      Account 8: -r-- TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA
      Account 9: -r-- 2TPBhV6fb7V2yJAg9qpfQHkpbEFNRLT7cTRpzPi2vzyY
      Account 10: -r-x Ed25519SigVerify111111111111111111111111111
      Account 11: -r-x CiHxDpJ424jwbKDikmxTxkLjufacAoF2kgGV5hAs9sLi
      Instruction 0
        Program:   Ed25519SigVerify111111111111111111111111111 (10)
        Data: [1, 0, 48, 0, 255, 255, 16, 0, 255, 255, 112, 0, 32, 0, 255, 255, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 40, 251, 130, 135, 238, 88, 235, 80, 96, 149, 82, 18, 155, 163, 29, 50, 230, 111, 172, 209, 150, 193, 105, 13, 143, 13, 157, 9, 15, 8, 30, 162, 247, 111, 65, 144, 250, 243, 54, 124, 30, 127, 228, 146, 184, 137, 32, 31, 61, 137, 103, 48, 61, 187, 34, 84, 37, 51, 211, 68, 200, 250, 147, 10, 244, 59, 135, 247, 211, 228, 77, 237, 101, 18, 172, 164, 239, 41, 104, 61, 69, 205, 194, 239, 197, 141, 153, 18, 40, 123, 94, 1, 96, 187, 97, 92]
      Instruction 1
        Program:   CiHxDpJ424jwbKDikmxTxkLjufacAoF2kgGV5hAs9sLi (11)
        Account 0: 8GACwwyqUoHbBoSrVZNB7EFUb1RqbWZtJSBS25tzW357 (1)
        Account 1: 3Jgcfv6MsEJwwcQUSqtZ1EjU7o6GJWJC9Ebeo9nww48q (0)
        Account 2: FDiUfSWXRjXJVkuMPz1M8CrMvLiwoskay6TJtLcvHUHG (2)
        Account 3: Sysvar1nstructions1111111111111111111111111 (7)
        Account 4: TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA (8)
        Account 5: 2TPBhV6fb7V2yJAg9qpfQHkpbEFNRLT7cTRpzPi2vzyY (9)
        Account 6: 8wndnSPMocSUuPkxbdtNpXKRnknsgjokMnGUM3xrPMZn (3)
        Account 7: 8QGWaD9vMbw6hM1N5sK7UW3oNE5JRpNinghZhXvzWp7o (4)
        Account 8: 4NfzL7wmepTag4n4zzmzjaNZAy4H8avBfLWS1DDyzfQW (5)
        Account 9: mxyyZ3cxNUUJDq9JvdmXjiCfAm579Jbi6WJYAdQSGyD (6)
        Account 10: 3Jgcfv6MsEJwwcQUSqtZ1EjU7o6GJWJC9Ebeo9nww48q (0)
        Data: [0, 0, 0, 0, 0, 0, 0, 0, 0, 14, 145, 90, 164, 9, 95, 220, 97, 53, 143, 11, 61, 231, 188, 191, 147, 224, 104, 246, 191, 129, 13, 165, 95, 110, 83, 58, 33, 143, 240, 89, 160, 119, 187, 99, 105, 191, 198, 165, 10, 33, 128, 46, 87, 144, 175, 111, 186, 213, 253, 203, 0, 174, 142, 42, 152, 253, 46, 82, 26, 8, 87, 235, 243, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 0, 202, 154, 59, 0, 0, 0, 0, 0, 148, 53, 119, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 156, 0, 0, 0, 34, 192, 118, 35, 128, 32, 126, 54, 71, 146, 146, 47, 241, 227, 117, 146, 224, 12, 197, 13, 212, 150, 35, 113, 137, 30, 41, 185, 2, 214, 159, 231, 0, 0, 0, 0, 0, 0, 0, 0, 108, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 21, 157, 223, 59, 68, 65, 192, 61, 156, 47, 143, 160, 51, 78, 167, 170, 210, 242, 48, 241, 15, 154, 186, 133, 102, 34, 135, 25, 212, 170, 198, 203, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 1, 21, 157, 223, 59, 68, 65, 192, 61, 156, 47, 143, 160, 51, 78, 167, 170, 210, 242, 48, 241, 15, 154, 186, 133, 102, 34, 135, 25, 212, 170, 198, 203, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 202, 154, 59, 0, 0, 0, 0, 0, 148, 53, 119, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1]
      Status: Unavailable

Transaction Log Statements

This transaction succeeds on v1.8.14 but fails on v1.9.x or master with an InstructionError(0, UnsupportedProgramId)

[2022-02-15T22:33:56.060347285Z DEBUG solana_runtime::message_processor::stable_log] Program 4skJ85cdxQAFVKbcGgfun8iZPL7BadVYXG3kGEGkufqA invoke [1]
[2022-02-15T22:33:56.060380218Z DEBUG solana_runtime::bank] store: 1us txs_len=1
[2022-02-15T22:33:56.060382538Z DEBUG solana_runtime::message_processor::stable_log] Program log: Mango: CachePrices
[2022-02-15T22:33:56.060386450Z DEBUG solana_metrics::metrics] CounterPoint { name: "bank-process_transactions-error_count", count: 0, timestamp: SystemTime { tv_sec: 1644964436, tv_nsec: 60370350 } }
[2022-02-15T22:33:56.060393325Z DEBUG solana_metrics::metrics] CounterPoint { name: "bank-process_transactions-error-instruction_error", count: 0, timestamp: SystemTime { tv_sec: 1644964436, tv_nsec: 60376747 } }
[2022-02-15T22:33:56.060397457Z DEBUG solana_metrics::metrics] CounterPoint { name: "bank-process_transactions-txs", count: 1, timestamp: SystemTime { tv_sec: 1644964436, tv_nsec: 60377538 } }
[2022-02-15T22:33:56.060400768Z DEBUG solana_metrics::metrics] CounterPoint { name: "bank-process_transactions-sigs", count: 1, timestamp: SystemTime { tv_sec: 1644964436, tv_nsec: 60377893 } }
[2022-02-15T22:33:56.060521740Z DEBUG solana_runtime::message_processor::stable_log] Program log: mango-log
[2022-02-15T22:33:56.060532652Z DEBUG solana_runtime::message_processor::stable_log] Program log: ux0uSxX5tBvKISAtTF7lMdQarmxDZG/wXw1EdsMrRmiMvKrmbhkiIQUAAAAIAAAAAAAAAAkAAAAAAAAACgAAAAAAAAALAAAAAAAAAAwAAAAAAAAABQAAAI7k8h/SnywAAAAAAAAAAADKSg7fzRQAAAAAAAAAAAAAzJ7P+meKAAAAAAAAAAAAAJ+rrdhfBgQAAAAAAAAAAABhpal2MgQAAAAAAAAAAAAA
[2022-02-15T22:33:56.060537127Z DEBUG solana_runtime::message_processor::stable_log] Program 4skJ85cdxQAFVKbcGgfun8iZPL7BadVYXG3kGEGkufqA consumed 26573 of 200000 compute units
[2022-02-15T22:33:56.060550161Z DEBUG solana_runtime::message_processor::stable_log] Program 4skJ85cdxQAFVKbcGgfun8iZPL7BadVYXG3kGEGkufqA success
[2022-02-15T22:33:56.060555307Z DEBUG solana_runtime::bank] check: 6us load: 393us execute: 18us txs_len=1
[2022-02-15T22:33:56.060586429Z DEBUG solana_runtime::message_processor::stable_log] Program 4skJ85cdxQAFVKbcGgfun8iZPL7BadVYXG3kGEGkufqA invoke [1]
[2022-02-15T22:33:56.060594783Z DEBUG solana_runtime::message_processor::stable_log] Program log: Mango: CachePerpMarkets
[2022-02-15T22:33:56.060566898Z DEBUG solana_runtime::bank] tx error: InstructionError(0, UnsupportedProgramId) SanitizedTransaction { message: Legacy(Message { header: MessageHeader { num_required_signatures: 1, num_readonly_signed_accounts: 0, num_readonly_unsigned_accounts: 5 }, account_keys: [3Jgcfv6MsEJwwcQUSqtZ1EjU7o6GJWJC9Ebeo9nww48q, 8GACwwyqUoHbBoSrVZNB7EFUb1RqbWZtJSBS25tzW357, FDiUfSWXRjXJVkuMPz1M8CrMvLiwoskay6TJtLcvHUHG, 8wndnSPMocSUuPkxbdtNpXKRnknsgjokMnGUM3xrPMZn, 8QGWaD9vMbw6hM1N5sK7UW3oNE5JRpNinghZhXvzWp7o, 4NfzL7wmepTag4n4zzmzjaNZAy4H8avBfLWS1DDyzfQW, mxyyZ3cxNUUJDq9JvdmXjiCfAm579Jbi6WJYAdQSGyD, Sysvar1nstructions1111111111111111111111111, TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA, 2TPBhV6fb7V2yJAg9qpfQHkpbEFNRLT7cTRpzPi2vzyY, Ed25519SigVerify111111111111111111111111111, CiHxDpJ424jwbKDikmxTxkLjufacAoF2kgGV5hAs9sLi], recent_blockhash: 7pGgSK9YfVdWmXBpJ2Y1irYNLALWpsm4C5rkdyEJSuGy, instructions: [CompiledInstruction { program_id_index: 10, accounts: [], data: [1, 0, 48, 0, 255, 255, 16, 0, 255, 255, 112, 0, 32, 0, 255, 255, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 40, 251, 130, 135, 238, 88, 235, 80, 96, 149, 82, 18, 155, 163, 29, 50, 230, 111, 172, 209, 150, 193, 105, 13, 143, 13, 157, 9, 15, 8, 30, 162, 247, 111, 65, 144, 250, 243, 54, 124, 30, 127, 228, 146, 184, 137, 32, 31, 61, 137, 103, 48, 61, 187, 34, 84, 37, 51, 211, 68, 200, 250, 147, 10, 244, 59, 135, 247, 211, 228, 77, 237, 101, 18, 172, 164, 239, 41, 104, 61, 69, 205, 194, 239, 197, 141, 153, 18, 40, 123, 94, 1, 96, 187, 97, 92] }, CompiledInstruction { program_id_index: 11, accounts: [1, 0, 2, 7, 8, 9, 3, 4, 5, 6, 0], data: [0, 0, 0, 0, 0, 0, 0, 0, 0, 14, 145, 90, 164, 9, 95, 220, 97, 53, 143, 11, 61, 231, 188, 191, 147, 224, 104, 246, 191, 129, 13, 165, 95, 110, 83, 58, 33, 143, 240, 89, 160, 119, 187, 99, 105, 191, 198, 165, 10, 33, 128, 46, 87, 144, 175, 111, 186, 213, 253, 203, 0, 174, 142, 42, 152, 253, 46, 82, 26, 8, 87, 235, 243, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 107, 227, 238, 11, 176, 71, 2, 2, 180, 249, 247, 164, 233, 17, 65, 74, 188, 229, 231, 3, 249, 105, 139, 148, 211, 172, 52, 242, 117, 159, 133, 174, 0, 202, 154, 59, 0, 0, 0, 0, 0, 148, 53, 119, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 156, 0, 0, 0, 34, 192, 118, 35, 128, 32, 126, 54, 71, 146, 146, 47, 241, 227, 117, 146, 224, 12, 197, 13, 212, 150, 35, 113, 137, 30, 41, 185, 2, 214, 159, 231, 0, 0, 0, 0, 0, 0, 0, 0, 108, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 21, 157, 223, 59, 68, 65, 192, 61, 156, 47, 143, 160, 51, 78, 167, 170, 210, 242, 48, 241, 15, 154, 186, 133, 102, 34, 135, 25, 212, 170, 198, 203, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 1, 21, 157, 223, 59, 68, 65, 192, 61, 156, 47, 143, 160, 51, 78, 167, 170, 210, 242, 48, 241, 15, 154, 186, 133, 102, 34, 135, 25, 212, 170, 198, 203, 0, 0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 202, 154, 59, 0, 0, 0, 0, 0, 148, 53, 119, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1] }] }), message_hash: 2wdbn29BpLVTE5Fk44GUWBiNzsjRniJiMa8W5C97cdUF, is_simple_vote_tx: false, signatures: [4Bfz5Ecc2P2YdS97GWJfRgoj2b4ZJ6qeYXdCEvFZqeN3x8bfu6z1uRCGtPwaSMwk72HHjQMBiRHesa1qrrBDzXrM] }

Error Source

The error is getting raised from this function:

solana/program-runtime/src/invoke_context.rs

Lines 910 to 913 in 577fa4e

	fn process_executable_chain(
	&mut self,
	instruction_data: &[u8],
	) -> Result<(), InstructionError> {

Stepping through, the code is entering this if branch and getting to the end without returning:

solana/program-runtime/src/invoke_context.rs

Lines 920 to 937 in 577fa4e

	if solana_sdk::native_loader::check_id(owner_id) {
	for entry in self.builtin_programs {
	if entry.program_id == *root_id {
	drop(borrowed_root_account);
	// Call the builtin program
	return (entry.process_instruction)(
	1, // root_id to be skipped
	instruction_data,
	self,
	);
	}
	}
	if !self.feature_set.is_active(&remove_native_loader::id()) {
	drop(borrowed_root_account);
	let native_loader = NativeLoader::default();
	// Call the program via the native loader
	return native_loader.process_instruction(0, instruction_data, self);
	}

which then falls through to here:

solana/program-runtime/src/invoke_context.rs

Line 951 in 577fa4e

Err(InstructionError::UnsupportedProgramId)

Reproducing Locally

The issue can be easily reproduced by pulling down this ledger.

Then, simply run solana-ledger-tool verify --ledger <expanded_path>; the snapshot in the ledger is at slot 114622492 so only need to replay the one slot to see 114622493 results.

The good results (ie 1.8.14) are:

[2022-02-15T22:25:24.401281928Z INFO  solana_runtime::bank]
    bank frozen: 114622493
    hash: 6SWtqmnoJ6GQuA14gzbwXgwD6QsU7dmtAs69tzaZMPSY
    accounts_delta: EjeEbrLfhbUsMx2PDE3imBPrXZSWvpN5hr5TAwKtHbkY
    signature_count: 74
    last_blockhash: BGigZST2xozAjLd9rrUpqCXvMvyHoiUGJgK3WeNTUsmS
    capitalization: 1086589784757103540
[2022-02-15T22:25:24.401293889Z INFO  solana_runtime::bank]
    accounts hash slot: 114622493 stats:
    BankHashStats {
        num_updated_accounts: 704,
        num_removed_accounts: 0,
        num_lamports_stored: 17835121367324991,
        total_data_len: 5277560,
        num_executable_accounts: 0
    }

The bad results (1.9 / master) are:

[2022-02-15T22:33:56.253140354Z INFO  solana_runtime::bank]
    bank frozen: 114622493
    hash: 32BU6rS68M5mnPfPcFNBpPSaj4UvfYJx5hYdMStykcWi
    accounts_delta: Bo4wow3GfcnCSnjrYDAup77zSWMnA2JzPVz84joPA3Xq
    signature_count: 74
    last_blockhash: BGigZST2xozAjLd9rrUpqCXvMvyHoiUGJgK3WeNTUsmS
    capitalization: 1086589784757103540
[2022-02-15T22:33:56.253150341Z INFO  solana_runtime::bank]
    accounts hash slot: 114622493 stats:
    BankHashStats {
        num_updated_accounts: 698,
        num_removed_accounts: 0,
        num_lamports_stored: 17835055086102000,
        total_data_len: 5276900,
        num_executable_accounts: 0
    }

[t-nelson]

Same code block in 1.8.

solana/runtime/src/message_processor.rs

Lines 662 to 688 in 5c3575c

	if native_loader::check_id(&root_account.owner()?) {
	for (id, process_instruction) in &self.programs {
	if id == root_id {
	invoke_context.remove_first_keyed_account()?;
	// Call the builtin program
	return process_instruction(program_id, instruction_data, invoke_context);
	}
	}
	if !invoke_context.is_feature_active(&remove_native_loader::id()) {
	// Call the program via the native loader
	return self.native_loader.process_instruction(
	&native_loader::id(),
	instruction_data,
	invoke_context,
	);
	}
	} else {
	let owner_id = &root_account.owner()?;
	for (id, process_instruction) in &self.programs {
	if id == owner_id {
	// Call the program via a builtin loader
	return process_instruction(program_id, instruction_data, invoke_context);
	}
	}
	}
	}
	Err(InstructionError::UnsupportedProgramId)

cc/ @Lichtso I think you were refactoring around here?

[steviez]

I did a very rudimentary "bisect" since it only takes ~5 minutes to reproduce; a few results:

• All v1.9 tags produce incorrect results
• 2aa113f produced the wrong result
• 9ff5611 segfaulted (far enough back that I didn't bother looking into it)

t-nelson beat me to the punch linking the code block from 1.8 above; they look fairly similar and nothing jumped off the screen as having been translated wrong potential next step for me might be (if nobody else takes a look) figuring out what codepath / return statement is hit on 1.8

[jstarry]

I was able to repro the issue in a failing test, will writeup details shortly.

[jstarry]

The main issue is that on master/v1.9, the ed25519 program is a "precompile" instead of a "builtin" so it's no longer added to a bank's builtin programs list. That list is usually copied from the parent bank but needs to be repopulated when starting from a snapshot. So any node starting up on a non-v1.8 version won't add ed25519 to the builtins list. Lastly, this is all fixed when the prevent_calling_precompiles_as_programs feature is activated because it short circuits the typical flow where the bank's builtin programs list is used to process builtin programs.

I think the simplest patch is to check if that feature isn't activated yet and if not, add ed25519 to the bank's builtin list.

[jstarry]

Ended up with a different patch from what I just suggested. PR here: #23182

[ryoqun]

@steviez by the way, great write-up of the regression investigation. :) it was very easy to follow when reviewing #23182

[github-actions]

This issue has been automatically locked since there has not been any activity in past 7 days after it was closed. Please open a new issue for related bugs.