View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000316Pgpool-IIBugpublic2017-06-23 19:432017-08-29 09:26
ReporterSeema Assigned ToMuhammad Usama  
PriorityurgentSeveritymajorReproducibilitysometimes
Status closedResolutionopen 
OSfreebsdOS VersionFreeBSD 11.0-REL 
Product Version3.5.3 
Summary0000316: One postgresql backend node is marked down often
DescriptionHi,

I am running one pgpool-II with two backend postgresql nodes, configured in 'replication mode' with 'load balancing'.

PGPOOL VERSION: pgpool-II version 3.5.3 (ekieboshi),
OS VERSION: FreeBSD 11.0-RELEASE-p1 FreeBSD 11.0-RELEASE-p1 #0 r306420

I am seeing that pgpool is marking the 'node 0' down frequently.

I am seeing the following messages in the pgpool log.

============================================
Jun 23 14:33:46 apgp1 pgpool: 2017-06-23 14:33:46: pid 744: DEBUG: persistent DB connection to backend node 1 having status 2 is successful
Jun 23 14:33:46 apgp1 pgpool: 2017-06-23 14:33:46: pid 744: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:46 apgp1 pgpool: 2017-06-23 14:33:46: pid 744: DEBUG: health check: clearing alarm
Jun 23 14:33:46 apgp1 pgpool: 2017-06-23 14:33:46: pid 744: DEBUG: health check: clearing alarm
Jun 23 14:33:49 apgp1 pgpool[753]: [7146-1] 2017-06-23 14:33:49: pid 753: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool[746]: [3372-1] 2017-06-23 14:33:49: pid 746: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool[746]: [3373-1] 2017-06-23 14:33:49: pid 746: LOG: received degenerate backend request for node_id: 0 from pid [746]
Jun 23 14:33:49 apgp1 pgpool[753]: [7147-1] 2017-06-23 14:33:49: pid 753: LOG: received degenerate backend request for node_id: 0 from pid [753]
Jun 23 14:33:49 apgp1 pgpool[746]: [3374-1] 2017-06-23 14:33:49: pid 746: DEBUG: sending 30 to the parent process with PID:744
Jun 23 14:33:49 apgp1 pgpool[744]: [21793-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler called
Jun 23 14:33:49 apgp1 pgpool[746]: [3375-1] 2017-06-23 14:33:49: pid 746: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21794-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[746]: [3376-1] 2017-06-23 14:33:49: pid 746: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool[744]: [21794-2] 2017-06-23 14:33:49: pid 744: DETAIL: starting to select new master node
Jun 23 14:33:49 apgp1 pgpool[744]: [21795-1] 2017-06-23 14:33:49: pid 744: LOG: starting degeneration. shutdown host adb1.labs.blr.cherrylabs.in(5432)
Jun 23 14:33:49 apgp1 pgpool[747]: [3372-1] 2017-06-23 14:33:49: pid 747: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool[753]: [7148-1] 2017-06-23 14:33:49: pid 753: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[746]: [3376-2] 2017-06-23 14:33:49: pid 746: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: LOG: received degenerate backend request for node_id: 0 from pid [746]
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: LOG: received degenerate backend request for node_id: 0 from pid [753]
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DEBUG: sending 30 to the parent process with PID:744
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler called
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: starting to select new master node
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: LOG: starting degeneration. shutdown host adb1.labs.blr.cherrylabs.in(5432)
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[746]: [3377-1] 2017-06-23 14:33:49: pid 746: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[753]: [7149-1] 2017-06-23 14:33:49: pid 753: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool[753]: [7149-2] 2017-06-23 14:33:49: pid 753: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool[753]: [7150-1] 2017-06-23 14:33:49: pid 753: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[747]: [3373-1] 2017-06-23 14:33:49: pid 747: LOG: received degenerate backend request for node_id: 0 from pid [747]
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 753: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 746: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[747]: [3374-1] 2017-06-23 14:33:49: pid 747: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: DEBUG: pool_read: read -1 bytes from backend 0
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: LOG: received degenerate backend request for node_id: 0 from pid [747]
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[747]: [3375-1] 2017-06-23 14:33:49: pid 747: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool[747]: [3375-2] 2017-06-23 14:33:49: pid 747: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool[747]: [3376-1] 2017-06-23 14:33:49: pid 747: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: DEBUG: write on backend 0 failed with error :"Broken pipe"
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: DETAIL: while trying to write data from offset: 0 wlen: 5
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 747: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21796-1] 2017-06-23 14:33:49: pid 744: LOG: Restart all children
Jun 23 14:33:49 apgp1 pgpool[744]: [21797-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21797-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:746
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: LOG: Restart all children
Jun 23 14:33:49 apgp1 pgpool[744]: [21798-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21798-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:747
Jun 23 14:33:49 apgp1 pgpool[744]: [21799-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21799-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:748
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:746
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:747
Jun 23 14:33:49 apgp1 pgpool[748]: [3372-1] 2017-06-23 14:33:49: pid 748: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:748
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 748: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[749]: [652-1] 2017-06-23 14:33:49: pid 749: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[748]: [3373-1] 2017-06-23 14:33:49: pid 748: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21800-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[748]: [3374-1] 2017-06-23 14:33:49: pid 748: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21800-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:749
Jun 23 14:33:49 apgp1 pgpool[744]: [21801-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[749]: [653-1] 2017-06-23 14:33:49: pid 749: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[749]: [654-1] 2017-06-23 14:33:49: pid 749: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21801-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:750
Jun 23 14:33:49 apgp1 pgpool[744]: [21802-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 749: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 748: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 748: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:749
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 749: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:750
Jun 23 14:33:49 apgp1 pgpool[750]: [7501-1] 2017-06-23 14:33:49: pid 750: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[751]: [11-1] 2017-06-23 14:33:49: pid 751: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 749: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool[744]: [21802-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:751
Jun 23 14:33:49 apgp1 pgpool[750]: [7502-1] 2017-06-23 14:33:49: pid 750: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 750: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[750]: [7503-1] 2017-06-23 14:33:49: pid 750: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 751: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21803-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21803-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:752
Jun 23 14:33:49 apgp1 pgpool[744]: [21804-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21804-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:753
Jun 23 14:33:49 apgp1 pgpool[744]: [21805-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 750: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[754]: [3046-1] 2017-06-23 14:33:49: pid 754: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:751
Jun 23 14:33:49 apgp1 pgpool[752]: [11-1] 2017-06-23 14:33:49: pid 752: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21805-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:754
Jun 23 14:33:49 apgp1 pgpool[754]: [3047-1] 2017-06-23 14:33:49: pid 754: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool[754]: [3048-1] 2017-06-23 14:33:49: pid 754: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:752
Jun 23 14:33:49 apgp1 pgpool[755]: [11-1] 2017-06-23 14:33:49: pid 755: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21806-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21806-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:755
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:753
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 750: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 754: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 754: DEBUG: pool_write: to backend: 0 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 752: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:754
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 754: DEBUG: pool_write: to backend: 1 kind:X
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:755
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 755: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[756]: [13-1] 2017-06-23 14:33:49: pid 756: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21807-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21807-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:756
Jun 23 14:33:49 apgp1 pgpool[757]: [11-1] 2017-06-23 14:33:49: pid 757: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 756: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21808-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21808-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:757
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:756
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:757
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 757: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[758]: [11-1] 2017-06-23 14:33:49: pid 758: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21809-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21809-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:758
Jun 23 14:33:49 apgp1 pgpool[759]: [11-1] 2017-06-23 14:33:49: pid 759: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21810-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 758: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:758
Jun 23 14:33:49 apgp1 pgpool[744]: [21810-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:759
Jun 23 14:33:49 apgp1 pgpool[760]: [11-1] 2017-06-23 14:33:49: pid 760: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21811-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 759: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:759
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 760: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21811-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:760
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:760
Jun 23 14:33:49 apgp1 pgpool[761]: [11-1] 2017-06-23 14:33:49: pid 761: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 761: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21812-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21812-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:761
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:761
Jun 23 14:33:49 apgp1 pgpool[762]: [11-1] 2017-06-23 14:33:49: pid 762: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21813-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[744]: [21813-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:762
Jun 23 14:33:49 apgp1 pgpool[763]: [11-1] 2017-06-23 14:33:49: pid 763: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21814-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 762: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:762
Jun 23 14:33:49 apgp1 pgpool[744]: [21814-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:763
Jun 23 14:33:49 apgp1 pgpool[744]: [21815-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[764]: [11-1] 2017-06-23 14:33:49: pid 764: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21815-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:764
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 763: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:763
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 764: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:764
Jun 23 14:33:49 apgp1 pgpool[744]: [21816-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[765]: [11-1] 2017-06-23 14:33:49: pid 765: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21816-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:765
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:765
Jun 23 14:33:49 apgp1 pgpool[766]: [11-1] 2017-06-23 14:33:49: pid 766: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21817-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 765: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 766: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21817-2] 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:766
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool: 2017-06-23 14:33:49: pid 744: DETAIL: kill process with PID:766
Jun 23 14:33:49 apgp1 pgpool[744]: [21818-1] 2017-06-23 14:33:49: pid 744: DEBUG: failover handler
Jun 23 14:33:49 apgp1 pgpool[767]: [3474-1] 2017-06-23 14:33:49: pid 767: LOG: child process received shutdown request signal 3
Jun 23 14:33:49 apgp1 pgpool[744]: [21818-2] 2017-06-23 14:33:49: p
======================================================================================================

I have attached the logs and pgpool.conf file your your investigation.

Thanks,
Seema
TagsNo tags attached.

Activities

Seema

2017-06-23 19:43

reporter  

pgpool.conf (34,847 bytes)
pgpool.log.errors-rep (8,084,264 bytes)

Seema

2017-06-23 21:43

reporter   ~0001543

Hi,
I would like to add some more information here.

The Postgresql DB nodes are behind the firewall. PGPOOL is outside the firewall.

Thanks,
Seema

t-ishii

2017-06-26 16:11

developer   ~0001545

It seems PostgreSQL backend closed the socket to Pgpool-II. That's the trigger for the fail over. Maybe firewall issue?

Seema

2017-06-26 17:17

reporter   ~0001547

Hi t-ishii,
But why is it always happening to node 0 only?

I did think the Firewall may be cutting the connections, so I also tried setting the "connection_life_time = 3000" in pgpool.conf file. Firewall setting for connection timeout is set to 3600. But this did not help.

Thanks,
Seema

Seema

2017-06-27 20:19

reporter   ~0001552

Hi,

I have the following observations. Today node 1 is marked down. I use the pop_attach_node command to attach the node back and it stays up for about 2 hours before being marked down again.

Every time a postgreSql node is marked down by pgpool, I am seeing the following logs .

On the postgresql server, log shows:

Jun 27 16:31:04 adb2 postgres[81513]: [3-1] LOG: could not receive data from client: Operation timed out
Jun 27 16:31:04 adb2 postgres[81513]: [4-1] DEBUG: unexpected EOF on client connection
Jun 27 16:31:05 adb2 postgres[81515]: [3-1] LOG: could not receive data from client: Operation timed out
Jun 27 16:31:05 adb2 postgres[81514]: [3-1] LOG: could not receive data from client: Operation timed out
Jun 27 16:31:05 adb2 postgres[81514]: [4-1] DEBUG: unexpected EOF on client connection
Jun 27 16:31:05 adb2 postgres[81515]: [4-1] DEBUG: unexpected EOF on client connection

And on the PGPOOL Server, I am able to see the following logs:

Jun 27 16:28:39 apgp1 pgpool[14359]: [3534-1] 2017-06-27 16:28:39: pid 14359: DEBUG: pool_read: read -1 bytes from backend 1
Jun 27 16:28:39 apgp1 pgpool[14349]: [3534-1] 2017-06-27 16:28:39: pid 14349: DEBUG: pool_read: read -1 bytes from backend 1
Jun 27 16:28:39 apgp1 pgpool[14349]: [3535-1] 2017-06-27 16:28:39: pid 14349: LOG: received degenerate backend request for node_id: 1 from pid [14349]
Jun 27 16:28:39 apgp1 pgpool: 2017-06-27 16:28:39: pid 14349: DEBUG: pool_read: read -1 bytes from backend 1


Thanks,
Seema

Seema

2017-06-28 14:45

reporter   ~0001557

URGENT. Please Help

Seema

2017-07-03 13:55

reporter   ~0001563

Hello Team,
Request your help in resolving this issue.

Thanks,
Seema

Muhammad Usama

2017-07-04 00:10

developer   ~0001565

Hi Seema,

I have analyzed the pgpool. conf and pgpool log files you shared and there doesn't seem anything wrong with Pgpool-II. The Pgpool-II logs and PostgreSQL log messages (pasted upthread) both suggest that the connection from Pgpool-II to PostgreSQL gets killed abruptly, which then because of your Pgpool-II setting ( fail_over_on_backend_error = on) causes the backend node failover. And I suspect this is the firewall which is killing that connection and causing all this.

Since you mentioned that you have enabled connection timeout on your firewall, I think that could be causing this connection disconnections and eventually the failover.

I think the we can also test this supposition by a simple test, Just by connecting a PSQL or some client with the Pgpool-II and leave it connected and unused for connection timeout ( firewall) amount of time and after that just fire any query. Since the firewall would already have killed that backend connection (after detecting no activity on it for connection timeout time) the Pgpool-II will get a broken pipe error and trigger the failover because of fail_over_on_backend_error = on.

This scenario can also happen even if the client is issuing the queries on the connection but somehow all the queries end up landing on single backend and other backend connection remain un-used for connection timeout (firewall) time.

So I suggest to disable the connection timeout on firewall side for Pgpool-II to backend connections and to see if it solves the issue.

Thanks
Best Regards
Muhammad Usama

Seema

2017-07-04 14:30

reporter   ~0001569

Hello Muhammad,

Thank you for replying.

I will test the FW scenario suggested by you and revert back.

I was also curious to know about the first scenario that you have mentioned - "client is issuing the queries on the connection but somehow all the queries end up landing on single backend and other backend connection remain un-used for connection timeout (firewall) time."
How can we check whether this is happening?

Reg the FW timeout causing PGPOOL-II disconnections. I had set the "connection_life_time = 3000" in pgpool.conf file. Since the FW connection timeout is set to 3600, I was hoping this configuration will force pgpool-II to disconnect all idle connections at 3000 sec and recestablish the connections before the FW will disconnect them. Is my thinking correct? But, it doesn't seem to be working though.

Thanks & Regards,
Seema

Muhammad Usama

2017-07-04 19:53

developer   ~0001572

You can analyse the Pgpool-II log after enabling "log_per_node_statement" config in pgpool.conf to see which query is routed to which backend node,
secondly you can use the ' show pool_nodes' command which outputs the 'select_cnt' for each backend node.

http://www.pgpool.net/docs/latest/en/html/sql-show-pool-nodes.html

postgres=# show pool_nodes;
 node_id | hostname | port | status | lb_weight | role | select_cnt | load_balance_node | replication_delay
---------+-----------+------+--------+-----------+---------+------------+-------------------+-------------------
 0 | localhost | 5432 | up | 0.500000 | primary | 2 | true | 0
 1 | localhost | 5434 | up | 0.500000 | standby | 0 | false | 0
(2 rows)


Regarding the connection_life_time in Pgpool-II, It only services the cashed backend connections, and does not affect the active backend connection. (The backend connection for which the frontend client is currently connected is considered as active even if does not have any activity on it).
So for your scenario the connection_life_time config will not come into play even for the inactive connections for which the frontend client exists and their backend connections would still be killed by the firewall.

Seema

2017-07-12 19:41

reporter   ~0001581

Hello Muhammad,

Currently we have moved both the DB Nodes and PGPOOL server to the same LAN and testing. As of now it seems to be working fine. We will be moving the DB Nodes across the FW again in couple of days time.

I will let you know the status once we have tested it.

Regards,
Seema

Issue History

Date Modified Username Field Change
2017-06-23 19:43 Seema New Issue
2017-06-23 19:43 Seema File Added: pgpool.conf
2017-06-23 19:43 Seema File Added: pgpool.log.errors-rep
2017-06-23 21:43 Seema Note Added: 0001543
2017-06-26 16:11 t-ishii Note Added: 0001545
2017-06-26 16:13 t-ishii Assigned To => Muhammad Usama
2017-06-26 16:13 t-ishii Status new => assigned
2017-06-26 17:17 Seema Note Added: 0001547
2017-06-27 20:19 Seema Note Added: 0001552
2017-06-28 14:45 Seema Note Added: 0001557
2017-07-03 13:55 Seema Note Added: 0001563
2017-07-04 00:10 Muhammad Usama Note Added: 0001565
2017-07-04 14:30 Seema Note Added: 0001569
2017-07-04 19:53 Muhammad Usama Note Added: 0001572
2017-07-12 19:41 Seema Note Added: 0001581
2017-08-29 09:26 pengbo Status assigned => closed