pool exahusted (exhausted) and SocketException

Diego Algorta Casamayou

unread,

Oct 13, 2006, 10:51:06 AM10/13/06

to jpos-...@googlegroups.com

Hi there.

I'm having two related (I think) problems.

1. Each time our client terminals (Verifone with C programs using the
iso8583.c library) disconnects from our jPOS server, we see 2
Exceptions on the q2.log. That wasn't a real problem until now because
the transactions concluded ok. But...

2. We are testing the server (very light, we're sending 6 0800
messages per minute) and after some hours of continuous excecution, it
starts saying that the ThreadPool is exhausted (It says exahusted, but
that's wrong :-D ). So it doesn't accept more transactions until I
restart the service. I can't go to production like this.

Here's an example:

<log realm="servidor.server.session/10.204.2.53" at="Wed Oct 11
20:35:56 GMT-02:00 2006.119">
<session-start/>
</log>
<log realm="servidor.server.channel/10.204.2.53:1473" at="Wed Oct 11
20:35:56 GMT-02:00 2006.119">
<receive>
<isomsg direction="incoming">
<field id="0" value="0800"/>
<field id="3" value="150100"/>
<field id="46" value="01060905"/>
</isomsg>
</receive>
</log>
<log realm="servidor.server.channel/10.204.2.53:1473" at="Wed Oct 11
20:35:56 GMT-02:00 2006.120">
<send>
<isomsg direction="outgoing">
<field id="0" value="0810"/>
<field id="3" value="150100"/>
<field id="39" value="00"/>
<field id="46" value="1234567890"/>
</isomsg>
</send>
</log>
<log realm="servidor.server" at="Wed Oct 11 20:35:56 GMT-02:00 2006.595">
<warn>
pool exahusted ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8000]
<thread-pool name="ThreadPool-0">
<jobs>85019</jobs>
<size>100</size>
<max>100</max>
<idle>0</idle>
<pending>1</pending>
</thread-pool>
</warn>
</log>
<log realm="servidor.server.channel/10.204.2.53:1473" at="Wed Oct 11
20:35:56 GMT-02:00 2006.687">
<receive>
<exception name="Connection reset">
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.DataInputStream.readFully(DataInputStream.java:176)
at org.jpos.iso.channel.ASCIIChannel.getMessageLength(ASCIIChannel.java:130)
at org.jpos.iso.BaseChannel.receive(BaseChannel.java:525)
at org.jpos.iso.ISOServer$Session.run(ISOServer.java:123)
at org.jpos.util.ThreadPool$PooledThread.run(ThreadPool.java:100)
</exception>
</receive>
</log>
<log realm="servidor.server.session/10.204.2.53" at="Wed Oct 11
20:35:56 GMT-02:00 2006.687">
<session-warning>
<exception name="Connection reset">
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.DataInputStream.readFully(DataInputStream.java:176)
at org.jpos.iso.channel.ASCIIChannel.getMessageLength(ASCIIChannel.java:130)
at org.jpos.iso.BaseChannel.receive(BaseChannel.java:525)
at org.jpos.iso.ISOServer$Session.run(ISOServer.java:123)
at org.jpos.util.ThreadPool$PooledThread.run(ThreadPool.java:100)
</exception>
</session-warning>
</log>
<log realm="servidor.server.channel/10.204.2.53:1473" at="Wed Oct 11
20:35:56 GMT-02:00 2006.688">
<disconnect>
null:0
</disconnect>
</log>
<log realm="servidor.server.session/10.204.2.53" at="Wed Oct 11
20:35:56 GMT-02:00 2006.688">
<session-end/>
</log>

Alejandro Revilla

unread,

Oct 13, 2006, 3:10:40 PM10/13/06

to jpos-...@googlegroups.com

>
> 1. Each time our client terminals (Verifone with C programs using the
> iso8583.c library) disconnects from our jPOS server, we see 2
> Exceptions on the q2.log. That wasn't a real problem until now because
> the transactions concluded ok. But...
>

I believe your C program might not be closing your socket properly.
Please have a look at a netstat from your server (jPOS) side in order
to double check you don't have outstanding connections.

Diego Algorta Casamayou

unread,

Oct 13, 2006, 3:48:34 PM10/13/06

to jpos-...@googlegroups.com

