[Geoserver-users] connection betwwen httpclient and geoserver closed before end...

Sebastien_Geindre1 · December 4, 2007, 9:51am

hi everybody,

i have a weird problem with my 1.6.x geoserver.

I make a wfs transaction, quite long, with more than 300 features.
It takes a certain time to handle it in geoserver.

my clien is build using httpclient apache library.

the client close the connection before the end of the treatment.

is it possible that geoserver do not write the wfs-response speed enough ?
and the httpclient consume the response so quick that it finish to close the socket before the end of response ?
could it be the DEBUG on, which slow process ?

Exception server side :

Result:

04 déc. 10:36:53 WARN [org.geoserver.ows] -
java.io.IOException
        at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:209)
        at org.geoserver.wfs.response.TransactionResponse.write(TransactionResponse.java:63)
        at org.geoserver.ows.Dispatcher.response(Dispatcher.java:608)
        at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:192)

Caused by: org.mortbay.jetty.EofException
        at org.apache.xml.serialize.XMLSerializer.endElement(Unknown Source)
        at org.geotools.xml.Encoder.end(Encoder.java:743)
        at org.geotools.xml.Encoder.encode(Encoder.java:394)
        at org.geotools.xml.Encoder.encode(Encoder.java:313)
        at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:207)

Trace and Exception client side :
2007-12-04 10:36:45,037 main TRACE httpclient.HttpConnection - enter HttpConnection.flushRequestOutputStream()
2007-12-04 10:36:45,038 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2007-12-04 10:36:45,038 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2007-12-04 10:36:45,038 main TRACE httpclient.HttpConnection - enter HttpConnection.readLine()
2007-12-04 10:36:45,040 main TRACE httpclient.HttpParser - enter HttpParser.readLine(InputStream, String)
2007-12-04 10:36:45,040 main TRACE httpclient.HttpParser - enter HttpParser.readRawLine()
_*2007-12-04 10:36:49,182 main DEBUG httpclient.HttpMethodDirector - Closing the connection.*_
2007-12-04 10:36:49,182 main TRACE httpclient.HttpConnection - enter HttpConnection.close()
2007-12-04 10:36:49,182 main TRACE httpclient.HttpConnection - enter HttpConnection.closeSockedAndStreams()
2007-12-04 10:36:49,182 main DEBUG transformer.WFSProxyHttpClient - Exception : The server localhost failed to respond
2007-12-04 10:36:49,182 main DEBUG httpclient.HttpMethodDirector - Method retry handler returned false. Automatic recovery will not be attempted
2007-12-04 10:36:49,182 main TRACE httpclient.HttpConnection - enter HttpConnection.releaseConnection()

thanks for your help !

--
Sébastien Geindre
DPREVI/AERO/DEV
sebastien.geindre __at__ meteo.fr

Andrea_Aime3 · December 4, 2007, 10:10am

Sébastien Geindre ha scritto:

hi everybody,

i have a weird problem with my 1.6.x geoserver.

I make a wfs transaction, quite long, with more than 300 features.
It takes a certain time to handle it in geoserver.

my clien is build using httpclient apache library.

the client close the connection before the end of the treatment.

is it possible that geoserver do not write the wfs-response speed enough ?
and the httpclient consume the response so quick that it finish to close the socket before the end of response ?
could it be the DEBUG on, which slow process ?

Exception server side :

Result:

04 déc. 10:36:53 WARN [org.geoserver.ows] -
java.io.IOException
        at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:209)
        at org.geoserver.wfs.response.TransactionResponse.write(TransactionResponse.java:63)
        at org.geoserver.ows.Dispatcher.response(Dispatcher.java:608)
        at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:192)

Caused by: org.mortbay.jetty.EofException
        at org.apache.xml.serialize.XMLSerializer.endElement(Unknown Source)
        at org.geotools.xml.Encoder.end(Encoder.java:743)
        at org.geotools.xml.Encoder.encode(Encoder.java:394)
        at org.geotools.xml.Encoder.encode(Encoder.java:313)
        at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:207)

