4.5.0 BackrestBackups loop until partitions full

[v3nturetheworld]

In Crunchy 4.4.0 and below I noticed the default behavior in regards to backrest backups being made was one backup was created on cluster creation prior to replica, then any following backup would be made from a failover or some pgo command. In Crunchy 4.5.0 I see backrestBackups being created every 10-15 minutes, and without settings limits in a custom pgBackRest Custom Configuration, it will repeatedly make backups until the local partitions are full and postgres will enter a non function state until all of the wal files are deleted in the local storage folder on each node. I'm not sure if there's some operator installation config that I missed when upgrading from 4.4 or if the automatic backups are intended behavior but I was wondering if there was a way to ensure backups only occur like in 4.4 which is on cluster creation, failover and from pgo commands rather then periodic.

I confirmed that this issue occurs when no custom configs used and and no data was ever added to the database by just running:

pgo create cluster test-cluster -n crunchy-test --cpu 15m --memory 690Mi --memory-limit 2Gi --storage-config testlocalstorage --replica-storage-config testlocalstorage --pgbackrest-cpu 30m --pgbackrest-memory 20Mi --pgbackrest-memory-limit 60Mi

I'm guessing this shouldn't be happening, as it doesnt happen with the same creation method on 4.4, and I haven't seen any issues similar to this.

Please tell us about your environment:

• Operating System:
• Where is this running ( Local , Cloud Provider): 3 node local cluster
• Storage being used (NFS, Hostpath, Gluster, etc): primary and replica use localstorage, backrest-shared-repo uses openebs-sc
• Container Image Tag: centos7-13.0-4.5.0
• PostgreSQL Version: 13.0
• Platform (Docker, Kubernetes, OpenShift): OpenShift
• Platform Version: 3.11

If possible please run the following on the kubernetes or OpenShift (oc) commands and provide the result:

[jkatz]

I've run this against the latest bug fix release (4.5.1) and was unable to reproduce your described issue. Perhaps this is a result of the fix presented in #1996 (backpatched down to 4.3).

However, this is tough to determine without logs from the Operator, the affected Pods, more information about your configuration, whether you have scheduled backups, etc.

I also recommend testing for bugs against the latest patch release as there is a chance that any issue may be resolved there.

[v3nturetheworld]

@jkatz I'm following up again on this issue, a bit late since I first opened it but I'm still having the same issue with backups being created every 10 to 15 minutes til the disk is full. The issue is still occurs with the latest crunchy versions (4.5.0 and 4.5.1). I've been sticking with 4.4 as the periodic backup issue doesnt occur on 4.4 and below. I've included the operator logs as well, I can grab the backrest backup logs if those are helpful but the backrest backups do run fine (while there's still space). Adding a custom pgBackrestConfig to limit the number of backups acts as a kind of temporary fix, but having these backups occur so frequently and unctrollable is problematic. Here are the additional logs and some command results:

edit: These logs were on the 4.5.0 operator. As a sanity check let me re-run the same test with 4.5.1 to see if the fix that was linked fixes the issue.

Cluster creation command:

pgo create cluster sso-crunchy-postgresql --cpu 30m --memory 690Mi --memory-limit 2Gi --storage-config testlocalstorage --replica-storage-config testlocalstorage --pgbackrest-cpu 60m --pgbackrest-memory 60Mi --pgbackrest-memory-limit 120Mi --tls-only --server-ca-secret=postgres-server-certs --server-tls-secret=postgres-server-certs --replication-tls-secret=postgres-server-certs -n test-project

No schedules were created:

sh-4.2$ pgo show schedule test-crunchy-postgresql -n test-project
No schedules found.

After the cluster was first fully deployed, as a test to see if the backups could be limited by manually triggering a backup I ran:

pgo backup hacluster --backup-opts="--type=full --repo1-retention-full=7"

However, backups continued to be created til the local storage volume ran out of space.

API Server Logs:

time="2021-01-13T05:05:16Z" level=debug msg="debug flag set to true"
time="2021-01-13T05:05:16Z" level=debug msg="TLS_NO_VERIFY set as false"
time="2021-01-13T05:05:16Z" level=debug msg="DISABLE_TLS set as false"
time="2021-01-13T05:05:21Z" level=info msg="postgres-operator apiserver starts" func="main.main()" file="apiserver.go:109" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="Pgo Namespace is [test-crunchy-operator]" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:102" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="InstallationName is [test-crunchy-postgresql]" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:109" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="apiserver starts" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:121" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="loading PermMap with 59 Permissions\n" func="internal/apiserver.initializePerms()" file="internal/apiserver/perms.go:187" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="Config: pgo-config ConfigMap found, using config files from the configmap" func="internal/config.getRootPath()" file="internal/config/pgoconfig.go:745" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="default instance memory set to [128Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:387" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="default pgbackrest repository memory set to [200Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:393" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="default pgbouncer memory set to [24Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:399" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="BasicAuth is true" func="internal/apiserver.initConfig()" file="internal/apiserver/root.go:189" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="Namespace operating mode is 'readonly'" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:148" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="pgo.tls Secret found in namespace test-crunchy-operator" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:421" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="cert key data len is 1285" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:422" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="private key data len is 1679" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:428" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="listening on port 8443" func="main.main()" file="apiserver.go:164" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="create cluster called for test-crunchy-cluster" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:558" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="pgcluster test-crunchy-cluster not found so we will create it" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:568" version=4.5.0
time="2021-01-13T05:06:01Z" level=error msg="pgclusters.crunchydata.com \"test-crunchy-cluster\" not found" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:716" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg=userLabelsMap func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:775" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="map[crunchy-postgres-exporter:false]" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:776" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="Pgo.Cluster.Policies " func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1359" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="[1] is Pgo.Cluster.Replicas" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1366" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="replica count is 0" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1370" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg=5432 func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1380" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="username set to [dbuser]" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1394" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="database set to [userdb]" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1409" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg=" is Pgo.Cluster.Policies" func="internal/apiserver/clusterservice.validateConfigPolicies()" file="internal/apiserver/clusterservice/clusterimpl.go:1050" version=4.5.0
time="2021-01-13T05:06:01Z" level=debug msg="no policies are specified in either pgo.yaml or from user" func="internal/apiserver/clusterservice.validateConfigPolicies()" file="internal/apiserver/clusterservice/clusterimpl.go:1057" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"000000010000000000000007\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:13:55Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="scheduleservice.ShowScheduleHandler called" func="internal/apiserver/scheduleservice.ShowScheduleHandler()" file="internal/apiserver/scheduleservice/scheduleservice.go:183" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="Authentication Attempt ShowSchedule username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="Show schedule called" func="internal/apiserver/scheduleservice.ShowSchedule()" file="internal/apiserver/scheduleservice/scheduleimpl.go:264" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="Finding configMaps with selector: crunchy-scheduler=true,pg-cluster=test-crunchy-cluster" func="internal/apiserver/scheduleservice.getSchedules()" file="internal/apiserver/scheduleservice/scheduleimpl.go:331" version=4.5.0
time="2021-01-13T05:14:05Z" level=debug msg="Parsing configMaps" func="internal/apiserver/scheduleservice.ShowSchedule()" file="internal/apiserver/scheduleservice/scheduleimpl.go:293" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="clusterservice.DeleteClusterHandler {pca-crunchy-postgresql  4.5.0 test-blue false true true}\n" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:198" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="DeleteClusterHandler: parameters namespace [test-blue] selector [] delete-data [true] delete-backups [true]" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:209" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="Authentication Attempt DeleteCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="clusterservice.DeleteClusterHandler called" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:220" version=4.5.0
time="2021-01-13T05:14:23Z" level=debug msg="GetNamespace username [admin] ns [test-blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:52Z" level=debug msg="GetNamespace username [admin] ns [test-blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:14:55Z" level=debug msg="GetNamespace username [admin] ns [test-blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:15:05Z" level=debug msg="GetNamespace username [admin] ns [test-blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:30:42Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:30:43Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000A\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:30:43Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="backrestservice.CreateBackupHandler called" func="internal/apiserver/backrestservice.CreateBackupHandler()" file="internal/apiserver/backrestservice/backrestservice.go:51" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="Authentication Attempt CreateBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="create backrestbackup called for test-crunchy-cluster" func="internal/apiserver/backrestservice.CreateBackup()" file="internal/apiserver/backrestservice/backrestimpl.go:123" version=4.5.0
time="2021-01-13T05:32:00Z" level=debug msg="sleeping a bit for delete job propagation" func="internal/apiserver/backrestservice.CreateBackup()" file="internal/apiserver/backrestservice/backrestimpl.go:187" version=4.5.0
time="2021-01-13T05:32:02Z" level=debug msg="setting jobName to backrest-backup-test-crunchy-cluster" func="internal/apiserver/backrestservice.CreateBackup()" file="internal/apiserver/backrestservice/backrestimpl.go:206" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000B\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:33:29Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000B\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:33:31Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000D\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000D\",\"stop\":\"00000001000000000000000D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817538},\"label\":\"20210113-054054F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610516454,\"stop\":1610516491},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:44:55Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000D\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000D\",\"stop\":\"00000001000000000000000D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817538},\"label\":\"20210113-054054F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610516454,\"stop\":1610516491},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:44:57Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"00000001000000000000000D\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000D\",\"stop\":\"00000001000000000000000D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817538},\"label\":\"20210113-054054F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610516454,\"stop\":1610516491},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T05:45:00Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.0] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:318" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:337" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:271" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:372" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:440" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-67854bdb7c-k4mlk/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"000000010000000000000095\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000003\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37528996,\"repository\":{\"delta\":4227064,\"size\":4227064},\"size\":37528996},\"label\":\"20210113-050718F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610514438,\"stop\":1610514509},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000008\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405643,\"size\":4405643},\"size\":37817538},\"label\":\"20210113-052140F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515300,\"stop\":1610515334},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817538},\"label\":\"20210113-053216F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610515936,\"stop\":1610515968},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000D\",\"stop\":\"00000001000000000000000D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817538},\"label\":\"20210113-054054F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610516454,\"stop\":1610516491},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000F\",\"stop\":\"00000001000000000000000F\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817538,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817538},\"label\":\"20210113-055554F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610517354,\"stop\":1610517387},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000011\",\"stop\":\"000000010000000000000011\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-061231F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610518351,\"stop\":1610518387},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000013\",\"stop\":\"000000010000000000000013\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-062019F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610518819,\"stop\":1610518852},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000015\",\"stop\":\"000000010000000000000016\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405649,\"size\":4405649},\"size\":37817540},\"label\":\"20210113-063647F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610519807,\"stop\":1610519842},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000018\",\"stop\":\"000000010000000000000019\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405654,\"size\":4405654},\"size\":37817540},\"label\":\"20210113-065055F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610520655,\"stop\":1610520691},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000001B\",\"stop\":\"00000001000000000000001B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-070437F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610521477,\"stop\":1610521513},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000001D\",\"stop\":\"00000001000000000000001D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817539,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817539},\"label\":\"20210113-071817F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610522297,\"stop\":1610522331},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000001F\",\"stop\":\"000000010000000000000020\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-073127F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610523087,\"stop\":1610523123},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000022\",\"stop\":\"000000010000000000000023\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-074035F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610523635,\"stop\":1610523672},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000025\",\"stop\":\"000000010000000000000025\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817540},\"label\":\"20210113-075515F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610524515,\"stop\":1610524550},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000027\",\"stop\":\"000000010000000000000027\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-080506F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610525106,\"stop\":1610525138},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000029\",\"stop\":\"00000001000000000000002A\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-082223F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610526143,\"stop\":1610526174},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000002C\",\"stop\":\"00000001000000000000002D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817539,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817539},\"label\":\"20210113-083731F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610527051,\"stop\":1610527085},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000002F\",\"stop\":\"00000001000000000000002F\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-085132F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610527892,\"stop\":1610527926},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000031\",\"stop\":\"000000010000000000000032\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-090538F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610528738,\"stop\":1610528770},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000034\",\"stop\":\"000000010000000000000035\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817540},\"label\":\"20210113-092303F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610529783,\"stop\":1610529817},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000037\",\"stop\":\"000000010000000000000038\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-093202F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610530322,\"stop\":1610530360},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000003A\",\"stop\":\"00000001000000000000003A\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-094105F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610530865,\"stop\":1610530897},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000003C\",\"stop\":\"00000001000000000000003D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405653,\"size\":4405653},\"size\":37817540},\"label\":\"20210113-095426F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610531666,\"stop\":1610531698},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000003F\",\"stop\":\"000000010000000000000040\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817539,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817539},\"label\":\"20210113-101132F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610532692,\"stop\":1610532729},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000042\",\"stop\":\"000000010000000000000043\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-102958F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610533798,\"stop\":1610533830},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000045\",\"stop\":\"000000010000000000000045\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817540},\"label\":\"20210113-104636F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610534796,\"stop\":1610534831},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000047\",\"stop\":\"000000010000000000000048\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-110141F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610535701,\"stop\":1610535736},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000004A\",\"stop\":\"00000001000000000000004A\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-111522F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610536522,\"stop\":1610536561},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000004C\",\"stop\":\"00000001000000000000004D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405652,\"size\":4405652},\"size\":37817540},\"label\":\"20210113-113135F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610537495,\"stop\":1610537531},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000004F\",\"stop\":\"000000010000000000000050\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405653,\"size\":4405653},\"size\":37817540},\"label\":\"20210113-114501F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610538301,\"stop\":1610538336},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000052\",\"stop\":\"000000010000000000000052\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-120139F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610539299,\"stop\":1610539336},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000054\",\"stop\":\"000000010000000000000054\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-121134F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610539894,\"stop\":1610539929},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000056\",\"stop\":\"000000010000000000000057\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817539,\"repository\":{\"delta\":4405648,\"size\":4405648},\"size\":37817539},\"label\":\"20210113-122750F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610540870,\"stop\":1610540906},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000059\",\"stop\":\"00000001000000000000005A\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405653,\"size\":4405653},\"size\":37817540},\"label\":\"20210113-124154F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610541714,\"stop\":1610541750},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000005C\",\"stop\":\"00000001000000000000005D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405653,\"size\":4405653},\"size\":37817540},\"label\":\"20210113-125814F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610542694,\"stop\":1610542726},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000005F\",\"stop\":\"00000001000000000000005F\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405651,\"size\":4405651},\"size\":37817540},\"label\":\"20210113-130550F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610543150,\"stop\":1610543188},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000061\",\"stop\":\"000000010000000000000061\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405650,\"size\":4405650},\"size\":37817540},\"label\":\"20210113-132032F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610544032,\"stop\":1610544070},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000063\",\"stop\":\"000000010000000000000064\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37817540,\"repository\":{\"delta\":4405653,\"size\":4405653},\"size\":37817540},\"label\":\"20210113-133652F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610545012,\"stop\":1610545045},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917106627632627914,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":false}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:459" version=4.5.0
time="2021-01-13T16:09:58Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:461" version=4.5.0

[v3nturetheworld]

Scheduler Logs:

time="2021-01-13T05:05:16Z" level=debug msg="debug flag set to true" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:77" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="PGO_INSTALLATION_NAME set to crunchy-operator" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:86" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="Setting timeout to: 3600" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:105" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="Config: pgo-config ConfigMap found, using config files from the configmap" func="internal/config.getRootPath()" file="internal/config/pgoconfig.go:745" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="default instance memory set to [128Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:387" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="default pgbackrest repository memory set to [200Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:393" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="default pgbouncer memory set to [24Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:399" version=4.5.0
time="2021-01-13T05:05:16Z" level=info msg="Starting Crunchy Scheduler" func="main.main()" file="pgo-scheduler/pgo-scheduler.go:127" version=4.5.0
time="2021-01-13T05:05:21Z" level=info msg="Watching namespaces: [test-project]" func="main.main()" file="pgo-scheduler/pgo-scheduler.go:155" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="ConfigMap Controller: added event handler to informer" func="pgo-scheduler/scheduler.(*Controller).AddConfigMapEventHandler()" file="pgo-scheduler/scheduler/configmapcontroller.go:71" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: added controller group for namespace test-project" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:237" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: new controller manager created for namespaces [test-project]" func="pgo-scheduler/scheduler.NewControllerManager()" file="pgo-scheduler/scheduler/controllermanager.go:78" version=4.5.0
I0113 05:05:21.577419       8 shared_informer.go:197] Waiting for caches to sync for test-project
I0113 05:05:21.677617       8 shared_informer.go:204] Caches are synced for test-project 
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is now running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:330" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: all contoller groups are now running" func="pgo-scheduler/scheduler.(*ControllerManager).RunAll()" file="pgo-scheduler/scheduler/controllermanager.go:174" version=4.5.0
I0113 05:05:21.677805       8 shared_informer.go:197] Waiting for caches to sync for scheduler namespace
I0113 05:05:21.778014       8 shared_informer.go:204] Caches are synced for scheduler namespace 
time="2021-01-13T05:05:21Z" level=debug msg="scheduler namespace controller is now running" func="main.createAndStartNamespaceController()" file="pgo-scheduler/pgo-scheduler.go:254" version=4.5.0
I0113 05:05:21.778121       8 shared_informer.go:197] Waiting for caches to sync for scheduler namespace
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0
I0113 05:05:21.878209       8 shared_informer.go:204] Caches are synced for scheduler namespace 
time="2021-01-13T05:05:21Z" level=debug msg="scheduler namespace controller is now running" func="main.createAndStartNamespaceController()" file="pgo-scheduler/pgo-scheduler.go:254" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T05:05:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T05:15:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0
time="2021-01-13T05:16:45Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T05:16:45Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T05:16:45Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0
...
time="2021-01-13T16:22:53Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.0
time="2021-01-13T16:22:53Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.0
time="2021-01-13T16:22:53Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.0