2006/10/13, Alejandro Revilla <a...@jpos.org>:

We did that, and nothing strange shows. It doesn't seem to have
pending connections or whatever.
But, it has happened to me that when I shut down the jPOS server it
starts closing down dozens of connections. I think these are the ones
causing the ThreadPool problem.

Here's a minimal example where after undeploying my QServer it starts
ending connections. These connections should have closed "years" ago:

<log realm="Q2.system" at="Thu Oct 12 16:13:51 GMT-02:00 2006.943">
<trace>
undeploying:50_labanca.xml
</trace>
</log>
<log realm="Q2.system" at="Thu Oct 12 16:13:51 GMT-02:00 2006.945">
<info>
undeployed:50_labanca.xml
</info>
</log>
<log realm="labanca_server.server.channel/10.204.2.53:2783" at="Thu
Oct 12 16:13:51 GMT-02:00 2006.946">
<receive/>
</log>
<log realm="labanca_server.server.channel/10.204.2.53:2783" at="Thu
Oct 12 16:13:51 GMT-02:00 2006.947">

The thing is... It would be better if the client behaves ok so it
doesn't fill my threadpool, but I think jPOS should be strong enough
to deal with bad clients, doesn't it?
So, at the client level the assigned programmer is working towards a
solution, but I need to make jPOS stronger so it doesn't go down and
continue serviceing the other clients. What would you suggest me to
do?

Thank you.
Diego

Mark Salter

unread,

Oct 13, 2006, 3:56:14 PM10/13/06

to jpos-...@googlegroups.com

Diego Algorta Casamayou wrote:

> The thing is... It would be better if the client behaves ok so it
> doesn't fill my threadpool, but I think jPOS should be strong enough
> to deal with bad clients, doesn't it?
> So, at the client level the assigned programmer is working towards a
> solution, but I need to make jPOS stronger so it doesn't go down and
> continue serviceing the other clients. What would you suggest me to
> do?

When a Thread dies and is not returned to the ThreadPool, I thought the
Thread name is changed to indicate the non recycle reason. As the pool
dries up, what Thread names do you see, if you run it under a debugger?

--
Mark

Mark Salter

unread,

Oct 13, 2006, 3:58:23 PM10/13/06

to jpos-...@googlegroups.com

Diego Algorta Casamayou wrote:

> We did that, and nothing strange shows. It doesn't seem to have
> pending connections or whatever.
> But, it has happened to me that when I shut down the jPOS server it
> starts closing down dozens of connections. I think these are the ones
> causing the ThreadPool problem.

Is it possible you have manages to make your 'process' Threads loop,
never ending and never being returned to the Pool?

Just a thought.

--
Mark

Alejandro Revilla

unread,

Oct 13, 2006, 3:58:43 PM10/13/06

to jpos-...@googlegroups.com

>
> The thing is... It would be better if the client behaves ok so it
> doesn't fill my threadpool, but I think jPOS should be strong enough
> to deal with bad clients, doesn't it?
>

How would you identify a bad versus a good client provided all of them
seem to be connected at the TCP/IP level?

>
> So, at the client level the assigned programmer is working towards a
> solution, but I need to make jPOS stronger so it doesn't go down and
> continue serviceing the other clients. What would you suggest me to
> do?
>

I would specify a timeout at the server's channel level, if a terminal
doesn't send a message in say one minute, the timeout would drop down
that channel.

I didn't test this, but if your terminals are to send one message per
connection, you could close the socket after sending back a response in
your ISORequestListener implementation (you may have to cast your
ISOSource to an ISOChannel in order to be able to call ISOChannel.disconnect()).

If you care to try the latter, please let us know if that works for you
(it should, but we may have to reduce some logging if it gets too verbose).

Alejandro Revilla

unread,

Oct 13, 2006, 4:19:27 PM10/13/06

to jpos-...@googlegroups.com

>
> Is it possible you have manages to make your 'process' Threads loop,
> never ending and never being returned to the Pool?
>
> Just a thought.
>

That would explain the problem. Can you show us your
ISORequestListener.process implementation? (please remove any
proprietary info, we just want to see the high level flow).

Diego Algorta Casamayou

unread,

Oct 17, 2006, 11:16:37 AM10/17/06