Trace and Exception client side :
2007-12-04 10:36:45,037 main TRACE httpclient.HttpConnection - enter HttpConnection.flushRequestOutputStream()
2007-12-04 10:36:45,038 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2007-12-04 10:36:45,038 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2007-12-04 10:36:45,038 main TRACE httpclient.HttpConnection - enter HttpConnection.readLine()
2007-12-04 10:36:45,040 main TRACE httpclient.HttpParser - enter HttpParser.readLine(InputStream, String)
2007-12-04 10:36:45,040 main TRACE httpclient.HttpParser - enter HttpParser.readRawLine()
_*2007-12-04 10:36:49,182 main DEBUG httpclient.HttpMethodDirector - Closing the connection.*_

Hum, here the client is closing the connection after 4 second (4 seconds
to process 300 inserts... hmmm... yeah, that's because we are sending
each insert command to the db separately instead of using batches of
statements...)

Now, I don't know why the client is closing the connection, but
may it be because of a timeout setting? HTTPClient can handle timeouts,
and I have no idea what the default values are (thought 4 seconds seems
to be definitely too short). Can you play with these settings and
see if you can make it work?
http://jakarta.apache.org/httpcomponents/httpclient-3.x/apidocs/org/apache/commons/httpclient/params/HttpConnectionParams.html#setConnectionTimeout(int)

Cheers
Andrea

Sebastien_Geindre1 · December 4, 2007, 1:20pm

Hum, here the client is closing the connection after 4 second (4 seconds
to process 300 inserts… hmmm… yeah, that’s because we are sending
each insert command to the db separately instead of using batches of
statements…)

ok it explains why it is quite long…but not why the connection fell down…

Now, I don’t know why the client is closing the connection, but
may it be because of a timeout setting? HTTPClient can handle timeouts,
and I have no idea what the default values are (thought 4 seconds seems
to be definitely too short). Can you play with these settings and
see if you can make it work?

i have already done this…
for my unit test, i have set huge values to each timeout !!
post.getParams().setParameter(“http.connection.timeout”, new Integer(150000));
post.getParams().setParameter(“http.connection-manager.timeout”, new Long(150000));
post.getParams().setParameter(“http.socket.timeout”, new Integer(150000));

in the analysis, another strange thing : sometimes it works…
when i debug i works if i wait on a break point…

I checkout the httpclient code, and put some new trace in it.

So the pb happens when reading the status line of the response.

httpclient is waiting for the response :
http://jakarta.apache.org/httpcomponents/httpclient-3.x/xref/org/apache/commons/httpclient/HttpParser.html#62
while ((ch = inputStream.read()) >= 0) {
buf.write(ch);
if (ch == ‘\n’) { // be tolerant (RFC-2616 Section 19.3)
break;
}
}
It receives -1 = inputStream.read()

http://java.sun.com/j2se/1.4.2/docs/api/java/io/InputStream.html#read()
In the javadoc, it says that “If no byte is available because the end of the stream has been reached, the value -1 is returned.”

For httpclient, it means that the server drop the connection.
So it throw an HttpNoResponse Exception
…
s = conn.readLine(charset);
if (s == null && count == 0) {
// The server just dropped connection on us
throw new NoHttpResponseException(“The server " + conn.getHost() + " failed to respond”);
}
This Exception close the connection, and geoserver stop process with the following exception:
Caused by: org.mortbay.jetty.EofException
at org.apache.xml.serialize.XMLSerializer.endElement(Unknown Source)
at org.geotools.xml.Encoder.end(Encoder.java:754)
at org.geotools.xml.Encoder.encode(Encoder.java:404)
at org.geotools.xml.Encoder.encode(Encoder.java:320)
at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:207)

But the data are in the database !!!

So the question is : why geoserver tells the client that this is the end of the stream ??

···

-- 
Sébastien Geindre
DPREVI/AERO/DEV
sebastien.geindre __at__ meteo.fr

Sebastien_Geindre1 · December 4, 2007, 2:33pm

new information:
i start my httpclient in debug mode, i put a breakpoint before the request was sent to the server, after the connection was established.
Then step-by step, httclient try to write on outputStream , but the connection is still over.

It seems that there IS a time out...
But i did not succeed in handle it !!

Sébastien Geindre a écrit :

Hum, here the client is closing the connection after 4 second (4 seconds
to process 300 inserts... hmmm... yeah, that's because we are sending
each insert command to the db separately instead of using batches of
statements...)

ok it explains why it is quite long...but not why the connection fell down...

Now, I don't know why the client is closing the connection, but
may it be because of a timeout setting? HTTPClient can handle timeouts,
and I have no idea what the default values are (thought 4 seconds seems
to be definitely too short). Can you play with these settings and
see if you can make it work?

