Postgres-operator: Panic of uncertain origin when restarting operator pod during a cluster sync that hung (due to bad SA config)

[valer-cara]

• I've updated pgop to the latest version.
• The operator started syncing my clusters. It hung due to the sts service account not existing. (since the config api of pgop changed, it defaulted to operator, etc...)
• Realising the bad SA setting, i've updated the config and restarted the operator and now got this panic:

pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:14Z" level=info msg="pod \"app/rabbit-pg-1\" has been recreated" cluster-name=app/rabbit-pg pkg=cluster worker=0                        
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:14Z" level=debug msg="unsubscribing from pod \"app/rabbit-pg-1\" events" cluster-name=app/rabbit-pg pkg=cluster worker=0                
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:14Z" level=debug msg="failing over from \"rabbit-pg-0\" to \"app/rabbit-pg-1\"" cluster-name=app/rabbit-pg pkg=cluster worker=0         
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:14Z" level=debug msg="making POST http request: http://100.107.29.224:8008/failover" cluster-name=app/rabbit-pg pkg=cluster worker=0    
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:14Z" level=debug msg="subscribing to pod \"app/rabbit-pg-1\"" cluster-name=app/rabbit-pg pkg=cluster worker=0                           
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:28Z" level=info msg="pod \"app/web-pg-1\" has been recreated" cluster-name=app/web-pg pkg=cluster worker=1                              
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:28Z" level=debug msg="unsubscribing from pod \"app/web-pg-1\" events" cluster-name=app/web-pg pkg=cluster worker=1                      
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:28Z" level=debug msg="failing over from \"web-pg-0\" to \"app/web-pg-1\"" cluster-name=app/web-pg pkg=cluster worker=1                  
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:28Z" level=debug msg="making POST http request: http://100.107.29.222:8008/failover" cluster-name=app/web-pg pkg=cluster worker=1       
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:28Z" level=debug msg="subscribing to pod \"app/web-pg-1\"" cluster-name=app/web-pg pkg=cluster worker=1                                 
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:29Z" level=warning msg="could not perform failover: could not failover: patroni returned 'Failover failed'" cluster-name=app/web-pg pkg=cluster worker=1
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:29Z" level=info msg="recreating old master pod \"app/web-pg-0\"" cluster-name=app/web-pg pkg=cluster worker=1                           
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:29Z" level=debug msg="subscribing to pod \"app/web-pg-0\"" cluster-name=app/web-pg pkg=cluster worker=1                                 
pgop-postgres-operator-8687f8cc54-trgb6 operator time="2018-07-13T12:16:29Z" level=debug msg="unsubscribing from pod \"app/web-pg-1\" events" cluster-name=app/web-pg pkg=cluster worker=1                      
pgop-postgres-operator-8687f8cc54-trgb6 operator panic: send on closed channel
pgop-postgres-operator-8687f8cc54-trgb6 operator
pgop-postgres-operator-8687f8cc54-trgb6 operator goroutine 142 [running]:
pgop-postgres-operator-8687f8cc54-trgb6 operator github.com/zalando-incubator/postgres-operator/pkg/cluster.(*Cluster).Switchover.func1(0xc420027b00, 0xc4202ffc17, 0x3, 0xc4202ffbe8, 0x8, 0xc42008cba0, 0xc42008c660)
pgop-postgres-operator-8687f8cc54-trgb6 operator        /home/blk/golang/src/github.com/zalando-incubator/postgres-operator/pkg/cluster/cluster.go:883 +0x1ca                                                   
pgop-postgres-operator-8687f8cc54-trgb6 operator created by github.com/zalando-incubator/postgres-operator/pkg/cluster.(*Cluster).Switchover                                                                    
pgop-postgres-operator-8687f8cc54-trgb6 operator        /home/blk/golang/src/github.com/zalando-incubator/postgres-operator/pkg/cluster/cluster.go:877 +0x22f                                                   

Atm the operator is stuck in this state and restarts.. i'll research some more to figure out how to get it unstuck. Any hints appreciated :)

Thanks!

[valer-cara]

It seems to have settled after all the pods were restarted, the panic is no longer happening.

I've seen this issue in the replica instance, just in case it helps:

web-pg-1 postgres 2018-07-13 12:24:27,492 INFO: no action.  i am a secondary and i am following a leader
web-pg-1 postgres 2018-07-13 12:24:27,492 INFO stopped: pgq (terminated by SIGTERM)                                                                                                                             
web-pg-1 postgres 2018-07-13 12:24:28,493 INFO reaped unknown pid 16375                                                                                                                                         
web-pg-1 postgres 2018-07-13 12:24:28,494 INFO reaped unknown pid 16377                                                                                                                                         
web-pg-1 postgres 2018-07-13 12:24:28,516 INFO: Lock owner: web-pg-0; I am web-pg-1                                                                                                                             
web-pg-1 postgres Exception ignored in: <bound method ApiClient.__del__ of <kubernetes.client.api_client.ApiClient object at 0x7f3cf0420f28>>                                                                   
web-pg-1 postgres Traceback (most recent call last):                                                                                                                                                            
web-pg-1 postgres   File "/usr/local/lib/python3.6/dist-packages/kubernetes/client/api_client.py", line 77, in __del__                                                                                          
web-pg-1 postgres     self.pool.close()
web-pg-1 postgres AttributeError: 'ApiClient' object has no attribute 'pool'
web-pg-1 postgres 2018-07-13 12:24:28,655 INFO stopped: patroni (exit status 0)
web-pg-1 postgres 2018-07-13 12:24:28,656 INFO stopped: cron (terminated by SIGTERM)

[alexeyklyukin]

Hi @valer-cara

Sorry about that, the go panic is the issue with the operator itself. Fix is on the way.
The exception that you get from Patroni is also interesting, which version of Spilo are you using?

[alexeyklyukin]

@valer-cara if this issue is reproducible (you may be able to reproduce the failover failure by deleting the pod to failover to right at the moment when it comes up after being re-created from the new template), please, try with the operator from https://github.com/zalando-incubator/postgres-operator/pull/343.

It looks good for me and I plan to merge it on Monday.

[valer-cara]

@alexeyklyukin - I've upgraded Spilo to the latest release a few days ago: registry.opensource.zalan.do/acid/spilo-10:1.4-p11

Reproducing is a bit hard on my end here, the db is in use and I wouldn't stress it further.

---

PS: any chance postgres-operator will have published releases/tags that follow the docker repo? I had to build it myself to get the latest version, didn't find any docker repos/tags while navigating through swaggerUI/pierOne

Thanks for the fast response! :)

[alexeyklyukin]

@valer-cara we will, so far we are looking forward for our first release soon :-)

[alexeyklyukin]

@valer-cara merged, thank you for the report and review!