docs: Add runtime logging SIP #974

etehtsea · 2022-12-14T10:35:11Z

Rendered

Refs: #962

Signed-off-by: Konstantin Shabanov [email protected]

etehtsea · 2022-12-14T12:58:39Z

If this isn't a secret - how does log collecting currently work in the fermyon cloud?

Also, it could help me a lot if somebody shared their typical dev workflows

Do you usually use --follow-all? Or do you tail -f ~/.spin/logs/<app_name>/*
Do you use --follow often?
Is there something that you feel is missing?
Do you usually use RUST_LOG=spin=<log_level>?

itowlson · 2022-12-14T19:24:09Z

@lann Are you the right person to comment on the question about logging in the Cloud?

lann · 2022-12-14T21:42:54Z

Logging in the cloud is functionally the same as Spin's built-in logging. It uses the same spin-core Store::stdout / ::stderr config, it just ships them out over the network to a logging service rather than writing to disk.

itowlson

Thanks for getting this under way. I left some comments where I thought it would be useful to expand on why we propose to do things in a particular way, and I've got some reservations about the proposed defaults. I wonder if we could add a bit more about the requirements / constraints / desired user experience - that might help give context to the proposal.

The format of "what do we do today / what do we build towards" is valuable, and I think helps address your question about "MVP vs all the toys" - we have often used the "future ideas" in SIPs as a good place to capture ideas that are only partially formed or are too big to tackle. If you've got other stuff you'd be excited to see then do jot it down.

Again, thanks so much for driving this. It's really valuable to have a structured discussion of this!

itowlson · 2022-12-14T22:12:27Z

docs/content/sips/008-logging.md

+## Proposal
+
+- Set default log level to `INFO`.
+- Set default log destination to `stdout/stderr`.


The combination of these two feels like it could get extremely noisy. For myself, I'd prefer the default experience to be fairly minimal, and to opt into a more verbose flow as and when I want it. I may be an outlier here though!

This is particularly the case for commands like spin deploy or spin templates list where there is salient output that we are trying to show to the user (the deployment URL, the list) and we don't want that to be just another logging message amongst dozens.

That may mean we need different default behaviour for the trigger commands (spin up) vs the non-trigger commands. Which is fine, of course, just needs to be in our minds.

This is particularly the case for commands like spin deploy or spin templates list where there is salient output that we are trying to show to the user (the deployment URL, the list) and we don't want that to be just another logging message amongst dozens.

That's right, these command shouldn't be affected. The only case for commands like these is to additionally provide something like --debug to enable debug/trace logging.

The combination of these two feels like it could get extremely noisy. For myself, I'd prefer the default experience to be fairly minimal, and to opt into a more verbose flow as and when I want it. I may be an outlier here though!

If INFO logging gets too noisy then it might make sense to review what is actually logged with this log level and change some of the output to debug/trace.

That may mean we need different default behaviour for the trigger commands (spin up) vs the non-trigger commands. Which is fine, of course, just needs to be in our minds.

Yep, that's why I narrowed it down to "runtime" logging but didn't provide the description of what I meant by it. Will adjust the doc.

itowlson · 2022-12-14T22:15:18Z

docs/content/sips/008-logging.md

+
+- Set default log level to `INFO`.
+- Set default log destination to `stdout/stderr`.
+- Provide a way for spin apps for logging (besides using `println!`/`eprintln!`).


Could you expand on the value of this - is it to allow structured logs? I really like stdout/stderr as a way to do quick printf debugging without needing to faff around with SDKs or subscribers or whatever.

Yep, I think it would be handy to log using tracing from the guest modules in the consistent manner.

When I was playing with an example app on the fermyon cloud, sometimes it was hard to distinguish one log record from another as there are no timestamps or ids.

Though, println! (or any other "print to std") behaviour should remain unaffected.

When I was playing with an example app on the fermyon cloud, sometimes it was hard to distinguish one log record from another as there are no timestamps or ids.

This is mostly just a UI issue in Fermyon Cloud; we are in fact recording more info for logging, just not displaying it yet. The trick with timestamps specifically is that some apps are already logging with timestamps; we'll probably need to apply some "timestamp dedupe" before unconditionally showing timestamps in the UI.

If those spin apps are using plain println!, then there shouldn't be any duplication as those records will be left intact. Eventually, these apps will be able to migrate to structured logging provided by SDKs and drop their timestamps.

itowlson · 2022-12-14T22:17:12Z

docs/content/sips/008-logging.md

+- Set default log level to `INFO`.
+- Set default log destination to `stdout/stderr`.
+- Provide a way for spin apps for logging (besides using `println!`/`eprintln!`).
+- Log `WARN`and `ERROR` into `stderr` and `INFO`, `DEBUG`, `TRACE` into `stdout`.


Again, could you expand on the logic here? It probably makes little difference for interactive output, but if logs are being persisted, would it not be more convenient to have a single sequential stream, e.g. to readily see debug and trace messages in the lead-up to an error?

It should remain sequential if you redirect both descriptors somewhere (spin up --follow-all &> out.log).
But, currently, there is not way to do the opposite - for example, if I want to capture only warnings and errors on prod system. In this case I would redirect stderr somewhere: spin up --follow-all 2&> err.log # or some fancy log collector instead of err.log

But for now all output incl. println! from the guest modules (spin apps) is pointed to stderr.

itowlson · 2022-12-14T22:26:48Z

docs/content/sips/008-logging.md

+
+### Goal
+
+To provide the new baseline that gives foundation for further iterative development of new features and enhancements based on the feedback.


Might be good to talk here (or elsewhere) about the problems and scenarios we want to address e.g.

Mikkel having to type --follow-all all the time

Correlating logs to external events (timestamps)

Complicated Rust-specific incantation to control verbosity

"Mikkel having to type --follow-all all the time" - let's consider the fictious figure 'Mikkel' to be someone exploring Spin and not unstanding why nothing is being written to the console where that person ran spin up given they had a printxyz statement in their code. That's the more urgent case here in my opinion.

I'd like the grow-up story of giving more control over what gets logged where, especially once you move to running instances, and not just development. Maybe those are the two top scenarios to distinguish between to begin with?

not unstanding why nothing is being written to the console

We could incrementally improve this immediately: add a message on startup e.g. "Writing app output to <path>; pass --follow-all to see it here on the console."

I think that's a great idea to do, independently of what the defaults end up being.

itowlson · 2022-12-14T23:02:50Z

docs/content/sips/008-logging.md

+--log-format <LOG_FORMAT>
+```
+
+`spin.toml`:


This is another one of those things where it's probably not an app definition concern - it might change from environment to environment depending on who or what is consuming the logs. I agree it's a discussion for the future though, and thanks for flagging it up!

itowlson · 2022-12-14T23:05:52Z

docs/content/sips/008-logging.md

+`spin.toml`:
+```toml
+[variables]
+log = {


Not quite sure what you're envisaging here. Are you thinking of the runtime config file rather than the application definition? I'm not quite seeing how this fits with the current use of the app def variables section.

The initial thought was that when log configuration evolves, it gets inconvenient to provide dozens of command line arguments quite fast, so it has to be defined somewhere in the config. You might want to permanently adjust the log format or timestamp format for your app.

Also, I've found a reference to it in the app-config SIP.

But I didn't take into consideration that spin.toml is somewhat static and is bundled into a bindle artifact. And there is no dev/prod configuration at the moment.

I think I better move this into Future design considerations.

It might fit in the new runtime-config.toml file but I don't know much about the intended scope of that... future considerations sounds good to me grin

itowlson · 2022-12-14T23:13:08Z

@mikkelhegn tagging you in on this because I know you have opinions

etehtsea · 2022-12-15T12:07:21Z

Logging in the cloud is functionally the same as Spin's built-in logging. It uses the same spin-core Store::stdout / ::stderr config, it just ships them out over the network to a logging service rather than writing to disk.

In this case, I would like to propose dropping writing log files to disk to reduce the complexity of the proposal.
Different log destinations might be re-implemented later when there is the use case (but it has to be discussed separately).

What do you think about it?

Refs: fermyon#962 Signed-off-by: Konstantin Shabanov <[email protected]>

itowlson reviewed Dec 14, 2022

View reviewed changes

etehtsea force-pushed the 962-sip-logging branch from 0095256 to 955f51d Compare December 16, 2022 16:07

docs: Add runtime logging SIP

21c8084

Refs: fermyon#962 Signed-off-by: Konstantin Shabanov <[email protected]>

etehtsea force-pushed the 962-sip-logging branch from 955f51d to 21c8084 Compare December 16, 2022 16:10

etehtsea marked this pull request as ready for review December 16, 2022 16:12

lann mentioned this pull request Dec 19, 2022

Print description of logging behavior on spin up #993

Closed

rajatjindal mentioned this pull request Jan 30, 2023

Show common trigger options on spin up --help #1081

Merged

etehtsea closed this Jan 31, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

docs: Add runtime logging SIP #974

docs: Add runtime logging SIP #974

etehtsea commented Dec 14, 2022 •

edited

Loading

etehtsea commented Dec 14, 2022 •

edited

Loading

itowlson commented Dec 14, 2022

lann commented Dec 14, 2022 •

edited

Loading

itowlson left a comment

itowlson Dec 14, 2022

itowlson Dec 14, 2022

etehtsea Dec 15, 2022

itowlson Dec 14, 2022

etehtsea Dec 15, 2022

lann Dec 15, 2022

etehtsea Dec 15, 2022

itowlson Dec 14, 2022

etehtsea Dec 15, 2022 •

edited

Loading

itowlson Dec 14, 2022

mikkelhegn Dec 16, 2022

lann Dec 16, 2022 •

edited

Loading

mikkelhegn Dec 19, 2022

itowlson Dec 14, 2022

itowlson Dec 14, 2022

etehtsea Dec 15, 2022 •

edited

Loading

itowlson Dec 15, 2022

itowlson commented Dec 14, 2022

etehtsea commented Dec 15, 2022


		### Goal

		To provide the new baseline that gives foundation for further iterative development of new features and enhancements based on the feedback.

docs: Add runtime logging SIP #974

docs: Add runtime logging SIP #974

Conversation

etehtsea commented Dec 14, 2022 • edited Loading

etehtsea commented Dec 14, 2022 • edited Loading

itowlson commented Dec 14, 2022

lann commented Dec 14, 2022 • edited Loading

itowlson left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

etehtsea Dec 15, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lann Dec 16, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

etehtsea Dec 15, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

itowlson commented Dec 14, 2022

etehtsea commented Dec 15, 2022

etehtsea commented Dec 14, 2022 •

edited

Loading

etehtsea commented Dec 14, 2022 •

edited

Loading

lann commented Dec 14, 2022 •

edited

Loading

etehtsea Dec 15, 2022 •

edited

Loading

lann Dec 16, 2022 •

edited

Loading

etehtsea Dec 15, 2022 •

edited

Loading