isUnique Validator executed 3 times instead of 1 leading to a bug

Blama

Registered Developer

Join Date: Sep 2009
Posts: 6815

isUnique Validator executed 3 times instead of 1 leading to a bug

26 Aug 2013, 23:52

Hi Isomorphic,

I have a strange situation where a Validator is executed three times for a single add operation. I thought this might be related to a missing serverOnly="true", which is not the case.
Could you tell me why the validator is executed so many times?
As you can see from the log this leads to an error message, even though everything executed as wanted (meaning that the INSERT is sent successfully to Oracle and commited).
The first validate checks OK, then the 2nd as well. Then the add is executed and afterwards the 3rd validate fails.
Also, this does not happen always (see 2nd error log), so this seems to be a timing related.

I use v9.0p_2013-08-17/EVAL Deployment

Please see the two logs (good and bad) and the ds.xml:

ds.xml

Code:

<DataSource dbName="Oracle" tableName="T_CAMPAIGN" ID="T_CAMPAIGN" dataSourceVersion="1" serverType="sql">
    <fields>
        <field primaryKey="true" hidden="true" name="ID" type="sequence"></field>
        <field hidden="true" name="TENANT_ID" title="TENANT_ID" type="integer"></field>
        <field foreignKey="V_USER_CREATED_BY.ID" name="CREATED_BY" title="Erstellt von" type="integer"></field>
        <field name="CREATED_AT" title="Erstellt am" type="date"></field>
        <field foreignKey="V_USER_MODIFIED_BY.ID" name="MODIFIED_BY" title="Ge�ndert von" type="integer"></field>
        <field name="MODIFIED_AT" title="Ge�ndert am" type="date"></field>
        <field foreignKey="T_COMPANY.ID" name="COMPANY_ID" title="COMPANY_ID" type="integer"></field>
        <field foreignKey="T_DISTRIBUTOR.ID" name="DISTRIBUTOR_ID" title="DISTRIBUTOR_ID" type="integer"></field>
        <field name="SHORTNAME" title="Kurzname" length="30" type="text" escapeHTML="true" required="true">
            <validators>
                <validator type="isUnique" errorMessage="Der Kurzname wird bereits verwendet!" serverOnly="true"></validator>
            </validators>
        </field>
        <field name="NAME" title="Name" length="60" type="text" escapeHTML="true" required="true">
            <validators>
                <validator type="isUnique" errorMessage="Der Name wird bereits verwendet!" serverOnly="true"></validator>
            </validators>
        </field>
        <field name="DESCRIPTION" title="Beschreibung" length="1000" type="text" escapeHTML="true"></field>
        <field name="STARTDATE" title="Startdatum" type="date" required="true">
            <validators>
                <validator type="serverCustom" serverOnly="true">
                    <serverCondition><![CDATA[
                      #if(         "$!record.ENDDATE" != "" )
                        #set( $gb = $!record.ENDDATE.getTime() )
                      ##elseif(     "$!dataSource.fetchById($record.ID).ENDDATE" != "" )
                        ##set( $gb = $!dataSource.fetchById($record.ID).ENDDATE.getTime() )
                      #else
                        #set( $gb = -1 )
                      #end
                      
                      $value.getTime() <= $gb || $gb == -1]]></serverCondition>
                    <errorMessage>Bitte beachten Sie, dass das Startdatum nicht kleiner als das Enddatum sein darf (sofern ein Enddatum gesetzt ist)!</errorMessage>
                </validator>
            </validators>
        </field>
        <field name="ENDDATE" title="Enddatum" type="date">
            <validators>
                <!-- Erkl�rung unter http://forums.smartclient.com/showthread.php?p=108718#post108718 -->
                <validator type="serverCustom" serverOnly="true">
                    <serverCondition><![CDATA[
                      #if(         "$!value" != "" )
                        #set( $gb = $!value.getTime() )
                      #else
                        #set( $gb = -1 )
                      #end

                      #if( "$!record.STARTDATE" != "" )
                        #set( $gv = $!record.STARTDATE.getTime() )
                      #else
                        #set( $gv = $!dataSource.fetchById($record.ID).STARTDATE.getTime() )
                      #end
                      $gv <= $gb || $gb == -1]]></serverCondition>
                    <errorMessage>Bitte beachten Sie, dass das Startdatum nicht kleiner als das Enddatum sein darf (sofern ein Enddatum gesetzt ist)!</errorMessage>
                </validator>
            </validators>
        </field>
    </fields>
    <!--  <serverObject lookupStyle="new" className="com.lmscompany.lms.server.worker.T_CAMPAIGN" />  -->
    <operationBindings>
        <operationBinding operationType="add">
            <values fieldName="CREATED_BY" value="$session.authenticatedUserID" />
            <values fieldName="CREATED_AT" value="$currentDate" />
            <values fieldName="MODIFIED_BY" value="$session.authenticatedUserID" />
            <values fieldName="MODIFIED_AT" value="$currentDate" />
            <values fieldName="TENANT_ID" value="$session.authenticatedUserTenantID" />

            <values fieldName="DISTRIBUTOR_ID" value="$!session.authenticatedUserDistributorID" />
            <values fieldName="COMPANY_ID" value="$!session.authenticatedUserCompanyID" />
        </operationBinding>
        <operationBinding operationType="update">
            <values fieldName="MODIFIED_BY" value="$session.authenticatedUserID" />
            <values fieldName="MODIFIED_AT" value="$currentDate" />
            <values fieldName="TENANT_ID" value="$session.authenticatedUserTenantID" />
        </operationBinding>
    </operationBindings>
