View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000101Pgpool-IIBugpublic2014-05-17 22:562014-05-18 18:30
Reporterekass Assigned Tot-ishii  
PrioritynormalSeveritymajorReproducibilityrandom
Status resolvedResolutionopen 
PlatformLinuxOSDebianOS VersionWheezy x64
Summary0000101: random kind mismatch among backends. Possible last query was: "SET default_transaction_isolation TO DEFAULT"
Descriptionpgpool2 v.3.3.3 with postgresql-9.3
pgpool2 configured in master slave mode with streaming replication, db nodes are synchronised correctly
django site connects to pgpool with psycopg2 and autocommit set to true. Somehow this command is frequently called: SET default_transaction_isolation to DEFAULT; and causes an error randomly.
Steps To Reproducepostgres@debian:~$ psql -h localhost -p 9999 -c 'SET default_transaction_isolation to DEFAULT;'
ERROR: kind mismatch among backends. Possible last query was: "SET default_transaction_isolation to DEFAULT;" kind details are: 0[N: statement: SET default_transaction_isolation to DEFAULT;] 1[C]
HINT: check data consistency among db nodes
ERROR: kind mismatch among backends. Possible last query was: "SET default_transaction_isolation to DEFAULT;" kind details are: 0[N: statement: SET default_transaction_isolation to DEFAULT;] 1[C]
HINT: check data consistency among db nodes
connection to server was lost

but select from database works fine!
Additional InformationSite throws 500 error because connection is already closed. Pgpool reports this error in log:

2014-05-17 16:48:21 LOG: pid 8401: DB node id: 1 backend pid: 31370 statement: SET default_transaction_isolation to DEFAULT;
2014-05-17 16:48:21 DEBUG: pid 8401: wait_for_query_response: waiting for backend 1 completing the query
2014-05-17 16:48:21 DEBUG: pid 8401: read_kind_from_one_backend: read kind from 0 th backend N
2014-05-17 16:48:21 DEBUG: pid 8401: read_kind_from_backend: kind: N from 0 th backend
2014-05-17 16:48:21 DEBUG: pid 8401: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 2
2014-05-17 16:48:21 DEBUG: pid 8401: read_kind_from_backend: kind: C from 1 th backend
2014-05-17 16:48:21 DEBUG: pid 8401: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2014-05-17 16:48:21 ERROR: pid 8401: read_kind_from_backend: 1 th kind C does not match with master or majority connection kind N
2014-05-17 16:48:21 ERROR: pid 8401: kind mismatch among backends. Possible last query was: "SET default_transaction_isolation to DEFAULT;" kind details are: 0[N: statement: SET default_transaction_isolation to DEFAULT;] 1[C]
2014-05-17 16:48:21 LOG: pid 8401: do_child: exits with status 1 due to error
TagsNo tags attached.

Activities

t-ishii

2014-05-18 00:17

developer   ~0000411

The log says one of PostgreSQL node returns NOTICE message when the query was sent to it. Can you show me the PostgreSQL? There must be NOTICE message there.

ekass

2014-05-18 00:24

reporter   ~0000412

I see no notice message.

master:
2014-05-17 17:49:56 EEST LOG: statement: SHOW default_transaction_isolation
2014-05-17 17:49:56 EEST LOG: duration: 1.042 ms
2014-05-17 17:49:56 EEST LOG: statement: SET default_transaction_isolation TO DEFAULT
2014-05-17 17:49:56 EEST LOG: duration: 0.569 ms

slave:
2014-05-17 16:48:21 EEST LOG: statement: BEGIN
2014-05-17 16:48:21 EEST LOG: duration: 0.451 ms
2014-05-17 16:48:21 EEST LOG: statement: SET default_transaction_isolation to DEFAULT;
2014-05-17 16:48:21 EEST LOG: duration: 0.455 ms

Shouldn't this command be executed only in one backend though?

ekass

2014-05-18 00:32

reporter   ~0000413

Last edited: 2014-05-18 00:33

 Ignore the different time of master, i just copied from the log the latest error but that's what he shows at the same time.

t-ishii

2014-05-18 00:32

developer   ~0000414

Can you set log_min_messages = notice in postgresql.conf? PostgreSQL does not log NOTICE message by default.

The SET command should be executed on both master and slave. A SELECT's behavior may depend on the tx isolation level.

