View Issue Details

IDProjectCategoryView StatusLast Update
0000531Pgpool-IIBugpublic2019-09-11 09:18
ReporterpodogAssigned Tot-ishii 
PrioritynormalSeverityminorReproducibilitysometimes
Status closedResolutionopen 
PlatformLinuxOSCentOSOS Version7.6.1810
Product Version3.7.7 
Target Version3.7.11Fixed in Version3.7.11 
Summary0000531: FATAL: unable to bind occurs
DescriptionHello,

The following content is output to pgpool.log.
I am in trouble without knowing the cause.

ex)
2019-07-31 09:35:09: pid 15415: FATAL: unable to bind
2019-07-31 09:35:09: pid 15415: DETAIL: cannot get parse message "S_24"

The numbers after "S_" are not fixed.

ex)
S_10, S_13, S_15, S_30, S_38, S_44, S_47 ...

What causes it?
Also, please let me know if there is any other necessary information for the survey.

Attached pgpool.log.

Regards.
Steps To Reproduceunknown
Additional InformationPostgreSQL : 10.6
Tagspgpool-II

Activities

podog

2019-07-31 17:00

reporter  

pgpool.zip (54,239 bytes)

t-ishii

2019-08-01 09:18

developer   ~0002742

3.6.7 is way too old (released almost 2 years ago). Can you please try the latest version?

podog

2019-08-01 09:21

reporter   ~0002743

We use 3.7.7.
Not 3.6.7.

t-ishii

2019-08-01 09:38

developer   ~0002744

OK. "S_24" and others are the names of prepared statements, which are generated by JDBC driver. Pgpool-II needs to remember them to process "bind" message from the driver but it seems Pgpool-II fails to find it. To look for the cause, unfortunately the log is not very helpful . If you were using 4.0, there's a new feature to allow to log what the driver sends to Pgpool-II. With 3.7 or before, the only way to take the log is setting log_min_messages = debug5, which will produce huge log. Is it possible to share the debug log?

podog

2019-08-01 11:36

reporter   ~0002745

Thank you for your advice.
I will consider changing logging settings, but it may be difficult to implement immediately.
I will contact you when the log is output.

podog

2019-08-05 15:10

reporter   ~0002746

I set "log_min_messages = debug5".
It became a huge log. I will attach the log.
Please check log.
The host name and SQL are hidden.

pgpool-2.zip (159,878 bytes)

t-ishii

2019-08-06 17:23

developer   ~0002748

Can you share pgpool.conf?

podog

2019-08-06 17:39

reporter   ~0002749

I will attach the pgpool.conf.
The host name, user, ip address and password are hidden.

pgpoolconf.zip (7,320 bytes)

t-ishii

2019-08-06 20:20

developer   ~0002750

I noticed that some of logs are strange.

2019-08-02 09:44:39: pid 28463: DEBUG: Execute: query string = <ds_code AS T1_C28,xxx_xxxxxxxx.xxxxxxx_xxxxxxx_xxxxxx_code AS T1_C29,xxx_xxxxxxxx.xxxxxxx_xxxxxx_flg AS T1_C30,xxx_xxxxxxxx.xxxxxxx_xxxxxx_start AS T1_C31,xxx_xxxxxxxx.purchased_time_end AS T1...

This does not look a proper SQL. Are they real log or did you edit part of the log?

podog

2019-08-07 08:31

reporter   ~0002751

Yes, the table name and column name is hidden.
I dare to hide.
Do you suggest that there may be a problem with the SQL itself?

t-ishii

2019-08-07 09:21

developer   ~0002752

I understand you want to hide table names etc. That's fine. My questions is, no SQL starts with something like: "ds_code AS T1_C28...". In my understanding SQL usually starts with SELECT, INSER, UPDATE, DELETE, WITH etc. Do you want to hide them? Then it's hard to analyze the issue.

podog

2019-08-07 10:05

reporter   ~0002753

Thank you for check the log file and the pgpool.conf.
I checked the contents of the origin log file.
This is my guess, it looks like a continuation of the SQL in the line above.
In the line above starts with a SELECT statement.
I think that the log could not be output with one line.

t-ishii

2019-08-07 11:35

developer   ~0002754

Can you share the part of original log (SQL was divided by a new line)? You can hide tables names etc. of course.

t-ishii

2019-08-09 17:29

developer   ~0002764

I think I fix the problem. It was caused by a bug of Pgpool-II. The reason why it does not reliably reproduce was, the bug was related to overly freed memory. So depending on the memory pressure, the bug may or may not occur.

The commit for 3.7 series is here:
https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=c896d21fb67ca0f649fd48c55017f4a6f9407d01