[v3nturetheworld]

Operator logs:

time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-cpxe-9875b455c-j7g9k/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-5d97444c75-x6xjh/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:32:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T15:32:30Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-4czn7 in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.0
time="2021-01-13T15:32:30Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4czn7 in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:32:30Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.0
time="2021-01-13T15:32:30Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.0
time="2021-01-13T15:32:30Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4czn7 in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:32:33Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4czn7 in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:32:49Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:32:49Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:33:09Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4czn7 in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T15:33:14Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T15:33:14Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0

time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:33:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T15:33:22Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T15:33:22Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T15:34:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T15:34:22Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T15:34:22Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
time="2021-01-13T15:35:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
....
time="2021-01-13T16:06:58Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.0
time="2021-01-13T16:06:58Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.0
time="2021-01-13T16:06:58Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-46xrb in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:07:01Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-46xrb in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:07:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:07:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:07:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:07:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:07:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:07:38Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-46xrb in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:08:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:08:18Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-s9frz in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.0
time="2021-01-13T16:08:18Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s9frz in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:18Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.0
time="2021-01-13T16:08:18Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.0
time="2021-01-13T16:08:18Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s9frz in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s9frz in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:08:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:08:39Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:39Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:49Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:49Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:08:54Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s9frz in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:09:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:09:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:09:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:09:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:09:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:10:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:10:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:10:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:10:50Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-lnl7d in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.0
time="2021-01-13T16:10:50Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-lnl7d in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:10:50Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.0
time="2021-01-13T16:10:50Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.0
time="2021-01-13T16:10:50Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-lnl7d in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:10:53Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-lnl7d in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:11:09Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:11:09Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:11:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:11:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:11:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-5d97444c75-x6xjh in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:11:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-cpxe-9875b455c-j7g9k in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:11:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:11:28Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-lnl7d in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.0
time="2021-01-13T16:12:03Z" level=debug msg="[pgreplica Controller] onUpdate ns=test-project /apis/crunchydata.com/v1/namespaces/test-project/pgreplicas/test-crunchy-cluster-cpxe" func="internal/controller/pgreplica.(*Controller).onUpdate()" file="internal/controller/pgreplica/pgreplicacontroller.go:173" version=4.5.0
time="2021-01-13T16:12:03Z" level=warning msg="crv1 pgreplica test-crunchy-cluster-cpxe is already marked complete, will not recreate" func="internal/operator/cluster.ScaleBase()" file="internal/operator/cluster/cluster.go:323" version=4.5.0
time="2021-01-13T16:12:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:12:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:12:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0
time="2021-01-13T16:13:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.0
time="2021-01-13T16:13:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.0
...
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-cpxe-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.0
time="2021-01-13T16:13:21Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.0

[jkatz]

@v3nturetheworld These logs are for 4.5.0. As mentioned in https://github.com/CrunchyData/postgres-operator/issues/2106#issuecomment-741823909 there was a fix in 4.5.1 that may have handled this scenario. If it's still being reproduced in 4.5.1, those logs would be more interesting, though could understand if it has similar output.

Also, I don't see anything particular in these logs that indicate there is an issue with the Operator. I may gander into the Pod controller to see if there could be something there, but I'm not convinced yet there is an issue.

How long do the backups take to execute?

(As I finished typing this I saw your edit in terms of retrying on 4.5.1 :smile:)

[v3nturetheworld]