ekass

2014-05-18 00:41

reporter   ~0000415

I had debug1 in postgres. In either way it doesn't show any notice message i just tried it.

A more detail pgpool log:

2014-05-17 18:37:35 DEBUG: pid 8274: select_load_balancing_node: selected backend id is 1
2014-05-17 18:37:35 DEBUG: pid 8274: selected load balancing node: 1
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_query_in_progress: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_command_success: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_writing_transaction: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_failed_transaction: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_transaction_isolation: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_skip_reading_from_backends: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_ignore_till_sync: done
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend Z
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: Z from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: Z from 1 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: Z
2014-05-17 18:37:35 DEBUG: pid 8274: pool_read_message_length: slot: 0 length: 5
2014-05-17 18:37:35 DEBUG: pid 8274: pool_read_message_length: slot: 1 length: 5
2014-05-17 18:37:35 DEBUG: pid 8274: ReadyForQuery: transaction state:
2014-05-17 18:37:35 DEBUG: pid 8274: ReadyForQuery: transaction state:I
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: Ready For Query
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessFrontendResponse: kind from frontend Q(51)
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_doing_extended_query_message: done
2014-05-17 18:37:35 LOG: pid 8274: statement: SHOW default_transaction_isolation
2014-05-17 18:37:35 DEBUG: pid 8274: pool_set_query_in_progress: done
2014-05-17 18:37:35 DEBUG: pid 8274: send_to_where: 0 query: SHOW default_transaction_isolation
2014-05-17 18:37:35 LOG: pid 8274: DB node id: 0 backend pid: 3540 statement: SHOW default_transaction_isolation
2014-05-17 18:37:35 DEBUG: pid 8274: wait_for_query_response: waiting for backend 0 completing the query
2014-05-17 18:37:35 LOG: pid 8274: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 3540 statement: SHOW default_transaction_isolation message: statement: SHOW default_transaction_isolation
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: N from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend T
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: T from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: T
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend D
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: D from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend D NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: D
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend C
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: C from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: C
2014-05-17 18:37:35 DEBUG: pid 8274: pool_set_command_success: done
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: N from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend Z
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: Z from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: kind from backend: Z
2014-05-17 18:37:35 DEBUG: pid 8274: pool_read_message_length: slot: 0 length: 5
2014-05-17 18:37:35 DEBUG: pid 8274: ReadyForQuery: transaction state:I
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_query_in_progress: done
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_query_in_progress: done
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessBackendResponse: Ready For Query
2014-05-17 18:37:35 DEBUG: pid 8274: ProcessFrontendResponse: kind from frontend Q(51)
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_doing_extended_query_message: done
2014-05-17 18:37:35 LOG: pid 8274: statement: SET default_transaction_isolation TO DEFAULT
2014-05-17 18:37:35 DEBUG: pid 8274: pool_set_query_in_progress: done
2014-05-17 18:37:35 DEBUG: pid 8274: send_to_where: 3 query: SET default_transaction_isolation TO DEFAULT
2014-05-17 18:37:35 LOG: pid 8274: DB node id: 0 backend pid: 3540 statement: BEGIN
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: Query: BEGIN
2014-05-17 18:37:35 DEBUG: pid 8274: wait_for_query_response: waiting for backend 0 completing the query
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: len:47000000
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: C
2014-05-17 18:37:35 DEBUG: pid 8274: len:a000000
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: len:4a000000
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: Z
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: transaction state: T
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_writing_transaction: done
2014-05-17 18:37:35 LOG: pid 8274: DB node id: 1 backend pid: 31803 statement: BEGIN
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: Query: BEGIN
2014-05-17 18:37:35 DEBUG: pid 8274: wait_for_query_response: waiting for backend 1 completing the query
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: C
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: C
2014-05-17 18:37:35 DEBUG: pid 8274: len:a000000
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: kind: Z
2014-05-17 18:37:35 DEBUG: pid 8274: do_command: transaction state: T
2014-05-17 18:37:35 DEBUG: pid 8274: pool_unset_writing_transaction: done
2014-05-17 18:37:35 LOG: pid 8274: DB node id: 0 backend pid: 3540 statement: SET default_transaction_isolation TO DEFAULT
2014-05-17 18:37:35 DEBUG: pid 8274: wait_for_query_response: waiting for backend 0 completing the query
2014-05-17 18:37:35 LOG: pid 8274: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 3540 statement: SET default_transaction_isolation TO DEFAULT message: statement: SET default_transaction_isolation TO DEFAULT
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 DEBUG: pid 8274: detect_error: kind: N
2014-05-17 18:37:35 LOG: pid 8274: DB node id: 1 backend pid: 31803 statement: SET default_transaction_isolation TO DEFAULT
2014-05-17 18:37:35 DEBUG: pid 8274: wait_for_query_response: waiting for backend 1 completing the query
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_one_backend: read kind from 0 th backend N
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: N from 0 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 2
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: kind: C from 1 th backend
2014-05-17 18:37:35 DEBUG: pid 8274: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
2014-05-17 18:37:35 ERROR: pid 8274: read_kind_from_backend: 1 th kind C does not match with master or majority connection kind N
2014-05-17 18:37:35 ERROR: pid 8274: kind mismatch among backends. Possible last query was: "SET default_transaction_isolation TO DEFAULT" kind details are: 0[N: statement: SET default_transaction_isolation TO DEFAULT] 1[C]
2014-05-17 18:37:35 LOG: pid 8274: do_child: exits with status 1 due to error
2014-05-17 18:37:35 DEBUG: pid 8063: reap_handler called
2014-05-17 18:37:35 DEBUG: pid 8063: reap_handler: call wait3
2014-05-17 18:37:35 DEBUG: pid 8063: child 8274 exits with status 256
2014-05-17 18:37:35 DEBUG: pid 8063: fork a new child pid 8575
2014-05-17 18:37:35 DEBUG: pid 8063: reap_handler: normally exited
2014-05-17 18:37:35 DEBUG: pid 8575: I am 8575
2014-05-17 18:37:35 DEBUG: pid 8575: pool_initialize_private_backend_status: initialize backend status

