Re: invalid message format and I/O error while comunicating with backend

Hello

I have a small server written in java. It receives data through UDP ports, and queues data until several working threads process the data.
The process involves launching several prepared statements selects/inserts over different db schemas for every data packet received.

The server and the database are both on the same machine. I would like to have a moderate to high level of throughput, as I'm interested in being able to
receive several data per second.

Everything is working ok and fast, but at some moment (sometimes sooner, sometimes later) the server starts to fail with the following messages

org.postgresql.util.PSQLException: invalid message format (for the first failure)
org.postgresql.util.PSQLException: A I/O error has happened while sending to backend (at every following jdbc call)

(Message errors are freely translated from the original spanish messages)

At first I though it was because of connection pooling, but I have tried it with and without pooling with no success.
Every working thread has one connection which last for as long as the program is running. This single connection per thread is used to access several schemas of the same data base.

It seems that sending data to the server faster makes the error to appear sooner.

I have'nt foound any suitable clue about it while googleing.. so I hope someone can help me here

More data:
Java(TM) SE Runtime Environment (build 1.6.0_03-b05)
PostgreSQL 8.1.10 (Ubuntu)
postgresql-8.2-507.jdbc4.jar

commons-dbcp-1.2.2
commons-pool-1.3

Thanks in advance

--
<http://www.emovilia.com/>

Sergio Vera
Rosellón, 34, 5 Planta
08029 Barcelona
tel. 902101870
www.emovilia.com

IMPRIME ESTE EMAIL Y SUS ARCHIVOS SI REALMENTE LOS NECESITAS.
GRACIAS POR RESPETAR EL MEDIO AMBIENTE.

NOTA: La información contenida en este email, y sus documentos adjuntos,
es confidencial y para uso exclusivo de la persona o personas a las que
va dirigido. No está permitido el acceso a este mensaje a otra persona
distinta a los indicados. Si no es uno de los destinatarios o ha
recibido este mensaje por error, cualquier duplicación, reproducción,
distribución, así como cualquier uso de la información contenida o
cualquiera otra acción tomada en relación con el mismo, está prohibida y
puede ser ilegal.

ADVICE: The information in this email as in the attachments is
confidential and private for exclusive use of the target user group.
Access to this message is disallowed to any other than the addressee. If
you are not the addressee or you have been included by mistake, any
duplication, reproduction, distribution as any other action relative to
this email is strictly forbidden and might be illegal.

Sergi Vera wrote:

> Everything is working ok and fast, but at some moment (sometimes sooner,
> sometimes later) the server starts to fail with the following messages
>
> org.postgresql.util.PSQLException: invalid message format (for the first
> failure)
> org.postgresql.util.PSQLException: A I/O error has happened while
> sending to backend (at every following jdbc call)

I suggest having a look in the server logs to see if there is any error
being reported by the backend.

You might also find it helpful to enable log_statement and
log_connection in postgresql.conf while you're trying to track the issue
down. Your logs might get quite big if your load is high, though.

--
Craig Ringer

Thanks Craig,

Browsing the pgsql logs I've found the following error messages (roughly
translated to english):

(autovacuums)
...
(autovacuums)
ERROR: remaining data on the message is not sufficient
FATAL: message type from the frontend 0 is not valid

I just don't understand why sometimes it fails and sometimes not.

I will try the other suggestion you made as soon as possible

Craig Ringer escribió:
> Sergi Vera wrote:
>
>
>> Everything is working ok and fast, but at some moment (sometimes sooner,
>> sometimes later) the server starts to fail with the following messages
>>
>> org.postgresql.util.PSQLException: invalid message format (for the first
>> failure)
>> org.postgresql.util.PSQLException: A I/O error has happened while
>> sending to backend (at every following jdbc call)
>>
>
> I suggest having a look in the server logs to see if there is any error
> being reported by the backend.
>
> You might also find it helpful to enable log_statement and
> log_connection in postgresql.conf while you're trying to track the issue
> down. Your logs might get quite big if your load is high, though.
>
> --
> Craig Ringer
>
>

