insufficient data left in message

Dave Cramer <pg@fastcrypt.com> writes:

This is a postgresql 8.2.5 backend. connected to a jdbc client.
2008-02-21 06:12:30 EST [18880] 10.21.0.21 ERROR: insufficient data
left in message

AFAIK this means that the frontend sent an invalidly-formatted message.
There's some chance that the message was OK and the backend's message
parsing code is at fault, but I'd suspect the former first.

So the question is: how to go about debugging this ?

Put a sniffer on the TCP session, or change the ERROR to a PANIC
and dig around in the core dump to see what the message was?

Also it might be worth updating to the latest JDBC driver, if you're
not on it already, just in case this is an already-fixed bug.

regards, tom lane

More questions....

Feb 21 10:22:52 db02a postgres[31111]: [742-1]
user=mocospace_user,db=jnj LOG: duration: 0.088 ms execute S_3:
select * from user_profile
,user_profile_access where
Feb 21 10:22:52 db02a postgres[31111]: [742-2]
user_profile.uid=user_profile_access.uid and user_profile.uid=$1 and
isactive=$2
Feb 21 10:22:52 db02a postgres[31111]: [742-3]
user=mocospace_user,db=jnj DETAIL: parameters: $1 = '1450984', $2 = 't'
Feb 21 10:22:52 db02a postgres[31111]: [743-1]
user=mocospace_user,db=jnj ERROR: insufficient data left in message
Feb 21 10:22:52 db02a postgres[31111]: [743-2]
user=mocospace_user,db=jnj STATEMENT: select * from
user_profile,user_profile_access where
Feb 21 10:22:52 db02a postgres[31111]: [743-3]
user_profile.uid=user_profile_access.uid and user_profile.uid=$1 and
isactive=$2
12:25Feb 21 10:22:52 db02a postgres[31111]: [744-1]
user=mocospace_user,db=jnj FATAL: invalid frontend message type 105

Is this all the same error, just logged twice or is this two
connections instances ?

Dave
On 21-Feb-08, at 10:39 AM, Tom Lane wrote:

Dave Cramer <pg@fastcrypt.com> writes:

More questions....
Feb 21 10:22:52 db02a postgres[31111]: [742-1]
user=mocospace_user,db=jnj LOG: duration: 0.088 ms execute S_3:
select * from user_profile
,user_profile_access where
Feb 21 10:22:52 db02a postgres[31111]: [742-2]
user_profile.uid=user_profile_access.uid and user_profile.uid=$1 and
isactive=$2
Feb 21 10:22:52 db02a postgres[31111]: [742-3]
user=mocospace_user,db=jnj DETAIL: parameters: $1 = '1450984', $2 = 't'
Feb 21 10:22:52 db02a postgres[31111]: [743-1]
user=mocospace_user,db=jnj ERROR: insufficient data left in message
Feb 21 10:22:52 db02a postgres[31111]: [743-2]
user=mocospace_user,db=jnj STATEMENT: select * from
user_profile,user_profile_access where
Feb 21 10:22:52 db02a postgres[31111]: [743-3]
user_profile.uid=user_profile_access.uid and user_profile.uid=$1 and
isactive=$2
12:25Feb 21 10:22:52 db02a postgres[31111]: [744-1]
user=mocospace_user,db=jnj FATAL: invalid frontend message type 105

Is this all the same error, just logged twice or is this two
connections instances ?

AFAICT this must be two successive executions of the same prepared
query. The STATEMENT: detail attached to message 743 would have
to have come from debug_query_string, but that gets reset immediately
after emitting the "duration" message in exec_execute_message, so it
couldn't be from the same execution that resulted in message 742.
So I'm guessing that what you are seeing is a failure during parsing
of a Bind message for a fresh execution, after the spot where it
sets debug_query_string --- so the statement name is good, and the
problem seems to be in the parameters part of the message.

regards, tom lane