</DataSource>

error log with error:

Code:

=== 2013-08-26 19:52:32,136 [ec-1] INFO  RequestContext - URL: '/lms/lms/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0': Moz (Gecko) with Accept-Encoding header
=== 2013-08-26 19:52:32,136 [ec-1] DEBUG IDACall - Header Name:Value pair: host:localhost:8080
=== 2013-08-26 19:52:32,136 [ec-9] INFO  RequestContext - URL: '/lms/lms/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0': Moz (Gecko) with Accept-Encoding header
=== 2013-08-26 19:52:32,136 [ec-1] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0
=== 2013-08-26 19:52:32,136 [ec-1] DEBUG IDACall - Header Name:Value pair: accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-08-26 19:52:32,136 [ec-9] DEBUG IDACall - Header Name:Value pair: host:localhost:8080
=== 2013-08-26 19:52:32,136 [ec-1] DEBUG IDACall - Header Name:Value pair: accept-language:de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
=== 2013-08-26 19:52:32,136 [ec-9] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0
=== 2013-08-26 19:52:32,136 [ec-1] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2013-08-26 19:52:32,136 [ec-9] DEBUG IDACall - Header Name:Value pair: accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: accept-language:de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/lms/Lms.html
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: content-length:2646
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: cookie:JSESSIONID=DD35A972D4D0B2A5934C63286C3181BF; isc_cState=ready; GLog=%7B%0D%20%20%20%20left%3A544%2C%20%0D%20%20%20%20top%3A0%2C%20%0D%20%20%20%20width%3A640%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%0D%7D
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/lms/Lms.html
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: connection:keep-alive
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: content-length:1103
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: pragma:no-cache
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: cookie:JSESSIONID=DD35A972D4D0B2A5934C63286C3181BF; isc_cState=ready; GLog=%7B%0D%20%20%20%20left%3A544%2C%20%0D%20%20%20%20top%3A0%2C%20%0D%20%20%20%20width%3A640%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%0D%7D
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - Header Name:Value pair: cache-control:no-cache
=== 2013-08-26 19:52:32,137 [ec-9] DEBUG IDACall - Header Name:Value pair: connection:keep-alive
=== 2013-08-26 19:52:32,137 [ec-1] DEBUG IDACall - session exists: DD35A972D4D0B2A5934C63286C3181BF
=== 2013-08-26 19:52:32,138 [ec-9] DEBUG IDACall - Header Name:Value pair: pragma:no-cache
=== 2013-08-26 19:52:32,138 [ec-1] DEBUG IDACall - remote user: Administrator
=== 2013-08-26 19:52:32,138 [ec-9] DEBUG IDACall - Header Name:Value pair: cache-control:no-cache
=== 2013-08-26 19:52:32,138 [ec-9] DEBUG IDACall - session exists: DD35A972D4D0B2A5934C63286C3181BF
=== 2013-08-26 19:52:32,138 [ec-9] DEBUG IDACall - remote user: Administrator
=== 2013-08-26 19:52:32,141 [ec-9] DEBUG XML - Parsed XML from (in memory stream): 2ms
=== 2013-08-26 19:52:32,142 [ec-1] DEBUG XML - Parsed XML from (in memory stream): 3ms
=== 2013-08-26 19:52:32,146 [ec-9] DEBUG RPCManager - Processing 1 requests.
=== 2013-08-26 19:52:32,147 [ec-9] DEBUG DSRequest - Caching instance 792 of DS T_CAMPAIGN from DSRequest.getDataSource()
=== 2013-08-26 19:52:32,147 [ec-9] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"add"
    },
    componentId:"isc_CampaignList_0",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_add",
    oldValues:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:52:32,147 [ec-9] INFO  IDACall - Performing 1 operation(s)
