View Issue Details

IDProjectCategoryView StatusLast Update
0000124Pgpool-IIBugpublic2015-08-21 19:49
ReporterravazzoloAssigned ToMuhammad Usama 
PriorityhighSeveritymajorReproducibilitysometimes
Status resolvedResolutionfixed 
PlatformIntelOSLinuxOS VersionDebian 3.2.63-2
Product Version 
Target VersionFixed in Version 
Summary0000124: Stuck connections - Same as issue 0000107 but with pgPool 3.4.0
Descriptionroot 22897 16000 0 13:28 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(56842) DISCARD
root 24041 16000 0 Dez15 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(56647) DISCARD
root 24043 16000 0 Dez15 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(39493) DISCARD
root 24310 16000 0 14:01 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(56855) DISCARD
root 24338 16000 0 14:02 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(39659) DISCARD
root 26434 16000 0 02:06 ? 00:00:00 pgpool: user_updt portoalegre 10.10.2.48(39562) DISCARD
Additional InformationI would like to know if I can apply the same patches of issue 0000107 in version 3.4.0 of pgPool.

Thanks!

Ricardo Ravazzolo
TagsNo tags attached.

Activities

t-ishii

2014-12-21 19:06

developer   ~0000503

In my understanding, those patches have been already applied to 3.4.0. So there might be another code path which could cause the problem. Do you have any idea how to reproduce the bug?

ravazzolo

2014-12-26 22:49

reporter  

Stuck Connections Logs.txt (53,290 bytes)
1 - STUCKED Processes 

root      3083 14479  0 Dez24 ?        00:00:00 pgpool: user_updt portoalegre 10.10.2.48(57785) DISCARD
root     11449 14479  0 10:51 ?        00:00:00 pgpool: user_updt portoalegre 10.10.2.49(40779) DISCARD 
root     15490 14479  0 00:15 ?        00:00:00 pgpool: user_updt portoalegre 10.10.2.48(57817) DISCARD
root     32191 14479  0 Dez25 ?        00:00:00 pgpool: user_updt portoalegre 10.10.2.48(57800) DISCARD




2 - PCP Info PID 3083 and PID 11449

pcp_proc_info 10 server-cl1 9898 postgres portoalegre 3083
portoalegre user_updt 2014-12-24 19:06:27 2014-12-24 20:00:02 3 0 1 5378 1
portoalegre user_updt 2014-12-24 19:06:27 2014-12-24 20:00:02 3 0 1 14486 1

pcp_proc_info 10 server-cl1 9898 postgres portoalegre 11449
portoalegre user_updt 2014-12-26 10:51:07 2014-12-26 10:52:27 3 0 2 11497 1
portoalegre user_updt 2014-12-26 10:51:07 2014-12-26 10:52:27 3 0 2 13418 1




3 - PostgreSQL Processes 

ps -ef | grep 5378
postgres  5378  3629  0 Dez24 ?        00:00:00 postgres: user_updt portoalegre 10.10.1.29(44061) idle
root     11381 11828  0 10:49 pts/2    00:00:00 grep 5378

ps -ef | grep 14486
root     11374 11828  0 10:49 pts/2    00:00:00 grep 14486

ps -ef | grep 11497
postgres 11497  3629  0 10:52 ?        00:00:00 postgres: user_updt portoalegre 10.10.1.29(44146) idle
root     12178 11828  0 11:06 pts/2    00:00:00 grep 11497

ps -ef | grep 13418
root     12187 11828  0 11:07 pts/2    00:00:00 grep 13418




4 - pgPool Log

4.1 - PID 3083 STUCKED

2014-12-24 19:06:27: pid 14479: DEBUG:  reaper handler: forked a new child with PID:3083
2014-12-24 19:06:27: pid 14479: DEBUG:  reaper handler: exiting normally
2014-12-24 19:06:27: pid 3083: DEBUG:  I am Pgpool Child process with pid: 3083
2014-12-24 19:06:27: pid 3083: DEBUG:  initializing backend status

