Why is the PostgreSQL JDBC driver sending a bad packet header to the server during authentication?

Question

Important Note -- Had a breakthrough in Edit #2 at the end, so be sure to read that as well.

I'm in clojure, trying to use JDBC to connect to our company PostgreSQL server. The server is using pgBouncer.

Here are my project dependencies:

  :dependencies [[org.clojure/clojure "1.6.0"]
                 [org.clojure/java.jdbc "0.3.6"]
                 [org.postgresql/postgresql "9.4-1200-jdbc41"]]

And here's my code:

(ns pg-test.core
  (:require [clojure.java.jdbc :as jdbc]))

(def db
  {:subprotocol "postgresql"
   :subname "//the-server-name:the-port/db-name"
   :sslmode "require"
   :user "my-username"
   :password "super-secret-password"})

(jdbc/query db ["SELECT 5"])

When I run this code, I get one of three results:

org.postgresql.util.PSQLException: The connection attempt failed.
org.postgresql.util.PSQLException: ERROR: bad packet header: '70'
VERY RARELY (three times now, out of hundreds of attempts), it will actually work! It returns ({:?column? 5})

What is going on? Why does this work sometimes, but almost NEVER?

My Setup

OS X Yosemite (but I was never able to make it work from my Ubuntu virtual machine, either.)
lein repl :headless :port 2358 followed by cider-connect in emacs.
Server is postgres 9.1.12

Edit #2

Just learned about the :loglevel 2 option. This sets it to "DEBUG" level of output, and I gathered some more interesting data. Here's the output:

21:45:34.921 (31) PostgreSQL 9.4 JDBC4.1 (build 1200)
21:45:34.927 (31) Trying to establish a protocol version 3 connection to the-server-name:the-port
21:45:35.020 (31)  FE=> SSLRequest
21:45:35.120 (31)  <=BE SSLOk
21:45:35.120 (31) converting regular socket connection to ssl
21:45:35.324 (31) Receive Buffer Size is 131072
21:45:35.324 (31) Send Buffer Size is 131136
21:45:35.324 (31)  FE=> StartupPacket(user=my-username, database=db-name, client_encoding=UTF8, DateStyle=ISO, TimeZone=America/Denver, extra_float_digits=2)
21:45:35.435 (31)  <=BE AuthenticationReqMD5(salt=f244b442)
21:45:35.436 (31)  FE=> Password(md5digest=md52e3d9f29d44d48ab19ef3469d54d50d1)
21:45:35.520 (31)  <=BE ErrorMessage(ERROR: bad packet header: '70')

It then gives the following stack trace:

org.postgresql.util.PSQLException: ERROR: bad packet header: '70'
    at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:420)
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:195)
    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:66)
    at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:127)
    at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:29)
    at org.postgresql.jdbc3g.AbstractJdbc3gConnection.<init>(AbstractJdbc3gConnection.java:21)
    at org.postgresql.jdbc4.AbstractJdbc4Connection.<init>(AbstractJdbc4Connection.java:41)
    at org.postgresql.jdbc4.Jdbc4Connection.<init>(Jdbc4Connection.java:24)
    at org.postgresql.Driver.makeConnection(Driver.java:414)
    at org.postgresql.Driver.connect(Driver.java:282)
    at java.sql.DriverManager.getConnection(DriverManager.java:571)
    at java.sql.DriverManager.getConnection(DriverManager.java:187)
    at clojure.java.jdbc$get_connection.invoke(jdbc.clj:255)
    at clojure.java.jdbc$db_query_with_resultset.invoke(jdbc.clj:798)
    at clojure.java.jdbc$query.doInvoke(jdbc.clj:832)
    at clojure.lang.RestFn.invoke(RestFn.java:425)
    at pg_test.core$eval4536.invoke(core.clj:14)
    at clojure.lang.Compiler.eval(Compiler.java:6703)
    at clojure.lang.Compiler.load(Compiler.java:7130)
    at pg_test.core$eval4524.invoke(form-init6588155330850041472.clj:1)
    at clojure.lang.Compiler.eval(Compiler.java:6703)
    at clojure.lang.Compiler.eval(Compiler.java:6666)
    at clojure.core$eval.invoke(core.clj:2927)
    at clojure.main$repl$read_eval_print__6625$fn__6628.invoke(main.clj:239)
    at clojure.main$repl$read_eval_print__6625.invoke(main.clj:239)
    at clojure.main$repl$fn__6634.invoke(main.clj:257)
    at clojure.main$repl.doInvoke(main.clj:257)
    at clojure.lang.RestFn.invoke(RestFn.java:1523)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate$fn__592.invoke(interruptible_eval.clj:67)
    at clojure.lang.AFn.applyToHelper(AFn.java:152)
    at clojure.lang.AFn.applyTo(AFn.java:144)
    at clojure.core$apply.invoke(core.clj:624)
    at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1862)
    at clojure.lang.RestFn.invoke(RestFn.java:425)
    at clojure.tools.nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:51)
    at clojure.tools.nrepl.middleware.interruptible_eval$interruptible_eval$fn__634$fn__637.invoke(interruptible_eval.clj:183)
    at clojure.tools.nrepl.middleware.interruptible_eval$run_next$fn__627.invoke(interruptible_eval.clj:152)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