=== 2013-08-26 19:52:32,147 [ec-9] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,147 [ec-9] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:52:32,148 [ec-1] DEBUG RPCManager - Processing 3 requests.
=== 2013-08-26 19:52:32,148 [ec-1] DEBUG DSRequest - Caching instance 1046 of DS T_CAMPAIGN from DSRequest.getDataSource()
=== 2013-08-26 19:52:32,149 [ec-1] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:52:32,149 [ec-1] DEBUG RPCManager - Request #2 (DSRequest) payload: {
    values:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:52:32,150 [ec-1] DEBUG RPCManager - Request #3 (DSRequest) payload: {
    values:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        NAME:"2",
        SHORTNAME:"2",
        STARTDATE:new Date(1376431200000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:52:32,150 [ec-1] INFO  IDACall - Performing 3 operation(s)
=== 2013-08-26 19:52:32,150 [ec-1] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,150 [ec-1] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:52:32,150 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,151 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:52:32,151 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,151 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,152 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,152 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"2"}    values: {NAME:"2"}
=== 2013-08-26 19:52:32,153 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,159 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,159 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing pingTest 'select 1 from dual' on connection 2080034564
=== 2013-08-26 19:52:32,160 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Borrowed connection '2080034564'
=== 2013-08-26 19:52:32,160 [ec-1] DEBUG SQLTransaction - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Started new Oracle transaction "2080034564"
=== 2013-08-26 19:52:32,160 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,160 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,162 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,166 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,166 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add] No public zero-argument method named '_T_CAMPAIGN_add' found, performing generic datasource operation
=== 2013-08-26 19:52:32,166 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,166 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,167 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,167 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"2"}    values: {NAME:"2"}
=== 2013-08-26 19:52:32,168 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,178 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,179 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,179 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,179 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,179 [ec-9] DEBUG PoolableSQLConnectionFactory - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing pingTest 'select 1 from dual' on connection 764764025
=== 2013-08-26 19:52:32,179 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"2"}    values: {SHORTNAME:"2"}
=== 2013-08-26 19:52:32,180 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,180 [ec-9] DEBUG SQLConnectionManager - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Borrowed connection '764764025'
=== 2013-08-26 19:52:32,180 [ec-9] DEBUG SQLTransaction - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Started new Oracle transaction "764764025"
=== 2013-08-26 19:52:32,180 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:52:32,180 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,180 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,180 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,181 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,181 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,182 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,182 [ec-1] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,182 [ec-1] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:52:32,182 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,182 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:52:32,183 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,183 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,183 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,184 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"2"}    values: {NAME:"2"}
=== 2013-08-26 19:52:32,184 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,194 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,195 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,195 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,195 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,195 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,195 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,195 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"2"}    values: {SHORTNAME:"2"}
=== 2013-08-26 19:52:32,196 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,196 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,197 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,197 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:52:32,197 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,198 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,199 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add] Performing add operation with
    criteria: {NAME:"2",SHORTNAME:"2",STARTDATE:new Date(1376431200000),CREATED_BY:0,CREATED_AT:new Date(1377539552148),MODIFIED_BY:0,MODIFIED_AT:new Date(1377539552148),TENANT_ID:0,DISTRIBUTOR_ID:"",COMPANY_ID:0}    values: {NAME:"2",SHORTNAME:"2",STARTDATE:new Date(1376431200000),CREATED_BY:0,CREATED_AT:new Date(1377539552148),MODIFIED_BY:0,MODIFIED_AT:new Date(1377539552148),TENANT_ID:0,DISTRIBUTOR_ID:"",COMPANY_ID:0}