to jpos-...@googlegroups.com

2006/10/13, Alejandro Revilla <a...@jpos.org>:

I don't think there's a problem with my process code... but.
Here's the process source in my ISORequestListener. Consider that I'm
sending just 0800 messages for this testing so the stripped "else"
part doesn't count:

public boolean process(ISOSource source, ISOMsg m) {
if (!source.isConnected()) {
warn("already disconnected - can't process");
return false;
}
String url;
String proccode;
String producto;
String operacion;
String response = "";
proccode = m.getString(FIELD_PROCCODE);
producto = proccode.substring(0, 2);
operacion = proccode.substring(2, 4);
this.servidor = proccode.substring(4, 6);
ISOMsg resMsg = new ISOMsg();
try {
boolean crcOK = validarCRC32(m);
if (crcOK) {
info("CRC32 OK");
} else {
warn("BAD CRC32");
}
boolean ignorarCRC32 = cfg.get("ignore-crc32-" + this.servidor)
.equalsIgnoreCase("true");
if (ignorarCRC32 || crcOK) {
if (m.getMTI().equals("0800")) {
resMsg.set(FIELD_TRANSACTION_DATA,
TRANSACTION_DATA_0800_TEST_RESPONSE);
} else {
// stripped business processing...
}
resMsg.set(FIELD_RESPONSE_CODE, JPOS_RESPONSE_OK);
} else {
resMsg.set(FIELD_RESPONSE_CODE, JPOS_RESPONSE_ERROR);
}
resMsg.setMTI(m.getMTI());
resMsg.set(FIELD_PROCCODE, m.getString(FIELD_PROCCODE));
resMsg.setResponseMTI();
resMsg.set(47, m.getString(47));
resMsg.set(FIELD_CRC32, Long.toString(calcularCRC32(resMsg)));
if (source.isConnected()) {
source.send(resMsg);
}
} catch (Throwable t) {
warn(t);
}
return false;
}

Thank you.

Diego Algorta Casamayou

unread,

Oct 17, 2006, 11:24:45 AM10/17/06

to jpos-...@googlegroups.com

2006/10/13, Alejandro Revilla <a...@jpos.org>:

>
> >
> > The thing is... It would be better if the client behaves ok so it
> > doesn't fill my threadpool, but I think jPOS should be strong enough
> > to deal with bad clients, doesn't it?
> >
> How would you identify a bad versus a good client provided all of them
> seem to be connected at the TCP/IP level?

I mean that a failed disconnection shouldn't have to fill my
ThreadPool. I don't know, maybe a timeout to free the processes?

>
> >
> > So, at the client level the assigned programmer is working towards a
> > solution, but I need to make jPOS stronger so it doesn't go down and
> > continue serviceing the other clients. What would you suggest me to
> > do?
> >
> I would specify a timeout at the server's channel level, if a terminal
> doesn't send a message in say one minute, the timeout would drop down
> that channel.

Ok. So here's the timeout :-D. I'll consider this.

>
> I didn't test this, but if your terminals are to send one message per
> connection, you could close the socket after sending back a response in
> your ISORequestListener implementation (you may have to cast your
> ISOSource to an ISOChannel in order to be able to call ISOChannel.disconnect()).
>
> If you care to try the latter, please let us know if that works for you
> (it should, but we may have to reduce some logging if it gets too verbose).

Ok. Maybe I try this.

Anyway, The client side programmer has come to a conclussion. He has 2
verifone models each with different brand of TCP stack libraries. One
model closes connections ok, and the other don't. Analyzing traffic
with tcpdump and ethereal he sees that the one working ok sens a "FIN"
packet while the other one send a "RST". That explains the "Connection
reset" exception at the server level. But the problem seems to be
inside the library whose code we don't have access to fix that :-(

Diego

Alan Honczar

unread,

Oct 17, 2006, 11:51:39 AM10/17/06

to jpos-...@googlegroups.com

Alejandro,

Some time ago, you oppened my eyes about the same exceptions in the log Diego reported.
What I found is that the most applications prefer to RST the connections than close them gracefully. After all, why exchange more packets if you can send a RST? Jeje...
The channel is logging the exceptions, right? Would you recommend a way for us to hook them and avoid that uncomfortable log?
What do you think about extending the channel and overriding the getMessageLength() to deal with the SocketException?