...

2014-12-24 20:00:02: pid 3083: DEBUG:  I am 3083 accept fd 7
2014-12-24 20:00:02: pid 3083: LOG:  new connection received
2014-12-24 20:00:02: pid 3083: DETAIL:  connecting host=10.10.2.48 port=57785
2014-12-24 20:00:02: pid 3083: DEBUG:  reading startup packet
2014-12-24 20:00:02: pid 3083: DETAIL:  Protocol Major: 3 Minor: 0 database: portoalegre user: user_updt
2014-12-24 20:00:02: pid 3083: DEBUG:  creating new connection to backend
2014-12-24 20:00:02: pid 3083: DETAIL:  connecting 0 backend
2014-12-24 20:00:02: pid 3083: DEBUG:  creating new connection to backend
2014-12-24 20:00:02: pid 3083: DETAIL:  connecting 1 backend
2014-12-24 20:00:02: pid 3083: DEBUG:  SSL is requested but SSL support is not available
2014-12-24 20:00:02: pid 3083: DEBUG:  SSL is requested but SSL support is not available
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  slot: 0 length: 12
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  slot: 1 length: 12
2014-12-24 20:00:02: pid 3083: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 3083: DETAIL:  auth kind:5
2014-12-24 20:00:02: pid 3083: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 3083: DETAIL:  trying md5 authentication
2014-12-24 20:00:02: pid 3083: DEBUG:  performing md5 authentication
2014-12-24 20:00:02: pid 3083: DETAIL:  DB node id: 0 salt: ffffffb0fffffffcffffff9d4d
2014-12-24 20:00:02: pid 3083: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 3083: DETAIL:  trying md5 authentication
2014-12-24 20:00:02: pid 3083: DEBUG:  performing md5 authentication
2014-12-24 20:00:02: pid 3083: DETAIL:  DB node id: 1 salt: ffffffb111fffffffca
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 22
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 22
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"application_name" value:""
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"application_name" value:""
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"client_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"client_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 23
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 23
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"DateStyle" value:"ISO, DMY"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"DateStyle" value:"ISO, DMY"
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"integer_datetimes" value:"on"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"integer_datetimes" value:"on"
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 27
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 27
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"IntervalStyle" value:"postgres"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"IntervalStyle" value:"postgres"
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 21
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 21
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"is_superuser" value:"off"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"is_superuser" value:"off"
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 name:"server_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 3083: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:1 name:"server_encoding" value:"UTF8"

...

