ISC: Configuring log4j from: file:/C:/Users/usus/workspace/register/war/WEB-INF/classes/log4j.isc.config.xml
=== 2013-02-05 14:38:43,612 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework - Initializing
=== 2013-02-05 14:38:43,619 [main] INFO  ConfigLoader - Attempting to load framework.properties from CLASSPATH
=== 2013-02-05 14:38:43,840 [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-02-05 14:38:43,840 [main] INFO  ConfigLoader - Attempting to load project.properties from CLASSPATH
=== 2013-02-05 14:38:43,859 [main] INFO  ConfigLoader - Unable to locate project.properties in CLASSPATH
=== 2013-02-05 14:38:43,863 [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-02-05 14:38:43,864 [main] INFO  ConfigLoader - Attempting to load server.properties from CLASSPATH
=== 2013-02-05 14:38:43,866 [main] INFO  ConfigLoader - Successfully loaded server.properties from CLASSPATH at location: file:/C:/Users/usus/workspace/register/war/WEB-INF/classes/server.properties
=== 2013-02-05 14:38:43,876 [main] INFO  Logger - Logging system started.
=== 2013-02-05 14:38:43,877 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework (v8.3p_2012-12-20/PowerEdition Deployment 2012-12-20) - Initialization Complete
=== 2013-02-05 14:38:43,884 [main] INFO  ISCInit - Auto-detected webRoot - using: C:\Users\usus\workspace\register\war
=== 2013-02-05 14:38:43,890 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Base
=== 2013-02-05 14:38:43,890 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework is already initialized
[WARN] Server class 'com.google.api.server.spi.SystemServiceServlet' could not be found in the web app, but was found on the system classpath
   [WARN] Adding classpath entry 'file:/D:/eclipse/plugins/com.google.appengine.eclipse.sdkbundle_1.7.2.1/appengine-java-sdk-1.7.2.1/lib/opt/user/appengine-endpoints/v1/appengine-endpoints.jar' to the web app classpath for this session
   For additional info see: file:/D:/eclipse/plugins/com.google.gwt.eclipse.sdkbundle_2.4.0.v201208080121-rel-r42/gwt-2.4.0/doc/helpInfo/webAppClassPath.html
log4j:WARN No appenders could be found for logger (org.apache.jasper.compiler.JspRuntimeContext).
log4j:WARN Please initialize the log4j system properly.
=== 2013-02-05 14:38:44,145 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework initialization called from com.isomorphic.base.Init
=== 2013-02-05 14:38:44,145 [main] INFO  ISCInit - Isomorphic SmartClient/SmartGWT Framework is already initialized
=== 2013-02-05 14:55:28,748 [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-02-05 14:55:28,768 [l0-0] INFO  Compression - /Register.html: 2400 -> 1009 bytes
=== 2013-02-05 14:55:28,885 [l0-0] 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-02-05 14:55:28,888 [l0-0] INFO  Compression - /Register.css: 602 -> 368 bytes
=== 2013-02-05 14:55:28,890 [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-02-05 14:55:28,894 [l0-0] INFO  Compression - /register/register.nocache.js: 7403 -> 2742 bytes
=== 2013-02-05 14:55:28,905 [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-02-05 14:55:28,970 [l0-0] INFO  PoolManager - SmartClient pooling disabled for 'columnMeta' objects
=== 2013-02-05 14:55:29,023 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\builtinTypes.xml: 9ms
=== 2013-02-05 14:55:29,156 [l0-3] 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-02-05 14:55:29,164 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\columnMeta.ds.xml: 3ms
=== 2013-02-05 14:55:29,171 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\DataSource.ds.xml: 6ms
=== 2013-02-05 14:55:29,187 [l0-4] 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-02-05 14:55:29,222 [l0-4] INFO  Compression - /register/sc/modules/ISC_Containers.js: 135398 -> 32185 bytes
=== 2013-02-05 14:55:29,225 [l0-3] INFO  Compression - /register/sc/modules/ISC_Foundation.js: 245507 -> 58307 bytes
=== 2013-02-05 14:55:29,247 [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-02-05 14:55:29,280 [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-02-05 14:55:29,303 [l0-6] INFO  Compression - /register/sc/modules/ISC_Grids.js: 855449 -> 214910 bytes
=== 2013-02-05 14:55:29,315 [l0-5] 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-02-05 14:55:29,331 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\DataSourceField.ds.xml: 51ms
=== 2013-02-05 14:55:29,374 [l0-2] INFO  Compression - /register/sc/initsc.js: 47 -> 72 bytes
=== 2013-02-05 14:55:29,409 [l0-0] INFO  SQLDataSource - Deriving dataSource columnMeta from table: Column_meta
=== 2013-02-05 14:55:29,441 [l0-3] 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-02-05 14:55:29,570 [l0-5] INFO  Compression - /register/sc/modules/ISC_Core.js: 784650 -> 205541 bytes
=== 2013-02-05 14:55:29,600 [l0-3] INFO  Compression - /register/sc/modules/ISC_Forms.js: 697515 -> 169415 bytes
=== 2013-02-05 14:55:29,646 [l0-0] INFO  PoolManager - SmartClient pooling started for 'SQLServer' objects
=== 2013-02-05 14:55:29,653 [l0-0] DEBUG PoolableSQLConnectionFactory - Initializing SQL config for 'SQLServer' from system config - using DriverManager:  com.microsoft.sqlserver.jdbc.SQLServerDriver
=== 2013-02-05 14:55:29,708 [l0-0] DEBUG PoolableSQLConnectionFactory - com.microsoft.sqlserver.jdbc.SQLServerDriver lookup successful
=== 2013-02-05 14:55:29,708 [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-02-05 14:55:29,708 [l0-0] DEBUG PoolableSQLConnectionFactory - Passing JDBC URL only to getConnection
=== 2013-02-05 14:55:29,790 [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-02-05 14:55:29,810 [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-02-05 14:55:29,822 [l0-4] 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-02-05 14:55:29,826 [l0-2] INFO  Compression - /register/sc/modules/ISC_RichTextEditor.js: 40327 -> 11327 bytes
=== 2013-02-05 14:55:29,829 [l0-5] 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-02-05 14:55:29,848 [l0-4] INFO  Compression - /register/sc/modules/ISC_Calendar.js: 117392 -> 28872 bytes
=== 2013-02-05 14:55:29,881 [l0-5] INFO  Compression - /register/sc/modules/ISC_DataBinding.js: 630178 -> 155350 bytes
=== 2013-02-05 14:55:29,871 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/load_skin.js
=== 2013-02-05 14:55:29,886 [l0-6] INFO  Compression - /register/sc/skins/Enterprise/load_skin.js: 55685 -> 9553 bytes
=== 2013-02-05 14:55:30,405 [l0-0] DEBUG PoolableSQLConnectionFactory - makeObject() created a pooled Connection '1253480289'
=== 2013-02-05 14:55:30,410 [l0-0] DEBUG SQLConnectionManager - Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:30,413 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for table: Column_meta
=== 2013-02-05 14:55:30,413 [l0-0] INFO  SQLDSGenerator - =============Using catalog: AC_new
=== 2013-02-05 14:55:30,541 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for Column_meta complete
=== 2013-02-05 14:55:30,549 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:30,574 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\biViewObj.ds.xml: 4ms
=== 2013-02-05 14:55:30,589 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\OperationBinding.ds.xml: 4ms
=== 2013-02-05 14:55:30,700 [l0-0] INFO  SQLDataSource - Deriving dataSource biViewObj from table: BI_view_obj
=== 2013-02-05 14:55:30,700 [l0-0] DEBUG SQLConnectionManager - Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:30,701 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for table: BI_view_obj
=== 2013-02-05 14:55:30,701 [l0-0] INFO  SQLDSGenerator - =============Using catalog: AC_new
=== 2013-02-05 14:55:30,716 [l0-0] INFO  SQLDSGenerator - Fetching column metadata for BI_view_obj complete
=== 2013-02-05 14:55:30,720 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:30,735 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\ds\fillPropertObj.ds.xml: 2ms
=== 2013-02-05 14:55:31,316 [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-02-05 14:55:31,320 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/skin_styles.css
=== 2013-02-05 14:55:31,326 [l0-0] INFO  Compression - /register/sc/skins/Enterprise/skin_styles.css: 212529 -> 17070 bytes
=== 2013-02-05 14:55:31,505 [l0-5] 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-02-05 14:55:31,511 [l0-5] INFO  Compression - /register/gwt/clean/clean.css: 29306 -> 4257 bytes
=== 2013-02-05 14:55:31,529 [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-02-05 14:55:31,541 [l0-0] INFO  Compression - /register/hosted.html: 11757 -> 4187 bytes
=== 2013-02-05 14:55:47,120 [l0-5] 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-02-05 14:55:47,122 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/RecordEditor/filter.png
=== 2013-02-05 14:55:47,125 [l0-5] 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-02-05 14:55:47,129 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/loadingSmall.gif
=== 2013-02-05 14:55:47,132 [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-02-05 14:55:47,134 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/blank.gif
=== 2013-02-05 14:55:47,681 [l0-0] 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-02-05 14:55:47,691 [l0-0] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:52940
=== 2013-02-05 14:55:47,691 [l0-0] 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-02-05 14:55:47,691 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-02-05 14:55:47,691 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-02-05 14:55:47,691 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-02-05 14:55:47,691 [l0-0] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:52940/Register.html?gwt.codesvr=127.0.0.1:52936
=== 2013-02-05 14:55:47,692 [l0-0] 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=qicrglti974k
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Length:1016
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - session exists: null
=== 2013-02-05 14:55:47,692 [l0-0] DEBUG IDACall - remote user: null
=== 2013-02-05 14:55:47,710 [l0-0] DEBUG XML - Parsed XML from (in memory stream): 2ms
=== 2013-02-05 14:55:47,713 [l0-0] DEBUG XML - Parsed XML from C:\Users\usus\workspace\register\war\register\sc\system\schema\List.ds.xml: 1ms
=== 2013-02-05 14:55:47,717 [l0-0] DEBUG RPCManager - Processing 1 requests.
=== 2013-02-05 14:55:47,735 [l0-0] 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-02-05 14:55:47,739 [l0-0] INFO  IDACall - Performing 1 operation(s)
=== 2013-02-05 14:55:47,739 [l0-0] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-02-05 14:55:47,740 [l0-0] DEBUG DeclarativeSecurity - DataSource columnMeta is not in the pre-checked list, processing...
=== 2013-02-05 14:55:47,749 [l0-0] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-02-05 14:55:47,749 [l0-0] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No public zero-argument method named '_columnMeta_fetch' found, performing generic datasource operation
=== 2013-02-05 14:55:47,760 [l0-0] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] Performing fetch operation with
	criteria: {}	values: {}
=== 2013-02-05 14:55:47,785 [l0-0] INFO  SQLWhereClause - [builtinApplication.columnMeta_fetch] empty condition
=== 2013-02-05 14:55:47,787 [l0-0] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-02-05 14:55:47,865 [l0-5] 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-02-05 14:55:47,941 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-02-05 14:55:47,942 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Eval'd row count query: SELECT COUNT(*) FROM dbo.Column_meta WHERE ('1'='1')
=== 2013-02-05 14:55:47,942 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:47,943 [l0-0] DEBUG SQLDriver - [builtinApplication.columnMeta_fetch] About to execute SQL query in 'SQLServer' using connection '1253480289'
=== 2013-02-05 14:55:47,943 [l0-0] INFO  SQLDriver - [builtinApplication.columnMeta_fetch] Executing SQL query on 'SQLServer': SELECT COUNT(*) FROM dbo.Column_meta WHERE ('1'='1')
=== 2013-02-05 14:55:47,952 [l0-0] 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-02-05 14:55:47,952 [l0-0] DEBUG PoolableSQLConnectionFactory - [builtinApplication.columnMeta_fetch] Passing JDBC URL only to getConnection
=== 2013-02-05 14:55:47,974 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed UNPOOLED connection '1142913471'
=== 2013-02-05 14:55:47,974 [l0-0] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] SQL Server version is '10.50.1600'
=== 2013-02-05 14:55:47,974 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using SQL Limit query
=== 2013-02-05 14:55:47,976 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using PK as default sorter: id
=== 2013-02-05 14:55:47,976 [l0-0] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] Using PK as default sorter: com.isomorphic.sql.SQLOrderClause@1d6d605
=== 2013-02-05 14:55:47,976 [l0-0] 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-02-05 14:55:47,976 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:48,012 [l0-0] INFO  DSResponse - [builtinApplication.columnMeta_fetch] DSResponse: List with 75 items
=== 2013-02-05 14:55:48,012 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:48,012 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:48,012 [l0-0] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-02-05 14:55:48,014 [l0-0] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-02-05 14:55:48,045 [l0-0] INFO  Compression - /register/sc/IDACall: 26469 -> 5245 bytes
=== 2013-02-05 14:55:51,272 [l0-5] 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-02-05 14:55:51,274 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_track.png
=== 2013-02-05 14:55:51,279 [l0-5] 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-02-05 14:55:51,280 [l0-0] 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-02-05 14:55:51,282 [l0-6] 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-02-05 14:55:51,284 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vthumb_grip.png
=== 2013-02-05 14:55:51,294 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_end.png
=== 2013-02-05 14:55:51,296 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_start.png
=== 2013-02-05 14:55:57,081 [l0-0] 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-02-05 14:55:57,082 [l0-0] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:52940
=== 2013-02-05 14:55:57,082 [l0-0] 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-02-05 14:55:57,082 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-02-05 14:55:57,082 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-02-05 14:55:57,082 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-02-05 14:55:57,083 [l0-0] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:52940/Register.html?gwt.codesvr=127.0.0.1:52936
=== 2013-02-05 14:55:57,084 [l0-0] 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=cmwm6ra6cre4
=== 2013-02-05 14:55:57,084 [l0-0] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-02-05 14:55:57,084 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-02-05 14:55:57,084 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Length:1070
=== 2013-02-05 14:55:57,084 [l0-0] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache
=== 2013-02-05 14:55:57,084 [l0-0] DEBUG IDACall - Header Name:Value pair: Cache-Control:no-cache
=== 2013-02-05 14:55:57,085 [l0-0] DEBUG IDACall - session exists: cmwm6ra6cre4
=== 2013-02-05 14:55:57,085 [l0-0] DEBUG IDACall - remote user: null
=== 2013-02-05 14:55:57,091 [l0-0] DEBUG XML - Parsed XML from (in memory stream): 5ms
=== 2013-02-05 14:55:57,093 [l0-0] DEBUG RPCManager - Processing 1 requests.
=== 2013-02-05 14:55:57,094 [l0-0] 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-02-05 14:55:57,095 [l0-0] INFO  IDACall - Performing 1 operation(s)
=== 2013-02-05 14:55:57,097 [l0-0] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null
=== 2013-02-05 14:55:57,097 [l0-0] DEBUG DeclarativeSecurity - DataSource columnMeta is not in the pre-checked list, processing...
=== 2013-02-05 14:55:57,103 [l0-0] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No userTypes defined, allowing anyone access to all operations for this application
=== 2013-02-05 14:55:57,103 [l0-0] DEBUG AppBase - [builtinApplication.columnMeta_fetch] No public zero-argument method named '_columnMeta_fetch' found, performing generic datasource operation
=== 2013-02-05 14:55:57,103 [l0-0] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] Performing fetch operation with
	criteria: {Name:"QSHI"}	values: {Name:"QSHI"}
=== 2013-02-05 14:55:57,104 [l0-0] INFO  SQLDataSource - [builtinApplication.columnMeta_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-02-05 14:55:57,122 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Executing row count query: SELECT COUNT(*) FROM $defaultTableClause WHERE $defaultWhereClause
=== 2013-02-05 14:55:57,122 [l0-0] 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-02-05 14:55:57,122 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:57,122 [l0-0] DEBUG SQLDriver - [builtinApplication.columnMeta_fetch] About to execute SQL query in 'SQLServer' using connection '1253480289'
=== 2013-02-05 14:55:57,124 [l0-0] 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-02-05 14:55:57,130 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using SQL Limit query
=== 2013-02-05 14:55:57,130 [l0-0] DEBUG SQLDataSource - [builtinApplication.columnMeta_fetch] Using PK as default sorter: id
=== 2013-02-05 14:55:57,130 [l0-0] DEBUG SQLServerDriver - [builtinApplication.columnMeta_fetch] Using PK as default sorter: com.isomorphic.sql.SQLOrderClause@18a743b6
=== 2013-02-05 14:55:57,130 [l0-0] 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-02-05 14:55:57,133 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] Returning borrowed connection '1253480289'
=== 2013-02-05 14:55:57,134 [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-02-05 14:55:57,137 [l0-6] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_end.png
=== 2013-02-05 14:55:57,132 [l0-5] 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-02-05 14:55:57,137 [l0-0] INFO  DSResponse - [builtinApplication.columnMeta_fetch] DSResponse: List with 1 items
=== 2013-02-05 14:55:57,142 [l0-0] DEBUG SQLConnectionManager - [builtinApplication.columnMeta_fetch] About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:57,143 [l0-0] DEBUG SQLConnectionManager - About to close PoolableConnection with hashcode "1253480289"
=== 2013-02-05 14:55:57,143 [l0-0] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2013-02-05 14:55:57,147 [l0-5] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_track.png
=== 2013-02-05 14:55:57,152 [l0-0] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2013-02-05 14:55:57,154 [l0-0] INFO  Compression - /register/sc/IDACall: 351 -> 267 bytes
=== 2013-02-05 14:55:57,156 [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-02-05 14:55:57,157 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/Scrollbar/vscroll_Disabled_start.png
=== 2013-02-05 14:55:58,739 [l0-0] 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-02-05 14:55:58,742 [l0-0] INFO  Download - done streaming: C:/Users/usus/workspace/register/war/register/sc/skins/Enterprise/images/ListGrid/sort_descending.png
=== 2013-02-05 14:55:59,801 [l0-0] 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-02-05 14:55:59,801 [l0-0] DEBUG IDACall - Header Name:Value pair: Host:127.0.0.1:52940
=== 2013-02-05 14:55:59,801 [l0-0] 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-02-05 14:55:59,801 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
=== 2013-02-05 14:55:59,801 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Language:en-US,en;q=0.5
=== 2013-02-05 14:55:59,801 [l0-0] DEBUG IDACall - Header Name:Value pair: Accept-Encoding:gzip, deflate
=== 2013-02-05 14:55:59,802 [l0-0] DEBUG IDACall - Header Name:Value pair: Referer:http://127.0.0.1:52940/Register.html?gwt.codesvr=127.0.0.1:52936
=== 2013-02-05 14:55:59,802 [l0-0] 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=cmwm6ra6cre4
=== 2013-02-05 14:55:59,802 [l0-0] DEBUG IDACall - Header Name:Value pair: Connection:keep-alive
=== 2013-02-05 14:55:59,802 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Type:application/x-www-form-urlencoded; charset=UTF-8
=== 2013-02-05 14:55:59,802 [l0-0] DEBUG IDACall - Header Name:Value pair: Content-Length:947
=== 2013-02-05 14:55:59,802 [l0-0] DEBUG IDACall - Header Name:Value pair: Pragma:no-cache