Thanks again,
Alan

-----Mensagem original-----
De: jpos-...@googlegroups.com [mailto:jpos-...@googlegroups.com] Em nome de Diego Algorta Casamayou
Enviada em: terça-feira, 17 de outubro de 2006 12:25
Para: jpos-...@googlegroups.com
Assunto: Re: pool exahusted (exhausted) and SocketException

Diego

--------

AVISO LEGAL - Esta mensagem e seu conteúdo - inclusive anexos - são para uso exclusivo de seu(s) destinatário(s), podendo conter informações confidenciais e/ou legalmente privilegiadas sobre a APPI Tecnologia S/A. Qualquer modificação, retransmissão, disseminação, impressão ou utilização não autorizada fica estritamente proibida. Se você recebeu esta mensagem por engano, por favor informe ao remetente e apague o material e as cópias de sua máquina.

LEGAL ADVICE - This message - including any attachments - contains confidential and privileged information from APPI Tecnologia S/A intended for the named recipient(s) only. Any modification, copying, printing or distribution of this message or the taking of any action based on it is strictly prohibited. If you have received it by mistake please notify the sender by return e-mail and delete this message from your system.

---------

Só imprima se for realmente necessário.
Cada tonelada de papel poupado economiza de 17 a 20 eucaliptos com 7 anos de idade.
Sua empresa também agradece.

Print only if necessary.
Each ton of non-used paper is equivalent to 17-20 young eucalyptus trees.
Your company will also appreciate this economy.

Mark Salter

unread,

Oct 17, 2006, 5:01:41 PM10/17/06

to jpos-...@googlegroups.com

Diego Algorta Casamayou wrote:

[code snip]

> resMsg.set(FIELD_CRC32, Long.toString(calcularCRC32(resMsg)));
> if (source.isConnected()) {
> source.send(resMsg);
> }

My initial thought was - you only ever return false, perhaps you should
return true after this send occurs.

However I looked at the code in ISOServer that invokes the
ISORequestListener.process(channel,m) and it doesn't appear to make any
difference, although it would be more efficient to return true *if* you
had multiple ISORequestListeners registered with the ISOServer *and*
only a single ISORequestListeners was required to generate a response.

My only other question relates to your call to :-

> boolean crcOK = validarCRC32(m);

this looks like the only 'external' call, is it at all possible that
this does not always return? A 'null' ISOMsg or something occasional
and 'odd'?

--
Mark

Alejandro Revilla

unread,

Oct 17, 2006, 6:22:35 PM10/17/06

to jpos-...@googlegroups.com

Alan,

Thank you for refreshing that issue, I think I know what's happening
here and Diego is right, and this is probably a bug in jPOS. A nasty
one BTW.

While modifying BaseChannel to trap SocketException in the same way we
trap EOFException just to make it less verbose, I suddenly figured out
what might produce that pool exhausted. When we call socket.close()
and we have these half-baked TCP/IP stacks at the other end we are
blocking until the final handshake takes place.

I'm fixing that now,

Diego, are you using jPOS6?

Alejandro Revilla

unread,

Oct 17, 2006, 8:13:57 PM10/17/06

to jpos-...@googlegroups.com

For the records, r2396 (just committed) should fix this issue.

Diego, if you are not getting jPOS off subversion, you can
get a precompiled snapshot here: http://jpos.org/download/jpos-1.6.0.jar

Please let us know if this fixes your problem.

Mark Salter

unread,

Oct 18, 2006, 1:41:02 AM10/18/06

to jpos-...@googlegroups.com

Alejandro Revilla wrote:
> For the records, r2396 (just committed) should fix this issue.

Excellent catch Alejandro.

> Please let us know if this fixes your problem.

Lets hope so, then I might be able to sleep tonight!

--
Mark

Alejandro Revilla

unread,

Oct 18, 2006, 5:20:56 AM10/18/06

to jpos-...@googlegroups.com

> While modifying BaseChannel to trap SocketException in the same way we
> trap EOFException just to make it less verbose, I suddenly figured out
> what might produce that pool exhausted. When we call socket.close()
> and we have these half-baked TCP/IP stacks at the other end we are
> blocking until the final handshake takes place.
>

