Fix extension logging strategy

[wirednkod]

Our logging strategy is going a bit all over the place in the extension.
This should be organised bit better.

[raoulmillais]

What there currently is:

• We have imported @polkadot/util and use it in some places.
• We have a debug helper to add trace level logging when running the extension in "dev" mode
• We use console.error and console.warn

Some thoughts on approach:

• I don't think we should be using @polkadot/util. It's an extra dependency and the extension logging needs are different from polkadot js. For starters we log to multiple different consoles (content script and background and popup and options). Secondly we don't need to be able to pretty-print the custom polkadotjs Codec types.
• The debug helper is too naive - could be improved and only does debug logging (obvs)
• Having console.warn and console.error peppered across our code makes it harder to spot when we've got left over console logging that wasn't intended.

I think we should extend the debug helper into a simple custom logging module. We can give it exactly the features we need (and no more) and it will be obvious when we leave console.logs in by mistake.

Aside: using the debug helper logger and leaving it in is absolutely fine, and actually helpful for our future selves debugging things. You don't need to worry about leaving it because end users wont ever see it.

[raoulmillais]

Also all our debug logs are ALL CAPS. I don't know why I started doing that. It's a bit over the top! 😲

[raoulmillais]

From @tomaka in chat:

Quick remark/brainstorm: when it comes to logging on the extension side, I think it'd be a good idea to keep in memory the last 500 or so lines of logs level 4 (the debug logs) and add some sort of semi-hidden button in the UI to show them
If we assume that things are working just fine, there's no point in showing logs to the end user (i.e. the person having the extension installed in their browser) anyway. So the only utility for logs is debugging in case something bad happens.

[tomaka]

What in my opinion we should do in terms of logging in the extension:

• Use log level 4 in smoldot.
• Don't output the logs in the console, but instead keep the logs in some buffer. Only the last ~500 or so lines should to be kept, otherwise our memory usage would continue increasing forever.
• Add a semi-hidden way somewhere in the extension that can display these logs. The average Joe doesn't need to know that these logs exist, it's more for developers to be able to understand problems.
• (maybe) If the ~500 log lines that we keep contain a warning or error, there should be some indication. Again, the average Joe doesn't need to see this, but for developers it's useful to be able to easily see if a warning or error has happened. Warnings or errors are generally bugs in smoldot that should be fixed, but don't necessarily prevent applications from working normally.
• If smoldot crashes: extract the log lines, and internally restart smoldot and reset the logs. Show a big indication in the UI (this time, visible for the average Joe) indicating that something terribly wrong has happened and that they should open an issue in smoldot. This should contain the logs that have been extracted.
  • One corner case is if smoldot crashes multiple times. I think that we only need to show the latest crash.

cc @Goranch3

[raoulmillais]

Can you add a quick update on the progress / status of this issue please @wirednkod ?

[wirednkod]

PR #853 covers almost whole scope except last bullet.
PR #958 covers smoldot crashes when it inits.
For covering rest of cases (smoldot crashes after init) I think there is implementation pending from @tomaka

[tomaka]

I don't know if it should be part of this issue, but the logging tab could really get some aesthetics improvements.

[wirednkod]

This is part of the UI refactor Im already doing based on @Goranch3 's figma designs:

[tomaka]

If I can give my two cents, it should really just be something like this:

[08:51:18.065] [sync-service-westend2] Sync => Disjoint
[08:51:18.069] [network] Connection(12D3KooWPVPzs42GvRBShdUMtFsk4SvnByrSdWqb6aeAAHvLMSLS, westend2) => BlockAnnounce(best_hash=0x0a6d…e335, is_best=true)
[08:51:18.069] [sync-service-westend2] Sync <= BlockAnnounce(sender=12D3KooWPVPzs42GvRBShdUMtFsk4SvnByrSdWqb6aeAAHvLMSLS, hash=0x0a6d…e335, is_best=true, parent_hash=0xcecb…0f09)
[08:51:18.069] [sync-service-westend2] Sync => Disjoint
[08:51:18.074] [sync-service-westend2] Sync => HeaderVerified(hash=0x0a6d…e335, new_best=yes)
[08:51:18.074] [runtime-westend2] Worker <= InputNewBlock(hash=0x0a6d…e335, parent=0xcecb…0f09, is_new_best=true)
[08:51:18.075] [runtime-westend2] Worker => OutputNewBlock(hash=0x0a6d…e335, is_new_best=true)
[08:51:18.075] [tx-service-westend2] BestChainUpdate(new-best-block=0x0a6d…e335, included-transactions={}, retracted-transactions={})
[08:51:18.078] [network] Connection(12D3KooWNg8iUqhux7X7voNU9Nty5pzehrFJwkQwg1CJnqN3CTzE, westend2) => BlockAnnounce(best_hash=0xd063…ad07, is_best=true)
[08:51:18.078] [network] Connection(12D3KooWGi1tCpKXLMYED9y28QXLnwgD4neYb1Arqq4QpeV1Sv3K, westend2) => BlockAnnounce(best_hash=0x0a6d…e335, is_best=true)
[08:51:18.078] [sync-service-westend2] Sync <= BlockAnnounce(sender=12D3KooWNg8iUqhux7X7voNU9Nty5pzehrFJwkQwg1CJnqN3CTzE, hash=0xd063…ad07, is_best=true, parent_hash=0xcecb…0f09)
[08:51:18.078] [sync-service-westend2] Sync => Disjoint

The level can be indicated with a background color on the line.

And the font should be monospace

[wirednkod]

This can close as all comments from @tomaka are implemented - except the following:

If smoldot crashes: extract the log lines, and internally restart smoldot and reset the logs. Show a big indication in the UI (this time, visible for the average Joe) indicating that something terribly wrong has happened and that they should open an issue in smoldot. This should contain the logs that have been extracted.
One corner case is if smoldot crashes multiple times. I think that we only need to show the latest crash.

which was discussed with @Goranch3 and will be covered during the redesign of UI. An issue #1031 has opened - thus this issue can close now.