[Pgpool-general] Node recovery failing in 3.0.x

[Karsten Düsterloh]

Hi!

Karsten Düsterloh wrote:
> We were running pgpool-II 2.3.3 with two Postgresql 8.3.11 nodes.
> 
> Yesterday, we switched to pgpool-II 3.0.1. After a while, node 1 
> degenerated:

We upgraded to 3.0.3 yesterday.
The second node was still offline, so we decided to reattach it by
running a recovery, using our scripts known to be working with 2.3.3.

Again, everything worked as usual up to the recovery_1st_stage_command.
Sessions are still disconnected after a timeout, but the second
checkpoint doesn't get created and the recovery_2nd_stage_command is
never executed...

Fortunately, we now do have a debug log!

I left out blocks like this, though:
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 26855: child life 300 seconds expired
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 21753: reap_handler called
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 21753: reap_handler: call wait3
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 21753: child 26855 exits with status 512
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 21753: fork a new child pid 28094
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 21753: reap_handler: normally exited
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: DEBUG: pid 28094: I am 28094

This leaves us with these ~230 log lines:

> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: LOG:   pid 22011: 1st stage is done
> 2011-03-10T10:01:30.000+01:00 pg1 pgpool: LOG:   pid 22011: starting 2nd stage
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 26797: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 26797: statement: ABORT
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 26797: statement:  DISCARD ALL
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 26797: pool_connection_pool_timer: set close time 1299747691
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24071: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24071: statement: ABORT
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24115: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24071: statement:  DISCARD ALL
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24115: statement: ABORT
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24071: pool_connection_pool_timer: set close time 1299747691
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 24115: statement:  DISCARD ALL
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 24115: pool_connection_pool_timer: set close time 1299747691
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21890: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21890: statement: ABORT
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21890: statement:  DISCARD ALL
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21890: pool_connection_pool_timer: set close time 1299747691
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21795: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21795: statement: ABORT
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: LOG:   pid 21795: statement:  DISCARD ALL
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_set_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_unset_query_in_progress: done
> 2011-03-10T10:01:31.000+01:00 pg1 pgpool: DEBUG: pid 21795: pool_connection_pool_timer: set close time 1299747691
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26820: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26820: statement: ABORT
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26820: statement:  DISCARD ALL
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26820: pool_connection_pool_timer: set close time 1299747692
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 21854: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 21854: statement: ABORT
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 21854: statement:  DISCARD ALL
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 21854: pool_connection_pool_timer: set close time 1299747692
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26559: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26559: statement: ABORT
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 26559: statement:  DISCARD ALL
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 26559: pool_connection_pool_timer: set close time 1299747692
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 25855: pool_process_query: child connection forced to terminate due to client_idle_limit_in_recovery(1) reached
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 25855: statement: ABORT
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_read_string: read all from pending data. po:10 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: CompletedResponse: string: "ROLLBACK"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: LOG:   pid 25855: statement:  DISCARD ALL
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_set_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: wait_for_query_response: waiting for backend 0 completing the query
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: ProcessBackendResponse: kind from backend: C
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_read_string: read all from pending data. po:13 len:1
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: CompletedResponse: string: "DISCARD ALL"
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: ProcessBackendResponse: kind from backend: Z
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_unset_query_in_progress: done
> 2011-03-10T10:01:32.000+01:00 pg1 pgpool: DEBUG: pid 25855: pool_connection_pool_timer: set close time 1299747692
> 2011-03-10T10:02:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:03:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:04:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:05:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:06:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:07:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:08:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:09:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:09:52.000+01:00 pg1 pgpool: LOG:   pid 21753: received fast shutdown request

We finally shutdown pgpool then (last line), as there seemed to be no
progress. We switched back to pgpool 2.3.3 then and the 2nd stage of
recovery was done in a few seconds as usual.

Is this a known problem?

Health checking as such does not seem to be a problem either, because in
stage 1 we see this about every minute:

> 2011-03-10T10:01:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: starting health checking
> 2011-03-10T10:01:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: health_check: 0 th DB node status: 2
> 2011-03-10T10:01:26.000+01:00 pg1 pgpool: DEBUG: pid 21753: health_check: 1 th DB node status: 3

Karsten


BTW: Running the OTRS 3.0.6 ticket system against pgpool 3.0.3 doesn't
seem to work properly either, it claims a lot of intermittent "no
connection to the server" errors…