@jkatz So I just re-ran the same scenario (with same configurations) but with the 4.5.1 Operator and images, the problem still seems to occur. The backrest backups run in ~60-70 seconds with the local storage configuration so they are quick at least, though there isn't much data in the actual DB.

# Show Cluster
sh-4.2$ pgo show cluster test-crunchy-cluster -n test-project

cluster : test-crunchy-cluster (crunchy-postgres-ha:centos7-13.1-4.5.1)
        pod : test-crunchy-cluster-6bf7576b7-lhx9r (Running) on node01.nmd7.zone5 (1/1) (primary)
                pvc: test-crunchy-cluster (1Gi)
        pod : test-crunchy-cluster-ibvn-77d954c8c5-wpf6f (Running) on node02.nmd7.zone5 (1/1) (replica)
                pvc: test-crunchy-cluster-ibvn (1Gi)
        resources : CPU: 30m Memory: 690Mi
        limits : Memory: 2Gi
        deployment : test-crunchy-cluster
        deployment : test-crunchy-cluster-backrest-shared-repo
        deployment : test-crunchy-cluster-ibvn
        service : test-crunchy-cluster - ClusterIP (172.30.253.149) - Ports (2022/TCP, 5432/TCP)
        service : test-crunchy-cluster-replica - ClusterIP (172.30.4.22) - Ports (2022/TCP, 5432/TCP)
        pgreplica : test-crunchy-cluster-ibvn
        labels : pg-cluster=test-crunchy-cluster pg-pod-anti-affinity= pgo-backrest=true pgo-version=4.5.1 crunchy-pgbadger=false crunchy-pgha-scope=test-crunchy-cluster deployment-name=test-crunchy-cluster name=test-crunchy-cluster pgouser=admin workflowid=57e53d79-8d65-46e3-aa81-2cffc63e2e3e autofail=true crunchy-postgres-exporter=false

Schedule:

sh-4.2$ pgo show schedule test-crunchy-cluster -n test-project
No schedules found.

Backups

sh-4.2$ pgo show backup test-crunchy-cluster -n test-project

cluster: test-crunchy-cluster
storage type: local

stanza: db
    status: ok
    cipher: none

    db (current)
        wal archive min/max (13-1)

        full backup: 20210114-001257F
            timestamp start/stop: 2021-01-14 00:12:57 +0000 UTC / 2021-01-14 00:13:39 +0000 UTC
            wal start/stop: 000000010000000000000002 / 000000010000000000000002
            database size: 35.4MiB, backup size: 35.4MiB
            repository size: 3.9MiB, repository backup size: 3.9MiB
            backup reference list: 

        full backup: 20210114-002622F
            timestamp start/stop: 2021-01-14 00:26:22 +0000 UTC / 2021-01-14 00:26:57 +0000 UTC
            wal start/stop: 000000010000000000000007 / 000000010000000000000008
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-004058F
            timestamp start/stop: 2021-01-14 00:40:58 +0000 UTC / 2021-01-14 00:41:32 +0000 UTC
            wal start/stop: 00000001000000000000000B / 00000001000000000000000B
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-005036F
            timestamp start/stop: 2021-01-14 00:50:36 +0000 UTC / 2021-01-14 00:51:08 +0000 UTC
            wal start/stop: 00000001000000000000000D / 00000001000000000000000D
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-010033F
            timestamp start/stop: 2021-01-14 01:00:33 +0000 UTC / 2021-01-14 01:01:06 +0000 UTC
            wal start/stop: 00000001000000000000000F / 00000001000000000000000F
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-011540F
            timestamp start/stop: 2021-01-14 01:15:40 +0000 UTC / 2021-01-14 01:16:14 +0000 UTC
            wal start/stop: 000000010000000000000011 / 000000010000000000000012
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-012847F
            timestamp start/stop: 2021-01-14 01:28:47 +0000 UTC / 2021-01-14 01:29:21 +0000 UTC
            wal start/stop: 000000010000000000000014 / 000000010000000000000015
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

        full backup: 20210114-013711F
            timestamp start/stop: 2021-01-14 01:37:11 +0000 UTC / 2021-01-14 01:37:46 +0000 UTC
            wal start/stop: 000000010000000000000017 / 000000010000000000000018
            database size: 36.1MiB, backup size: 36.1MiB
            repository size: 4.2MiB, repository backup size: 4.2MiB
            backup reference list: 

Backrest backup times:

sh-4.2$ cat /tmp/db-backup.log | grep "backup command end"
2021-01-14 00:13:53.768 P00   INFO: backup command end: completed successfully (67378ms)
2021-01-14 00:27:12.385 P00   INFO: backup command end: completed successfully (60275ms)
2021-01-14 00:41:47.431 P00   INFO: backup command end: completed successfully (59445ms)
2021-01-14 00:51:23.117 P00   INFO: backup command end: completed successfully (57631ms)
2021-01-14 01:01:21.553 P00   INFO: backup command end: completed successfully (58496ms)
2021-01-14 01:16:41.659 P00   INFO: backup command end: completed successfully (71668ms)
2021-01-14 01:29:48.826 P00   INFO: backup command end: completed successfully (72119ms)
2021-01-14 01:38:01.032 P00   INFO: backup command end: completed successfully (60231ms)
2021-01-14 01:51:21.478 P00   INFO: backup command end: completed successfully (58272ms)

I'll add the operator logs in another comment

[v3nturetheworld]

Operator logs (I cut a lot out, so let me know if I should focus on getting a specific type or sequence of logs from the operator container):

time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-ibvn-77d954c8c5-wpf6f/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true " func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-6bf7576b7-lhx9r/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true " func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-ibvn-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:28:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:16:42 +0000 UTC 2021-01-14 01:16:42 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="jobController onUpdate backrest job case" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:131" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="got a backrest job status=1" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:132" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="update the status to completed here for backrest test-crunchy-cluster job backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:133" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="[{\"op\":\"replace\",\"path\":\"/spec/status\",\"value\":\"job completed\"}]" func="internal/util.Patch()" file="internal/util/util.go:76" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="jobController onUpdate initial backup complete" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:145" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/test-crunchy-cluster-stanza-create active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 00:12:42 +0000 UTC 2021-01-14 00:12:42 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="jobController onUpdate backrest stanza-create job case" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:169" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="backrest stanza successfully created for cluster test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:176" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="proceeding with the initial full backup for cluster test-crunchy-cluster as needed for replica creation" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:177" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="the backrest repo pod for the initial backup of cluster test-crunchy-cluster is test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:185" version=4.5.1
time="2021-01-14T01:28:33Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-qjlft in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="pgBackRest operator CreateBackup called" func="internal/operator/backrest.CreateBackup()" file="internal/operator/backrest/backup.go:177" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:16:42 +0000 UTC 2021-01-14 01:16:42 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="task putting key in queue test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).onAdd()" file="internal/controller/pgtask/pgtaskcontroller.go:183" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="working on test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:74" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="queue got key ns=[test-project] resource=[backrest-backup-test-crunchy-cluster]" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:79" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster is being deleted and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:48" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="[Job Controller] onDelete ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onDelete()" file="internal/controller/job/jobcontroller.go:105" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="backrest task added" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:139" version=4.5.1
{
    "apiVersion": "batch/v1",
    "kind": "Job",
    "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
    },
    "spec": {
        "template": {
            "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
            },
            "spec": {
                "volumes": [

                ],
                "securityContext": {},
                "serviceAccountName": "pgo-backrest",
                "containers": [{
                    "name": "backrest",
                    "image": "registry.site.server:49652/pgo-backrest:centos7-4.5.1",
            "resources": { "limits": { "cpu": "250m", "memory": "200Mi"}, "requests": { "cpu": "50m", "memory": "75Mi" }},
                    "volumeMounts": [

                    ],
                    "env": [{
            "name": "NSS_SDB_USE_CACHE", 
            "value": "no"
            }, {
                        "name": "COMMAND",
                        "value": "backup"
                    }, {
                        "name": "COMMAND_OPTS",
                        "value": "--type=full --db-host=10.130.0.233 --db-path=/pgdata/test-crunchy-cluster"
                    }, {
                        "name": "PITR_TARGET",
                        "value": ""
                    }, {
                        "name": "PODNAME",
                        "value": "test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52"
                    }, {
                        "name": "PGBACKREST_STANZA",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_DB_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_TYPE",
                        "value": "posix"
                    },{
                        "name": "PGHA_PGBACKREST_LOCAL_S3_STORAGE",
                        "value": "false"
                    },{
                        "name": "PGHA_PGBACKREST_S3_VERIFY_TLS",
                        "value": "false"
                    },{
                        "name": "PGBACKREST_LOG_PATH",
                        "value": "/tmp"
                    }, {
                        "name": "NAMESPACE",
                        "valueFrom": {
                            "fieldRef": {
                                "fieldPath": "metadata.namespace"
                            }
                        }
                    }]
                }],
                "restartPolicy": "Never"
            }
        }
    }
}
time="2021-01-14T01:28:34Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="Job Controller: onAdd ns=test-project jobName=/apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onAdd()" file="internal/controller/job/jobcontroller.go:50" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:28:34Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:28:37Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:28:55Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:28:55Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:05Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:05Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:09Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
time="2021-01-14T01:29:09Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1
time="2021-01-14T01:29:15Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:15Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-ibvn-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:119" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: applying DCS config to cluster test-crunchy-cluster in namespace test-project" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:172" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: applying local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:229" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: DCS config for cluster test-crunchy-cluster in namespace test-project is up-to-date, nothing to apply" func="internal/operator/config.(*DCS).apply()" file="internal/operator/config/dcs.go:189" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-ibvn-77d954c8c5-wpf6f/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true " func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-6bf7576b7-lhx9r/exec?command=%2Fopt%2Fcpm%2Fbin%2Fcommon%2Fpgha-reload-local.sh&command=postgresql%3A%0A++authentication%3A%0A++++replication%3A%0A++++++sslcert%3A+%2Fpgconf%2Ftls-replication%2Ftls.crt%0A++++++sslkey%3A+%2Fpgconf%2Ftls-replication%2Ftls.key%0A++++++sslmode%3A+verify-ca%0A++++++sslrootcert%3A+%2Fpgconf%2Ftls%2Fca.crt%0A++callbacks%3A%0A++++on_role_change%3A+%2Fopt%2Fcpm%2Fbin%2Fcallbacks%2Fpgha-on-role-change.sh%0A++create_replica_methods%3A%0A++-+pgbackrest%0A++-+basebackup%0A++pg_hba%3A%0A++-+local+all+postgres+peer%0A++-+local+all+crunchyadm+peer%0A++-+hostssl+replication+primaryuser+0.0.0.0%2F0+cert%0A++-+hostssl+all+primaryuser+0.0.0.0%2F0+reject%0A++-+hostssl+all+all+0.0.0.0%2F0+md5%0A++pgbackrest%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+replica%0A++++keep_data%3A+true%0A++++no_params%3A+true%0A++pgbackrest_standby%3A%0A++++command%3A+%2Fopt%2Fcpm%2Fbin%2Fpgbackrest%2Fpgbackrest-create-replica.sh+standby%0A++++keep_data%3A+true%0A++++no_master%3A+1%0A++++no_params%3A+true%0A++pgpass%3A+%2Ftmp%2F.pgpass%0A++remove_data_directory_on_rewind_failure%3A+true%0A++use_unix_socket%3A+true%0A&command=8009&container=database&stderr=true&stdout=true " func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-ibvn-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:29:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T01:29:25Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:25Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:35Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:35Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:29:49 +0000 UTC 2021-01-14 01:29:49 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="jobController onUpdate backrest job case" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:131" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="got a backrest job status=1" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:132" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="update the status to completed here for backrest test-crunchy-cluster job backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:133" version=4.5.1
time="2021-01-14T01:29:49Z" level=debug msg="[{\"op\":\"replace\",\"path\":\"/spec/status\",\"value\":\"job completed\"}]" func="internal/util.Patch()" file="internal/util/util.go:76" version=4.5.1

