ISC: Configuring log4j from: file:/C:/Users/usus/workspace/register/war/WEB-INF/classes/log4j.isc.config.xml
=== 2013-01-30 09:51:22,170 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework - Initializing
=== 2013-01-30 09:51:22,181 [main] INFO  ConfigLoader - Attempting to load framework.properties from CLASSPATH
=== 2013-01-30 09:51:22,332 [main] INFO  ConfigLoader - Successfully loaded framework.properties from CLASSPATH at location: jar:file:/C:/Users/usus/workspace/register/war/WEB-INF/lib/isomorphic_core_rpc.jar!/framework.properties
=== 2013-01-30 09:51:22,332 [main] INFO  ConfigLoader - Attempting to load project.properties from CLASSPATH
=== 2013-01-30 09:51:22,334 [main] INFO  ConfigLoader - Unable to locate project.properties in CLASSPATH
=== 2013-01-30 09:51:22,341 [main] INFO  ConfigLoader - Successfully loaded isc_interfaces.properties from CLASSPATH at location: jar:file:/C:/Users/usus/workspace/register/war/WEB-INF/lib/isomorphic_core_rpc.jar!/isc_interfaces.properties
=== 2013-01-30 09:51:22,341 [main] INFO  ConfigLoader - Attempting to load server.properties from CLASSPATH
=== 2013-01-30 09:51:22,357 [main] INFO  ConfigLoader - Successfully loaded server.properties from CLASSPATH at location: file:/C:/Users/usus/workspace/register/war/WEB-INF/classes/server.properties
=== 2013-01-30 09:51:22,368 [main] INFO  Logger - Logging system started.
=== 2013-01-30 09:51:22,369 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework (v8.3_2012-11-20/EVAL Deployment 2012-11-20) - Initialization Complete
=== 2013-01-30 09:51:22,378 [main] INFO  ISCInit - Auto-detected webRoot - using: C:\Users\usus\workspace\register\war
=== 2013-01-30 09:51:22,384 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Base
=== 2013-01-30 09:51:22,384 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework is already initialized
=== 2013-01-30 09:51:22,575 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
=== 2013-01-30 09:51:22,575 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework is already initialized
=== 2013-01-30 09:51:27,459 [l0-0] INFO  RequestContext - URL: '/Register.html', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:27,475 [l0-0] INFO  Compression - /Register.html: 2400 -> 1009 bytes
=== 2013-01-30 09:51:27,649 [l0-2] INFO  RequestContext - URL: '/Register.css', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:27,652 [l0-2] INFO  Compression - /Register.css: 602 -> 368 bytes
=== 2013-01-30 09:51:27,660 [l0-0] INFO  RequestContext - URL: '/register/register.nocache.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:27,663 [l0-0] INFO  Compression - /register/register.nocache.js: 16054 -> 3917 bytes
=== 2013-01-30 09:51:27,693 [l0-0] INFO  RequestContext - URL: '/register/sc/DataSourceLoader', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:27,730 [l0-0] INFO  PoolManager - SmartClient pooling disabled for 'columnMeta' objects
=== 2013-01-30 09:51:27,776 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\builtinTypes.xml: 8ms
=== 2013-01-30 09:51:27,836 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\columnMeta.ds.xml: 4ms
=== 2013-01-30 09:51:27,842 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\DataSource.ds.xml: 5ms
=== 2013-01-30 09:51:27,925 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\DataSourceField.ds.xml: 7ms
=== 2013-01-30 09:51:27,981 [l0-4] INFO  RequestContext - URL: '/register/sc/modules/ISC_Core.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,016 [l0-0] INFO  SQLDataSource - Deriving dataSource columnMeta from table: Column_meta
=== 2013-01-30 09:51:28,039 [l0-2] INFO  RequestContext - URL: '/register/sc/initsc.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,097 [l0-0] INFO  PoolManager - SmartClient pooling started for 'SQLServer' objects
=== 2013-01-30 09:51:28,104 [l0-0] DEBUG PoolableSQLConnectionFactory - Initializing SQL config for 'SQLServer' from system config - using DriverManager:  com.microsoft.sqlserver.jdbc.SQLServerDriver
=== 2013-01-30 09:51:28,240 [l0-0] DEBUG PoolableSQLConnectionFactory - com.microsoft.sqlserver.jdbc.SQLServerDriver lookup successful
=== 2013-01-30 09:51:28,241 [l0-0] DEBUG PoolableSQLConnectionFactory - DriverManager fetching connection for SQLServer via jdbc url jdbc:sqlserver://192.168.1.156:1433;DatabaseName=AC_new;User=sa;Password=sasa
=== 2013-01-30 09:51:28,269 [l0-0] DEBUG PoolableSQLConnectionFactory - Passing JDBC URL only to getConnection
=== 2013-01-30 09:51:28,256 [l0-3] INFO  RequestContext - URL: '/register/sc/modules/ISC_Containers.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,308 [l0-3] INFO  Compression - /register/sc/modules/ISC_Containers.js: 135750 -> 32244 bytes
=== 2013-01-30 09:51:28,255 [l0-6] INFO  RequestContext - URL: '/register/sc/modules/ISC_Grids.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,247 [l0-5] INFO  RequestContext - URL: '/register/sc/modules/ISC_Foundation.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,245 [l0-2] INFO  Compression - /register/sc/initsc.js: 47 -> 72 bytes
=== 2013-01-30 09:51:28,362 [l0-4] INFO  Compression - /register/sc/modules/ISC_Core.js: 783536 -> 205340 bytes
=== 2013-01-30 09:51:28,379 [l0-5] INFO  Compression - /register/sc/modules/ISC_Foundation.js: 245759 -> 58546 bytes
=== 2013-01-30 09:51:28,412 [l0-2] INFO  RequestContext - URL: '/register/sc/modules/ISC_Calendar.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,421 [l0-2] INFO  Compression - /register/sc/modules/ISC_Calendar.js: 117740 -> 28936 bytes
=== 2013-01-30 09:51:28,460 [l0-6] INFO  Compression - /register/sc/modules/ISC_Grids.js: 854111 -> 214493 bytes
=== 2013-01-30 09:51:28,514 [l0-5] INFO  RequestContext - URL: '/register/sc/modules/ISC_Forms.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,548 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/load_skin.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,556 [l0-2] INFO  RequestContext - URL: '/register/sc/modules/ISC_RichTextEditor.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,560 [l0-2] INFO  Compression - /register/sc/modules/ISC_RichTextEditor.js: 40675 -> 11399 bytes
=== 2013-01-30 09:51:28,616 [l0-5] INFO  Compression - /register/sc/modules/ISC_Forms.js: 692828 -> 168264 bytes
=== 2013-01-30 09:51:28,628 [l0-4] INFO  RequestContext - URL: '/register/sc/modules/ISC_DataBinding.js', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:28,746 [l0-4] INFO  Compression - /register/sc/modules/ISC_DataBinding.js: 631194 -> 155453 bytes
=== 2013-01-30 09:51:28,919 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/load_skin.js
=== 2013-01-30 09:51:28,921 [l0-6] INFO  Compression - /register/sc/skins/Enterprise/load_skin.js: 55511 -> 9523 bytes
=== 2013-01-30 09:51:28,966 [l0-0] DEBUG PoolableSQLConnectionFactory - makeObject() created a pooled Connection '745346830'
=== 2013-01-30 09:51:28,970 [l0-0] DEBUG SQLConnectionManager - Returning borrowed connection '745346830'
=== 2013-01-30 09:51:28,974 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for table: Column_meta
=== 2013-01-30 09:51:28,974 [l0-0] INFO  SQLDSGenerator - =============Using catalog: AC_new
=== 2013-01-30 09:51:29,116 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for Column_meta complete
=== 2013-01-30 09:51:29,124 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:51:29,150 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\biViewObj.ds.xml: 5ms
=== 2013-01-30 09:51:29,168 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\OperationBinding.ds.xml: 5ms
=== 2013-01-30 09:51:29,184 [l0-0] INFO  SQLDataSource - Deriving dataSource biViewObj from table: BI_view_obj
=== 2013-01-30 09:51:29,184 [l0-0] DEBUG SQLConnectionManager - Returning borrowed connection '745346830'
=== 2013-01-30 09:51:29,185 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for table: BI_view_obj
=== 2013-01-30 09:51:29,185 [l0-0] INFO  SQLDSGenerator - =============Using catalog: AC_new
=== 2013-01-30 09:51:29,207 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for BI_view_obj complete
=== 2013-01-30 09:51:29,227 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:51:29,244 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\fillPropertObj.ds.xml: 3ms
=== 2013-01-30 09:51:29,902 [l0-0] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/skin_styles.css', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:29,905 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/skin_styles.css
=== 2013-01-30 09:51:29,912 [l0-0] INFO  Compression - /register/sc/skins/Enterprise/skin_styles.css: 212163 -> 17048 bytes
=== 2013-01-30 09:51:30,088 [l0-0] INFO  RequestContext - URL: '/register/gwt/clean/clean.css', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:30,092 [l0-0] INFO  Compression - /register/gwt/clean/clean.css: 29306 -> 4257 bytes
=== 2013-01-30 09:51:30,141 [l0-0] INFO  RequestContext - URL: '/register/hosted.html', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:30,144 [l0-0] INFO  Compression - /register/hosted.html: 11757 -> 4187 bytes
=== 2013-01-30 09:51:57,565 [l0-0] INFO  RequestContext - URL: '/favicon.ico', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,572 [l0-5] INFO  RequestContext - URL: '/register/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,580 [l0-5] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:57269
=== 2013-01-30 09:51:57,580 [l0-5] DEBUG IDACall - Header Name:Value pair: User-Agent:Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0
=== 2013-01-30 09:51:57,580 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-01-30 09:51:57,590 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-01-30 09:51:57,590 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-01-30 09:51:57,590 [l0-5] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:57269/Register.html?gwt.codesvr=127.0.0.1:57201
=== 2013-01-30 09:51:57,590 [l0-5] DEBUG IDACall - Header Name:Value pair: Cookie:GLog=%7B%0D%20%20%20%20left%3A43%2C%20%0D%20%20%20%20top%3A44%2C%20%0D%20%20%20%20width%3A767%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%2C%20%0D%20%20%20%20trackRPC%3Anull%0D%7D; isc_cState=ready; JSESSIONID=5ksfor1og7bi
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - Header Name:Value pair: Content-Length:1016
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - session exists: null
=== 2013-01-30 09:51:57,595 [l0-5] DEBUG IDACall - remote user: null
=== 2013-01-30 09:51:57,626 [l0-5] DEBUG XML - Parsed XML from (in memory stream): 4ms
=== 2013-01-30 09:51:57,629 [l0-5] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\List.ds.xml: 2ms
=== 2013-01-30 09:51:57,636 [l0-5] DEBUG RPCManager - Processing 1 requests.
=== 2013-01-30 09:51:57,651 [l0-5] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    criteria:{
    },
    operationConfig:{
        dataSource:"columnMeta",
        operationType:"fetch",
        textMatchStyle:"substring"
    },
    startRow:0,
    endRow:75,
    componentId:"isc_ListGrid_0",
    appID:"builtinApplication",
    operation:"columnMeta_fetch",
    oldValues:{
    }
}
=== 2013-01-30 09:51:57,659 [l0-5] INFO  IDACall - Performing 1 operation(s)
=== 2013-01-30 09:51:57,659 [l0-5] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-01-30 09:51:57,659 [l0-5] DEBUG DeclarativeSecurity - DataSource columnMeta is not in the pre-checked list, processing...
=== 2013-01-30 09:51:57,673 [l0-5] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-01-30 09:51:57,673 [l0-5] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No public zero-argument method named '_columnMeta_fetch' found, performing generic datasource operation
=== 2013-01-30 09:51:57,675 [l0-5] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] Performing fetch operation with
	criteria: {}	values: {}
