Replace custom logging by tracing

[WorldSEnder]

Description

Fixes #2790
Fixes #2795

Replaces the logging of lifecycle events by the tracing crate. The nice thing is that the behaviour, including compile-time maximal levels, can be configured in the final executable, and is automatically applied in all crates emitting traces. Does not include a subscriber, this should also be configured in the final binary crate.

Not included (yet?) is the configuration of all examples crates to turn off tracing events at compile time, so I wouldn't be surprised by a small increase in bundle size per the benchmarks. If it turns out to be a sizeable increase, I will add this. EDIT: seems to at least balanced by the removed code.

I have tried tracing-wasm crate for consuming the logs/as a subscriber, but there seems to be some incompatibility with chrome (works better on Firefox) that leads to weirdly long measurements. The span and events are fine though, the problem is more with the performance browser API.

Another nice feature is that one can turn on tracing = { feature = ["log-always"] } to forward events to log consumers, which works with wasm_logger.

Checklist

• I have reviewed my own code

[github-actions]

Visit the preview URL for this PR (updated for commit 00ae994):

https://yew-rs-api--pr2814-tracing-30juq21r.web.app

_{(expires Sat, 13 Aug 2022 23:07:15 GMT)}

_{🔥 via Firebase Hosting GitHub Action 🌎}

[github-actions]

Benchmark - SSR

Yew Master

Benchmark	Round	Min (ms)	Max (ms)	Mean (ms)	Standard Deviation
Baseline	10	307.586	333.244	315.968	10.428
Hello World	10	1042.002	1122.215	1064.429	28.737
Function Router	10	4098.764	4497.601	4166.255	129.520
Concurrent Task	10	1011.198	1013.625	1012.471	0.906

Pull Request

Benchmark	Round	Min (ms)	Max (ms)	Mean (ms)	Standard Deviation
Baseline	10	353.728	374.600	357.449	6.567
Hello World	10	1081.413	1161.111	1099.532	24.331
Function Router	10	4149.125	4167.101	4159.302	5.892
Concurrent Task	10	1011.421	1012.649	1012.044	0.368

[github-actions]

Size Comparison

examples	master (KB)	pull request (KB)	diff (KB)	diff (%)
boids	172.722	172.002	-0.720	-0.417%
contexts	109.580	109.019	-0.562	-0.512%
counter	86.526	85.895	-0.632	-0.730%
counter_functional	87.179	86.532	-0.646	-0.742%
dyn_create_destroy_apps	89.619	89.042	-0.577	-0.644%
file_upload	102.758	102.024	-0.733	-0.714%
function_memory_game	166.896	166.195	-0.701	-0.420%
function_router	351.738	351.130	-0.608	-0.173%
function_todomvc	161.595	160.707	-0.888	-0.549%
futures	225.433	224.707	-0.726	-0.322%
game_of_life	107.137	106.399	-0.737	-0.688%
immutable	208.692	208.344	-0.349	-0.167%
inner_html	83.687	83.041	-0.646	-0.771%
js_callback	112.752	112.193	-0.559	-0.495%
keyed_list	195.249	194.545	-0.704	-0.361%
mount_point	86.170	85.533	-0.637	-0.739%
nested_list	115.645	115.082	-0.562	-0.486%
node_refs	93.464	92.957	-0.507	-0.542%
password_strength	1546.080	1545.828	-0.252	-0.016%
portals	97.259	96.695	-0.563	-0.579%
router	321.074	320.486	-0.588	-0.183%
simple_ssr	154.248	153.716	-0.532	-0.345%
ssr_router	397.798	397.092	-0.706	-0.177%
suspense	110.486	109.915	-0.571	-0.517%
timer	89.259	88.673	-0.586	-0.656%
todomvc	142.623	141.729	-0.894	-0.627%
two_apps	87.190	86.560	-0.631	-0.724%
web_worker_fib	153.608	153.015	-0.594	-0.387%
webgl	87.539	86.894	-0.646	-0.737%

✅ None of the examples has changed their size significantly.

[ranile]

The problem with this approach is that the binary must be recompiled every time logging level is to be changed. Unlike CLI applications (for example), there's no RUST_LOG environment variable that can be set. The setting must be hard-coded into the binary.

Browser dev tools take care of this with their logging levels and filers. See them for Firefox and Chrome

I'm not really keen on adding tracing here. I think we should use console.* functions instead and let the browser handle this

[WorldSEnder]

The problem with this approach is that the binary must be recompiled every time logging level is to be changed. [..] The setting must be hard-coded into the binary.

I don't think that's generally true. By default, all tracing events are statically enabled. Then, you register a tracing subscriber on startup. Not sure which one is best here, but there's a lot to choose from, and it's not too hard to write your own. Then, at runtime, the subscriber can once again decide to filter spans and events by their metadata, including their log level and module, or handle them in any way they see fit - or not at all. Since there is no environment variables to read, one could still read a global from javascript to determine the log level on initialization.

To make the analogy to logging in other programs, it's env_logger that reads RUST_LOG to determine the log level and handling, but logs are still emitted with the log crate. tracing is an upgrade on log (and it has some compatibility modes), and it also doesn't determine how the traces are handled. You do that by registering a subscriber and it's the end user that decides what to use.

On the other hand, using console.* is hard coded and can't be changed or used by other libraries, and there is no way a yew app can change it.

To also quell some fears about code size: the above comparison actually has all tracing callsites (events and spans) statically enabled (they can still be filtered by the eventual subscriber), yet the bundle size actually decreases.

[ranile]

I wasn't really concerned about code size because of dead code elimination, in case tracing isn't used.

Since there is no environment variables to read, one could still read a global from javascript to determine the log level on initialization.

I didn't think of this approach, but it makes sense. Read a JS variable and then use it initialize the tracing subscriber.

Would it make sense to tracing for our other logs?

[WorldSEnder]

Would it make sense to [use] tracing for our other logs?

I guess so. Incidentally, that would also address #2795.

[futursolo]

I am in favour of switching to log or tracing instead of gloo::console.

As This allows a logging experience unified for wasm and non-wasm environments. Logs from other crates can also be captured if we encourage users to register a logger with log crate.

In addition, a logger does not have to always write to console. With tracing / log, we can implement a custom logger that shows an overlay like webpack when an error is logged via error!.

[ranile]

Looks good to me. It should be documentation that we use tracing for logging so users know to enable it. Maybe we can set it up, like the console panic hook?

If you don't want to document it in this PR, please do create an issue for it.

[WorldSEnder]

Follow up is linked. Setting up a subscriber by default sounds like a good idea, unless it has the potential of overriding an already set user defined one. I think it's simpler to find a good example of one to use, usually, they can be setup in a single line of code, like tracing_wasm::set_as_global_default();.