Bug 112987

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.