=== 2013-01-30 09:51:57,676 [l0-0] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/blank.gif', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,678 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/blank.gif
=== 2013-01-30 09:51:57,691 [l0-5] INFO  SQLWhereClause - [builtinApplication.columnMeta_fetch] empty condition
=== 2013-01-30 09:51:57,692 [l0-5] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-01-30 09:51:57,695 [l0-4] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/loadingSmall.gif', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,696 [l0-4] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/loadingSmall.gif
=== 2013-01-30 09:51:57,682 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/RecordEditor/filter.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,701 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/RecordEditor/filter.png
=== 2013-01-30 09:51:57,769 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Dialog/say.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,771 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Dialog/say.png
=== 2013-01-30 09:51:57,773 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/headerIcons/close.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:51:57,775 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/headerIcons/close.png
=== 2013-01-30 09:51:58,092 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-01-30 09:51:58,092 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Eval'd row count query: SELECT COUNT(*) FROM dbo.Column_meta WHERE ('1'='1')
=== 2013-01-30 09:51:58,094 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '745346830'
=== 2013-01-30 09:51:58,094 [l0-5] DEBUG SQLDriver - [builtinApplication.columnMeta_fetch] About to execute SQL query in 'SQLServer' using connection '745346830'
=== 2013-01-30 09:51:58,094 [l0-5] INFO  SQLDriver - [builtinApplication.columnMeta_fetch] Executing SQL query on 'SQLServer': SELECT COUNT(*) FROM dbo.Column_meta WHERE ('1'='1')
=== 2013-01-30 09:51:58,103 [l0-5] DEBUG PoolableSQLConnectionFactory - [builtinApplication.columnMeta_fetch] DriverManager fetching connection for SQLServer via jdbc url jdbc:sqlserver://192.168.1.156:1433;DatabaseName=AC_new;User=sa;Password=sasa
=== 2013-01-30 09:51:58,103 [l0-5] DEBUG PoolableSQLConnectionFactory - [builtinApplication.columnMeta_fetch] Passing JDBC URL only to getConnection
=== 2013-01-30 09:51:58,125 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed UNPOOLED connection '227281767'
=== 2013-01-30 09:51:58,125 [l0-5] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] SQL Server version is '10.50.1600'
=== 2013-01-30 09:51:58,125 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using SQL Limit query
=== 2013-01-30 09:51:58,126 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using PK as default sorter: id
=== 2013-01-30 09:51:58,126 [l0-5] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] Using PK as default sorter: com.isomorphic.sql.SQLOrderClause@754e3fc3
=== 2013-01-30 09:51:58,127 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] SQL windowed select rows 0->75, result size 75. Query: SELECT * FROM (SELECT *, ROW_NUMBER() OVER (ORDER BY x.id) AS rowID FROM (SELECT TOP 100 PERCENT  Column_meta.IgnoreData, Column_meta.IsRegistr, Column_meta.Name, Column_meta.TP, Column_meta.Typ_id, Column_meta.fullnamekz, Column_meta.fullnamer, Column_meta.id, Column_meta.namekz, Column_meta.namer FROM dbo.Column_meta WHERE ('1'='1')) x) y WHERE y.rowID BETWEEN 1 AND 75
=== 2013-01-30 09:51:58,127 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '745346830'
=== 2013-01-30 09:51:58,154 [l0-5] INFO  DSResponse - [builtinApplication.columnMeta_fetch] DSResponse: List with 75 items
=== 2013-01-30 09:51:58,155 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:51:58,155 [l0-5] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:51:58,155 [l0-5] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-01-30 09:51:58,160 [l0-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-01-30 09:51:58,180 [l0-5] INFO  Compression - /register/sc/IDACall: 26469 -> 5245 bytes
=== 2013-01-30 09:52:01,071 [l0-4] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_track.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:01,073 [l0-4] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_track.png
=== 2013-01-30 09:52:01,071 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_end.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:01,078 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_end.png
=== 2013-01-30 09:52:01,123 [l0-5] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_start.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:01,149 [l0-0] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vthumb_grip.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:01,150 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vthumb_grip.png
=== 2013-01-30 09:52:01,210 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_start.png
=== 2013-01-30 09:52:03,810 [l0-5] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/ListGrid/sort_descending.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:03,814 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/ListGrid/sort_descending.png
=== 2013-01-30 09:52:08,844 [l0-5] INFO  RequestContext - URL: '/register/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:08,844 [l0-5] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:57269
=== 2013-01-30 09:52:08,844 [l0-5] DEBUG IDACall - Header Name:Value pair: User-Agent:Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0
=== 2013-01-30 09:52:08,844 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-01-30 09:52:08,844 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:57269/Register.html?gwt.codesvr=127.0.0.1:57201
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Cookie:GLog=%7B%0D%20%20%20%20left%3A43%2C%20%0D%20%20%20%20top%3A44%2C%20%0D%20%20%20%20width%3A767%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%2C%20%0D%20%20%20%20trackRPC%3Anull%0D%7D; isc_cState=ready; JSESSIONID=f0gmcckv1coq
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Content-Length:1070
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - session exists: f0gmcckv1coq
=== 2013-01-30 09:52:08,845 [l0-5] DEBUG IDACall - remote user: null
=== 2013-01-30 09:52:08,849 [l0-5] DEBUG XML - Parsed XML from (in memory stream): 2ms
=== 2013-01-30 09:52:08,851 [l0-5] DEBUG RPCManager - Processing 1 requests.
=== 2013-01-30 09:52:08,854 [l0-5] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    criteria:{
        Name:"QSHI"
    },
    operationConfig:{
        dataSource:"columnMeta",
        operationType:"fetch",
        textMatchStyle:"substring"
    },
    startRow:0,
    endRow:75,
    componentId:"isc_ListGrid_0",
    appID:"builtinApplication",
    operation:"columnMeta_fetch",
    oldValues:{
        Name:"QSHI"
    }
}
=== 2013-01-30 09:52:08,854 [l0-5] INFO  IDACall - Performing 1 operation(s)
=== 2013-01-30 09:52:08,856 [l0-5] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-01-30 09:52:08,857 [l0-5] DEBUG DeclarativeSecurity - DataSource columnMeta is not in the pre-checked list, processing...
=== 2013-01-30 09:52:08,857 [l0-5] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-01-30 09:52:08,857 [l0-5] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No public zero-argument method named '_columnMeta_fetch' found, performing generic datasource operation
=== 2013-01-30 09:52:08,857 [l0-5] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] Performing fetch operation with
	criteria: {Name:"QSHI"}	values: {Name:"QSHI"}
