Jul 22, 2014 12:29:02 PM org.apache.catalina.core.AprLifecycleListener init INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /Users/mark/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:. Jul 22, 2014 12:29:02 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["http-bio-8080"] Jul 22, 2014 12:29:02 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["ajp-bio-8009"] Jul 22, 2014 12:29:02 PM org.apache.catalina.startup.Catalina load INFO: Initialization processed in 518 ms Jul 22, 2014 12:29:02 PM org.apache.catalina.core.StandardService startInternal INFO: Starting service Catalina Jul 22, 2014 12:29:02 PM org.apache.catalina.core.StandardEngine startInternal INFO: Starting Servlet Engine: Apache Tomcat/7.0.53 Jul 22, 2014 12:29:07 PM org.apache.catalina.startup.HostConfig deployWAR INFO: Deploying web application archive /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS.war ISC: Configuring log4j from: file:/Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/WEB-INF/classes/log4j.isc.config.xml === 2014-07-22 12:29:10,943 [op-1] INFO ISCInit - Isomorphic SmartClient/SmartGWT Framework - Initializing === 2014-07-22 12:29:10,948 [op-1] INFO ConfigLoader - Attempting to load framework.properties from CLASSPATH === 2014-07-22 12:29:11,064 [op-1] INFO ConfigLoader - Successfully loaded framework.properties from CLASSPATH at location: jar:file:/Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/WEB-INF/lib/isomorphic_core_rpc.jar!/framework.properties === 2014-07-22 12:29:11,064 [op-1] INFO ConfigLoader - Attempting to load project.properties from CLASSPATH === 2014-07-22 12:29:11,065 [op-1] INFO ConfigLoader - Unable to locate project.properties in CLASSPATH === 2014-07-22 12:29:11,069 [op-1] INFO ConfigLoader - Successfully loaded isc_interfaces.properties from CLASSPATH at location: jar:file:/Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/WEB-INF/lib/isomorphic_core_rpc.jar!/isc_interfaces.properties === 2014-07-22 12:29:11,070 [op-1] INFO ConfigLoader - Attempting to load server.properties from CLASSPATH === 2014-07-22 12:29:11,072 [op-1] INFO ConfigLoader - Successfully loaded server.properties from CLASSPATH at location: file:/Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/WEB-INF/classes/server.properties === 2014-07-22 12:29:11,078 [op-1] INFO Logger - Logging system started. === 2014-07-22 12:29:11,081 [op-1] INFO ISCInit - Auto-detected webRoot - using: /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS === 2014-07-22 12:29:11,082 [op-1] INFO ISCInit - Isomorphic SmartClient/SmartGWT Framework (v9.1p_2014-07-12/Pro Deployment 2014-07-12) - Initialization Complete Jul 22, 2014 12:29:16 PM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory /Volumes/tomcat/apache-tomcat/webapps/docs Jul 22, 2014 12:29:16 PM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory /Volumes/tomcat/apache-tomcat/webapps/examples Jul 22, 2014 12:29:17 PM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory /Volumes/tomcat/apache-tomcat/webapps/host-manager Jul 22, 2014 12:29:17 PM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory /Volumes/tomcat/apache-tomcat/webapps/manager Jul 22, 2014 12:29:17 PM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory /Volumes/tomcat/apache-tomcat/webapps/ROOT Jul 22, 2014 12:29:17 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["http-bio-8080"] Jul 22, 2014 12:29:17 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["ajp-bio-8009"] Jul 22, 2014 12:29:17 PM org.apache.catalina.startup.Catalina start INFO: Server startup in 14416 ms === 2014-07-22 12:29:51,527 [ec-1] DEBUG IDACall - Header Name:Value pair: host:localhost:8080 === 2014-07-22 12:29:51,527 [ec-1] DEBUG IDACall - Header Name:Value pair: connection:keep-alive === 2014-07-22 12:29:51,527 [ec-1] DEBUG IDACall - Header Name:Value pair: content-length:1197 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: origin:http://localhost:8080 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.153 Safari/537.36 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: content-type:application/x-www-form-urlencoded; charset=UTF-8 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: accept:*/* === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: referer:http://localhost:8080/BuiltInDS/BuiltInDS.html === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: accept-encoding:gzip,deflate,sdch === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: accept-language:en-US,en;q=0.8 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - Header Name:Value pair: cookie:JSESSIONID=F2A08D015016A5EA0CE8AC796F6563BB; PHPSESSID=jl8ck8trdl8lg9tb3vlkholrv1; GLog=%7B%0D%20%20%20%20left%3A-3328%2C%20%0D%20%20%20%20top%3A6%2C%20%0D%20%20%20%20width%3A734%2C%20%0D%20%20%20%20height%3A850%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%3A5%2C%20%0D%20%20%20%20trackRPC%3Anull%0D%7D; plushContainerWidth=100%25; plushNoTopMenu=0 === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - session exists: null === 2014-07-22 12:29:51,528 [ec-1] DEBUG IDACall - remote user: null === 2014-07-22 12:29:51,550 [ec-1] INFO RequestContext - URL: '/BuiltInDS/builtinds/sc/IDACall', User-Agent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.153 Safari/537.36': Safari with Accept-Encoding header === 2014-07-22 12:29:51,574 [ec-1] DEBUG XML - Parsed XML from (in memory stream): 3ms === 2014-07-22 12:29:51,595 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/builtinTypes.xml: 3ms === 2014-07-22 12:29:51,619 [ec-1] INFO PoolManager - SmartClient pooling started for 'simpleTypes' objects === 2014-07-22 12:29:51,700 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/List.ds.xml: 1ms === 2014-07-22 12:29:51,703 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/DataSource.ds.xml: 3ms === 2014-07-22 12:29:51,738 [ec-1] DEBUG RPCManager - Processing 1 requests. === 2014-07-22 12:29:51,751 [ec-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'supplyItem' === 2014-07-22 12:29:51,752 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/ds/supplyItem.ds.xml: 1ms === 2014-07-22 12:29:51,753 [ec-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSource' === 2014-07-22 12:29:51,755 [ec-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'DataSourceField' === 2014-07-22 12:29:51,759 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/DataSourceField.ds.xml: 4ms === 2014-07-22 12:29:51,789 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/ValueMap.ds.xml: 1ms === 2014-07-22 12:29:51,789 [ec-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Object' === 2014-07-22 12:29:51,791 [ec-1] DEBUG ISCKeyedObjectPool - Borrowing object for 'Validator' === 2014-07-22 12:29:51,793 [ec-1] DEBUG XML - Parsed XML from /Volumes/tomcat/apache-tomcat/webapps/BuiltInDS/builtinds/sc/system/schema/Validator.ds.xml: 1ms === 2014-07-22 12:29:51,842 [ec-1] DEBUG DSRequest - Caching instance 13 of DS supplyItem from DSRequest.getDataSource() === 2014-07-22 12:29:51,844 [ec-1] DEBUG RPCManager - Request #1 (DSRequest) payload: { values:{ nextShipment:new Date(1405983600000), itemName:"Test", SKU:"212345", description:"test", unitCost:1.99, units:"Ea", category:"Test" }, operationConfig:{ dataSource:"supplyItem", operationType:"add", textMatchStyle:"exact" }, componentId:"isc_DynamicForm_0", appID:"builtinApplication", operation:"supplyItem_add", oldValues:{ }, criteria:{ } } === 2014-07-22 12:29:51,845 [ec-1] INFO IDACall - Performing 1 operation(s) === 2014-07-22 12:29:51,849 [ec-1] DEBUG DeclarativeSecurity - Processing security checks for DataSource null, field null === 2014-07-22 12:29:51,849 [ec-1] DEBUG DeclarativeSecurity - DataSource supplyItem is not in the pre-checked list, processing... === 2014-07-22 12:29:51,858 [ec-1] DEBUG AppBase - [builtinApplication.supplyItem_add] No userTypes defined, allowing anyone access to all operations for this application === 2014-07-22 12:29:51,858 [ec-1] DEBUG AppBase - [builtinApplication.supplyItem_add] No public zero-argument method named '_supplyItem_add' found, performing generic datasource operation === 2014-07-22 12:29:51,860 [ec-1] INFO SQLDataSource - [builtinApplication.supplyItem_add] Performing add operation with criteria: {nextShipment:new Date(1405983600000),itemName:"Test",SKU:"212345",description:"test",unitCost:1.99,units:"Ea",category:"Test"} values: {nextShipment:new Date(1405983600000),itemName:"Test",SKU:"212345",description:"test",unitCost:1.99,units:"Ea",category:"Test"} === 2014-07-22 12:29:51,863 [ec-1] DEBUG SQLValuesClause - [builtinApplication.supplyItem_add] Sequences: {} log4j:WARN No appenders could be found for logger (org.apache.Velocity). log4j:WARN Please initialize the log4j system properly. === 2014-07-22 12:29:51,974 [ec-1] INFO PoolManager - [builtinApplication.supplyItem_add] SmartClient pooling started for 'PostgreSQL' objects === 2014-07-22 12:29:51,974 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] Initializing SQL config for 'PostgreSQL' from system config - using DriverManager: org.postgresql.Driver === 2014-07-22 12:29:51,977 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] org.postgresql.Driver lookup successful === 2014-07-22 12:29:51,977 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] DriverManager fetching connection for PostgreSQL via jdbc url jdbc:postgresql://localhost:5432/builtinds?user=postgres&password=test === 2014-07-22 12:29:51,977 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] Passing JDBC URL only to getConnection === 2014-07-22 12:29:52,006 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] makeObject() created a pooled Connection '1411781470' === 2014-07-22 12:29:52,010 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.supplyItem_add] Borrowed connection '1411781470' === 2014-07-22 12:29:52,010 [ec-1] DEBUG SQLDriver - [builtinApplication.supplyItem_add] About to execute SQL update in 'PostgreSQL' using connection'1411781470' === 2014-07-22 12:29:52,010 [ec-1] INFO SQLDriver - [builtinApplication.supplyItem_add] Executing SQL update on 'PostgreSQL': INSERT INTO supplyItem (SKU, category, description, itemID, itemName, nextShipment, unitCost, units) VALUES ('212345', 'Test', 'test', NULL, 'Test', '2014-07-22', 1.99, 'Ea') === 2014-07-22 12:29:52,023 [ec-1] INFO SQLDriver - [builtinApplication.supplyItem_add] Execute of update: INSERT INTO supplyItem (SKU, category, description, itemID, itemName, nextShipment, unitCost, units) VALUES ('212345', 'Test', 'test', NULL, 'Test', '2014-07-22', 1.99, 'Ea') on db: PostgreSQL threw exception: org.postgresql.util.PSQLException: ERROR: null value in column "itemid" violates not-null constraint Detail: Failing row contains (null, Test, 212345, test, Test, Ea, 1.99, null, 2014-07-22). - assuming stale connection and retrying update. === 2014-07-22 12:29:52,023 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.supplyItem_add] About to close ISCPoolableConnection with hashcode "1411781470" === 2014-07-22 12:29:52,023 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] DriverManager fetching connection for PostgreSQL via jdbc url jdbc:postgresql://localhost:5432/builtinds?user=postgres&password=test === 2014-07-22 12:29:52,023 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] Passing JDBC URL only to getConnection === 2014-07-22 12:29:52,027 [ec-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.supplyItem_add] makeObject() created a pooled Connection '1977898606' === 2014-07-22 12:29:52,029 [ec-1] WARN RequestContext - dsRequest.execute() failed: org.postgresql.util.PSQLException: ERROR: null value in column "itemid" violates not-null constraint Detail: Failing row contains (null, Test, 212345, test, Test, Ea, 1.99, null, 2014-07-22). at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2161) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1890) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:560) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:363) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102) at com.isomorphic.sql.SQLDriver.doUpdate(SQLDriver.java:876) at com.isomorphic.sql.SQLDriver.update(SQLDriver.java:791) at com.isomorphic.sql.SQLDriver.executeUpdate(SQLDriver.java:961) at com.isomorphic.sql.SQLDataSource.executeNativeUpdate(SQLDataSource.java:571) at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1963) at com.isomorphic.sql.SQLDataSource.processRequest(SQLDataSource.java:444) at com.isomorphic.sql.SQLDataSource.executeAdd(SQLDataSource.java:397) at com.isomorphic.datasource.DataSource.execute(DataSource.java:1544) at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:723) at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658) at com.isomorphic.application.AppBase.execute(AppBase.java:491) at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:2534) at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:215) at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:172) at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:137) at com.isomorphic.servlet.IDACall.doPost(IDACall.java:73) at javax.servlet.http.HttpServlet.service(HttpServlet.java:646) at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) === 2014-07-22 12:29:52,032 [ec-1] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8 === 2014-07-22 12:29:52,033 [ec-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false === 2014-07-22 12:29:52,036 [ec-1] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1977898606 === 2014-07-22 12:29:52,036 [ec-1] DEBUG SQLConnectionManager - About to close ISCPoolableConnection with hashcode "1977898606"