--
<http://www.emovilia.com/>

Sergio Vera
Rosellón, 34, 5 Planta
08029 Barcelona
tel. 902101870
www.emovilia.com

IMPRIME ESTE EMAIL Y SUS ARCHIVOS SI REALMENTE LOS NECESITAS.
GRACIAS POR RESPETAR EL MEDIO AMBIENTE.

NOTA: La información contenida en este email, y sus documentos adjuntos,
es confidencial y para uso exclusivo de la persona o personas a las que
va dirigido. No está permitido el acceso a este mensaje a otra persona
distinta a los indicados. Si no es uno de los destinatarios o ha
recibido este mensaje por error, cualquier duplicación, reproducción,
distribución, así como cualquier uso de la información contenida o
cualquiera otra acción tomada en relación con el mismo, está prohibida y
puede ser ilegal.

ADVICE: The information in this email as in the attachments is
confidential and private for exclusive use of the target user group.
Access to this message is disallowed to any other than the addressee. If
you are not the addressee or you have been included by mistake, any
duplication, reproduction, distribution as any other action relative to
this email is strictly forbidden and might be illegal.

Adding more logs doesn't give any more clue:

(...)

LOG: sentencia: EXECUTE unnamed [PREPARE: COMMIT]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: BEGIN]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT * FROM loctest.posicion, loctest.datosensor WHERE id_activo = $1 AND posicion.idposicion = datosensor.idposicion AND idsensor = 2 ORDER BY time DESC LIMIT 1]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT * FROM loctest.posicion, loctest.datosensor WHERE id_activo = $1 AND posicion.idposicion = datosensor.idposicion AND idsensor = 2 ORDER BY time DESC LIMIT 1]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT * FROM loctest.pois]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT * FROM loctest.pois]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT current FROM loctest.id_pos_seq_view]

LOG: sentencia: BIND

LOG: sentencia: EXECUTE unnamed [PREPARE: SELECT current FROM loctest.id_pos_seq_view]

LOG: sentencia: BIND

ERROR: message format invalid

FATAL: message type of frontend 0 is not valid

Besides this unnamed that appears on the sentences not much more info is shown on the logs.

Sometimes the number associated whith the fronted changes Sometimes it's 0 sometimes it's 255..

Regards

Sergi Vera escribió:

Thanks Craig,

Browsing the pgsql logs I've found the following error messages (roughly translated to english):

(autovacuums)

...

(autovacuums)

ERROR: remaining data on the message is not sufficient

FATAL: message type from the frontend 0 is not valid

I just don't understand why sometimes it fails and sometimes not.

I will try the other suggestion you made as soon as possible

Craig Ringer escribió:

Sergi Vera wrote:

Everything is working ok and fast, but at some moment (sometimes sooner,

sometimes later) the server starts to fail with the following messages

org.postgresql.util.PSQLException: invalid message format (for the first

failure)

org.postgresql.util.PSQLException: A I/O error has happened while

sending to backend (at every following jdbc call)

I suggest having a look in the server logs to see if there is any error

being reported by the backend.

You might also find it helpful to enable log_statement and

log_connection in postgresql.conf while you're trying to track the issue

down. Your logs might get quite big if your load is high, though.

--

Craig Ringer

--

/*<![CDATA[*/
<!--
@page { size: 21cm 29.7cm; margin: 2cm }
P { margin-bottom: 0.21cm }
-->
/*]]>*/

Sergio Vera

Rosellón, 34, 5 Planta

08029 Barcelona

tel. 902101870

www.emovilia.com

IMPRIME ESTE EMAIL Y SUS ARCHIVOS SI REALMENTE LOS NECESITAS.

GRACIAS POR RESPETAR EL MEDIO AMBIENTE.

