2015-09-16 17:02:14,325 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Server fingerprint: 2,533,819 jYtUzNuQjM8llQzgTO3QTO3MDSD5UVChFWTx0QWCa+VNAN0MmZA0 2015-09-16 17:02:14,325 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Executing job: ramiro_etl/phase2-redshift-scratch/get_s3_filename.jbf with permissions of user "clover" 2015-09-16 17:02:14,325 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Triggered via Job ramiro_etl/phase2-redshift-scratch/check_if_table_exists.jbf with runID 1,412,897 2015-09-16 17:02:14,330 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing job id:1407197006707 hashCode:247244278 2015-09-16 17:02:14,330 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Graph configuration checking is skipped. 2015-09-16 17:02:14,330 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Graph initialization (get_s3_filename) 2015-09-16 17:02:14,331 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing connection: 2015-09-16 17:02:14,331 INFO 1412925 [EXECUTE_JOBFLOW_1412897] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@4017c753]:jndi[]:url[jdbc:mysql://mysqlserver.us-west-2.rds.amazonaws.com:3306]:user[clover] ... OK 2015-09-16 17:02:14,331 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing connection: 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@3cbf4b2b]:jndi[]:url[jdbc:postgresql://myredshiftserver.us-west-2.redshift.amazonaws.com:5439/mydb]:user[myuser] ... OK 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing connection: 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[jdbc:postgresql://hostname/database]:user[] ... OK 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing connection: 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[null]:user[null] ... OK 2015-09-16 17:02:14,332 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing phase 0 2015-09-16 17:02:14,333 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Phase 0 initialized successfully. 2015-09-16 17:02:14,333 INFO 1412925 [EXECUTE_JOBFLOW_1412897] Initializing watchdog 2015-09-16 17:02:14,339 INFO 1412925 [WatchDog_1412925] Job parameters: S3_TABLE=tags, BATCH_ID=55, NITRO_VERSION=5_2_0, PARENT_ID=150, CONFIG_NAME=ramiro_smoke_test_sites.prm, RS_SCHEMA=ramiro_smoke_test_sites14, RSDB_HOST=myredshift.us-west-2.redshift.amazonaws.com, RSDB_PORT=5439, RSDB_NAME=mydb, RSDB_USER=myuser, RSDB_PASSWORD=mypassword, RDS_HOST=myrds.us-west-2.rds.amazonaws.com, RDS_PORT=3306, RDS_USER_NAME=myuser, RDS_PASSWORD=mypassword, RDS_DATABASE=ramiro_smoke_test_sites, GLOBALDB_NAME=nitro_common, GLOBALDB_PORT=3306, GLOBALDB_HOST=mystuff.ec2.bunchball.net, GLOBALDB_USER=myuser, GLOBALDB_PASSWORD=mypassword, S3_FOLDER=analytics/ramiro_smoke_test_sites14, S3_BUCKET=bbetl3, S3_ACCESS_KEY=mys3access, S3_SECRET_KEY=mys3key, CHUNK_SIZE=1000000, ENVIRONMENT=production, NITRO_VERSIONS=5.0.0,5.1.0,5.2.0, SITEIDS=166154,166282, SITES_FILTER=test, SITE_FILTER_PREFIX=test, EPOCH=1970-01-01 00:00:01, VACUUM_INTERVAL=1440, BATCH_THRESHOLD=0, PROJECT=., CONN_DIR=${PROJECT}/conn, DATAIN_DIR=${PROJECT}/data-in, LOOKUP_DIR=${PROJECT}/lookup, META_DIR=${PROJECT}/meta, SANDBOX_ROOT=/ROOT/CloverETL/ramiro_etl, CLOVER_USERNAME=clover, GRAPH_FILE=phase2-redshift-scratch/get_s3_filename.jbf, SANDBOX_CODE=ramiro_etl, JOB_FILE=phase2-redshift-scratch/get_s3_filename.jbf, RUN_ID=1412925, NODE_ID=node01 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Pre-execute initialization of connection: 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@4017c753]:jndi[]:url[jdbc:mysql://clover-metadata.crsivdt70avv.us-west-2.rds.amazonaws.com:3306]:user[clover] ... OK 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Pre-execute initialization of connection: 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@3cbf4b2b]:jndi[]:url[jdbc:postgresql://myredshift.us-west-2.redshift.amazonaws.com:5439/mydb]:user[myuser] ... OK 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Pre-execute initialization of connection: 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[jdbc:postgresql://hostname/database]:user[] ... OK 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Pre-execute initialization of connection: 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[null]:user[null] ... OK 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Starting up all nodes in phase [0] 2015-09-16 17:02:14,340 INFO 1412925 [WatchDog_1412925] Successfully started all nodes in phase! 2015-09-16 17:04:24,342 ERROR 1412925 [WatchDog_1412925] Component [truncate staging tables:TRUNCATE_STAGING_TABLES] finished with status ERROR. Component pre-execute initialization failed. Cannot establish DB connection to JNDI:java:comp/env/redshift Cannot get a connection, pool error Timeout waiting for idle object 2015-09-16 17:04:24,343 ERROR 1412925 [WatchDog_1412925] Error details: org.jetel.exception.JetelRuntimeException: Component [truncate staging tables:TRUNCATE_STAGING_TABLES] finished with status ERROR. at org.jetel.graph.Node.createNodeException(Node.java:566) at org.jetel.graph.Node.run(Node.java:542) 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) Caused by: Element [TRUNCATE_STAGING_TABLES:truncate staging tables]-Component pre-execute initialization failed. at org.jetel.graph.Node.run(Node.java:497) ... 3 more Caused by: org.jetel.exception.JetelException: Cannot establish DB connection to JNDI:java:comp/env/redshift Cannot get a connection, pool error Timeout waiting for idle object at org.jetel.component.DBExecute.acquireConnection(DBExecute.java:429) at org.jetel.component.DBExecute.preExecute(DBExecute.java:370) at org.jetel.graph.Node.run(Node.java:495) ... 3 more Caused by: org.jetel.exception.JetelException: Cannot establish DB connection to JNDI:java:comp/env/redshift Cannot get a connection, pool error Timeout waiting for idle object at org.jetel.connection.jdbc.DBConnectionImpl.connect(DBConnectionImpl.java:913) at org.jetel.connection.jdbc.DBConnectionImpl.getConnection(DBConnectionImpl.java:350) at org.jetel.component.DBExecute.acquireConnection(DBExecute.java:426) ... 5 more Caused by: org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114) at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044) at org.jetel.connection.jdbc.DBConnectionImpl.connect(DBConnectionImpl.java:907) ... 7 more Caused by: java.util.NoSuchElementException: Timeout waiting for idle object at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1171) at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:79) at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) ... 9 more 2015-09-16 17:04:24,343 INFO 1412925 [WatchDog_1412925] Execution of phase [0] finished with error - elapsed time(sec): 130 2015-09-16 17:04:24,343 ERROR 1412925 [WatchDog_1412925] !!! Phase finished with error - stopping graph run !!! 2015-09-16 17:04:24,345 INFO 1412925 [WatchDog_1412925] Post-execute finalization of connection: 2015-09-16 17:04:24,345 INFO 1412925 [WatchDog_1412925] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@4017c753]:jndi[]:url[jdbc:mysql://myclover.us-west-2.rds.amazonaws.com:3306]:user[myuser] ... OK 2015-09-16 17:04:24,346 INFO 1412925 [WatchDog_1412925] Post-execute finalization of connection: 2015-09-16 17:04:24,346 INFO 1412925 [WatchDog_1412925] DBConnection driver[org.jetel.connection.jdbc.driver.JdbcDriverImpl@3cbf4b2b]:jndi[]:url[jdbc:postgresql://myredshift.us-west-2.redshift.amazonaws.com:5439/mydb]:user[myuser] ... OK 2015-09-16 17:04:24,346 INFO 1412925 [WatchDog_1412925] Post-execute finalization of connection: 2015-09-16 17:04:24,346 INFO 1412925 [WatchDog_1412925] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[jdbc:postgresql://hostname/database]:user[] ... OK 2015-09-16 17:04:24,347 INFO 1412925 [WatchDog_1412925] Post-execute finalization of connection: 2015-09-16 17:04:24,347 INFO 1412925 [WatchDog_1412925] DBConnection driver[null]:jndi[java:comp/env/redshift]:url[null]:user[null] ... OK 2015-09-16 17:04:24,349 INFO 1412925 [WatchDog_1412925] -----------------------** Summary of Phases execution **--------------------- 2015-09-16 17:04:24,349 INFO 1412925 [WatchDog_1412925] Phase# Finished Status RunTime(sec) MemoryAllocation(KB) 2015-09-16 17:04:24,349 INFO 1412925 [WatchDog_1412925] 0 ERROR 130 872626 2015-09-16 17:04:24,349 INFO 1412925 [WatchDog_1412925] ------------------------------** End of Summary **--------------------------- 2015-09-16 17:04:24,349 INFO 1412925 [JobFinalizer_1412925] Finalisation 2015-09-16 17:04:24,349 INFO 1412925 [WatchDog_1412925] WatchDog thread finished - total execution time: 130 (sec) 2015-09-16 17:04:25,398 INFO 1412925 [JobFinalizer_1412925] RunTime: 130 s 2015-09-16 17:04:26,011 ERROR 1412925 [JobFinalizer_1412925] ---------------------------------------------------------- Error details ------------------------------------------------------------ Component [truncate staging tables:TRUNCATE_STAGING_TABLES] finished with status ERROR. Component pre-execute initialization failed. Cannot establish DB connection to JNDI:java:comp/env/redshift Cannot get a connection, pool error Timeout waiting for idle object ------------------------------------------------------------------------------------------------------------------------------------- 2015-09-16 17:04:26,011 INFO 1412925 [JobFinalizer_1412925] Finished Status: ERROR