2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  Execute: portal name <>
2014-12-24 20:00:02: pid 3083: DEBUG:  Execute: query string = <select this_.cod_ano_nume as y0_, this_.cod_cnpj as y1_, this_.cod_insc_muni as y2_ from nfse.nfses this_ where this_.ind_sinc=$1 order by this_.dat_emis_nfse asc limit $2>
2014-12-24 20:00:02: pid 3083: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 3083: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'C'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'S'(53) from frontend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'Z'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'Z'(5a) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  Ready For Query received
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  slot: 0 length: 5
2014-12-24 20:00:02: pid 3083: DEBUG:  processing ReadyForQuery
2014-12-24 20:00:02: pid 3083: DETAIL:  transaction state 'T'(54)
2014-12-24 20:00:02: pid 3083: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'P'(50) from frontend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  Parse: statement name <S_2>
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  decide where to send the queries
2014-12-24 20:00:02: pid 3083: DETAIL:  destination = 3 for query= "COMMIT"
2014-12-24 20:00:02: pid 3083: DEBUG:  Parse: waiting for master completing the query
2014-12-24 20:00:02: pid 3083: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 3083: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 3083: DEBUG:  detect error: kind: 1
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'1'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = '1'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind '1'(31) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'B'(42) from frontend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  Bind: waiting for master completing the query
2014-12-24 20:00:02: pid 3083: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 3083: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'2'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = '2'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind '2'(32) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  adding sent message to list
2014-12-24 20:00:02: pid 3083: DETAIL:  portal "" already exists
2014-12-24 20:00:02: pid 3083: DEBUG:  checking if query context can be safely destroyed
2014-12-24 20:00:02: pid 3083: DETAIL:  query context 0x143c510 is still used 2 times. query:"select this_.cod_ano_nume as y0_, this_.cod_cnpj as y1_, this_.cod_insc_muni as y2_ from nfse.nfses this_ where this_.ind_sinc=$1 order by this_.dat_emis_nfse asc limit $2"
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'E'(45) from frontend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  Execute: portal name <>
2014-12-24 20:00:02: pid 3083: DEBUG:  Execute: query string = <COMMIT>
2014-12-24 20:00:02: pid 3083: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 3083: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'C'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'S'(53) from frontend
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 kind:'Z'
2014-12-24 20:00:02: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 3083: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  received kind 'Z'(5a) from backend
2014-12-24 20:00:02: pid 3083: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 3083: DETAIL:  Ready For Query received
2014-12-24 20:00:02: pid 3083: DEBUG:  reading message length
2014-12-24 20:00:02: pid 3083: DETAIL:  slot: 0 length: 5
2014-12-24 20:00:02: pid 3083: DEBUG:  processing ReadyForQuery
2014-12-24 20:00:02: pid 3083: DETAIL:  transaction state 'T'(54)
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing writing transaction. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing failed transaction. DONE
2014-12-24 20:00:02: pid 3083: DEBUG:  session context: clearing failed transaction. DONE

...

2014-12-24 20:01:03: pid 3083: ERROR:  unable to read data
2014-12-24 20:01:03: pid 3083: DETAIL:  child connection forced to terminate due to client_idle_limit:60 is reached
2014-12-24 20:01:03: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 3083: DEBUG:  decide where to send the queries
2014-12-24 20:01:03: pid 3083: DETAIL:  destination = 3 for query= " DISCARD ALL"
2014-12-24 20:01:03: pid 3083: DEBUG:  waiting for query response
2014-12-24 20:01:03: pid 3083: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:01:03: pid 3083: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 3083: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 3083: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 3083: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 kind:'S'
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  parameter name: is_superuser value: "off"
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 kind:'S'
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  parameter name: session_authorization value: "user_updt"
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 kind:'C'
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-24 20:01:03: pid 3083: DEBUG:  processing backend response
2014-12-24 20:01:03: pid 3083: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:01:03: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 3083: DEBUG:  checking if query context can be safely destroyed
2014-12-24 20:01:03: pid 3083: DETAIL:  query context 0x143b0d8 is still used 2 times. query:"COMMIT"
2014-12-24 20:01:03: pid 3083: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 3083: DEBUG:  session context: setting command success. DONE
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 kind:'Z'
2014-12-24 20:01:03: pid 3083: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 3083: DETAIL:  backend:0 of 2 kind = 'Z'




4.2 - PID 446 NOT STUCKED

2014-12-24 18:06:03: pid 14479: DEBUG:  reaper handler: forked a new child with PID:446
2014-12-24 18:06:03: pid 14479: DEBUG:  reaper handler: exiting normally
2014-12-24 18:06:03: pid 446: DEBUG:  I am Pgpool Child process with pid: 446
2014-12-24 18:06:03: pid 446: DEBUG:  initializing backend status

...