NOTA: La información contenida en este email, y sus documentos adjuntos, es confidencial y para uso exclusivo de la persona o personas a las que va dirigido. No está permitido el acceso a este mensaje a otra persona distinta a los indicados. Si no es uno de los destinatarios o ha recibido este mensaje por error, cualquier duplicación, reproducción, distribución, así como cualquier uso de la información contenida o cualquiera otra acción tomada en relación con el mismo, está prohibida y puede ser ilegal.

ADVICE: The information in this email as in the attachments is confidential and private for exclusive use of the target user group. Access to this message is disallowed to any other than the addressee. If you are not the addressee or you have been included by mistake, any duplication, reproduction, distribution as any other action relative to this email is strictly forbidden and might be illegal.

On Mon, 14 Apr 2008, Sergi Vera wrote:

> ERROR: message format invalid
> FATAL: message type of frontend 0 is not valid
>
> Besides this <unnamed> that appears on the sentences not much more info
> is shown on the logs.
> Sometimes the number associated whith the fronted changes Sometimes it's
> 0 sometimes it's 255..
>

This makes it look like the JDBC driver is doing something wrong when
calculating a message length or message content for the frontend/backend
protocol. If you've got a self-contained test case we could take a
look at that. If not can you try adding loglevel=2 to your JDBC URL to
get debugging information from the driver? Also capturing the network
traffic with tcpdump would be interesting.

Kris Jurka

Sergi Vera wrote:
> Thanks Kris for the help
>
> Adding loglevel=2 dind't add any more info on logs, and it will be not
> easy to make a self contained program, but I have attached the result of

The loglevel=2 logging will go to the driver's System.out not into the
server error log.

> tcpdump -vvv -i lo -w pgsqlerror2.dat
>

This only captures the start of each packet so it doesn't have the whole
thing. Could you recapture with:

tcpdump -n -w pgsqlerror3.dat -s 1514 -i any tcp port 5432

This ups the capture size (-s 1514) and also filters out the unrelated
UDP traffic you've got going on.

> Browsing through the first failing pgsql data chunk, one can see that:
>
> http://img139.imageshack.us/my.php?image=pantallazolm8.png
>
> The last data has column lenght -1 which seems strange even if I don'k
> know anything of this particular protocol
>

-1 length indicates a NULL value, so that's expected.

This appears to be a thread safety related problem. I believe your code
has one thread setting the parameter values and another thread executing
the prepared statement at the same time. The executor does two passes
through the parameter list, once to calculate a total message length and
another time to send the values. If the contents change between the
length calculation and the message sending we'll have the wrong length
and the whole client-server communication gets messed up. The attached
test case demonstrates this failure mode.

I'm unsure how hard we should try to fix this, there are a couple of
approaches:

1) Do nothing. It's really a client problem and they shouldn't be
setting and executing at the same time.

2) Just copy the parameters at execution time so we get a consistent
view of them. This may not be exactly what the user wants though if the
order things actually execute is: execute, set, copy instead of
execute, copy, set.

3) Go through all the PreparedStatement functions making most of them
synchronized so that you cannot set while an execute is running.

Kris Jurka

Sergi Vera wrote:
> Hi!
>
> I've been a little busy thoose days and was unable to work on this, but
> I've made the tcpdump session that you requested and
> here are the results
>
>
> Kris Jurka escribió:
>> Sergi Vera wrote:
>>> Thanks Kris for the help
>>>
>>> Adding loglevel=2 dind't add any more info on logs, and it will be
>>> not easy to make a self contained program, but I have attached the
>>> result of
>>
>> The loglevel=2 logging will go to the driver's System.out not into the
>> server error log.
>>
>>> tcpdump -vvv -i lo -w pgsqlerror2.dat
>>>
>>
>> This only captures the start of each packet so it doesn't have the
>> whole thing. Could you recapture with:
>>
>> tcpdump -n -w pgsqlerror3.dat -s 1514 -i any tcp port 5432
>>
>> This ups the capture size (-s 1514) and also filters out the unrelated
>> UDP traffic you've got going on.
>>
>>> Browsing through the first failing pgsql data chunk, one can see that:
>>>
>>> http://img139.imageshack.us/my.php?image=pantallazolm8.png
>>>
>>> The last data has column lenght -1 which seems strange even if I
>>> don'k know anything of this particular protocol
>>>
>>
>> -1 length indicates a NULL value, so that's expected.
>>
>
>

