Announcement

Collapse
No announcement yet.
X
Collapse
  • Page of 3
  • Filter
  • Time
Clear All
new posts
Previous 1 2 3 template Next
    #1

    DB deadlock / transaction

    I have a server-side DMI method which executes two DSRequests that should be executed in the same transaction. But it seems they don't, since I get a DB deadlock and the logs tell me that these two requests use a different connection!!!!

    My DSRequests are:
    Code:
    DSRequest relDeleteRequest = new DSRequest(
                KidsDataSources.REL_SCHUELER_ELTERN.getDataSourceId(),
                DataSource.OP_REMOVE, rpcManager);
        relDeleteRequest.setCriteria("f_eltern_id", elternId);
        relDeleteRequest.execute();

        DSRequest elternDeleteRequest = new DSRequest(
                KidsDataSources.ELTERN.getDataSourceId(), DataSource.OP_REMOVE,
                rpcManager);
        elternDeleteRequest.setCriteria("f_id", elternId);
        elternDeleteRequest.execute();
    These are basically two delete requests. As you see, they share a RPCManager, but in the logs, I see the following:
    Code:
    === 2015-12-26 15:27:03,520 [ec-3] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_eltern_id:8919}    values: {f_eltern_id:8919}
=== 2015-12-26 15:27:03,521 [ec-3] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '890193153'
=== 2015-12-26 15:27:03,521 [ec-3] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'890193153'
=== 2015-12-26 15:27:03,521 [ec-3] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_rel_schueler_eltern WHERE (t_rel_schueler_eltern.f_eltern_id=8919)
=== 2015-12-26 15:27:03,527 [ec-3] DEBUG SQLDataSource - [builtinApplication.null] remove operation affected 1 rows
=== 2015-12-26 15:27:03,527 [ec-3] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {f_eltern_id=8919}
=== 2015-12-26 15:27:03,527 [ec-3] DEBUG DSRequest - About to free up resources for request of type remove on DataSource relSchuelerEltern
=== 2015-12-26 15:27:03,527 [ec-3] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2015-12-26 15:27:03,527 [ec-3] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-26 15:27:03,527 [ec-3] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-26 15:27:03,528 [ec-3] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_id:8919}    values: {f_id:8919}
=== 2015-12-26 15:27:03,528 [ec-3] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '758550353'
=== 2015-12-26 15:27:03,528 [ec-3] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'758550353'
=== 2015-12-26 15:27:03,528 [ec-3] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_eltern WHERE (t_eltern.f_id=8919)
=== 2015-12-26 15:27:03,529 [ec-3] DEBUG SQLDataSource - [builtinApplication.null] remove operation affected 1 rows
=== 2015-12-26 15:27:03,529 [ec-3] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {f_id=8919}
=== 2015-12-26 15:27:03,529 [ec-3] INFO  DSResponse - [builtinApplication.null] DSResponse: List with 1 items
    These two requests are being executed using two different connections: '890193153' and '758550353'. How can this be true if they share the same transaction ?
    Using smartgwt 5.0p power 2015-09-20

    Tags: None
    #2
    Here is a testcase where you can reproduce this:

    Entrypoint:
    Code:
    public class TestingModule implements EntryPoint {

    DynamicForm df = null;
    
    @Override
    public void onModuleLoad() {

        final VLayout vlayout = new VLayout();
        IButton button = new IButton("go!");
        button.addClickHandler(new ClickHandler() {

            @Override
            public void onClick(ClickEvent event) {
                DataSource.get("test")
                .performCustomOperation("delete", new Record(),
                        new DSCallback() {

                            @Override
                            public void execute(
                                    DSResponse dsResponse,
                                    Object data, DSRequest dsRequest) {
                                SC.say("ok");
                            }
                        });
            }
        });
        vlayout.addMember(button);
        vlayout.draw();
        
    }

}
    test.ds.xml:
    Code:
    <DataSource ID="test" serverType="sql" tableName="t_rel_schueler_eltern">

    <fields>
        <field name="f_id" type="sequence" primaryKey="true" />
    </fields>

    <operationBindings>
        <operationBinding operationType="custom" operationId="delete">
            <serverObject className="de.mks_infofabrik.kids.server.test.TestingDMI"
                methodName="doRemove" />
        </operationBinding>
    </operationBindings>

</DataSource>
    TestingDMI:
    Code:
    public DSResponse doRemove(DSRequest dsRequest) throws Exception {
        RPCManager rpcManager = dsRequest.getRPCManager();
        
        DSRequest relDeleteRequest = new DSRequest(
                "relSchuelerEltern",
                DataSource.OP_REMOVE, rpcManager);
        relDeleteRequest.setCriteria("f_eltern_id", 8919);
        relDeleteRequest.execute();

        DSRequest elternDeleteRequest = new DSRequest(
                "eltern", DataSource.OP_REMOVE,
                rpcManager);
        elternDeleteRequest.setCriteria("f_id", 8919);
        elternDeleteRequest.execute();
        
        return new DSResponse();
    }
    Logs:
    Code:
    === 2015-12-26 16:49:59,242 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'transaction' in the pooling flow
