View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000014Pgpool-IIBugpublic2012-05-15 04:062012-10-05 18:06
Reportersingh.gurjeet Assigned Tot-ishii  
PriorityhighSeveritymajorReproducibilitysometimes
Status resolvedResolutionfixed 
Summary0000014: pgpool beeaks unnamed prepared statements used by the application
DescriptionHi,

    We have had reports of come of our customers facing this problem, and my analysis [1] shows that this is pgpool's fault.

    Here's a summary of the problem:
1) Application issues 'prepare' operation to parse/prepare a SQL statement.

2) Postgres prepares the statement and creates an unnamed portal for it.

3) pgpool issues its own query, say a 'select count(*) from pg_class...'

4) Postgres drops the unnamed portal it created in step 2 and processes pgpool's query.

5) Application issues 'bind' operation to bind the values to the statement it prepared in step 1.

6) Postgres (correctly) throws the error:
ERROR: 26000: unnamed prepared statement does not exist
LOCATION: exec_bind_message, postgres.c:1444


IMHO, pgpool should be fixed so that it does not execute any queries of its own as long as the application is using an unnamed prepared statement.

Please note that this fix is not needed when the application is using *named* prepared statements.

Regards,

[1] http://forums.enterprisedb.com/posts/list/3126.page#11679
TagsNo tags attached.

Activities

t-ishii

2012-05-22 18:53

developer   ~0000029

I think your analsys is correct but do not agree with the solution you suggested. Probably pgpool should issue internal queries by using extended protocol with named statements, rather than using simple protocol since the later breaks unamed statements (and portals) which may be used by the client.

singh.gurjeet

2012-05-22 23:27

reporter   ~0000030

That's a good idea!

But what if the client is using simple protocol? Can Postgres handle mixed protocol?

I mean, can Postgres handle the scenario where pgpool forwards the simple protocol messages from the client as is, and sends its own queries using extended protocol?

t-ishii

2012-05-23 08:31

developer   ~0000031

Of course. As long as we strictly keep the command boundary as the protocol requires. For example, we can issue new qury before or after Q(uery)->R(owDescription)->D(ataRow)->C(omandCommpelete)->R(eadyForQueyr) cycle.

t-ishii

2012-06-03 16:48

developer   ~0000033

Is the user running in pgpool-II native replication mode? I think the case pgpool sends internal queries anything after parse is only replication mode. I need to confirm this idea to fix the problem.

t-ishii

2012-06-03 22:04

developer   ~0000034

I think I have fixed the issue by using the method I proposed. See:
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=afcf2505745bd19bfbd9b38149199e84b667d65a

singh.gurjeet

2012-06-06 01:03

reporter   ~0000035

Can you please confirm if this fix will be available in next minor release, or a major release?

Regards,

t-ishii

2012-06-06 16:19

developer   ~0000036

It has been already committed in the stable releases and will be in next minor release. It would be great if you could grab the git snapshot and test it before the official release. I would like to make sure that the fix actualy solve your customers problem.

Ashish Nauriyal

2012-07-23 02:46

reporter   ~0000039

I faced following issue in master database server log with latest pgpool-II3.2RC1:

10478 2012-07-21 13:54:20.094 IST LOG: execute pgpool4521/pgpool4521: SELECT count(*) FROM pg_catalog.pg_proc AS p WHERE p.proname = 'pgpool_regclass'
13:54:20.094 IST LOG: duration: 0.142 ms
13:54:20.095 IST ERROR: portal "" does not exist
13:54:20.114 IST LOG: duration: 0.067 ms
13:54:20.115 IST LOG: duration: 0.018 ms


