Include searchable severity level in log lines

[lackhoa]

/kind feature

Describe the solution you'd like
Currently logs produced by the capa controller does not include an obvious "grep"-able severity level, which makes it hard to search for errors or warnings, for example

I0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"  

I suggest including a severity level in the log lines, such as this...

INFO I0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"  

... or this

INFO-0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"  

The above are just some ideas; the exact format can be something else.

Anything else you would like to add:

Environment:

• Cluster-api-provider-aws version: v1.2

[k8s-ci-robot]

@lackhoa: This issue is currently awaiting triage.

If CAPA/CAPI contributors determines this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.

The triage/accepted label can be added by org members by writing /triage accepted in a comment.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[Skarlso]

/assign

[Skarlso]

@lackhoa The log in the controller begins with a character that represents the log level.
I -> INFO
D -> DEBUG
E -> ERROR

grep for info:

cat logs.txt|grep "^I"
I0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"
I0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"
I0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"

grep for errors:

cat logs.txt|grep "^E"
E0122 00:41:32.797919       1 awsmachine_controller.go:461]  "msg"="Reconciling AWSMachine"

It think this works pretty well.

[lackhoa]

@Skarlso Nice idea but unfortunately if you use stern, the log isn't at the beginning anymore.

capa-controller-manager-6d956f866c-9qdj8 manager I0131 06:09:25.818603       1 identity_provider.go:32]  "msg"="reconciling oidc identity provider"  

[Skarlso]

The "problem" here is that we are using logr which is used by k8s. They have a different opinion on log levels based on numbers, which do make sense. Also, if I recall, stern is a defunct project, right? :)

Further, it is still pretty much grep-able since manager is a constant ( the name of the container ). So you can grep manager [I|E].

I'll look into providing a header, but the header then won't match the log level, right? Logr is configured through numbers which represent chattyness. But at what point to switch to debug and what point to switch to trace or whatever? There is really no correlation other than an arbitrary one.

These are the letter constant used byklogr:

const severityChar = "IWEF"

With severity binding such as:

	infoLog severity = iota
	warningLog
	errorLog
	fatalLog
	numSeverity = 4

So I guess, I can bind these to the something. 🤔

Also this would, of course, mean that all of the controller and the whole project would have to adjust to use these log level headers.

[lackhoa]

@Skarlso I didn't know stern was a defunct project, but my point wasn't about stern. It was about how grepping based on line opening can fail when you integrate with other things.

Further, it is still pretty much grep-able since manager is a constant

I guess everything is greppable if you put enough effort into it. I could also use awk to parse the log lines and then grep. But the point is that it should be easy, right?
I'd like to add another point is that I0122 is kind of confusing to beginners. I for example have no idea what that means.

I personally would have no problem with numeric log levels, and it'd make things more transparent then why not.

[Skarlso]

@lackhoa I get your point, and it's a valid one. We'll figure something out in the next community meeting as this affects the whole project ( so we would like to be consistent over other controllers as well ).

Maybe something like level=INFO in amongst the values of the logger. The header is sadly not changeable as it's set based on severity. You can disable it, but that's about it. :))

[sedefsavas]

Copying comment from #3152

We should also consider adding JSON support during this refactoring, which is being discussed in CAPI:
kubernetes-sigs/cluster-api#5571 (comment)

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle stale
• Mark this issue or PR as rotten with /lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue or PR with /reopen
• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close

[k8s-ci-robot]

@k8s-triage-robot: Closing this issue.

In response to this:

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue or PR with /reopen
• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.