=== 2013-01-30 09:52:08,885 [l0-5] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-01-30 09:52:08,885 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-01-30 09:52:08,886 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Eval'd row count query: SELECT COUNT(*) FROM dbo.Column_meta WHERE (LOWER(Column_meta.Name) LIKE '%qshi%' {ESCAPE '\'})
=== 2013-01-30 09:52:08,886 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '745346830'
=== 2013-01-30 09:52:08,886 [l0-5] DEBUG SQLDriver - [builtinApplication.columnMeta_fetch] About to execute SQL query in 'SQLServer' using connection '745346830'
=== 2013-01-30 09:52:08,886 [l0-5] INFO  SQLDriver - [builtinApplication.columnMeta_fetch] Executing SQL query on 'SQLServer': SELECT COUNT(*) FROM dbo.Column_meta WHERE (LOWER(Column_meta.Name) LIKE '%qshi%' {ESCAPE '\'})
=== 2013-01-30 09:52:08,896 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using SQL Limit query
=== 2013-01-30 09:52:08,896 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using PK as default sorter: id
=== 2013-01-30 09:52:08,896 [l0-5] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] Using PK as default sorter: com.isomorphic.sql.SQLOrderClause@19e089f0
=== 2013-01-30 09:52:08,896 [l0-5] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] SQL windowed select rows 0->75, result size 75. Query: SELECT * FROM (SELECT *, ROW_NUMBER() OVER (ORDER BY x.id) AS rowID FROM (SELECT TOP 100 PERCENT  Column_meta.IgnoreData, Column_meta.IsRegistr, Column_meta.Name, Column_meta.TP, Column_meta.Typ_id, Column_meta.fullnamekz, Column_meta.fullnamer, Column_meta.id, Column_meta.namekz, Column_meta.namer FROM dbo.Column_meta WHERE (LOWER(Column_meta.Name) LIKE '%qshi%' {ESCAPE '\'})) x) y WHERE y.rowID BETWEEN 1 AND 75
=== 2013-01-30 09:52:08,905 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '745346830'
=== 2013-01-30 09:52:08,908 [l0-0] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_track.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:08,910 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_track.png
=== 2013-01-30 09:52:08,921 [l0-5] INFO  DSResponse - [builtinApplication.columnMeta_fetch] DSResponse: List with 1 items
=== 2013-01-30 09:52:08,934 [l0-5] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:52:08,934 [l0-5] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "745346830"
=== 2013-01-30 09:52:08,934 [l0-5] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-01-30 09:52:08,940 [l0-5] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-01-30 09:52:08,928 [l0-6] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_end.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:08,942 [l0-5] INFO  Compression - /register/sc/IDACall: 351 -> 267 bytes
=== 2013-01-30 09:52:08,943 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_end.png
=== 2013-01-30 09:52:08,931 [l0-0] INFO  RequestContext - URL: '/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_start.png', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 09:52:08,946 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_start.png
=== 2013-01-30 10:31:28,823 [l0-6] INFO  RequestContext - URL: '/register/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0': Moz (Gecko) with Accept-Encoding header
=== 2013-01-30 10:31:28,824 [l0-6] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:57269
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: User-Agent:Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/20100101 Firefox/18.0
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:57269/Register.html?gwt.codesvr=127.0.0.1:57201
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Content-Length:947
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Cookie:GLog=%7B%0D%20%20%20%20left%3A43%2C%20%0D%20%20%20%20top%3A44%2C%20%0D%20%20%20%20width%3A767%2C%20%0D%20%20%20%20height%3A480%2C%20%0D%20%20%20%20priorityDefaults%3A%7B%0D%20%20%20%20%20%20%20%20Log%3A4%0D%20%20%20%20%7D%2C%20%0D%20%20%20%20defaultPriority%3A3%2C%20%0D%20%20%20%20trackRPC%3Anull%0D%7D; isc_cState=ready; JSESSIONID=f0gmcckv1coq
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - session exists: null
=== 2013-01-30 10:31:28,825 [l0-6] DEBUG IDACall - remote user: null
=== 2013-01-30 10:31:28,831 [l0-6] DEBUG XML - Parsed XML from (in memory stream): 4ms
=== 2013-01-30 10:31:28,839 [l0-6] DEBUG RPCManager - Processing 1 requests.
=== 2013-01-30 10:31:38,670 [l0-6] DEBUG RPCManager - Processing 1 requests.