[claudiobosticco]

thanks a lot for the further clarification

[Isomorphic]

No, your updates will be unaffected; the requirement for criteria to be included in values is only about validation. For normal update requests that specify a record by its primaryKeys, we now copy the primaryKeys into the values to be validated, so you don't have to add the PK to dsRequest.values. This can't be done for allowMultiUpdate, since the criteria could involve operators other than just equals, there is no way to automatically translate such criteria into values.

Note, there will often be no way to translate such criteria into values by hand, either. This just means that validators that rely on existing stored values, like the ones we have been discussing in this thread, are usually not going to work with multi-updates.

[claudiobosticco]

In short, as of tomorrow's builds of 6.1 / 11.1 and 7.0 / 12.0, you do not need to include criteria in values when you are doing a regular update via primaryKey, but you do need to do so for allowMultiUpdate requests.

Thanks for the clarification, I've also just read the docs.
Actually I don't use frequently the allowMultiUpdate feature.
If I understand correctly, those updates won't work at all if I switch to the latest build (because I've never included criteria in values).
Will they raise an exception, or log a warning, or what else?

[Isomorphic]

claudiobosticco

We have clarified the documentation on this issue of whether criteria should be included in values or not, and also changed the validation flow in the specific case of applyWhen validations to match this clarified position. In short, as of tomorrow's builds of 6.1 / 11.1 and 7.0 / 12.0, you do not need to include criteria in values when you are doing a regular update via primaryKey, but you do need to do so for allowMultiUpdate requests.

Regards,
Isomorphic Software Support

[Isomorphic]

@Blama

There is good news on this - we discovered and fixed another potential case where validations could be inherited incorrectly. We have posted more details on your original thread

[Blama]

Hi claudiobosticco, Hi Isomorphic,

this is a bit off an hijacked thread, but claudiobosticco was able to see the same error I saw. Then Isomorphic fixed some source of this error here:

Yes, the validation should not be happening for an included field - we're looking into it right now. claudiobosticco we see why you are getting the problem causing the validation to fire inappropriately, but right now the underlying cause is not clear - again, we are looking into it

But for me it still occurs (only after some time):

Hi Isomorphic,

really bad news. This issue appeared again, this time using v10.1p_2017-03-02.
Did your fix from #32 also make it in 5.1p?



Best regards
Blama

Now my question is: Can you still reproduce it with your code from #22 - #27?
If so, perhaps you could send some stack trace, log, or similar to Isomorphic, so that they can investigate further.

Thank you & Best regards
Blama

[Isomorphic]

We are discussing this internally. We'll post back on here soon

[claudiobosticco]

Usually, when I create a DSRequest (server side) for an update, I don't set the criteria also in the values. Is it always mandatory, or only when there's an applyWhen validator?

Hello Isomorphic, could you please comment about this question?

[claudiobosticco]

This DSRequest is going to end up back in that same method

oh well, this is a bit embarassing, in this aspect my test case is completely flawed.
After fixing this, the test case works.

And what about my other comment?

Usually, when I create a DSRequest (server side) for an update, I don't set the criteria also in the values. Is it always mandatory, or only when there's an applyWhen validator?

[Isomorphic]

Your DataSource only has one update operation configured:

<operationBinding operationType="update" serverMethod="updateTestValidator">
    <serverObject lookupStyle="new" className="com.juve.jas.utils.TestValidatorDMI"/>
</operationBinding>

However, testValidatorDMI::updateTestValidator() blindly creates and executes a new "update" DSRequests on the same DataSource. This DSRequest is going to end up back in that same method - of course it is, that is the only "update" operation defined for that DataSource. You need to do something to prevent the second request from just going down the same path as the first: use a different operationId and test for it in the code, for example, or look to see if the DSRequest came from the client or the server (dsRequest.isClientRequest()).

[claudiobosticco]

Hello, apart from my comment above, I tried your suggestion, so the new DMI code is:

public class TestValidatorDMI {

    public DSResponse updateTestValidator(DSRequest dsRequest, HttpServletRequest request, RPCManager rpcManager) throws Exception {
        DSRequest dsRequestTest = new DSRequest("JAS_ANAG_GIOCATORI_TEST", DataSource.OP_UPDATE, rpcManager);
        dsRequestTest.setCriteria("ID_REC", dsRequest.getCriteria().get("ID_REC"));
        dsRequestTest.setFieldValue("ID_REC", dsRequest.getCriteria().get("ID_REC"));
        dsRequestTest.setFieldValue("ID_STATUS_GIOCATORE_FK", 5);
        return dsRequestTest.execute();
    }

}

the dataSource is unchanged:

