search

kubernetes-sigs / cluster-api

Home for Cluster API, a subproject of sig-cluster-lifecycle
https://cluster-api.sigs.k8s.io
Apache License 2.0
3.58k stars 1.31k forks source link

Add timestamps to Ginkgo output #5355

Closed sbueringer closed 3 years ago

sbueringer commented 3 years ago

User Story

As a contributor who frequently debugs CAPI e2e tests I would like to be able to correlate the e2e test output with e.g. controller logs.

(I'm talking about the INFO/STEP output, e.g. here: https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/kubernetes-sigs_cluster-api/5354/pull-cluster-api-e2e-full-main/1442921166653100032)

Detailed Description

It's very hard and sometimes impossible to correlate what our e2e test code does with log lines of controllers. It would make debugging the e2e tests a lot easier if we could prepend a timestamp to the test output.

Anything else you would like to add:

This could be achieved by adjusting the log.LogF func and by introducing a By func which wraps the ginkgo By func and which we then use instead of the original.

/kind feature /area testing

sbueringer commented 3 years ago

@fabriziopandini WDYT? (I'm not sure if there are other/better ways to achieve this)

fabriziopandini commented 3 years ago

I'm ok with the goal, however I will investigate how a little bit more. Wrapping By seems kind of hacky

sbueringer commented 3 years ago

Absolutely agree. I spent 1-2 hours to find a way a while ago for CAPO, but couldn't find a better way.

The only idea I have spontaneously is maybe to overwrite the GinkgoWriter. Afaik Ginkgo doesn't expose any API to customize the log output.

But I'm fine with any other way (preferably less hacky as the one I described), I just want to have the output

vincepri commented 3 years ago

/milestone v1.0

randomvariable commented 3 years ago

I had considered doing this before.

Wrapping By seems kind of hacky

That's how it's being done in K/k in a few places, but it's not consistent.

Even bigger hack, but it'll be consistent, you could use one of the things here in e2e shell scripts to prepend a timestamp on every new line. https://unix.stackexchange.com/questions/26728/prepending-a-timestamp-to-each-line-of-output-from-a-command

sbueringer commented 3 years ago

When we're talking about hacks, previously I used a different entrypoint container in Prow which prepended a timestamp on every log-line of every ProwJob :). But that's not a good idea with upstream Prow, if it is even possible.

But I think you're variant comes pretty close. I don't necessarily need timestamps in ginkgo. Ever log line printed by make -C test/e2e/ run would be even better.

sbueringer commented 3 years ago

@randomvariable Doesn't work as expected: https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/kubernetes-sigs_cluster-api/5367/pull-cluster-api-e2e-main/1443868443865518080

We run the e2e tests without -stream which means that the test result is printed at once and thus the entire test case is printed with the timestamp of the test completion.

Imho we shouldn't add -stream as otherwise the test output of parallel running tests wouldn't be separated.

So I think we're back to that we need some adjustments to the e2e test logging in Go.

randomvariable commented 3 years ago

We use -stream in the AWS tests actually. That's been basically an encoding of my personal preference when running the e2e tests locally.

randomvariable commented 3 years ago

I should add, that's because at least for AWS, the feedback time is too long otherwise.

sbueringer commented 3 years ago

I think for CAPD it makes sense to keep it as is as the tests are faster and mixed test case output is bad to read. That's not a problem in CAPA?

randomvariable commented 3 years ago

Yeah, that's what I meant.

sbueringer commented 3 years ago

I found a way to additionally redirect the logs. So it would be possible to e.g. also write them to a file with timestamps prepended.

This wouldn't be visible in stdout, but it's the only option I see without stream.

CecileRobertMichon commented 3 years ago

FWIW this is what we did in CAPZ: https://github.com/kubernetes-sigs/cluster-api-provider-azure/blob/main/test/e2e/log.go#L37, and then use it like this: https://github.com/kubernetes-sigs/cluster-api-provider-azure/blob/main/test/e2e/azure_lb.go#L127

The downside of this approach is obviously that we need to add log lines for everything we want to have a timestamp for... but it's visible in stdout.

sbueringer commented 3 years ago

Yup, I think that are essentially our options:

For me the second option would be enough and it would avoid introducing our on logging functions and the need to use them everywhere.

PoC for the second option: https://github.com/kubernetes-sigs/cluster-api/pull/5367