=== 2013-08-26 19:52:32,199 [ec-9] DEBUG SQLValuesClause - [builtinApplication.T_CAMPAIGN_add] Sequences: {ID=__default}
=== 2013-08-26 19:52:32,210 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,210 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,210 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add] About to execute SQL update in 'Oracle' using connection'764764025'
=== 2013-08-26 19:52:32,211 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add] Executing SQL update on 'Oracle': INSERT INTO T_CAMPAIGN (COMPANY_ID, CREATED_AT, CREATED_BY, DISTRIBUTOR_ID, MODIFIED_AT, MODIFIED_BY, NAME, SHORTNAME, STARTDATE, TENANT_ID, ID) VALUES (0, TO_DATE('2013-08-26 19:52:32','YYYY-MM-DD HH24:MI:SS'), 0, NULL, TO_DATE('2013-08-26 19:52:32','YYYY-MM-DD HH24:MI:SS'), 0, '2', '2', TO_DATE('2013-08-14 00:00:00','YYYY-MM-DD HH24:MI:SS'), 0, T_CAMPAIGN_ID.NextVal)
=== 2013-08-26 19:52:32,211 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,211 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"2"}    values: {SHORTNAME:"2"}
=== 2013-08-26 19:52:32,212 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,213 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,213 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,213 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,215 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,216 [ec-9] DEBUG SQLDataSource - [builtinApplication.T_CAMPAIGN_add] add operation affected 1 rows
=== 2013-08-26 19:52:32,216 [ec-1] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,216 [ec-1] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:52:32,216 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:52:32,216 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN_ID.CurrVal FROM DUAL
=== 2013-08-26 19:52:32,216 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,216 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:52:32,217 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,217 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,217 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,217 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add] primaryKeys: {ID=20}
=== 2013-08-26 19:52:32,218 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,218 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:52:32,218 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"2"}    values: {NAME:"2"}
=== 2013-08-26 19:52:32,218 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,218 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,219 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,219 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    criteria: {ID:"20"}    values: {ID:"20"}
=== 2013-08-26 19:52:32,220 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,220 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,220 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,220 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='2')
=== 2013-08-26 19:52:32,220 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.COMPANY_ID, T_CAMPAIGN.CREATED_AT, T_CAMPAIGN.CREATED_BY, T_CAMPAIGN.DESCRIPTION, T_CAMPAIGN.DISTRIBUTOR_ID, T_CAMPAIGN.ENDDATE, T_CAMPAIGN.ID, T_CAMPAIGN.MODIFIED_AT, T_CAMPAIGN.MODIFIED_BY, T_CAMPAIGN.NAME, T_CAMPAIGN.SHORTNAME, T_CAMPAIGN.STARTDATE, T_CAMPAIGN.TENANT_ID FROM T_CAMPAIGN WHERE (T_CAMPAIGN.ID=20)
=== 2013-08-26 19:52:32,221 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:52:32,221 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.COMPANY_ID, T_CAMPAIGN.CREATED_AT, T_CAMPAIGN.CREATED_BY, T_CAMPAIGN.DESCRIPTION, T_CAMPAIGN.DISTRIBUTOR_ID, T_CAMPAIGN.ENDDATE, T_CAMPAIGN.ID, T_CAMPAIGN.MODIFIED_AT, T_CAMPAIGN.MODIFIED_BY, T_CAMPAIGN.NAME, T_CAMPAIGN.SHORTNAME, T_CAMPAIGN.STARTDATE, T_CAMPAIGN.TENANT_ID FROM T_CAMPAIGN WHERE (T_CAMPAIGN.ID=20)
=== 2013-08-26 19:52:32,221 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:52:32,227 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 1 items
=== 2013-08-26 19:52:32,228 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add] DSResponse: List with 1 items
=== 2013-08-26 19:52:32,228 [ec-9] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-08-26 19:52:32,228 [ec-9] DEBUG SQLTransaction - Committing Oracle transaction "764764025"
=== 2013-08-26 19:52:32,229 [ec-9] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:52:32,230 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle with hashcode "764764025"
=== 2013-08-26 19:52:32,230 [ec-9] DEBUG SQLTransaction - Ending Oracle transaction "764764025"
=== 2013-08-26 19:52:32,230 [ec-9] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "764764025"
=== 2013-08-26 19:52:32,230 [ec-9] DEBUG PoolableSQLConnectionFactory - Executing pingTest 'select 1 from dual' on connection 764764025
=== 2013-08-26 19:52:32,231 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,231 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,232 [ec-9] INFO  Compression - /lms/lms/sc/IDACall: 350 -> 238 bytes
=== 2013-08-26 19:52:32,234 [ec-1] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:52:32,234 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:52:32,234 [ec-1] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:52:32,235 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"2"}    values: {SHORTNAME:"2"}
=== 2013-08-26 19:52:32,235 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:52:32,236 [ec-1] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,236 [ec-1] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:52:32,236 [ec-1] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='2')
=== 2013-08-26 19:52:32,238 [ec-1] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 1 items
=== 2013-08-26 19:52:32,243 [ec-1] DEBUG DefaultValidators - [builtinApplication.T_CAMPAIGN_validate] unique check: pkField: ID, old PK: 20, new PK: null
=== 2013-08-26 19:52:32,243 [ec-1] DEBUG DefaultValidators - [builtinApplication.T_CAMPAIGN_validate] unique check: key fields do not match, fails unique check
=== 2013-08-26 19:52:32,243 [ec-1] DEBUG ValidationContext - [builtinApplication.T_CAMPAIGN_validate] Adding validation errors at path '/T_CAMPAIGN/SHORTNAME/SHORTNAME': {errorMessage=Der Kurzname wird bereits verwendet!}
=== 2013-08-26 19:52:32,244 [ec-1] INFO  Validation - [builtinApplication.T_CAMPAIGN_validate] Validation error: [
    {
        SHORTNAME:{
            errorMessage:"Der Kurzname wird bereits verwendet!"
        }
    }
]
=== 2013-08-26 19:52:32,244 [ec-1] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-08-26 19:52:32,244 [ec-1] DEBUG SQLTransaction - Rolling back Oracle transaction "2080034564"
=== 2013-08-26 19:52:32,245 [ec-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:52:32,245 [ec-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:52:32,245 [ec-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:52:32,246 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle with hashcode "2080034564"
=== 2013-08-26 19:52:32,246 [ec-1] DEBUG SQLTransaction - Ending Oracle transaction "2080034564"
=== 2013-08-26 19:52:32,246 [ec-1] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "2080034564"
=== 2013-08-26 19:52:32,246 [ec-1] DEBUG PoolableSQLConnectionFactory - Executing pingTest 'select 1 from dual' on connection 2080034564
=== 2013-08-26 19:52:32,247 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,247 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,247 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,247 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,247 [ec-1] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:52:32,248 [ec-1] INFO  Compression - /lms/lms/sc/IDACall: 425 -> 201 bytes

error log without error:

Code:

=== 2013-08-26 19:55:03,394 [ec-6] INFO  RequestContext - URL: '/lms/lms/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0': Moz (Gecko) with Accept-Encoding header
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: host:localhost:8080
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: accept-language:de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2013-08-26 19:55:03,394 [ec-6] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/lms/Lms.html
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: content-length:2646
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: cookie:JSESSIONID=DD35A972D4D0B2A5934C63286C3181BF; isc_cState=ready; GLog=%7B%0D%20%20%20%20left%3A544%2C%20%0D%20%20%20%20top%3A0%2C%20%0D%20%20%20%20width%3A640%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%0D%7D
=== 2013-08-26 19:55:03,395 [ec-9] INFO  RequestContext - URL: '/lms/lms/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0': Moz (Gecko) with Accept-Encoding header
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: connection:keep-alive
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: pragma:no-cache
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - Header Name:Value pair: cache-control:no-cache
=== 2013-08-26 19:55:03,395 [ec-9] DEBUG IDACall - Header Name:Value pair: host:localhost:8080
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - session exists: DD35A972D4D0B2A5934C63286C3181BF
=== 2013-08-26 19:55:03,395 [ec-9] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (Windows NT 6.2; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0
=== 2013-08-26 19:55:03,395 [ec-6] DEBUG IDACall - remote user: Administrator
=== 2013-08-26 19:55:03,395 [ec-9] DEBUG IDACall - Header Name:Value pair: accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: accept-language:de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/lms/Lms.html
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: content-length:1103
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: cookie:JSESSIONID=DD35A972D4D0B2A5934C63286C3181BF; isc_cState=ready; GLog=%7B%0D%20%20%20%20left%3A544%2C%20%0D%20%20%20%20top%3A0%2C%20%0D%20%20%20%20width%3A640%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%0D%7D
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: connection:keep-alive
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: pragma:no-cache
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - Header Name:Value pair: cache-control:no-cache
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - session exists: DD35A972D4D0B2A5934C63286C3181BF
=== 2013-08-26 19:55:03,396 [ec-9] DEBUG IDACall - remote user: Administrator
=== 2013-08-26 19:55:03,400 [ec-9] DEBUG XML - Parsed XML from (in memory stream): 2ms
=== 2013-08-26 19:55:03,400 [ec-6] DEBUG XML - Parsed XML from (in memory stream): 3ms
=== 2013-08-26 19:55:03,403 [ec-9] DEBUG RPCManager - Processing 1 requests.
=== 2013-08-26 19:55:03,404 [ec-9] DEBUG DSRequest - Caching instance 792 of DS T_CAMPAIGN from DSRequest.getDataSource()
=== 2013-08-26 19:55:03,404 [ec-9] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"add"
    },
    componentId:"isc_CampaignList_1",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_add",
    oldValues:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:55:03,404 [ec-9] INFO  IDACall - Performing 1 operation(s)
=== 2013-08-26 19:55:03,405 [ec-9] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,405 [ec-9] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:55:03,405 [ec-6] DEBUG RPCManager - Processing 3 requests.
=== 2013-08-26 19:55:03,406 [ec-6] DEBUG DSRequest - Caching instance 1046 of DS T_CAMPAIGN from DSRequest.getDataSource()
=== 2013-08-26 19:55:03,406 [ec-6] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:55:03,407 [ec-6] DEBUG RPCManager - Request #2 (DSRequest) payload: {
    values:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:55:03,407 [ec-6] DEBUG RPCManager - Request #3 (DSRequest) payload: {
    values:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    operationConfig:{
        dataSource:"T_CAMPAIGN",
        operationType:"validate"
    },
    validationMode:"partial",
    appID:"builtinApplication",
    operation:"T_CAMPAIGN_validate",
    oldValues:{
        SHORTNAME:"4",
        NAME:"4",
        STARTDATE:new Date(1691964000000)
    },
    criteria:{
    }
}
=== 2013-08-26 19:55:03,408 [ec-6] INFO  IDACall - Performing 3 operation(s)
=== 2013-08-26 19:55:03,408 [ec-6] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,408 [ec-6] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:55:03,408 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,408 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:55:03,409 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,409 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,409 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,410 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"4"}    values: {NAME:"4"}
=== 2013-08-26 19:55:03,411 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,413 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,413 [ec-6] DEBUG PoolableSQLConnectionFactory - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing pingTest 'select 1 from dual' on connection 2080034564
=== 2013-08-26 19:55:03,414 [ec-6] DEBUG SQLConnectionManager - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Borrowed connection '2080034564'
=== 2013-08-26 19:55:03,414 [ec-6] DEBUG SQLTransaction - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Started new Oracle transaction "2080034564"
=== 2013-08-26 19:55:03,414 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,414 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,417 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,430 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,430 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,430 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,431 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"4"}    values: {SHORTNAME:"4"}
=== 2013-08-26 19:55:03,431 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,433 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,433 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add] No public zero-argument method named '_T_CAMPAIGN_add' found, performing generic datasource operation
=== 2013-08-26 19:55:03,433 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,433 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,433 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,433 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,434 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,434 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,434 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"4"}    values: {NAME:"4"}
=== 2013-08-26 19:55:03,435 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,435 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,435 [ec-6] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,436 [ec-6] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:55:03,436 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,436 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,436 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:55:03,436 [ec-9] DEBUG PoolableSQLConnectionFactory - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing pingTest 'select 1 from dual' on connection 764764025
=== 2013-08-26 19:55:03,437 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,437 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,437 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,437 [ec-9] DEBUG SQLConnectionManager - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Borrowed connection '764764025'
=== 2013-08-26 19:55:03,437 [ec-9] DEBUG SQLTransaction - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Started new Oracle transaction "764764025"
=== 2013-08-26 19:55:03,437 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:55:03,438 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,438 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"4"}    values: {NAME:"4"}
=== 2013-08-26 19:55:03,438 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,439 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,439 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,440 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,440 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,441 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,452 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,453 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,453 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,453 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"4"}    values: {SHORTNAME:"4"}
=== 2013-08-26 19:55:03,454 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,465 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,465 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,465 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,465 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,465 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:55:03,465 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,466 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"4"}    values: {SHORTNAME:"4"}
=== 2013-08-26 19:55:03,467 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,467 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,467 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,468 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,468 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,468 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add] Performing add operation with
    criteria: {SHORTNAME:"4",NAME:"4",STARTDATE:new Date(1691964000000),CREATED_BY:0,CREATED_AT:new Date(1377539703405),MODIFIED_BY:0,MODIFIED_AT:new Date(1377539703405),TENANT_ID:0,DISTRIBUTOR_ID:"",COMPANY_ID:0}    values: {SHORTNAME:"4",NAME:"4",STARTDATE:new Date(1691964000000),CREATED_BY:0,CREATED_AT:new Date(1377539703405),MODIFIED_BY:0,MODIFIED_AT:new Date(1377539703405),TENANT_ID:0,DISTRIBUTOR_ID:"",COMPANY_ID:0}
