Skip to content
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.

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

feature: mpl-utils: Log assert failures for easier debugging #1163

Open
wants to merge 4 commits into
base: master
Choose a base branch
from

Conversation

KartikSoneji
Copy link
Contributor

At the moment, when an assertion fails, the program only throws an error about the type of assertion that has failed.
This there no indication to which account is the incorrect one, making it a nightmare to debug.

For example:

> Program invoked: Token Metadata Program
  > Program logged: "IX: Delegate"
  > Program logged: "Public key does not match expected value"
  > Program consumed: 18426 of 373338 compute units
  > Program returned error: "custom program error: 0x9a"

This PR adds logs that print the account that failed the assertion and some debug information about why the assertion failed.
They only trigger if the assertion fails, so shouldn't effect the compute unit budget during normal operation.

@KartikSoneji KartikSoneji requested a review from a team as a code owner November 11, 2023 07:22
@KartikSoneji KartikSoneji requested review from febo and blockiosaurus and removed request for a team November 11, 2023 07:22
@blockiosaurus
Copy link
Contributor

Thanks for this PR! It is indeed awful to debug any of these issues. The lack of logging of specific failures is unfortunately a necessity due to program size and compute constraints.

However, ExtendProgram is scheduled to be enabled Monday so that will hopefully solve the size issue.

@KartikSoneji
Copy link
Contributor Author

Oh does calling sol_log() really increase the program size so much?
Or is it format!()? I can refactor to remove calls to format if that's the issue.

@blockiosaurus
Copy link
Contributor

It's the actual strings. I think we have more space now but we were a handful of bytes from the max a couple months ago.

@KartikSoneji
Copy link
Contributor Author

Ah I see.
Let me know if the messages are too long, I think I can cut it down to just a few extra bytes.
Eg: <actual key>!=<expected key>
Even terse log messages like this should be a great help while debugging.

@KartikSoneji
Copy link
Contributor Author

Hi, just a friendly ping on this.

@blockiosaurus
Copy link
Contributor

Huzzah, we have space now! Can you just change these to use msg! to be consistent with our other programs? That should also be a little cleaner as it uses the same string formatting as println!.

@KartikSoneji
Copy link
Contributor Author

Done!

@@ -33,6 +42,12 @@ pub fn assert_owned_by(
error: impl Into<ProgramError>,
) -> ProgramResult {
if account.owner != owner {
msg!(
"owner assertion failed for {key}: expected {expected}, got {actual}",
Copy link
Contributor

Choose a reason for hiding this comment

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

"invalid owner for {key} ({actual} != {expected})"

@@ -47,6 +62,14 @@ pub fn assert_derivation(
) -> Result<u8, ProgramError> {
let (key, bump) = Pubkey::find_program_address(path, program_id);
if key != *account.key {
msg!(
"derivation assertion failed for {actual_key}:\n
Copy link
Contributor

Choose a reason for hiding this comment

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

"invalid derivation {actual_key} != {key}"

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Looks like \n is not needed, I'll remove that.

Copy link
Contributor

@febo febo left a comment

Choose a reason for hiding this comment

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

What do you think if we make the log messages a bit shorter so the log does not get cluttered?

@KartikSoneji
Copy link
Contributor Author

Hmm I really think the log messages should provide as much information to debug as possible.
Plus I think in most cases programs failing an assertion is a fatal error, so this should be the last message that is in the log.

@febo
Copy link
Contributor

febo commented Nov 23, 2023

Hmm I really think the log messages should provide as much information to debug as possible. Plus I think in most cases programs failing an assertion is a fatal error, so this should be the last message that is in the log.

I agree that log messages should be descriptive, but the observation here is because this is a library not a program. A program might handle an assert failure so it does not end up being a "fatal error".

@KartikSoneji
Copy link
Contributor Author

OK, I'll shorten the messages for assert_signer, assert_initialized and assert_rent_exempt.
But I think assert_owned_by, assert_derivation are almost always fatal errors so should clearly communicate the issue without having to refer back to the source code of the program.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants