=== 2013-10-28 12:27:48,717 [sor2] DEBUG RPCDMI - rpc returned data
=== 2013-10-28 12:27:48,717 [sor2] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-10-28 12:27:48,717 [sor2] INFO  Compression - /isomorphic/IDACall: 1732 -> 433 bytes
=== 2013-10-28 12:28:17,601 [sor2] INFO  RequestContext - URL: '/isomorphic/IDACall', User-Agent: 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0': Moz (Gecko) with Accept-Encoding header
=== 2013-10-28 12:28:17,624 [sor2] INFO  Compression - /isomorphic/IDACall: 114099 -> 8333 bytes
=== 2013-10-28 12:28:44,757 [sor2] INFO  Download - Returning 304: Not modified on conditional get of: /home/kk/Downloads/WSO2/projects/SmartClient_v90p_2013-09-12/smartclientSDK/isomorphic/skins/Graphite/images/actions/remove.png
=== 2013-10-28 12:29:10,333 [sor2] INFO  RequestContext - URL: '/isomorphic/IDACall', User-Agent: 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0': Moz (Gecko) with Accept-Encoding header
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: host:localhost:8080
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: accept-language:en-US,en;q=0.5
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip, deflate
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/tools/visualBuilder/workspace/masterdetail.html
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: content-length:2376
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: cookie:GLog=%7B%0D%20%20%20%20left%3A432%2C%20%0D%20%20%20%20top%3A74%2C%20%0D%20%20%20%20width%3A640%2C%20%0D%20%20%20%20height%3A602%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%3A4%2C%20%0D%20%20%20%20trackRPC%3Atrue%0D%7D; menuPanel=visible; menuPanelType=main; PPA_ID=8ea6pojmfpeoqqtd6ddthg7u66; webfx-tree-cookie-persistence=wfxt-38+wfxt-36+wfxt-32+wfxt-6+wfxt-4+wfxt-10; isc_cState=ready; JSESSIONID=B33AF348C4177C286CAB5D982B290C59; Modernizr=; current-breadcrumb=manage_menu%2Cwebapps_menu%2Cwebapps_list_menu%23webapp-list+index.jsp*; MSG13827002454030.9759742186908851=true; MSG13827002911080.27745977358052354=true; MSG13827004999240.7742731177782382=true
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: connection:keep-alive
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: pragma:no-cache
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - Header Name:Value pair: cache-control:no-cache
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - session exists: B33AF348C4177C286CAB5D982B290C59
=== 2013-10-28 12:29:10,333 [sor2] DEBUG IDACall - remote user: null
=== 2013-10-28 12:29:10,335 [sor2] DEBUG XML - Parsed XML from (in memory stream): 1ms
=== 2013-10-28 12:29:10,335 [sor2] DEBUG RPCManager - Processing 3 requests.
=== 2013-10-28 12:29:10,336 [sor2] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    values:{
        custname:"o3"
    },
    operationConfig:{
        dataSource:"smaster",
        operationType:"add"
    },
    componentId:"DynamicForm0",
    appID:"builtinApplication",
    operation:"ref:smaster_add",
    oldValues:{
    },
    criteria:{
    }
}
=== 2013-10-28 12:29:10,336 [sor2] DEBUG RPCManager - Request #2 (DSRequest) payload: {
    values:{
        item:"it1",
        qty:1,
        rate:11
    },
    operationConfig:{
        dataSource:"sdetail",
        operationType:"add"
    },
    componentId:"ListGrid0",
    appID:"builtinApplication",
    operation:"sdetail_add",
    oldValues:{
        item:"it1",
        qty:1,
        rate:11
    },
    criteria:{
    }
}
=== 2013-10-28 12:29:10,336 [sor2] DEBUG RPCManager - Request #3 (DSRequest) payload: {
    values:{
        item:"it2",
        qty:2,
        rate:12
    },
    operationConfig:{
        dataSource:"sdetail",
        operationType:"add"
    },
    componentId:"ListGrid0",
    appID:"builtinApplication",
    operation:"sdetail_add",
    oldValues:{
        item:"it2",
        qty:2,
        rate:12
    },
    criteria:{
    }
}
=== 2013-10-28 12:29:10,336 [sor2] INFO  IDACall - Performing 3 operation(s)
=== 2013-10-28 12:29:10,336 [sor2] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,336 [sor2] DEBUG DeclarativeSecurity - DataSource smaster is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,336 [sor2] WARN  DataSourceDMI - DataSource smaster: received a request to execute an operation of type 'add' named 'ref:smaster_add', but this operation is not defined to the dataSource.  Falling back to default behavior for operationType 'add'
=== 2013-10-28 12:29:10,336 [sor2] DEBUG AppBase - [builtinApplication.ref:smaster_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,336 [sor2] DEBUG AppBase - [builtinApplication.ref:smaster_add] No public zero-argument method named '_ref:smaster_add' found, performing generic datasource operation
=== 2013-10-28 12:29:10,337 [sor2] INFO  SQLDataSource - [builtinApplication.ref:smaster_add] Performing add operation with
	criteria: {custname:"o3"}	values: {custname:"o3"}
=== 2013-10-28 12:29:10,337 [sor2] DEBUG SQLValuesClause - [builtinApplication.ref:smaster_add] Sequences: {}
=== 2013-10-28 12:29:10,337 [sor2] DEBUG SQLConnectionManager - [builtinApplication.ref:smaster_add] Borrowed connection '1378126555'
=== 2013-10-28 12:29:10,337 [sor2] DEBUG SQLTransaction - [builtinApplication.ref:smaster_add] Started new USCProduction-localhost transaction "1378126555"
=== 2013-10-28 12:29:10,337 [sor2] DEBUG SQLDriver - [builtinApplication.ref:smaster_add] About to execute SQL update in 'USCProduction-localhost' using connection'1378126555'
=== 2013-10-28 12:29:10,337 [sor2] INFO  SQLDriver - [builtinApplication.ref:smaster_add] Executing SQL update on 'USCProduction-localhost': INSERT INTO public.smaster (custname) VALUES ('o3')
=== 2013-10-28 12:29:10,338 [sor2] DEBUG SQLDataSource - [builtinApplication.ref:smaster_add] add operation affected 1 rows
=== 2013-10-28 12:29:10,339 [sor2] INFO  SQLDataSource - [builtinApplication.ref:smaster_add] primaryKeys: {}
=== 2013-10-28 12:29:10,339 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.ref:smaster_add] Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,339 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.ref:smaster_add] DataSource smaster is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,339 [sor2] DEBUG AppBase - [builtinApplication.ref:smaster_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,339 [sor2] DEBUG AppBase - [builtinApplication.ref:smaster_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-10-28 12:29:10,340 [sor2] INFO  SQLDataSource - [builtinApplication.ref:smaster_add, builtinApplication.null] Performing fetch operation with
	criteria: {}	values: {}
=== 2013-10-28 12:29:10,340 [sor2] INFO  SQLWhereClause - [builtinApplication.ref:smaster_add, builtinApplication.null] empty condition
=== 2013-10-28 12:29:10,340 [sor2] INFO  SQLDataSource - [builtinApplication.ref:smaster_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-10-28 12:29:10,340 [sor2] INFO  SQLDataSource - [builtinApplication.ref:smaster_add, builtinApplication.null] 676: Executing SQL query on 'USCProduction-localhost': SELECT smaster.custname, smaster.orderid FROM public.smaster WHERE ('1'='1')
=== 2013-10-28 12:29:10,340 [sor2] DEBUG SQLDriver - [builtinApplication.ref:smaster_add, builtinApplication.null] About to execute SQL query in 'USCProduction-localhost' using connection '1378126555'
=== 2013-10-28 12:29:10,341 [sor2] INFO  SQLDriver - [builtinApplication.ref:smaster_add, builtinApplication.null] Executing SQL query on 'USCProduction-localhost': SELECT smaster.custname, smaster.orderid FROM public.smaster WHERE ('1'='1')
=== 2013-10-28 12:29:10,343 [sor2] INFO  DSResponse - [builtinApplication.ref:smaster_add, builtinApplication.null] DSResponse: List with 3 items
=== 2013-10-28 12:29:10,343 [sor2] INFO  DSResponse - [builtinApplication.ref:smaster_add] DSResponse: List with 3 items
=== 2013-10-28 12:29:10,343 [sor2] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,343 [sor2] DEBUG DeclarativeSecurity - DataSource sdetail is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,345 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,345 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add] No public zero-argument method named '_sdetail_add' found, performing generic datasource operation
=== 2013-10-28 12:29:10,346 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add] Performing add operation with
	criteria: {item:"it1",qty:1,rate:11,orderid:850698800793060}	values: {item:"it1",qty:1,rate:11.0,orderid:850698800793060}
=== 2013-10-28 12:29:10,346 [sor2] DEBUG SQLValuesClause - [builtinApplication.sdetail_add] Sequences: {}
=== 2013-10-28 12:29:10,347 [sor2] DEBUG SQLDriver - [builtinApplication.sdetail_add] About to execute SQL update in 'USCProduction-localhost' using connection'1378126555'
=== 2013-10-28 12:29:10,347 [sor2] INFO  SQLDriver - [builtinApplication.sdetail_add] Executing SQL update on 'USCProduction-localhost': INSERT INTO public.sdetail (item, orderid, qty, rate) VALUES ('it1', 850698800793060, 1, 11.0)
=== 2013-10-28 12:29:10,348 [sor2] DEBUG SQLDataSource - [builtinApplication.sdetail_add] add operation affected 1 rows
=== 2013-10-28 12:29:10,348 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add] primaryKeys: {}
=== 2013-10-28 12:29:10,348 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.sdetail_add] Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,348 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.sdetail_add] DataSource sdetail is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,348 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,348 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-10-28 12:29:10,348 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] Performing fetch operation with
	criteria: {}	values: {}