=== 2015-12-26 16:49:59,242 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'Object'
=== 2015-12-26 16:49:59,242 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 595 of type 'Object' and assigned it to thread http-nio-8080-exec-10
=== 2015-12-26 16:49:59,242 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 595 of type 'Object' in the pooling flow
=== 2015-12-26 16:49:59,242 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 595 of type 'Object'
=== 2015-12-26 16:49:59,243 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'List'
=== 2015-12-26 16:49:59,243 [c-10] DEBUG XML - Parsed XML from /Users/eduardo/Documents/git/kids/kids/target/kids-1.4.2-SNAPSHOT/V010402SNAPSHOT/sc/system/schema/List.ds.xml: 0ms
=== 2015-12-26 16:49:59,243 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-26 16:49:59,244 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 596 of type 'DataSource' and assigned it to thread http-nio-8080-exec-10
=== 2015-12-26 16:49:59,244 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 596 of type 'DataSource' in the pooling flow
=== 2015-12-26 16:49:59,244 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 596 of type 'DataSource'
=== 2015-12-26 16:49:59,245 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 597 of type 'List' and assigned it to thread http-nio-8080-exec-10
=== 2015-12-26 16:49:59,245 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource 597 of type 'List' in the pooling flow
=== 2015-12-26 16:49:59,245 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 597 of type 'List'
=== 2015-12-26 16:49:59,245 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'elem'
=== 2015-12-26 16:49:59,245 [c-10] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'elem' in the pooling flow
=== 2015-12-26 16:49:59,245 [c-10] DEBUG RPCManager - Processing 1 requests.
=== 2015-12-26 16:49:59,246 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'test'
=== 2015-12-26 16:49:59,246 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 587 of type 'test'
=== 2015-12-26 16:49:59,246 [c-10] DEBUG DSRequest - Caching instance 587 of DS 'test' from DSRequest.getDataSource()
=== 2015-12-26 16:49:59,246 [c-10] DEBUG DSRequest - Caching instance 587 of DS test
=== 2015-12-26 16:49:59,247 [c-10] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
    },
    operationConfig:{
        dataSource:"test",
        repo:null,
        operationType:"custom",
        textMatchStyle:"exact"
    },
    appID:"builtinApplication",
    operation:"delete",
    oldValues:{
    },
    criteria:{
    }
}
=== 2015-12-26 16:49:59,247 [c-10] INFO  IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Performing 1 operation(s)
=== 2015-12-26 16:49:59,247 [c-10] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2015-12-26 16:49:59,247 [c-10] DEBUG DeclarativeSecurity - DataSource test is not in the pre-checked list, processing...
=== 2015-12-26 16:49:59,252 [c-10] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2015-12-26 16:49:59,252 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'relSchuelerEltern'
=== 2015-12-26 16:49:59,252 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 156 of type 'relSchuelerEltern'
=== 2015-12-26 16:49:59,252 [c-10] DEBUG DSRequest - Caching instance 156 of DS 'relSchuelerEltern' from DSRequest.getDataSource()
=== 2015-12-26 16:49:59,252 [c-10] DEBUG DSRequest - Caching instance 156 of DS relSchuelerEltern
=== 2015-12-26 16:49:59,253 [c-10] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-26 16:49:59,253 [c-10] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-26 16:49:59,253 [c-10] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_eltern_id:8919}    values: {f_eltern_id:8919}
=== 2015-12-26 16:49:59,254 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] Passing JDBC URL only to getConnection
=== 2015-12-26 16:49:59,268 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] makeObject() created a pooled Connection '1067468142'
=== 2015-12-26 16:49:59,268 [c-10] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '1067468142'
=== 2015-12-26 16:49:59,268 [c-10] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'1067468142'
=== 2015-12-26 16:49:59,268 [c-10] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_rel_schueler_eltern WHERE (t_rel_schueler_eltern.f_eltern_id=8919)
=== 2015-12-26 16:49:59,289 [c-10] DEBUG SQLDataSource - [builtinApplication.null] remove operation affected 1 rows
=== 2015-12-26 16:49:59,290 [c-10] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {f_eltern_id=8919}
=== 2015-12-26 16:49:59,290 [c-10] DEBUG DSRequest - About to free up resources for request of type remove on DataSource relSchuelerEltern
=== 2015-12-26 16:49:59,290 [c-10] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2015-12-26 16:49:59,290 [c-10] DEBUG ISCKeyedObjectPool - Borrowing object for 'eltern'
=== 2015-12-26 16:49:59,290 [c-10] DEBUG PoolableDataSourceFactory - Activated DataSource 153 of type 'eltern'
=== 2015-12-26 16:49:59,290 [c-10] DEBUG DSRequest - Caching instance 153 of DS 'eltern' from DSRequest.getDataSource()
=== 2015-12-26 16:49:59,290 [c-10] DEBUG DSRequest - Caching instance 153 of DS eltern
=== 2015-12-26 16:49:59,290 [c-10] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-26 16:49:59,290 [c-10] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-26 16:49:59,292 [c-10] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_id:8919}    values: {f_id:8919}
=== 2015-12-26 16:49:59,293 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] Passing JDBC URL only to getConnection
=== 2015-12-26 16:49:59,303 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] makeObject() created a pooled Connection '953725302'
=== 2015-12-26 16:49:59,303 [c-10] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '953725302'
=== 2015-12-26 16:49:59,303 [c-10] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'953725302'
=== 2015-12-26 16:49:59,303 [c-10] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_eltern WHERE (t_eltern.f_id=8919)
=== 2015-12-26 16:49:59,309 [c-10] DEBUG SQLDataSource - [builtinApplication.null] remove operation affected 1 rows
=== 2015-12-26 16:49:59,309 [c-10] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {f_id=8919}
=== 2015-12-26 16:49:59,309 [c-10] INFO  DSResponse - [builtinApplication.null] DSResponse: List with 1 items
    As you can see in the log, the two dsrequests are using two different connections : '1067468142' and '953725302' although they share the same RPCManager.
    Last edited by edulid; 26 Dec 2015, 07:58.

    Comment

      #3
      Hi edulid,

      are you sure, you are using transactions at all? There are no DEBUG SQLTransaction entries in the logs (sorry, not sure that this is also the class in 5.0p). Did you enable that category?
      While I agree that the use case should use a transaction, I don't see the deadlock / exception you mention.

      Best regards
      Blama

      Comment

        #4
        I didn't deactivate transactions, so I have the normal smartGWT settings. Where can I see if I am using transactions at all? Where is this setting?

        Yes, the deadlock does not always happen. But, I need these two DSRequests to be in the same transaction, so they execute after each other (so they have to use the same connection). If not, I get the DB deadlock (sometimes!).

        Comment

          #5
          Hi edulid,

          there is sql.YOURDB.autoJoinTransactions: true in my server.properties, that is one place to look. Then autoJoinTransactions in your .ds.xml.
          My log4j-settings with 5.0p, where I definitely saw transaction messages for Oracle, were:

          Code:
               <category name="com.isomorphic">
        <priority value="DEBUG" />
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE_LOG" />
        <appender-ref ref="SmartClientLog" />
    </category>