i have already done this...
for my unit test, i have set huge values to each timeout !!
            post.getParams().setParameter("http.connection.timeout", new Integer(150000));
            post.getParams().setParameter("http.connection-manager.timeout", new Long(150000)); post.getParams().setParameter("http.socket.timeout", new Integer(150000));

in the analysis, another strange thing : sometimes it works...
when i debug i works if i wait on a break point....

I checkout the httpclient code, and put some new trace in it.

So the pb happens when reading the status line of the response.

httpclient is waiting for the response :
http://jakarta.apache.org/httpcomponents/httpclient-3.x/xref/org/apache/commons/httpclient/HttpParser.html#62
            while ((ch = inputStream.read()) >= 0) {
                buf.write(ch);
                if (ch == '\n') { // be tolerant (RFC-2616 Section 19.3)
                    break;
                }
            }
It receives -1 = inputStream.read()

http://java.sun.com/j2se/1.4.2/docs/api/java/io/InputStream.html#read() <http://java.sun.com/j2se/1.4.2/docs/api/java/io/InputStream.html#read()>
In the javadoc, it says that "If no byte is available because the end of the stream has been reached, the value |-1| is returned."

For httpclient, it means that the server drop the connection.
So it throw an HttpNoResponse Exception
                ....
                s = conn.readLine(charset);
                if (s == null && count == 0) {
                    // The server just dropped connection on us
                    throw new NoHttpResponseException("The server " + conn.getHost() + " failed to respond");
                }
This Exception close the connection, and geoserver stop process with the following exception:
Caused by: org.mortbay.jetty.EofException
        at org.apache.xml.serialize.XMLSerializer.endElement(Unknown Source)
        at org.geotools.xml.Encoder.end(Encoder.java:754)
        at org.geotools.xml.Encoder.encode(Encoder.java:404)
        at org.geotools.xml.Encoder.encode(Encoder.java:320)
        at org.geoserver.wfs.response.TransactionResponse.v_1_1(TransactionResponse.java:207)

But the data are in the database !!!!

So the question is : why geoserver tells the client that this is the end of the stream ??

http://jakarta.apache.org/httpcomponents/httpclient-3.x/apidocs/org/apache/commons/httpclient/params/HttpConnectionParams.html#setConnectionTimeout(int)

Cheers
Andrea

--
Sébastien Geindre
DPREVI/AERO/DEV
sebastien.geindre __at__ meteo.fr

  ------------------------------------------------------------------------

-------------------------------------------------------------------------
SF.Net email is sponsored by: The Future of Linux Business White Paper
from Novell. From the desktop to the data center, Linux is going
mainstream. Let it simplify your IT future.
http://altfarm.mediaplex.com/ad/ck/8857-50307-18918-4
------------------------------------------------------------------------

_______________________________________________
Geoserver-users mailing list
Geoserver-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/geoserver-users

--
Sébastien Geindre
DPREVI/AERO/DEV
sebastien.geindre __at__ meteo.fr

Sebastien_Geindre1 · December 6, 2007, 4:27pm

Sébastien Geindre a écrit :

new information:
i start my httpclient in debug mode, i put a breakpoint before the 
request was sent to the server, after the connection was established.
Then step-by step, httclient try to write on outputStream , but the 
connection is still over.

It seems that there IS a time out...
But i did not succeed in handle it !!

i am not sure about this timeout…

sometimes it works :
2007-12-06 17:01:16,899 main TRACE methods.EntityEnclosingMethod - enter EntityEnclosingMethod.hasRequestContent()
2007-12-06 17:01:16,899 main TRACE httpclient.HttpConnection - enter HttpConnection.getRequestOutputStream()
2007-12-06 17:01:19,565 main DEBUG methods.EntityEnclosingMethod - Request body sent
2007-12-06 17:01:19,565 main TRACE httpclient.HttpConnection - enter HttpConnection.flushRequestOutputStream()
2007-12-06 17:01:19,565 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2007-12-06 17:01:19,565 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2007-12-06 17:01:19,565 main TRACE httpclient.HttpConnection - enter HttpConnection.readLine()
2007-12-06 17:01:19,567 main TRACE httpclient.HttpParser - enter HttpParser.readLine(InputStream, String)
2007-12-06 17:01:19,567 main TRACE httpclient.HttpParser - enter HttpParser.readRawLine()
2007-12-06 17:01:26,972 main TRACE httpclient.HttpParser - stream received : 17 : HTTP/1.1 200 OK
2007-12-06 17:01:26,972 main DEBUG wire.header - << “HTTP/1.1 200 OK[\r][\n]”

