search

eXist-db / exist

eXist Native XML Database and Application Platform
https://exist-db.org
GNU Lesser General Public License v2.1
419 stars 179 forks source link

EOF error during transform #976

Open wshager opened 8 years ago

wshager commented 8 years ago

Just for bookkeeping, because I haven't a clue... Exist spontaneously quits when it encounters a org.eclipse.jetty.io.EofException after a javax.xml.transform.TransformerException after a javax.servlet.ServletException: Error while serializing xml.

Curious thing is that this seems to me a Xerces related error (unless I'm utterly mistaken) while I run Saxon...

2016-04-14 15:48:20,844 [eXistThread-200069] WARN  (ServletHandler.java [doHandle]:563) - /exist/apps/benjamins/new/journal_issues/content/customers/mailinglist/catalog/sl.26.1
javax.servlet.ServletException: Error while serializing xml: javax.xml.transform.TransformerException: org.eclipse.jetty.io.EofException
        at org.exist.http.servlets.EXistServlet.doGet(EXistServlet.java:226) ~[exist-optional.jar:?]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:735) ~[servlet-api-3.0.jar:?]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[servlet-api-3.0.jar:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684) ~[jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503) ~[jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:575) ~[jetty-security-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429) ~[jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:229) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:103) ~[jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.exist.http.urlrewrite.Forward.doRewrite(Forward.java:50) ~[exist-optional.jar:?]
        at org.exist.http.urlrewrite.XQueryURLRewrite.doRewrite(XQueryURLRewrite.java:549) ~[exist-optional.jar:?]
        at org.exist.http.urlrewrite.XQueryURLRewrite.service(XQueryURLRewrite.java:353) ~[exist-optional.jar:?]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[servlet-api-3.0.jar:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684) ~[jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503) [jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:533) [jetty-security-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429) [jetty-servlet-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.Server.handle(Server.java:370) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644) [jetty-http-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) [jetty-http-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82) [jetty-server-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696) [jetty-io-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53) [jetty-io-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) [jetty-util-8.1.17.v20150415.jar:8.1.17.v20150415]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) [jetty-util-8.1.17.v20150415.jar:8.1.17.v20150415]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_60]
dizzzz commented 8 years ago

not sure about your idea if Xerces. But... that is /exist/apps/benjamins/new/journal_issues/content/customers/mailinglist/catalog/sl.26.1 ? A collection? a binary resource?

wshager commented 8 years ago

@dizzzz that's a path from the controller, but it doesn't resolve anything (as it's incorrect).

dizzzz commented 8 years ago

but who does set this path? what is is the issue? what means "quits" ? How does the code looks like? I just don't understand your ticket.... There is soo little info.

wshager commented 8 years ago

@dizzzz exist exits and restarts itself, we're having trouble tracking down the reason, but I did want to mention it. Investigations continue.

dizzzz commented 8 years ago

really restarts? ouch!

are you running existdb with the service wrapper? is so, please check the wrapper.log too ;

please state version: 2.x ? 3.x ?

wshager commented 8 years ago

@dizzzz hmm this is the log from that day, but the timestamp is slightly off.

INFO | jvm 1 | 2016/04/14 10:16:24 | [Fatal Error] :1:1: Content is not allowed in prolog. STATUS | wrapper | 2016/04/14 16:33:29 | TERM trapped. Shutting down. ERROR | wrapper | 2016/04/14 16:34:28 | Shutdown failed: Timed out waiting for signal from JVM. ERROR | wrapper | 2016/04/14 16:34:28 | JVM did not exit on request, termination requested. STATUS | wrapper | 2016/04/14 16:34:28 | JVM received a signal SIGKILL (9). STATUS | wrapper | 2016/04/14 16:34:28 | JVM process is gone. STATUS | wrapper | 2016/04/14 16:34:28 | JVM exited after being requested to terminate. STATUS | wrapper | 2016/04/14 16:34:29 | <-- Wrapper Stopped STATUS | wrapper | 2016/04/14 16:37:14 | --> Wrapper Started as Daemon STATUS | wrapper | 2016/04/14 16:37:14 | Java Service Wrapper Community Edition 64-bit 3.5.26 STATUS | wrapper | 2016/04/14 16:37:14 | Copyright (C) 1999-2014 Tanuki Software, Ltd. All Rights Reserved. STATUS | wrapper | 2016/04/14 16:37:14 | http://wrapper.tanukisoftware.com STATUS | wrapper | 2016/04/14 16:37:14 | STATUS | wrapper | 2016/04/14 16:37:15 | Launching a JVM...

wshager commented 8 years ago

@dizzzz after the log entry I posted there's some "journal scanning" and another reboot that I probably did manually.

wshager commented 8 years ago

@dizzzz sorry, this doesn't help. I can't seem to find the log back...

wshager commented 8 years ago

@dizzzz unfortunately I deleted the exist.log of april 16, which was the correct date. The wrapper.log says exactly what I have pasted (SIGKILL 9), only from 2016/04/16 13:54:45. I think I messed up the log posting due to stress...

wshager commented 8 years ago

@dizzzz below is the correct log posting I sent to @wolfgangmm. It's roughly the same error, and there's also quite a difference in the timestamp. I wonder why?

2016-04-16 13:17:03,749 [eXistThread-263648] WARN (ServletHandler.java [doHandle]:563) - /exist/apps/benjamins/catalog/books/content/catalog/pumrl javax.servlet.ServletException: Error while serializing xml: javax.xml.transform.TransformerException: org.eclipse.jetty.io.EofException

wshager commented 8 years ago

@dizzzz in both cases the path to the controller is messed up, so there may be a pattern here. Possibly there's a configuration error in my app, but I'd never be able to reproduce this path. The "content" path never follows the "catalog" path: both may only appear after "benjamins". The repeating "catalog" is a bad sign.

wshager commented 8 years ago

Another finding: when I access the above paths directly, there's no error in the logs.

duncdrum commented 4 years ago

is anybody still seeing shutdowns related to EoF and xml.transform. If not I propose to close.