Understanding the Cosmos Daemon Output and Changing the Log Level

Over the last couple of weeks, I have been working with Cosmos to build a dApp chain. The tooling they provide is excellent. If you follow the namecoin tutorial you get a good feel for the pieces that make up a Cosmos dApp chain.

Once you have gotten to the point where you start trying to run this chain via the cli the logging may not seem immediately obvious but once you grok it the first time it is very intuitive and easy to follow.

For example when you have signed a transaction, broadcast it and had no issues you should see logging similar to the below:

I[2019-08-29|18:25:19.528] Executed block                               module=state height=3 validTxs=1 invalidTxs=0
I[2019-08-29|18:25:19.536] Committed state                              module=state height=3 txs=1 appHash=0DCF65F8289AF1ED98B3BA71E6CF446C8A99F6B0007B12CB6E19F756C666800B

For every block, there are 2 logs the first telling you how many transactions are involved and the second telling you that this block has been committed. Most of the time when nothing is happening on the chain validTxs=0 and so will invalidTxs=0.

When there is an error with a transaction you will see logs similar to the below:

I[2019-08-29|18:28:00.247] Executed block                               module=state height=34 validTxs=0 invalidTxs=0
I[2019-08-29|18:28:00.255] Committed state                              module=state height=34 txs=0 appHash=07EB9CB827483796295C238DDA688E073CE4A7A2A46B413367A99D87BA22B0A5

We can see some error happened but the transaction receipt on the cli shows a success (the transaction was broadcast successfully but this does not mean it has been validated).

To make the daemon output errors you need to change the log level to debug. Using the namespace daemon nsd to illustrate (the flags should still be the same on any Cosmos Daemon) I would run it as follows:

nsd start --trace --log_level 'main:debug,state:debug,*:error'

Now if there is an error it outputs as below (note the D in the beginning of the log which indicates this error output is coming from a debug log):

I[2019-08-29|18:28:00.247] Executed block                               module=state height=34 validTxs=0 invalidTxs=0
D[2019-08-29|18:28:00.255] Commit synced                                module=main commit=436F6D6D697449447B5B37203233352031353620313834203339203732203535203135302034312039322033352031343120323138203130342031343220372036302032323820313637203136322031363420313037203635203531203130332031363920313537203133352031383620333420313736203136355D3A32327D
I[2019-08-29|18:28:00.255] Committed state                              module=state height=34 txs=0 appHash=07EB9CB827483796295C238DDA688E073CE4A7A2A46B413367A99D87BA22B0A5
D[2019-08-29|18:28:05.289] Invalid tx                                   module=state code=4 log="[{\"msg_index\":0,\"success\":false,\"log\":\"{\\\"codespace\\\":\\\"sdk\\\",\\\"code\\\":4,\\\"message\\\":\\\"An sdk error you returned from your code\\\"}\"}]"

We can now clearly see what the error is on the last line (this should match the SDK error you return in your code).

Success cases with this level of logging output as below:

I[2019-08-29|18:33:02.116] Executed block                               module=state height=5 validTxs=1 invalidTxs=0
D[2019-08-29|18:33:02.123] Commit synced                                module=main commit=436F6D6D697449447B5B373920383520323230203520313437203137342032323420323120353120313839203135332031363820313130203130302032203539203134302039322039392032372033352031353520343320323331203139362032332033322036352036332031353620313933203234335D3A357D
I[2019-08-29|18:33:02.123] Committed state                              module=state height=5 txs=1 appHash=4F55DC0593AEE01533BD99A86E64023B8C5C631B239B2BE7C41720413F9CC1F3

One this that is strange is that these errors are logged at debug level and not error level. It may be that only panics log at error level since SDK errors may pop up often for things like validation errors. Either way using the above setup in dev greatly aids in debugging interactions with the chain.