.....
.....

   <category name="com.isomorphic.assembly.FileAssembler">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.base.ConfigLoader">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.base.ISCInit">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.base.Reflection">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.compression.Compression">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.BasicDataSource">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.DSRequest">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.DataSource">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.DeclarativeSecurity">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.PoolableDataSourceFactory">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.datasource.Relation">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.download.Download">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.interfaces.InterfaceProvider">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.js.JSSyntaxScannerFilter">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.mail.MailMessage">
        <priority value="DEBUG" />
    </category>
    <category name="com.isomorphic.naming.JNDI">
        <priority value="WARN" />
    </category>
    <category name="com.isomorphic.obfuscation.Obfuscator">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.pool.ISCKeyedObjectPool">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.resultData.ResultData">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.rpc">
        <priority value="DEBUG" />
    </category>
    <category name="com.isomorphic.servlet.PreCache">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.servlet.ProxyHttpServletResponse">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.servlet.RequestContext">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.sql.PoolableSQLConnectionFactory">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.sql.ValueSet">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.store.DataStructCache">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.timing.Timing">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.validation.Validation">
        <priority value="INFO" />
    </category>
    <category name="com.isomorphic.xml.XML">
        <priority value="INFO" />
    </category>

          Could you show a log with the error as well?

          Best regards
          Blama

          Comment

            #6
            I don't have any autoJoinTransaction setting on server.properties, so I have the default settings. If I understand correctly, since I am executing deletes, these should be in the same transaction if they share the same RPCManager. And they don't, since they are using even different connections! As you see in the log.

            With your log settings I get:
            Code:
            
