server at changelist 39143. I have a server populated with a bunch of cms articles. When I have multiple users login to view the authoring page for different articles, the server gives the following error: -*-*-*-*-*- Begin Error Report -*-*-*-*-*- -*-*-*- ACS Error Report Code: 192.168.37.22:11323b2:f9ed323d10 -*-*-*- -*-*-*- Message 1: com.caucho.jsp.JspLineException: Illegal access to an unlocked com.arsdigita.bebop.FormModel -*-*-*- -*-*-*- Message 2: java.lang.IllegalStateException: Illegal access to an unlocked com.arsdigita.bebop.FormModel -*-*-*- -*-*-*- Section: CCM User -*-*-*- Party not logged in -*-*-*- Section: System properties -*-*-*- ccm.home: /var/ccm-devel/web/root/cms-dev com.arsdigita.util.Assert.enabled: true file.encoding: UTF-8 file.encoding.pkg: sun.io file.separator: / java.awt.graphicsenv: sun.awt.X11GraphicsEnvironment java.awt.printerjob: sun.print.PSPrinterJob java.class.path: :/opt/apps/oracle/product/9.2.0/jdbc/lib/classes12.zip:/opt/apps/oracle/product/9.2.0/jdbc/lib/classes12.zip:/opt/resin/2.1.8/lib/resin.jar:/opt/resin/2.1.8/lib/jdbc2_0-stdext.jar:/opt/resin/2.1.8/lib/jta-spec1_0_1.jar:/opt/resin/2.1.8/lib/jndi.jar:/opt/resin/2.1.8/lib/dom.jar:/opt/resin/2.1.8/lib/sax.jar:/opt/resin/2.1.8/lib/jaxp.jar:/opt/resin/2.1.8/lib/jmx.jar:/opt/resin/2.1.8/lib/webutil.jar:/opt/resin/2.1.8/lib/jdbc-mysql.jar:/opt/j2sdk1.4.2_02/lib/tools.jar:/opt/j2sdk1.4.2_02/jre/lib/rt.jar:/opt/resin/2.1.8/lib/jsdk23.jar java.class.version: 48.0 java.endorsed.dirs: /var/local/j2sdk1.4.2_02/jre/lib/endorsed java.ext.dirs: /opt/j2sdk1.4.2_02/jre/lib/ext:/opt/j2sdk1.4.2_02/lib/ext:/usr/share/ccm-tools/lib/security java.home: /var/local/j2sdk1.4.2_02/jre java.io.tmpdir: /tmp java.library.path: /var/local/j2sdk1.4.2_02/jre/lib/i386/client:/var/local/j2sdk1.4.2_02/jre/lib/i386:/var/local/j2sdk1.4.2_02/jre/../lib/i386:/opt/apps/oracle/product/9.2.0/lib:/opt/apps/oracle/product/9.2.0/ctx/lib:/usr/lib:/usr/local/lib:/opt/apps/oracle/product/9.2.0/JRE/lib/linux/native_threads:/opt/resin/2.1.8/libexec java.naming.factory.initial: com.caucho.naming.InitialContextFactoryImpl java.naming.factory.url.pkgs: com.caucho.naming java.runtime.name: Java(TM) 2 Runtime Environment, Standard Edition java.runtime.version: 1.4.2_02-b03 java.specification.name: Java Platform API Specification java.specification.vendor: Sun Microsystems Inc. java.specification.version: 1.4 java.util.prefs.PreferencesFactory: java.util.prefs.FileSystemPreferencesFactory java.vendor: Sun Microsystems Inc. java.vendor.url: http://java.sun.com/ java.vendor.url.bug: http://java.sun.com/cgi-bin/bugreport.cgi java.version: 1.4.2_02 java.vm.info: mixed mode java.vm.name: Java HotSpot(TM) Client VM java.vm.specification.name: Java Virtual Machine Specification java.vm.specification.vendor: Sun Microsystems Inc. java.vm.specification.version: 1.0 java.vm.vendor: Sun Microsystems Inc. java.vm.version: 1.4.2_02-b03 javax.xml.parsers.DocumentBuilderFactory: org.apache.xerces.jaxp.DocumentBuilderFactoryImpl javax.xml.parsers.SAXParserFactory: org.apache.xerces.jaxp.SAXParserFactoryImpl javax.xml.transform.TransformerFactory: com.icl.saxon.TransformerFactoryImpl line.separator: log4j.configuration: file:///var/ccm-devel/web/root/cms-dev/conf/log4j.properties org.xml.sax.driver: com.caucho.xml.Xml os.arch: i386 os.name: Linux os.version: 2.4.21-4.ELsmp path.separator: : resin.home: /opt/resin/2.1.8 sun.arch.data.model: 32 sun.boot.class.path: /var/local/j2sdk1.4.2_02/jre/lib/rt.jar:/var/local/j2sdk1.4.2_02/jre/lib/i18n.jar:/var/local/j2sdk1.4.2_02/jre/lib/sunrsasign.jar:/var/local/j2sdk1.4.2_02/jre/lib/jsse.jar:/var/local/j2sdk1.4.2_02/jre/lib/jce.jar:/var/local/j2sdk1.4.2_02/jre/lib/charsets.jar:/var/local/j2sdk1.4.2_02/jre/classes sun.boot.library.path: /var/local/j2sdk1.4.2_02/jre/lib/i386 sun.cpu.endian: little sun.cpu.isalist: sun.io.unicode.encoding: UnicodeLittle sun.java2d.fontpath: sun.os.patch.level: unknown user.country: US user.dir: /var/local/resin/2.1.8 user.home: /root user.language: en user.name: root user.timezone: America/New_York -*-*-*- Section: Stack trace -*-*-*- java.lang.IllegalStateException: Illegal access to an unlocked com.arsdigita.bebop.FormModel at com.arsdigita.util.Assert.assertTrue(Assert.java:374) at com.arsdigita.util.Assert.assertLocked(Assert.java:507) at com.arsdigita.bebop.FormModel.fireSubmitted(FormModel.java:385) at com.arsdigita.bebop.FormModel.process(FormModel.java:322) at com.arsdigita.bebop.PageState.<init>(PageState.java:310) at com.arsdigita.bebop.Page.process(Page.java:682) at com.arsdigita.bebop.Page.buildDocument(Page.java:737) at com.arsdigita.cms.dispatcher.CMSPage$1.excurse(CMSPage.java:280) at com.arsdigita.cms.CMSExcursion$1.excurse(CMSExcursion.java:80) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.cms.CMSExcursion.run(CMSExcursion.java:75) at com.arsdigita.cms.dispatcher.CMSPage.dispatch(CMSPage.java:294) at _packages._content_22dsection._www._admin._item__jsp._jspService(_item__jsp.java:61) at com.caucho.jsp.JavaPage.service(JavaPage.java:75) at com.caucho.jsp.Page.subservice(Page.java:497) at com.caucho.server.http.FilterChainPage.doFilter(FilterChainPage.java:182) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:225) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:106) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:83) at com.arsdigita.dispatcher.DispatcherHelper.forwardHelper(DispatcherHelper.java:193) at com.arsdigita.dispatcher.DispatcherHelper.forwardRequestByPath(DispatcherHelper.java:222) at com.arsdigita.dispatcher.DispatcherHelper.forwardRequestByPath(DispatcherHelper.java:235) at com.arsdigita.cms.ContentSectionServlet.doService(ContentSectionServlet.java:136) at com.arsdigita.web.BaseApplicationServlet$1.excurse(BaseApplicationServlet.java:111) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseApplicationServlet.doService(BaseApplicationServlet.java:105) at com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:176) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseServlet.internalService(BaseServlet.java:147) at com.arsdigita.web.BaseServlet.doGet(BaseServlet.java:272) at javax.servlet.http.HttpServlet.service(HttpServlet.java:126) at javax.servlet.http.HttpServlet.service(HttpServlet.java:103) at com.caucho.server.http.FilterChainServlet.doFilter(FilterChainServlet.java:96) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:225) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:106) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:83) at com.arsdigita.web.BaseDispatcher.forward(BaseDispatcher.java:231) at com.arsdigita.web.BaseDispatcher.forward(BaseDispatcher.java:215) at com.arsdigita.web.BaseDispatcher.dispatch(BaseDispatcher.java:139) at com.arsdigita.web.DispatcherServlet.doService(DispatcherServlet.java:123) at com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:176) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseServlet.internalService(BaseServlet.java:147) at com.arsdigita.web.BaseServlet.doGet(BaseServlet.java:272) at javax.servlet.http.HttpServlet.service(HttpServlet.java:126) at javax.servlet.http.HttpServlet.service(HttpServlet.java:103) at com.caucho.server.http.FilterChainServlet.doFilter(FilterChainServlet.java:96) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:246) at com.caucho.server.http.HttpRequest.handleConnection(HttpRequest.java:163) at com.caucho.server.TcpConnection.run(TcpConnection.java:139) at java.lang.Thread.run(Thread.java:534) -*-*-*- Section: HTTP headers -*-*-*- Accept: text/html, image/gif, image/jpeg, */* Accept-Language: en-us Connection: Keep-Alive Cookie: JSESSIONID=a6nxJtQRGEtd; ad_user_login=331001!1168034339115!lDzN4eerZToVgyK38Whm3w== Host: 172.16.65.125 User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Win32) -*-*-*- Section: Servlet attributes -*-*-*- com.arsdigita.cms.dispatcher.section: [com.arsdigita.cms.ContentSection:{id=1021}] com.arsdigita.dispatcher.RequestContext: com.arsdigita.sitenode.SiteNodeRequestContext@d1da68 com.arsdigita.dispatcher.RequestValue: {com.arsdigita.dispatcher.RequestValue@e54f3=null} com.arsdigita.web.BaseApplicationServlet.application_id: 1021 com.arsdigita.web.BaseDispatcher.dispatched: true com.arsdigita.web.BaseServlet.request_url: /ccm/content/admin/item.jsp?set_tab=1&item_id=7387 -*-*-*- Section: Request summary -*-*-*- Context path: Request URI: /ccm/content/admin/item.jsp Query string: set_tab=1&item_id=7387 Method: GET Remote user: null -*-*-*- Section: Cookies -*-*-*- JSESSIONID: a6nxJtQRGEtd (expires: -1) ad_user_login: 331001!1168034339115!lDzN4eerZToVgyK38Whm3w== (expires: -1) -*-*-*-*-*- End Error Report -*-*-*-*-*-
I think we may be seeing the same or a related problem to the one I reported in bug 112340. I am using Resin 2.1.4. I've found that with certain actions in the CMS, like deleting workflow, publishing, and unpublishing, if I look at error.log, I see Resin destroy and then init content-section/admin/item.jsp. I think Resin is re-init'ing because the timestamp variable in item.jsp is somehow resetting to the default. If two threads are doing these actions at the same time, it will cause a race condition where one thread is reinstantiating the page and another thread is using that Page before it is lock()'ed by the other thread. The second thread will throw this exception: java.lang.IllegalStateException: Illegal access to an unlocked com.arsdigita.bebop.FormModel because the Page has not been locked and thus the FormModel has not been locked. I also saw this behavior with Resin 2.1.8 but less so. I was able to publish and unpublish with two threads at the same time. Deleting two different workflows in two threads did throw the error. This made me think that there might be a bug with Resin. As to what type of bug, I don't know. So installed Resin 2.1.12 and the problem has disappeared, at least with my manual mouse clicking type testing. I'd be curious to see what would happen if we were to load test deleting workflows, publishing, and unpublishing with larger number of threads.
Bryan, Can you check out the three .java files from //users/vadim/code/java/debug/multi-threaded and run the Main class on a dual-CPU box? If it doesn't throw a ConcurrentModificationException (CME) after about half a minute or so, you'll have to Ctrl-C out of it. If it does throw a CME, I'd be interested to hear about it. I'm kinda grasping at straws here. My current theory is that the CME that both Richard and you have observed is due to the fact that you are running on a dual-CPU box. (I know you are, since I asked you about it earlier today. I think that Richard might be using a dual-CPU box, if he did his testing on "alewife".") The reason why the dual- vs. single-CPU distinction might matter is as follows. So, let's elaborate on Richard's scenario a little bit. Say, you have two concurrently executing threads X and Y. +----------------------------------+-------------------------------------+ | X comes along and initializes | | | itemPage to an instance of | | | ContentItemPage. | | |----------------------------------+-------------------------------------| | X starts executing | Y starts executing itemPage.init(), | | itemPage.init(), which locks the | because the page is still unlocked | | page. | (since X's invocation of init() | | | hasn't finished yet) | |----------------------------------+-------------------------------------| | X is still working init() | Y has finished running init(), and | | | begins executing | | | itemPage.dispatch() | |----------------------------------+-------------------------------------| | X is done executing init() and | Y is still executing dispatch() | | begins executing dispatch() | | +------------------------------------------------------------------------+ So, if we assume that our code is executed sequentially by each thread, then Richard's scenario is impossible. Before X can execute dispatch(), it must execute init(), which will lock the page. Same is true for Y. It doesn't matter what the other thread is doing. However, if you read http://www.cs.umd.edu/~pugh/java/memoryModel/DoubleCheckedLocking.html, it says that in absence of any synchronization, it is possible for thread Y to get a hold of the variable itemPage holding a _partially_initialized_ instance of ContentItemPage. One way this can happen is when compiler performs reorderings. Say, the compiler inlines the constructor call in the following piece of code (from item.jsp): if (Utilities.getLastSectionRefresh(section).after(timestamp)) { itemPage = new ContentItemPage(); timestamp = new Date(); } In pseudocode, the compiled code will look like: create an object Q that will hold an instance of ContentItemPage write the first field of object Q. write the second field of object Q. ... write the N-th field of object Q. write the value of Q into variable itemPage In absence of any synchronization blocks, the compiler can reorder like so: create an object Q that will hold an instance of ContentItemPage write the value of Q into variable itemPage write the first field of object Q. write the second field of object Q. ... write the N-th field of object Q. So, thread X is executing the above code and is preempted. Thread Y comes along, grabs the variable itemPage which is already holding the partially initialized object Q. Thread Y calls init() on this partially initialized object and then dispatch(). Meanwhile, thread X is still populating the data structures in Q. Note that this scenario is possible if compiler (or JVM) performs reorderings. I doubt Sun's javac is smart enough to do that. Pugh suggests that the second possibility that might make this happen is when the above code is executed on SMP architectures with aggressive memory models. That's why I'm wondering if the dual-CPU-ness of your test boxes is partially accountable for the CME you have observed. Anyhow, the correct solution seems to be to synchronize both the construction and locking stages. I'm going to check in a slightly modified Richard's fix, even though I can't test it.
Vadim, I ran your test for about an hour on a dual-cpu box but didn't encounter any errors.
Here is a ConcurrentModificationException stack trace at the tip: -*-*-*-*-*- Begin Error Report -*-*-*-*-*- -*-*-*- ACS Error Report Code: 127.0.0.1:57b1d2d:fa52e70d4c -*-*-*- -*-*-*- Message 1: com.caucho.jsp.JspLineException: null -*-*-*- -*-*-*- Message 2: java.util.ConcurrentModificationException: null -*-*-*- -*-*-*- Section: HTTP headers -*-*-*- Accept: text/html, image/gif, image/jpeg, */* Accept-Language: en-us Connection: Keep-Alive Cookie: JSESSIONID=ah5Xzqy2jW6d; ad_user_login=313229!1169740689122!yH2qu/W4BcN4ZqEyAV+QJw== Host: 172.16.65.125 User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Win32) -*-*-*- Section: Cookies -*-*-*- JSESSIONID: ah5Xzqy2jW6d (expires: -1) ad_user_login: 313229!1169740689122!yH2qu/W4BcN4ZqEyAV+QJw== (expires: -1) -*-*-*- Section: CCM User -*-*-*- Party not logged in -*-*-*- Section: Stack trace -*-*-*- java.util.ConcurrentModificationException at java.util.AbstractList$Itr.checkForComodification(AbstractList.java(Inlined Compiled Code)) at java.util.AbstractList$Itr.next(AbstractList.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.util.Traversal.preorder(Traversal.java(Compiled Code)) at com.arsdigita.bebop.Page.finish(Page.java:795) at com.arsdigita.bebop.Page.lock(Page.java:813) at com.arsdigita.cms.dispatcher.CMSPage.init(CMSPage.java:159) at _packages._content_22dsection._www._admin._item__jsp._jspService(_item__jsp.java:60) at com.caucho.jsp.JavaPage.service(JavaPage.java:75) at com.caucho.jsp.Page.subservice(Page.java:497) at com.caucho.server.http.FilterChainPage.doFilter(FilterChainPage.java:182) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:225) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:106) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:83) at com.arsdigita.dispatcher.DispatcherHelper.forwardHelper(DispatcherHelper.java:193) at com.arsdigita.dispatcher.DispatcherHelper.forwardRequestByPath(DispatcherHelper.java:222) at com.arsdigita.dispatcher.DispatcherHelper.forwardRequestByPath(DispatcherHelper.java:235) at com.arsdigita.cms.ContentSectionServlet.doService(ContentSectionServlet.java:136) at com.arsdigita.web.BaseApplicationServlet$1.excurse(BaseApplicationServlet.java:111) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseApplicationServlet.doService(BaseApplicationServlet.java:105) at com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:176) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseServlet.internalService(BaseServlet.java:147) at com.arsdigita.web.BaseServlet.doGet(BaseServlet.java:272) at javax.servlet.http.HttpServlet.service(HttpServlet.java:740) at javax.servlet.http.HttpServlet.service(HttpServlet.java:853) at com.caucho.server.http.FilterChainServlet.doFilter(FilterChainServlet.java:96) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:225) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:106) at com.caucho.server.http.QRequestDispatcher.forward(QRequestDispatcher.java:83) at com.arsdigita.web.BaseDispatcher.forward(BaseDispatcher.java:199) at com.arsdigita.web.BaseDispatcher.forward(BaseDispatcher.java:183) at com.arsdigita.web.BaseDispatcher.dispatch(BaseDispatcher.java:130) at com.arsdigita.web.DispatcherServlet.doService(DispatcherServlet.java:123) at com.arsdigita.web.BaseServlet$1.excurse(BaseServlet.java:176) at com.arsdigita.kernel.KernelExcursion.run(KernelExcursion.java:57) at com.arsdigita.web.BaseServlet.internalService(BaseServlet.java:147) at com.arsdigita.web.BaseServlet.doGet(BaseServlet.java:272) at javax.servlet.http.HttpServlet.service(HttpServlet.java:740) at javax.servlet.http.HttpServlet.service(HttpServlet.java:853) at com.caucho.server.http.FilterChainServlet.doFilter(FilterChainServlet.java:96) at com.caucho.server.http.Invocation.service(Invocation.java:315) at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:246) at com.caucho.server.http.HttpRequest.handleConnection(HttpRequest.java:163) at com.caucho.server.TcpConnection.run(TcpConnection.java:139) at java.lang.Thread.run(Thread.java:513) -*-*-*- Section: Servlet attributes -*-*-*- com.arsdigita.cms.dispatcher.section: [com.arsdigita.cms.ContentSection:{id=69}] com.arsdigita.dispatcher.RequestContext: com.arsdigita.sitenode.SiteNodeRequestContext@58721cd4 com.arsdigita.dispatcher.RequestValue: {com.arsdigita.dispatcher.RequestValue@649b5d6b=null} com.arsdigita.web.BaseApplicationServlet.application_id: 69 com.arsdigita.web.BaseDispatcher.dispatched: true com.arsdigita.web.BaseServlet.request_url: /ccm/content/admin/item.jsp?set_tab=1&item_id=1184 -*-*-*- Section: Request summary -*-*-*- Context path: Request URI: /ccm/content/admin/item.jsp Query string: set_tab=1&item_id=1184 Method: GET Remote user: null -*-*-*- Section: System properties -*-*-*- ccm.home: /var/ccm-devel/web/root/cms-dev com.arsdigita.util.Assert.enabled: true file.encoding: ISO-8859-1 file.encoding.pkg: sun.io file.separator: / invokedviajava: java.assistive: ON java.awt.fonts: java.awt.graphicsenv: sun.awt.X11GraphicsEnvironment java.awt.printerjob: sun.awt.motif.PSPrinterJob java.class.path: :/opt/apps/oracle/product/9.2.0/jdbc/lib/classes12.zip:/usr/share/java/servletapi4.jar:/opt/apps/oracle/product/9.2.0/jdbc/lib/classes12.zip:/opt/resin/2.1.8/lib/resin.jar:/opt/resin/2.1.8/lib/jdbc2_0-stdext.jar:/opt/resin/2.1.8/lib/jta-spec1_0_1.jar:/opt/resin/2.1.8/lib/jndi.jar:/opt/resin/2.1.8/lib/dom.jar:/opt/resin/2.1.8/lib/sax.jar:/opt/resin/2.1.8/lib/jaxp.jar:/opt/resin/2.1.8/lib/jmx.jar:/opt/resin/2.1.8/lib/webutil.jar:/opt/resin/2.1.8/lib/jdbc-mysql.jar:/opt/IBMJava2-131/lib/tools.jar:/opt/IBMJava2-131/jre/lib/rt.jar:/opt/resin/2.1.8/lib/jsdk23.jar java.class.version: 46.0 java.compiler: jitc java.ext.dirs: /opt/IBMJava2-131/jre/lib/ext:/opt/IBMJava2-131/lib/ext:/var/ccm-devel/web/root/cms-dev/webapps/WEB-INF/system:/usr/share/ccm-tools/lib/security java.fullversion: J2RE 1.3.1 IBM build cxia32131-20030618 (JIT enabled: jitc) java.home: /opt/IBMJava2-131/jre java.io.tmpdir: /tmp java.library.path: /opt/IBMJava2-131/jre/bin:/opt/IBMJava2-131/jre/bin/classic:/opt/apps/oracle/product/9.2.0/lib:/opt/apps/oracle/product/9.2.0/ctx/lib:/usr/lib:/usr/local/lib:/opt/apps/oracle/product/9.2.0/JRE/lib/linux/native_threads:/opt/resin/2.1.8/libexec:/usr/lib java.naming.factory.initial: com.caucho.naming.InitialContextFactoryImpl java.naming.factory.url.pkgs: com.caucho.naming java.runtime.name: Java(TM) 2 Runtime Environment, Standard Edition java.runtime.version: 1.3.1 java.specification.name: Java Platform API Specification java.specification.vendor: Sun Microsystems Inc. java.specification.version: 1.3 java.vendor: IBM Corporation java.vendor.url: http://www.ibm.com/ java.vendor.url.bug: java.version: 1.3.1 java.vm.info: J2RE 1.3.1 IBM build cxia32131-20030618 (JIT enabled: jitc) java.vm.name: Classic VM java.vm.specification.name: Java Virtual Machine Specification java.vm.specification.vendor: Sun Microsystems Inc. java.vm.specification.version: 1.0 java.vm.vendor: IBM Corporation java.vm.version: 1.3.1 javax.xml.parsers.DocumentBuilderFactory: org.apache.xerces.jaxp.DocumentBuilderFactoryImpl javax.xml.parsers.SAXParserFactory: org.apache.xerces.jaxp.SAXParserFactoryImpl javax.xml.transform.TransformerFactory: com.icl.saxon.TransformerFactoryImpl line.separator: log4j.configuration: file:///var/ccm-devel/web/root/cms-dev/conf/log4j.properties org.xml.sax.driver: com.caucho.xml.Xml os.arch: x86 os.name: Linux os.version: 2.4.9-e.27smp path.separator: : resin.home: /opt/resin/2.1.8 sun.boot.class.path: /opt/IBMJava2-131/jre/lib/rt.jar:/opt/IBMJava2-131/jre/lib/i18n.jar:/opt/IBMJava2-131/jre/classes sun.boot.library.path: /opt/IBMJava2-131/jre/bin sun.io.unicode.encoding: UnicodeLittle user.dir: /var/local/resin/2.1.8 user.home: /root user.language: en user.name: root user.region: US user.timezone: America/New_York -*-*-*-*-*- End Error Report -*-*-*-*-*-
The following comments apply both to this ticket (bug 112987) and bug 112340. In the process of working on these two bugs, I made the following changes. (a) Change 39705 fixes minor logic error in component/parameter locking. (b) Change 39706 fixes the known problem in RequestLocal. We used to do "double-checked locking", which is known to be a broken idiom (http://www.cs.umd.edu/~pugh/java/memoryModel/DoubleCheckedLocking.html) Data point #1: Neither of the above fixed the bug. I also tried making the entire init() method in CMSPage synchronized. (ContentItemPage inherits this method from CMSPage.) Data point #2: This did not fix the bug either. So, the only way I can think of that the error conditions reported in bugs 112987 and 112340 can occur is if "itemPage" is assigned an instance of ContentItemPage before the latter is fully initialized. Bryan verified that Richard Su's fix from https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=112340#c7 does make the problem go away. This seems to be the least amount of synchronization we can get away with. In the common case, Utilities.getLastSectionRefresh(section).after(timestamp) returns false and the monitor object is released. This case is not made much worse by introducing the additional synchronization, because the Utilities.getLastSectionRefresh is already synchronized. If Utilities.getLastSectionRefresh(section).after(timestamp) evaluates to true, then the lock is held for as long as it takes to fully initialize a new instance of ContentItemPage. Although this make take a fair amount of time, the synchronization overhead seems unavoidable in this case. We can't let other threads get a hold of a partially initialized itemPage variable. I'm going to have Bryan and Archit take a look at the fix, before committing it.
Fixed on the trunk in change 39754.
After syncing, could not reproduce the error with a load test.