2014-12-24 20:00:02: pid 446: DEBUG:  I am 446 accept fd 7
2014-12-24 20:00:02: pid 446: LOG:  new connection received
2014-12-24 20:00:02: pid 446: DETAIL:  connecting host=10.10.2.49 port=40727
2014-12-24 20:00:02: pid 446: DEBUG:  reading startup packet
2014-12-24 20:00:02: pid 446: DETAIL:  Protocol Major: 3 Minor: 0 database: portoalegre user: user_updt
2014-12-24 20:00:02: pid 446: DEBUG:  creating new connection to backend
2014-12-24 20:00:02: pid 446: DETAIL:  connecting 0 backend
2014-12-24 20:00:02: pid 446: DEBUG:  creating new connection to backend
2014-12-24 20:00:02: pid 446: DETAIL:  connecting 1 backend
2014-12-24 20:00:02: pid 446: DEBUG:  SSL is requested but SSL support is not available
2014-12-24 20:00:02: pid 446: DEBUG:  SSL is requested but SSL support is not available
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  slot: 0 length: 12
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  slot: 1 length: 12
2014-12-24 20:00:02: pid 446: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 446: DETAIL:  auth kind:5
2014-12-24 20:00:02: pid 446: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 446: DETAIL:  trying md5 authentication
2014-12-24 20:00:02: pid 446: DEBUG:  performing md5 authentication
2014-12-24 20:00:02: pid 446: DETAIL:  DB node id: 0 salt: ffffffdb2c2557
2014-12-24 20:00:02: pid 446: DEBUG:  authentication backend
2014-12-24 20:00:02: pid 446: DETAIL:  trying md5 authentication
2014-12-24 20:00:02: pid 446: DEBUG:  performing md5 authentication
2014-12-24 20:00:02: pid 446: DETAIL:  DB node id: 1 salt: ffffff86ffffffac701b
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 22
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 22
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"application_name" value:""
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"application_name" value:""
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"client_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"client_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 23
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 23
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"DateStyle" value:"ISO, DMY"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"DateStyle" value:"ISO, DMY"
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"integer_datetimes" value:"on"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"integer_datetimes" value:"on"
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 27
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 27
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"IntervalStyle" value:"postgres"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"IntervalStyle" value:"postgres"
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 21
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 21
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"is_superuser" value:"off"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"is_superuser" value:"off"
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 0 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  master slot: 1 length: 25
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 name:"server_encoding" value:"UTF8"
2014-12-24 20:00:02: pid 446: DEBUG:  process parameter status
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 name:"server_encoding" value:"UTF8"

...

2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  Execute: portal name <>
2014-12-24 20:00:02: pid 446: DEBUG:  Execute: query string = <select this_.idn_prtc as idn1_15_0_, this_.cod_raiz_cnpj as cod2_15_0_, this_.ind_sinc as ind3_15_0_ from desif.protocolos this_ where this_.ind_sinc=$1 order by this_.idn_prtc asc limit $2>
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:1 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'C'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = 'C'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'S'(53) from frontend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = 'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'Z'(5a) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  Ready For Query received
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  slot: 1 length: 5
2014-12-24 20:00:02: pid 446: DEBUG:  processing ReadyForQuery
2014-12-24 20:00:02: pid 446: DETAIL:  transaction state 'T'(54)
2014-12-24 20:00:02: pid 446: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'P'(50) from frontend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  Parse: statement name <S_2>
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  decide where to send the queries
2014-12-24 20:00:02: pid 446: DETAIL:  destination = 3 for query= "COMMIT"
2014-12-24 20:00:02: pid 446: DEBUG:  Parse: waiting for master completing the query
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  detect error: kind: 1
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:1 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 kind:'1'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 of 2 kind = '1'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'1'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = '1'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind '1'(31) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'B'(42) from frontend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  Bind: waiting for master completing the query
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:1 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 kind:'2'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 of 2 kind = '2'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'2'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = '2'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind '2'(32) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  adding sent message to list
2014-12-24 20:00:02: pid 446: DETAIL:  portal "" already exists
2014-12-24 20:00:02: pid 446: DEBUG:  checking if query context can be safely destroyed
2014-12-24 20:00:02: pid 446: DETAIL:  query context 0x143c510 is still used 2 times. query:"select this_.idn_prtc as idn1_15_0_, this_.cod_raiz_cnpj as cod2_15_0_, this_.ind_sinc as ind3_15_0_ from desif.protocolos this_ where this_.ind_sinc=$1 order by this_.idn_prtc asc limit $2"
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'E'(45) from frontend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  Execute: portal name <>
2014-12-24 20:00:02: pid 446: DEBUG:  Execute: query string = <COMMIT>
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  waiting for query response
2014-12-24 20:00:02: pid 446: DETAIL:  waiting for backend:1 to complete the query
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 kind:'C'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'C'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = 'C'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting command success. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  processing frontend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'S'(53) from frontend
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 kind:'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 kind:'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:00:02: pid 446: DETAIL:  backend:1 of 2 kind = 'Z'
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  received kind 'Z'(5a) from backend
2014-12-24 20:00:02: pid 446: DEBUG:  processing backend response
2014-12-24 20:00:02: pid 446: DETAIL:  Ready For Query received
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  slot: 0 length: 5
2014-12-24 20:00:02: pid 446: DEBUG:  reading message length
2014-12-24 20:00:02: pid 446: DETAIL:  slot: 1 length: 5
2014-12-24 20:00:02: pid 446: DEBUG:  processing ReadyForQuery
2014-12-24 20:00:02: pid 446: DETAIL:  transaction state 'T'(54)
2014-12-24 20:00:02: pid 446: DEBUG:  processing ReadyForQuery
2014-12-24 20:00:02: pid 446: DETAIL:  transaction state 'I'(49)
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing writing transaction. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing failed transaction. DONE
2014-12-24 20:00:02: pid 446: DEBUG:  session context: clearing failed transaction. DONE

