search

authzed / spicedb-operator

Kubernetes controller for managing instances of SpiceDB
Apache License 2.0
62 stars 26 forks source link

Excessive `syncing owned object` logs after upgrading to 1.6 #265

Closed artursmolarek closed 9 months ago

artursmolarek commented 9 months ago

After upgrading the SpiceDB operator from version 1.4 to 1.6 (and newer, including 1.10), we observed an enormous number of syncing owned object logs repeated every second. This behavior was not present in versions 1.4 and 1.5.

We use the following args:

      run
      -v=4
      --crd=false
      --config
      /opt/operator/config.yaml
I1016 10:04:07.733704       1 controller.go:312]  "msg"="syncing owned object" "controller"="spicedbclusters" "gvr"={"Group":"authzed.com","Version":"v1alpha1","Resource":"spicedbclusters"} "obj"={"name":"spicedb",
"namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.733745       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="pauseCluster" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.733756       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="adoptSecret" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.733897       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ConfigChangedHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="V
ALiA"
I1016 10:04:07.733972       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ValidateConfigHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="
VALiA"
I1016 10:04:07.735372       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[ensureServiceAccount,ensureRole,ensureService]" "obj"={"name":"spicedb","namespace":"spicedb
-internal"} "syncID"="VALiA"
I1016 10:04:07.735422       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureService" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.735454       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRole" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.735442       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureServiceAccount" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.735874       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRoleBinding" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.736010       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="deploymentsPre" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.736029       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="jobsPre" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.736043       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[getDeployments,getJobs]" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="V
ALiA"
I1016 10:04:07.736078       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getJobs" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.736095       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getDeployments" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALiA"
I1016 10:04:07.736589       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.MigrationCheckHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="
VALiA"
I1016 10:04:07.736624       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.DeploymentHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="VALi
A"
I1016 10:04:08.743747       1 controller.go:312]  "msg"="syncing owned object" "controller"="spicedbclusters" "gvr"={"Group":"authzed.com","Version":"v1alpha1","Resource":"spicedbclusters"} "obj"={"name":"spicedb",
"namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.743783       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="pauseCluster" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.743794       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="adoptSecret" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.743935       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ConfigChangedHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.744017       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ValidateConfigHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.745448       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[ensureServiceAccount,ensureRole,ensureService]" "obj"={"name":"spicedb","namespace":"spicedb
"} "syncID"="DO6SL"
I1016 10:04:08.817847       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureService" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.817862       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRole" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.817846       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureServiceAccount" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818202       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRoleBinding" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818348       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="deploymentsPre" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818368       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="jobsPre" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818382       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[getDeployments,getJobs]" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818424       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getJobs" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818439       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getDeployments" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818935       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.MigrationCheckHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
I1016 10:04:08.818960       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.DeploymentHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="DO6SL"
ecordell commented 9 months ago

Thanks for the bug report!

Do you see anything in the status block of the SpiceDBCluster objects? If not, can you enable a higher log mode --v=5 or --v=6 and report back?

artursmolarek commented 9 months ago

Hey @ecordell ,

This is the status of the SpiceDBCluster:

Status:
  Current Migration Hash:  [...]
  Image:                   our.registry.tld/authzed/spicedb:v1.25.0
  Migration:               head
  Observed Generation:     21
  Secret Hash:             [...]
  Target Migration Hash:   [...]

--v=6 logs:

I1017 07:45:26.234640       1 pathrecorder.go:241] controller-manager: "/healthz" satisfied by exact match
I1017 07:45:26.235849       1 pathrecorder.go:241] healthz: "/healthz" satisfied by exact match
I1017 07:45:26.372126       1 controller.go:314]  "msg"="syncing owned object" "controller"="spicedbclusters" "gvr"={"Group":"authzed.com","Version":"v1alpha1","Resource":"spicedbclusters"} "obj"={"name":"spicedb",
"namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.372157       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="pauseCluster" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.372204       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="adoptSecret" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.372513       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ConfigChangedHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="D
ahco"
I1017 07:45:26.372683       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ValidateConfigHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="
Dahco"
I1017 07:45:26.374578       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[ensureServiceAccount,ensureRole,ensureService]" "obj"={"name":"spicedb","namespace":"spicedb
-internal"} "syncID"="Dahco"
I1017 07:45:26.470690       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureService" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.470864       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureServiceAccount" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.471425       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRole" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.570627       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRoleBinding" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.570869       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="deploymentsPre" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.570894       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="jobsPre" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.570911       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[getDeployments,getJobs]" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="D
ahco"
I1017 07:45:26.570968       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getJobs" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.570993       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getDeployments" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahco"
I1017 07:45:26.571598       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.MigrationCheckHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="
Dahco"
I1017 07:45:26.571625       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.DeploymentHandler" "obj"={"name":"spicedb","namespace":"spicedb-internal"} "syncID"="Dahc
o"
I1017 07:45:26.670719       1 round_trippers.go:553] PATCH https://172.20.0.1:443/apis/authzed.com/v1alpha1/namespaces/spicedb-internal/spicedbclusters/spicedb/status?fieldManager=spicedb-operator&force=true 200 OK
 in 97 milliseconds
