[Pgpool-general] pgpool-II and JDBC problem

[Greg Smith]

I've seen a couple of people mention JDBC issues on this list recently, 
but with no details.  Well, I've got plenty of those for you.  Here's how 
I've been able to replicate a hung Java client on two systems now during a 
simple query.  I haven't gotten anything to work with the pgpool-II/JDBC 
combination.  The system I give sample output from is running Redhat 
Enterprise Linux 4; I had the same issue with SuSE 9 as well on different 
hardware.

1) Install pgpool-II, add a user to pcp.conf.  Only change to pgpool.conf 
is:

backend_hostname0 = 'localhost'
backend_port0 = 5432

The backend in this case is a PostgreSQL 8.1.5 server.  I tried a 8.2 
backend instead, that didn't help.

2) Start pgpool-II with "pgpool -n -d" so I can watch what it's doing. 
Confirm I can execute queries from psql against the real database or the 
pooled one and they look the same:

-bash-3.00$ psql -t -p 5432 -c "select 1"
         1

-bash-3.00$ psql -t -p 9999 -c "select 1"
         1

(I did some real selects against the database here as well, everything 
worked fine with psql)

3) Write some simple Java into test.java:

import java.sql.Connection;
import java.sql.DatabaseMetaData;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.Statement;

public class test
{
   public static void main(String args[])
   {
       try
       {
       System.setProperty("jdbc.drivers", "org.postgresql.Driver");
       Connection c=DriverManager.getConnection
         ("jdbc:postgresql://localhost:5432/db","postgres","password");

       DatabaseMetaData md=c.getMetaData();
       System.out.println("Database "+md.getDatabaseProductName()+
         " "+md.getDatabaseMajorVersion()+
         "."+md.getDatabaseMinorVersion());

       Statement stat=c.createStatement();
       ResultSet rs=stat.executeQuery("select 1");
       while (rs.next())
         { System.out.println("Select returned " + rs.getInt(1)); }
       }
       catch (Exception e)
       {
         System.err.println("Database error: " + e);
         e.printStackTrace(System.err);
       }
   }
}

4) Download the Postgres JDBC Driver, execute the test code like this:

-bash-3.00$ export CLASSPATH=./postgresql-8.1-408.jdbc3.jar:.
-bash-3.00$ javac test.java
-bash-3.00$ java test
Database PostgreSQL 8.1
Select returned 1

5) Edit the code and switch the port to 9999.  Recompile and run.  Now I 
get this:

-bash-3.00$ javac test.java
-bash-3.00$ java test
Database PostgreSQL 8.1
<hangs>

At this point, I removed the part that's working successfully (the 
metadata lines) and got a debug log from connection to the point at which 
the Java client tries to execute the select:

2007-01-12 00:00:45 DEBUG: pid 2544: I am 2544 accept fd 7
2007-01-12 00:00:45 DEBUG: pid 2544: Protocol Major: 3 Minor: 0 database: 
stocks user: postgres
2007-01-12 00:00:45 DEBUG: pid 2544: new_connection: connecting 0 backend
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length: slot: 0 
length: 8
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 28
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: client_encoding 
value: UNICODE
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 23
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: DateStyle value: 
ISO, MDY
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 26
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: integer_datetimes 
value: off
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 20
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: is_superuser 
value: on
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 25
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: server_encoding 
value: UTF8
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 25
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: server_version 
value: 8.1.5
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 35
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: 
session_authorization value: postgres
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 36
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: 
standard_conforming_strings value: off
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length2: master 
slot: 0 length: 21
2007-01-12 00:00:45 DEBUG: pid 2544: 0 th backend: name: TimeZone value: 
EST5EDT
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length: slot: 0 
length: 12
2007-01-12 00:00:45 DEBUG: pid 2544: pool_send_auth_ok: send pid 2638 to 
frontend
2007-01-12 00:00:45 DEBUG: pid 2544: read_kind_from_backend: read kind 
from 0 th backend Z NUM_BACKENDS: 1
2007-01-12 00:00:45 DEBUG: pid 2544: cached kind(5a) or kind1(00) != 0
2007-01-12 00:00:45 DEBUG: pid 2544: pool_process_query: kind from 
backend: Z
2007-01-12 00:00:45 DEBUG: pid 2544: pool_read_message_length: slot: 0 
length: 5
2007-01-12 00:00:45 DEBUG: pid 2544: ReadyForQuery: message length: 5
2007-01-12 00:00:45 DEBUG: pid 2544: ReadyForQuery: transaction state: I
2007-01-12 00:00:45 DEBUG: pid 2544: pool_process_query: num_fds: 9
2007-01-12 00:00:45 DEBUG: pid 2544: read kind from frontend P(50)

Every time I've tried it, that's where I get stopped at; the client does 
nothing, and I don't see additional information on the log from this 
process.

For comparison sake, here's a partial log of what I see when executing the 
successful select from psql, the lines just before and after where I get 
stuck at going through pgpool-II:

2007-01-12 00:02:54 DEBUG: pid 2477: pool_process_query: kind from 
backend: Z
2007-01-12 00:02:54 DEBUG: pid 2477: pool_read_message_length: slot: 0 
length: 5
2007-01-12 00:02:54 DEBUG: pid 2477: ReadyForQuery: message length: 5
2007-01-12 00:02:54 DEBUG: pid 2477: ReadyForQuery: transaction state: I
2007-01-12 00:02:54 DEBUG: pid 2477: pool_process_query: num_fds: 7
2007-01-12 00:02:54 DEBUG: pid 2477: read kind from frontend Q(51)
2007-01-12 00:02:54 DEBUG: pid 2477: statement2: select 1
2007-01-12 00:02:54 DEBUG: pid 2477: waiting for backend 0 completing the 
query

So it looks like the next thing I should see in the logs is "statement2: 
select 1".  The differences in num_fds and P(50) vs. Q(51) jump out at me, 
but I don't know what those mean so I'm stuck at this point.

--
* Greg Smith gsmith at gregsmith.com http://www.gregsmith.com Baltimore, MD