[pgpool-general: 2155] Re: Postgres Sequence numbers different on backends when inserts run concurrently

[Karsten Düsterloh]

Tatsuo Ishii wrote:
> Ok, I think I found the cause of the problem.
> 
> Pgpool automatically issues a LOCK command(table lock or row lock
> depending on your configuration) to keep consistency while handling
> INSERT command. This works fine with your test program until 4
> iterated INSERT. In each INSERT cycle, pgpool issues LOCK while
> processing "parse" message (which is generated by JDBC driver while
> handling "prepare") which is followed by "bind" "describe" and
> "execute" message. This is good. However, starting from 5th INSERT,
> JDBC skips generating the parse message and starts from
> "bind". Unfortunately pgpool does not issue LOCK while processing the
> bind message. Note that the behavior of JDBC is legal. Just pgpool is
> not prepared for the situation. Fixing it is not a trivial work.

We do see this problem as well, but we neither use JDBC nor parse/bind/exec.
- pgpool 3.3.0
- postgres 9.1.9
- replication, load balancing, two backend nodes

Any two connections INSERTing (or calling nextval etc.) in parallel into
the same table with automatic primary key generation from a sequence
will eventually be applied to the backend in different order and hence
cause a duplicate key error (if such an index exists).

Log of the last clash yesterday:
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: DB node id: 0 backend pid: 15910 statement: INSERT INTO "accounting"("created_by", "type", "typeid", "begin", "end", "reftable1", "refid1", "sourcegroup", "targetgroup", "str1", "str2", "str3", "str4", "str5", "val1", "val2", "val3", "val4", "val5", "bool1", "created") VALUES ( … valueset#1 … ) RETURNING "id"
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: wait_for_query_response: waiting for backend 0 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessFrontendResponse: kind from frontend Q(51)
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:0 len:0
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_unset_doing_extended_query_message: done
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: statement: SELECT nextval('accounting_id_seq') AS id;/*kylix.ipbsa_dev*/;
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_set_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: DB node id: 0 backend pid: 9212 statement: SELECT nextval('accounting_id_seq') AS id;/*kylix.ipbsa_dev*/;
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: wait_for_query_response: waiting for backend 0 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: DB node id: 1 backend pid: 21133 statement: SELECT nextval('accounting_id_seq') AS id;/*kylix.ipbsa_dev*/;
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: wait_for_query_response: waiting for backend 1 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: P from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend P NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: P from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend P NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessBackendResponse: kind from backend: P
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: DB node id: 1 backend pid: 14686 statement: INSERT INTO "accounting"("created_by", "type", "typeid", "begin", "end", "reftable1", "refid1", "sourcegroup", "targetgroup", "str1", "str2", "str3", "str4", "str5", "val1", "val2", "val3", "val4", "val5", "bool1", "created") VALUES ( … valueset#1 … ) RETURNING "id"
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:7 len:42
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:7 len:42
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: wait_for_query_response: waiting for backend 1 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: T from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: T from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend T NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessBackendResponse: kind from backend: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:13 len:36
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:13 len:36
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: RowDescription: type oid: 20
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: RowDescription: field size: 8
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: RowDescription: modifier: 65535
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: D from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend D NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: D from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend D NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessBackendResponse: kind from backend: D
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: AsciiRow: len: 9 data: 202403747
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: C from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: C from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessBackendResponse: kind from backend: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:48 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:48 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: CompletedResponse: string: "SELECT 1"
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: Z from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: Z from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessBackendResponse: kind from backend: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_unset_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_unset_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: T from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: T from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 1 th backend T NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ProcessBackendResponse: kind from backend: T
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: D from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 0 th backend D NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: D from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 1 th backend D NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ProcessBackendResponse: kind from backend: D
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: C from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: C from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 1 th backend C NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ProcessBackendResponse: kind from backend: C
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: pool_set_command_success: done
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: Z from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: kind: Z from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: read_kind_from_backend: read kind from 1 th backend Z NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ProcessBackendResponse: kind from backend: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: DB node id: 1 backend pid: 14686 statement: COMMIT
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: Query: COMMIT
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: wait_for_query_response: waiting for backend 1 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: len:b000000
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: kind: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: DB node id: 0 backend pid: 15910 statement: COMMIT
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: Query: COMMIT
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: wait_for_query_response: waiting for backend 0 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: len:b000000
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: do_command: kind: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: pool_read_message_length: slot: 0 length: 5
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: pool_read_message_length: slot: 1 length: 5
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ReadyForQuery: transaction state:T
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ReadyForQuery: transaction state:I
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: pool_unset_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: pool_unset_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[15155]: ProcessBackendResponse: Ready For Query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: ProcessFrontendResponse: kind from frontend Q(51)
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:0 len:0
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_unset_doing_extended_query_message: done
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: statement: INSERT INTO accounting ("type","typeid","reftable1","refid1","begin","end","targetgroup","val1","val2","val3","str1","str2","bool1","created_by","id") VALUES ( … valueset#2 … );/*kylix.ipbsa_dev*/;
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_set_query_in_progress: done
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: get_insert_command_table_name: extracted table name: "accounting"
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: extended:0 query:SELECT now()
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:6 len:62
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: T

> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: row description received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: num_fileds: 1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:13 len:55
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: D
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: data row received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:67 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: Command complete received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: Ready for query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: extended:0 query:SELECT now()
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: P
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:6 len:62
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: T
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: row description received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: num_fileds: 1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:13 len:55
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: D
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: data row received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:67 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: Command complete received
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: kind: Z
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: do_query: Ready for query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: DB node id: 0 backend pid: 9212 statement: INSERT INTO "accounting"("type", "typeid", "reftable1", "refid1", "begin", "end", "targetgroup", "val1", "val2", "val3", "str1", "str2", "bool1", "created_by", "id", "created") VALUES ( … valueset#2 … )
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: wait_for_query_response: waiting for backend 0 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: detect_error: kind: C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: DB node id: 1 backend pid: 21133 statement: INSERT INTO "accounting"("type", "typeid", "reftable1", "refid1", "begin", "end", "targetgroup", "val1", "val2", "val3", "str1", "str2", "bool1", "created_by", "id", "created") VALUES ( … valueset#2 … )
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: wait_for_query_response: waiting for backend 1 completing the query
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:74 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 21133 statement: INSERT INTO "accounting"("type", "typeid", "reftable1", "refid1", "begin", "end", "targetgroup", "val1", "val2", "val3", "str1", "str2", "bool1", "created_by", "id", "created") VALUES ( … valueset#2 … ) message: ERROR:  duplicate key value violates unique constraint "accounting_pkey"
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: C from 0 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: kind: E from 1 th backend
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: read kind from 1 th backend E NUM_BACKENDS: 2
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: read_kind_from_backend: 1 th kind E does not match with master or majority connection kind C
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: pool_read_string: read all from pending data. po:75 len:1
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: kind mismatch among backends. Possible last query was: "INSERT INTO accounting ("type","typeid","reftable1","refid1","begin","end","targetgroup","val1","val2","val3","str1","str2","bool1","created_by","id") VALUES ( … valueset#2 … );/*kylix.ipbsa_dev*/;" kind details are: 0[C] 1[E: ERROR:  duplicate key value violates unique constraint "accounting_pkey"
> ]
> 2013-09-23T15:33:59.000+02:00 pgpool[8837]: degenerate_backend_set: 1 fail over request from pid 8837
> 2013-09-23T15:33:59.000+02:00 pgpool[2975]: failover_handler called
> 2013-09-23T15:33:59.000+02:00 pgpool[2975]: failover_handler: starting to select new master node
> 2013-09-23T15:33:59.000+02:00 pgpool[2975]: starting degeneration. shutdown host 172.19.0.11(5433)
> 2013-09-23T15:33:59.000+02:00 pgpool[2975]: Restart all children


Karsten