We also plan to push minor releases including 3.7 on 15th this month. You can wait for that if you like.

podog

2019-08-09 17:55

reporter   ~0002765

Thank you for your comment.
I was late to contact, but since the log about pgpool was output to / var / log / messages, it shares.

Aug 9 09:36:12 (hostname) kernel: pgpool [15389]: segfault at 1674420 ip 0000000000427d27 sp 00007ffd897b56e8 error 4 in pgpool [400000 + 14e000]

Is it related to the bug you fixed?

t-ishii

2019-08-09 21:44

developer   ~0002766

I assume you are seeing the log with unfixed Pgpool-II (3.7.7).

> Is it related to the bug you fixed?

Yes, I think so. The bug I found make Pgpool-II accesses freed memory, and it could cause random problem including segfault.

podog

2019-08-13 11:56

reporter   ~0002774

Thank you for your answer.
I will consider install the latest version of the Pgpool-II.
(3.7.11)

t-ishii

2019-08-15 09:08

developer   ~0002782

Looking forward to hearing from after you upgrade to 3.7.11.

podog

2019-09-10 09:25

reporter   ~0002828

Hello,

I apologized late your contact.
I install Pgpool-II 3.7.11(source) on test server.
It seems to not issue.
But, the environment provided to customers has more user access and higher load.
If we don't install it in that environment, we won't be able to determine if the problem is resolved.

Thank you.

t-ishii

2019-09-10 17:14

developer   ~0002829

Do you have a plan to install 3.7.11 to the customers environment? If yes, you can keep this issue open up to 1 month. If no, you can close this issue for now and reopen later if needed.

podog

2019-09-10 17:54

reporter   ~0002830

Yes, we have a plan to install 3.7.11, but install date does not decide yet.
So, please this issue close.

t-ishii

2019-09-11 09:17

developer   ~0002831

Thank you for your understanding. I am going to close this issue.

Issue History

Date Modified Username Field Change
2019-07-31 17:00 podog New Issue
2019-07-31 17:00 podog File Added: pgpool.zip
2019-07-31 17:00 podog Tag Attached: pgpool-II
2019-08-01 09:16 t-ishii Assigned To => t-ishii
2019-08-01 09:16 t-ishii Status new => assigned
2019-08-01 09:18 t-ishii Note Added: 0002742
2019-08-01 09:19 t-ishii Status assigned => feedback
2019-08-01 09:19 t-ishii Description Updated View Revisions
2019-08-01 09:21 podog Note Added: 0002743
2019-08-01 09:21 podog Status feedback => assigned
2019-08-01 09:38 t-ishii Note Added: 0002744
2019-08-01 09:38 t-ishii Status assigned => feedback
2019-08-01 11:36 podog Note Added: 0002745
2019-08-01 11:36 podog Status feedback => assigned
2019-08-05 15:10 podog File Added: pgpool-2.zip
2019-08-05 15:10 podog Note Added: 0002746
2019-08-06 17:23 t-ishii Note Added: 0002748
2019-08-06 17:39 podog File Added: pgpoolconf.zip
2019-08-06 17:39 podog Note Added: 0002749
2019-08-06 20:20 t-ishii Note Added: 0002750
2019-08-07 08:31 podog Note Added: 0002751
2019-08-07 09:21 t-ishii Note Added: 0002752
2019-08-07 10:05 podog Note Added: 0002753
2019-08-07 11:35 t-ishii Note Added: 0002754
2019-08-09 10:32 t-ishii Status assigned => feedback
2019-08-09 17:29 t-ishii Note Added: 0002764
2019-08-09 17:39 t-ishii Target Version => 3.7.11
2019-08-09 17:55 podog Note Added: 0002765
2019-08-09 17:55 podog Status feedback => assigned
2019-08-09 21:44 t-ishii Note Added: 0002766
2019-08-11 07:36 t-ishii Status assigned => feedback
2019-08-13 11:56 podog Note Added: 0002774
2019-08-13 11:56 podog Status feedback => assigned
2019-08-15 09:08 t-ishii Note Added: 0002782
2019-08-15 09:08 t-ishii Status assigned => feedback
2019-08-15 19:13 administrator Fixed in Version => 3.7.11
2019-09-10 09:25 podog Note Added: 0002828
2019-09-10 09:25 podog Status feedback => assigned
2019-09-10 17:14 t-ishii Note Added: 0002829
2019-09-10 17:14 t-ishii Status assigned => feedback
2019-09-10 17:54 podog Note Added: 0002830
2019-09-10 17:54 podog Status feedback => assigned
2019-09-11 09:17 t-ishii Note Added: 0002831
2019-09-11 09:18 t-ishii Status assigned => closed