...

2014-12-24 20:01:03: pid 446: ERROR:  unable to read data
2014-12-24 20:01:03: pid 446: DETAIL:  child connection forced to terminate due to client_idle_limit:60 is reached
2014-12-24 20:01:03: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 446: DEBUG:  decide where to send the queries
2014-12-24 20:01:03: pid 446: DETAIL:  destination = 3 for query= " DISCARD ALL"
2014-12-24 20:01:03: pid 446: DEBUG:  waiting for query response
2014-12-24 20:01:03: pid 446: DETAIL:  waiting for backend:0 to complete the query
2014-12-24 20:01:03: pid 446: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 446: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 446: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 446: DEBUG:  detect error: kind: S
2014-12-24 20:01:03: pid 446: DEBUG:  waiting for query response
2014-12-24 20:01:03: pid 446: DETAIL:  waiting for backend:1 to complete the query
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 kind:'S'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  parameter name: is_superuser value: "off"
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 kind:'S'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  parameter name: session_authorization value: "user_updt"
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 kind:'C'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 kind:'S'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  parameter name: is_superuser value: "off"
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 kind:'S'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  parameter name: session_authorization value: "user_updt"
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 kind:'C'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 of 2 kind = 'C'
2014-12-24 20:01:03: pid 446: DEBUG:  processing backend response
2014-12-24 20:01:03: pid 446: DETAIL:  received kind 'C'(43) from backend
2014-12-24 20:01:03: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 446: DEBUG:  checking if query context can be safely destroyed
2014-12-24 20:01:03: pid 446: DETAIL:  query context 0x143b0d8 is still used 2 times. query:"COMMIT"
2014-12-24 20:01:03: pid 446: DEBUG:  session context: setting query in progress. DONE
2014-12-24 20:01:03: pid 446: DEBUG:  session context: setting command success. DONE
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 kind:'Z'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 kind:'Z'
2014-12-24 20:01:03: pid 446: DEBUG:  reading backend data packet kind
2014-12-24 20:01:03: pid 446: DETAIL:  backend:1 of 2 kind = 'Z'
2014-12-24 20:01:03: pid 446: DEBUG:  processing backend response
2014-12-24 20:01:03: pid 446: DETAIL:  received kind 'Z'(5a) from backend
2014-12-24 20:01:03: pid 446: DEBUG:  processing backend response
2014-12-24 20:01:03: pid 446: DETAIL:  Ready For Query received
2014-12-24 20:01:03: pid 446: DEBUG:  reading message length
2014-12-24 20:01:03: pid 446: DETAIL:  slot: 0 length: 5
2014-12-24 20:01:03: pid 446: DEBUG:  reading message length
2014-12-24 20:01:03: pid 446: DETAIL:  slot: 1 length: 5
2014-12-24 20:01:03: pid 446: DEBUG:  processing ReadyForQuery
2014-12-24 20:01:03: pid 446: DETAIL:  transaction state 'I'(49)
2014-12-24 20:01:03: pid 446: DEBUG:  processing ReadyForQuery
2014-12-24 20:01:03: pid 446: DETAIL:  transaction state 'I'(49)
2014-12-24 20:01:03: pid 446: DEBUG:  setting backend connection close timer
2014-12-24 20:01:03: pid 446: DETAIL:  close time 1419458463
2014-12-24 20:01:03: pid 446: DEBUG:  setting backend connection close timer
2014-12-24 20:01:03: pid 446: DETAIL:  setting alarm after 60 seconds




