Materialize: UX - materialized startup - logfile does not report information such as startup time, version, config etc

[krishmanoh2]

Could we report more details in materialized.log on startup?

Start-time
Version
Flags passed to mz
OS details and system specs
If any existing schema present in the data directory - details on that

@rjnn

[ruchirK]

When I run Materialize like so:

MZ_LOG=info cargo run -- --dev -w 1 --log-file=stderr

The first lines in my log output are:

Oct 23 13:37:19.170  INFO materialized: materialized version: v0.5.1-dev (cb05bd525)
invoked as: target/debug/materialized --dev -w 1 --log-file=stderr
environment:
MZ_LOG=info
=======================================================================
Thank you for trying Materialize!

We are interested in any and all feedback you have, which may be able
to improve both our software and your queries! Please reach out at:

    Web: https://materialize.io
    GitHub issues: https://github.com/MaterializeInc/materialize/issues
    Email: [email protected]
    Twitter: @MaterializeInc
=======================================================================

materialized v0.5.1-dev (cb05bd525) listening on 0.0.0.0:6875...
Oct 23 13:37:19.176  INFO coord::catalog: create source mz_catalog.mz_dataflow_operators (s1000)
Oct 23 13:37:19.177  INFO coord::catalog: create index mz_catalog.mz_dataflow_operators_primary_idx (s1001)

which captures start time, version and flags (and environment variables) passed to Materialize at least

[rjnn]

That's interesting. Perhaps we should upgrade some of those from info, because so far I'm running

materialized -w 4

and my start messages is:

=======================================================================
Thank you for trying Materialize!

We are interested in any and all feedback you have, which may be able
to improve both our software and your queries! Please reach out at:

    Web: https://materialize.io
    GitHub issues: https://github.com/MaterializeInc/materialize/issues
    Email: [email protected]
    Twitter: @MaterializeInc
=======================================================================

materialized v0.5.1-dev (2965421f8) listening on 0.0.0.0:6875...

and my log file is completely blank.

[ruchirK]

sorry, I don't think this is tied to the MZ_LOG=info flag. I just included that to demonstrate that we capture env variables too. I did a few more tests and it seems like we only capture the initial details if the log file is set to stderr (regardless of MZ_LOG) and that output doesn't show up if log-file is set to another file (even stdout)

[ruchirK]

i think i see the issue one sec pr incoming

[ruchirK]

I'm not going to put out a PR rn because I can't tell how to generate a proper fix but the issue is in

348                 .with(LevelFilter::WARN)
349                 .with(fmt::layer().with_writer(io::stderr))

in src/materialized/src/bin/materialized.rs basically when the user specifies a log file that is not stderr we want to route everything at the specified log level (default: info) to that file, and also bubble up warn level logs to stderr, however, we instead seem to filter out all logs at a level < WARN to both the user specified file and stderr. I can't tell how to coaxtracing_subscriber into having two different log subscribers with different log level filters because the docs are inscrutable.

[awang]

Thanks Ruchir!

(commenting specifically to the initial request) I'm hugely in favor of more diagnostic info in general. However, I don't think materialized.log is the right location for data like OS details, system specs, and sources/views, as it will flood the logs, and can't be as easily queried. Some sort of structured format is much better, imo

[benesch]

I can take a look at this. I've wrestled with the tracing API before, and I think I know how to fix this.

(commenting specifically to the initial request) I'm hugely in favor of more diagnostic info in general. However, I don't think materialized.log is the right location for data like OS details, system specs, and sources/views, as it will flood the logs, and can't be as easily queried. Some sort of structured format is much better, imo

Actually, I think the logs are exactly the right place for OS details and system specs. The goal is to stuff as much information in the log file as possible so when a customer reports a problem, uploads the log file, but fails to tell us much else, we have a better clue of how to reproduce the issue. That's not to say we can't also add structured sources of this information, but I can't see a pressing reason why you'd need SQL access to the system specs.

We don't presently include schemas of any sources or views because they can contain sensitive information. If the user is willing to supply this information, they can upload mzdata/catalog, which is just a SQLite database that can be easily queried for the source/view/sink/index definitions.

[awang]

Machine data is unlikely to change across restarts -- I don't see why that needs to be emitted on each startup?

If it's just a few lines, then it doesn't matter -- I just want to be sure we don't flood the log file with hundreds of static lines that people gloss over on each startup

[benesch]

Machine data is unlikely to change across restarts -- I don't see why that needs to be emitted on each startup?

I mentioned this above, but the goal is to stuff as much information in the log file as possible so when a customer reports a problem, uploads the log file, but fails to tell us much else, we have a better clue of how to reproduce the issue. There isn't really a way to accomplish this besides emitting the information into the log file on every startup. Due to our (lack of) log rotation, we don't clear out the existing log file.

If it's just a few lines, then it doesn't matter

Yep, it's just a few lines. Although I think making the logs intelligible for users should be secondary to making them useful to developers. Generally these goals are aligned, but hypothetically, if there were some reason to include 100 lines of really useful context for developers in the log file, even if your average user didn't care, I think it'd be worth it.