On a second thought, my brilliant late-night theory is not good in
morning, because Diego saw the socket exception in the logs, that means
that socket.close() was not blocking. Anyways, worth a try, but I
believe we are back at step zero.

Alan Honczar

unread,

Oct 18, 2006, 10:31:16 AM10/18/06

to jpos-...@googlegroups.com

Me again,
A strange thing is that Diego reported that while stopping the JVM, a
lot of connections went down, but the clients disconnected, as the log
says.
I was curious about what a command like "netstat -atun" would return
while the pool is exausted...
Maybe so_linger should be checked.
Check if the POS connects directly to the JPOS server or if there are
network nodes between them...
I do not know what Diego is using for logging, but I found very useful
to log the thread ID in the header, because the thread logs always get
mixed...

Alan

-----Mensagem original-----
De: jpos-...@googlegroups.com [mailto:jpos-...@googlegroups.com] Em

nome de Alejandro Revilla
Enviada em: quarta-feira, 18 de outubro de 2006 06:21
Para: jpos-...@googlegroups.com
Assunto: Re: RES: pool exahusted (exhausted) and SocketException

--------

AVISO LEGAL - Esta mensagem e seu conteudo - inclusive anexos - sao para uso exclusivo de seu(s) destinatario(s), podendo conter informacoes confidenciais e/ou legalmente privilegiadas sobre a APPI Tecnologia S/A. Qualquer modificacao, retransmissao, disseminacao, impressao ou utilizacao nao autorizada fica estritamente proibida. Se voce recebeu esta mensagem por engano, por favor informe ao remetente e apague o material e as copias de sua maquina.

LEGAL ADVICE - This message - including any attachments - contains confidential and privileged information from APPI Tecnologia S/A intended for the named recipient(s) only. Any modification, copying, printing or distribution of this message or the taking of any action based on it is strictly prohibited. If you have received it by mistake please notify the sender by return e-mail and delete this message from your system.

---------

So imprima se for realmente necessario.

Cada tonelada de papel poupado economiza de 17 a 20 eucaliptos com 7 anos de idade.

Sua empresa tambem agradece.

Diego Algorta Casamayou

unread,

Oct 18, 2006, 4:19:25 PM10/18/06

to jpos-...@googlegroups.com

2006/10/18, Alan Honczar <al...@appi.com.br>:

>
> Me again,
> A strange thing is that Diego reported that while stopping the JVM, a
> lot of connections went down, but the clients disconnected, as the log
> says.

I'm sending new data now.

We setted a terminal to stress the server and configured a thread pool
of 20 max to hit the pool exhausted more easily.

Here's a tipical testing transaction:

<receive>
<exception name="Connection reset">
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.DataInputStream.readFully(DataInputStream.java:176)
at org.jpos.iso.channel.ASCIIChannel.getMessageLength(ASCIIChannel.java:130)
at org.jpos.iso.BaseChannel.receive(BaseChannel.java:525)
at org.jpos.iso.ISOServer$Session.run(ISOServer.java:123)
at org.jpos.util.ThreadPool$PooledThread.run(ThreadPool.java:100)
</exception>
</receive>
</log>

<session-warning>
<exception name="Connection reset">
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.DataInputStream.readFully(DataInputStream.java:176)
at org.jpos.iso.channel.ASCIIChannel.getMessageLength(ASCIIChannel.java:130)
at org.jpos.iso.BaseChannel.receive(BaseChannel.java:525)
at org.jpos.iso.ISOServer$Session.run(ISOServer.java:123)
at org.jpos.util.ThreadPool$PooledThread.run(ThreadPool.java:100)
</exception>
</session-warning>
</log>

After some time, we started to get the pool exahusted problem. At that
time, I taked a snapshot of the "netstat -atun | grep 8800" you wanted
(we're using port 8800):

Then, I stopped jpos:

<log realm="labanca_server.server" at="Wed Oct 18 18:01:16 GMT-02:00 2006.657">
<warn>
pool exahusted ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8800]
<thread-pool name="ThreadPool-1">
<jobs>2288</jobs>
<size>20</size>
<max>20</max>

<log realm="labanca_server.server" at="Wed Oct 18 18:02:18 GMT-02:00 2006.99">
<warn>
pool exahusted ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8800]
<thread-pool name="ThreadPool-1">
<jobs>2288</jobs>
<size>20</size>
<max>20</max>