time="2021-01-14T01:36:57Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="jobController onUpdate initial backup complete" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:145" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/test-crunchy-cluster-stanza-create active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 00:12:42 +0000 UTC 2021-01-14 00:12:42 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="jobController onUpdate backrest stanza-create job case" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:169" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="backrest stanza successfully created for cluster test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:176" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="proceeding with the initial full backup for cluster test-crunchy-cluster as needed for replica creation" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:177" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="the backrest repo pod for the initial backup of cluster test-crunchy-cluster is test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:185" version=4.5.1
time="2021-01-14T01:36:57Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-twl6b in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="pgBackRest operator CreateBackup called" func="internal/operator/backrest.CreateBackup()" file="internal/operator/backrest/backup.go:177" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="task putting key in queue test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).onAdd()" file="internal/controller/pgtask/pgtaskcontroller.go:183" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="working on test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:74" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="queue got key ns=[test-project] resource=[backrest-backup-test-crunchy-cluster]" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:79" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:29:49 +0000 UTC 2021-01-14 01:29:49 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster is being deleted and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:48" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="[Job Controller] onDelete ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onDelete()" file="internal/controller/job/jobcontroller.go:105" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="backrest task added" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:139" version=4.5.1
{
    "apiVersion": "batch/v1",
    "kind": "Job",
    "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
    },
    "spec": {
        "template": {
            "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
            },
            "spec": {
                "volumes": [

                ],
                "securityContext": {},
                "serviceAccountName": "pgo-backrest",
                "containers": [{
                    "name": "backrest",
                    "image": "registry.site.server:49652/pgo-backrest:centos7-4.5.1",
            "resources": { "limits": { "cpu": "250m", "memory": "200Mi"}, "requests": { "cpu": "50m", "memory": "75Mi" }},
                    "volumeMounts": [

                    ],
                    "env": [{
            "name": "NSS_SDB_USE_CACHE", 
            "value": "no"
            }, {
                        "name": "COMMAND",
                        "value": "backup"
                    }, {
                        "name": "COMMAND_OPTS",
                        "value": "--type=full --db-host=10.130.0.233 --db-path=/pgdata/test-crunchy-cluster"
                    }, {
                        "name": "PITR_TARGET",
                        "value": ""
                    }, {
                        "name": "PODNAME",
                        "value": "test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52"
                    }, {
                        "name": "PGBACKREST_STANZA",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_DB_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_TYPE",
                        "value": "posix"
                    },{
                        "name": "PGHA_PGBACKREST_LOCAL_S3_STORAGE",
                        "value": "false"
                    },{
                        "name": "PGHA_PGBACKREST_S3_VERIFY_TLS",
                        "value": "false"
                    },{
                        "name": "PGBACKREST_LOG_PATH",
                        "value": "/tmp"
                    }, {
                        "name": "NAMESPACE",
                        "valueFrom": {
                            "fieldRef": {
                                "fieldPath": "metadata.namespace"
                            }
                        }
                    }]
                }],
                "restartPolicy": "Never"
            }
        }
    }
}
time="2021-01-14T01:36:58Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="Job Controller: onAdd ns=test-project jobName=/apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onAdd()" file="internal/controller/job/jobcontroller.go:50" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.1
time="2021-01-14T01:36:58Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:03Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:08Z" level=debug msg="pgcluster onUpdate for cluster test-project (namespace test-crunchy-cluster)" func="internal/controller/pgcluster.(*Controller).onUpdate()" file="internal/controller/pgcluster/pgclustercontroller.go:173" version=4.5.1
time="2021-01-14T01:37:15Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:15Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
...
time="2021-01-14T01:37:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T01:37:25Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:25Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:54Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
time="2021-01-14T01:37:54Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1
time="2021-01-14T01:37:55Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:37:55Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:38:01 +0000 UTC 2021-01-14 01:38:01 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="jobController onUpdate backrest job case" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:131" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="got a backrest job status=1" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:132" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="update the status to completed here for backrest test-crunchy-cluster job backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:133" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="[{\"op\":\"replace\",\"path\":\"/spec/status\",\"value\":\"job completed\"}]" func="internal/util.Patch()" file="internal/util/util.go:76" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:38:01Z" level=debug msg="jobController onUpdate initial backup complete" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:145" version=4.5.1
time="2021-01-14T01:38:17Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.1
time="2021-01-14T01:38:17Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.1
...
time="2021-01-14T01:38:17Z" level=debug msg="Cluster Config: finished syncing DCS config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*DCS).Sync()" file="internal/operator/config/dcs.go:132" version=4.5.1

ime="2021-01-14T01:50:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-ibvn-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:50:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T01:50:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:38:01 +0000 UTC 2021-01-14 01:38:01 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="jobController onUpdate backrest job case" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:131" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="got a backrest job status=1" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:132" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="update the status to completed here for backrest test-crunchy-cluster job backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:133" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="[{\"op\":\"replace\",\"path\":\"/spec/status\",\"value\":\"job completed\"}]" func="internal/util.Patch()" file="internal/util/util.go:76" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="jobController onUpdate initial backup complete" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:145" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/test-crunchy-cluster-stanza-create active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 00:12:42 +0000 UTC 2021-01-14 00:12:42 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="jobController onUpdate backrest stanza-create job case" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:169" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="backrest stanza successfully created for cluster test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:176" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="proceeding with the initial full backup for cluster test-crunchy-cluster as needed for replica creation" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:177" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="the backrest repo pod for the initial backup of cluster test-crunchy-cluster is test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:185" version=4.5.1
time="2021-01-14T01:50:19Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-s44jf in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="pgBackRest operator CreateBackup called" func="internal/operator/backrest.CreateBackup()" file="internal/operator/backrest/backup.go:177" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="task putting key in queue test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).onAdd()" file="internal/controller/pgtask/pgtaskcontroller.go:183" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="working on test-project/backrest-backup-test-crunchy-cluster" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:74" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="queue got key ns=[test-project] resource=[backrest-backup-test-crunchy-cluster]" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:79" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:38:01 +0000 UTC 2021-01-14 01:38:01 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster is being deleted and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:48" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="[Job Controller] onDelete ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onDelete()" file="internal/controller/job/jobcontroller.go:105" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="backrest task added" func="internal/controller/pgtask.(*Controller).processNextItem()" file="internal/controller/pgtask/pgtaskcontroller.go:139" version=4.5.1
{
    "apiVersion": "batch/v1",
    "kind": "Job",
    "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
    },
    "spec": {
        "template": {
            "metadata": {
                "name": "backrest-backup-test-crunchy-cluster",
                "labels": {
                    "vendor": "crunchydata",
                    "pgo-backrest": "true",
                    "pgo-backrest-job": "true",
                    "backrest-command": "backup",
                    "pg-cluster": "test-crunchy-cluster"
                }
            },
            "spec": {
                "volumes": [

                ],
                "securityContext": {},
                "serviceAccountName": "pgo-backrest",
                "containers": [{
                    "name": "backrest",
                    "image": "registry.site.server:49652/pgo-backrest:centos7-4.5.1",
            "resources": { "limits": { "cpu": "250m", "memory": "200Mi"}, "requests": { "cpu": "50m", "memory": "75Mi" }},
                    "volumeMounts": [

                    ],
                    "env": [{
            "name": "NSS_SDB_USE_CACHE", 
            "value": "no"
            }, {
                        "name": "COMMAND",
                        "value": "backup"
                    }, {
                        "name": "COMMAND_OPTS",
                        "value": "--type=full --db-host=10.130.0.233 --db-path=/pgdata/test-crunchy-cluster"
                    }, {
                        "name": "PITR_TARGET",
                        "value": ""
                    }, {
                        "name": "PODNAME",
                        "value": "test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52"
                    }, {
                        "name": "PGBACKREST_STANZA",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_DB_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_PATH",
                        "value": ""
                    }, {
                        "name": "PGBACKREST_REPO_TYPE",
                        "value": "posix"
                    },{
                        "name": "PGHA_PGBACKREST_LOCAL_S3_STORAGE",
                        "value": "false"
                    },{
                        "name": "PGHA_PGBACKREST_S3_VERIFY_TLS",
                        "value": "false"
                    },{
                        "name": "PGBACKREST_LOG_PATH",
                        "value": "/tmp"
                    }, {
                        "name": "NAMESPACE",
                        "valueFrom": {
                            "fieldRef": {
                                "fieldPath": "metadata.namespace"
                            }
                        }
                    }]
                }],
                "restartPolicy": "Never"
            }
        }
    }
}
time="2021-01-14T01:50:20Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="Job Controller: onAdd ns=test-project jobName=/apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).onAdd()" file="internal/controller/job/jobcontroller.go:50" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="Pod Controller: onAdd processing the addition of pod backrest-backup-test-crunchy-cluster-4s7wq in namespace test-project" func="internal/controller/pod.(*Controller).onAdd()" file="internal/controller/pod/podcontroller.go:48" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4s7wq in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=1 succeeded=0 conditions=[[]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="jobController onUpdate job backrest-backup-test-crunchy-cluster was unsuccessful and will be ignored" func="internal/controller/job.(*Controller).handleBackrestUpdate()" file="internal/controller/job/backresthandler.go:41" version=4.5.1
time="2021-01-14T01:50:20Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4s7wq in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:23Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4s7wq in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:35Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-6bf7576b7-lhx9r in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:35Z" level=debug msg="Pod Controller: onUpdate processing update for pod test-crunchy-cluster-ibvn-77d954c8c5-wpf6f in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:50:38Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227"
...
time="2021-01-14T01:51:22Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-test-crunchy-cluster-4s7wq in namespace test-project" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="[Job Controller] onUpdate ns=test-project /apis/batch/v1/namespaces/test-project/jobs/backrest-backup-test-crunchy-cluster active=0 succeeded=1 conditions=[[{Complete True 2021-01-14 01:51:22 +0000 UTC 2021-01-14 01:51:22 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="jobController onUpdate backrest job case" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:131" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="got a backrest job status=1" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:132" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="update the status to completed here for backrest test-crunchy-cluster job backrest-backup-test-crunchy-cluster" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:133" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="[{\"op\":\"replace\",\"path\":\"/spec/status\",\"value\":\"job completed\"}]" func="internal/util.Patch()" file="internal/util/util.go:76" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="eventing disabled" func="pkg/events.Publish()" file="pkg/events/eventing.go:39" version=4.5.1
time="2021-01-14T01:51:22Z" level=debug msg="jobController onUpdate initial backup complete" func="internal/controller/job.(*Controller).handleBackrestBackupUpdate()" file="internal/controller/job/backresthandler.go:145" version=4.5.1
time="2021-01-14T01:51:50Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
time="2021-01-14T01:51:50Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1
time="2021-01-14T01:52:17Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.1
time="2021-01-14T01:52:17Z" level=debug msg="Cluster Config: syncing local config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:149" version=4.5.1
...
time="2021-01-14T01:52:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T01:52:50Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
time="2021-01-14T01:52:50Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1
time="2021-01-14T01:53:17Z" level=debug msg="ConfigMap Controller: handling a configmap sync for key test-project/test-crunchy-cluster-pgha-config" func="internal/controller/configmap.(*Controller).handleConfigMapSync()" file="internal/controller/configmap/synchandler.go:35" version=4.5.1
...
time="2021-01-14T02:07:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T02:07:17Z" level=debug msg="Cluster Config: successfully applied local config test-crunchy-cluster-ibvn-local-config in cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
time="2021-01-14T02:07:17Z" level=debug msg="Cluster Config: finished syncing config for cluster test-crunchy-cluster (namespace test-project)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
time="2021-01-14T02:07:37Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
time="2021-01-14T02:07:37Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1

[v3nturetheworld]

API Server:

time="2021-01-14T00:11:12Z" level=debug msg="debug flag set to true"
time="2021-01-14T00:11:12Z" level=debug msg="TLS_NO_VERIFY set as false"
time="2021-01-14T00:11:12Z" level=debug msg="DISABLE_TLS set as false"
time="2021-01-14T00:11:17Z" level=info msg="postgres-operator apiserver starts" func="main.main()" file="apiserver.go:109" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="Pgo Namespace is [test-crunchy-operator]" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:103" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="InstallationName is [test-crunchy-operator]" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:110" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="apiserver starts" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:122" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="loading PermMap with 59 Permissions\n" func="internal/apiserver.initializePerms()" file="internal/apiserver/perms.go:187" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="Config: \"pgo-config\" ConfigMap found, using config files from the configmap" func="internal/config.initialize()" file="internal/config/pgoconfig.go:742" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="default instance memory set to [128Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:388" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="default pgbackrest repository memory set to [200Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:394" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="default pgbouncer memory set to [24Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:400" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="BasicAuth is true" func="internal/apiserver.initConfig()" file="internal/apiserver/root.go:194" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="Namespace operating mode is 'readonly'" func="internal/apiserver.Initialize()" file="internal/apiserver/root.go:154" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="pgo.tls Secret found in namespace test-crunchy-operator" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:427" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="cert key data len is 1285" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:428" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="private key data len is 1679" func="internal/apiserver.WriteTLSCert()" file="internal/apiserver/root.go:434" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="listening on port 8443" func="main.main()" file="apiserver.go:164" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="create cluster called for test-crunchy-cluster" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:561" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="pgcluster test-crunchy-cluster not found so we will create it" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:571" version=4.5.1
time="2021-01-14T00:11:53Z" level=error msg="pgclusters.crunchydata.com \"test-crunchy-cluster\" not found" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:719" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg=userLabelsMap func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:778" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="map[crunchy-postgres-exporter:false]" func="internal/apiserver/clusterservice.CreateCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:779" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="Pgo.Cluster.Policies " func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1370" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="[1] is Pgo.Cluster.Replicas" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1377" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="replica count is 0" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1381" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg=5432 func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1391" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="username set to [dbuser]" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1405" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="database set to [userdb]" func="internal/apiserver/clusterservice.getClusterParams()" file="internal/apiserver/clusterservice/clusterimpl.go:1420" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg=" is Pgo.Cluster.Policies" func="internal/apiserver/clusterservice.validateConfigPolicies()" file="internal/apiserver/clusterservice/clusterimpl.go:1061" version=4.5.1
time="2021-01-14T00:11:53Z" level=debug msg="no policies are specified in either pgo.yaml or from user" func="internal/apiserver/clusterservice.validateConfigPolicies()" file="internal/apiserver/clusterservice/clusterimpl.go:1068" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="clusterservice.DeleteClusterHandler {pca-crunchy-postgresql  4.5.1 blue false true true}\n" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:198" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="DeleteClusterHandler: parameters namespace [blue] selector [] delete-data [true] delete-backups [true]" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:209" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="Authentication Attempt DeleteCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="clusterservice.DeleteClusterHandler called" func="internal/apiserver/clusterservice.DeleteClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:220" version=4.5.1
time="2021-01-14T00:19:22Z" level=debug msg="GetNamespace username [admin] ns [blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:19:53Z" level=debug msg="GetNamespace username [admin] ns [blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:20:00Z" level=debug msg="GetNamespace username [admin] ns [blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="clusterservice.CreateClusterHandler called" func="internal/apiserver/clusterservice.CreateClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:52" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="Authentication Attempt CreateCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T00:20:08Z" level=debug msg="GetNamespace username [admin] ns [blue]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="clusterservice.ShowClusterHandler {test-crunchy-operator   4.5.1 test-project false}\n" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:125" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="ShowClusterHandler: parameters name [test-crunchy-operator] selector [] ccpimagetag [] version [4.5.1] namespace [test-project] allflag [false]" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:134" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="Authentication Attempt ShowCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="clusterservice.ShowClusterHandler GET called" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:145" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="selector on showCluster is name=test-crunchy-operator" func="internal/apiserver/clusterservice.ShowCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:140" version=4.5.1
time="2021-01-14T01:49:10Z" level=debug msg="clusters found len is 0" func="internal/apiserver/clusterservice.ShowCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:150" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="clusterservice.ShowClusterHandler {test-crunchy-cluster   4.5.1 test-project false}\n" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:125" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="ShowClusterHandler: parameters name [test-crunchy-cluster] selector [] ccpimagetag [] version [4.5.1] namespace [test-project] allflag [false]" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:134" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="Authentication Attempt ShowCluster username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="clusterservice.ShowClusterHandler GET called" func="internal/apiserver/clusterservice.ShowClusterHandler()" file="internal/apiserver/clusterservice/clusterservice.go:145" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="selector on showCluster is name=test-crunchy-cluster" func="internal/apiserver/clusterservice.ShowCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:140" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="clusters found len is 1" func="internal/apiserver/clusterservice.ShowCluster()" file="internal/apiserver/clusterservice/clusterimpl.go:150" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="selector for GetPods is pg-cluster=test-crunchy-cluster,pgo-pg-database" func="internal/apiserver/clusterservice.GetPods()" file="internal/apiserver/clusterservice/clusterimpl.go:227" version=4.5.1
time="2021-01-14T01:49:16Z" level=debug msg="got 2 services for test-crunchy-cluster" func="internal/apiserver/clusterservice.getServices()" file="internal/apiserver/clusterservice/clusterimpl.go:299" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="scheduleservice.ShowScheduleHandler called" func="internal/apiserver/scheduleservice.ShowScheduleHandler()" file="internal/apiserver/scheduleservice/scheduleservice.go:183" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="Authentication Attempt ShowSchedule username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="Show schedule called" func="internal/apiserver/scheduleservice.ShowSchedule()" file="internal/apiserver/scheduleservice/scheduleimpl.go:264" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="Finding configMaps with selector: crunchy-scheduler=true,pg-cluster=test-crunchy-cluster" func="internal/apiserver/scheduleservice.getSchedules()" file="internal/apiserver/scheduleservice/scheduleimpl.go:331" version=4.5.1
time="2021-01-14T01:50:27Z" level=debug msg="Parsing configMaps" func="internal/apiserver/scheduleservice.ShowSchedule()" file="internal/apiserver/scheduleservice/scheduleimpl.go:293" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="ShowBackrestHandler parameters name [test-crunchy-cluster] version [4.5.1] selector [] namespace [test-project]" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:125" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="Authentication Attempt ShowBackup username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="backrestservice.ShowBackrestHandler GET called" func="internal/apiserver/backrestservice.ShowBackrestHandler()" file="internal/apiserver/backrestservice/backrestservice.go:135" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="clusters found len is 1\n" func="internal/apiserver/backrestservice.ShowBackrest()" file="internal/apiserver/backrestservice/backrestimpl.go:366" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="backrest info command requested" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:434" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="Request URL: https://172.30.0.1:443/api/v1/namespaces/test-project/pods/test-crunchy-cluster-backrest-shared-repo-74554cbb58-z2x52/exec?command=pgbackrest&command=info&command=--output&command=json&container=database&stderr=true&stdout=true " func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:60" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="output=[[{\"archive\":[{\"database\":{\"id\":1},\"id\":\"13-1\",\"max\":\"000000010000000000000019\",\"min\":\"000000010000000000000001\"}],\"backup\":[{\"archive\":{\"start\":\"000000010000000000000002\",\"stop\":\"000000010000000000000002\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37094744,\"repository\":{\"delta\":4049582,\"size\":4049582},\"size\":37094744},\"label\":\"20210114-001257F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610583177,\"stop\":1610583219},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000007\",\"stop\":\"000000010000000000000008\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809269,\"repository\":{\"delta\":4404170,\"size\":4404170},\"size\":37809269},\"label\":\"20210114-002622F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610583982,\"stop\":1610584017},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000B\",\"stop\":\"00000001000000000000000B\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809269,\"repository\":{\"delta\":4404176,\"size\":4404176},\"size\":37809269},\"label\":\"20210114-004058F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610584858,\"stop\":1610584892},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000D\",\"stop\":\"00000001000000000000000D\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809268,\"repository\":{\"delta\":4404174,\"size\":4404174},\"size\":37809268},\"label\":\"20210114-005036F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610585436,\"stop\":1610585468},\"type\":\"full\"},{\"archive\":{\"start\":\"00000001000000000000000F\",\"stop\":\"00000001000000000000000F\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809269,\"repository\":{\"delta\":4404174,\"size\":4404174},\"size\":37809269},\"label\":\"20210114-010033F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610586033,\"stop\":1610586066},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000011\",\"stop\":\"000000010000000000000012\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809271,\"repository\":{\"delta\":4404176,\"size\":4404176},\"size\":37809271},\"label\":\"20210114-011540F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610586940,\"stop\":1610586974},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000014\",\"stop\":\"000000010000000000000015\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809271,\"repository\":{\"delta\":4404177,\"size\":4404177},\"size\":37809271},\"label\":\"20210114-012847F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610587727,\"stop\":1610587761},\"type\":\"full\"},{\"archive\":{\"start\":\"000000010000000000000017\",\"stop\":\"000000010000000000000018\"},\"backrest\":{\"format\":5,\"version\":\"2.29\"},\"database\":{\"id\":1},\"info\":{\"delta\":37809270,\"repository\":{\"delta\":4404175,\"size\":4404175},\"size\":37809270},\"label\":\"20210114-013711F\",\"prior\":null,\"reference\":null,\"timestamp\":{\"start\":1610588231,\"stop\":1610588266},\"type\":\"full\"}],\"cipher\":\"none\",\"db\":[{\"id\":1,\"system-id\":6917401884435321032,\"version\":\"13\"}],\"name\":\"db\",\"status\":{\"code\":0,\"lock\":{\"backup\":{\"held\":true}},\"message\":\"ok\"}}]]" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:453" version=4.5.1
time="2021-01-14T01:50:44Z" level=debug msg="backrest info ends" func="internal/apiserver/backrestservice.getInfo()" file="internal/apiserver/backrestservice/backrestimpl.go:455" version=4.5.1
time="2021-01-14T01:53:00Z" level=debug msg="versionservice.VersionHandler called" func="internal/apiserver/versionservice.VersionHandler()" file="internal/apiserver/versionservice/versionservice.go:40" version=4.5.1
time="2021-01-14T01:53:00Z" level=debug msg="Authentication Attempt Version username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:53:00Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:53:32Z" level=debug msg="ShowConfigHandler parameters version [4.5.1] namespace []" func="internal/apiserver/configservice.ShowConfigHandler()" file="internal/apiserver/configservice/configservice.go:55" version=4.5.1
time="2021-01-14T01:53:32Z" level=debug msg="Authentication Attempt ShowConfig username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:53:32Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:53:32Z" level=debug msg="GetNamespace username [admin] ns []" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:53:40Z" level=debug msg="ShowConfigHandler parameters version [4.5.1] namespace [test-project]" func="internal/apiserver/configservice.ShowConfigHandler()" file="internal/apiserver/configservice/configservice.go:55" version=4.5.1
time="2021-01-14T01:53:40Z" level=debug msg="Authentication Attempt ShowConfig username=[admin]" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:324" version=4.5.1
time="2021-01-14T01:53:40Z" level=debug msg="Authentication Success" func="internal/apiserver.Authn()" file="internal/apiserver/root.go:343" version=4.5.1
time="2021-01-14T01:53:40Z" level=debug msg="GetNamespace username [admin] ns [test-project]" func="internal/apiserver.GetNamespace()" file="internal/apiserver/root.go:276" version=4.5.1
time="2021-01-14T01:53:40Z" level=debug msg="ShowConfig called" func="internal/apiserver/configservice.ShowConfig()" file="internal/apiserver/configservice/configimpl.go:25" version=4.5.1

[v3nturetheworld]

Scheduler Logs:

time="2021-01-14T00:11:12Z" level=debug msg="debug flag set to true" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:77" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="PGO_INSTALLATION_NAME set to test-crunchy-operator" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:86" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="Setting timeout to: 3600" func="main.init.0()" file="pgo-scheduler/pgo-scheduler.go:105" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="Config: \"pgo-config\" ConfigMap found, using config files from the configmap" func="internal/config.initialize()" file="internal/config/pgoconfig.go:742" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="default instance memory set to [128Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:388" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="default pgbackrest repository memory set to [200Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:394" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="default pgbouncer memory set to [24Mi]" func="internal/config.(*PgoConfig).Validate()" file="internal/config/pgoconfig.go:400" version=4.5.1
time="2021-01-14T00:11:12Z" level=info msg="Starting Crunchy Scheduler" func="main.main()" file="pgo-scheduler/pgo-scheduler.go:127" version=4.5.1
time="2021-01-14T00:11:17Z" level=info msg="Watching namespaces: [test-project]" func="main.main()" file="pgo-scheduler/pgo-scheduler.go:155" version=4.5.1
time="2021-01-14T00:11:17Z" level=debug msg="ConfigMap Controller: added event handler to informer" func="pgo-scheduler/scheduler.(*Controller).AddConfigMapEventHandler()" file="pgo-scheduler/scheduler/configmapcontroller.go:71" version=4.5.1
time="2021-01-14T00:11:17Z" level=debug msg="Controller Manager: added controller group for namespace test-project" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:237" version=4.5.1
time="2021-01-14T00:11:17Z" level=debug msg="Controller Manager: new controller manager created for namespaces [test-project]" func="pgo-scheduler/scheduler.NewControllerManager()" file="pgo-scheduler/scheduler/controllermanager.go:78" version=4.5.1
I0114 00:11:17.898699       9 shared_informer.go:197] Waiting for caches to sync for test-project
I0114 00:11:17.998807       9 shared_informer.go:204] Caches are synced for test-project 
time="2021-01-14T00:11:17Z" level=debug msg="Controller Manager: controller group for namespace test-project is now running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:330" version=4.5.1
time="2021-01-14T00:11:17Z" level=debug msg="Controller Manager: all contoller groups are now running" func="pgo-scheduler/scheduler.(*ControllerManager).RunAll()" file="pgo-scheduler/scheduler/controllermanager.go:174" version=4.5.1
I0114 00:11:17.998955       9 shared_informer.go:197] Waiting for caches to sync for scheduler namespace
I0114 00:11:18.099065       9 shared_informer.go:204] Caches are synced for scheduler namespace 
time="2021-01-14T00:11:18Z" level=debug msg="scheduler namespace controller is now running" func="main.createAndStartNamespaceController()" file="pgo-scheduler/pgo-scheduler.go:254" version=4.5.1
I0114 00:11:18.099190       9 shared_informer.go:197] Waiting for caches to sync for scheduler namespace
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
I0114 00:11:18.199300       9 shared_informer.go:204] Caches are synced for scheduler namespace 
time="2021-01-14T00:11:18Z" level=debug msg="scheduler namespace controller is now running" func="main.createAndStartNamespaceController()" file="pgo-scheduler/pgo-scheduler.go:254" version=4.5.1
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:11:18Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:21:18Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:23:11Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:23:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:23:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:26:04Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:26:04Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:26:04Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:33:03Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:33:03Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:33:03Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:36:04Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:36:04Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:36:04Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:38:03Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:38:03Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:38:03Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:42:16Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:42:16Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:42:16Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:48:03Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:48:03Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:48:03Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:52:13Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:52:13Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:52:13Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:52:16Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:52:16Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:52:16Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T00:55:15Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T00:55:15Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T00:55:15Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:00:15Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:00:15Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:00:15Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:05:15Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:05:15Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:05:15Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:10:11Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:10:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:10:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:10:15Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:10:15Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:10:15Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:15:30Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:15:30Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:15:30Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:20:11Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:20:11Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:20:11Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:24:40Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:24:40Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:24:40Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:25:01Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:25:01Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:25:01Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:30:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:30:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:30:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:35:01Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:35:01Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:35:01Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:35:31Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:35:31Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:35:31Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:40:21Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:40:21Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:40:21Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:45:31Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:45:31Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:45:31Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:48:13Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:48:13Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:48:13Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:52:19Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:52:19Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:52:19Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T01:58:13Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T01:58:13Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T01:58:13Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T02:01:40Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T02:01:40Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T02:01:40Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1
time="2021-01-14T02:01:42Z" level=debug msg="Controller Manager: namespace test-project acquired clean lock and will clean the controller groups" func="pgo-scheduler/scheduler.(*ControllerManager).clean()" file="pgo-scheduler/scheduler/controllermanager.go:252" version=4.5.1
time="2021-01-14T02:01:42Z" level=debug msg="Controller Manager: a controller for namespace test-project already exists" func="pgo-scheduler/scheduler.(*ControllerManager).addControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:204" version=4.5.1
time="2021-01-14T02:01:42Z" level=debug msg="Controller Manager: controller group for namespace test-project is already running" func="pgo-scheduler/scheduler.(*ControllerManager).runControllerGroup()" file="pgo-scheduler/scheduler/controllermanager.go:311" version=4.5.1