t-ishii

2014-05-18 01:16

developer   ~0000416

If you run psql -c 'SET default_transaction_isolation to DEFAULT;' against PostgreSQL *master* directry, what do you get? I expect you see a NOTICE message.

ekass

2014-05-18 01:25

reporter   ~0000417

Last edited: 2014-05-18 01:36

 postgres@pgmaster:~$ psql -c 'SET default_transaction_isolation to DEFAULT;'
LOG: statement: SET default_transaction_isolation to DEFAULT;
LOG: duration: 0.419 ms
SET
postgres@pgmaster:~$

the same is the output from pgpool node with this command:
psql -h pgmaster -p 5432 -c 'SET default_transaction_isolation to DEFAULT;'
LOG: statement: SET default_transaction_isolation to DEFAULT;
LOG: duration: 0.702 ms
SET

t-ishii

2014-05-18 07:21

developer   ~0000418

Ok. What if you execute the same psql against slave node?

ekass

2014-05-18 17:04

reporter   ~0000419

postgres@pgslave:~$ psql -c 'SET default_transaction_isolation to DEFAULT;'
SET
postgres@pgslave:~$

Ok i probably figured it out. I had different client_min_messages in master and slave. I'm so sorry and thank you for your help!

t-ishii

2014-05-18 18:29

developer   ~0000420

Yep, that's what I guessed too. Please come back if you have further problems. Happy hacking!

Issue History

Date Modified Username Field Change
2014-05-17 22:56 ekass New Issue
2014-05-18 00:17 t-ishii Note Added: 0000411
2014-05-18 00:17 t-ishii Assigned To => t-ishii
2014-05-18 00:17 t-ishii Status new => assigned
2014-05-18 00:24 ekass Note Added: 0000412
2014-05-18 00:32 ekass Note Added: 0000413
2014-05-18 00:32 t-ishii Note Added: 0000414
2014-05-18 00:33 ekass Note Edited: 0000413
2014-05-18 00:41 ekass Note Added: 0000415
2014-05-18 01:16 t-ishii Note Added: 0000416
2014-05-18 01:25 ekass Note Added: 0000417
2014-05-18 01:36 ekass Note Edited: 0000417
2014-05-18 07:21 t-ishii Note Added: 0000418
2014-05-18 17:04 ekass Note Added: 0000419
2014-05-18 18:29 t-ishii Note Added: 0000420
2014-05-18 18:30 t-ishii Status assigned => resolved