4.3 - PID 11449 STUCKED

2014-12-26 10:51:07: pid 14479: DEBUG:  reaper handler: forked a new child with PID:11449
2014-12-26 10:51:07: pid 14479: DEBUG:  reaper handler: exiting normally
2014-12-26 10:51:07: pid 11449: DEBUG:  I am Pgpool Child process with pid: 11449
2014-12-26 10:51:07: pid 11449: DEBUG:  initializing backend status

...

2014-12-26 10:54:11: pid 11449: DEBUG:  I am 11449 accept fd 7
2014-12-26 10:54:11: pid 11449: LOG:  new connection received
2014-12-26 10:54:11: pid 11449: DETAIL:  connecting host=10.10.2.49 port=40779
2014-12-26 10:54:11: pid 11449: DEBUG:  reading startup packet
2014-12-26 10:54:11: pid 11449: DETAIL:  Protocol Major: 3 Minor: 0 database: portoalegre user: user_updt
2014-12-26 10:54:11: pid 11449: DEBUG:  sending backend key data
2014-12-26 10:54:11: pid 11449: DETAIL:  send pid 11497 to frontend
2014-12-26 10:54:11: pid 11449: WARNING:  failed to execute regex matching, pattern is NULL
2014-12-26 10:54:11: pid 11449: DEBUG:  selecting load balance node
2014-12-26 10:54:11: pid 11449: DETAIL:  selected backend id is 0
2014-12-26 10:54:11: pid 11449: DEBUG:  initializing session context
2014-12-26 10:54:11: pid 11449: DETAIL:  selected load balancing node: 0
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing transaction isolation. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing writing transaction. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing failed transaction. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing failed transaction. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing skip reading from backends. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing ignore till sync. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'P'(50) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  Parse: statement name <>
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  decide where to send the queries
2014-12-26 10:54:11: pid 11449: DETAIL:  destination = 3 for query= "SET extra_float_digits = 3"
2014-12-26 10:54:11: pid 11449: DEBUG:  Parse: waiting for master completing the query
2014-12-26 10:54:11: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:54:11: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:54:11: pid 11449: DEBUG:  detect error: kind: 1
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'1'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = '1'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind '1'(31) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting command success. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'B'(42) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  Bind: waiting for master completing the query
2014-12-26 10:54:11: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:54:11: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'2'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = '2'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind '2'(32) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting command success. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'E'(45) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  Execute: portal name <>
2014-12-26 10:54:11: pid 11449: DEBUG:  Execute: query string = <SET extra_float_digits = 3>
2014-12-26 10:54:11: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:54:11: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'C'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'C'(43) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting command success. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'S'(53) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'Z'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'Z'(5a) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  Ready For Query received
2014-12-26 10:54:11: pid 11449: DEBUG:  reading message length
2014-12-26 10:54:11: pid 11449: DETAIL:  slot: 0 length: 5
2014-12-26 10:54:11: pid 11449: DEBUG:  processing ReadyForQuery
2014-12-26 10:54:11: pid 11449: DETAIL:  transaction state 'I'(49)
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'P'(50) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  Parse: statement name <>
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
2014-12-26 10:54:11: pid 11449: DETAIL:  result = 0
2014-12-26 10:54:11: pid 11449: DEBUG:  decide where to send the queries
2014-12-26 10:54:11: pid 11449: DETAIL:  destination = 2 for query= "select 1"
2014-12-26 10:54:11: pid 11449: DEBUG:  Parse: waiting for master completing the query
2014-12-26 10:54:11: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:54:11: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:54:11: pid 11449: DEBUG:  detect error: kind: 1
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'1'

