[Isomorphic]

I do see lots of the following in the logs. Is this normal?

2013-07-03 07:23:23,041 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-11]: Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
2013-07-03 07:23:23,041 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-11]: Isomorphic SmartClient/SmartGWT Framework is already initialized 
... several repeats ...

I put a breakpoint in our SmartClientInitializer documented above, and it only seems to be called once during the Spring application context startup. I've added a log statement for it to our next version so I can keep an eye on it.

No, this isn't normal, and it does indicate several calls to com.isomorphic.base.Init.go(). But the framework is successfully ignoring the redundant calls.

[ibrandt]

Well, it would certainly be ironic if somewhere in all that test infrastructure there was an intermittent bug.

Fair enough. My primary concern is to resolve this issue for our customers. The test infrastructure entails just basic proxying and standard Spring object initialization. Spring is open source, and I've posted all the source for our part except DelegatingServletProxy. I can post this as well (we're planning on contributing it to Spring). Since the stack traces are terminating in SmartClient code, and I can't see the source for that, I need to rely on suggestions from you all as to what sort of bugs in our code or general misuses of SmartClient that I'd need to hunt for. Incorrect SmartClient initialization order is one. Any others?

Let us know if you find anything that suggests this is a framework bug.

Do you mean something that suggests this is a SmartClient framework bug? If so, again--be it a SmartClient bug or a misuse on our part--given:

com.isomorphic.js.UnconvertableException: java.lang.ClassCastException: org.apache.commons.collections.map.LinkedMap cannot be cast to com.isomorphic.datasource.DSField
	at com.isomorphic.datasource.BasicDataSource.getField(BasicDataSource.java:1045)

..., and the fact that we don't use org.apache.commons.collections.map.LinkedMap in our POJO model objects, I have to rely on your troubleshooting instructions.

[Isomorphic]

As far as we can tell, we've exhaustively provided all possible causes (other than the always possible but very rare - bad server memory or JVM bugs or the like).

You don't think your code does any of those things... so the next step is a way that we can reproduce the problem. That means getting it to happen in your test environment; at the moment, we don't see a way that we can help you with that any further. We can, of course, answer more questions if you have some.

[ibrandt]

As far as we can tell, we've exhaustively provided all possible causes (other than the always possible but very rare - bad server memory or JVM bugs or the like).

You don't think your code does any of those things... so the next step is a way that we can reproduce the problem. That means getting it to happen in your test environment; at the moment, we don't see a way that we can help you with that any further. We can, of course, answer more questions if you have some.

I don't have any other intermittent or unexplained issues outside of SmartClient, so I'd agree that bad server memory or a JVM bug is unlikely. We've been on the same Java version for years now without incident:

java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02, mixed mode)

A concurrency bug, or as you mentioned a state issue, would seem more likely from what I could guess (not knowing anything about the code in question).

I've tried aggressively double-clicking the link to the page that's failing in both development and production, but have been unable to trip the bug. My next step would be to setup a load test with JMeter, which I will do.

In the meantime you mentioned that the repeating, "Framework is already initialized" messages are abnormal, and that initialization or state may be a cause. I've set method breakpoints on all the versions of Init.go(). I get the following pair of breakpoint stacks per usage of the <isc:loadDS /> tag from our JSPs:

Daemon Thread [http-bio-127.0.0.1-8080-exec-8] (Suspended (entry into method go in com.isomorphic.base.Init))	
	com.isomorphic.base.Init.go(javax.servlet.ServletContext) line: 96	
	com.isomorphic.taglib.LoadDSTag(com.isomorphic.taglib.BaseTag).init() line: 56	
	com.isomorphic.taglib.LoadDSTag(com.isomorphic.taglib.VirtualTag).init() line: 52	
	com.isomorphic.taglib.LoadDSTag.doStartTag() line: 51	
	WEB-INF/jsp/mypage/mypage.jsp line: 33	
	[...]