Let me know if I should gather logs from anywhere else

[jkatz]

Thanks for the details We'll review and see if we need more.

I suspect there is something unique in your environment that is causing this to happen. I'm not saying that there isn't a potential code change to account for it, but there does seem to be something unique that is causing this.

I'll reopen this issue. I'm not convinced there is a bug yet, but I'm also not convinced that there isn't a bug.

[andrewlecuyer]

@v3nturetheworld can you please provide the contents of your pgcluster resource, e.g. the output of the following:

kubectl get pgcluster test-cluster -n crunchy-test -o yaml

[v3nturetheworld]

@andrewlecuyer Note: I have the S3 settings for minio configured as part of the operator deployment yaml, but its not being used here. Though the same issue did occur when using the s3 backup, which on an unrelated note I noticed some different issues with a race condition of some kind happening after a few backups occurred then an error message would pop up about a specific file already existing and needing to be deleted if I recall. Anyway let me know if you need anything additional. The crunchy operator is deployed using the pgo-deployer but a custom helm chart is used for setting up the RBACs, service accounts and other resources for watched namespaces, I'm not sure if there might be some issue being caused by that helm chart.

apiVersion: crunchydata.com/v1
kind: Pgcluster
metadata:
  annotations:
    current-primary: test-crunchy-cluster
    primary-deployment: test-crunchy-cluster
  creationTimestamp: "2021-01-14T00:11:53Z"
  generation: 1
  labels:
    autofail: "true"
    crunchy-pgbadger: "false"
    crunchy-pgha-scope: test-crunchy-cluster
    crunchy-postgres-exporter: "false"
    deployment-name: test-crunchy-cluster
    name: test-crunchy-cluster
    pg-cluster: test-crunchy-cluster
    pg-pod-anti-affinity: ""
    pgo-backrest: "true"
    pgo-version: 4.5.1
    pgouser: admin
    workflowid: 57e53d79-8d65-46e3-aa81-2cffc63e2e3e
  name: test-crunchy-cluster
  namespace: test-project
  resourceVersion: "82674517"
  selfLink: /apis/crunchydata.com/v1/namespaces/test-project/pgclusters/test-crunchy-cluster
  uid: 1b3d7c38-55fd-11eb-a6b8-9440c949d868
