chemistry-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bindu Wavell <bwav...@google.com>
Subject Re: Infinite loop in AtomEntryParser
Date Thu, 20 Mar 2014 17:38:37 GMT
Thanks for your reply Florian. I too would like to be able to reproduce
this issue, it would make things much easier to debug. Even having a live
system experiencing the issue, it is quite difficult to get enough
information from a profiler (can't attach a debugger to our live systems)
to really understand in detail what the problem is.

It seems to me that woodstox has an issue where next() is looping
infinitely or we are producing an atompub document with a hell of a lot of
atom:entry elements. I'm leaning towards the former. Partly because I am
able to reproduce a different issue that seems to be related.

I have a document where the document name contains some strange characters,
when I upload this document via Alfresco Workdesk using their html5
drag-and-drop uploader the create atom pub document ends with
<chemistry:filename>  i.e. the document is incomplete. This results in an
invalid space exception from woodstox when alfresco/opencmis-server tries
to parse the document.

Here is the incomplete creation atompub document that is sent to alfresco:

<?xml version='1.0' encoding='UTF-8'?><atom:entry xmlns:atom="
http://www.w3.org/2005/Atom" xmlns:cmis="
http://docs.oasis-open.org/ns/cmis/core/200908/" xmlns:cmisra="
http://docs.oasis-open.org/ns/cmis/restatom/200908/" xmlns:chemistry="
http://chemistry.apache.org/"><atom:id>urn:uuid:00000000-0000-0000-0000-00000000000</atom:id><atom:title>Exhibit
2.2(c) to Series F Disclosure Schedule
</atom:title><atom:updated>2014-03-20T16:56:51Z</atom:updated><cmisra:content><cmisra:mediatype>application/vnd.openxmlformats-officedocument.spreadsheetml.sheet</cmisra:mediatype><chemistry:filename>

Here is a zip containing the document with the strange characters in the
name, note the zip may also have the strange characters in the name. I made
the zip to protect the original filename as certain things like email
clients will "fix" the name of an attachment...

https://dl.dropboxusercontent.com/u/54062/forum%20attachments/Exhibit%202.2(c)%20to%20Series%20F%20Disclosure%20Schedule%20%E2%80%93%20Capitalization%20Table.xlsx.zip

For what it's worth, I don't think that this particular use case triggers
the memory explosion, but it is indicative of some problems with
serializing and deserializing in
wordkesk/alfresco/opencmis/woodstox/xerces...

We are using Tomcat, I'll see if I can find an open network connection that
is spewing a lot of data the next time the issue occurs (for what it's
worth I looked in my YourKit dump and did not see that, but I'm not
confident in that answer.)

I'm not sure which timeouts you are referring to, we have timeouts
configured for opencmis-client in workdesk, not sure if alfresco configures
timeouts (I assume they do)... We have increased the timeouts for workdesk.
We have the connection timeout set to 10000 and the readtimeout set to
60000. I'm not sure if there is a write timeout, but I don't see one in the
config, so I assume it would use the default.



On Thu, Mar 20, 2014 at 10:51 AM, Florian Müller <fmui@apache.org> wrote:

> 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
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message