Thread: very interesting JDBC problem ...

very interesting JDBC problem ...

From
Hans-Jürgen Schönig
Date:
Hi everybody,

I am facing an interesting problem with some JDBC drivers. I am doi9ng
some fairly simple SQL:


microtec=# UPDATE t_consoleserver SET data = data || '021011014504'
WHERE procid = '47';
UPDATE 1


My program gives me the following logging information:


[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: old data in db:
[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: adding data to buffer:
(021011014504)
[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: DSQL: UPDATE t_consoleserver
SET data = data || '021011014504' WHERE procid = '57'
[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: cannot update data in database:
ERROR: invalid message format

The code is fairly simple:


                 Elog.Elog("old data in db: " + this.readOnly());
                 Elog.Elog("adding data to buffer: (" + newdata + ")");

                 try
                 {
                         String dsql = "UPDATE t_consoleserver "
                                 + "SET data = data || '" + newdata
                                 + "' WHERE procid = '" + procid + "' ";
                         Elog.Elog("DSQL: " + dsql);

                         stmt.executeUpdate(dsql);
                 }
                 catch (Exception e)
                 {
                         Elog.Elog("cannot update data in database: "
                + e.getMessage());
                 }

                 curpos += newdata.length();


The interesting thing here is that I have used the same code with the
JDBC driver which is included in 7.3. It did not work as well but the
error message was different. "tail -f postgres_log" told me that only
half of the query has been transmitted to the server:

UPDATE t_consoleserver SET data = data || '021011014504

The rest has been discarded silently. PostgreSQL complains that there is
a syntax error or course.
Removing "|| '021011014504' " solved the problem and the entire query
was transmitted as well.

By the way: "invalid message format" is sent by build 301.
Did anybody encounter similar problem?
I coded SQL statement number 1.0000000000000....000000 in this
application but the only statement making use of || seems to cause problems.

Did anybody encounter similar problems?

    Regards,

        Hans


--
Cybertec Geschwinde u Schoenig
Schoengrabern 134, A-2020 Hollabrunn, Austria
Tel: +43/2952/30706 or +43/664/233 90 75
www.cybertec.at, www.postgresql.at, kernel.cybertec.at


Re: very interesting JDBC problem ...

From
Hans-Jürgen Schönig
Date:
Dave Cramer wrote:
> What do the logs from postgres show ?
>
> Dave


Hi Dave,

In case of the old JDBC driver they show me an incomplete SQL statement
followed by a syntax error.
In case of build 301 it tells me "ERROR: invalid message format"
I have checked the source code of PostgreSQL briefly - it seems to be a
protocol problem:


/* --------------------------------
  *              pq_getmsgend    - verify message fully consumed
  * --------------------------------
  */
void
pq_getmsgend(StringInfo msg)
{
         if (msg->cursor != msg->len)
                 ereport(ERROR,
                                 (errcode(ERRCODE_PROTOCOL_VIOLATION),
                                  errmsg("invalid message format")));
}
"backend/libpq/pqformat.c" 688L, 18526C


I haven't found this message anywhere else.

    Regards,

        Hans




> On Wed, 2004-03-31 at 15:31, Hans-Jürgen Schönig wrote:
>
>>Hi everybody,
>>
>>I am facing an interesting problem with some JDBC drivers. I am doi9ng
>>some fairly simple SQL:
>>
>>
>>microtec=# UPDATE t_consoleserver SET data = data || '021011014504'
>>WHERE procid = '47';
>>UPDATE 1
>>
>>
>>My program gives me the following logging information:
>>
>>
>>[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: old data in db:
>>[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: adding data to buffer:
>>(021011014504)
>>[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: DSQL: UPDATE t_consoleserver
>>SET data = data || '021011014504' WHERE procid = '57'
>>[Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: cannot update data in database:
>>ERROR: invalid message format
>>
>>The code is fairly simple:
>>
>>
>>                 Elog.Elog("old data in db: " + this.readOnly());
>>                 Elog.Elog("adding data to buffer: (" + newdata + ")");
>>
>>                 try
>>                 {
>>                         String dsql = "UPDATE t_consoleserver "
>>                                 + "SET data = data || '" + newdata
>>                                 + "' WHERE procid = '" + procid + "' ";
>>                         Elog.Elog("DSQL: " + dsql);
>>
>>                         stmt.executeUpdate(dsql);
>>                 }
>>                 catch (Exception e)
>>                 {
>>                         Elog.Elog("cannot update data in database: "
>>                + e.getMessage());
>>                 }
>>
>>                 curpos += newdata.length();
>>
>>
>>The interesting thing here is that I have used the same code with the
>>JDBC driver which is included in 7.3. It did not work as well but the
>>error message was different. "tail -f postgres_log" told me that only
>>half of the query has been transmitted to the server:
>>
>>UPDATE t_consoleserver SET data = data || '021011014504
>>
>>The rest has been discarded silently. PostgreSQL complains that there is
>>a syntax error or course.
>>Removing "|| '021011014504' " solved the problem and the entire query
>>was transmitted as well.
>>
>>By the way: "invalid message format" is sent by build 301.
>>Did anybody encounter similar problem?
>>I coded SQL statement number 1.0000000000000....000000 in this
>>application but the only statement making use of || seems to cause problems.
>>
>>Did anybody encounter similar problems?
>>
>>    Regards,
>>
>>        Hans


--
Cybertec Geschwinde u Schoenig
Schoengrabern 134, A-2020 Hollabrunn, Austria
Tel: +43/2952/30706 or +43/664/233 90 75
www.cybertec.at, www.postgresql.at, kernel.cybertec.at


Re: very interesting JDBC problem ...

From
Dave Cramer
Date:
What do the logs from postgres show ?

Dave
On Wed, 2004-03-31 at 15:31, Hans-Jürgen Schönig wrote:
> Hi everybody,
>
> I am facing an interesting problem with some JDBC drivers. I am doi9ng
> some fairly simple SQL:
>
>
> microtec=# UPDATE t_consoleserver SET data = data || '021011014504'
> WHERE procid = '47';
> UPDATE 1
>
>
> My program gives me the following logging information:
>
>
> [Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: old data in db:
> [Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: adding data to buffer:
> (021011014504)
> [Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: DSQL: UPDATE t_consoleserver
> SET data = data || '021011014504' WHERE procid = '57'
> [Mar 31, 2004 10:16:01 PM] - 0 - NOTICE: cannot update data in database:
> ERROR: invalid message format
>
> The code is fairly simple:
>
>
>                  Elog.Elog("old data in db: " + this.readOnly());
>                  Elog.Elog("adding data to buffer: (" + newdata + ")");
>
>                  try
>                  {
>                          String dsql = "UPDATE t_consoleserver "
>                                  + "SET data = data || '" + newdata
>                                  + "' WHERE procid = '" + procid + "' ";
>                          Elog.Elog("DSQL: " + dsql);
>
>                          stmt.executeUpdate(dsql);
>                  }
>                  catch (Exception e)
>                  {
>                          Elog.Elog("cannot update data in database: "
>                 + e.getMessage());
>                  }
>
>                  curpos += newdata.length();
>
>
> The interesting thing here is that I have used the same code with the
> JDBC driver which is included in 7.3. It did not work as well but the
> error message was different. "tail -f postgres_log" told me that only
> half of the query has been transmitted to the server:
>
> UPDATE t_consoleserver SET data = data || '021011014504
>
> The rest has been discarded silently. PostgreSQL complains that there is
> a syntax error or course.
> Removing "|| '021011014504' " solved the problem and the entire query
> was transmitted as well.
>
> By the way: "invalid message format" is sent by build 301.
> Did anybody encounter similar problem?
> I coded SQL statement number 1.0000000000000....000000 in this
> application but the only statement making use of || seems to cause problems.
>
> Did anybody encounter similar problems?
>
>     Regards,
>
>         Hans
--
Dave Cramer
519 939 0336
ICQ # 14675561


Re: very interesting JDBC problem ...

From
Oliver Jowett
Date:
Hans-Jürgen Schönig wrote:
>                         String dsql = "UPDATE t_consoleserver "
>                                 + "SET data = data || '" + newdata
>                                 + "' WHERE procid = '" + procid + "' ";
>                         Elog.Elog("DSQL: " + dsql);
>
>                         stmt.executeUpdate(dsql);

> The interesting thing here is that I have used the same code with the
> JDBC driver which is included in 7.3. It did not work as well but the
> error message was different. "tail -f postgres_log" told me that only
> half of the query has been transmitted to the server:
>
> UPDATE t_consoleserver SET data = data || '021011014504
>
> The rest has been discarded silently. PostgreSQL complains that there is
> a syntax error or course.
> Removing "|| '021011014504' " solved the problem and the entire query
> was transmitted as well.
>
> By the way: "invalid message format" is sent by build 301.
> Did anybody encounter similar problem?
> I coded SQL statement number 1.0000000000000....000000 in this
> application but the only statement making use of || seems to cause
> problems.

'newdata' contains a literal \0 and you are not escaping it correctly.
The v2 protocol treats the \0 as a message separator and much confusion
ensues. Note that you probably won't see the \0 in your debug logs --
I've noticed that it can get silently removed when encoding String ->
actual output encoding. You'll see the \0 if you print the individual
values of the array returned by newdata.toCharArray() as integers.

Improving the driver code so it detects and rejects this type of query
with a more useful error message is on my todo list.

I'd suggest that you use a PreparedStatement for parameterized queries;
the driver knows how to correctly escape parameters (which you're not
doing at all -- better hope that newdata doesn't contain a single quote
or backslash!) and will reject a String containing \0s with a useful error.

-O

Re: very interesting JDBC problem ...

From
Hans-Jürgen Schönig
Date:
Oliver Jowett wrote:
> Hans-Jürgen Schönig wrote:
>
>>                         String dsql = "UPDATE t_consoleserver "
>>                                 + "SET data = data || '" + newdata
>>                                 + "' WHERE procid = '" + procid + "' ";
>>                         Elog.Elog("DSQL: " + dsql);
>>
>>                         stmt.executeUpdate(dsql);
>
>
>> The interesting thing here is that I have used the same code with the
>> JDBC driver which is included in 7.3. It did not work as well but the
>> error message was different. "tail -f postgres_log" told me that only
>> half of the query has been transmitted to the server:
>>
>> UPDATE t_consoleserver SET data = data || '021011014504
>>
>> The rest has been discarded silently. PostgreSQL complains that there
>> is a syntax error or course.
>> Removing "|| '021011014504' " solved the problem and the entire query
>> was transmitted as well.
>>
>> By the way: "invalid message format" is sent by build 301.
>> Did anybody encounter similar problem?
>> I coded SQL statement number 1.0000000000000....000000 in this
>> application but the only statement making use of || seems to cause
>> problems.
>
>
> 'newdata' contains a literal \0 and you are not escaping it correctly.
> The v2 protocol treats the \0 as a message separator and much confusion
> ensues. Note that you probably won't see the \0 in your debug logs --
> I've noticed that it can get silently removed when encoding String ->
> actual output encoding. You'll see the \0 if you print the individual
> values of the array returned by newdata.toCharArray() as integers.
>
> Improving the driver code so it detects and rejects this type of query
> with a more useful error message is on my todo list.
>
> I'd suggest that you use a PreparedStatement for parameterized queries;
> the driver knows how to correctly escape parameters (which you're not
> doing at all -- better hope that newdata doesn't contain a single quote
> or backslash!) and will reject a String containing \0s with a useful error.

Oh, I see.
Somehow this little symbol got in there. That's the problem. I did not
think about that because obviously my logging function has done it
right. I did not JDBC to behave differently.
The message returned by PostgreSQL made me think of a JDBC bug.

You have saved me some JDBC-internal work :).

    Thanks a lot,

        Hans

--
Cybertec Geschwinde u Schoenig
Schoengrabern 134, A-2020 Hollabrunn, Austria
Tel: +43/2952/30706 or +43/664/233 90 75
www.cybertec.at, www.postgresql.at, kernel.cybertec.at