=== 2013-08-26 19:55:03,469 [ec-9] DEBUG SQLValuesClause - [builtinApplication.T_CAMPAIGN_add] Sequences: {ID=__default}
=== 2013-08-26 19:55:03,469 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,470 [ec-6] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,470 [ec-6] DEBUG DeclarativeSecurity - DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:55:03,470 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,470 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate] No public zero-argument method named '_T_CAMPAIGN_validate' found, performing generic datasource operation
=== 2013-08-26 19:55:03,470 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add] About to execute SQL update in 'Oracle' using connection'764764025'
=== 2013-08-26 19:55:03,470 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add] Executing SQL update on 'Oracle': INSERT INTO T_CAMPAIGN (COMPANY_ID, CREATED_AT, CREATED_BY, DISTRIBUTOR_ID, MODIFIED_AT, MODIFIED_BY, NAME, SHORTNAME, STARTDATE, TENANT_ID, ID) VALUES (0, TO_DATE('2013-08-26 19:55:03','YYYY-MM-DD HH24:MI:SS'), 0, NULL, TO_DATE('2013-08-26 19:55:03','YYYY-MM-DD HH24:MI:SS'), 0, '4', '4', TO_DATE('2023-08-14 00:00:00','YYYY-MM-DD HH24:MI:SS'), 0, T_CAMPAIGN_ID.NextVal)
=== 2013-08-26 19:55:03,470 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,471 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,471 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,471 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [NAME, ID]    criteria: {NAME:"4"}    values: {NAME:"4"}
=== 2013-08-26 19:55:03,472 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,473 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,473 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,473 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.NAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.NAME='4')
=== 2013-08-26 19:55:03,474 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,477 [ec-9] DEBUG SQLDataSource - [builtinApplication.T_CAMPAIGN_add] add operation affected 1 rows
=== 2013-08-26 19:55:03,477 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:55:03,478 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN_ID.CurrVal FROM DUAL
=== 2013-08-26 19:55:03,479 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add] primaryKeys: {ID=22}
=== 2013-08-26 19:55:03,479 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,479 [ec-9] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_add] DataSource T_CAMPAIGN is not in the pre-checked list, processing...
=== 2013-08-26 19:55:03,480 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,480 [ec-9] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,480 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Performing fetch operation with
    criteria: {ID:"22"}    values: {ID:"22"}