...

2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  Execute: portal name <>
2014-12-26 10:54:11: pid 11449: DEBUG:  Execute: query string = <SELECT username,password,enabled FROM users WHERE username = $1>
2014-12-26 10:54:11: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:54:11: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'C'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'C'(43) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting command success. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  processing frontend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'S'(53) from frontend
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: clearing doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting doing extended query messaging. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 kind:'Z'
2014-12-26 10:54:11: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:54:11: pid 11449: DETAIL:  backend:0 of 2 kind = 'Z'
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  received kind 'Z'(5a) from backend
2014-12-26 10:54:11: pid 11449: DEBUG:  processing backend response
2014-12-26 10:54:11: pid 11449: DETAIL:  Ready For Query received
2014-12-26 10:54:11: pid 11449: DEBUG:  reading message length
2014-12-26 10:54:11: pid 11449: DETAIL:  slot: 0 length: 5
2014-12-26 10:54:11: pid 11449: DEBUG:  processing ReadyForQuery
2014-12-26 10:54:11: pid 11449: DETAIL:  transaction state 'I'(49)

...

2014-12-26 10:55:12: pid 11449: ERROR:  unable to read data
2014-12-26 10:55:12: pid 11449: DETAIL:  child connection forced to terminate due to client_idle_limit:60 is reached
2014-12-26 10:55:12: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:55:12: pid 11449: DEBUG:  decide where to send the queries
2014-12-26 10:55:12: pid 11449: DETAIL:  destination = 3 for query= " DISCARD ALL"
2014-12-26 10:55:12: pid 11449: DEBUG:  waiting for query response
2014-12-26 10:55:12: pid 11449: DETAIL:  waiting for backend:0 to complete the query
2014-12-26 10:55:12: pid 11449: DEBUG:  detect error: kind: S
2014-12-26 10:55:12: pid 11449: DEBUG:  detect error: kind: S
2014-12-26 10:55:12: pid 11449: DEBUG:  detect error: kind: S
2014-12-26 10:55:12: pid 11449: DEBUG:  detect error: kind: S
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 kind:'S'
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  parameter name: is_superuser value: "off"
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 kind:'S'
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  parameter name: session_authorization value: "user_updt"
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 kind:'C'
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 of 2 kind = 'C'
2014-12-26 10:55:12: pid 11449: DEBUG:  processing backend response
2014-12-26 10:55:12: pid 11449: DETAIL:  received kind 'C'(43) from backend
2014-12-26 10:55:12: pid 11449: DEBUG:  checking if query context can be safely destroyed
2014-12-26 10:55:12: pid 11449: DETAIL:  query context 0x143a530 is still used 2 times. query:"SELECT username,password,enabled FROM users WHERE username = $1"
2014-12-26 10:55:12: pid 11449: DEBUG:  session context: setting query in progress. DONE
2014-12-26 10:55:12: pid 11449: DEBUG:  session context: setting command success. DONE
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 kind:'Z'
2014-12-26 10:55:12: pid 11449: DEBUG:  reading backend data packet kind
2014-12-26 10:55:12: pid 11449: DETAIL:  backend:0 of 2 kind = 'Z'