Yes, your are right

It is a problem related with multiple threads working on the same Prepared Statement.

I have modified the code to run with one single thread and it runs very smoothly.

Previously there were more than one thread working onthe same prepared statements (they were created at server startup) Even if the code already included some synchronization code, it seems I was loosing control of the threads.

I will modify the code, and make sure every thread has his own Prepared Statements.

I thought that sharing the same prepared statements was more efficient.

Thanks

Kris Jurka escribió:

This appears to be a thread safety related problem. I believe your code has one thread setting the parameter values and another thread executing the prepared statement at the same time. The executor does two passes through the parameter list, once to calculate a total message length and another time to send the values. If the contents change between the length calculation and the message sending we'll have the wrong length and the whole client-server communication gets messed up. The attached test case demonstrates this failure mode.

I'm unsure how hard we should try to fix this, there are a couple of approaches:

1) Do nothing. It's really a client problem and they shouldn't be setting and executing at the same time.

2) Just copy the parameters at execution time so we get a consistent view of them. This may not be exactly what the user wants though if the order things actually execute is: execute, set, copy instead of execute, copy, set.

3) Go through all the PreparedStatement functions making most of them synchronized so that you cannot set while an execute is running.

Kris Jurka

Sergi Vera wrote:

Hi!

I've been a little busy thoose days and was unable to work on this, but I've made the tcpdump session that you requested and

here are the results

Kris Jurka escribió:

Sergi Vera wrote:

Thanks Kris for the help

Adding loglevel=2 dind't add any more info on logs, and it will be not easy to make a self contained program, but I have attached the result of

The loglevel=2 logging will go to the driver's System.out not into the server error log.

tcpdump -vvv -i lo -w pgsqlerror2.dat

This only captures the start of each packet so it doesn't have the whole thing. Could you recapture with:

tcpdump -n -w pgsqlerror3.dat -s 1514 -i any tcp port 5432

This ups the capture size (-s 1514) and also filters out the unrelated UDP traffic you've got going on.

Browsing through the first failing pgsql data chunk, one can see that:

http://img139.imageshack.us/my.php?image=pantallazolm8.png

The last data has column lenght -1 which seems strange even if I don'k know anything of this particular protocol

-1 length indicates a NULL value, so that's expected.

--

/*<![CDATA[*/
<!--
@page { size: 21cm 29.7cm; margin: 2cm }
P { margin-bottom: 0.21cm }
-->
/*]]>*/

Sergio Vera

Rosellón, 34, 5 Planta

08029 Barcelona

tel. 902101870

www.emovilia.com

IMPRIME ESTE EMAIL Y SUS ARCHIVOS SI REALMENTE LOS NECESITAS.

GRACIAS POR RESPETAR EL MEDIO AMBIENTE.

NOTA: La información contenida en este email, y sus documentos adjuntos, es confidencial y para uso exclusivo de la persona o personas a las que va dirigido. No está permitido el acceso a este mensaje a otra persona distinta a los indicados. Si no es uno de los destinatarios o ha recibido este mensaje por error, cualquier duplicación, reproducción, distribución, así como cualquier uso de la información contenida o cualquiera otra acción tomada en relación con el mismo, está prohibida y puede ser ilegal.

ADVICE: The information in this email as in the attachments is confidential and private for exclusive use of the target user group. Access to this message is disallowed to any other than the addressee. If you are not the addressee or you have been included by mistake, any duplication, reproduction, distribution as any other action relative to this email is strictly forbidden and might be illegal.