spec:
  ArchiveStorage:
    accessmode: ""
    matchLabels: ""
    name: ""
    size: ""
    storageclass: ""
    storagetype: ""
    supplementalgroups: ""
  BackrestStorage:
    accessmode: ReadWriteOnce
    matchLabels: ""
    name: ""
    size: 1Gi
    storageclass: openebs-sc
    storagetype: dynamic
    supplementalgroups: ""
  PrimaryStorage:
    accessmode: ReadWriteOnce
    matchLabels: ""
    name: test-crunchy-cluster
    size: 1Gi
    storageclass: local-storage-crunchy-sso
    storagetype: dynamic
    supplementalgroups: ""
  ReplicaStorage:
    accessmode: ReadWriteOnce
    matchLabels: ""
    name: ""
    size: 1Gi
    storageclass: local-storage-crunchy-sso
    storagetype: dynamic
    supplementalgroups: ""
  WALStorage:
    accessmode: ""
    matchLabels: ""
    name: ""
    size: ""
    storageclass: ""
    storagetype: ""
    supplementalgroups: ""
  annotations:
    backrest: {}
    global: {}
    pgBouncer: {}
    postgres: {}
  backrestConfig: null
  backrestLimits:
    memory: 120Mi
  backrestRepoPath: ""
  backrestResources:
    cpu: 60m
    memory: 60Mi
  backrestS3Bucket: crunchy-backups
  backrestS3Endpoint: minio.minio.svc.cluster.local:9000
  backrestS3Region: us-east-1
  backrestS3URIStyle: path
  backrestS3VerifyTLS: "false"
  ccpimage: crunchy-postgres-ha
  ccpimageprefix: registry.site.server:49652
  ccpimagetag: centos7-13.1-4.5.1
  clustername: test-crunchy-cluster
  collectSecretName: test-crunchy-cluster-exporter-secret
  customconfig: ""
  database: userdb
  exporterLimits: {}
  exporterResources:
    memory: 24Mi
  exporterport: "9187"
  limits:
    memory: 2Gi
  name: test-crunchy-cluster
  namespace: test-project
  pgBouncer:
    limits: {}
    replicas: 0
    resources:
      memory: 24Mi
  pgDataSource:
    restoreFrom: ""
    restoreOpts: ""
  pgbadgerport: "10000"
  pgoimageprefix: registry.site.server:49652
  podAntiAffinity:
    default: disabled
    pgBackRest: disabled
    pgBouncer: disabled
  policies: ""
  port: "5432"
  primarysecretname: test-crunchy-cluster-primaryuser-secret
  replicas: "1"
  resources:
    cpu: 30m
    memory: 690Mi
  rootsecretname: test-crunchy-cluster-postgres-secret
  shutdown: false
  standby: false
  status: completed
  syncReplication: null
  tablespaceMounts: {}
  tls:
    caSecret: postgres-server-certs
    replicationTLSSecret: postgres-server-certs
    tlsSecret: postgres-server-certs
  tlsOnly: true
  user: dbuser
  userlabels:
    crunchy-postgres-exporter: "false"
    pg-pod-anti-affinity: ""
    pgo-version: 4.5.1
    workflowid: 57e53d79-8d65-46e3-aa81-2cffc63e2e3e
  usersecretname: test-crunchy-cluster-dbuser-secret