=== 2013-08-26 19:55:03,481 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,488 [ec-6] DEBUG DeclarativeSecurity - [builtinApplication.T_CAMPAIGN_validate] Processing security checks for DataSource null, field null
=== 2013-08-26 19:55:03,488 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-08-26 19:55:03,488 [ec-9] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] 792: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.COMPANY_ID, T_CAMPAIGN.CREATED_AT, T_CAMPAIGN.CREATED_BY, T_CAMPAIGN.DESCRIPTION, T_CAMPAIGN.DISTRIBUTOR_ID, T_CAMPAIGN.ENDDATE, T_CAMPAIGN.ID, T_CAMPAIGN.MODIFIED_AT, T_CAMPAIGN.MODIFIED_BY, T_CAMPAIGN.NAME, T_CAMPAIGN.SHORTNAME, T_CAMPAIGN.STARTDATE, T_CAMPAIGN.TENANT_ID FROM T_CAMPAIGN WHERE (T_CAMPAIGN.ID=22)
=== 2013-08-26 19:55:03,488 [ec-9] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '764764025'
=== 2013-08-26 19:55:03,489 [ec-6] DEBUG AppBase - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-08-26 19:55:03,489 [ec-9] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.COMPANY_ID, T_CAMPAIGN.CREATED_AT, T_CAMPAIGN.CREATED_BY, T_CAMPAIGN.DESCRIPTION, T_CAMPAIGN.DISTRIBUTOR_ID, T_CAMPAIGN.ENDDATE, T_CAMPAIGN.ID, T_CAMPAIGN.MODIFIED_AT, T_CAMPAIGN.MODIFIED_BY, T_CAMPAIGN.NAME, T_CAMPAIGN.SHORTNAME, T_CAMPAIGN.STARTDATE, T_CAMPAIGN.TENANT_ID FROM T_CAMPAIGN WHERE (T_CAMPAIGN.ID=22)
=== 2013-08-26 19:55:03,489 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Performing fetch operation with
    outputs: [ID, SHORTNAME]    criteria: {SHORTNAME:"4"}    values: {SHORTNAME:"4"}
