Feat/timestamp in logs

[lidongjies]

Signed-off-by: lidongjies [email protected]

I added a timestamp to the write method in WriteDestinations, but I think this is not appropriate. Please give me some feedback. 🤔

Related issue #693

[radu-matei]

Do we want this to be human readable?

cc @itowlson

[itowlson]

If I'm reading the code correctly (I haven't tested it), this looks like it prints milliseconds since the Unix epoch? I think a wall clock timestamp would be more broadly acceptable.

It might be a good idea to discuss the desired behaviour before @lidongjies dives into the code though, to avoid wasted effort and excessive iteration. E.g.:

1. How should the timestamp be presented? E.g.:

• Time format
• Local or UTC
• Separator from text
• Whether there are any brackets or other decoration around the timestamp

2. Should the user be able to configure whether timestamps are output?
3. Should the user be able to choose different options in the follow output vs the persistent logs?

• E.g. I want them in the persistent logs so I can refer back, but they may feel like clutter in the follow output
• I want them in local time in the follow output but UTC in the logs that are going to be ingested by a distributed tracing system

I am definitely NOT saying that we need all the knobs, and even more definitely not that we need them all on day one. But I think it would be good to get a sense for what we want long term, and how we want to start, before writing more code. Thoughts?

[itowlson]

@lidongjies Just circling round on this since time has passed - are you interested in pursuing this PR in the light of the discussion, or would you prefer us to close it? We'd be very happy to work with you on determining what a solution might look like - let us know! Thanks!

[etehtsea]

@itowlson I'm currently researching this one as a follow-up of #938 and #931.

The current idea is to rely on logging provided by tracing crate as it already provides nice-looking log output:

2022-12-07T02:57:48.977528Z  INFO spin_build: Successfully ran the build command for the Spin components.    
2022-12-07T02:57:49.726490Z  INFO spin_http: Serving http://127.0.0.1:3000    
2022-12-07T02:57:49.726514Z  INFO spin_http: Available Routes:    
2022-12-07T02:57:49.726522Z  INFO spin_http:   rust-outbound-http: http://127.0.0.1:3000/outbound    
2022-12-07T02:57:49.726533Z  INFO spin_http:   rust-outbound-http-wildcard: http://127.0.0.1:3000/wildcard    

The high-level plan is (probably not well-formed yet):

• Change default RUST_LOG level from ERROR to INFO;
• Replace println! with log::info! where it makes sense (in the spin itself);
• Provide spin_sdk::log to be used in spin apps. This will give app developers the ability to integrate into the spin's log:

2022-12-07T02:57:49.726533Z  INFO spin_http:   rust-outbound-http-wildcard: http://127.0.0.1:3000/wildcard  
2022-12-07T02:57:49.726490Z  INFO <component-id-1>: the log message
2022-12-07T02:57:49.726490Z  INFO <component-id-2>: another log message
2022-12-07T02:57:49.726490Z  INFO <component-id-2>: and one moar
2022-12-07T03:01:19.696378Z  INFO spin_trigger::cli: User requested shutdown: exiting   

In the end, it has to provide the unified logging system:

• control verbosity (implement spin -vvvvv #609)
• log in the consistent manner (format)
• ability to filter out information based on the need (theoretically, --follow flag can be expanded from filtering out by spin component into general-purpose flag, like --follow spin_http --follow <component_id>;

Will be happy to discuss!

[itowlson]

@etehtsea Here's the thing: I know some of what I want and don't want from all this. (For example, I don't want logging spew when I'm following a component interactively.) But other people want different things. (You clearly value unifying all output via the trace system for consistent presentation and processing, and I know you're not alone in that.) And situationally I may want different things. (If I've got a component running in the cloud, I probably do want timestamps. If I've got something running on my computer, any timestamps had better be local time; if it's remote, they'd better be UTC.) And what about tools, do I need to be able to configure the format to feed smoothly into Data Dog or Observability Ostrich or whatever the young people use nowadays?

So... what do we need? Do we need knobs? What knobs do we need and how are they surfaced? Or am I a crankish outlier and everybody except me wants the same thing and I can be safely ignored? (Honestly the latter seems like a very likely outcome.)

So before we go any further on this I would really like to see a requirements discussion resulting in a SIP laying out the user experience. Or at least a proposal with enough people agreeing with it to shut me up. We don't need to think about design or implementation until the desired behaviour is agreed at least at a high level.

Does that caution seem appropriate? Is the proposal something you'd be interested in driving, or would you prefer us to tackle that stage of it?

[etehtsea]

@itowlson, the stuff I've posted above is not "an ultimate solution" but more of a proposal to gather feedback. Also, I wasn't familiar with how logging is done internally in spin, so I conducted a little research to be able to reason about it (also, I wanted to check what tracing is capable of).

And situationally I may want different things. (If I've got a component running in the cloud, I probably do want timestamps. If I've got something running on my computer, any timestamps had better be local time; if it's remote, they'd better be UTC.)

This sound more like a dev/prod mode (#389) where one log format is defined for dev and another one for prod mode.

And what about tools, do I need to be able to configure the format to feed smoothly into Data Dog or Observability Ostrich or whatever the young people use nowadays?

It seems there is an open pull request about it (#655).

Does that caution seem appropriate? Is the proposal something you'd be interested in driving, or would you prefer us to tackle that stage of it?

I agree with you. But also, it might make sense to define the baseline to make it easier to reason about enhancements and further integrations (such as log format, UTC vs local, log collectors integration, and so on). By it, I mean that spin already has timestamps in the log output but only for the stuff that is using tracing. The rest is using env_logger/log which looks like a bug (there is no output as it is not initialized anywhere). And the only way for spin apps to print something in the output is the println!/eprintln! which isn't about "logging" per se (as it doesn't care about log levels and such).

I created a few issues and have stopped looking further into this until the consensus.
P.S.

• --follow doesn't validate provided values #944
• redis-rust template doesn't log anything #945

[itowlson]

@etehtsea I may be misreading but I'm concerned I may have upset you - if so, I apologise. I did not intend to derail you, and I value the investigations you were doing. I meant only to highlight that I feel we need to approach this cautiously and to have a way of gathering opinions and getting consensus (such as what is given by a SIP). I would love it if you felt willing to drive that - you clearly have the broad view that is needed, and your attention to detail in describing user interfaces and outputs would be super valuable. But of course I also appreciate that you're volunteering your time and may not want to invest it in that process!

[etehtsea]

@itowlson Actually, it's the opposite, I appreciate your feedback. Sorry if it seemed like that, I probably didn't elaborate well. I would prefer to gather some feedback/requirements before creating the SIP, but I think I can try to figure out something and open a draft PR, and we'll go from there.

[itowlson]

@lidongjies I'm going to close this PR because there's been a lot of churn in the codebase since, and #962 is defining clearer requirements. Thanks for the contribution and sorry we couldn't accept it!