=== 2013-10-28 12:29:10,348 [sor2] INFO  SQLWhereClause - [builtinApplication.sdetail_add, builtinApplication.null] empty condition
=== 2013-10-28 12:29:10,349 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-10-28 12:29:10,349 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] 675: Executing SQL query on 'USCProduction-localhost': SELECT sdetail.item, sdetail.orderdetailid, sdetail.orderid, sdetail.qty, sdetail.rate FROM public.sdetail WHERE ('1'='1')
=== 2013-10-28 12:29:10,349 [sor2] DEBUG SQLDriver - [builtinApplication.sdetail_add, builtinApplication.null] About to execute SQL query in 'USCProduction-localhost' using connection '1378126555'
=== 2013-10-28 12:29:10,349 [sor2] INFO  SQLDriver - [builtinApplication.sdetail_add, builtinApplication.null] Executing SQL query on 'USCProduction-localhost': SELECT sdetail.item, sdetail.orderdetailid, sdetail.orderid, sdetail.qty, sdetail.rate FROM public.sdetail WHERE ('1'='1')
=== 2013-10-28 12:29:10,350 [sor2] INFO  DSResponse - [builtinApplication.sdetail_add, builtinApplication.null] DSResponse: List with 5 items
=== 2013-10-28 12:29:10,350 [sor2] INFO  DSResponse - [builtinApplication.sdetail_add] DSResponse: List with 5 items
=== 2013-10-28 12:29:10,350 [sor2] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,350 [sor2] DEBUG DeclarativeSecurity - DataSource sdetail is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,351 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,351 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add] No public zero-argument method named '_sdetail_add' found, performing generic datasource operation
=== 2013-10-28 12:29:10,352 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add] Performing add operation with
	criteria: {item:"it2",qty:2,rate:12,orderid:850698800793060}	values: {item:"it2",qty:2,rate:12.0,orderid:850698800793060}
