View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000317 | Pgpool-II | Bug | public | 2017-06-26 22:34 | 2017-08-29 09:27 |
| Reporter | whiskerp | Assigned To | t-ishii | ||
| Priority | normal | Severity | major | Reproducibility | sometimes |
| Status | closed | Resolution | open | ||
| Platform | Linux | OS | Redhat | OS Version | 7.3 |
| Product Version | 3.6.4 | ||||
| Target Version | 3.6.5 | ||||
| Summary | 0000317: pgpool sometimes fails to return a "Ready for query" causing client to hang. | ||||
| Description | This has been seen in the startup sequence of Apache ActiveMQ - this client attempts to create the database tables and indexes every time it starts (causing transaction errors). Most of the time, one of the startup transactions will hang waiting for a "Ready for Query" (Z) PDU. Postgres provides this PDU to pgpool but pgpool never passes it on. Occasionally the startup succeeds. Postgres 9.6 backend is correcty completing the transaction with a "Ready for Query" but pgpool frontend is not passing this back to the client. I have shut down the second configured node for clarity, however the same problem happens even with it running. | ||||
| Steps To Reproduce | Attempt to start up Apache ActiveMQ ! | ||||
| Additional Information | Two "pcap" files attached and the system log with debug5 set. - In pgpool-192.pcap, the packet starting the query which results in the missing "Ready for query" is packet 255. - In pgpool-lo.pcap, the same start of transaction on the backend is packet 224. - In the system log, the transaction is the last one logged at 12:40:40. pgpool.conf is attached. | ||||
| Tags | No tags attached. | ||||
|
|
|
|
|
Sorry - In the system log, the transaction is the last one logged at 12:48:40 and not as stated. |
|
|
Apache ActiveMQ is written in Java. JDBC debug log will help a lot. |
|
|
Hi ActiveMQ works perfectly against Postgres 9.6 alone. However putting the transactions through pgpool fails. The logs I have already attached prove that the problem lies with pgpool not sending a "Ready for Query" back to the client at the end of one of the transactions. I have enabled JDBC logging in log4j but the logs show little more than one of the transactions failing to complete which confirms the behaviour seen in the pcap traces. Thanks Peter |
|
|
I have added some more logs. activemq1.log covers the time period of the original logs filed in this report. I had already selected DEBUG for JDBC. I have re-run the tets - this time it went further before it hung. Every time, the cause is due to pgpool not sending a "Ready for Query" at the end of a transaction which posted an error. In every case, Postgresql 9.6 itself *does* send a "Ready for Query". |
|
|
activemq1.log and activemq2.log do not seem to be useful because JDBC driver level debug is not enabled. If it were, you should see something like: Start test iteration '0' DriverManager.getConnection("jdbc:postgresql://localhost:11000/test?loglevel=2") trying org.postgresql.Driver 18:59:20.824 (1) PostgreSQL 9.4.1212.jre7 18:59:20.833 (1) Trying to establish a protocol version 3 connection to localhost:11000 18:59:20.850 (1) Receive Buffer Size is 530904 18:59:20.850 (1) Send Buffer Size is 1313280 18:59:20.854 (1) FE=> StartupPacket(user=t-ishii, database=test, client_encoding=UTF8, DateStyle=ISO, TimeZone=Asia/Tokyo, extra_float_digits=2) 18:59:20.854 (1) <=BE AuthenticationOk 18:59:20.873 (1) <=BE BackendKeyData(pid=26719,ckey=2078375336) 18:59:20.873 (1) <=BE ParameterStatus(application_name = ) 18:59:20.873 (1) <=BE ParameterStatus(client_encoding = UTF8) 18:59:20.873 (1) <=BE ParameterStatus(DateStyle = ISO, MDY) 18:59:20.873 (1) <=BE ParameterStatus(integer_datetimes = on) pgpool2.log is not useful either because debug option of Pgpool-II is not enabled. |
|
|
I have run pgpool with -n -d switches and saved the debug log as pgpool.log. I have obtained the newest postgresql-42.1.1.jar JDBC and enabled loggingLevel 2 (the maximum). The output is in java0.log. I have also included the activemq.log which has JDBC set to debug. The fault is reproduced - the last message received by JDBC is an "ErrorMessage". There is no "Ready for Query" received from PGPOOL to complete the statement. I have zipped the files. |
|
|
Thanks for the data. I was able to reproduce the problem by issuing following sequence of messages: Parse (CREATE INDEX) Bind Describe Sync (CREATE INDEX returns an error because it's a duplicate index). Will fix when I have time. BTW, why are you trying to create the duplicated index? ActiveMQ is broken? |
|
|
I was wrong. I was not able to reproduce the problem. Will try again if I can think of any idea how to reproduce the problem... |
|
|
Hi It's not a specific transaction which seems to cause the issue, it's only caused by Error transactions as far as I can see and it doesn't always happen. I have had a few cases where it has got through the initial error-causing transactions and then runs normally. We also run OpenNMS and that works normally. It's just the burst of error-causing transactions at the start of ActiveMQ which seems to cause the issue. Sometimes its the CREATE TABLE, sometimes the CREATE INDEX, sometimes and ALTER TABLE. The common factor is that they all cause error transactions because the tables are already created or have some constraints already set which cause the errors. This is just how ActiveMQ works unfortunately. It is a free product and needs little configuration other than setting up the datasource. The setup details I have used is here: https://www.linkedin.com/pulse/activemq-configure-postgresql-message-persistence-syed-shabbir. So perhaps installing the product and attempting to restart it will be the easiest way to recreate the problem. The release is at http://activemq.apache.org/activemq-5145-release.html Thanks, Peter |
|
|
Recently similar report (bug#318 https://www.pgpool.net/mantisbt/view.php?id=318) was sent. I did some investigations last weekend and created a patch. It has been posted to the pgpool-general mailing list. I attached the patch here. Please try. |
|
|
|
|
|
Thanks - I have passed to a colleague for testing and will respond once I hear from him. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2017-06-26 22:34 | whiskerp | New Issue | |
| 2017-06-26 22:34 | whiskerp | File Added: pgpool-lo.pcap | |
| 2017-06-26 22:34 | whiskerp | File Added: pgpool-192.pcap | |
| 2017-06-26 22:34 | whiskerp | File Added: pgpool.conf | |
| 2017-06-26 22:34 | whiskerp | File Added: syslog | |
| 2017-06-26 22:38 | whiskerp | Note Added: 0001548 | |
| 2017-06-27 08:39 | t-ishii | Note Added: 0001549 | |
| 2017-06-27 16:57 | whiskerp | Note Added: 0001550 | |
| 2017-06-27 18:15 | whiskerp | File Added: activemq1.log | |
| 2017-06-27 18:15 | whiskerp | File Added: pgpool2.log | |
| 2017-06-27 18:15 | whiskerp | File Added: activemq2.log | |
| 2017-06-27 18:15 | whiskerp | Note Added: 0001551 | |
| 2017-06-28 10:10 | t-ishii | Note Added: 0001553 | |
| 2017-06-28 23:39 | whiskerp | File Added: ActiveMq.zip | |
| 2017-06-28 23:39 | whiskerp | Note Added: 0001558 | |
| 2017-06-29 07:19 | t-ishii | Assigned To | => t-ishii |
| 2017-06-29 07:19 | t-ishii | Status | new => assigned |
| 2017-06-29 07:19 | t-ishii | Note Added: 0001559 | |
| 2017-06-29 17:32 | t-ishii | Note Added: 0001560 | |
| 2017-06-29 18:56 | whiskerp | Note Added: 0001561 | |
| 2017-07-19 13:55 | t-ishii | Note Added: 0001583 | |
| 2017-07-19 13:56 | t-ishii | File Added: pgpool-hung.diff | |
| 2017-07-19 13:57 | t-ishii | Status | assigned => feedback |
| 2017-07-19 16:40 | whiskerp | Note Added: 0001592 | |
| 2017-07-19 16:40 | whiskerp | Status | feedback => assigned |
| 2017-07-19 16:46 | t-ishii | Status | assigned => feedback |
| 2017-07-19 16:46 | t-ishii | Target Version | => 3.6.5 |
| 2017-08-29 09:27 | pengbo | Status | feedback => closed |