<DataSource xmlns:fmt="urn:jsptld:/WEB-INF/fmt.tld" xmlns="http://www.smartclient.com/schema"
            ID="JAS_ANAG_GIOCATORI_TEST"
            tableName="JAS_ANAG_GIOCATORI"
            schema="DBJAS"
            dbName="dbJas"
            serverType="sql"
        >
    <fields>
        <field name="ID_REC"  primaryKey="true"  type="sequence" hidden="true" sequenceName="SEQUENCE_ID_REC"/>
        <field name="NOME" length="30" type="text" required="true"/>
        <field name="COGNOME" length="50" type="text" required="true"/>
        <field name="LUOGO_NASCITA" length="60" type="text">
            <validators>
                <validator type="required">
                    <applyWhen fieldName="ID_NAZIONE_NASCITA_FK" operator="notEqual" value="118"/>
                </validator>
            </validators>
        </field>
        <field  name="ID_NAZIONE_NASCITA_FK" type="integer"/>
        <field name="ID_STATUS_GIOCATORE_FK" type="integer" />
    </fields>
    <operationBindings>
        <operationBinding operationType="update" serverMethod="updateTestValidator">
            <serverObject lookupStyle="new" className="com.juve.jas.utils.TestValidatorDMI"/>
        </operationBinding>
    </operationBindings>
</DataSource>

Now, there's a very strange behaviour: it keeps on doing the same fetch (the log is cut after 3 fetches...):

