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

Tue Sep 24 21:23:30 JST 2013

> 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

It seems you are using old protocol (version 2) that might cause the
problem. Is there any reason for you to use the old protocol?
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> 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
> _______________________________________________
> pgpool-general mailing list
> pgpool-general at pgpool.net
> http://www.pgpool.net/mailman/listinfo/pgpool-general