I1017 07:45:26.771496       1 file_informer.go:235]  "msg"="resyncing file" "after"="1m0s" "file"="/opt/operator/config.yaml"
I1017 07:45:26.771545       1 controller.go:230]  "msg"="loading config" "path"="/opt/operator/config.yaml"
I1017 07:45:26.873127       1 controller.go:259]  "msg"="config hasn't changed" "new hash"=17758556671654252025 "old hash"=17758556671654252025
I1017 07:45:27.071112       1 controller.go:314]  "msg"="syncing owned object" "controller"="spicedbclusters" "gvr"={"Group":"authzed.com","Version":"v1alpha1","Resource":"spicedbclusters"} "obj"={"name":"spicedb",
"namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.071296       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="pauseCluster" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.071330       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="adoptSecret" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.570936       1 pathrecorder.go:241] controller-manager: "/healthz" satisfied by exact match
I1017 07:45:27.571047       1 pathrecorder.go:241] healthz: "/healthz" satisfied by exact match
I1017 07:45:27.571369       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ConfigChangedHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.572478       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.ValidateConfigHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.571525       1 pathrecorder.go:241] controller-manager: "/healthz" satisfied by exact match
I1017 07:45:27.671971       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[ensureServiceAccount,ensureRole,ensureService]" "obj"={"name":"spicedb","namespace":"spicedb
"} "syncID"="s46vP"
I1017 07:45:27.672018       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureService" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.672396       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureServiceAccount" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.672643       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRole" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.672870       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="ensureRoleBinding" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.673039       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="deploymentsPre" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.673071       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="jobsPre" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.673097       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="parallel[getDeployments,getJobs]" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.673129       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getJobs" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.673161       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="getDeployments" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.670617       1 pathrecorder.go:241] healthz: "/healthz" satisfied by exact match
I1017 07:45:27.970825       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.MigrationCheckHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:27.970856       1 logging.go:35]  "msg"="entering handler" "controller"="spicedbclusters" "handler"="*controller.DeploymentHandler" "obj"={"name":"spicedb","namespace":"spicedb"} "syncID"="s46vP"
I1017 07:45:28.085617       1 round_trippers.go:553] PATCH https://172.20.0.1:443/apis/authzed.com/v1alpha1/namespaces/spicedb/spicedbclusters/spicedb/status?fieldManager=spicedb-operator&force=true 200 OK in 14 mi
lliseconds
I1017 07:45:28.234470       1 pathrecorder.go:241] controller-manager: "/healthz" satisfied by exact match
I1017 07:45:28.234581       1 pathrecorder.go:241] healthz: "/healthz" satisfied by exact match
ecordell commented 9 months ago

Thanks @artursmolarek - I don't see anything unusual there, unfortunately. I tried to repro locally with 1.10, but after the cluster is up and running the logs stabilize.

Can you do kubectl -n spicedb get spicedbcluster spicedb -o yaml -w and see if there are any changes happening to the object? Do you have anything else writing to the SpiceDBCluster?

artursmolarek commented 9 months ago

I was able to identify the root cause of it. Kyverno was patching some of the resources created by the Operator.

I appreciate your help. The issue can be closed.