=== 2013-10-28 12:29:10,352 [sor2] DEBUG SQLValuesClause - [builtinApplication.sdetail_add] Sequences: {}
=== 2013-10-28 12:29:10,353 [sor2] DEBUG SQLDriver - [builtinApplication.sdetail_add] About to execute SQL update in 'USCProduction-localhost' using connection'1378126555'
=== 2013-10-28 12:29:10,353 [sor2] INFO  SQLDriver - [builtinApplication.sdetail_add] Executing SQL update on 'USCProduction-localhost': INSERT INTO public.sdetail (item, orderid, qty, rate) VALUES ('it2', 850698800793060, 2, 12.0)
=== 2013-10-28 12:29:10,353 [sor2] DEBUG SQLDataSource - [builtinApplication.sdetail_add] add operation affected 1 rows
=== 2013-10-28 12:29:10,353 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add] primaryKeys: {}
=== 2013-10-28 12:29:10,354 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.sdetail_add] Processing security checks for DataSource null, field null
=== 2013-10-28 12:29:10,354 [sor2] DEBUG DeclarativeSecurity - [builtinApplication.sdetail_add] DataSource sdetail is not in the pre-checked list, processing...
=== 2013-10-28 12:29:10,354 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add, builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-10-28 12:29:10,354 [sor2] DEBUG AppBase - [builtinApplication.sdetail_add, builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2013-10-28 12:29:10,354 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] Performing fetch operation with
	criteria: {}	values: {}
