[pgpool-general: 2360] Re: Problems with recovered master node.
Tatsuo Ishii
ishii at postgresql.org
Sat Dec 21 09:53:33 JST 2013
Ok, I will look into this.
Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp
> Hi.
> Here are the logs:
> In this log we have
> node 0 master
> node 1 slave
> node 2 slave
>
> Here we can see that the rollback is only sent to the node 0, that is
> the actual master.
>
> 2013-12-20 19:09:33 LOG: pid 10454: pgpool-II successfully started.
> version 3.3.2 (tokakiboshi)
> 2013-12-20 19:09:33 LOG: pid 10454: find_primary_node: primary node id
> is 0
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SET DATESTYLE TO 'ISO'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 1 backend pid: 8744
> statement: BEGIN
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 2 backend pid: 2708
> statement: BEGIN
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SET DATESTYLE TO 'ISO'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 1 backend pid: 8744
> statement: SET DATESTYLE TO 'ISO'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 2 backend pid: 2708
> statement: SET DATESTYLE TO 'ISO'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 1 backend pid: 8744
> statement: COMMIT
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 2 backend pid: 2708
> statement: COMMIT
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: COMMIT
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SHOW client_encoding
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SHOW client_encoding
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SHOW
> default_transaction_isolation
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SHOW default_transaction_isolation
> 2013-12-20 19:09:48 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: statement: select version()
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: select version()
> 2013-12-20 19:09:48 LOG: pid 10487: statement: select current_schema()
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: select current_schema()
> 2013-12-20 19:09:48 LOG: pid 10487: statement: show transaction
> isolation level
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: show transaction isolation level
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SELECT CAST('test plain
> returns' AS VARCHAR(60)) AS anon_1
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SELECT CAST('test
> unicode returns' AS VARCHAR(60)) AS anon_1
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
> 2013-12-20 19:09:48 LOG: pid 10487: statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: statement: INSERT INTO transaction
> (uuid, creation, server_version, server_fingerprint, client_agent,
> client_ip, query) VALUES ('hTq0do5BElHrojk2tXm4vFCUo32MNbkB6lqTDVDSvs0',
> '2013-12-21T00:10:00.731241+00:00', '3.5~rc2',
> '4096R/BC8C3F28CCC1EEEF64429563F1FCF92CCE34DD2C',
> '/usr/lib/application-server/orgtool', 'localhost', 'list')
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: INSERT INTO transaction (uuid, creation, server_version,
> server_fingerprint, client_agent, client_ip, query) VALUES
> ('hTq0do5BElHrojk2tXm4vFCUo32MNbkB6lqTDVDSvs0',
> '2013-12-21T00:10:00.731241+00:00', '3.5~rc2',
> '4096R/BC8C3F28CCC1EEEF64429563F1FCF92CCE34DD2C',
> '/usr/lib/application-server/orgtool', 'localhost', 'list')
> 2013-12-20 19:09:48 LOG: pid 10487: statement: COMMIT
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: COMMIT
> 2013-12-20 19:09:48 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SELECT org.uuid,
> org.creation, org.expiration, org.state, org.name
> FROM org
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) from (SELECT
> has_function_privilege('application', 'pgpool_regclass(cstring)',
> 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE
> p.proname = 'pgpool_regclass')) AS s
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'pg_namespace' AND c.relnamespace = n.oid AND n.nspname =
> 'pg_catalog'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org' AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute
> AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname =
> 'relistemp'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c,
> pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid
> = c.oid AND a.attname = 'relpersistence'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname
> = 'org' AND c.relpersistence = 'u'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT org.uuid, org.creation, org.expiration, org.state,
> org.name
> FROM org
> 2013-12-20 19:09:48 LOG: pid 10487: statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SELECT org_auth.uuid,
> org_auth.creation, org_auth.expiration, org_auth.state,
> org_auth.org_uuid, org_auth.auth_secret
> FROM org_auth
> WHERE org_auth.org_uuid = 'ypjrtlcE1I2XpTMhWpEhroUOxdOMwxiDqXqJAyg4qpK'
> AND org_auth.state = 0 AND org_auth.creation <=
> '2013-12-21T00:10:00.763479+00:00' AND org_auth.expiration >
> '2013-12-21T00:10:00.763571+00:00' ORDER BY org_auth.creation DESC
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org_auth' AND c.relnamespace = n.oid AND n.nspname =
> 'pg_catalog'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org_auth' AND c.relnamespace = n.oid AND n.nspname ~
> '^pg_temp_'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname
> = 'org_auth' AND c.relpersistence = 'u'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT org_auth.uuid, org_auth.creation, org_auth.expiration,
> org_auth.state, org_auth.org_uuid, org_auth.auth_secret
> FROM org_auth
> WHERE org_auth.org_uuid = 'ypjrtlcE1I2XpTMhWpEhroUOxdOMwxiDqXqJAyg4qpK'
> AND org_auth.state = 0 AND org_auth.creation <=
> '2013-12-21T00:10:00.763479+00:00' AND org_auth.expiration >
> '2013-12-21T00:10:00.763571+00:00' ORDER BY org_auth.creation DESC
> 2013-12-20 19:09:48 LOG: pid 10487: statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: ROLLBACK
> 2013-12-20 19:09:48 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:48 LOG: pid 10487: statement: SELECT org.uuid AS
> org_uuid, org.creation AS org_creation, org.expiration AS
> org_expiration, org.state AS org_state, org.name AS org_name,
> contact.uuid AS contact_uuid, contact.creation AS contact_creation,
> contact.expiration AS contact_expiration, contact.state AS
> contact_state, contact.fingerprint AS contact_fingerprint, contact.class
> AS contact_class, contact.contact AS contact_contact,
> org_to_contact.uuid AS org_to_contact_uuid, org_to_contact.creation AS
> org_to_contact_creation, org_to_contact.expiration AS
> org_to_contact_expiration, org_to_contact.state AS org_to_contact_state,
> org_to_contact.org_uuid AS org_to_contact_org_uuid,
> org_to_contact.contact_uuid AS org_to_contact_contact_uuid
> FROM org, contact, org_to_contact
> WHERE org.uuid = org_to_contact.org_uuid AND contact.uuid =
> org_to_contact.contact_uuid AND org.uuid =
> 'ypjrtlcE1I2XpTMhWpEhroUOxdOMwxiDqXqJAyg4qpK'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'contact' AND c.relnamespace = n.oid AND n.nspname =
> 'pg_catalog'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org_to_contact' AND c.relnamespace = n.oid AND n.nspname =
> 'pg_catalog'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'contact' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE
> c.relname = 'org_to_contact' AND c.relnamespace = n.oid AND n.nspname ~
> '^pg_temp_'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname
> = 'contact' AND c.relpersistence = 'u'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname
> = 'org_to_contact' AND c.relpersistence = 'u'
> 2013-12-20 19:09:48 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: SELECT org.uuid AS org_uuid, org.creation AS org_creation,
> org.expiration AS org_expiration, org.state AS org_state, org.name AS
> org_name, contact.uuid AS contact_uuid, contact.creation AS
> contact_creation, contact.expiration AS contact_expiration,
> contact.state AS contact_state, contact.fingerprint AS
> contact_fingerprint, contact.class AS contact_class, contact.contact AS
> contact_contact, org_to_contact.uuid AS org_to_contact_uuid,
> org_to_contact.creation AS org_to_contact_creation,
> org_to_contact.expiration AS org_to_contact_expiration,
> org_to_contact.state AS org_to_contact_state, org_to_contact.org_uuid AS
> org_to_contact_org_uuid, org_to_contact.contact_uuid AS
> org_to_contact_contact_uuid
> FROM org, contact, org_to_contact
> WHERE org.uuid = org_to_contact.org_uuid AND contact.uuid =
> org_to_contact.contact_uuid AND org.uuid =
> 'ypjrtlcE1I2XpTMhWpEhroUOxdOMwxiDqXqJAyg4qpK'
> 2013-12-20 19:09:49 LOG: pid 10487: statement: ROLLBACK
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: ROLLBACK
> 2013-12-20 19:09:49 LOG: pid 10487: statement: BEGIN; SET TRANSACTION
> ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> 2013-12-20 19:09:49 LOG: pid 10487: statement: UPDATE transaction SET
> expiration='2013-12-21T00:10:00.785848+00:00', state=0 WHERE
> transaction.uuid = 'hTq0do5BElHrojk2tXm4vFCUo32MNbkB6lqTDVDSvs0'
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: UPDATE transaction SET
> expiration='2013-12-21T00:10:00.785848+00:00', state=0 WHERE
> transaction.uuid = 'hTq0do5BElHrojk2tXm4vFCUo32MNbkB6lqTDVDSvs0'
> 2013-12-20 19:09:49 LOG: pid 10487: statement: COMMIT
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: COMMIT
> 2013-12-20 19:09:49 LOG: pid 10487: statement: DISCARD ALL
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 0 backend pid: 11392
> statement: DISCARD ALL
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 1 backend pid: 8744
> statement: DISCARD ALL
> 2013-12-20 19:09:49 LOG: pid 10487: DB node id: 2 backend pid: 2708
> statement: DISCARD ALL
>
>
> Regards!
> On 20/12/13 17:20, Tatsuo Ishii wrote:
>> Does it? It's not what I expected. Can you please show the pgpool log?
>>
>> Best regards,
>> --
>> Tatsuo Ishii
>> SRA OSS, Inc. Japan
>> English: http://www.sraoss.co.jp/index_en.php
>> Japanese: http://www.sraoss.co.jp
>>
>>> But then, why it works when master node is node 0?
>>>
>>> On 20/12/13 01:01, Tatsuo Ishii wrote:
>>>> I see now the source of the problem:
>>>>
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: BEGIN; SET TRANSACTION
>>>>> ISOLATION LEVEL READ COMMITTED
>>>> pgpool-II cannot handle "multi statement queries" (multiple SQL
>>>> statement in single line like this). If pgpool-II finds such a query,
>>>> it sends to the primary node (in your case node 1) regardless the
>>>> contents of the query. So it sends "BEGIN" to node 1, while it does
>>>> not send to node 0. Later on "ROLLBACK" is sent to both node 0 and
>>>> 1. Of course there's no explicit transaction is running on node 0, it
>>>> fails.
>>>>
>>>> If such a query is generated by the flame work, There's not much
>>>> which pgpool-II can do...
>>>>
>>>> Best regards,
>>>> --
>>>> Tatsuo Ishii
>>>> SRA OSS, Inc. Japan
>>>> English: http://www.sraoss.co.jp/index_en.php
>>>> Japanese: http://www.sraoss.co.jp
>>>>
>>>>> I actually don't know too much about the internals of the application.
>>>>> And the problem is when the application is trying to start a connection.
>>>>> (The RollBack are probably internals of sqlalchemy, I really don't know)
>>>>> The only thing I know is that they are using sqlalchemy and flask.
>>>>>
>>>>> Here is the pgppol log about the error:
>>>>> 2013-12-19 20:32:29 LOG: pid 31014: received smart shutdown request
>>>>> 2013-12-19 20:32:30 LOG: pid 4295: pgpool-II successfully started.
>>>>> version 3.3.2 (tokakiboshi)
>>>>> 2013-12-19 20:32:30 LOG: pid 4295: find_primary_node: primary node id is 1
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: SET DATESTYLE TO 'ISO'
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 0 backend pid: 5382
>>>>> statement: BEGIN
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: BEGIN
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 2 backend pid: 16458
>>>>> statement: BEGIN
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 0 backend pid: 5382
>>>>> statement: SET DATESTYLE TO 'ISO'
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: SET DATESTYLE TO 'ISO'
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 2 backend pid: 16458
>>>>> statement: SET DATESTYLE TO 'ISO'
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: COMMIT
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 2 backend pid: 16458
>>>>> statement: COMMIT
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 0 backend pid: 5382
>>>>> statement: COMMIT
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: SHOW client_encoding
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: SHOW client_encoding
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: SHOW
>>>>> default_transaction_isolation
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: SHOW default_transaction_isolation
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: BEGIN; SET TRANSACTION
>>>>> ISOLATION LEVEL READ COMMITTED
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: BEGIN; SET TRANSACTION ISOLATION LEVEL READ COMMITTED
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: select version()
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: select version()
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: select current_schema()
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: select current_schema()
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: show transaction
>>>>> isolation level
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: show transaction isolation level
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: SELECT CAST('test plain
>>>>> returns' AS VARCHAR(60)) AS anon_1
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: SELECT CAST('test
>>>>> unicode returns' AS VARCHAR(60)) AS anon_1
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: statement: ROLLBACK
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 1 backend pid: 9744
>>>>> statement: ROLLBACK
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: DB node id: 0 backend pid: 5382
>>>>> statement: ROLLBACK
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: pool_send_and_wait: Error or notice
>>>>> message from backend: : DB node id: 0 backend pid: 5382 statement:
>>>>> ROLLBACK message: there is no transaction in progress
>>>>> 2013-12-19 20:35:16 ERROR: pid 4328: read_kind_from_backend: 1 th kind C
>>>>> does not match with master or majority connection kind N
>>>>> 2013-12-19 20:35:16 ERROR: pid 4328: kind mismatch among backends.
>>>>> Possible last query was: "ROLLBACK" kind details are: 0[N: there is no
>>>>> transaction in progress] 1[C]
>>>>> 2013-12-19 20:35:16 LOG: pid 4328: do_child: exits with status 1 due
>>>>> to error
>>>>>
>>>>> And here is the stack trace:
>>>>> 2013-12-19 20:35:25,080 - application.flaskapp - ERROR - kind mismatch
>>>>> among backends. Possible last query was: "ROLLBACK" kind details are:
>>>>> 0[N: there is no transaction in progress] 1[C]
>>>>> HINT: check data consistency among db nodes
>>>>> ERROR: kind mismatch among backends. Possible last query was:
>>>>> "ROLLBACK" kind details are: 0[N: there is no transaction in progress] 1[C]
>>>>> HINT: check data consistency among db nodes
>>>>> Traceback (most recent call last):
>>>>> File
>>>>> "/usr/lib/python2.6/site-packages/application/server/flaskapp.py", line
>>>>> 34, in __init__
>>>>> self._init_db()
>>>>> File "/usr/lib/python2.6/site-packages/application/server/orgtool.py",
>>>>> line 47, in _init_db
>>>>> self.db = ApplicationMutableDb(self.config)
>>>>> File "/usr/lib/python2.6/site-packages/application/server/db.py", line
>>>>> 1014, in __init__
>>>>> ApplicationAppendDb.__init__(self, *args, **kwargs)
>>>>> File "/usr/lib/python2.6/site-packages/application/server/db.py", line
>>>>> 937, in __init__
>>>>> ApplicationQueryDb.__init__(self, *args, **kwargs)
>>>>> File "/usr/lib/python2.6/site-packages/application/server/db.py", line
>>>>> 234, in __init__
>>>>> BaseDb.__init__(self, *args, **kwargs)
>>>>> File "/usr/lib/python2.6/site-packages/application/server/db.py", line
>>>>> 192, in __init__
>>>>> self.db_conn()
>>>>> File "/usr/lib/python2.6/site-packages/application/server/db.py", line
>>>>> 216, in db_conn
>>>>> self.conn = self.engine.connect()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/base.py",
>>>>> line 2322, in connect
>>>>> return self._connection_cls(self, **kwargs)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/base.py",
>>>>> line 872, in __init__
>>>>> self.__connection = connection or engine.raw_connection()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/base.py",
>>>>> line 2408, in raw_connection
>>>>> return self.pool.unique_connection()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 169,
>>>>> in unique_connection
>>>>> return _ConnectionFairy(self).checkout()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 371,
>>>>> in __init__
>>>>> rec = self._connection_record = pool._do_get()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 758,
>>>>> in _do_get
>>>>> return self._create_connection()
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 174,
>>>>> in _create_connection
>>>>> return _ConnectionRecord(self)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 259,
>>>>> in __init__
>>>>> pool.dispatch.first_connect.exec_once(self.connection, self)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/event.py", line 265,
>>>>> in exec_once
>>>>> self(*args, **kw)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/event.py", line 274,
>>>>> in __call__
>>>>> fn(*args, **kw)
>>>>> File
>>>>> "/usr/lib/python2.6/site-packages/sqlalchemy/engine/strategies.py", line
>>>>> 166, in first_connect
>>>>> dialect.initialize(c)
>>>>> File
>>>>> "/usr/lib/python2.6/site-packages/sqlalchemy/dialects/postgresql/base.py",
>>>>> line 977, in initialize
>>>>> super(PGDialect, self).initialize(connection)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/default.py",
>>>>> line 187, in initialize
>>>>> self.do_rollback(connection.connection)
>>>>> File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/default.py",
>>>>> line 299, in do_rollback
>>>>> connection.rollback()
>>>>> InternalError: kind mismatch among backends. Possible last query was:
>>>>> "ROLLBACK" kind details are: 0[N: there is no transaction in progress] 1[C]
>>>>> HINT: check data consistency among db nodes
>>>>> ERROR: kind mismatch among backends. Possible last query was:
>>>>> "ROLLBACK" kind details are: 0[N: there is no transaction in progress] 1[C]
>>>>> HINT: check data consistency among db nodes
>>>>>
>>>>> 2013-12-19 20:35:25,085 - application - ERROR - Action failed: 500:
>>>>> Internal Server Error
>>>>> Traceback (most recent call last):
>>>>> File "./orgtool", line 65, in main
>>>>> org = self._get_orgtool(options.confbase)
>>>>> File "./orgtool", line 19, in _get_orgtool
>>>>> org = orgtool.OrgTool(confbase)
>>>>> File "/usr/lib/python2.6/site-packages/application/server/orgtool.py",
>>>>> line 41, in __init__
>>>>> BaseServer.__init__(self, environ, os.path.join(confbase,
>>>>> ".application"))
>>>>> File
>>>>> "/usr/lib/python2.6/site-packages/application/server/flaskapp.py", line
>>>>> 37, in __init__
>>>>> raise wzex.InternalServerError("DATABASE CONNECTION FAILED")
>>>>>
>>>>> On 19/12/13 17:28, Tatsuo Ishii wrote:
>>>>>>> Hi.
>>>>>>>
>>>>>>> It wasn't installed, but I installed it and had the same result.
>>>>>> Can you show the PostgreSQL around "ROLLBACK"?
>>>>>>
>>>>>>> By the way, to install it I just need to execute this right?
>>>>>>> CREATE EXTENSION pgpool_regclass;
>>>>>> Yes.
>>>>>>
>>>>>> Best regards,
>>>>>> --
>>>>>> Tatsuo Ishii
>>>>>> SRA OSS, Inc. Japan
>>>>>> English: http://www.sraoss.co.jp/index_en.php
>>>>>> Japanese: http://www.sraoss.co.jp
>>>>>>
>>>>>>> On 18/12/13 18:17, Tatsuo Ishii wrote:
>>>>>>>> Have you installed pgpool_regclass?
>>>>>>>>
>>>>>>>> Best regards,
>>>>>>>> --
>>>>>>>> Tatsuo Ishii
>>>>>>>> SRA OSS, Inc. Japan
>>>>>>>> English: http://www.sraoss.co.jp/index_en.php
>>>>>>>> Japanese: http://www.sraoss.co.jp
>>>>>>>>
>>>>>>>>> Hi everyone.
>>>>>>>>>
>>>>>>>>> I'm having an issue with pgpool.
>>>>>>>>> First of all my configuration:
>>>>>>>>> 1 Server with pgpool-II version 3.3.2 (tokakiboshi)
>>>>>>>>> 3 Servers with:
>>>>>>>>> postgresql93-contrib-9.3.2-1PGDG.rhel6.x86_64
>>>>>>>>> postgresql93-devel-9.3.2-1PGDG.rhel6.x86_64
>>>>>>>>> postgresql93-libs-9.3.2-1PGDG.rhel6.x86_64
>>>>>>>>> postgresql93-9.3.2-1PGDG.rhel6.x86_64
>>>>>>>>> postgresql93-server-9.3.2-1PGDG.rhel6.x86_64
>>>>>>>>>
>>>>>>>>> All 4 servers are RHEL 6 machines. (Amazon AMI's actually)
>>>>>>>>>
>>>>>>>>> Pgpool is configured to have Master/Slave Nodes with replication
>>>>>>>>> and Load Balancing.
>>>>>>>>>
>>>>>>>>> #------------------------------------------------------------------------------
>>>>>>>>> # LOAD BALANCING MODE
>>>>>>>>> #------------------------------------------------------------------------------
>>>>>>>>>
>>>>>>>>> load_balance_mode = on
>>>>>>>>> # Activate load balancing mode
>>>>>>>>> # (change requires restart)
>>>>>>>>> ignore_leading_white_space = on
>>>>>>>>> # Ignore leading white spaces of each
>>>>>>>>> query
>>>>>>>>> white_function_list = ''
>>>>>>>>> # Comma separated list of function names
>>>>>>>>> # that don't write to database
>>>>>>>>> # Regexp are accepted
>>>>>>>>> black_function_list = 'nextval,setval'
>>>>>>>>> # Comma separated list of function names
>>>>>>>>> # that write to database
>>>>>>>>> # Regexp are accepted
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> #------------------------------------------------------------------------------
>>>>>>>>> # MASTER/SLAVE MODE
>>>>>>>>> #------------------------------------------------------------------------------
>>>>>>>>>
>>>>>>>>> master_slave_mode = on
>>>>>>>>> # Activate master/slave mode
>>>>>>>>> # (change requires restart)
>>>>>>>>> master_slave_sub_mode = 'stream'
>>>>>>>>> # Master/slave sub mode
>>>>>>>>> # Valid values are combinations slony or
>>>>>>>>> # stream. Default is slony.
>>>>>>>>> # (change requires restart)
>>>>>>>>>
>>>>>>>>> # - Streaming -
>>>>>>>>>
>>>>>>>>> sr_check_period = 1
>>>>>>>>> # Streaming replication check period
>>>>>>>>> # Disabled (0) by default
>>>>>>>>> sr_check_user = 'postgres'
>>>>>>>>> # Streaming replication check user
>>>>>>>>> # This is necessary even if you disable
>>>>>>>>> # streaming replication delay check with
>>>>>>>>> # sr_check_period = 0
>>>>>>>>> sr_check_password = ''
>>>>>>>>> # Password for streaming replication
>>>>>>>>> check user
>>>>>>>>> delay_threshold = 1
>>>>>>>>> # Threshold before not dispatching
>>>>>>>>> query to standby node
>>>>>>>>> # Unit is in bytes
>>>>>>>>> # Disabled (0) by default
>>>>>>>>>
>>>>>>>>> # - Special commands -
>>>>>>>>>
>>>>>>>>> follow_master_command = '/bin/follow_master.sh %d %h %D %m %H %R'
>>>>>>>>> # Executes this command after master
>>>>>>>>> failover
>>>>>>>>> # Special values:
>>>>>>>>> # %d = node id
>>>>>>>>> # %h = host name
>>>>>>>>> # %p = port number
>>>>>>>>> # %D = database cluster path
>>>>>>>>> # %m = new master node id
>>>>>>>>> # %H = hostname of the new master node
>>>>>>>>> # %M = old master node id
>>>>>>>>> # %P = old primary node id
>>>>>>>>> # %r = new master port number
>>>>>>>>> # %R = new master database cluster path
>>>>>>>>> # %% = '%' character
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> #All three nodes are configured like this
>>>>>>>>> backend_hostnamen = 'ip_node_n'
>>>>>>>>> backend_portn = 5432
>>>>>>>>> backend_weightn = 0
>>>>>>>>> backend_data_directoryn = '/var/lib/pgsql/9.3/data/'
>>>>>>>>> backend_flagn = 'ALLOW_TO_FAILOVER'
>>>>>>>>>
>>>>>>>>> I'm using repmgr to handle the replication in the nodes.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> My problem occurs when I kill the master node, everything works as
>>>>>>>>> expected and a slave takes it's place.
>>>>>>>>> My application continues working with no major issues until I decide to
>>>>>>>>> recover the dead master node.
>>>>>>>>>
>>>>>>>>> After that pgool starts sending this message:
>>>>>>>>> 2013-12-18 17:19:07 LOG: pid 30801: do_child: exits with status 1 due
>>>>>>>>> to error
>>>>>>>>> 2013-12-18 17:19:10 LOG: pid 30802: pool_send_and_wait: Error or
>>>>>>>>> notice message from backend: : DB node id: 0 backend pid: 27585
>>>>>>>>> statement: ROLLBACK message: there is no transaction in progress
>>>>>>>>> 2013-12-18 17:19:10 ERROR: pid 30802: read_kind_from_backend: 1 th kind
>>>>>>>>> C does not match with master or majority connection kind N
>>>>>>>>> 2013-12-18 17:19:10 ERROR: pid 30802: kind mismatch among backends.
>>>>>>>>> Possible last query was: "ROLLBACK" kind details are: 0[N: there is no
>>>>>>>>> transaction in progress] 1[C]
>>>>>>>>>
>>>>>>>>> And I identified that the problem is that pgpool is sending a rollback
>>>>>>>>> to the old master node [node 0] (Something illegal as far as I know) and
>>>>>>>>> then all the transaction is cancelled and my application fails.
>>>>>>>>> If I promote the old master again, then the application works with no
>>>>>>>>> problem.
>>>>>>>>>
>>>>>>>>> Anyone has an idea why is this ocurring?
>>>>>>>>>
>>>>>>>>> Regards!
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Be aware that if you reply directly to this message, your reply may not be
>>>>>>>>> secure. Do not send us communications that contain unencrypted confidential
>>>>>>>>> information such as passwords, account numbers, or Social Security numbers.
>>>>>>>>>
>>>>>>>>> This message, including any attachments, is for the sole use of the
>>>>>>>>> intended recipient(s) and may contain confidential and privileged
>>>>>>>>> information. If you are not the intended recipient, please destroy all
>>>>>>>>> copies of this message and any attachments. In addition, please notify
>>>>>>>>> Gazzang immediately by email to info at gazzang.com.
>>>>>>>>> _______________________________________________
>>>>>>>>> pgpool-general mailing list
>>>>>>>>> pgpool-general at pgpool.net
>>>>>>>>> http://www.pgpool.net/mailman/listinfo/pgpool-general
>>>>>>> --
>>>>>>>
>>>>>>>
>>>>>>> Be aware that if you reply directly to this message, your reply may not be
>>>>>>> secure. Do not send us communications that contain unencrypted confidential
>>>>>>> information such as passwords, account numbers, or Social Security numbers.
>>>>>>>
>>>>>>> This message, including any attachments, is for the sole use of the
>>>>>>> intended recipient(s) and may contain confidential and privileged
>>>>>>> information. If you are not the intended recipient, please destroy all
>>>>>>> copies of this message and any attachments. In addition, please notify
>>>>>>> Gazzang immediately by email to info at gazzang.com.
>>>>> --
>>>>>
>>>>>
>>>>> Be aware that if you reply directly to this message, your reply may not be
>>>>> secure. Do not send us communications that contain unencrypted confidential
>>>>> information such as passwords, account numbers, or Social Security numbers.
>>>>>
>>>>> This message, including any attachments, is for the sole use of the
>>>>> intended recipient(s) and may contain confidential and privileged
>>>>> information. If you are not the intended recipient, please destroy all
>>>>> copies of this message and any attachments. In addition, please notify
>>>>> Gazzang immediately by email to info at gazzang.com.
>>>
>>> --
>>>
>>>
>>> Be aware that if you reply directly to this message, your reply may not be
>>> secure. Do not send us communications that contain unencrypted confidential
>>> information such as passwords, account numbers, or Social Security numbers.
>>>
>>> This message, including any attachments, is for the sole use of the
>>> intended recipient(s) and may contain confidential and privileged
>>> information. If you are not the intended recipient, please destroy all
>>> copies of this message and any attachments. In addition, please notify
>>> Gazzang immediately by email to info at gazzang.com.
>
>
> --
>
>
> Be aware that if you reply directly to this message, your reply may not be
> secure. Do not send us communications that contain unencrypted confidential
> information such as passwords, account numbers, or Social Security numbers.
>
> This message, including any attachments, is for the sole use of the
> intended recipient(s) and may contain confidential and privileged
> information. If you are not the intended recipient, please destroy all
> copies of this message and any attachments. In addition, please notify
> Gazzang immediately by email to info at gazzang.com.
More information about the pgpool-general
mailing list