Daemon Thread [http-bio-127.0.0.1-8080-exec-13] (Suspended (entry into method go in com.isomorphic.base.Init))	
	com.isomorphic.base.Init.go(javax.servlet.ServletContext, boolean) line: 90	
	com.isomorphic.base.Init.go(javax.servlet.ServletContext) line: 96	
	com.isomorphic.taglib.LoadDSTag(com.isomorphic.taglib.BaseTag).init() line: 56	
	com.isomorphic.taglib.LoadDSTag(com.isomorphic.taglib.VirtualTag).init() line: 52	
	com.isomorphic.taglib.LoadDSTag.doStartTag() line: 51	
	WEB-INF/jsp/mypage/mypage.jsp line: 33	
	[...]

I also get a couple of these from data source fetch calls following the initial page delivery, but there are no "already initialized" messages accompanying them:

Daemon Thread [http-bio-127.0.0.1-8080-exec-8] (Suspended (entry into method go in com.isomorphic.base.Init))	
	com.isomorphic.base.Init.go(javax.servlet.ServletContext, boolean) line: 90	
	com.isomorphic.servlet.RequestContext.init(javax.servlet.ServletContext, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 173	
	com.isomorphic.servlet.RequestContext.instance(javax.servlet.ServletContext, javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 153	
	com.isomorphic.servlet.RequestContext.instance(javax.servlet.Servlet, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 131	
	com.isomorphic.servlet.IDACall.processRequest(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 129	
	com.isomorphic.servlet.IDACall.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 74	
	com.isomorphic.servlet.IDACall(javax.servlet.http.HttpServlet).service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 641	
	com.isomorphic.servlet.IDACall(com.isomorphic.servlet.BaseServlet).service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) line: 152	
	com.isomorphic.servlet.IDACall(javax.servlet.http.HttpServlet).service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 722	
	com.mycompany.common.web.spring.servlet.DelegatingServletProxy.invokeDelegate(javax.servlet.Servlet, javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 213	
	com.mycompany.common.web.spring.servlet.DelegatingServletProxy.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) line: 128

I've enabled trace level logging for all of com.isomorphic. Here is the log for the entire page load:

2013-08-13 10:54:41,997 INFO  [c.i.d.DSResponse] [AsyncAppender-Dispatcher-Thread-13]: DSResponse: List with 129 items
2013-08-13 10:54:41,998 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.ArrayList to JS Object: 1ms
2013-08-13 10:54:46,232 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
2013-08-13 10:54:46,232 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework is already initialized
2013-08-13 10:54:47,020 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/WEB-INF/jsp/layout/main_layout.jsp'
Request URI: '/WEB-INF/jsp/layout/main_layout.jsp'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/WEB-INF/jsp/layout/main_layout.jsp'
2013-08-13 10:54:47,020 INFO  [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: URL: '/WEB-INF/jsp/layout/main_layout.jsp', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari
/537.36': Safari with Accept-Encoding header
2013-08-13 10:54:47,021 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageTreeDS' with DSRequest: null
2013-08-13 10:54:47,021 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageTreeDS' instance of datasources: 0ms
2013-08-13 10:54:47,021 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageTreeDataSource' as implementer for DataSource MyPageTreeDS
2013-08-13 10:54:47,021 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:54:47,021 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageTreeDS'
2013-08-13 10:54:47,024 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:47,024 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 1ms
2013-08-13 10:54:47,024 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert com.mycompany.common.web.smartclient.DelegatingBasicDataSource to JS Object: 1ms
2013-08-13 10:54:48,717 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
2013-08-13 10:54:48,717 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework is already initialized
2013-08-13 10:54:49,586 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/WEB-INF/jsp/layout/main_layout.jsp'
Request URI: '/WEB-INF/jsp/layout/main_layout.jsp'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/WEB-INF/jsp/layout/main_layout.jsp'
2013-08-13 10:54:49,587 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageDS' with DSRequest: null
2013-08-13 10:54:49,587 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageDS' instance of datasources: 0ms
2013-08-13 10:54:49,587 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageDataSource' as implementer for DataSource MyPageDS
2013-08-13 10:54:49,587 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:54:49,587 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageDS'
2013-08-13 10:54:49,591 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:49,591 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:49,591 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert com.mycompany.common.web.smartclient.DelegatingBasicDataSource to JS Object: 1ms
2013-08-13 10:54:52,862 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
2013-08-13 10:54:52,862 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework is already initialized
2013-08-13 10:54:53,972 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/WEB-INF/jsp/layout/main_layout.jsp'
Request URI: '/WEB-INF/jsp/layout/main_layout.jsp'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/WEB-INF/jsp/layout/main_layout.jsp'
2013-08-13 10:54:53,973 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageDetailsDS' with DSRequest: null
2013-08-13 10:54:53,973 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageDetailsDS' instance of datasources: 0ms
2013-08-13 10:54:53,973 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageDetailsDataSource' as implementer for DataSource MyPageDetailsDS
2013-08-13 10:54:53,973 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:54:53,973 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageDetailsDS'
2013-08-13 10:54:53,975 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:53,975 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:53,975 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert com.mycompany.common.web.smartclient.DelegatingBasicDataSource to JS Object: 0ms
2013-08-13 10:54:58,313 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
2013-08-13 10:54:58,313 INFO  [c.i.b.ISCInit] [AsyncAppender-Dispatcher-Thread-13]: Isomorphic SmartClient/SmartGWT Framework is already initialized
2013-08-13 10:54:59,577 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/WEB-INF/jsp/layout/main_layout.jsp'
Request URI: '/WEB-INF/jsp/layout/main_layout.jsp'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/WEB-INF/jsp/layout/main_layout.jsp'
2013-08-13 10:54:59,577 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageNotesDS' with DSRequest: null
2013-08-13 10:54:59,577 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageNotesDS' instance of datasources: 0ms
2013-08-13 10:54:59,577 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageNotesDataSource' as implementer for DataSource MyPageNotesDS
2013-08-13 10:54:59,577 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:54:59,577 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageNotesDS'
2013-08-13 10:54:59,580 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:59,580 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.HashMap to JS Object: 0ms
2013-08-13 10:54:59,580 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert com.mycompany.common.web.smartclient.DelegatingBasicDataSource to JS Object: 0ms
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: host:localhost:8080
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: connection:keep-alive
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: content-length:1589
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: origin:http://localhost:8080
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/
537.36
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: accept:*/*
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: referer:http://localhost:8080/my-page.do
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: accept-encoding:gzip,deflate,sdch
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: accept-language:en-US,en;q=0.8
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Header Name:Value pair: cookie:GLog=%7B%0D%20%20%20%20left%3A244%2C%20%0D%20%20%20%20top%3A22%2C%20%0D%20%20%20%20width%3A1510%2C%20%0D%20%20%20%20h
eight%3A922%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A5%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%2C%20%0D%20%20%20%20trackRPC%3Atrue%0D%7D; hasSurveyed=1; JSESSIONID=11157CA005F4074D967AAA0170FBA33F; MC_LOGIN_
METHOD=NORMAL; MC_SEL_NODE_20801=20801
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - session exists: 11157CA005F4074D967AAA0170FBA33F
2013-08-13 10:55:01,071 DEBUG [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - remote user: null
2013-08-13 10:55:12,730 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/static/isomorphic/IDACall'
Request URI: '/static/isomorphic/IDACall'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/static/isomorphic/IDACall'
2013-08-13 10:55:12,730 INFO  [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: URL: '/static/isomorphic/IDACall', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36':
 Safari with Accept-Encoding header
2013-08-13 10:55:18,364 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Paths for request:
Servlet path: '/static/isomorphic/IDACall'
Request URI: '/static/isomorphic/IDACall'
Path Info: 'null'
Path Translated: 'null'
Real FileSystem Path: '/Users/ibrandt/mc/tomcat/wtpwebapps/mycompany-web/static/isomorphic/IDACall'
2013-08-13 10:55:18,365 DEBUG [c.i.x.XML] [AsyncAppender-Dispatcher-Thread-13]: Parsed XML from (in memory stream): 1ms
2013-08-13 10:55:18,365 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'transaction' with DSRequest: null
2013-08-13 10:55:18,365 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (failure): 'transaction' instance of datasources: 0ms
2013-08-13 10:55:18,365 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'Object' with DSRequest: null
2013-08-13 10:55:18,365 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'Object'
2013-08-13 10:55:18,365 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Validating a 'Object' at path ''
2013-08-13 10:55:18,365 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.xsi: value is: http://www.w3.org/2000/10/XMLSchema-instance
2013-08-13 10:55:18,365 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/transactionNum as Object.transactionNum type: long
2013-08-13 10:55:18,366 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'List' with DSRequest: null
2013-08-13 10:55:18,366 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'List' instance of datasources: 0ms
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Using class com.isomorphic.datasource.ListType as implementer for DataSource List
2013-08-13 10:55:18,366 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'List'
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations as Object.operations type: List
2013-08-13 10:55:18,366 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'elem' with DSRequest: null
2013-08-13 10:55:18,366 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (failure): 'elem' instance of datasources: 0ms
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Validating a 'Object' at path '/transaction/operations'
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/criteria as Object.criteria type: Object
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Validating a 'Object' at path '/transaction/operations/elem/criteria'
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/criteria/criteria/oneId as Object.oneId type: long
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/criteria/criteria/twoId as Object.twoId type: long
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/criteria/criteria/threeId as Object.threeId type: long
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.dateRangeId: value is: s
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'Object' at path '/transaction/operations/elem/criteria': 0ms
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/operationConfig as Object.operationConfig type: Object
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Validating a 'Object' at path '/transaction/operations/elem/operationConfig'
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.dataSource: value is: MyPageDS
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.operationType: value is: fetch
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.textMatchStyle: value is: exact
2013-08-13 10:55:18,366 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'Object' at path '/transaction/operations/elem/operationConfig': 0ms
2013-08-13 10:55:18,366 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/startRow as Object.startRow type: long
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/endRow as Object.endRow type: long
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/sortBy as Object.sortBy type: List
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'List' at path '/transaction/operations/elem/sortBy': 0ms
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.componentId: value is: myPageGrid
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.appID: value is: builtinApplication
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.operation: value is: MyPageDS_fetch
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/oldValues as Object.oldValues type: Object
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Validating a 'Object' at path '/transaction/operations/elem/oldValues'
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/oldValues/oldValues/oneId as Object.oneId type: long
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/oldValues/oldValues/twoId as Object.twoId type: long
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Validating field:
/transaction/operations/elem/oldValues/oldValues/threeId as Object.threeId type: long
2013-08-13 10:55:18,367 DEBUG [c.i.v.Validation] [AsyncAppender-Dispatcher-Thread-13]: Value provided for unknown field: Object.dateRangeId: value is: s
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'Object' at path '/transaction/operations/elem/oldValues': 0ms
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'Object' at path '/transaction/operations': 1ms
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'List' at path '/transaction/operations': 1ms
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Done validating a 'Object' at path '': 2ms
2013-08-13 10:55:18,367 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: DataSource record created from XML with document element: 'transaction': 2ms
2013-08-13 10:55:18,367 DEBUG [c.i.r.RPCManager] [AsyncAppender-Dispatcher-Thread-13]: Processing 1 requests.
2013-08-13 10:55:18,367 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageDS' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,367 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageDS' instance of datasources: 0ms
2013-08-13 10:55:18,367 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageDataSource' as implementer for DataSource MyPageDS
2013-08-13 10:55:18,367 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:55:18,367 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageDS'
2013-08-13 10:55:18,368 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert org.apache.commons.collections.map.LinkedMap to JS Object: 0ms
2013-08-13 10:55:18,368 DEBUG [c.i.r.RPCManager] [AsyncAppender-Dispatcher-Thread-13]: Request #1 (DSRequest) payload: {
    criteria:{
        oneId:20801,
        twoId:2,
        threeId:10,
        dateRangeId:"s"
    },
    operationConfig:{
        dataSource:"MyPageDS",
        operationType:"fetch",
        textMatchStyle:"exact"
    },
    startRow:0,
    endRow:75,
    sortBy:[
        "-date"
    ],
    componentId:"myPageGrid",
    appID:"builtinApplication",
    operation:"MyPageDS_fetch",
    oldValues:{
        oneId:20801,
        twoId:2,
        threeId:10,
        dateRangeId:"s"
    }
}
2013-08-13 10:55:18,368 INFO  [c.i.s.IDACall] [AsyncAppender-Dispatcher-Thread-13]: smartClientIdaCallServlet - Performing 1 operation(s)
2013-08-13 10:55:18,368 DEBUG [c.i.d.DeclarativeSecurity] [AsyncAppender-Dispatcher-Thread-13]: Processing security checks for DataSource null, field null
2013-08-13 10:55:18,368 DEBUG [c.i.d.DeclarativeSecurity] [AsyncAppender-Dispatcher-Thread-13]: DataSource MyPageDS is not in the pre-checked list, processing...
2013-08-13 10:55:18,368 DEBUG [c.i.a.AppBase] [AsyncAppender-Dispatcher-Thread-13]: [builtinApplication.MyPageDS_fetch] No userTypes defined, allowing anyone access to all operations for this application
2013-08-13 10:55:18,368 DEBUG [c.i.a.AppBase] [AsyncAppender-Dispatcher-Thread-13]: [builtinApplication.MyPageDS_fetch] No public zero-argument method named '_MyPageDS_fetch' found, performing generic datasource operation
2013-08-13 10:55:18,671 INFO  [c.i.d.DSResponse] [AsyncAppender-Dispatcher-Thread-13]: [builtinApplication.MyPageDS_fetch] DSResponse: List with 16 items
2013-08-13 10:55:18,694 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Setting headers to disable caching
2013-08-13 10:55:18,703 DEBUG [c.i.r.RPCManager] [AsyncAppender-Dispatcher-Thread-13]: Content type for RPC transaction: text/plain; charset=UTF-8
2013-08-13 10:55:18,703 DEBUG [c.i.s.RequestContext] [AsyncAppender-Dispatcher-Thread-13]: Getting output stream via servletResponse.getWriter()
2013-08-13 10:55:18,703 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageDS' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,704 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageDS' instance of datasources: 0ms
2013-08-13 10:55:18,704 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageDataSource' as implementer for DataSource MyPageDS
2013-08-13 10:55:18,704 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:55:18,704 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageDS'
2013-08-13 10:55:18,704 DEBUG [c.i.r.RPCManager] [AsyncAppender-Dispatcher-Thread-13]: non-DMI response, dropExtraFields: false
2013-08-13 10:55:18,704 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageDS' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,704 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageDS' instance of datasources: 0ms
2013-08-13 10:55:18,704 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageDataSource' as implementer for DataSource MyPageDS
2013-08-13 10:55:18,704 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:55:18,704 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageDS'
2013-08-13 10:55:18,706 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'java.util.SortedSet' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,706 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (failure): 'java.util.SortedSet' instance of datasources: 0ms
2013-08-13 10:55:18,706 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'MyPageNotesDS' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,706 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (success): 'MyPageNotesDS' instance of datasources: 0ms
2013-08-13 10:55:18,706 DEBUG [c.i.d.BasicDataSource] [AsyncAppender-Dispatcher-Thread-13]: Looking up Spring bean 'myPageNotesDataSource' as implementer for DataSource MyPageNotesDS
2013-08-13 10:55:18,706 DEBUG [c.i.i.InterfaceProvider] [AsyncAppender-Dispatcher-Thread-13]: Instantiating com.isomorphic.spring.SpringBeanFactory to satisfy request for an ISpringBeanFactory
2013-08-13 10:55:18,706 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: Creating instance of DataSource 'MyPageNotesDS'
2013-08-13 10:55:18,706 DEBUG [c.i.d.DataSource] [AsyncAppender-Dispatcher-Thread-13]: In DS.forName() for 'java.util.List' with DSRequest: com.isomorphic.datasource.DSRequest@4b5d7f05
2013-08-13 10:55:18,706 DEBUG [c.i.s.DataStructCache] [AsyncAppender-Dispatcher-Thread-13]: getInstanceFile (failure): 'java.util.List' instance of datasources: 0ms
2013-08-13 10:55:18,716 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Time to convert java.util.ArrayList to JS Object: 11ms
2013-08-13 10:55:18,716 DEBUG [c.i.t.Timing] [AsyncAppender-Dispatcher-Thread-13]: Request: /static/isomorphic/IDACall (start->finish): 17645ms

Does anything else stand out as abnormal in the log?

I do see a single reference to org.apache.commons.collections.map.LinkedMap.

[Isomorphic]

We'll check on whether those logs about Init can be reduced. Again they don't seem to represent a problem - the framework is not noting that Init was attempted redundantly - it's not a warning.

Also, since you are showing logs that indicate the framework has initialized, and since you've indicated you've seen this happen as the second or later access to the DataSource, there's nothing that suggests an initialization issue any more.

JMeter or similar load testing tools seem like a good idea as a next step.

[Isomorphic]

We found the reason why there are repeated logs of "Framework already initialized" - it's fixed for tomorrow's 9.1 build and we'll backport the fix shortly just so it doesn't confuse anyone else.

[retep]

Hello,

I have the same problem with the ClassCastExeption.

Here ist the solution:
You have to set the scope of your bean to "prototype". The BasicDataSource isn't thread safe.

See here:
http://forums.smartclient.com/showthread.php?t=24433

Peter

[ibrandt]

You have to set the scope of your bean to "prototype". The BasicDataSource isn't thread safe.

Thanks Peter! I deployed this change on 11/22, and haven't seen a ClassCastException or ConcurrentModificationException since. Before that I was seeing at least one every other day in production.

When I was implementing the workaround I initially wondered why not scope="request"? I was thinking in terms of typical Spring WebApplicationContext initialization where prototype beans are all instantiated at context creation time, and only request-scoped beans are instantiated per request. I take it the IDACall Servlet (or what have you) is calling getBean(...) per request for "spring:" serverConstructors? If so prototype scope in this case is synonymous with request scope. If a DataSource is fetched more than once during a given request via getBean() then in fact prototype scope is more fine-grained, and perhaps request scope is more appropriate.

Isomorphic: any recommendation regarding prototype or request scope?

Searching around I just came across the Notes on Server-side DataSource Implementations:

There is no requirement or expectation that DataSource subclasses be threadsafe. As long as you use documented techniques for creating DataSource instances, the server framework will ensure that no single instance is used concurrently by more than one thread.

Given that I would say either there is a bug in the server framework, or some additional Spring Integration documentation should be added regarding DataSource bean scopes in Spring.

[Isomorphic]

DataSource instances are cached in the RPCManager, which is a request-scoped object. So you should see no practical difference between "prototype" and "request" scopes - in either case, Spring should only be asked for a given DataSource bean once per HttpServletRequest.

Another thing to note is that SmartClient DataSource pooling is switched on by default (in recent versions), so Spring will only be involved enough times (typically just after application startup) to populate the pool to a level where it can serve your application without being starved. If this is not desired behavior, switch off DataSource pooling by setting server.properties flag "datasources.pool.enabled" to false, as described in the docs here

Finally, there is no framework bug here - there's nothing we can do to prevent an object being handed to more then one thread when that object is a singleton under the control of Spring. But yes, this does need to be documented better and we will do so.

[ibrandt]

...DataSource pooling is switched on by default (in recent versions), so Spring will only be involved enough times (typically just after application startup) to populate the pool to a level where it can serve your application without being starved.

Okay, got it. So after startup the pool will create further new instances as needed. If you're adding to the documentation some additional info about the pooling would be interesting. For example what is the initial pool size? Is it configurable? Does the pool shrink automatically after spikes in activity?