=== 2013-10-28 12:29:10,354 [sor2] INFO  SQLWhereClause - [builtinApplication.sdetail_add, builtinApplication.null] empty condition
=== 2013-10-28 12:29:10,355 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-10-28 12:29:10,355 [sor2] INFO  SQLDataSource - [builtinApplication.sdetail_add, builtinApplication.null] 675: Executing SQL query on 'USCProduction-localhost': SELECT sdetail.item, sdetail.orderdetailid, sdetail.orderid, sdetail.qty, sdetail.rate FROM public.sdetail WHERE ('1'='1')
=== 2013-10-28 12:29:10,355 [sor2] DEBUG SQLDriver - [builtinApplication.sdetail_add, builtinApplication.null] About to execute SQL query in 'USCProduction-localhost' using connection '1378126555'
=== 2013-10-28 12:29:10,355 [sor2] INFO  SQLDriver - [builtinApplication.sdetail_add, builtinApplication.null] Executing SQL query on 'USCProduction-localhost': SELECT sdetail.item, sdetail.orderdetailid, sdetail.orderid, sdetail.qty, sdetail.rate FROM public.sdetail WHERE ('1'='1')
=== 2013-10-28 12:29:10,357 [sor2] INFO  DSResponse - [builtinApplication.sdetail_add, builtinApplication.null] DSResponse: List with 6 items
=== 2013-10-28 12:29:10,357 [sor2] INFO  DSResponse - [builtinApplication.sdetail_add] DSResponse: List with 6 items
=== 2013-10-28 12:29:10,357 [sor2] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-10-28 12:29:10,357 [sor2] DEBUG SQLTransaction - Committing USCProduction-localhost transaction "1378126555"
=== 2013-10-28 12:29:10,377 [sor2] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-10-28 12:29:10,377 [sor2] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-10-28 12:29:10,377 [sor2] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-10-28 12:29:10,378 [sor2] DEBUG SQLTransaction - Returning transactional connection for USCProduction-localhost with hashcode "1378126555"
=== 2013-10-28 12:29:10,378 [sor2] DEBUG SQLTransaction - Ending USCProduction-localhost transaction "1378126555"
=== 2013-10-28 12:29:10,378 [sor2] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "1378126555"
=== 2013-10-28 12:29:10,378 [sor2] DEBUG SQLTransaction - Returning transactional connection for USCProduction-localhost (connection is null)
=== 2013-10-28 12:29:10,378 [sor2] DEBUG SQLTransaction - Returning transactional connection for USCProduction-localhost (connection is null)
=== 2013-10-28 12:29:10,379 [sor2] INFO  Compression - /isomorphic/IDACall: 1347 -> 307 bytes
=== 2013-10-28 12:29:10,609 [sor2] INFO  RequestContext - URL: '/isomorphic/system/reference/skin/images/opener_opened.png', User-Agent: 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0': Moz (Gecko) with Accept-Encoding header
=== 2013-10-28 12:29:10,610 [sor2] INFO  Download - File /home/kk/Downloads/WSO2/projects/SmartClient_v90p_2013-09-12/smartclientSDK/isomorphic/system/reference/skin/images/opener_opened.png not found, sending 404
=== 2013-10-28 12:29:43,827 [sor2] INFO  RequestContext - URL: '/isomorphic/IDACall', User-Agent: 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0': Moz (Gecko) with Accept-Encoding header
=== 2013-10-28 12:29:43,835 [sor2] INFO  Compression - /isomorphic/IDACall: 81 -> 86 bytes
=== 2013-10-28 12:29:43,926 [sor2] INFO  RequestContext - URL: '/isomorphic/IDACall', User-Agent: 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0': Moz (Gecko) with Accept-Encoding header