Thread: JDBC and Binary protocol error, for some statements
Hi,
I work on implementing binary protocol, during test "select ?::int" has
been
executed few times to compile it to server prepared statement, but after
this
backend returned field format = text, but sent field data in binary mode.
The parameter is long and is sent to in text mode, with oid 0, as value
"2"
Result is oid=23, format=(0) T, value = 0x00,0x00,0x00,0x02
When I send parameter explicite in binary mode and int4 oid, problem
doesn't
occurs.
Here is debug of protocol
---------------------------------------
07:52:02.995 (54) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@508aeb74,
maxRows=0, fetchSize=0, flags=17
07:52:02.996 (54) FE=> Parse(stmt=null,query="SELECT $1::int",oids={0})
07:52:02.996 (54) FE=> Bind(stmt=null,portal=null,$1=<'2'>)
07:52:02.996 (54) FE=> Describe(portal=null)
07:52:02.996 (54) FE=> Execute(portal=null,limit=0)
07:52:02.996 (54) FE=> Sync
07:52:02.997 (54) <=BE ParseComplete [null]
07:52:02.997 (54) <=BE BindComplete [null]
07:52:02.998 (54) <=BE RowDescription(1)
07:52:02.998 (54) Field(,INT4,4,B)
07:52:02.998 (54) <=BE DataRow(len=4)
07:52:02.998 (54) <=BE CommandStatus(SELECT)
07:52:02.999 (54) <=BE ReadyForQuery(I)
---------------------------------------
Compiled stat exec
07:52:06.059 (54) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@128ae45a,
maxRows=0, fetchSize=0, flags=16
07:52:06.059 (54) FE=> Parse(stmt=S_1,query="SELECT $1::int",oids={0})
07:52:06.059 (54) FE=> Describe(statement=S_1)
07:52:06.060 (54) FE=> Bind(stmt=S_1,portal=null,$1=<'2'>)
07:52:06.060 (54) FE=> Execute(portal=null,limit=0)
07:52:06.060 (54) FE=> Sync
07:52:06.060 (54) <=BE ParseComplete [S_1]
07:52:06.061 (54) <=BE ParameterDescription
07:52:06.061 (54) <=BE RowDescription(1)
07:52:06.061 (54) Field(,INT4,4,T)
07:52:06.061 (54) <=BE BindComplete [null]
07:52:06.061 (54) <=BE DataRow(len=4)
07:52:06.062 (54) <=BE CommandStatus(SELECT)
07:52:06.062 (54) <=BE ReadyForQuery(I)
org.postgresql.jdbc4.exceptions.PSQLDataException: Zła wartość dla typu
int:
Kind regards,
Radek
>Result is oid=23, format=(0) T, value = 0x00,0x00,0x00,0x02 What do you mean regarding the format? Are you just inferring that from the data? If memory serves, the format of a particular column is not specified anywhere other than the RowDescription, and according to your JDBC log output above, the server is telling you the format is text (1) (which is your point--it doesn't match the resulting data--but I want to make sure we're clear on what's actually going on). Also, can you narrow this down to a simple, self-contained test case (with code)? Even if it's against a custom driver build, that would be easier to investigate. --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
I didn't described log correctly, 1st attached response is normal execution; flags QUERY_SUPPRESS_BEGIN | QUERY_ONESHOT, 2nd is compiled statement QUERY_SUPPRESS_BEGIN only. Text format is marked as 0, binary format is 1. The 1st shown execution (flags=17) is good, it tells that result is sended in binary format, as int4, but 2nd one (flags=16) (statement compiled) result is bad because Server described row as text 07:52:06.061 (54) <=BE RowDescription(1) 07:52:06.061 (54) Field(,INT4,4,T) but recieved "tuple" was clearly in binary format, 0x00, 0x00, 0x00, 0x02. (Look at length should be 1 or 2 if it's text format and value 2) Speaking it simple, server said "you will recive text data", but sent it as binary encoded int. I've checked this againt 8.4 and 9.0.1. Maciek Sakrejda <msakrejda@truviso.com> Wednesday 24 November 2010 18:02:27 > >Result is oid=23, format=(0) T, value = 0x00,0x00,0x00,0x02 > > What do you mean regarding the format? Are you just inferring that > from the data? If memory serves, the format of a particular column is > not specified anywhere other than the RowDescription, and according to > your JDBC log output above, the server is telling you the format is > text (1) (which is your point--it doesn't match the resulting > data--but I want to make sure we're clear on what's actually going > on). It's jdbc2.PreparedStatementTest, form JDBC driver unit tests. I've exposed sources here http://www.rsmogura.net/pgsql/pgjdbc_exp_20101124.tar.gz compiled driver and unit tests are in parent directory. In above all not related to this bug tests has been commented, just run ant test. > Also, can you narrow this down to a simple, self-contained test case > (with code)? Even if it's against a custom driver build, that would be > easier to investigate. > --- > Maciek Sakrejda | System Architect | Truviso > > 1065 E. Hillsdale Blvd., Suite 215 > Foster City, CA 94404 > (650) 242-3500 Main > www.truviso.com Kind regards, Radek
> Text format is marked as 0, binary format is 1. Sorry--I misread the docs. This is consistent and something does look fishy. Thanks for the tarball. I can take a look tonight. --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
I've run your test and I can confirm the error. I've looked at the protocol traffic with Wireshark, and the back-end is clearly lying about the format of the results in this particular case: as you stated, the row description says text, but the data is in binary. I also wrote a simple Java program (on github at https://github.com/deafbybeheading/postgresql-result-format-testcase ; I didn't know if uninvited attachments were kosher) to minimize the test case. Note that the program relies on trust authentication to be on. Since triggering the set of FEBE messages that leads to this was tied deep into the guts of JDBC, I opted for raw wire protocol. It looks like the following sequence of messages from the client leads to this result format mixup: 1. Parse, with statement name "S_1", sql "SELECT $1::int", and parameter type oid 0 (ask server to guess) 2. Describe "S_1" 3. Bind "S_1" to anonymous portal, with param formats [ 0 (text) ], param values [ '2' ], result formats [ 1 (binary) ] 4. Execute anonymous portal (returning all rows) 5. Sync I have not tried to narrow this further yet. This essentially reproduces what Radosław was seeing but outside of the JDBC driver. That is, the server responds with: 1. Parse completion 2. Parameter description, with type oids [ 23 ] 3. Row description, with empty table data, type oids [ 23 ], type length 4, type mod -1, and format 0 (text) 4. Bind completion 5. DataRow, with the result in binary, as requested, but not as described in message (3) above 6. Command completion & RFQ For what it's worth, I'm running this against an 8.4 server: PostgreSQL 8.4.5 on i486-pc-linux-gnu, compiled by GCC gcc-4.4.real (Ubuntu 4.4.3-4ubuntu5) 4.4.3, 32-bit I'll try to look into this some more, but first of all, is the client sequence above valid? As far as I can tell, it is. I'm guessing that the root of the problem is providing the parameter as text and requesting it back in binary, but I'll freely admit my knowledge of the internals here (well, beyond the protocol itself) is very limited. Thanks, --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
Haven't really gotten much further, but an interesting note: the named / unnamed prepared statement and portal stuff seems to be a red herring. I can add a name to the portal, or move to an unnamed prepared statement, and I still see the same thing. Which is interesting, since that's not what Radosław saw (his original test only failed once named prepared statements kicked in)... --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
I checked against other parameter bindings and it looks like problem is connected with oid=0. In those cases: 1. Executing statement with parameter sent as varchar, int, long, with text and binary format is ok. 2. Executing statement with oid=0 fail always; I've sent parameter in text mode (encoded '2'), and in binary mode encoded int4 2 - both failed. On Thu, 25 Nov 2010 01:56:02 -0800, Maciek Sakrejda <msakrejda@truviso.com> wrote: > Haven't really gotten much further, but an interesting note: the named > / unnamed prepared statement and portal stuff seems to be a red > herring. I can add a name to the portal, or move to an unnamed > prepared statement, and I still see the same thing. Which is > interesting, since that's not what Radosław saw (his original test > only failed once named prepared statements kicked in)... > --- > Maciek Sakrejda | System Architect | Truviso > > 1065 E. Hillsdale Blvd., Suite 215 > Foster City, CA 94404 > (650) 242-3500 Main > www.truviso.com -- ---------- Radosław Smogura http://www.softperience.eu
Maciek Sakrejda <msakrejda@truviso.com> writes:
> Since triggering the set of FEBE messages that leads to this was tied
> deep into the guts of JDBC, I opted for raw wire protocol. It looks
> like the following sequence of messages from the client leads to this
> result format mixup:
> 1. Parse, with statement name "S_1", sql "SELECT $1::int", and
> parameter type oid 0 (ask server to guess)
> 2. Describe "S_1"
> 3. Bind "S_1" to anonymous portal, with param formats [ 0 (text) ],
> param values [ '2' ], result formats [ 1 (binary) ]
> 4. Execute anonymous portal (returning all rows)
> 5. Sync
> I have not tried to narrow this further yet. This essentially
> reproduces what Radosław was seeing but outside of the JDBC driver.
> That is, the server responds with:
> 1. Parse completion
> 2. Parameter description, with type oids [ 23 ]
> 3. Row description, with empty table data, type oids [ 23 ], type
> length 4, type mod -1, and format 0 (text)
> 4. Bind completion
> 5. DataRow, with the result in binary, as requested, but not as
> described in message (3) above
> 6. Command completion & RFQ
AFAICS this isn't a bug. What you're issuing Describe against is the
prepared statement, not the portal. The result column formats are not
specified by a prepared statement, so Describe just returns zeroes for
them. Result column formats are specified by the Bind command, which
creates a Portal. If you'd issued the Describe against the Portal, you
should get back the correct format codes. Per the protocol
specification:
The Describe message (statement variant) specifies the name of an
existing prepared statement (or an empty string for the unnamed
prepared statement). The response is a ParameterDescription message
describing the parameters needed by the statement, followed by a
RowDescription message describing the rows that will be returned
when the statement is eventually executed (or a NoData message if
the statement will not return rows). ErrorResponse is issued if
there is no such prepared statement. Note that since Bind has not
yet been issued, the formats to be used for returned columns are not
yet known to the backend; the format code fields in the
RowDescription message will be zeroes in this case.
Now, if there's something in the JDBC driver that expects
DescribeStatement to return useful result format codes, that'd be
a bug in the driver.
regards, tom lane
Interesting. I think you're right. Looking at the Wireshark traffic again, the driver seems to issue a portal-variant Describe when using unnamed prepared statements, but as soon as the named prepared statements kick in (per prepare threshold), the Describe is a statement-variant Describe with the expected behavior you've noted. Actually, the driver sends Parse / Bind / Describe with the unnamed statement, but for some reason switches to Parse / Describe / Bind with named ones. --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
Okay, looking at the JDBC side of things, I think JDBC doesn't actually need that information (since, it always used text results before Radosław's patch--the previous binary support was for parameters only, right?). From looking at QueryExecutorImpl (specifically sendOneQuery), it's clear that it *does* need the Describe before the Bind when using named prepared statements. I can't quite follow why, but I think the upshot of this is that there is no bug in either the JDBC driver or the backend. This is just a limitation of the existing implementation in the JDBC driver that Radosław would need to work around for binary result processing (probably by storing the requested format somewhere and using that instead of what comes back from Describe). I think the lessons are (1) the bug is probably *not* in the established library or backend code and (2) it's a little confusing that the result codes for "I don't know what format this will be in" and "this will be in text format" are aliased. It's too late to do anything about the second one and it's only a minor quibble. Thanks for the help in making sense of this. --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
Hi, Thank you for your response. I would only ask to be sure... So, to summarise, I shouldn't believe server DescribeRow (in context of format), in this situation, but only I should look at this what I asked for, isn't it? If I asked for columns in binary format, I need to do binary reading regarding what server has responded? If I asked for odd columns in text, even in binary do I need to choose proper format basing only on my request? But to the last part of cited protocol specification, when I've sent message with statement parameter's type int4, int8, varchar the format field wasn't set to 0, but 1. Kind regards, Radosław Smogura On Thu, 25 Nov 2010 12:23:03 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote: > AFAICS this isn't a bug. What you're issuing Describe against is the > prepared statement, not the portal. The result column formats are not > specified by a prepared statement, so Describe just returns zeroes for > them. Result column formats are specified by the Bind command, which > creates a Portal. If you'd issued the Describe against the Portal, you > should get back the correct format codes. Per the protocol > specification: > > The Describe message (statement variant) specifies the name of an > existing prepared statement (or an empty string for the unnamed > prepared statement). The response is a ParameterDescription message > describing the parameters needed by the statement, followed by a > RowDescription message describing the rows that will be returned > when the statement is eventually executed (or a NoData message if > the statement will not return rows). ErrorResponse is issued if > there is no such prepared statement. Note that since Bind has not > yet been issued, the formats to be used for returned columns are not > yet known to the backend; the format code fields in the > RowDescription message will be zeroes in this case. > > Now, if there's something in the JDBC driver that expects > DescribeStatement to return useful result format codes, that'd be > a bug in the driver. > > regards, tom lane -- ---------- Radosław Smogura http://www.softperience.eu
> So, to summarise, I shouldn't believe server DescribeRow (in context of format), in this situation, but only I should lookat this what I asked > for, isn't it? If I asked for columns in binary format, I need to do binary reading regarding what server has responded? Yes, because in this case "0" doesn't mean "the result will be in text", it means, "you issued the statement-variant of Describe, so I'm not sure what the result format will be yet." > If I asked for odd columns in text, even in binary do I need to choose proper format basing only on my request? I don't quite understand this question, but I think so. I don't think there's ever a situation where the server will ignore your result format requests. > But to the last part of cited protocol specification, when I've sent message with statement parameter's type int4, int8,varchar the format > field wasn't set to 0, but 1. I wasn't able to reproduce that with my standalone test case. When I changed the parameter oid to 23, I still got the same behavior. Can you alter my test case to reproduce the error? --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
On Thu, 25 Nov 2010 11:28:02 -0800, Maciek Sakrejda <msakrejda@truviso.com> wrote: >> So, to summarise, I shouldn't believe server DescribeRow (in context of >> format), in this situation, but only I should look at this what I asked >> for, isn't it? If I asked for columns in binary format, I need to do >> binary reading regarding what server has responded? > > Yes, because in this case "0" doesn't mean "the result will be in > text", it means, "you issued the statement-variant of Describe, so I'm > not sure what the result format will be yet." > >> If I asked for odd columns in text, even in binary do I need to choose >> proper format basing only on my request? > > I don't quite understand this question, but I think so. I don't think > there's ever a situation where the server will ignore your result > format requests. > >> But to the last part of cited protocol specification, when I've sent >> message with statement parameter's type int4, int8, varchar the format >> field wasn't set to 0, but 1. > > I wasn't able to reproduce that with my standalone test case. When I > changed the parameter oid to 23, I still got the same behavior. Can > you alter my test case to reproduce the error? > I will do it tomorrow. In this situation I need to test portals as well. > --- > Maciek Sakrejda | System Architect | Truviso > > 1065 E. Hillsdale Blvd., Suite 215 > Foster City, CA 94404 > (650) 242-3500 Main > www.truviso.com -- ---------- Radosław Smogura http://www.softperience.eu
Maciek Sakrejda <msakrejda@truviso.com> writes:
>> But to the last part of cited protocol specification, when I've sent message with statement parameter's type int4,
int8,varchar the format
>> field wasn't set to 0, but 1.
> I wasn't able to reproduce that with my standalone test case. When I
> changed the parameter oid to 23, I still got the same behavior. Can
> you alter my test case to reproduce the error?
I'd be really surprised if that affected the server-side behavior.
OTOH, it seems possible that the JDBC driver might behave differently
depending on whether parameter types were prespecified or not --- it
might issue Describe earlier in order to get the parameter types,
perhaps.
regards, tom lane
> OTOH, it seems possible that the JDBC driver might behave differently
> depending on whether parameter types were prespecified or not --- it
> might issue Describe earlier in order to get the parameter types,
> perhaps.
Ah. Bingo:
boolean describeStatement = describeOnly || (!oneShot &&
paramsHasUnknown && queryHasUnknown && !query.isStatementDescribed());
---
Maciek Sakrejda | System Architect | Truviso
1065 E. Hillsdale Blvd., Suite 215
Foster City, CA 94404
(650) 242-3500 Main
www.truviso.com
Hm... I moved Bind before Describe, I now have
// Construct a new portal if needed.
Portal portal = null;
if (usePortal)
{
String portalName = "C_" + (nextUniqueID++);
portal = new Portal(query, portalName);
}
sendBind(query, params, portal, noBinaryTransfer);
if (describeStatement) {
sendDescribeStatement(query, params, describeOnly);
if (describeOnly)
return;
}
still nothing
21:43:02.263 (26) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@337ec9f7,
maxRows=0, fetchSize=0, flags=16
21:43:02.264 (26) FE=> Parse(stmt=S_1,query="SELECT $1::int",oids={0})
21:43:02.264 (26) FE=> Bind(stmt=S_1,portal=null,$1=<'2'>)
21:43:02.264 (26) FE=> Describe(statement=S_1)
21:43:02.264 (26) FE=> Execute(portal=null,limit=0)
21:43:02.265 (26) FE=> Sync
21:43:02.265 (26) <=BE ParseComplete [S_1]
21:43:02.265 (26) <=BE BindComplete [null]
21:43:02.266 (26) <=BE ParameterDescription
21:43:02.266 (26) <=BE RowDescription(1)
21:43:02.266 (26) Field(,INT4,4,T)
21:43:02.266 (26) <=BE DataRow(len=4)
21:43:02.267 (26) <=BE CommandStatus(SELECT 1)
21:43:02.267 (26) <=BE ReadyForQuery(I)
If I've understood well I should get proper result after 1st bind...?
On Thu, 25 Nov 2010 12:21:39 -0800, Maciek Sakrejda
<msakrejda@truviso.com>
wrote:
>> OTOH, it seems possible that the JDBC driver might behave differently
>> depending on whether parameter types were prespecified or not --- it
>> might issue Describe earlier in order to get the parameter types,
>> perhaps.
>
> Ah. Bingo:
>
> boolean describeStatement = describeOnly || (!oneShot &&
> paramsHasUnknown && queryHasUnknown && !query.isStatementDescribed());
>
>
> ---
> Maciek Sakrejda | System Architect | Truviso
>
> 1065 E. Hillsdale Blvd., Suite 215
> Foster City, CA 94404
> (650) 242-3500 Main
> www.truviso.com
--
----------
Radosław Smogura
http://www.softperience.eu
> 21:43:02.264 (26) FE=> Describe(statement=S_1) You're still doing the statement-flavor Describe. As Tom pointed out, this won't tell you the result types because it doesn't know them. Actually, technically if you issue a statement-flavor Describe *after* a Bind, the server does have this information, but I'm not surprised that it doesn't send it correctly, since it seems pointless to send the statement variation after already doing a Bind. You may be able to change the JDBC code to call sendDescribePortal() instead. --- Maciek Sakrejda | System Architect | Truviso 1065 E. Hillsdale Blvd., Suite 215 Foster City, CA 94404 (650) 242-3500 Main www.truviso.com
Maciek Sakrejda <msakrejda@truviso.com> writes:
>> 21:43:02.264 (26) FE=> Describe(statement=S_1)
> You're still doing the statement-flavor Describe. As Tom pointed out,
> this won't tell you the result types because it doesn't know them.
> Actually, technically if you issue a statement-flavor Describe *after*
> a Bind, the server does have this information, but I'm not surprised
> that it doesn't send it correctly, since it seems pointless to send
> the statement variation after already doing a Bind.
In principle you could open more than one Portal off a Statement
at the same time, so it wouldn't necessarily be well-defined anyway.
regards, tom lane
Thank you, but I think about this last night. Opening unnecessary portals isn't good idea, similarly sending 2nd describe when statement was prepared. Currently JDBC drivers doesn't make this. I think better will be to store what format we had requested on stack, and then coerce those formats when results are handled. Kind regards, Radosław Smogura On Fri, 26 Nov 2010 01:02:25 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Maciek Sakrejda <msakrejda@truviso.com> writes: >>> 21:43:02.264 (26) FE=> Describe(statement=S_1) >> You're still doing the statement-flavor Describe. As Tom pointed out, >> this won't tell you the result types because it doesn't know them. >> Actually, technically if you issue a statement-flavor Describe *after* >> a Bind, the server does have this information, but I'm not surprised >> that it doesn't send it correctly, since it seems pointless to send >> the statement variation after already doing a Bind. > > In principle you could open more than one Portal off a Statement > at the same time, so it wouldn't necessarily be well-defined anyway. > > regards, tom lane -- ---------- Radosław Smogura http://www.softperience.eu
This what I done is 1. Send bind 2. Put on stack the requested format types 3. On bind complete get requestedFormats from stack. 4. When execute is complete (or portal suspend) then, use requestedFormats to change the field formats received from describe or previously cached. I assume server can't change formats after bind, even the describe portal was fired. Is it all good? I don't know much about server internals. Kind regards, Radek. On Fri, 26 Nov 2010 01:02:25 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Maciek Sakrejda <msakrejda@truviso.com> writes: >>> 21:43:02.264 (26) FE=> Describe(statement=S_1) >> You're still doing the statement-flavor Describe. As Tom pointed out, >> this won't tell you the result types because it doesn't know them. >> Actually, technically if you issue a statement-flavor Describe *after* >> a Bind, the server does have this information, but I'm not surprised >> that it doesn't send it correctly, since it seems pointless to send >> the statement variation after already doing a Bind. > > In principle you could open more than one Portal off a Statement > at the same time, so it wouldn't necessarily be well-defined anyway. > > regards, tom lane -- ---------- Radosław Smogura http://www.softperience.eu