Add more debug output from multi-test

[ethanfrey]

It can be hard to track down failures, especially when they happen in multiple levels of submessages. Getting the full backtrace can be helpful, but it seems I am the only one who can really parse those to see what the issue was.

The main info I pull out is what the messages are and which depth of the submessages we are at. We can add some dbg!() statements to the framework... maybe when each message is executed, when each submessage is executed, each query is called, etc. basically all contract -> contract interactions could be traced.

Since multi-test only compiles for test environments (not into wasm), we can just dump everything with debug logs. Maybe we have some way to configure how many/which logs to dump, but first let's make sure we have all the needed info there, then make it optional.

[ueco-jb]

I'd rather not use dbg!(), since it's quite messy if there are more then couple of them.
I recommend using something like slog with customizable levels of logging, to not clutter the output.
Also, I wonder if we could figure some reasonable way of enabling logs only for particular modules we wan't to debug, for example instantiation, execution, query etc.

In general, ability to turn all logging, or for example log all submessages on debug level and others only on error.

[ueco-jb]

@uint I see you've assigned youself here - could you share your vision/approach?

[uint]

@uint I see you've assigned youself here - could you share your vision/approach?

I don't have one yet. I was going to first try and reproduce the situations when errors happen and the output is confusing (I'm guessing any multitests with a bunch of nested contract -> contract calls?), poke at how multitest/cosmwasm_std mocks work, etc. Basically I need to understand the issue better.

slog (or tracing?) sounds good.

Since we use anyhow in a lot of places, kind of curious if there's any use for anyhow::Error::context. Or wrapping errors in context in some other fashion.

If you already have ideas about this and wanted to tackle it, I can pass it on and work on something else. I was only starting to look at this.

[ueco-jb]

If you already have ideas about this and wanted to tackle it, I can pass it on and work on something else. I was only starting to look at this.

Nah, I'm actually curious.

I was going to first try and reproduce the situations when errors happen and the output is confusing (I'm guessing any multitests with a bunch of nested contract -> contract calls?)

I remember that I struggled a lot for example when I was introducing migration into tgrade-validator-voting contract. I was getting output from multitest framework - something like "Unauthorized", and that was all. And debug stack trace was going looong into multi test insides...
Later Ethan figured, that contract needs to be privileged to sudo to allow migration - but I'm 100% I wouldn't get that info from any logs.

[uint]

I remember that I struggled a lot for example when I was introducing migration into tgrade-validator-voting contract. I was getting output from multitest framework - something like "Unauthorized", and that was all. And debug stack trace was going looong into multi test insides... Later Ethan figured, that contract needs to be privileged to sudo to allow migration - but I'm 100% I wouldn't get that info from any logs.

Ahhh, I think @hashedone had a similar problem. Thanks for that. It sounds annoying.

[uint]

Something like this is possible by making the multitest lib attach context to errors.

---- multitest::voting::executing_slashing_proposals_works stdout ----
thread 'multitest::voting::executing_slashing_proposals_works' panicked at 'called `Result::unwrap()` on an `Err` value: Contract returned an error on execute
Contract address: Contract #4
Message sender: voter2
Funds: []
Message dump:
Execute { proposal_id: 1 }


Caused by:
    0: Contract returned an error on execute
       Contract address: Contract #2
       Message sender: Contract #4
       Funds: []
       Message dump:
       Slash { addr: "voter1", portion: Decimal(Uint128(500000000000000000)) }
       
    1: Caller is not admin', contracts/tgrade-oc-proposals/src/multitest.rs:522:48

I kind of like the approach of giving errors more information, but I have two concerns to figure out:

1. This looks a little ugly in test output.
2. The attached context currently messes up tests that downcast anyhow errors.

Would you still want logs, too? Or prefer logs over this?

[ueco-jb]

This looks a little ugly in test output.

But this is debug? Those are opt-in, so I wouldn't worry about prettines if they are giving more valueable info.
Beside that, those are looking nicely formatted, what to want more. :)

And I don't quite get the second point, you mean that logs are crossing each other?

Best if you could attach some dumps.

Would you still want logs, too? Or prefer logs over this?

If this could be an option to enable I wouldn't mind to have that context anyway.

[uint]

And I don't quite get the second point, you mean that logs are crossing each other?

Actually, I just pushed a draft PR to show you what I'm doing. I'll explain there. #597

[ethanfrey]

Great solution for execute. We should support at least query and instantiate as well. (More complex ones can be added in as-needed follow-ups). #597 (comment)

[uint]

Great solution for execute. We should support at least query and instantiate as well. (More complex ones can be added in as-needed follow-ups). #597 (comment)

When you say "support instantiate", do you mean situations when a contract instantiates another contract from a code id?

[ethanfrey]

Yup. Both that and when an instantiate call triggers another call (like execute or instantiate)

Instantiate and Query calls are not wrapped in a context afaik.

[uint]

when an instantiate call triggers another call (like execute or instantiate)

The instantiate -> execute case should work as it is, though I guess a test to show that would be nice.

Instantiate and Query calls are not wrapped in a context afaik.

I did that in the final commit in that PR (just before merging) since it was really simple to add and looked more consistent. But not all the possible situations are tested.

[ethanfrey]

I did that in the final commit in that PR (just before merging) since it was really simple to add and looked more consistent. But not all the possible situations are tested.

Ah, I didn't see that. Let me look again at the merged PR

[ethanfrey]

You are right. It was done, I will close this.

I did see some other minor cleanup you can make in a follow-up PR if you think it is relevant.
#597 (review)

But this issue is closed 👍