But then it gives this error code!

SQLException: SQLState(08P01)

Which, according to this website means "PROTOCOL VIOLATION".

I searched google for 08P01 protocol violation, and found this bug report for a completely unrelated project on GitHub with the title "'08P01 PROTOCOL VIOLATION' when trying to write encoded unicode characters to string fields".

So let's look at what we're sending:

StartupPacket(user=my-username, database=db-name, client_encoding=UTF8, DateStyle=ISO, TimeZone=America/Denver, extra_float_digits=2). Notice that our encoding is UTF8.
Then, we send Password(md5digest=md52e3d9f29d44d48ab19ef3469d54d50d1), and immediately we get the "bad packet header '70'" exception.

Is UTF8 ruining my life again? I thought we had left these bad days behind us so long ago.

So now I'm wondering if there's a way to change the client encoding. Or possibly to change the authentication method being used.

It may also be helpful to know that the psql client program works without a hitch from my machine. This leads me to believe that it's some jdbc weirdness, and not a problem with the network. — Aaron Johnson, Feb 12 '15 at 13:02
I just tried doing this with pure Java (i.e., not in Clojure.) I get the same results. Wondering if pgBouncer is not playing nicely with JDBC. — Aaron Johnson, Feb 12 '15 at 17:20

score 1 · Answer 1 · answered Feb 11 '15 at 23:21

1

According to the PgJDBC driver the "PgJDBC has optional dependencies on other libraries for some features. These libraries must also be on your classpath if you wish to use those features; if they aren't, you'll get a PSQLException at runtime when you try to use features with missing libraries."

Some dependecy or maybe native-compiled SSL-library is likely missing. I have no idea why it would work sometimes in a blue moon if that was the case, though.

https://github.com/pgjdbc/pgjdbc/blob/f96f6b3c0fdcb9c393b870b834adb1248f955cee/README.md#dependencies

answered Feb 11 '15 at 23:21

claj

5,172
2
27
30

Well, and that's the most troubling thing to me, that it does work sometimes, albeit very rarely. It makes me wonder if this is somehow a weird network issue, but I have no idea how I would go about diagnosing that. – Aaron Johnson Feb 12 '15 at 01:06
have a look at Edit #2. The problem occurs right after we send the Password(md5digest=md5blahblahblah). Could it be that the salt sent from the server (different each time) occasionally results in a series of bytes that DO get encoded correctly, and allow for the connection to take place? – Aaron Johnson Feb 12 '15 at 05:29

score 0 · Answer 2 · answered Feb 11 '15 at 23:11

Does it work without SSL? If so, can you make sure you don't run a cryptographically crippled version of your JVM? I guess Oracles JVM needs the export restricted stronger encryption JCE.

The strong encryption JCE can be downloaded from http://www.oracle.com/technetwork/java/javase/downloads/jce-7-download-432124.html

score 0 · Answer 3 · answered Feb 11 '15 at 23:26

0

This link to an Heroku postgres connection example mentions two more key-value pairs,

:ssl true

and

:sslfactory (when-not (:production environ/env)  
             "org.postgresql.ssl.NonValidatingFactory")

answered Feb 11 '15 at 23:26

claj

5,172
2
27
30

using the non validating provider will tell you affirmativly that the problem is either a missing root cert or the DB using a self signed cert. Otherwise it will give you little information. Leaving it on provides nearly the same level of security as not using SSL – Arthur Ulfeldt Feb 12 '15 at 01:42

score 0 · Answer 4 · answered Jun 03 '15 at 00:13

0

Adding the extra parameter ignore_startup_parameters=extra_float_digits should solve the problem.

See http://www.postgresql.org/message-id/20080625170634.DC16A17AE6FB@pgfoundry.org

answered Jun 03 '15 at 00:13

Ben Mears

86
1
2

Why is the PostgreSQL JDBC driver sending a bad packet header to the server during authentication?

4 Answers4