Excessive syncing owned object logs after upgrading to 1.6

[artursmolarek]

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]

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]

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]

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]

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.