</log>
<log realm="Q2.system" at="Wed Oct 18 18:02:35 GMT-02:00 2006.473">
<info>
deploy:shutdown.xml
</info>
</log>
<log realm="Q2.system" at="Wed Oct 18 18:02:35 GMT-02:00 2006.479">
<trace>
undeploying:shutdown.xml
</trace>
</log>
<log realm="Q2.system" at="Wed Oct 18 18:02:35 GMT-02:00 2006.479">
<info>
undeployed:shutdown.xml
</info>
</log>
<log realm="Q2.system" at="Wed Oct 18 18:02:35 GMT-02:00 2006.480">

<trace>
undeploying:50_labanca.xml
</trace>
</log>

<info>
undeployed:50_labanca.xml
</info>
</log>

<log realm="Q2.system" at="Wed Oct 18 18:02:35 GMT-02:00 2006.480">
<trace>
undeploying:00_logger.xml
</trace>
</log>

This time, I didn't get all those disconnections when I shutted it down.
Then, I did netstat again:

> I was curious about what a command like "netstat -atun" would return
> while the pool is exausted...

there you are...

> Maybe so_linger should be checked.

I don't know so_linger.

> Check if the POS connects directly to the JPOS server or if there are
> network nodes between them...

There are planty of nodes between them. We are testing terminals using
CDPD, GPRS, ADSL and LAN. Imagine yourself all that's between our
client and server. Much of that we even don't know.

> I do not know what Diego is using for logging, but I found very useful
> to log the thread ID in the header, because the thread logs always get
> mixed...

Mmm... I don't know how to do that. Can you show me an example?

>
> Alan
>

Thank you.

Diego Algorta Casamayou

unread,

Oct 18, 2006, 4:24:41 PM10/18/06

to jpos-...@googlegroups.com

2006/10/17, Mark Salter <marks...@dsl.pipex.com>:

>
> Diego Algorta Casamayou wrote:
>
> [code snip]
> > resMsg.set(FIELD_CRC32, Long.toString(calcularCRC32(resMsg)));
> > if (source.isConnected()) {
> > source.send(resMsg);
> > }
>
> My initial thought was - you only ever return false, perhaps you should
> return true after this send occurs.
>
> However I looked at the code in ISOServer that invokes the
> ISORequestListener.process(channel,m) and it doesn't appear to make any
> difference, although it would be more efficient to return true *if* you
> had multiple ISORequestListeners registered with the ISOServer *and*
> only a single ISORequestListeners was required to generate a response.

I only haver 1 ISORequestListener by now. But we're planning to add more.

>
> My only other question relates to your call to :-
>
> > boolean crcOK = validarCRC32(m);
>
> this looks like the only 'external' call, is it at all possible that
> this does not always return? A 'null' ISOMsg or something occasional
> and 'odd'?

It's simple:

private boolean validarCRC32(ISOMsg m) throws ISOException {
return m.hasField(FIELD_CRC32)
&& Long.parseLong(m.getString(FIELD_CRC32)) == calcularCRC32(m);
}
private long calcularCRC32(ISOMsg m) {
String buffer = "";
for (int i = 0; i < m.getMaxField() + 1; i++) {
if (m.hasField(i) && i != FIELD_CRC32) {
buffer += m.getString(i);
}
}
debug("CRC32 buffer: '" + buffer + "'");
CRC32 checksum = new CRC32();
checksum.update(buffer.getBytes());
return checksum.getValue();
}

>
> --
> Mark

Thank you
Diego

Diego Algorta Casamayou

unread,

Oct 18, 2006, 4:25:41 PM10/18/06

to jpos-...@googlegroups.com

Thank you Alejandro. I'll be testing this tomorrow, I hope.

Diego

2006/10/17, Alejandro Revilla <a...@jpos.org>:

Alejandro Revilla

unread,

Oct 18, 2006, 4:20:24 PM10/18/06

to jpos-...@googlegroups.com

Diego,

Can you test that very same scenerio with the new jPOS 6 patch (r2396)?

--Alejandro

Alan Honczar

unread,

Oct 18, 2006, 6:14:31 PM10/18/06

to jpos-...@googlegroups.com