And app server says: [#|2012-07-21T14:09:41.329+0530|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=19;_ThreadName=httpSSLWorkerThread-38080-1;|
Error SQL Common DBSelect : select as_usm_user_type,as_usm_fname,as_usm_stockingpoint_access from as_user_master where as_usm_emp_uid ='admin' ERROR: portal "" does not exist|#]

Is this the same issue as above ?

ryansanders

2012-08-16 02:50

reporter   ~0000041

I am seeing similar errors in 3.2.0 Final:

2012-08-15 17:29:07 LOG: pid 19669: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 22259 statement: select this_.optionid as optionid12_0_, this_.valueid as valueid12_0_, this_.gameid as gameid12_0_, this_.optiontype as optiontype12_0_, this_.option as option12_0_, this_.validfor as validfor12_0_, this_.value as value12_0_, this_.optionsequenceid as optionse8_12_0_, this_.valuesequenceid as valueseq9_12_0_, this_.parent as parent12_0_, this_.customType as customType12_0_ from public.gameoptions this_ where this_.gameid=$1 and this_.optionid=$2 and this_.valueid=$3 and this_.optiontype=$4 message: portal "" does not exist
2012-08-15 17:29:17 LOG: pid 19669: pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 24187 statement: select playernetw0_.playerid as playerid1_, playernetw0_.playernetworkid as playerne1_1_, playernetw0_.networkid as networkid1_, playernetw0_.playernetworkid as playerne1_26_0_, playernetw0_.networkid as networkid26_0_, playernetw0_.playerid as playerid26_0_, playernetw0_.playernetworktag as playerne4_26_0_, playernetw0_.creationdate as creation5_26_0_, playernetw0_.lastupdatedate as lastupda6_26_0_ from public.playernetwork playernetw0_ where playernetw0_.playerid=$1 message: bind message supplies 1 parameters, but prepared statement "" requires 4

I am assuming this relates to the above. Is there an ETA for a fix, or perhaps any pgpool related work-arounds in the works?

If there is more information that would be helpful, please let me know.

t-ishii

2012-08-16 09:35

developer   ~0000042

I need to know which pgpool's internal query breaks the unnamed statememt/portal. Can you provide such that information? Or do you know how to reproduce the problem? Since I couldn't reproduce the problem.

ericsun

2012-08-16 23:16

reporter   ~0000043

This is log from PGPOOL 3.2 final, no other output from same process:
We are using hibernate but i don't know how name a prepared statement in hibernate if this is a workaround.

2012-08-15 13:26:51 LOG: pid 19497: pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 23451 statement: select avatarsdto0_.avatarid as avatarid2_0_, avatarsdto0_.path as path2_0_, avatarsdto0_.status as status2_0_ from avatars avatarsdto0_ where avatarsdto0_.avatarid=$1 message: portal "" does not exist

t-ishii

2012-08-17 08:19

developer   ~0000045

I need PostgreSQL log, not pgpool log. Please send PostgreSQL log.

ryansanders

2012-08-17 08:59

reporter   ~0000046

The problem both Ericsun and I have is that our production database server is so busy, that if we enable full query logging, it will saturate our current storage array. I am working on an alternate solution to get you the full text of those internal queries, as well as the original server responses.

darronh

2012-08-22 14:38

reporter   ~0000047

not sure if this helps, but i have the same issue with pgpool II 3.1.3
this log is from the slave, although there isn't much sql it must be getting sent to the master.


LOG: execute S_2: COMMIT
LOG: statement: SELECT pg_last_xlog_replay_location()
LOG: execute S_1: BEGIN
LOG: execute S_2: COMMIT
LOG: execute S_1: BEGIN
LOG: execute S_2: COMMIT
LOG: execute S_2: COMMIT
LOG: execute S_1: BEGIN
LOG: execute S_2: COMMIT
LOG: execute S_1: BEGIN
LOG: execute S_2: COMMIT
LOG: execute S_2: COMMIT
LOG: execute S_1: BEGIN
LOG: execute S_2: COMMIT
LOG: execute S_1: BEGIN
LOG: statement: SELECT pg_last_xlog_replay_location()
LOG: execute S_1: BEGIN
ERROR: portal "" cannot be run

t-ishii

2012-08-22 15:25

developer   ~0000048

Unfortunately the PostgreSQL log lacks process id. Without it, I cannot trace session, thus cannot find the cause of the errro.

darronh

2012-08-23 04:53

reporter   ~0000049

2012-08-22 12:29:12 PDT State(00000) Session(50351c85.186e) PID(6254) LOG: execute S_2: COMMIT
2012-08-22 12:29:12 PDT State(00000) Session(50351c83.1867) PID(6247) LOG: execute S_2: COMMIT
2012-08-22 12:29:12 PDT State(00000) Session(50351c85.186e) PID(6254) LOG: execute S_1: BEGIN
2012-08-22 12:29:12 PDT State(00000) Session(50351c83.186b) PID(6251) LOG: execute S_2: COMMIT
2012-08-22 12:29:12 PDT State(00000) Session(50350e74.9ac) PID(2476) LOG: execute S_2: COMMIT
2012-08-22 12:29:12 PDT State(00000) Session(50351c83.186b) PID(6251) LOG: execute S_1: BEGIN
2012-08-22 12:29:12 PDT State(00000) Session(50351c83.1867) PID(6247) LOG: execute S_1: BEGIN
2012-08-22 12:29:13 PDT State(00000) Session(50350e74.9ac) PID(2476) LOG: execute S_1: BEGIN
2012-08-22 12:29:13 PDT State(00000) Session(50350e75.9b1) PID(2481) LOG: execute S_2: COMMIT
2012-08-22 12:29:13 PDT State(00000) Session(50351c85.186e) PID(6254) LOG: execute S_2: COMMIT
2012-08-22 12:29:14 PDT State(00000) Session(50351c85.186e) PID(6254) LOG: execute S_1: BEGIN
2012-08-22 12:29:14 PDT State(00000) Session(50350e75.9b1) PID(2481) LOG: execute S_1: BEGIN
2012-08-22 12:29:14 PDT State(00000) Session(50350e74.9ac) PID(2476) LOG: execute S_2: COMMIT
2012-08-22 12:29:14 PDT State(00000) Session(5035330a.2f54) PID(12116) LOG: statement: SELECT pg_last_xlog_replay_location()
2012-08-22 12:29:14 PDT State(00000) Session(50350e75.9b1) PID(2481) LOG: execute S_1: BEGIN
2012-08-22 12:29:14 PDT State(55000) Session(50350e75.9b1) PID(2481) ERROR: portal "" cannot be run

Here are some logs from today with the PID numbers

t-ishii

2012-10-02 10:09

developer   ~0000102

I have fixed the problem in master and all supported branch. For 3.1-stable, please take a look at commit:
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=3e902fe700dae67018ae4c98e027d5d45299d6c6

Issue History

Date Modified Username Field Change
2012-05-15 04:06 singh.gurjeet New Issue
2012-05-22 18:52 t-ishii Additional Information Updated
2012-05-22 18:53 t-ishii Note Added: 0000029
2012-05-22 18:53 t-ishii Additional Information Updated
2012-05-22 23:27 singh.gurjeet Note Added: 0000030
2012-05-23 08:31 t-ishii Note Added: 0000031
2012-06-03 16:48 t-ishii Note Added: 0000033
2012-06-03 22:04 t-ishii Note Added: 0000034
2012-06-06 01:03 singh.gurjeet Note Added: 0000035
2012-06-06 16:19 t-ishii Note Added: 0000036
2012-07-23 02:46 Ashish Nauriyal Note Added: 0000039
2012-08-16 02:50 ryansanders Note Added: 0000041
2012-08-16 09:35 t-ishii Note Added: 0000042
2012-08-16 23:16 ericsun Note Added: 0000043
2012-08-17 08:19 t-ishii Note Added: 0000045
2012-08-17 08:59 ryansanders Note Added: 0000046
2012-08-22 14:38 darronh Note Added: 0000047
2012-08-22 15:25 t-ishii Note Added: 0000048
2012-08-23 04:53 darronh Note Added: 0000049
2012-10-02 10:06 t-ishii Assigned To => t-ishii
2012-10-02 10:06 t-ishii Status new => assigned
2012-10-02 10:09 t-ishii Note Added: 0000102
2012-10-05 18:06 t-ishii Status assigned => resolved
2012-10-05 18:06 t-ishii Resolution open => fixed