ravazzolo

2014-12-26 22:50

reporter   ~0000505

I can't reproduce the bug, it occurs eventually, but it's occurring every day.

I started debbuging pgPool and in the uploaded file "Stuck Connections Logs" there are some informations that maybe can help you.

The file contains:
1 - STUCKED Processes
2 - PCP Info PID 3083 and PID 11449
3 - PostgreSQL Processes
4 - pgPool Log
4.1 - PID 3083 STUCKED
4.2 - PID 446 NOT STUCKED
4.3 - PID 11449 STUCKED

Thanks,

Ricardo Ravazzolo.

jormiya

2015-07-29 14:29

reporter   ~0000548

I hava a similar phenomenon in my system.

OS CentOS 6.6
pgpool-II 3.4.2

It sometimes occuered coused by "can't read data from frontend" or "unable to read data".


 

Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24454: ERROR: unable to read data from frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24454: DETAIL: EOF encountered with frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24455: ERROR: unable to read data from frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24455: DETAIL: EOF encountered with frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 25149: ERROR: unable to read data from frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 25149: DETAIL: EOF encountered with frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24343: ERROR: unable to read data from frontend
Jul 29 10:55:41 pgpool: 2015-07-29 10:55:41: pid 24343: DETAIL: EOF encountered with frontend


Jul 29 12:50:23 pgpool: 2015-07-29 12:50:23: pid 31926: ERROR: unable to read data
Jul 29 12:50:23 pgpool: 2015-07-29 12:50:23: pid 31926: DETAIL: child connection forced to terminate due to client_idle_limit:1800 is reached

root 13868 1748 0 04:56 ? 00:00:00 pgpool: test1 test1 172.16.XX.XX(53568) DISCARD
root 24455 1750 0 10:55 ? 00:00:01 pgpool: test2 test2 172.16.XX.XX(37315) DISCARD
root 25482 1750 0 11:26 ? 00:00:00 pgpool: test2 test2 172.16.XX.XX(54540) DISCARD
root 26055 1748 0 Jul28 ? 00:00:00 pgpool: test1 test1 172.16.XX.XX(44655) DISCARD
root 31926 1750 0 Jul28 ? 00:00:04 pgpool: test2 test2 172.16.17.84(45584) DISCARD

Muhammad Usama

2015-08-21 19:47

developer   ~0000559

Hi,
Thanks for the report.

I have committed the fix in master and 3.4 branches.
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=9b8a909c5558268851685e96c49ae831438e330d

Best regards!

Muhammad Usama

2015-08-21 19:49

developer   ~0000560

Fix committed to master and 3.4 branches.
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=9b8a909c5558268851685e96c49ae831438e330d [^]

Issue History

Date Modified Username Field Change
2014-12-17 04:50 ravazzolo New Issue
2014-12-21 19:04 t-ishii Assigned To => t-ishii
2014-12-21 19:04 t-ishii Status new => assigned
2014-12-21 19:04 t-ishii Additional Information Updated View Revisions
2014-12-21 19:06 t-ishii Note Added: 0000503
2014-12-26 22:49 ravazzolo File Added: Stuck Connections Logs.txt
2014-12-26 22:50 ravazzolo Note Added: 0000505
2015-07-29 14:29 jormiya Note Added: 0000548
2015-08-04 10:00 t-ishii Assigned To t-ishii => Muhammad Usama
2015-08-21 19:47 Muhammad Usama Note Added: 0000559
2015-08-21 19:49 Muhammad Usama Note Added: 0000560
2015-08-21 19:49 Muhammad Usama Status assigned => resolved
2015-08-21 19:49 Muhammad Usama Resolution open => fixed