=== 2013-08-26 19:55:03,490 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-08-26 19:55:03,491 [ec-6] INFO  SQLDataSource - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] 1046: Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,491 [ec-6] DEBUG SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] About to execute SQL query in 'Oracle' using connection '2080034564'
=== 2013-08-26 19:55:03,491 [ec-6] INFO  SQLDriver - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] Executing SQL query on 'Oracle': SELECT T_CAMPAIGN.ID, T_CAMPAIGN.SHORTNAME FROM T_CAMPAIGN WHERE (T_CAMPAIGN.SHORTNAME='4')
=== 2013-08-26 19:55:03,493 [ec-6] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_validate, builtinApplication.null] DSResponse: List with 0 items
=== 2013-08-26 19:55:03,493 [ec-6] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-08-26 19:55:03,493 [ec-6] DEBUG SQLTransaction - Committing Oracle transaction "2080034564"
=== 2013-08-26 19:55:03,494 [ec-6] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:55:03,494 [ec-6] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:55:03,494 [ec-6] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:55:03,494 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add, builtinApplication.null] DSResponse: List with 1 items
=== 2013-08-26 19:55:03,494 [ec-9] INFO  DSResponse - [builtinApplication.T_CAMPAIGN_add] DSResponse: List with 1 items
=== 2013-08-26 19:55:03,495 [ec-9] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-08-26 19:55:03,495 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle with hashcode "2080034564"
=== 2013-08-26 19:55:03,495 [ec-6] DEBUG SQLTransaction - Ending Oracle transaction "2080034564"
=== 2013-08-26 19:55:03,495 [ec-9] DEBUG SQLTransaction - Committing Oracle transaction "764764025"
=== 2013-08-26 19:55:03,495 [ec-6] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "2080034564"
=== 2013-08-26 19:55:03,495 [ec-6] DEBUG PoolableSQLConnectionFactory - Executing pingTest 'select 1 from dual' on connection 2080034564
=== 2013-08-26 19:55:03,496 [ec-9] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-08-26 19:55:03,496 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,496 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,496 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,496 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,496 [ec-6] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,496 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle with hashcode "764764025"
=== 2013-08-26 19:55:03,496 [ec-9] DEBUG SQLTransaction - Ending Oracle transaction "764764025"
=== 2013-08-26 19:55:03,496 [ec-6] INFO  Compression - /lms/lms/sc/IDACall: 346 -> 135 bytes
=== 2013-08-26 19:55:03,497 [ec-9] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "764764025"
=== 2013-08-26 19:55:03,497 [ec-9] DEBUG PoolableSQLConnectionFactory - Executing pingTest 'select 1 from dual' on connection 764764025
=== 2013-08-26 19:55:03,498 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,498 [ec-9] DEBUG SQLTransaction - Returning transactional connection for Oracle (connection is null)
=== 2013-08-26 19:55:03,498 [ec-9] INFO  Compression - /lms/lms/sc/IDACall: 350 -> 240 bytes

Thanks,
Blama

Tags: None

Blama

Registered Developer

Join Date: Sep 2009

Posts: 6815
#2

9 Oct 2013, 23:58

@All other readers:
Might be related to/solved with http://forums.smartclient.com/showthread.php?t=28138
Comment

Previous template Next

Announcement

isUnique Validator executed 3 times instead of 1 leading to a bug

Comment