sometines it does not…

2007-12-06 17:03:49,028 main TRACE methods.EntityEnclosingMethod - enter EntityEnclosingMethod.hasRequestContent()
2007-12-06 17:03:49,028 main TRACE methods.EntityEnclosingMethod - enter EntityEnclosingMethod.getRequestContentLength()
2007-12-06 17:03:49,028 main TRACE methods.PostMethod - enter PostMethod.hasRequestContent()
2007-12-06 17:03:49,028 main TRACE methods.EntityEnclosingMethod - enter EntityEnclosingMethod.hasRequestContent()
2007-12-06 17:03:49,028 main TRACE httpclient.HttpConnection - enter HttpConnection.getRequestOutputStream()
2007-12-06 17:03:52,978 main DEBUG methods.EntityEnclosingMethod - Request body sent
2007-12-06 17:03:52,978 main TRACE httpclient.HttpConnection - enter HttpConnection.flushRequestOutputStream()
2007-12-06 17:03:52,978 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2007-12-06 17:03:52,978 main TRACE httpclient.HttpMethodBase - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2007-12-06 17:03:52,978 main TRACE httpclient.HttpConnection - enter HttpConnection.readLine()
2007-12-06 17:03:52,980 main TRACE httpclient.HttpParser - enter HttpParser.readLine(InputStream, String)
2007-12-06 17:03:52,980 main TRACE httpclient.HttpParser - enter HttpParser.readRawLine()
2007-12-06 17:03:59,042 main TRACE httpclient.HttpParser - Nothing in the stream : -1 [1]
2007-12-06 17:03:59,043 main TRACE httpclient.HttpMethodBase - FLYSAFE HttpMethodBase.readStatusLine : charset : US-ASCII The server localhost failed to respond
2007-12-06 17:03:59,043 main TRACE httpclient.HttpMethodBase - FLYSAFE : The server localhost failed to respond
2007-12-06 17:03:59,043 main DEBUG httpclient.HttpMethodDirector - Closing the connection.
2007-12-06 17:03:59,043 main TRACE httpclient.HttpConnection - enter HttpConnection.close()

[1] trace happens while waiting for response :
So -1means end of the stream…
“Reads the next byte of data from the input stream. The value byte is returned as an int in the range 0 to 255. If no byte is available because the end of the stream has been reached, the value -1 is returned. This method blocks until input data is available, the end of the stream is detected, or an exception is thrown.”

public static byte readRawLine(InputStream inputStream) throws IOException {
LOG.trace(“enter HttpParser.readRawLine()”);
ByteArrayOutputStream buf = new ByteArrayOutputStream();
try {
int ch;
while ((ch = inputStream.read()) >= 0) {
buf.write(ch);
if (ch == ‘\n’) { // be tolerant (RFC-2616 Section 19.3)
break;
}
}
if (ch < 0)
LOG.trace("Nothing in the stream : " + ch);
else
LOG.trace("stream received : " + buf.size() + " : " + buf.toString());
if (buf.size() == 0) {
return null;
}
return buf.toByteArray();
} catch (IOException e) {
LOG.trace("exit HttpParser.readRawLine(IOException) : " + e.getMessage());
throw e;
} catch (Exception e) {
LOG.trace("exit HttpParser.readRawLine(Exception) : " + e.getMessage());
return buf.toByteArray();
}
}

···

-- 
Sébastien Geindre
DPREVI/AERO/DEV
sebastien.geindre __at__ meteo.fr

Andrea_Aime3 · December 6, 2007, 4:57pm

Sébastien Geindre ha scritto:

Sébastien Geindre a écrit :

new information:
i start my httpclient in debug mode, i put a breakpoint before the request was sent to the server, after the connection was established.
Then step-by step, httclient try to write on outputStream , but the connection is still over.

It seems that there IS a time out...
But i did not succeed in handle it !!

i am not sure about this timeout....

Sebastien,
there is nothing I can do with these stack traces only.
If you can put togheter a reproducable test case that I can
run on my pc (code + data set) then I can try to have a look
at it.

Cheers
Andrea