status:
  message: Cluster has been initialized
  state: pgcluster Initialized

[jkatz]

The crunchy operator is deployed using the pgo-deployer but a custom helm chart is used for setting up the RBACs, service accounts and other resources for watched namespaces, I'm not sure if there might be some issue being caused by that helm chart.

Given that last bit is in the "batteries not included" camp this immediately raises a flag in terms of what may be causing the issue. I'd recommend checking git diff v4.4.0..v4.5.1 installers (or further back based upon when your chart was last modified).

That being said, my quick scan of the logs do not seem to indicate any permission issues, though perhaps if there is an error around that it is not being logged. If there is a missing permission that's causing it to fail silently, it'd be helpful to know so we can either account for it in the logs and/or logic itself.

[v3nturetheworld]

If I recall we did not need to make any major changes between the 4.4 chart and 4.5 chart. I will try either later today or tomorrow to take the latest official helm chart and install the operator using that to see if the issue still occurs without any sort of customization.

[jkatz]

This has been reported again, and the only common thread thus far is that both occurred on OpenShift 3.11.

[v3nturetheworld]

Hi, sorry for the delay. I took the latest helm chart for Crunchy and deployed the operator using that without any modifications other then changing apiVersion in Chart.yaml from v2 to v1 (as far as I could tell from a quick scan, there shouldn't be issues from that). The backups occurring every ~10-15 minutes still happen with this 'vanilla' configuration. I created the cluster the same way as before with:

pgo create cluster test-crunchy-postgresql --cpu 30m --memory 690Mi --memory-limit 2Gi --pgbackrest-cpu 60m --pgbackrest-memory 60Mi --pgbackrest-memory-limit 120Mi --tls-only --server-ca-secret=postgres-server-certs --server-tls-secret=postgres-server-certs --replication-tls-secret=postgres-server-certs -n pgo

This is the values.yaml I used for the helm chart:

---
# ======================
# Installer Controls
# ======================
fullnameOverride: ""

# rbac: settings for deployer RBAC creation
rbac:
    # rbac.create: if false RBAC resources should be in place
    create: true
    # rbac.useClusterAdmin: creates a ClusterRoleBinding giving cluster-admin to serviceAccount.name
    useClusterAdmin: true

# serviceAccount: settings for Service Account used by the deployer
serviceAccount:
    # serviceAccount.create: Whether to create a Service Account or not
    create: true
    # serviceAccount.name: The name of the Service Account to create or use
    name: "pgosa3"

# =====================
# Configuration Options
# More info for these options can be found in the docs
# https://access.crunchydata.com/documentation/postgres-operator/latest/installation/configuration/
# =====================
archive_mode: "true"
archive_timeout: "120"
backrest_aws_s3_bucket: ""
backrest_aws_s3_endpoint: ""
backrest_aws_s3_key: ""
backrest_aws_s3_region: ""
backrest_aws_s3_secret: ""
backrest_aws_s3_uri_style: ""
backrest_aws_s3_verify_tls: "true"
backrest_port: "2022"
badger: "false"
ccp_image_prefix: "registry.site.server:49652"
ccp_image_pull_secret: ""
ccp_image_pull_secret_manifest: ""
ccp_image_tag: "centos7-13.1-4.5.1"
create_rbac: "true"
crunchy_debug: "true"
db_name: "userdb"
db_password_age_days: "0"
db_password_length: "24"
db_port: "5432"
db_replicas: "1"
db_user: "dbuser"
default_instance_memory: "128Mi"
default_pgbackrest_memory: "48Mi"
default_pgbouncer_memory: "24Mi"
default_exporter_memory: "24Mi"
delete_operator_namespace: "false"
delete_watched_namespaces: "false"
disable_auto_failover: "false"
disable_fsgroup: "true"
reconcile_rbac: "true"
exporterport: "9187"
metrics: "false"
namespace: "pgo"
namespace_mode: "readonly"
pgbadgerport: "10000"
pgo_add_os_ca_store: "false"
pgo_admin_password: "examplepassword"
pgo_admin_perms: "*"
pgo_admin_role_name: "pgoadmin"
pgo_admin_username: "admin"
pgo_apiserver_port: "8443"
pgo_apiserver_url: "https://postgres-operator"
pgo_client_cert_secret: "pgo.tls"
pgo_client_container_install: "true"
pgo_client_install: "false"
pgo_client_version: "4.5.1"
pgo_cluster_admin: "true"
pgo_disable_eventing: "false"
pgo_disable_tls: "false"
pgo_image_prefix: "registry.site.server:49652"
pgo_image_pull_secret: ""
pgo_image_pull_secret_manifest: ""
pgo_image_tag: "centos7-4.5.1"
pgo_installation_name: "devtest"
pgo_noauth_routes: ""
pgo_operator_namespace: "pgo"
pgo_tls_ca_store: ""
pgo_tls_no_verify: "false"
pod_anti_affinity: "preferred"
pod_anti_affinity_pgbackrest: ""
pod_anti_affinity_pgbouncer: ""
scheduler_timeout: "3600"
service_type: "ClusterIP"
sync_replication: "false"
backrest_storage: "openebs"
backup_storage: "openebs"
primary_storage: "openebs"
replica_storage: "openebs"
wal_storage: ""
storage1_name: "openebs"
storage1_access_mode: "ReadWriteOnce"
storage1_size: "1Gi"
storage1_type: "dynamic"
storage1_class: "openebs-sc"
storage2_name: "hostpathstorage"
storage2_access_mode: "ReadWriteMany"
storage2_size: "1G"
storage2_type: "create"

That's interesting that OpenShift3.11 seems to be the common denominator (for now), were there any changes between crunchy 4.4 and 4.5 around things using the kubernetes API? I have access to an OpenShift4.6 cluster, so I can try using the same configuration and perform the same test on that cluster to see if the backup issue occurs with the newer OpenShift version. I was thinking the problem may be related to the storage system, but since #2227 is using NFS while I'm using OpenEBS that does not seem to be the case.

[v3nturetheworld]

@jkatz The issue does not occur when performing the same deployment and cluster creation as my previous comment on OpenShift4.6, as expected only a single backrest backup is created on initial cluster creation. Deployment wise, rook-ceph replicated-sc is being used instead of openEBS and useClusterAdmin is set to false. Let me know if there are any additional logs I could provide about the openshift3.11 that might help point to the cause or ability to reproduce the issue.

[aleksrosz]

Hi Can I help with this issue? When can I expect patch?

[jkatz]

@AleksanderRoszig if you are looking for immediate assistance you can check out the support page.

As mentioned above, logs and reproduction steps help. Patches with a fix are of course welcome for review. Otherwise this will be handled in the fullness of time, and if it is patched before the next set of bugfix releases (timed around PostgreSQL bugfix releases) it will be available then.

[v3nturetheworld]

@jkatz Not sure if this helps narrow down what might be causing the issue, but when I scale down the operator to 0 after the crunchy cluster is deployed, the looping backups do not occur. I tested with an all local storage deployment for primary, replica and backrest. After ~15-20 minutes a backup automatically occurred. Scaling down the operator after caused the backups to stop. I waited an hour with the operator scaled down then scaled it back up. 16 minutes after scaling the operator up a backup was automatically created.... from the operator container logs it seems like the Control Manager reconciling RBAC's is what triggered the backup in this case, and from the logs it thinks it needs to create another initial backup. @AleksanderRoszig see if you have similar logs in your operator container (make sure debug is enabled when deploying the cluster). Also see if scaling down the operator stops the looping backups for you.

time="2021-01-28T04:47:17Z" level=debug msg="Cluster Config: successfully applied local config all-local-storage-local-config in cluster all-local-storage (namespace pgo)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
--
  | time="2021-01-28T04:47:17Z" level=debug msg="Cluster Config: successfully applied local config all-local-storage-jzbh-local-config in cluster all-local-storage (namespace pgo)" func="internal/operator/config.(*LocalDB).apply()" file="internal/operator/config/localdb.go:264" version=4.5.1
  | time="2021-01-28T04:47:17Z" level=debug msg="Cluster Config: finished syncing config for cluster all-local-storage (namespace pgo)" func="internal/operator/config.(*LocalDB).Sync()" file="internal/operator/config/localdb.go:189" version=4.5.1
  | time="2021-01-28T04:47:32Z" level=debug msg="Controller Manager: Now reconciling RBAC in namespace pgo" func="internal/controller/manager.(*ControllerManager).reconcileRBAC()" file="internal/controller/manager/rbac.go:41" version=4.5.1
  | time="2021-01-28T04:47:32Z" level=debug msg="ServiceAccout pgo-default in namespace pgo is invalid and will now be reconciled" func="internal/ns.ReconcileServiceAccount()" file="internal/ns/nslogic.go:405" version=4.5.1
  | time="2021-01-28T04:47:33Z" level=debug msg="ServiceAccout pgo-target in namespace pgo is invalid and will now be reconciled" func="internal/ns.ReconcileServiceAccount()" file="internal/ns/nslogic.go:405" version=4.5.1
  | time="2021-01-28T04:47:33Z" level=debug msg="ServiceAccout pgo-backrest in namespace pgo is invalid and will now be reconciled" func="internal/ns.ReconcileServiceAccount()" file="internal/ns/nslogic.go:405" version=4.5.1
  | time="2021-01-28T04:47:33Z" level=debug msg="ServiceAccout pgo-pg in namespace pgo is invalid and will now be reconciled" func="internal/ns.ReconcileServiceAccount()" file="internal/ns/nslogic.go:405" version=4.5.1
  | time="2021-01-28T04:47:33Z" level=debug msg="Controller Manager: a controller for namespace pgo already exists" func="internal/controller/manager.(*ControllerManager).addControllerGroup()" file="internal/controller/manager/controllermanager.go:227" version=4.5.1
  | time="2021-01-28T04:47:33Z" level=debug msg="Controller Manager: controller group for namespace pgo is already running" func="internal/controller/manager.(*ControllerManager).runControllerGroup()" file="internal/controller/manager/controllermanager.go:394" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="[Job Controller] onUpdate ns=pgo /apis/batch/v1/namespaces/pgo/jobs/all-local-storage-stanza-create active=0 succeeded=1 conditions=[[{Complete True 2021-01-28 03:30:29 +0000 UTC 2021-01-28 03:30:29 +0000 UTC  }]]" func="internal/controller/job.(*Controller).onUpdate()" file="internal/controller/job/jobcontroller.go:66" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="jobController onUpdate backrest stanza-create job case" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:169" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="backrest stanza successfully created for cluster all-local-storage" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:176" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="proceeding with the initial full backup for cluster all-local-storage as needed for replica creation" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:177" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="the backrest repo pod for the initial backup of cluster all-local-storage is all-local-storage-backrest-shared-repo-77f46d69fc-zhrkr" func="internal/controller/job.(*Controller).handleBackrestStanzaCreateUpdate()" file="internal/controller/job/backresthandler.go:185" version=4.5.1
  | time="2021-01-28T04:47:53Z" level=debug msg="Pod Controller: onUpdate processing update for pod backrest-backup-all-local-storage-b86jw in namespace pgo" func="internal/controller/pod.(*Controller).onUpdate()" file="internal/controller/pod/podcontroller.go:72" version=4.5.1
  | time="2021-01-28T04:47:54Z" level=debug msg="pgBackRest operator CreateBackup called" func="internal/operator/backrest.CreateBackup()" file="internal/operator/backrest/backup.go:177" version=4.5.1

[jkatz]

@v3nturetheworld Thanks, that does help narrow it down.

[andrewlecuyer]

@v3nturetheworld could you provide the output of your stanza-create job (e.g. oc get job mycluster-stanza-create -o yaml)? From what I am seeing, something is updating that Job periodically, which results in an Update event that triggers the backup (I would assume the metadata.resourceVersion changes in the Job each time a backup is triggered, indicating something updated it). I am therefore hoping this might provide some clues as to what/where these updates are coming from.

Additionally, if you simply delete the stanza-create Job, does the behavior go away? Once this Job completes successfully, it can be safely removed, which should then prevent any subsequent updates to the Job, and therefore the periodic backups you're seeing.

I was also curious if you have image pull secrets configured for your local registry? And if so, how do you have them configured?

I also wanted to mention that there is a known issue with OpenShift 3.11 involving the RBAC reconciliation logic in the operator that results in the various ServiceAccout in namespace pgo is invalid and will now be reconciled errors in your output above. This is the result of operator reconciliation fighting with OpenShift, which also wants to add its own updated to the various operator Service Accounts (e.g. auto-generated dockercfg secrets). To disable operator RBAC reconciliation and prevent this behavior, you can set Pgo.DisableReconcileRBAC to false within the pgo.yaml configuration file (this will require a restart of the operator). This might be worth trying just to ensure its not playing a role in the behavior we're seeing here.

[v3nturetheworld]

So another interesting observation, after scaling down and scaling back up the operator backups kept looping in 10-15 minute increments creating about 43 more backups, then it just stopped making backups this morning. I have not seen that behavior before, usually it loops until the partition is full and backups fail... The only thing different was restarting the operator last night, ill try and reproduce that. I still see logs about the issues with reconciling RBACs every 10 or so seconds but I'll try disabling that. Normally we have reconcile_rbac set to false in our custom helm chart, but when I took the official crunchy chart I tried to keep as many of the default values as possible, but I'll disable it in the existing deployment. After deleting the test cluster, it looks like the last successfully completed backrest-backup job stuck around... another thing I haven't seen before, I had to manually delete the job after the pgo-rmdata job finished.

Regarding image pull secrets, I'm not as familiar with how thats setup but yes we do have global image pull secrets so that images can be pulled in any namespace on the cluster, its an image stream secret to be specific. I attached the output of the stanza create and backrest job yamls.

all-local-storage-stanza-create.txt backrest-backup-all-local-storage.txt

[v3nturetheworld]

After re-creating the cluster with Pgo.DisableReconcileRBAC set to True, I compared the stanza-create job yamls after the initial backup and first bugged backup (changing the reconcileRBAC value and restarting the operator didnt seem to have any impact other then reducing log messages). Maybe I grabbed the stanza-create jobs yaml the second time too quickly. The resourceVersions matched in both cases and there were 0 differences between the two files, though running oc delete job test-cluster-stanza-create does seem to fix the issue, after deleting it no backup job ran on its own.

[andrewlecuyer]

Thanks for the update. We have narrowed down the behavior in OpenShift 3.11 that is leading to these additional backups, and will be working on a solution to add additional protections to prevent this behavior.

In the meantime, the workaround is to simply delete the stanza-create Job following the successful initialization of a new cluster. As you are seeing, this should prevent further backups form occurring (other than those specifically requested and/or scheduled).

[jkatz]

For a quick update: @andrewlecuyer has proposed a workaround in #2243 to ensure that the backup jobs stop repeating. However, through our (read: "Andrew's") explorations, we're fairly confident that the genesis of this is a bug in OpenShift 3.11. We are going to open up a case against the upstream to see if we can get it fixed there, but in the immediate term, we will ameliorate the situation with #2243

[mjrussell]

I just ran into this issue also in Openshift 3.11, and I believe also in Vmware TKG (sorry dont have the version on hand but can get it if needed). Really appreciate the detective work here.

I will see if deleting the create stanza job resolves the issue for us in both environments.

[jkatz]

This is committed and backpatched down to 4.5. This "adjustment" (I hesitate to use "fix" given it's a workaround for what we suspect is a platform bug :smile:) will be available in 4.6.1 + 4.5.2, which is due out after the next PostgreSQL update release in mid-February.

For information on our release schedule, please see: https://github.com/CrunchyData/postgres-operator#releases.

We are filing a bug report upstream with OpenShift, though @andrewlecuyer is first going to verify that the issue still exists in 3.11 latest.

@v3nturetheworld Thanks for reporting and working through this one! I guess my initial analysis was correct that it was not a bug with the Operator, but I'm glad we can at least provide something programmatic that will resolve the problem :wink:

[aleksrosz]

I don't know that I should write in this topic but now problem is that scheduling backups doesn't work. I deleted stanza job, created cluster and: pgo create schedule test_cluster --schedule="0 /2 " --schedule-type=pgbackrest --pgbackrest-backup-type=incr

pgo show schedule test_cluster test_cluster-pgbackrest-incr: schedule: 0 /2 schedule-type: pgbackrest backup-type: incr

but scheduler doesn't make any backups. @v3nturetheworld do you have this same problem? @jkatz how to deal with that?

[v3nturetheworld]

@AleksanderRoszig I haven't tried setting up a scheduled backup yet after the change, but I did check that manually running pgo backup test-cluster -n pgo worked. I'll give testing scheduled backups a try tomorrow if I have a chance.

[jkatz]

If there is an issue related to the scheduled backups, it would not be related to @andrewlecuyer's fix as that did not go anywhere near that code.

If you are building off of master, #2237 (08e8e56379f78fee94838b4c3f4d3e2118288758) applied a fix for ensuring that scheduled backups can properly run off of a valid pgBackRest repository, but unless you relabled your Pods, this should run correctly. You should ensure the scheduler container within the Operator Pod is healthy.

Though I understand these are famous last words, I don't think there is a bug. If scheduled backups are actually not working on OCP 3.11, it would likely point to a different issue.

[aleksrosz]

My fault. I see problem in my Openshift cluster.