Closed phritz closed 3 years ago
aboodman
commented
3 years ago I think we don't need a setLogLevel RPC because of the way that the developer console in browsers integrates with rust/wasm bindings. We should just set this statically to Debug.
aboodman
commented
3 years ago I changed the title of this bug to get at what I think is more the real issue. Some history here:
The last time this was changed was https://github.com/rocicorp/repc/pull/189/commits/9f3f25c2729f537b8cc6556ba9dd601684dcd6ca as part of https://github.com/rocicorp/repc/pull/189.
The point of 189 was to ensure that we only do work for logging if the runtime log level indicates it is needed.
Apparently, when I was doing this work, I convinced myself that the UI in the web developer console was actually affecting the runtime log level that the rust log infrastructure was seeing. But that seems to not be true now.
Either:
If 2, then sad panda because it means that we need to do one of: a. implement setLogLevel (which would be more work for us, and less usable for developers) b. be more careful with where we sprinkle debug lines, because we will basically always have the log level at Debug c. default this statically, but do it differently in debug build than release build, and tell developers they need to use debug build to get verbose output
a and c are pretty shitty dx so i would probably choose b if those were the only options.
phritz
commented
3 years ago I convinced myself that the UI in the web developer console was actually affecting the runtime log level that the rust log infrastructure was seeing. But that seems to not be true now.
Yeah I think we should assume it is not true. console_log sets itself as the rust log:: logger to use and I looked through the console_log implementation and did not see any hooks or anything that provides an interface for the browser to use. There can't be anything in log:: itself, so I'm not sure what the mechanism would be. And there's nothing in the docs about this, just that console_log forwards log calls to the browser's console. calls. So seems like a safe assumption that the the setting in the dev console is a filter on what you see at some level.
The point of 189 was to ensure that we only do work for logging if the runtime log level indicates it is needed.
Apparently log:: already only does work for logging if the runtime level indicates that it is needed. When console_log inits it sets itself as the logger and sets the log:: level to what we provide. All calls to log! which the normal error! etc macros and our macros both call get filtered: it turns logging calls at a log level greater than the current max into nops: https://docs.rs/log/0.4.11/src/log/macros.rs.html#31-55. So I think the level check in our macros are redundant, or rather, that they only save allocating the string we would otherwise send to log::log, which is maybe reason enough to keep it.
we need to do one of: a. implement setLogLevel (which would be more work for us, and less usable for developers)
The implementation of setLogLevel is exactly one line (log::set_max_level(...)) and the rpc will have one field, an integer, so the amount of work in repc is small. I would imagine it is a similarly small amount of work in js unless I'm missing something.
I agree that the ux is less good. A bookmarklet or similar could make it easier for devs to control the level? Or maybe the bindings export top-level functions repcLogDebug(), repcLogInfo(), etc so it's easy to switch with a single line of js in the console?
b. be more careful with where we sprinkle debug lines, because we will basically always have the log level at Debug
I would like to assert that we will always want to have -- need -- a spewy log level that dumps more information than anyone wants under normal circumstances. We (replicache devs) need that sometimes to understand at a fine-grained level of detail what is happening. Most customers will not need it, except when something mysterious is going on and we want them to turn that level on and send us the output. In this case it is an especially nice feature that the level can be set at runtime: they don't need to reload to set the level, which would potentially destroy the interesting state that was causing an issue.
The spewy log level is currently debug, which we define as "verbose information about what's happening that might be useful to a developer". Info is currently defined as "information that is immediately useful to the developer, or an important change of state. Info logs should not be spammy". I think maybe the issue is that we are confusing what "developer" means. Like maybe we need a distinction between developer in the sense of "as a dev using replicache i want to see more detail" and "as a dev of replicache i want to see more detail", the latter being more spewy. OR that we need to revisit the meaning of our existing log levels.
In either case, I could imagine us maybe going down one of two paths (maybe there are others): b1. Define info logs to be what's useful for a dev using replicache. Let's carefully choose log lines to include in info such that it gives the dev what they need. Keep debug for spewy output that devs of replicache might want to see, or for when info doesn't reveal enough. Default to info logging in development, none in production. b2. Keep info for important changes of state and info immediately useful and define debug to be a carefully groomed set of lines for someone using replicache. Move spewy log lines that don't make the cut to a new level, trace. Default to debug in development, info (or none) in production.
I think b2 is what you are suggesting here.
c. default this statically, but do it differently in debug build than release build, and tell developers they need to use debug build to get verbose output
Let's eliminate this one from consideration. Changing at runtime is really nice.
I think we should do (a) introduce a setloglevel rpc AND do either b1 or b2. I favor b1 because it is fewer levels but b2 also seems fine.
Would this address the issue?
aboodman
commented
3 years ago On Sun, Nov 15, 2020 at 9:45 AM Phritz notifications@github.com wrote:
I convinced myself that the UI in the web developer console was actually affecting the runtime log level that the rust log infrastructure was seeing. But that seems to not be true now.
Yeah I think we should assume it is not true. console_log sets itself as the rust log:: logger to use and I looked through the console_log implementation and did not see any hooks or anything that provides an interface for the browser to use. There can't be anything in log:: itself, so I'm not sure what the mechanism would be. And there's nothing in the docs about this, just that console_log forwards log calls to the browser's console. calls. So seems like a safe assumption that the the setting in the dev console is a filter on what you see at some level.
Alright. Thanks for investigating and sorry for screwing this up.
The point of 189 was to ensure that we only do work for logging if the runtime log level indicates it is needed.
Apparently log:: already only does work for logging if the runtime level indicates that it is needed. When console_log inits it sets itself as the logger and sets the log:: level https://docs.rs/console_log/0.2.0/src/console_log/lib.rs.html#211-215 to what we provide. All calls to log! which the normal error! etc macros and our macros https://github.com/rocicorp/repc/blob/d2e03db36a9a436d32da60abc9a863543384ba18/src/util/rlog/logger.rs#L65 both call get filtered: it turns logging calls at a log level greater than the current max into nops: https://docs.rs/log/0.4.11/src/log/macros.rs.html#31-55. So I think the level check in our macros are redundant, or rather, that they only save allocating the string we would otherwise send to log::log, which is maybe reason enough to keep it.
Yes, that's what I meant by "work". The allocating for log lines can be surprisingly costly, especially in tight loops. Contrary to my straw man in the last message I do like not having to think at all about where you put log lines and just know that they won't be expensive under normal circumstances.
we need to do one of: a. implement setLogLevel (which would be more work for us, and less usable for developers)
The implementation of setLogLevel is exactly one line ( log::set_max_level(...)) and the rpc will have one field, an integer, so the amount of work in repc is small. I would imagine it is a similarly small amount of work in js unless I'm missing something.
Ah yes. I implemented setLogLevel once before and the bit that got gnarly was that I wanted it to apply to the logging in the bindings code too. But since RPCs are async I could not just use the level in the rust (go at the time) as the source of truth.
Actually in Rust/wasm it is possible to do a synchronous RPC and have it not be too expensive, so that's a possibility.
On reflection though, that was probably over engineering and we should maybe have a setLogLevel RPC that is used basically in the case that something weird is going on and we want to ask devs to give us extra info. Otherwise, the bindings-level logging would work the normal way.
I agree that the ux is less good. A bookmarklet or similar could make it easier for devs to control the level?
b. be more careful with where we sprinkle debug lines, because we will basically always have the log level at Debug
I would like to assert that we will always want to have -- need -- a spewy log level that dumps more information than anyone wants under normal circumstances. We (replicache devs) need that sometimes to understand at a fine-grained level of detail what is happening. Most customers will not need it, except when something mysterious is going on and we want them to turn that level on and send us the output. In this case it is an especially nice feature that the level can be set at runtime: they don't need to reload to set the level, which would potentially destroy the interesting state that was causing an issue.
Yup. Actually in the case I was debugging that led to me looking at this, the spewey logs were exactly what I reached for because I knew they would help me understand and I was sad to not be able to access them.
You are right, thank you for reminding me.
The spewy log level is currently debug, which we define as "verbose information about what's happening that might be useful to a developer". Info is currently defined as "information that is immediately useful to the developer, or an important change of state. Info logs should not be spammy". I think maybe the issue is that we are confusing what "developer" means. Like maybe we need a distinction between developer in the sense of "as a dev using replicache i want to see more detail" and "as a dev of replicache i want to see more detail", the latter being more spewy.
If this is the case, I could imagine us maybe going down one of two paths (maybe there are others): b1. Define info logs to be what's useful for a dev using replicache. Let's carefully choose log lines to include in info such that it gives the dev what they need. Keep debug for spewy output that devs of replicache might want to see, or for when info doesn't reveal enough. Default to info logging in development, none in production. b2. Keep info for important changes of state and info immediately useful and define debug to be a carefully groomed set of lines for someone using replicache. Move spewy log lines that don't make the cut to a new level, trace. Default to debug in development, info (or none) in production.
I think b2 is what you are suggesting here.
c. default this statically, but do it differently in debug build than release build, and tell developers they need to use debug build to get verbose output
Let's eliminate this one from consideration. Changing at runtime is really nice.
Agreed.
I think we should do (a) introduce a setloglevel rpc AND do either b1 or b2. I favor b1 because it is fewer levels but b2 also seems fine.
No, you are right, I just momentarily forgot how useful the debug logging is, and to who (us).
The right solution is to simply implement the setLogLevel RPC and be done with it.
Would this address the issue?
— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/rocicorp/repc/issues/243#issuecomment-727625582, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAATUBGJO6FVXB4MXXFLKI3SQAVXJANCNFSM4TBYP5AA .
aboodman
commented
3 years ago Bumping prio and milestone of this cuz it sure makes debugging difficult.
right now it is set statically https://github.com/rocicorp/repc/blob/560ec4b7d318264400c8c45f0961026bedf20b88/src/wasm.rs#L28