2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: host:axelpro.local:8443 
2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: connection:keep-alive 
2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: content-length:1149 
2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: origin:https://axelpro.local:8443 
2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36 
2017-06-07 09:54:40,765 DEBUG IDACall Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: accept:*/* 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: dnt:1 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: referer:https://axelpro.local:8443/Jas/ 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: accept-encoding:gzip, deflate, br 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: accept-language:it-IT,it;q=0.8,en-US;q=0.6,en;q=0.4 
2017-06-07 09:54:40,766 DEBUG IDACall Header Name:Value pair: cookie:JSESSIONID=39E340BC9BEF2136394262E0B8EB7774; isc_cState=ready; GLog=%7B%0A%20%20%20%20trackRPC%3Atrue%2C%20%0A%20%20%20%20isc_pageURL%3A%22https%3A//axelpro.local%3A8443/Jas/%23ath%22%2C%20%0A%20%20%20%20isc_pageGUID%3A%222DDA87CD-2702-4597-B094-9B6E3683B5D6%22%2C%20%0A%20%20%20%20priorityDefaults%3A%7B%0A%20%20%20%20%20%20%20%20sgwtInternal%3A1%2C%20%0A%20%20%20%20%20%20%20%20Log%3A4%0A%20%20%20%20%7D%2C%20%0A%20%20%20%20defaultPriority%3A3%2C%20%0A%20%20%20%20left%3A215%2C%20%0A%20%20%20%20top%3A22%2C%20%0A%20%20%20%20width%3A1280%2C%20%0A%20%20%20%20height%3A951%0A%7D 
2017-06-07 09:54:40,766 DEBUG IDACall session exists: 39E340BC9BEF2136394262E0B8EB7774 
2017-06-07 09:54:40,769 DEBUG XML Parsed XML from (in memory stream): 2ms 
2017-06-07 09:54:40,770 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'transaction' but null was returned 
2017-06-07 09:54:40,770 DEBUG PoolableDataSourceFactory Created DataSource 1975 of type 'Object' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:54:40,771 DEBUG PoolableDataSourceFactory Created DataSource 1976 of type 'List' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:54:40,771 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'elem' but null was returned 
2017-06-07 09:54:40,772 DEBUG RPCManager Processing 1 requests. 
2017-06-07 09:54:40,772 DEBUG PoolableDataSourceFactory Created DataSource 1977 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:54:40,772 DEBUG DSRequest Caching instance 1977 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-06-07 09:54:40,772 DEBUG DSRequest Caching instance 1977 of DS JAS_ANAG_GIOCATORI_TEST 
2017-06-07 09:54:40,773 DEBUG RPCManager Request #1 (DSRequest) payload: {
    criteria:{
        ID_REC:499
    },
    values:{
        ID_REC:499
    },
    operationConfig:{
        dataSource:"JAS_ANAG_GIOCATORI_TEST",
        repo:null,
        operationType:"update",
        textMatchStyle:"exact"
    },
    appID:"builtinApplication",
    operation:"JAS_ANAG_GIOCATORI_TEST_update",
    oldValues:{
        ID_REC:499
    }
} 
2017-06-07 09:54:40,773 INFO  IDACall Performing 1 operation(s) 
2017-06-07 09:54:40,773 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:54:40,773 DEBUG DeclarativeSecurity DataSource JAS_ANAG_GIOCATORI_TEST is not in the pre-checked list, processing... 
2017-06-07 09:54:40,776 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_REC:499,
    LUOGO_NASCITA:null
} 
2017-06-07 09:54:40,776 DEBUG PoolableDataSourceFactory Created DataSource 1978 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:54:40,776 DEBUG DSRequest Caching instance 1978 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-06-07 09:54:40,776 DEBUG DSRequest Caching instance 1978 of DS JAS_ANAG_GIOCATORI_TEST 
2017-06-07 09:54:40,776 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:54:40,776 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:54:44,147 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:54:44,147 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:54:44,147 DEBUG AppBase [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application 
2017-06-07 09:54:44,147 DEBUG AppBase [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation 
2017-06-07 09:54:44,148 INFO  SQLDataSource [builtinApplication.null] Performing fetch operation with
    criteria: {ID_REC:499}    values: {ID_REC:499} 
2017-06-07 09:54:44,148 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/server_network_closed.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-06-07 09:54:44,148 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/opener_opened.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-06-07 09:54:44,148 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/server_client_exchange.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-06-07 09:54:44,149 DEBUG SQLDataSource [builtinApplication.null] DataSource 1978 acquired SQLDriver instance 1008244188 during initialization 
2017-06-07 09:54:44,149 INFO  SQLDataSource [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause 
2017-06-07 09:54:44,150 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:54:44,150 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,150 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-06-07 09:54:44,150 INFO  SQLDataSource [builtinApplication.null] 1978: Executing SQL query on 'dbJas': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:54:44,150 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,150 DEBUG PoolableSQLConnectionFactory [builtinApplication.null] makeObject() created an unpooled Connection '688459482' 
2017-06-07 09:54:44,150 DEBUG SQLConnectionManager [builtinApplication.null] Borrowed connection '688459482' 
2017-06-07 09:54:44,150 DEBUG SQLTransaction [builtinApplication.null] Started new dbJas transaction "688459482" 
2017-06-07 09:54:44,150 DEBUG SQLDataSource [builtinApplication.null] Setting DSRequest as being part of a transaction 
2017-06-07 09:54:44,150 INFO  SQLDriver [builtinApplication.null] Executing SQL query on 'dbJas' using connection '688459482': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:54:44,150 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-06-07 09:54:44,151 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,152 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-06-07 09:54:44,152 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,152 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-06-07 09:54:44,152 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:54:44,152 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,152 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /monitoring*; matched=false 
2017-06-07 09:54:44,153 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /monitoring*; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-06-07 09:54:44,153 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:54:44,153 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /monitoring*; matched=false 
2017-06-07 09:54:44,154 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:54:44,153 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /*.jsp; matched=false 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:54:44,154 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /monitoring*; matched=false 
2017-06-07 09:54:44,154 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-06-07 09:54:44,154 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-06-07 09:54:44,154 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:54:44,154 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-06-07 09:54:44,154 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-06-07 09:54:44,161 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:54:44,161 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:54:44,161 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:54:44,161 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:54:44,161 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'sequence' but null was returned 
2017-06-07 09:54:44,161 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:54:44,161 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:54:44,161 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:54:44,162 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:54:44,162 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:54:44,162 DEBUG DefaultValidators NOTE: Record after applying stored values is:
{
    ID_REC:499,
    LUOGO_NASCITA:"CUNEO"
} 
2017-06-07 09:54:44,162 DEBUG DefaultValidators NOTE: Merged conditionRecord is:
{
    ID_NAZIONE_NASCITA_FK:118,
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO",
    NOME:"Simone",
    COGNOME:"MURATORE"
} 
2017-06-07 09:54:44,163 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:54:44,163 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:54:44,163 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:54:44,163 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:54:44,163 INFO  DefaultValidators on field: 'LUOGO_NASCITA' conditional validator of type 'required' is: inactive 
2017-06-07 09:54:44,164 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:54:44,164 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:54:44,164 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:54:44,164 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:54:44,165 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:54:44,165 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:54:44,165 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-06-07 09:54:44,166 DEBUG PoolableDataSourceFactory Created DataSource 1979 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:54:44,166 DEBUG DSRequest Caching instance 1979 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-06-07 09:54:44,166 DEBUG DSRequest Caching instance 1979 of DS JAS_ANAG_GIOCATORI_TEST 
2017-06-07 09:54:44,166 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:54:44,166 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:01,647 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:01,647 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:01,648 DEBUG AppBase [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application 
2017-06-07 09:57:01,648 DEBUG AppBase [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation 
2017-06-07 09:57:01,649 INFO  SQLDataSource [builtinApplication.null] Performing fetch operation with
    criteria: {ID_REC:499}    values: {ID_REC:499} 
2017-06-07 09:57:01,649 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,650 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,649 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,650 DEBUG SQLDataSource [builtinApplication.null] DataSource 1979 acquired SQLDriver instance 1179510431 during initialization 
2017-06-07 09:57:01,650 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,651 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,650 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,651 INFO  SQLDataSource [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause 
2017-06-07 09:57:01,651 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,652 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,652 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:57:01,654 INFO  SQLDataSource [builtinApplication.null] 1979: Executing SQL query on 'dbJas': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:57:01,654 DEBUG SQLDataSource [builtinApplication.null] Setting DSRequest as being part of a transaction 
2017-06-07 09:57:01,654 INFO  SQLDriver [builtinApplication.null] Executing SQL query on 'dbJas' using connection '688459482': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:57:01,654 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,654 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /monitoring*; matched=false 
2017-06-07 09:57:01,655 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/messaging'; to: '/isomorphic/messaging' 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /isomorphic/idacall*; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /monitoring*; matched=false 
2017-06-07 09:57:01,655 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:57:01,655 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/*.jsp; matched=false 
2017-06-07 09:57:01,656 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-06-07 09:57:01,656 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/messaging'; pattern is /monitoring*; matched=false 
2017-06-07 09:57:01,656 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-06-07 09:57:01,668 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:57:01,668 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:57:01,668 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:57:01,668 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'sequence' but null was returned 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:57:01,669 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:57:01,670 DEBUG DefaultValidators NOTE: Record after applying stored values is:
{
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO"
} 
2017-06-07 09:57:01,670 DEBUG DefaultValidators NOTE: Merged conditionRecord is:
{
    ID_NAZIONE_NASCITA_FK:118,
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO",
    NOME:"Simone",
    COGNOME:"MURATORE"
} 
2017-06-07 09:57:01,670 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:01,670 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:57:01,671 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:01,671 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:57:01,671 INFO  DefaultValidators on field: 'LUOGO_NASCITA' conditional validator of type 'required' is: inactive 
2017-06-07 09:57:01,672 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:01,672 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:57:01,672 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:01,672 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:57:01,673 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:01,673 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:01,674 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-06-07 09:57:01,674 DEBUG PoolableDataSourceFactory Created DataSource 1980 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:57:01,674 DEBUG DSRequest Caching instance 1980 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-06-07 09:57:01,674 DEBUG DSRequest Caching instance 1980 of DS JAS_ANAG_GIOCATORI_TEST 
2017-06-07 09:57:01,675 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:01,675 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:02,557 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:02,557 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:02,558 DEBUG AppBase [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application 
2017-06-07 09:57:02,558 DEBUG AppBase [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation 
2017-06-07 09:57:02,559 INFO  SQLDataSource [builtinApplication.null] Performing fetch operation with
    criteria: {ID_REC:499}    values: {ID_REC:499} 
2017-06-07 09:57:02,559 DEBUG SQLDataSource [builtinApplication.null] DataSource 1980 acquired SQLDriver instance 1517656029 during initialization 
2017-06-07 09:57:02,560 INFO  SQLDataSource [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause 
2017-06-07 09:57:02,561 INFO  SQLDataSource [builtinApplication.null] 1980: Executing SQL query on 'dbJas': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:57:02,561 DEBUG SQLDataSource [builtinApplication.null] Setting DSRequest as being part of a transaction 
2017-06-07 09:57:02,561 INFO  SQLDriver [builtinApplication.null] Executing SQL query on 'dbJas' using connection '688459482': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-06-07 09:57:02,572 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:57:02,572 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:57:02,572 INFO  DSResponse DSResponse: List with 1 items 
2017-06-07 09:57:02,572 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-06-07 09:57:02,573 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'sequence' but null was returned 
2017-06-07 09:57:02,573 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:02,573 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:02,573 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-06-07 09:57:02,576 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:57:02,576 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-06-07 09:57:02,576 DEBUG DefaultValidators NOTE: Record after applying stored values is:
{
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO"
} 
2017-06-07 09:57:02,577 DEBUG DefaultValidators NOTE: Merged conditionRecord is:
{
    ID_NAZIONE_NASCITA_FK:118,
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO",
    NOME:"Simone",
    COGNOME:"MURATORE"
} 
2017-06-07 09:57:02,577 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:02,577 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:57:02,577 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:02,577 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:57:02,577 INFO  DefaultValidators on field: 'LUOGO_NASCITA' conditional validator of type 'required' is: inactive 
2017-06-07 09:57:02,578 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:02,578 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-06-07 09:57:02,578 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-06-07 09:57:02,578 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-06-07 09:57:02,579 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:02,579 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-06-07 09:57:02,580 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-06-07 09:57:02,580 DEBUG PoolableDataSourceFactory Created DataSource 1981 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-8 
2017-06-07 09:57:02,580 DEBUG DSRequest Caching instance 1981 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-06-07 09:57:02,580 DEBUG DSRequest Caching instance 1981 of DS JAS_ANAG_GIOCATORI_TEST 
2017-06-07 09:57:02,580 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-06-07 09:57:02,580 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
[cut]

...until a stack overflow error:

2017-06-07 10:12:04,262 INFO  SQLDataSource [builtinApplication.null] Performing fetch operation with
    criteria: {ID_REC:499}    values: {ID_REC:499} 
2017-06-07 10:12:04,262 DEBUG SQLDataSource [builtinApplication.null] DataSource 4689 acquired SQLDriver instance 1534284657 during initialization 
2017-06-07 10:12:04,263 INFO  SQLDataSource [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause 
2017-06-07 10:12:04,340 WARN  RequestContext dsRequest.execute() failed:  
java.lang.StackOverflowError
    at org.apache.commons.lang.text.StrBuilder.ensureCapacity(StrBuilder.java:232)
    at org.apache.commons.lang.text.StrBuilder.append(StrBuilder.java:626)
    at org.apache.velocity.runtime.parser.ParserTokenManager.SkipLexicalActions(ParserTokenManager.java:5437)
    at org.apache.velocity.runtime.parser.ParserTokenManager.getNextToken(ParserTokenManager.java:5389)
    at org.apache.velocity.runtime.parser.Parser.jj_scan_token(Parser.java:3567)
    at org.apache.velocity.runtime.parser.Parser.jj_3R_73(Parser.java:2905)
    at org.apache.velocity.runtime.parser.Parser.jj_3R_63(Parser.java:3413)
    at org.apache.velocity.runtime.parser.Parser.jj_3R_38(Parser.java:2809)
    at org.apache.velocity.runtime.parser.Parser.jj_3R_24(Parser.java:2841)
    at org.apache.velocity.runtime.parser.Parser.jj_3_1(Parser.java:3219)
    at org.apache.velocity.runtime.parser.Parser.jj_2_1(Parser.java:2661)
    at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:356)
    at org.apache.velocity.runtime.parser.Parser.process(Parser.java:317)
    at org.apache.velocity.runtime.parser.Parser.parse(Parser.java:117)
    at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:1226)
    at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:1181)
    at org.apache.velocity.runtime.RuntimeInstance.evaluate(RuntimeInstance.java:1297)
    at org.apache.velocity.runtime.RuntimeInstance.evaluate(RuntimeInstance.java:1265)
    at org.apache.velocity.app.VelocityEngine.evaluate(VelocityEngine.java:199)
    at com.isomorphic.velocity.Velocity.evaluate(Velocity.java:371)
    at com.isomorphic.velocity.Velocity.evaluateAsString(Velocity.java:296)
    at com.isomorphic.velocity.Velocity.evaluateWithSnippets(Velocity.java:496)
    at com.isomorphic.sql.SQLDataSource.generateSQLStatement(SQLDataSource.java:1486)
    at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1723)
    at com.isomorphic.sql.SQLDataSource.processRequest(SQLDataSource.java:434)
    at com.isomorphic.sql.SQLDataSource.executeFetch(SQLDataSource.java:379)
    at com.isomorphic.datasource.DataSource.execute(DataSource.java:2224)
    at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:629)
    at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:546)
    at com.isomorphic.application.AppBase.execute(AppBase.java:489)
    at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:2807)
    at com.juve.jas.utils.TestValidatorDMI.fetchTestValidator(TestValidatorDMI.java:22)
[cut]

am I missing something?

[claudiobosticco]

Whoa, I didn't know that. Usually, when I create a DSRequest (server side) for an update, I don't set the criteria also in the values. Is it always mandatory, or only when there's an applyWhen validator?

[Isomorphic]

Now this is happening because the key value "ID_REC" is only present in the criteria. If you look at the request sent from the client in the SmartClient Developer Console, you will see that the complete record - sent up as "values" - includes the criteria field(s); your server-created DSRequest should do the same thing. For example, add this line:

dsRequestTest.setFieldValue("ID_REC", dsRequest.getCriteria().get("ID_REC"));

[claudiobosticco]

Sorry, you're right about the posted DMI test case, but I've got the same behaviour using the correct version:

public class TestValidatorDMI {

    public DSResponse updateTestValidator(DSRequest dsRequest, HttpServletRequest request, RPCManager rpcManager) throws Exception {
        DSRequest dsRequestTest = new DSRequest("JAS_ANAG_GIOCATORI_TEST", DataSource.OP_UPDATE, rpcManager);
        dsRequestTest.setCriteria("ID_REC", dsRequest.getCriteria().get("ID_REC"));
        dsRequestTest.setFieldValue("ID_STATUS_GIOCATORE_FK", 5);
        dsRequestTest.execute();
        return new DSResponse().setFailure();
    }
}

It gives this server log:

2017-05-25 15:20:53,876 DEBUG RPCManager Processing 1 requests. 
2017-05-25 15:20:53,884 DEBUG PoolableDataSourceFactory Created DataSource 1993 of type 'DataSource' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,887 DEBUG PoolableDataSourceFactory Created DataSource 1994 of type 'DataSourceField' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,887 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'field' but null was returned 
2017-05-25 15:20:53,890 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'validator' but null was returned 
2017-05-25 15:20:53,892 DEBUG PoolableDataSourceFactory Created DataSource 1995 of type 'Validator' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,894 DEBUG PoolableDataSourceFactory Created DataSource 1997 of type 'Criterion' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,894 DEBUG PoolableDataSourceFactory Created DataSource 1996 of type 'AdvancedCriteria' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,895 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'applyWhen' but null was returned 
2017-05-25 15:20:53,900 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'operationBinding' but null was returned 
2017-05-25 15:20:53,904 DEBUG PoolableDataSourceFactory Created DataSource 1998 of type 'OperationBinding' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,906 DEBUG PoolableDataSourceFactory Created DataSource 1999 of type 'ServerObject' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,907 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'serverObject' but null was returned 
2017-05-25 15:20:53,908 DEBUG PoolableDataSourceFactory Created DataSource 2000 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,908 DEBUG DSRequest Caching instance 2000 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-05-25 15:20:53,908 DEBUG DSRequest Caching instance 2000 of DS JAS_ANAG_GIOCATORI_TEST 
2017-05-25 15:20:53,909 DEBUG RPCManager Request #1 (DSRequest) payload: {
    criteria:{
        ID_REC:499
    },
    values:{
        ID_REC:499
    },
    operationConfig:{
        dataSource:"JAS_ANAG_GIOCATORI_TEST",
        repo:null,
        operationType:"update",
        textMatchStyle:"exact"
    },
    appID:"builtinApplication",
    operation:"JAS_ANAG_GIOCATORI_TEST_update",
    oldValues:{
        ID_REC:499
    }
} 
2017-05-25 15:20:53,909 INFO  IDACall Performing 1 operation(s) 
2017-05-25 15:20:53,909 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-05-25 15:20:53,909 DEBUG DeclarativeSecurity DataSource JAS_ANAG_GIOCATORI_TEST is not in the pre-checked list, processing... 
2017-05-25 15:20:53,918 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_REC:499,
    LUOGO_NASCITA:null
} 
2017-05-25 15:20:53,918 DEBUG PoolableDataSourceFactory Created DataSource 2001 of type 'JAS_ANAG_GIOCATORI_TEST' and assigned it to thread http-bio-8443-exec-51 
2017-05-25 15:20:53,918 DEBUG DSRequest Caching instance 2001 of DS 'JAS_ANAG_GIOCATORI_TEST' from DSRequest.getDataSource() 
2017-05-25 15:20:53,918 DEBUG DSRequest Caching instance 2001 of DS JAS_ANAG_GIOCATORI_TEST 
2017-05-25 15:20:53,918 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-05-25 15:20:53,918 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-05-25 15:20:53,918 DEBUG AppBase [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application 
2017-05-25 15:20:53,919 DEBUG AppBase [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation 
2017-05-25 15:20:53,919 INFO  SQLDataSource [builtinApplication.null] Performing fetch operation with
    criteria: {ID_REC:499}  values: {ID_REC:499} 
2017-05-25 15:20:53,920 DEBUG SQLDataSource [builtinApplication.null] DataSource 2001 acquired SQLDriver instance 1749392828 during initialization 
2017-05-25 15:20:53,920 INFO  SQLDataSource [builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause 
2017-05-25 15:20:53,921 INFO  SQLDataSource [builtinApplication.null] 2001: Executing SQL query on 'dbJas': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-05-25 15:20:54,002 DEBUG PoolableSQLConnectionFactory [builtinApplication.null] makeObject() created an unpooled Connection '846649119' 
2017-05-25 15:20:54,002 DEBUG SQLConnectionManager [builtinApplication.null] Borrowed connection '846649119' 
2017-05-25 15:20:54,002 DEBUG SQLTransaction [builtinApplication.null] Started new dbJas transaction "846649119" 
2017-05-25 15:20:54,002 DEBUG SQLDataSource [builtinApplication.null] Setting DSRequest as being part of a transaction 
2017-05-25 15:20:54,002 INFO  SQLDriver [builtinApplication.null] Executing SQL query on 'dbJas' using connection '846649119': SELECT JAS_ANAG_GIOCATORI.ID_REC, JAS_ANAG_GIOCATORI.NOME, JAS_ANAG_GIOCATORI.COGNOME, JAS_ANAG_GIOCATORI.LUOGO_NASCITA, JAS_ANAG_GIOCATORI.ID_NAZIONE_NASCITA_FK, JAS_ANAG_GIOCATORI.ID_STATUS_GIOCATORE_FK FROM DBJAS.JAS_ANAG_GIOCATORI WHERE (JAS_ANAG_GIOCATORI.ID_REC=499) 
2017-05-25 15:20:54,009 INFO  DSResponse DSResponse: List with 1 items 
2017-05-25 15:20:54,009 DEBUG DSRequest freeOnExecute is false for request of type fetch on DataSource JAS_ANAG_GIOCATORI_TEST - not freeing resources! 
2017-05-25 15:20:54,009 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'sequence' but null was returned 
2017-05-25 15:20:54,010 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-05-25 15:20:54,010 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-05-25 15:20:54,010 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'text' but null was returned 
2017-05-25 15:20:54,010 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-05-25 15:20:54,010 DEBUG PoolableDataSourceFactory Tried to create DataSource  of type 'integer' but null was returned 
2017-05-25 15:20:54,011 DEBUG DefaultValidators NOTE: Record after applying stored values is:
{
    ID_REC:499,
    LUOGO_NASCITA:"CUNEO"
} 
2017-05-25 15:20:54,011 DEBUG DefaultValidators NOTE: Merged conditionRecord is:
{
    ID_NAZIONE_NASCITA_FK:118,
    ID_REC:499,
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:"CUNEO",
    NOME:"Simone",
    COGNOME:"MURATORE"
} 
2017-05-25 15:20:54,011 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-05-25 15:20:54,012 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:54,012 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-05-25 15:20:54,012 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-05-25 15:20:54,012 INFO  DefaultValidators on field: 'LUOGO_NASCITA' conditional validator of type 'required' is: inactive 
2017-05-25 15:20:54,012 DEBUG DefaultOperators value (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-05-25 15:20:54,012 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:54,013 DEBUG DefaultOperators passedOp (class java.math.BigDecimal): 118: isEqualToConfiguredValue 
2017-05-25 15:20:54,013 DEBUG DefaultOperators isEqualToConfiguredValue returnstrue 
2017-05-25 15:20:56,982 DEBUG DeclarativeSecurity Processing security checks for DataSource null, field null 
2017-05-25 15:20:56,982 DEBUG DeclarativeSecurity Request is not a client request, ignoring security checks. 
2017-05-25 15:20:56,983 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/opener_opened.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-05-25 15:20:56,983 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/server_client_exchange.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-05-25 15:20:56,990 INFO  RequestContext URL: '/Jas/isomorphic/system/reference/skin/images/server_network_closed.png', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36': Safari with Accept-Encoding header 
2017-05-25 15:20:56,990 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-05-25 15:20:56,990 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /images/*; matched=false 
2017-05-25 15:20:56,990 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /isomorphic/resthandler*; matched=false 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-05-25 15:20:56,991 DEBUG DefaultValidators on field: 'LUOGO_NASCITA' for validator type 'required', 'applyWhen' is:
{
    fieldName:"ID_NAZIONE_NASCITA_FK",
    operator:"notEqual",
    value:"118"
}
record is:
{
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /images/*; matched=false 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /**; matched=true 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 1 of 10 in additional filter chain; firing Filter: 'ChannelProcessingFilter' 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /images/*; matched=false 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-05-25 15:20:56,991 DEBUG DefaultValidators NOTE: Record after applying stored values is:
{
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-05-25 15:20:56,991 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-05-25 15:20:56,991 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,991 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /isomorphic/resthandler*; matched=false 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 2 of 10 in additional filter chain; firing Filter: 'ConcurrentSessionFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /isomorphic/resthandler*; matched=false 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 3 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /**; matched=true 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /**; matched=true 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 1 of 10 in additional filter chain; firing Filter: 'ChannelProcessingFilter' 
2017-05-25 15:20:56,992 DEBUG DefaultValidators NOTE: Merged conditionRecord is:
{
    ID_STATUS_GIOCATORE_FK:5,
    LUOGO_NASCITA:null
} 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 1 of 10 in additional filter chain; firing Filter: 'ChannelProcessingFilter' 
2017-05-25 15:20:56,992 DEBUG DefaultOperators value (null): isEqualToConfiguredValue 
2017-05-25 15:20:56,992 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-05-25 15:20:56,992 DEBUG DefaultFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-05-25 15:20:56,992 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 2 of 10 in additional filter chain; firing Filter: 'ConcurrentSessionFilter' 
2017-05-25 15:20:56,992 DEBUG DefaultFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 3 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 4 of 10 in additional filter chain; firing Filter: 'LogoutFilter' 
2017-05-25 15:20:56,992 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 2 of 10 in additional filter chain; firing Filter: 'ConcurrentSessionFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 5 of 10 in additional filter chain; firing Filter: 'CasAuthenticationFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 3 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter' 
2017-05-25 15:20:56,992 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 6 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 4 of 10 in additional filter chain; firing Filter: 'LogoutFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 7 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 5 of 10 in additional filter chain; firing Filter: 'CasAuthenticationFilter' 
2017-05-25 15:20:56,993 DEBUG DefaultOperators passedOp (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter' 
2017-05-25 15:20:56,993 DEBUG DefaultOperators isEqualToConfiguredValue returnsfalse 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 6 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter' 
2017-05-25 15:20:56,993 INFO  DefaultValidators on field: 'LUOGO_NASCITA' conditional validator of type 'required' is: active 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 4 of 10 in additional filter chain; firing Filter: 'LogoutFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 7 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 5 of 10 in additional filter chain; firing Filter: 'CasAuthenticationFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor' 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 6 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter' 
2017-05-25 15:20:56,993 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/opener_opened.png'; to: '/isomorphic/system/reference/skin/images/opener_opened.png' 
2017-05-25 15:20:56,993 DEBUG ValidationContext Adding validation errors at path '/JAS_ANAG_GIOCATORI_TEST/LUOGO_NASCITA/LUOGO_NASCITA': {errorMessage=Field is required} 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter' 
2017-05-25 15:20:56,993 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,993 DEBUG DefaultOperators value (null): isEqualToConfiguredValue 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 7 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter' 
2017-05-25 15:20:56,993 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /isomorphic/idacall*; matched=false 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor' 
2017-05-25 15:20:56,993 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /tools/*.jsp; matched=false 
2017-05-25 15:20:56,993 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter' 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; to: '/isomorphic/system/reference/skin/images/server_client_exchange.png' 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/opener_opened.png'; pattern is /monitoring*; matched=false 
2017-05-25 15:20:56,994 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-05-25 15:20:56,994 DEBUG DefaultOperators operand (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:56,994 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter' 
2017-05-25 15:20:56,994 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/opener_opened.png reached end of additional filter chain; proceeding with original chain 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor' 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /isomorphic/idacall*; matched=false 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Converted URL to lowercase, from: '/isomorphic/system/reference/skin/images/server_network_closed.png'; to: '/isomorphic/system/reference/skin/images/server_network_closed.png' 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /tools/*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG DefaultOperators passedOp (class java.lang.String): "118": isEqualToConfiguredValue 
2017-05-25 15:20:56,994 DEBUG DefaultOperators isEqualToConfiguredValue returnsfalse 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /isomorphic/idacall*; matched=false 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_client_exchange.png'; pattern is /monitoring*; matched=false 
2017-05-25 15:20:56,994 DEBUG ValidationContext Adding validation errors at path '/JAS_ANAG_GIOCATORI_TEST/LUOGO_NASCITA': {errorMessage=Field is required} 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /tools/*.jsp; matched=false 
2017-05-25 15:20:56,994 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-05-25 15:20:56,994 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-05-25 15:20:56,994 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-05-25 15:20:56,994 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_client_exchange.png reached end of additional filter chain; proceeding with original chain 
2017-05-25 15:20:56,994 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /tools/visualbuilder/*.jsp; matched=false 
2017-05-25 15:20:56,995 DEBUG ExpressionBasedFilterInvocationSecurityMetadataSource Candidate is: '/isomorphic/system/reference/skin/images/server_network_closed.png'; pattern is /monitoring*; matched=false 
2017-05-25 15:20:56,995 DEBUG FilterSecurityInterceptor Public object - authentication not attempted 
2017-05-25 15:20:56,995 DEBUG FilterChainProxy /isomorphic/system/reference/skin/images/server_network_closed.png reached end of additional filter chain; proceeding with original chain 
2017-05-25 15:20:56,995 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-05-25 15:20:56,995 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-05-25 15:20:56,995 DEBUG ExceptionTranslationFilter Chain processed normally 
2017-05-25 15:20:56,995 DEBUG SecurityContextPersistenceFilter SecurityContextHolder now cleared, as request processing completed 
2017-05-25 15:20:56,995 INFO  Validation Validation error: [
    {
        LUOGO_NASCITA:[
            {
                errorMessage:"Field is required"
            },
            {
                errorMessage:"Field is required"
            }
        ]
    }
] 
2017-05-25 15:20:56,996 DEBUG DSRequest About to free up resources for request of type update on DataSource JAS_ANAG_GIOCATORI_TEST 
2017-05-25 15:20:56,996 DEBUG DSRequest Ignoring freeResources call because this is not a primary request! 
2017-05-25 15:20:56,996 DEBUG DSRequest About to free up resources for request of type update on DataSource JAS_ANAG_GIOCATORI_TEST 
2017-05-25 15:20:56,996 DEBUG DSRequest Ignoring freeResources call because this is not a primary request! 
2017-05-25 15:20:56,996 DEBUG RPCManager Content type for RPC transaction: text/plain; charset=UTF-8 
2017-05-25 15:20:56,996 DEBUG SQLDataSource DataSource 2000 acquired SQLDriver instance 1197150680 during initialization 
2017-05-25 15:20:56,997 DEBUG SQLTransaction Rolling back dbJas transaction "846649119"

[Isomorphic]

What you are seeing here is the validation of two distinct update DSRequests - the one sent from the client (which is handled correctly) and then the one you create and execute from your DMI (which is not handled correctly). The second request is not validating as you expect because you have a bug in your DMI code, specifically in this line:

dsRequestTest.setCriteria("ID_REC", dsRequest.getCriteria());

In case you don't see the problem immediately, this is setting the "ID_REC" property of the new request's criteria to the entire criteria of the original request. A fix would be:

dsRequestTest.setCriteria("ID_REC", dsRequest.getCriteria()[b].get("ID_REC")[/b]);

Regards,
Isomorphic Software Support