Ok,

You are logging this:

10.204.2.1:2568

but this socket is not listed in your "netstat -atun"...

Verify the following situation in your client app:

In your verifone C application you open 2 connections, but use only one and closes it with a RST.

The other remains.

I think it would be easy to happen…

When you close with a RST, the socket automatically closes.

If you do a FIN, it would enter in FIN_WAIT.

(The linger configuration is the time it will wait in FIN_WAIT to close gracefully.)

about the logger:

If you use Java logger, overrride your own log formatter.

Would be something like this:

public synchronized String format(LogRecord record) {

StringBuffer sb = new StringBuffer();

// if date is to be written in log

if(dateTime){

long time = record.getMillis();

dat.setTime(time);

SimpleDateFormat format = new SimpleDateFormat (dateFormat);

String dateString = format.format(dat);

sb.append(dateString).append(" ");

}

// if thread number is to be written in log

if (record.getThreadID() > 0 && threadId) {

sb.append(record.getThreadID()).append(" ");

}

// if class name is to be written in log

if(className){

if (record.getSourceClassName() != null) {

sb.append(record.getSourceClassName()).append(" ");

} else {

sb.append(record.getLoggerName()).append(" ");

}

and so on...

if you use log4j, I think it is the “%t” option…

Alan

-----Mensagem original-----
De: jpos-...@googlegroups.com [mailto:jpos-...@googlegroups.com] Em nome de Diego Algorta Casamayou
Enviada em: quarta-feira, 18 de outubro de 2006 17:19

Para: jpos-...@googlegroups.com
Assunto: Re: RES: pool exahusted (exhausted) and SocketException

AVISO LEGAL - Esta mensagem e seu conteudo - inclusive anexos - sao para uso exclusivo de seu(s) destinatario(s), podendo conter informacoes confidenciais e/ou legalmente privilegiadas sobre a APPI Tecnologia S/A. Qualquer modificacao, retransmissao, disseminacao, impressao ou utilizacao nao autorizada fica estritamente proibida. Se voce recebeu esta mensagem por engano, por favor informe ao remetente e apague o material e as copias de sua maquina.

LEGAL NOTICE - This message - including any attachments - contains confidential and privileged information from APPI Tecnologia S/A intended for the named recipient(s) only. Any modification, copying, printing or distribution of this message or the taking of any action based on it is strictly prohibited. If you have received it by mistake please notify the sender by return e-mail and delete this message from your system.

Diego Algorta Casamayou

unread,

Oct 20, 2006, 12:30:30 PM10/20/06

to jpos-...@googlegroups.com

2006/10/18, Alejandro Revilla <a...@jpos.org>:

>
> Diego,
>
> Can you test that very same scenerio with the new jPOS 6 patch (r2396)?

Ok. Here it is. The log of each transaction is different, but the
problem persists.

Here's the new version of the log for a typical transaction:

<log realm="labanca_server.server.channel/10.204.2.1:1494" at="Thu Oct
19 16:56:59 GMT-02:00 2006.138">
<receive>
<peer-disconnect>Connection reset</peer-disconnect>
</receive>
</log>
<log realm="labanca_server.server.session/10.204.2.1" at="Thu Oct 19
16:56:59 GMT-02:00 2006.139">

<session-warning>
<exception name="Connection reset">
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.DataInputStream.readFully(DataInputStream.java:176)

at org.jpos.iso.channel.ASCIIChannel.getMessageLength(ASCIIChannel.java:132)
at org.jpos.iso.BaseChannel.receive(BaseChannel.java:533)
at org.jpos.iso.ISOServer$Session.run(ISOServer.java:124)
at org.jpos.util.ThreadPool$PooledThread.run(ThreadPool.java:101)
</exception>
</session-warning>
</log>
<log realm="labanca_server.server.session/10.204.2.1" at="Thu Oct 19
16:56:59 GMT-02:00 2006.140">
<session-end/>
</log>

As you can see, jPOS is now catching one of the two SocketExceptions
and reporting it briefly as <peer-disconnect>Connection
reset</peer-disconnect>.
But again, after some time running the test it starts reporting the
pool exhausted problem.

Here's the new version of netstat -atun | grep 8800 before stopping the server:

tcp 0 0 :::8800 :::* LISTEN

tcp 0 0 10.100.4.100:8800 10.204.2.1:1850 ESTABLISHED

tcp 0 0 10.100.4.100:8800 10.204.2.1:1547 ESTABLISHED
tcp 0 0 10.100.4.100:8800 10.204.2.1:2579 ESTABLISHED

Then I stopped the server:

<warn>
pool exahusted ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8800]

<thread-pool name="ThreadPool-0">
<jobs>1896</jobs>

<info>
deploy:shutdown.xml
</info>
</log>

<log realm="Q2.system" at="Fri Oct 20 14:05:33 GMT-02:00 2006.347">
<info>
shutting down
</info>
</log>
<log realm="Q2.system" at="Fri Oct 20 14:05:33 GMT-02:00 2006.347">

<trace>
undeploying:shutdown.xml
</trace>
</log>

<info>
undeployed:shutdown.xml
</info>
</log>

<trace>
undeploying:50_labanca.xml
</trace>
</log>

<info>
undeployed:50_labanca.xml
</info>
</log>

<trace>
undeploying:00_logger.xml
</trace>
</log>

And this time, the netstat throws this: nothing. It shows nothing
related to port 8800. Remember last time all ESTABLISHED converted to
FIN_WAIT1.

So, Alejandro, thank you for paying attention to this problem. But it
seems the fix wasnt enough. :-(

>
> --Alejandro
>

Diego

Alan Honczar

unread,

Oct 20, 2006, 1:46:33 PM10/20/06

to jpos-...@googlegroups.com

Again, connection 1494 is not listed in your netstat, it seems to be
successfully closed.
We need to track who opened those connections.
Are there any "session-start"s in your log without "session-end"?

-----Mensagem original-----
De: jpos-...@googlegroups.com [mailto:jpos-...@googlegroups.com] Em
nome de Diego Algorta Casamayou

Enviada em: sexta-feira, 20 de outubro de 2006 13:31

Para: jpos-...@googlegroups.com
Assunto: Re: RES: pool exahusted (exhausted) and SocketException

>
> --Alejandro
>

Diego

--------

AVISO LEGAL - Esta mensagem e seu conteudo - inclusive anexos - sao para uso exclusivo de seu(s) destinatario(s), podendo conter informacoes confidenciais e/ou legalmente privilegiadas sobre a APPI Tecnologia S/A. Qualquer modificacao, retransmissao, disseminacao, impressao ou utilizacao nao autorizada fica estritamente proibida. Se voce recebeu esta mensagem por engano, por favor informe ao remetente e apague o material e as copias de sua maquina.

LEGAL ADVICE - This message - including any attachments - contains confidential and privileged information from APPI Tecnologia S/A intended for the named recipient(s) only. Any modification, copying, printing or distribution of this message or the taking of any action based on it is strictly prohibited. If you have received it by mistake please notify the sender by return e-mail and delete this message from your system.

---------

Alejandro Revilla

unread,

Oct 20, 2006, 7:43:00 PM10/20/06

to jpos-...@googlegroups.com

Well, that's actually the same exception, BaseChannel catches it, logs
it, and then re-throw it. I modified ISOServer so the second one is not
issued (committed in r2397 - a new snapshot can be downloaded
here: http://jpos.org/download/jpos-1.6.0.jar).

Alan's observation is quite right, port 1494 is not one of the
established connections, that means that that particular session was
closed properly.

>
> <log realm="labanca_server.server" at="Fri Oct 20 14:04:41 GMT-02:00 2006.455">
> <warn>
> pool exahusted ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8800]
> <thread-pool name="ThreadPool-0">
> <jobs>1896</jobs>
> <size>20</size>
> <max>20</max>
> <idle>0</idle>
> <pending>1</pending>
> </thread-pool>
> </warn>
> </log>
>

It seems to me that you just overloaded the server, it has processed
1896 requests, have 20 in-transit and just one pending. That pool
exhausted message is just a warning, it doesn't mean that the server
stopped processing, if you let it run for another minute, you should
receive yet another message like that, you can compare the jobs
count from both log events in order to figure out if pending has
increased or not.

>
> And this time, the netstat throws this: nothing. It shows nothing
> related to port 8800. Remember last time all ESTABLISHED converted to
> FIN_WAIT1.
>