=== 2015-12-27 13:27:22,918 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,920 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 23 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,920 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 23 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,920 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 23 of type 'DataSource'
=== 2015-12-27 13:27:22,920 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,921 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 24 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,921 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 24 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,921 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 24 of type 'DataSourceField'
=== 2015-12-27 13:27:22,921 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,921 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,923 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:22,923 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 25 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,923 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 25 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:22,923 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 25 of type 'ValueMap'
=== 2015-12-27 13:27:22,936 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'type'
=== 2015-12-27 13:27:22,936 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'type' in the pooling flow
=== 2015-12-27 13:27:22,939 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,939 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/MethodDeclaration.ds.xml: 0ms
=== 2015-12-27 13:27:22,939 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 26 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 26 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 26 of type 'DataSource'
=== 2015-12-27 13:27:22,940 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 27 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 27 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,940 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 27 of type 'DataSourceField'
=== 2015-12-27 13:27:22,940 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,941 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,941 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 28 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,941 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 28 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,941 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 28 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,942 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 29 of type 'Canvas' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,942 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 29 of type 'Canvas' in the pooling flow
=== 2015-12-27 13:27:22,942 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,942 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,942 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Img'
=== 2015-12-27 13:27:22,943 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/Img.ds.xml: 1ms
=== 2015-12-27 13:27:22,943 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,943 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 30 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,943 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 30 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,943 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 30 of type 'DataSource'
=== 2015-12-27 13:27:22,943 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,944 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 31 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,944 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 31 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,944 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 31 of type 'DataSourceField'
=== 2015-12-27 13:27:22,944 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,944 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,945 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,945 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 32 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,946 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 32 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,946 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 32 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,946 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'StatefulCanvas'
=== 2015-12-27 13:27:22,947 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/StatefulCanvas.ds.xml: 1ms
=== 2015-12-27 13:27:22,947 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,948 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 34 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,948 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 34 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,948 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 34 of type 'DataSource'
=== 2015-12-27 13:27:22,948 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,949 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 35 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,949 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 35 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,949 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 35 of type 'DataSourceField'
=== 2015-12-27 13:27:22,949 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,949 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,953 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'type'
=== 2015-12-27 13:27:22,954 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'type' in the pooling flow
=== 2015-12-27 13:27:22,954 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:22,954 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 36 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,954 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 36 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:22,954 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 36 of type 'ValueMap'
=== 2015-12-27 13:27:22,955 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,955 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 37 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,955 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 37 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,955 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 37 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,955 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Canvas'
=== 2015-12-27 13:27:22,955 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 38 of type 'StatefulCanvas' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 38 of type 'StatefulCanvas' in the pooling flow
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 38 of type 'StatefulCanvas'
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 33 of type 'Img' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 33 of type 'Img' in the pooling flow
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 33 of type 'Img'
=== 2015-12-27 13:27:22,956 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,957 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 38 of type 'StatefulCanvas'
=== 2015-12-27 13:27:22,957 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 33 of type 'Img'
=== 2015-12-27 13:27:22,957 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Button'
=== 2015-12-27 13:27:22,957 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/Button.ds.xml: 0ms
=== 2015-12-27 13:27:22,957 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,958 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 39 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,958 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 39 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,958 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 39 of type 'DataSource'
=== 2015-12-27 13:27:22,959 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,959 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 40 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,959 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 40 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,959 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 40 of type 'DataSourceField'
=== 2015-12-27 13:27:22,959 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,959 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,960 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 41 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 41 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 41 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'StatefulCanvas'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 38 of type 'StatefulCanvas'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Canvas'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 42 of type 'Button' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 42 of type 'Button' in the pooling flow
=== 2015-12-27 13:27:22,960 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 42 of type 'Button'
=== 2015-12-27 13:27:22,961 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,961 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 38 of type 'StatefulCanvas'
=== 2015-12-27 13:27:22,961 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 42 of type 'Button'
=== 2015-12-27 13:27:22,961 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ListViewer'
=== 2015-12-27 13:27:22,961 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/ListViewer.ds.xml: 0ms
=== 2015-12-27 13:27:22,961 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,962 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 43 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,962 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 43 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,962 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 43 of type 'DataSource'
=== 2015-12-27 13:27:22,962 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ListGrid'
=== 2015-12-27 13:27:22,963 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/ListGrid.ds.xml: 1ms
=== 2015-12-27 13:27:22,964 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,964 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 45 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,964 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 45 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,964 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 45 of type 'DataSource'
=== 2015-12-27 13:27:22,964 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,965 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 46 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,965 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 46 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,965 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 46 of type 'DataSourceField'
=== 2015-12-27 13:27:22,965 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,965 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,966 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:22,966 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 47 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,966 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 47 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:22,966 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 47 of type 'ValueMap'
=== 2015-12-27 13:27:22,973 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'type'
=== 2015-12-27 13:27:22,974 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'type' in the pooling flow
=== 2015-12-27 13:27:22,974 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,974 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 48 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,974 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 48 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,974 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 48 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,975 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Canvas'
=== 2015-12-27 13:27:22,975 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 49 of type 'ListGrid' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 49 of type 'ListGrid' in the pooling flow
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 49 of type 'ListGrid'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 44 of type 'ListViewer' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 44 of type 'ListViewer' in the pooling flow
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 44 of type 'ListViewer'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 49 of type 'ListGrid'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 44 of type 'ListViewer'
=== 2015-12-27 13:27:22,977 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ListViewerField'
=== 2015-12-27 13:27:22,978 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'ListViewerField' in the pooling flow
=== 2015-12-27 13:27:22,978 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DynamicForm'
=== 2015-12-27 13:27:22,981 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/DynamicForm.ds.xml: 1ms
=== 2015-12-27 13:27:22,981 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,982 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 50 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,982 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 50 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,982 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 50 of type 'DataSource'
=== 2015-12-27 13:27:22,982 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,983 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 51 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,983 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 51 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,983 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 51 of type 'DataSourceField'
=== 2015-12-27 13:27:22,983 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,983 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,984 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:22,984 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 52 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,984 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 52 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:22,984 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 52 of type 'ValueMap'
=== 2015-12-27 13:27:22,987 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,987 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 53 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,987 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 53 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,987 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 53 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Canvas'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 54 of type 'DynamicForm' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 54 of type 'DynamicForm' in the pooling flow
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 54 of type 'DynamicForm'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 54 of type 'DynamicForm'
=== 2015-12-27 13:27:22,988 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'FormItem'
=== 2015-12-27 13:27:22,992 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/FormItem.ds.xml: 3ms
=== 2015-12-27 13:27:22,992 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 55 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 55 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 55 of type 'DataSource'
=== 2015-12-27 13:27:22,993 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 56 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 56 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 56 of type 'DataSourceField'
=== 2015-12-27 13:27:22,993 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:22,993 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:22,998 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 57 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 57 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 57 of type 'MethodDeclaration'
=== 2015-12-27 13:27:22,998 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'type'
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'type' in the pooling flow
=== 2015-12-27 13:27:22,998 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 58 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 58 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:22,998 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 58 of type 'ValueMap'
=== 2015-12-27 13:27:22,999 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 59 of type 'FormItem' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:22,999 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 59 of type 'FormItem' in the pooling flow
=== 2015-12-27 13:27:22,999 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 59 of type 'FormItem'
=== 2015-12-27 13:27:22,999 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 59 of type 'FormItem'
=== 2015-12-27 13:27:22,999 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DetailViewer'
=== 2015-12-27 13:27:23,000 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/DetailViewer.ds.xml: 1ms
=== 2015-12-27 13:27:23,000 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:23,000 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 60 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,000 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 60 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:23,000 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 60 of type 'DataSource'
=== 2015-12-27 13:27:23,001 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:23,001 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 61 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,001 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 61 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:23,001 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 61 of type 'DataSourceField'
=== 2015-12-27 13:27:23,001 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:23,001 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:23,002 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 62 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 62 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 62 of type 'ValueMap'
=== 2015-12-27 13:27:23,002 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'MethodDeclaration'
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 63 of type 'MethodDeclaration' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 63 of type 'MethodDeclaration' in the pooling flow
=== 2015-12-27 13:27:23,002 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 63 of type 'MethodDeclaration'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Canvas'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 64 of type 'DetailViewer' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 64 of type 'DetailViewer' in the pooling flow
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 64 of type 'DetailViewer'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 29 of type 'Canvas'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 64 of type 'DetailViewer'
=== 2015-12-27 13:27:23,003 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DetailViewerField'
=== 2015-12-27 13:27:23,004 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/DetailViewerField.ds.xml: 1ms
=== 2015-12-27 13:27:23,004 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:23,004 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 65 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,004 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 65 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:23,004 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 65 of type 'DataSource'
=== 2015-12-27 13:27:23,004 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField'
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 66 of type 'DataSourceField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 66 of type 'DataSourceField' in the pooling flow
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 66 of type 'DataSourceField'
=== 2015-12-27 13:27:23,005 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'field'
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource null of type 'field' in the pooling flow
=== 2015-12-27 13:27:23,005 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'ValueMap'
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 67 of type 'ValueMap' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 67 of type 'ValueMap' in the pooling flow
=== 2015-12-27 13:27:23,005 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 67 of type 'ValueMap'
=== 2015-12-27 13:27:23,006 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 68 of type 'DetailViewerField' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,006 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 68 of type 'DetailViewerField' in the pooling flow
=== 2015-12-27 13:27:23,006 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 68 of type 'DetailViewerField'
=== 2015-12-27 13:27:23,006 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 68 of type 'DetailViewerField'
=== 2015-12-27 13:27:23,006 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'isomorphicXML'
=== 2015-12-27 13:27:23,006 [op-1] DEBUG XML - Parsed XML from /usr/local/apache-tomcat-8.0.27/webapps/kids/V010402SNAPSHOT/sc/system/schema/isomorphicXML.ds.xml: 0ms
=== 2015-12-27 13:27:23,006 [op-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource'
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 69 of type 'DataSource' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 69 of type 'DataSource' in the pooling flow
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 69 of type 'DataSource'
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 70 of type 'isomorphicXML' and assigned it to thread localhost-startStop-1
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Created DataSource 70 of type 'isomorphicXML' in the pooling flow
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Activated DataSource 70 of type 'isomorphicXML'
=== 2015-12-27 13:27:23,007 [op-1] DEBUG PoolableDataSourceFactory - Cleared and passivated DataSource 70 of type 'isomorphicXML'
=== 2015-12-27 13:27:23,007 [op-1] INFO  PreCache - Isomorphic PreCache complete (191ms)
27-Dec-2015 13:27:23.012 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/local/apache-tomcat-8.0.27/webapps/kids has finished in 3,235 ms
27-Dec-2015 13:27:23.012 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/local/apache-tomcat-8.0.27/webapps/manager
27-Dec-2015 13:27:23.080 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
27-Dec-2015 13:27:23.082 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/local/apache-tomcat-8.0.27/webapps/manager has finished in 70 ms
27-Dec-2015 13:27:23.082 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/local/apache-tomcat-8.0.27/webapps/ROOT
27-Dec-2015 13:27:23.144 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
27-Dec-2015 13:27:23.145 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/local/apache-tomcat-8.0.27/webapps/ROOT has finished in 63 ms
27-Dec-2015 13:27:23.149 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
27-Dec-2015 13:27:23.152 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
27-Dec-2015 13:27:23.153 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 8184 ms
Requesting: /kids-dev/V010402SNAPSHOT/V010402SNAPSHOT.nocache.js
=== 2015-12-27 13:27:26,342 [ec-9] INFO  RequestContext - URL: '/kids-dev/V010402SNAPSHOT/sc/DataSourceLoader', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36': Safari with Accept-Encoding header
=== 2015-12-27 13:27:26,343 [ec-9] DEBUG ConfigParser - Matched var name: gwtModuleName
=== 2015-12-27 13:27:26,344 [ec-9] DEBUG ConfigParser - value after substitution: V010402SNAPSHOT/sc
=== 2015-12-27 13:27:26,380 [ec-9] DEBUG DataSourceLoader - Key[type=com.isomorphic.servlet.DataSourceLoader, annotation=[none]] - For DataSource 'schuelerSimple', got instanceId 75
=== 2015-12-27 13:27:26,416 [ec-9] DEBUG DataSourceLoader - Key[type=com.isomorphic.servlet.DataSourceLoader, annotation=[none]] - For DataSource 'schuelerDetails', got instanceId 81
=== 2015-12-27 13:27:26,456 [ec-9] WARN  Validation - attribute 'customSelectExpresion' is not declared in Component Schema '{DataSourceField.ds.xml}' and strict mode is enabled.  See 'Strict Mode' overview in the documentation for details.DataSource.fields.DataSourceField /DataSource[@ID=schueler]/fields/206/field[@name=gemeinsameEinrichtungVertrag]
=== 2015-12-27 13:27:26,456 [ec-9] WARN  Validation - attribute 'customSelectExpresion' is not declared in Component Schema '{DataSourceField.ds.xml}' and strict mode is enabled.  See 'Strict Mode' overview in the documentation for details.DataSource.fields.DataSourceField /DataSource[@ID=schueler]/fields/207/field[@name=gemeinsameEinrichtungGruppe]
=== 2015-12-27 13:27:26,457 [ec-9] WARN  Validation - attribute 'customSelectExpresion' is not declared in Component Schema '{DataSourceField.ds.xml}' and strict mode is enabled.  See 'Strict Mode' overview in the documentation for details.DataSource.fields.DataSourceField /DataSource[@ID=schueler]/fields/208/field[@name=gemeinsameEinrichtungComponent]
=== 2015-12-27 13:27:27,130 [ec-9] DEBUG DataSourceLoader - Key[type=com.isomorphic.servlet.DataSourceLoader, annotation=[none]] - For DataSource 'test', got instanceId 587
=== 2015-12-27 13:27:27,138 [ec-9] INFO  Compression - /kids-dev/V010402SNAPSHOT/sc/DataSourceLoader: 232086 -> 46994 bytes
=== 2015-12-27 13:27:27,472 [c-10] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-27 13:27:27,472 [c-10] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-27 13:27:27,472 [c-10] INFO  SQLDataSource - [builtinApplication.null] Performing fetch operation with
    criteria: {f_mandant:"mandant"}    values: {f_mandant:"mandant"}
=== 2015-12-27 13:27:27,473 [c-10] INFO  SQLDataSource - [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2015-12-27 13:27:27,474 [c-10] INFO  SQLDataSource - [builtinApplication.null] 462: Executing SQL query on 'SQLSERVER': SELECT t_mandanten.f_id, t_mandanten.f_mandant, t_mandanten.f_application_name, t_mandanten.f_application_long_name, t_mandanten.f_kontakt, t_mandanten.f_kontakt_url, t_mandanten.f_kontakt_email, t_mandanten.f_buchhaltung_email, t_mandanten.f_logo, t_mandanten.f_logo_filename, t_mandanten.f_logo_filesize, t_mandanten.f_logo_date_created, t_mandanten.f_logo_width, t_mandanten.f_logo_height, t_mandanten.f_icon, t_mandanten.f_icon_filename, t_mandanten.f_icon_filesize, t_mandanten.f_icon_date_created FROM t_mandanten WHERE (LOWER(t_mandanten.f_mandant)='mandant')
=== 2015-12-27 13:27:27,485 [c-10] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '824055079'
=== 2015-12-27 13:27:27,485 [c-10] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL query in 'SQLSERVER' using connection '824055079'
=== 2015-12-27 13:27:27,485 [c-10] INFO  SQLDriver - [builtinApplication.null] Executing SQL query on 'SQLSERVER': SELECT t_mandanten.f_id, t_mandanten.f_mandant, t_mandanten.f_application_name, t_mandanten.f_application_long_name, t_mandanten.f_kontakt, t_mandanten.f_kontakt_url, t_mandanten.f_kontakt_email, t_mandanten.f_buchhaltung_email, t_mandanten.f_logo, t_mandanten.f_logo_filename, t_mandanten.f_logo_filesize, t_mandanten.f_logo_date_created, t_mandanten.f_logo_width, t_mandanten.f_logo_height, t_mandanten.f_icon, t_mandanten.f_icon_filename, t_mandanten.f_icon_filesize, t_mandanten.f_icon_date_created FROM t_mandanten WHERE (LOWER(t_mandanten.f_mandant)='mandant')
=== 2015-12-27 13:27:27,488 [c-10] INFO  DSResponse - [builtinApplication.null] DSResponse: List with 1 items
=== 2015-12-27 13:27:28,721 [ec-1] INFO  RequestContext - URL: '/kids-dev/V010402SNAPSHOT/sc/IDACall', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36': Safari with Accept-Encoding header
=== 2015-12-27 13:27:28,722 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: host:localhost:8080
=== 2015-12-27 13:27:28,722 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: connection:keep-alive
=== 2015-12-27 13:27:28,722 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: content-length:855
=== 2015-12-27 13:27:28,722 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: origin:http://localhost:8080
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: accept:*/*
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: referer:http://localhost:8080/kids-dev/
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: accept-language:de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Header Name:Value pair: cookie:JSESSIONID=5E20ABAA90AE0DAA0BE020599E9F7746; lastLoggedInUser=admin%40mandant; GWT_LOCALE=de; human.version=1.4.2%20pre-release%20development%20version%2020151227-1222; isc_cState=ready; GLog=%7B%0D%20%20%20%20trackRPC%3Afalse%0D%7D
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - session exists: 5E20ABAA90AE0DAA0BE020599E9F7746
=== 2015-12-27 13:27:28,723 [ec-1] DEBUG IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - remote user: admin@mandant
=== 2015-12-27 13:27:28,740 [ec-1] DEBUG RPCManager - Processing 1 requests.
=== 2015-12-27 13:27:28,741 [ec-1] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
    },
    operationConfig:{
        dataSource:"test",
        repo:null,
        operationType:"custom",
        textMatchStyle:"exact"
    },
    appID:"builtinApplication",
    operation:"delete",
    oldValues:{
    },
    criteria:{
    }
}
=== 2015-12-27 13:27:28,741 [ec-1] INFO  IDACall - Key[type=com.isomorphic.servlet.IDACall, annotation=[none]] - Performing 1 operation(s)
=== 2015-12-27 13:27:28,745 [ec-1] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-27 13:27:28,745 [ec-1] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-27 13:27:28,745 [ec-1] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_eltern_id:8919}    values: {f_eltern_id:8919}
=== 2015-12-27 13:27:29,113 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '449261950'
=== 2015-12-27 13:27:29,113 [ec-1] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'449261950'
=== 2015-12-27 13:27:29,113 [ec-1] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_rel_schueler_eltern WHERE (t_rel_schueler_eltern.f_eltern_id=8919)
=== 2015-12-27 13:27:29,127 [ec-1] WARN  SQLDataSource - [builtinApplication.null] remove operation affected no rows
=== 2015-12-27 13:27:29,128 [ec-1] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-27 13:27:29,128 [ec-1] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-27 13:27:29,129 [ec-1] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_id:8919}    values: {f_id:8919}
=== 2015-12-27 13:27:29,141 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '2133748684'
=== 2015-12-27 13:27:29,141 [ec-1] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'2133748684'
=== 2015-12-27 13:27:29,141 [ec-1] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_eltern WHERE (t_eltern.f_id=8919)
=== 2015-12-27 13:27:29,144 [ec-1] WARN  SQLDataSource - [builtinApplication.null] remove operation affected no rows
=== 2015-12-27 13:27:29,144 [ec-1] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2015-12-27 13:27:29,144 [ec-1] DEBUG RPCManager - DMI response, dropExtraFields: false
=== 2015-12-27 13:27:29,146 [ec-1] DEBUG SQLDriver - Freeing SQLDriver dbConnection 449261950
=== 2015-12-27 13:27:29,146 [ec-1] DEBUG SQLConnectionManager - About to close connection with hashcode "449261950"
=== 2015-12-27 13:27:29,146 [ec-1] DEBUG SQLDriver - Freeing SQLDriver dbConnection 2133748684
=== 2015-12-27 13:27:29,146 [ec-1] DEBUG SQLConnectionManager - About to close connection with hashcode "2133748684"
=== 2015-12-27 13:27:29,146 [ec-1] INFO  Compression - /kids-dev/V010402SNAPSHOT/sc/IDACall: 159 -> 142 bytes
            I think there are also no logs for the SQLTransaction.
            Still, the two dsRequests are using different connections and THIS IS THE ERROR: They should use the same transaction since they share the same RPCManager... or ? And they can't, since they are using two different connections. If I set autoJoinTransaction to ALL, then even fetches will join the transaction, and this should normally not be necessary.

            I don't have any error log. The DB just gets blocked (deadlock) and I have to restart it. When analyzing the DB, I see that the deadlock occurs because of these two requests, which is normal, since I expect the two requests to execute one after another, and not concurrently.
            Last edited by edulid; 20 Feb 2018, 00:52.

            Comment

              #7
              Hi edulid,

              I don't see any log entry containing commit, rollback, transaction so you are clearly not using connections.

              Why don't you just add the autoJoinTransaction to server.properties? These docs describe the result of this and possible alternatives.
              As it is not clear what the default is, perhaps the behavior you are seeing is correct, but that is for Isomorphic to answer.

              Why do you not want fetches to join transactions? This should be correct most of the time. For example it is necessary after inserts in order to find the generated id for sequences-PKs in Oracle (not sure about MSSQL).

              Best regards
              Blama


              PS: I do not understand why you get a deadlock as the 1st delete does not depend on the 2nd. So either you should get an error returned from the db directly or it should succeed in the end. But that's does not matter here.

              Comment

                #8
                The reason why fetches are not in transactions is explained by Isomorphic here: http://forums.smartclient.com/forum/...409#post209409

                The default setting is described here (ANY_CHANGE) : http://forums.smartclient.com/forum/...405#post209405

                If I change it to ALL: then transactions seem to work, as you can see in this log:
                Code:
                === 2015-12-27 15:50:42,790 [ec-8] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] Passing JDBC URL only to getConnection
=== 2015-12-27 15:50:42,801 [ec-8] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] makeObject() created a pooled Connection '2070155282'
=== 2015-12-27 15:50:42,801 [ec-8] DEBUG SQLConnectionManager - [builtinApplication.null] Borrowed connection '2070155282'
=== 2015-12-27 15:50:42,802 [ec-8] DEBUG SQLTransaction - [builtinApplication.null] Started new SQLSERVER transaction "2070155282"
=== 2015-12-27 15:50:42,802 [ec-8] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'2070155282'
=== 2015-12-27 15:50:42,802 [ec-8] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_rel_schueler_eltern WHERE (t_rel_schueler_eltern.f_eltern_id=8919)
=== 2015-12-27 15:50:42,818 [ec-8] WARN  SQLDataSource - [builtinApplication.null] remove operation affected no rows
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG DSRequest - freeOnExecute is false for request of type remove on DataSource relSchuelerEltern - not freeing resources!
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG ISCKeyedObjectPool - Borrowing object for 'eltern'
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG PoolableDataSourceFactory - Activated DataSource 153 of type 'eltern'
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG DSRequest - Caching instance 153 of DS 'eltern' from DSRequest.getDataSource()
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG DSRequest - Caching instance 153 of DS eltern
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2015-12-27 15:50:42,818 [ec-8] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2015-12-27 15:50:42,820 [ec-8] INFO  SQLDataSource - [builtinApplication.null] Performing remove operation with
    criteria: {f_id:8919}    values: {f_id:8919}
=== 2015-12-27 15:50:42,820 [ec-8] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'2070155282'
=== 2015-12-27 15:50:42,821 [ec-8] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLSERVER': DELETE FROM t_eltern WHERE (t_eltern.f_id=8919)
=== 2015-12-27 15:50:42,825 [ec-8] WARN  SQLDataSource - [builtinApplication.null] remove operation affected no rows
=== 2015-12-27 15:50:42,825 [ec-8] DEBUG DSRequest - freeOnExecute is false for request of type remove on DataSource eltern - not freeing resources!
=== 2015-12-27 15:50:42,825 [ec-8] DEBUG DSRequest - About to free up resources for request of type custom on DataSource test
=== 2015-12-27 15:50:42,825 [ec-8] DEBUG DSRequest - Ignoring freeResources call because this is not a primary request!
=== 2015-12-27 15:50:42,825 [ec-8] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2015-12-27 15:50:42,825 [ec-8] DEBUG SQLTransaction - Committing SQLSERVER transaction "2070155282"
=== 2015-12-27 15:50:42,826 [ec-8] DEBUG RPCManager - DMI response, dropExtraFields: false
                Now I am seeing SQL-Transactions if I set the policy to ALL.

                But, refering again to the old thread (http://forums.smartclient.com/forum/...blocking-my-db) , the default setting should be ANY_CHANGE. Which, according to the docs:
                "Bundle all requests into a transaction, including leading fetches, if there is any change operation in the queue."

                If I explicitely set the policy to ANY_CHANGE, then I get, again, different connections for the two DSRequests.

                The docs say that if there is any change operation in the queue, with ANY_CHANGE, they will be in the same transaction. Deletes ARE change-operations, so this seems not to work in this case. I think THIS is the problem: that this DSRequests are somehow not identified as change-operations.

                I could leave the policy to ALL, but Isomorphic said this would may impact performance (http://forums.smartclient.com/forum/...409#post209409) , and the docs say that ANY_CHANGE should work in this case So it seems to be a bug here.

                Comment

                  #9
                  Hi edulid,

                  that's a good read, thanks. I think I found the problem. In this post in your older thread you can see that the ANY_CHANGE-setting only applies when there are change requests in the *client-sent*-queue.
                  This is clear because the framework can't know your DMI method beforehand.

                  I think one solution is to set the transactionPolicy manually in the 1st line of your DMI (should work in 5.0p).
                  In 5.1p you could use DSTransaction + Queueing if you don't need one's requests for the 2nd requests (which you don't in your use case).
                  If you were dependent on the result like I am here, you could use DSRequest.setDsTransaction().

                  Isomorphic: Wouldn't this be an improvement?
                  • Leave the behavior for client queues as it is.
                  • If the transactionPolicy is ANY_CHANGE or FROM_FIRST_CHANGE, for every change-request that comes in that is not part of a queue, start a Transaction if there is a serverObject-method used.
                  • This way no manual setting of a transactionPolicy in the DMI is necessary.
                  Best regards
                  Blama

                  Comment

                    #10
                    Hi Blama,

                    Originally posted by Blama View Post
                    that's a good read, thanks. I think I found the problem. In this post in your older thread you can see that the ANY_CHANGE-setting only applies when there are change requests in the *client-sent*-queue.
                    This is clear because the framework can't know your DMI method beforehand.
                    You are right, this is the reason, thanks.

                    Originally posted by Blama View Post
                    I think one solution is to set the transactionPolicy manually in the 1st line of your DMI (should work in 5.0p).
                    How ? In my old thread I tried to use dsRequest.getRPCManager().setTransactionPolicy(TransactionPolicy.ALL); but without success. Isomorphic's answer (http://forums.smartclient.com/forum/...579#post209579) was in a subclass of the IDACall servlet. But I don't understand how exactly to set this policy for only this dmi method inside another servlet.
                    So how exactly can I set this policy for this dmi method only ?

                    Originally posted by Blama View Post
                    In 5.1p you could use DSTransaction + Queueing if you don't need one's requests for the 2nd requests (which you don't in your use case).
                    If you were dependent on the result like I am here, you could use DSRequest.setDsTransaction().
                    I don't need the first request results for the second request, BUT I need to make sure that the first request is finished before the second request executes. If not, I may have again a deadlock. Would this be guaranteed? Will the second request be executed AFTER the first one is finished?
                    And if you have some example of this use in 5.1, could you post one please? I am soon upgrading to 5.1 so it would be very important to know how to adapt my DMI methods for this. Thank you

                    Comment

                      #11
                      Hi edulid,

                      I have this in my web.xml:
                      Code:
                          <!-- The IDACall servlet handles all Built-in DataSource operations -->
    <servlet>
        <servlet-name>IDACall</servlet-name>
        <servlet-class>com.mycomp.myproj.server.MyIDACall</servlet-class>
        <!-- <servlet-class>com.isomorphic.servlet.IDACall</servlet-class> -->
    </servlet>
...
    <!-- RPCManager uses this URL by default for Built-in DataSource operations -->
    <servlet-mapping>
        <servlet-name>IDACall</servlet-name>
        <url-pattern>/myproj/sc/IDACall/*</url-pattern>
    </servlet-mapping>
                      I think I only changed the used class.
                      You class might look like:
                      Code:
                      public class MyIDACall extends IDACall {
  
    @Override
    public DSResponse handleDSRequest(DSRequest dsRequest, RPCManager rpc, RequestContext context) throws Exception {
        [B]//depending on dsRequest.getDataSource().getID() modify rpc[/B]
        return super.handleDSRequest(dsRequest, rpc, context);
    }
}
    }
                      If that's already too late (which I think), do this:
                      Code:
                          @Override
    public void processRequest(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
            try {
                RequestContext context = RequestContext.instance(this, request, response);
                
                [B]RPCManager rpc = new RPCManager(request, response);[/B]
                [B]// check rpc.getRequests()[/B]
                [B]// try casting content to DSRequests[/B]
                [B]// check dsRequest.getDataSource().getID()[/B]
                [B]// if your wanted DS: modify rpc[/B]
                [B]processRPCTransaction(rpc, context);[/B]

            } catch (Throwable e) {
                handleError(response, e);
            }
    }
                      This is only a guess, especially the casting part. Make sure your code still works for non-DSRequests, which the client side framework generates as well.

                      For the 5.1p features, see this thread were I started using the feature (nothing in production, yet) and also the very helpful StandaloneDataSourceUsage-docs.

                      Best regards
                      Blama

                      EDIT:
                      The sequential, non-deadlock execution would be guaranteed with manual DSTransaction, yes.
                      Last edited by Blama; 27 Dec 2015, 08:22.

                      Comment

                        #12
                        Originally posted by Blama View Post

                        In 5.1p you could use DSTransaction + Queueing if you don't need one's requests for the 2nd requests (which you don't in your use case).
                        If you were dependent on the result like I am here, you could use DSRequest.setDsTransaction().
                        As I see from your other thread you are always setting DSRequest.setDsTransaction(), as you said, because you are dependent on the result.
                        If not, you say I can use DSTransaction + Queuing (in 5.1). What would be the difference to your code? Only not setting .setDsTransaction() ? But how would the dsRequest then "know" it is part of the transaction? Or what do you mean by queuing (we are in the server -side ?)

                        Comment

                          #13
                          Ah I think you mean, as shown in http://www.smartclient.com/smartgwte...urceUsage.html, dst.processQueue(); instead of the dsRequest.execute()s that you call in your example, right ? Since we are still in a DSRequest, I would further set the RPCManager (as in 5.0). Would this be necessary or not, since we are using here DSTransactions ?

                          Comment

                            #14
                            Hi edulid,

                            see the example in the linked docs. This shows the different way, which saves you the req.excute() (but needs dst.registerRequest(req)).
                            req.setDsTransaction(dst) seems to be needed always (Isomorphic: Is this true?).

                            Best regards
                            Blama

                            EDIT: Crosspost

                            Comment

                              #15
                              Originally posted by Blama View Post
                              req.setDsTransaction(dst) seems to be needed always (Isomorphic: Is this true?).
                              And Isomorphic is the DSRequest.setRPCManager() also necessary in these cases? (we are now talking about 5.1)
                              Last edited by edulid; 27 Dec 2015, 13:31.

                              Comment

                              Previous 1 2 3 template Next
                              Working...
                              X