chemistry-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Florian Müller <f...@apache.org>
Subject Re: Infinite loop in AtomEntryParser
Date Thu, 20 Mar 2014 16:51:19 GMT
 Hi Bindu,

 I've scanned the OpenCMIS and Woodstox code again, but I can't find the 
 cause of this issue. It's difficult without being able to reproduce 
 this.
 I can exclude at least that OpenCMIS parses the entry over and over 
 again. The incoming stream is directly read and parsed. There is (at 
 least for OpenCMIS) no way to jump back and parse it again.

 There might be some kind of IO issue (see the exceptions). What servlet 
 container do you use? Is there a proxy or firewall between the client 
 and the server?
 In one of your emails I found this: "Frozen for at least 47m 15 sec". 
 Usually a connection times out when no bytes are transferred. Did you 
 disable the timeout on the client and the server? If not, the client 
 must send more and more data, but I don't know how. The OpenCMIS client 
 doesn't do that. Could you check if there is steady incoming network 
 traffic when the server is in that state?

 - Florian



> I should add that I'm seeing 3.6 million of the following three 
> exceptions
> (with associate stacks resulting in the exception):
>
> com.ctc.wstx.exc.WstxParsingException
>   BasicStreamReader.readPIPrimary()
>     BasicStreamReader.nextFromTree()
>       BasicStreamReader.next()
>         AtomEntryParser.next()
>           AtomEntryParser.skip()
>             AtomEntryParser.parseCmisContent()
>               AtomEntryParser.parseEntry()
>                 AtomEntryParser.parse()
>                   ObjectService.create()
>
> java.io.IOException
>   ChunkedInputFilter.doRead()
>     InternalInputBuffer.doRead()
>       Request.doRead()
>         InputBuffer.realReadBytes()
>           ByteChunk.substract()
>             InputBuffer.read()
>               CoyoteInputStream.read()
>                 UTF8Reader.loadMore()
>                   UTF8Reader.read()
>                     ReaderSource.readInto()
>                       BranchingReaderSource.readInto()
>                         StreamScanner.loadMore()
>
> com.ctc.wstx.exc.WstxIOException
>   BasicStreamReader.next()
>     AtomEntryParser.next()
>       AtomEntryParser.skip()
>         AtomEntryParser.parseCmisContent()
>           AtomEntryParser.parseEntry()
>             AtomEntryParser.parse()
>               ObjectService.create()
>
>
> Looking at the 3.2.4 version of com.ctc.wstx.sr.BasicStreamReader I 
> see the
> following in readPIPrimary()
>
>
> if (target.equalsIgnoreCase
> 
> <http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b27/java/lang/String.java#String.equalsIgnoreCase%28java.lang.String%29>("xml"))
> {
>
>     // 07-Oct-2005, TSa: Still legal in multi-doc mode...
>
>     if (!mConfig
> 
> <http://grepcode.com/file/repo1.maven.org/maven2/org.codehaus.woodstox/wstx-asl/3.2.4/com/ctc/wstx/sr/StreamScanner.java#StreamScanner.0mConfig>.inputParsingModeDocuments
> 
> <http://grepcode.com/file/repo1.maven.org/maven2/org.codehaus.woodstox/wstx-asl/3.2.4/com/ctc/wstx/api/ReaderConfig.java#ReaderConfig.inputParsingModeDocuments%28%29>())
> {
>
>         throwParseError
> 
> <http://grepcode.com/file/repo1.maven.org/maven2/org.codehaus.woodstox/wstx-asl/3.2.4/com/ctc/wstx/sr/StreamScanner.java#StreamScanner.throwParseError%28java.lang.String%2Cjava.lang.Object%29>(ErrorConsts
> 
> <http://grepcode.com/file/repo1.maven.org/maven2/org.codehaus.woodstox/wstx-asl/3.2.4/com/ctc/wstx/cfg/ErrorConsts.java#ErrorConsts.0ERR_WF_PI_XML_TARGET>.ERR_WF_PI_XML_TARGET
> 
> <http://grepcode.com/file/repo1.maven.org/maven2/org.codehaus.woodstox/wstx-asl/3.2.4/com/ctc/wstx/cfg/ErrorConsts.java#ErrorConsts.0ERR_WF_PI_XML_TARGET>,
> target);
>
>     }
>
>
> I also see next() catching IOException and throwing
> com.ctc.wstx.exc.WstxIOException.
>
> Does this mean that cmisra:content somehow contains another xml 
> document
> with an xml root processing instruction? Since I'm not sure how to 
> capture
> the source AtomPub document that is triggering this I find that I'm 
> really
> grasping at straws, I hope someone with more experience in the code 
> base
> can shed some light :)
>
> Thanks for reading through my ramblings...
>
>
>
> On Wed, Mar 19, 2014 at 8:33 PM, Bindu Wavell <bwavell@google.com> 
> wrote:
>
>> As I said we had a bunch of very large string arrays allocated and
>> collected... These huge arrays have the following list of strings 
>> over and
>> again (as indicated in the linked picture):
>>
>> atom
>> entry
>> http://www.w3.org/2005/Atom
>> cmisra
>> content
>> http://docs.oasis-open.org/ns/cmis/restatom/200908/
>> chemistry
>> filename
>> http://chemistry.apache.org/
>>
>> Since Alfresco Workdesk 4.1.1.1 is using the openchemistry 0.8.0 
>> AtomPub
>> client the chemistry:filename element is included in the 
>> cmisra:content
>> element. The parser in openchemistry 0.7.0 is trying to skip this 
>> (because
>> it doesn't know about the chemistry:filename extension.) Notice that 
>> we
>> aren't seeing cmisra:mediatype or cmisra:base64 here.
>>
>> For some reason this is introducing a parsing loop where we re-parse 
>> the
>> atom:entry over and over again. I guess it's possible the client is
>> producing this repetition too...
>>
>>
>>
>> On Wed, Mar 19, 2014 at 3:18 PM, Bindu Wavell <bwavell@google.com> 
>> wrote:
>>
>>> I believe they are using 3.2.4, assuming this is the right
>>> jar: wstx-asl-3.2.4.jar
>>>
>>>
>>> On Wed, Mar 19, 2014 at 2:11 PM, Florian Müller <fmui@apache.org> 
>>> wrote:
>>>
>>>> Hi Bindu,
>>>>
>>>> I've never seen something like this. Do you know which Woodstox 
>>>> version
>>>> is used?
>>>>
>>>> The CappedInputStream is something different. It prevents 
>>>> malicious
>>>> clients from sending an endless XML and consuming server 
>>>> resources.
>>>>
>>>>
>>>> - Florian
>>>>
>>>>
>>>>
>>>> > Our server is Alfresco Enterprise 4.1.3.0 which is in turn using
>>>> > openchemistry 0.7.0. Our client is Alfresco Workdesk 4.1.1.1 
>>>> which is
>>>> in
>>>> > turn using openchemistry 0.8.0.
>>>> >
>>>> > For the last few weeks we have run into a situation where the 
>>>> Alfresco
>>>> > server becomes unresponsive. Specifically it doesn't crash it 
>>>> simply
>>>> > becomes so overloaded that we can't login via Workdesk/CMIS. 
>>>> Using
>>>> > JConsole and subsequently YourKit we can see that the server 
>>>> runs fine
>>>> > and uses between 3-6GB of RAM with nice slow growth and cleanup. 
>>>> Then
>>>> at
>>>> > some point we see a huge amount of memory allocation and 
>>>> deallocation
>>>> > between 3GB and 15GB every couple of seconds and this occurs 
>>>> forever
>>>> > until we restart the server. The parallel GC cleaning up this 
>>>> memory
>>>> > consumes so much CPU that folks can't actually use the system.
>>>> >
>>>> > To begin with we took a stackshot every 10 seconds for a minute. 
>>>> We saw
>>>> > that there were 5 opencmis threads "frozen" while parsing an 
>>>> AtomPub
>>>> > document. They were not deadlocked. Subsequently we found the 
>>>> same
>>>> thing
>>>> > using YourKit, it calls these frozen threads. Following is an 
>>>> example
>>>> > stack trace from YourKit:
>>>> >
>>>> > http-127.0.0.1-8080-2 <--- Frozen for at least 47m 15 sec
>>>> > com.ctc.wstx.sr.StreamScanner.getNext()
>>>> > com.ctc.wstx.sr.BasicStreamReader.skipToken()
>>>> > com.ctc.wstx.sr.BasicStreamReader.nextFromTree()
>>>> > com.ctc.wstx.sr.BasicStreamReader.next()
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.AtomEntryParser.next(XMLStreamReader)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.AtomEntryParser.skip(XMLStreamReader)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.AtomEntryParser.parseCmisContent(XMLStreamReader)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.AtomEntryParser.parseEntry(XMLStreamReader)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.AtomEntryParser.parse(InputStream)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.ObjectService.create(CallContext,
>>>> > CmisService, String, HttpServletRequest, HttpServletResponse)
>>>> > sun.reflect.NativeMethodAccessorImpl.invoke0(Method, Object, 
>>>> Object[])
>>>> > sun.reflect.NativeMethodAccessorImpl.invoke(Object, Object[])
>>>> > sun.reflect.DelegatingMethodAccessorImpl.invoke(Object, 
>>>> Object[])
>>>> > java.lang.reflect.Method.invoke(Object, Object[])
>>>> > 
>>>> org.apache.chemistry.opencmis.server.shared.Dispatcher.dispatch(String,
>>>> > String, CallContext, CmisService, String, HttpServletRequest,
>>>> > HttpServletResponse)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.CmisAtomPubServlet.dispatch(CallContext,
>>>> > HttpServletRequest, HttpServletResponse)
>>>> >
>>>> 
>>>> org.apache.chemistry.opencmis.server.impl.atompub.CmisAtomPubServlet.service(HttpServletRequest,
>>>> > HttpServletResponse)
>>>> > javax.servlet.http.HttpServlet.service(ServletRequest, 
>>>> ServletResponse)
>>>> >
>>>> 
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest,
>>>> > ServletResponse)
>>>> >
>>>> 
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest,
>>>> > ServletResponse)
>>>> >
>>>> 
>>>> org.alfresco.web.app.servlet.GlobalLocalizationFilter.doFilter(ServletRequest,
>>>> > ServletResponse, FilterChain)
>>>> >
>>>> 
>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest,
>>>> > ServletResponse)
>>>> >
>>>> 
>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest,
>>>> > ServletResponse)
>>>> > org.apache.catalina.core.StandardWrapperValve.invoke(Request, 
>>>> Response)
>>>> > org.apache.catalina.core.StandardContextValve.invoke(Request, 
>>>> Response)
>>>> > 
>>>> org.apache.catalina.authenticator.AuthenticatorBase.invoke(Request,
>>>> > Response)
>>>> > org.apache.catalina.core.StandardHostValve.invoke(Request, 
>>>> Response)
>>>> > org.apache.catalina.valves.ErrorReportValve.invoke(Request, 
>>>> Response)
>>>> > org.apache.catalina.core.StandardEngineValve.invoke(Request, 
>>>> Response)
>>>> > org.apache.catalina.connector.CoyoteAdapter.service(Request, 
>>>> Response)
>>>> > org.apache.coyote.http11.Http11Processor.process(Socket)
>>>> >
>>>> 
>>>> org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Socket)
>>>> > org.apache.tomcat.util.net.JIoEndpoint$Worker.run()
>>>> > java.lang.Thread.run()
>>>> >
>>>> > By inspecting garbage collected objects we can see that this is 
>>>> almost
>>>> > all string[] tied back to AtomEntryParser (and the woodstox 
>>>> parser
>>>> stuff
>>>> > under it.) If we look at one of these arrays we see the same 
>>>> stuff over
>>>> > and over again... see a screenshot here of the first few 
>>>> elements in
>>>> > such an array: http://i.imgur.com/RzNQBYG.png . There are a 
>>>> bunch of
>>>> > these VERY large string arrays and they all look like they are 
>>>> looping
>>>> > over the front of an AtomPub document.
>>>> >
>>>> > I noticed in opencmis 0.9.0 in the implementation of 
>>>> AtomEntryParser
>>>> > that a CappedInputStream was added while parsing the AtomPub 
>>>> stream.
>>>> > This appears to be limited to 10MB. Not sure if that is related 
>>>> to this
>>>> > issue. Or if others have run into this issue. Any 
>>>> thought/guidance
>>>> would
>>>> > be greatly appreciated.
>>>> >
>>>> > I'm bcc'ing Florian and Gab (the spy) but figured it was worth 
>>>> having
>>>> > this public as I've been trying to track this issue down for a 
>>>> while
>>>> and
>>>> > have not found an answer.
>>>> >
>>>> > Thanks all!
>>>>
>>>
>>>
>>


Mime
View raw message