You are viewing a plain text version of this content. The canonical link for it is here.
Posted to fop-dev@xmlgraphics.apache.org by "Johannes Herr (JIRA)" <ji...@apache.org> on 2013/07/19 13:56:48 UTC

[jira] [Commented] (FOP-2157) Deadlock in CompareUtil class

    [ https://issues.apache.org/jira/browse/FOP-2157?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13713586#comment-13713586 ] 

Johannes Herr commented on FOP-2157:
------------------------------------

We have had the same problem in our test environment (see the attached thread-dump).

I have been able to reproduce the problem in the debugger. The following describes the result of my analysis.

As Gareth explained the deadlock happens when two Vectors V1 and V2 are compared with each other by two threads at the same time. Moreover the comparisons have the forms:

V1.equals(V2)
V2.equals(V1)

and not

V1.equals(V2)
V1.equals(V2)

This is important since otherwise there would be lock-ordering and no deadlock.

The Vectors in this case are contained in FontFamilyProperties which are contained in CommontFonts. (We know this, since line 240 in CommonFont appears in the traces, which does the comparison 'CompareUtil.equal(fontFamily, other.fontFamily)'.)

The comparison of the CommonFonts takes place in PropertyCache.fetch(..) in line 134:

if (eq(cached, obj)) {

The previously cached object is compared with the newly created one. To create the deadlock we need two threads that execute this line at the same time where for Thread A the 'cached' object contains V1 and the new 'obj' contains V2 and for Thread B the 'cached' object contains V2 and the new 'obj' contains V1 (again because if the order was the same there would be no deadlock because of lock ordering).

So at first glance the problem seems easy to reproduce. It becomes tricky however because the PropertyCaches seem to ensure that there is always only one instance of a class (with equal values) in use. If that would be the case we would always compare the cached version (say V1) with new Version (V2, V3, V4), which cannot lead to this deadlock. Also when the WeakReference for V1 is cleared we would expect to compare V2 with V3, V4, ... and not somehow compare V2 with V1 at the same time that V1 is compared with V2.

The trick is line 151 in the PropertyCache:

map.put(hashCode, new WeakReference<T>(obj));

This line is executed when there was an entry in the cache, but its reference has already been cleared by the GC.

Because of this line we can have 2 Threads A and B at this line, A with an object containing V1 and B with an object containing V2. A adds the element to the cache, while B waits for a while. A number of other threads pick up V1 from the cache, then Thread B adds V2 to the cache and other threads pick up V2 from the cache. In this way we have multiple threads with V1 and V2 running at the same time which can lead to the comparison that produces the deadlock.

That's the rough idea, now the steps to actually reproduce the problem in the debugger. You need an application which keeps running and repeatedly executes FOP with a number of threads. Between the runs the weak references to FontFamilyProperty and CommonFont need to be cleared, so don't keep any strong references to FOP around between the runs.

1. Trigger the generation
There will be an entry for the FontFamilyProperty in the cache.

2. (Maybe) run Garbage Collection (i.e. through JVisualVM)
This clears the WeakReference to the FontFamilyProperty, but keeps the WeakReference itself in the cache.

3. Place a breakpoint in line 151 of the PropertyCache and wait for 2 FontFamilyProperties

map.put(hashCode, new WeakReference<T>(obj));

Note that this line is only reached, when there is a cleared WeakReference in the cache.
(Unfortunately I had weired Eclipse error msgs, with conditional breakpoints here, so either use a conditional breakpoint or just wait till the breakpoint is hit by a FontFamilyProperty.)
I would suggest noting the object-ids of these FontFamilyProperties for later reference. (Btw these contain our vectors V1 and V2 that will later produce the deadlock.)

4. Place a breakpoint in line 119 of PropertyCache (to stop threads from putting a CommonFont in the cache).

5. Let one of the Threads with FontFamilyProperties in line 151 execute the put to place its object in the cache, while still keeping the other Thread stopped.

6. Wait for 2 Threads where obj instanceof CommonFont in line 119 (the breakpoint set in step 4): 

Integer hashCode = Integer.valueOf(obj.hashCode());

These will contain the FontFamilyProperty with V1, because it has been in the cache at this time.

7. Now place the second FontFamilyProperty in the cache.

8. Wait for 2 more Threads at line 119, which now hold a reference to a FontFamilyProperty with V2.

9. Let one of the V1 Threads at line 119 execute up to line 151, that is to the unconditional put of a CommonFont. (Again it is only possible to reach line 151 if there is a cleared WeakReference in the cache, so you must put your breakpoints accordingly so that no other thread can fill the cache in the meantime.)

10. Let one of the V2 Threads at line 119 execute up to line 151, that is to the unconditional put of a CommonFont.

11. Let the V1 Thread put the CommonFont at line 151. That means the  cache contains now CommonFont -> FontFamilyProperty -> V1. And we have another thread sitting in front of the unconditional put, which can put a CommonFont -> FontFamilyProperty -> V2 in the cache in the next step.

12. Let one of the V2 Threads at line 119 execute to the the 

if (eq(cached, obj)) {

at line 134. This will lead to the first comparison, V1.equals(V2).

14. Let the V2 Thread at line 151 put its object in the cache. The cache now contains V2.

15. Let the remaining V1 Thread at line 119 execute to line 134

if (eq(cached, obj)) {

since the cache now contains V2 this is the second comparison, V2.equals(V1).

16. Put a breakpoint in line 988 of class Vector

    public synchronized int hashCode() {
        return super.hashCode();
    }

And let the Threads calling eq(..) execute to this line. One Thread will then have acquired a Lock for V1 the other for V2.

17. Let the Threads execute their equals implementation, they will try to acquire the respective other lock, which will fail and we have a deadlock.


For completeness sake: In one of the above comments there was a question about the ordering of attributes blocks. We do not have a mix of orders in our templates:

$ grep font-family *
template_A.xsl:        <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt">
template_A.xsl:        <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt" >
template_A.xsl:        <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt" >
template_B.xsl:         <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt">
template_C.xsl:       <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt">
template_D.xsl:        <fo:page-sequence master-reference="A4" font-family="Helvetica" font-size="10pt">


Sorry for the long text, hope this helps.




                
> Deadlock in CompareUtil class
> -----------------------------
>
>                 Key: FOP-2157
>                 URL: https://issues.apache.org/jira/browse/FOP-2157
>             Project: Fop
>          Issue Type: Bug
>          Components: general
>    Affects Versions: trunk
>         Environment: Operating System: All
> Platform: PC
>            Reporter: Matthias Reischenbacher
>            Assignee: Alexios Giotis
>         Attachments: FOP DEADLOCK jakarta_service_20121107.log, thread-dump.txt
>
>
> I'm getting a dead lock in the CompareUtil class, see the attached thread dump. 
> Here small fragment of the thread dump
> [2012-11-07 14:06:25] [info] Found one Java-level deadlock:
> [2012-11-07 14:06:25] [info] =============================
> [2012-11-07 14:06:25] [info] 
> [2012-11-07 14:06:25] [info] "http-80-exec-58":
> [2012-11-07 14:06:25] [info]   waiting to lock monitor 0x0000000006ca9480
> [2012-11-07 14:06:25] [info]  (object 0x000000071fe9bd00, a java.util.Vector)
> [2012-11-07 14:06:25] [info] ,
>   which is held by "http-80-exec-5"
> [2012-11-07 14:06:25] [info] 
> [2012-11-07 14:06:25] [info] "http-80-exec-5":
> [2012-11-07 14:06:25] [info]   waiting to lock monitor 0x00000000116ecfc8
> [2012-11-07 14:06:25] [info]  (object 0x000000071fe9a000, a java.util.Vector)
> [2012-11-07 14:06:25] [info] ,
>   which is held by "http-80-exec-18"
> [2012-11-07 14:06:25] [info] 
> [2012-11-07 14:06:25] [info] "http-80-exec-18":
> [2012-11-07 14:06:25] [info]   waiting to lock monitor 0x0000000006ca9480
> [2012-11-07 14:06:25] [info]  (object 0x000000071fe9bd00, a java.util.Vector)
> [2012-11-07 14:06:25] [info] ,
>   which is held by "http-80-exec-5"
> [2012-11-07 14:06:25] [info] 
> [2012-11-07 14:06:25] [info] 
> [2012-11-07 14:06:25] [info] Java stack information for the threads listed above:
> [2012-11-07 14:06:25] [info] ===================================================
> [2012-11-07 14:06:25] [info] "http-80-exec-58":
> [2012-11-07 14:06:25] [info] 	at java.util.Vector.equals(Vector.java:925)
> [2012-11-07 14:06:25] [info] 	- waiting to lock <0x000000071fe9bd00> 
> [2012-11-07 14:06:25] [info] (a java.util.Vector)
> [2012-11-07 14:06:25] [info] 	at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)
> [2012-11-07 14:06:25] [info] 	at org.apache.fop.fo.properties.ListProperty.equals(ListProperty.java:123)
> [2012-11-07 14:06:25] [info] 	at org.apache.fop.fo.properties.PropertyCache.eq(PropertyCache.java:193)
> [2012-11-07 14:06:25] [info] 	at org.apache.fop.fo.properties.PropertyCache.fetch(PropertyCache.java:134)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.FontFamilyProperty$Maker.make(FontFamilyProperty.java:94)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.PropertyList.convertAttributeToProperty(PropertyList.java:413)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.PropertyList.addAttributesToList(PropertyList.java:321)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FObj.processNode(FObj.java:122)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder$MainFOHandler.startElement(FOTreeBuilder.java:280)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder.startElement(FOTreeBuilder.java:175)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.startElement(TransformerIdentityImpl.java:1073)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.startNode(TreeWalker.java:359)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.traverse(TreeWalker.java:145)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.transform(TransformerIdentityImpl.java:390)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:150)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:125)
> [2012-11-07 14:06:26] [info] 	at smc.plugin.Dom2PDF.process(Dom2PDF.java:179)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.GeneratedMethodAccessor97.invoke(Unknown Source)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> [2012-11-07 14:06:26] [info] 	at java.lang.reflect.Method.invoke(Method.java:597)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.dynacode.DynaCode$MyInvocationHandler.invoke(DynaCode.java:374)
> [2012-11-07 14:06:26] [info] 	at $Proxy35.process(Unknown Source)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.TransformerStep.processDocument(TransformerStep.java:211)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:491)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:442)
> [2012-11-07 14:06:26] [info] 	at smc.transform.TransformServlet.doGet(TransformServlet.java:184)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
> [2012-11-07 14:06:26] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:183)
> [2012-11-07 14:06:26] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:138)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
> [2012-11-07 14:06:26] [info] 	at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:880)
> [2012-11-07 14:06:26] [info] 	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:719)
> [2012-11-07 14:06:26] [info] 	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2081)
> [2012-11-07 14:06:26] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> [2012-11-07 14:06:26] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> [2012-11-07 14:06:26] [info] 	at java.lang.Thread.run(Thread.java:662)
> [2012-11-07 14:06:26] [info] "http-80-exec-5":
> [2012-11-07 14:06:26] [info] 	at java.util.Vector.size(Vector.java:268)
> [2012-11-07 14:06:26] [info] 	- waiting to lock <0x000000071fe9a000> 
> [2012-11-07 14:06:26] [info] (a java.util.Vector)
> [2012-11-07 14:06:26] [info] 	at java.util.AbstractList.listIterator(AbstractList.java:312)
> [2012-11-07 14:06:26] [info] 	at java.util.AbstractList.listIterator(AbstractList.java:284)
> [2012-11-07 14:06:26] [info] 	at java.util.AbstractList.equals(AbstractList.java:503)
> [2012-11-07 14:06:26] [info] 	at java.util.Vector.equals(Vector.java:925)
> [2012-11-07 14:06:26] [info] 	- locked <0x000000071fe9bd00> 
> [2012-11-07 14:06:26] [info] (a java.util.Vector)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.ListProperty.equals(ListProperty.java:123)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.CommonFont.equals(CommonFont.java:240)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.PropertyCache.eq(PropertyCache.java:193)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.PropertyCache.fetch(PropertyCache.java:134)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.CommonFont.getInstance(CommonFont.java:132)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.PropertyList.getFontProps(PropertyList.java:642)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.flow.Block.bind(Block.java:111)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FObj.processNode(FObj.java:124)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder$MainFOHandler.startElement(FOTreeBuilder.java:280)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder.startElement(FOTreeBuilder.java:175)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.startElement(TransformerIdentityImpl.java:1073)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.startNode(TreeWalker.java:359)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.traverse(TreeWalker.java:145)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.transform(TransformerIdentityImpl.java:390)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:150)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:125)
> [2012-11-07 14:06:26] [info] 	at smc.plugin.Dom2PDF.process(Dom2PDF.java:179)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> [2012-11-07 14:06:26] [info] 	at java.lang.reflect.Method.invoke(Method.java:597)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.dynacode.DynaCode$MyInvocationHandler.invoke(DynaCode.java:374)
> [2012-11-07 14:06:26] [info] 	at $Proxy35.process(Unknown Source)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.TransformerStep.processDocument(TransformerStep.java:211)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:491)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:442)
> [2012-11-07 14:06:26] [info] 	at smc.transform.TransformServlet.doGet(TransformServlet.java:184)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
> [2012-11-07 14:06:26] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:183)
> [2012-11-07 14:06:26] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:138)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
> [2012-11-07 14:06:26] [info] 	at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:880)
> [2012-11-07 14:06:26] [info] 	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:719)
> [2012-11-07 14:06:26] [info] 	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2081)
> [2012-11-07 14:06:26] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> [2012-11-07 14:06:26] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> [2012-11-07 14:06:26] [info] 	at java.lang.Thread.run(Thread.java:662)
> [2012-11-07 14:06:26] [info] "http-80-exec-18":
> [2012-11-07 14:06:26] [info] 	at java.util.Vector.get(Vector.java:693)
> [2012-11-07 14:06:26] [info] 	- waiting to lock <0x000000071fe9bd00> 
> [2012-11-07 14:06:26] [info] (a java.util.Vector)
> [2012-11-07 14:06:26] [info] 	at java.util.AbstractList$Itr.next(AbstractList.java:345)
> [2012-11-07 14:06:26] [info] 	at java.util.AbstractList.equals(AbstractList.java:506)
> [2012-11-07 14:06:26] [info] 	at java.util.Vector.equals(Vector.java:925)
> [2012-11-07 14:06:26] [info] 	- locked <0x000000071fe9a000> 
> [2012-11-07 14:06:26] [info] (a java.util.Vector)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.ListProperty.equals(ListProperty.java:123)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.util.CompareUtil.equal(CompareUtil.java:38)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.CommonFont.equals(CommonFont.java:240)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.PropertyCache.eq(PropertyCache.java:193)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.PropertyCache.fetch(PropertyCache.java:134)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.properties.CommonFont.getInstance(CommonFont.java:132)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.PropertyList.getFontProps(PropertyList.java:642)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.flow.Block.bind(Block.java:111)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FObj.processNode(FObj.java:124)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder$MainFOHandler.startElement(FOTreeBuilder.java:280)
> [2012-11-07 14:06:26] [info] 	at org.apache.fop.fo.FOTreeBuilder.startElement(FOTreeBuilder.java:175)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.startElement(TransformerIdentityImpl.java:1073)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.startNode(TreeWalker.java:359)
> [2012-11-07 14:06:26] [info] 	at org.apache.xml.serializer.TreeWalker.traverse(TreeWalker.java:145)
> [2012-11-07 14:06:26] [info] 	at org.apache.xalan.transformer.TransformerIdentityImpl.transform(TransformerIdentityImpl.java:390)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:150)
> [2012-11-07 14:06:26] [info] 	at smc.fop.FopWrapper.transform(FopWrapper.java:125)
> [2012-11-07 14:06:26] [info] 	at smc.plugin.Dom2PDF.process(Dom2PDF.java:179)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> [2012-11-07 14:06:26] [info] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> [2012-11-07 14:06:26] [info] 	at java.lang.reflect.Method.invoke(Method.java:597)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.dynacode.DynaCode$MyInvocationHandler.invoke(DynaCode.java:374)
> [2012-11-07 14:06:26] [info] 	at $Proxy35.process(Unknown Source)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.TransformerStep.processDocument(TransformerStep.java:211)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:491)
> [2012-11-07 14:06:26] [info] 	at smc.transform.core.Transformer.process(Transformer.java:442)
> [2012-11-07 14:06:26] [info] 	at smc.transform.TransformServlet.doGet(TransformServlet.java:184)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
> [2012-11-07 14:06:26] [info] 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
> [2012-11-07 14:06:26] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:26] [info] 	at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
> [2012-11-07 14:06:27] [info] 	at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
> [2012-11-07 14:06:27] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:183)
> [2012-11-07 14:06:27] [info] 	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:138)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
> [2012-11-07 14:06:27] [info] 	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
> [2012-11-07 14:06:27] [info] 	at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:880)
> [2012-11-07 14:06:27] [info] 	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:719)
> [2012-11-07 14:06:27] [info] 	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2081)
> [2012-11-07 14:06:27] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> [2012-11-07 14:06:27] [info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> [2012-11-07 14:06:27] [info] 	at java.lang.Thread.run(Thread.java:662)
> [2012-11-07 14:06:27] [info] 
> Found 1 deadlock.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira