How to interpret diagnostic file with "org.eclipse.jetty.io.EofException"

[former_SQLA_member1694901]

We have an installation using an ODATA server on SQL Anywhere Network Server Version 17.0.11.6933.

The installation work fine up to a certain request rate, after which the response time deteriorates rapidly. We are now trying to find the bottleneck.

The only things we found which explicitly states an error are the diagnostics files which are created when we are near or over the critical request rate. They are all more or less identically like the example cited below.

It sounds like some java job is complaining that its partner has closed the connection. Is there any way to find out who is complaining, is it the database server itself, the ODATA producer or something else? And, maybe, some hint about the partner who closed the channel.

Content of the diagnostics file:

javax.xml.stream.XMLStreamException: org.eclipse.jetty.io.EofException
at com.sun.xml.internal.stream.writers.XMLStreamWriterImpl.flush(XMLStreamWriterImpl.java:399)
at com.sybase.odata.producer.odata.MetadataDocWriter.writeMetadataDoc(MetadataDocWriter.java:159)
at com.sybase.odata.producer.handler.GetHandler.handleRequestImpl(GetHandler.java:191)
at com.sybase.odata.producer.handler.AbstractHandler.handleRequest(AbstractHandler.java:1076)
at com.sybase.odata.producer.servlets.ODataServlet.doGet(ODataServlet.java:466)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:618)
at com.sybase.odata.producer.servlets.ODataServlet.service(ODataServlet.java:487)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:516)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:383)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036)
at java.lang.Thread.run(Thread.java:836)
Caused by: org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:279)
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422)
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277)
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:381)
at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:820)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:223)
at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:550)
at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:910)
at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:987)
at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:285)
at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:269)
at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:749)
at java.util.zip.DeflaterOutputStream.flush(DeflaterOutputStream.java:282)
at com.sun.xml.internal.stream.writers.UTF8OutputStreamWriter.flush(UTF8OutputStreamWriter.java:138)
at com.sun.xml.internal.stream.writers.XMLStreamWriterImpl.flush(XMLStreamWriterImpl.java:397)
... 35 more
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:55)
at sun.nio.ch.IOUtil.write(IOUtil.java:148)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:509)
at java.nio.channels.SocketChannel.write(SocketChannel.java:502)
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:273)
... 50 more

[VolkerBarth]

I don't have a clue but as a general question: Do you run OData with a log file ("dbsrvsrv17 -xs odata(LOG=...)") and if so, does this reveal any hints?

[former_SQLA_member1694901]

Yes, we are running OData with LogVerbosity=3, and it indeed reports an error:

R. 2022-10-27 08:49:52. [odata_register:207] Request GET http://10.0.0.5:8090/odata_register/$metadata

E. 2022-10-27 08:49:52. [odata_register:207] (HTTP 500 Internal Server Error - 30000) An unexpected error occurred in the producer and was written to file "C:\\ProgramData\\SQL Anywhere 17\\diagnostics\\ODP17_20221027_084952_751.txt"

The requests preceding the error vary. A cursory look gives the request for metadata, GET calls to different procedures, POST calls to different database views

[Vlad]

I know, that I must be late. Here is what I see: 1. the end-user tries to get $metadata; 2. OData producer prepares it (builds XML tags as a collection of strings), and starts flushing it to the connection (between the user and the server, or client and OData server). Technically, it is a socket and we throw our bytes into it. 3. At some point of time, when this happens, the connection is terminated.

Internet says, this errors happens when SOMEBODY closes the connection. I doubt that something goes wrong with the server, because the error says that "remote host forcibly closed the connection". So it means that the user all of a sudden decided to give up, and terminated the connection, or somebody did it for him.

Now, we come to the point who is guilty? Again, Internet says, the connection is closed, when the "RST" (reset) packet comes from any party (in our case, again, I assume this is a client). And people suggest to run Wireshark on the server side and check all incoming packets to this port. If you see the RST packet coming from the client, you probably has to start Wireshark on the client side and assure that it was sent by HIM, not by his firewall, router or a proxy server.

People tell, that sometimes (if the connection is long enough) the browser/client can terminate it after some timeout (e.g. at SAP Cloud etc, the timeout is usually 30 seconds, so if your connection is active for this time, it should be m-m-m-m killed). This you can confirm only if you detect/capture RST packet.

Now we come to the question, what if our response time was so long, that the end-user gave up. In theory (I have never done this before) since OData server is just a stupid Java servlet. Thank God, it is running on SAP JVM, so it is better to switch to SAP JDK (8 of course), and profile it as a regular Java application.

Unfortunately, Java profiling goes beyond this comment, but if you don't have an answer on this topic, feel free to try my idea. As I said, I don't know what happened, but I wish I can come to you and check it myself 🙂 I like these riddles.