CALICO_NETWORKING_BACKEND none creates noisy log output

[tobiasgiese]

With calico v3.26.1 there is an issue with CALICO_NETWORKING_BACKEND: none.
Using no network backend creates alot of log output. Every second the following lines will be printed:

W0627 10:59:35.128237     457 feature_gate.go:241] Setting GA feature gate ServiceInternalTrafficPolicy=true. It will be removed in a future release.
2023-06-27 10:59:35.132 [INFO][457] monitor-addresses/startup.go 432: Early log level set to info
2023-06-27 10:59:35.132 [INFO][457] monitor-addresses/startup.go 315: Skipped monitoring node IP changes when CALICO_NETWORKING_BACKEND=none

With the latest master (i.e., v3.27.0-dev) this issue does not occur.

Reproducable with kind:

1. Create a v1.26 kind cluster

❯ kind create cluster --image kindest/node:v1.26.4@sha256:f4c0d87be03d6bea69f5e5dc0adb678bb498a190ee5c38422bf751541cebe92e

2. Apply calico v3.26.1 with backend type none

❯ curl https://raw.githubusercontent.com/projectcalico/calico/v3.26.1/manifests/calico.yaml | sed -r 's/(calico_backend:) "bird"/\1 "none"/' | kubectl apply -f -

3. Wait for calico-node Pods running and see the log output

❯ kubectl -n kube-system logs calico-node-l7mv4 --tail 9
Defaulted container "calico-node" out of: calico-node, upgrade-ipam (init), install-cni (init), mount-bpffs (init)
W0627 11:06:02.068549     650 feature_gate.go:241] Setting GA feature gate ServiceInternalTrafficPolicy=true. It will be removed in a future release.
2023-06-27 11:06:02.072 [INFO][650] monitor-addresses/startup.go 432: Early log level set to info
2023-06-27 11:06:02.072 [INFO][650] monitor-addresses/startup.go 315: Skipped monitoring node IP changes when CALICO_NETWORKING_BACKEND=none
W0627 11:06:03.114813     666 feature_gate.go:241] Setting GA feature gate ServiceInternalTrafficPolicy=true. It will be removed in a future release.
2023-06-27 11:06:03.119 [INFO][666] monitor-addresses/startup.go 432: Early log level set to info
2023-06-27 11:06:03.119 [INFO][666] monitor-addresses/startup.go 315: Skipped monitoring node IP changes when CALICO_NETWORKING_BACKEND=none
W0627 11:06:04.159043     680 feature_gate.go:241] Setting GA feature gate ServiceInternalTrafficPolicy=true. It will be removed in a future release.
2023-06-27 11:06:04.163 [INFO][680] monitor-addresses/startup.go 432: Early log level set to info
2023-06-27 11:06:04.163 [INFO][680] monitor-addresses/startup.go 315: Skipped monitoring node IP changes when CALICO_NETWORKING_BACKEND=none

Setting CALICO_STARTUP_LOGLEVEL or FELIX_LOGSEVERITYSCREEN to error does not fix the issue.

Your Environment

• Calico version v3.26.1
• Orchestrator version (e.g. kubernetes, mesos, rkt): kind v1.26.4
• Operating System and version:
• Link to your project (optional):

_{Tobias Giese tobias.giese@mercedes-benz.com, Mercedes-Benz Tech Innovation GmbH, legal info/Impressum}

[caseydavenport]

Looks like that spammy log was removed in this commit: 08f2765

Seems like a reasonable enough cherry-pick if anyone wants to have a go

[tobiasgiese]

Seems like a reasonable enough cherry-pick if anyone wants to have a go

I can try this, for sure. Should I open a cherry-pick PR after testing?

[tobiasgiese]

@caseydavenport only this cherry-pick creates a nil pointer because configureASNumber (L187 from the stacktrace below is L188 on master)

calico/node/pkg/lifecycle/startup/startup.go

Lines 188 to 189 in 8234b36

	needsNodeUpdate = configureASNumber(node) || needsNodeUpdate
	// Populate a reference to the node based on orchestrator node identifiers.

needs node.Spec.BGP.ASNumber (L705 from the stacktrace below is L706 on master)

calico/node/pkg/lifecycle/startup/startup.go

Line 706 in 8234b36

if node.Spec.BGP.ASNumber == nil {

calico-node-ghflt calico-node W0628 07:25:57.491768       9 feature_gate.go:241] Setting GA feature gate ServiceInternalTrafficPolicy=true. It will be removed in a future release.
calico-node-ghflt calico-node panic: runtime error: invalid memory address or nil pointer dereference
calico-node-ghflt calico-node [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x19e7718]
calico-node-ghflt calico-node 
calico-node-ghflt calico-node goroutine 1 [running]:
calico-node-ghflt calico-node github.com/projectcalico/calico/node/pkg/lifecycle/startup.configureASNumber(0xc0000e8000)
calico-node-ghflt calico-node 	/go/src/github.com/projectcalico/calico/node/pkg/lifecycle/startup/startup.go:705 +0x58
calico-node-ghflt calico-node github.com/projectcalico/calico/node/pkg/lifecycle/startup.Run()
calico-node-ghflt calico-node 	/go/src/github.com/projectcalico/calico/node/pkg/lifecycle/startup/startup.go:187 +0x8e5
calico-node-ghflt calico-node main.main()
calico-node-ghflt calico-node 	/go/src/github.com/projectcalico/calico/node/cmd/calico-node/main.go:146 +0x732
calico-node-ghflt calico-node Calico node failed to start

Btw, this is also an issue with the latest v3.27.0-0.dev and master

[tobiasgiese]

@caseydavenport i've created a PR that fixes this nil pointer. After merge we can cherry-pick both PRs to backport this change to v3.26

[caseydavenport]

@tobiasgiese good catch! I just gave that PR a look over and gave some suggestions - LMK what you think.

[tobiasgiese]

@caseydavenport adjusted the PR according to your suggestions and it's working as expected. Thanks for your review! 👍🏻

[tobiasgiese]

@caseydavenport created PR #7824 to cherry-pick both commits.

[sridhartigera]

@tobiasgiese Thanks for your PRs. Closing this issue.

[mindw]

Any news on when this gets released? or at least if there is a workaround till it is?
Tx!

[tobiasgiese]

@mindw seems like v3.26.3 has been released last week
https://github.com/projectcalico/calico/releases/tag/v3.26.3