Something looks like it's gone wrong with Dream Extractor. What steps should I take to see if further action is necessary?
- Check the job is running and not stuck in Rundeck. It should rarely take more than 3 minutes. If it's been running for over 10, it's almost certainly stuck. Stop, allow to stop and then restart the Rundeck job and continue checking the below steps.
- Check the Mantiki Database entity event tables to see if any events are in an error state ie have failed and no processing has occurred (SQL below). Provided accounts have not manually adjusted for these entries, the state could be set back to pending here and when the extractor runs, it will try and process this entry again.
- Check the Mantiki Database Dream Extractor temporary tables. A status of 'Error' indicates that the attempt got so far as to be placed in the Mantiki temporary tables but has failed here. You can set the corresponding entry to pending in the entity event tables but the attempt will probably fail due to a duplicate entry in the temporary table and you may need to remove a failed entry in the temporary table before setting the entity event to pending.
- If you find errors above, it's unlikely that the entries will have reached the Dream Extractor Sql Server tables. On taking some of the remedies above you'll want to check that the entry has appeared here though. Connection details in the main Dream Extractor guide page. Also worth checking is that the tables contain recent data as if they don't, this is an indication that probably there is a problem (most likely one of the numbers above).
Useful SQL
Find transactions which haven't been processed - eg are either pending (probably legitimately waiting for processing) or are in an error state.
select entity_event.*, customer_account_entry.entity_reference from entity_event
join customer_account_entry on customer_account_entry.id = entity_event.entity_instance_id
where entity_event.state <> 'processed'
and entity_event.name in ('winebank_payment', 'winebank_refund', 'account_adjustment')
UNION
select entity_event.*, sales_order_shipment.shipment_reference from entity_event
join sales_order_shipment on sales_order_shipment.id = entity_event.entity_instance_id
where entity_event.state <> 'processed'
and entity_event.name = 'sale'
UNION
select entity_event.*, sales_order_credit.credit_reference from entity_event
join sales_order_credit on sales_order_credit.id = entity_event.entity_instance_id
where entity_event.state <> 'processed'
and entity_event.name = 'refund';
Find transactions that have been processed by the first half of the daemons ie are queued for writing to the SQL Server Dream Extractor database but not reached a 'done' state - this may be due to errors.
select extract_customer_number, extract_shipment_created_on, extract_shipment_reference_number, record_status, record_status_comment from process_extract_dream_shipment where record_status != 'done' UNION select extract_customer_number, extract_refund_created_on, extract_credit_reference_number, record_status, record_status_comment from process_extract_dream_credit where record_status != 'done' UNION select extract_customer_number, extract_created_on, extract_payment_reference_number, record_status, record_status_comment from process_extract_dream_wbpayment_customer where record_status != 'done' UNION select extract_customer_number, extract_created_on, extract_payment_reference_number, record_status, record_status_comment from process_extract_dream_wbrefund_customer where record_status != 'done' UNION select extract_customer_number, extract_date, extract_account_type, record_status, record_status_comment from process_extract_dream_account_adjustment where record_status != 'done';
The transaction is marked as processed and I can see it in the temporary tables in Mantiki but it is not in Dream Extractor. What's the problem?
The Dream Extractor daemons are a series of 2 part daemons. First a transaction is copied into a temporary table within Mantiki. From there it is accessed a second time upon which it is written to the Dream Extractor tables. On a very rare occasion, the entry may be copied to the temporary tables but access may fail when attempting to write to the Dream Extractor table. Because there is only one trigger for both actions, this results in the transaction being marked as processed when it has not been successfully transferred to the Dream Extractor tables. It's unfortunate that this is a weakness of the methodology used with these paired daemons. At this time, the solution is that Finance remedies these transactions manually and they always appear to spot them themselves but they will ask for an investigation when one occurs to ensure that there is no other problem with the transaction.
In the logs/rundeck, such a failure will look like this:
2018-09-19 13:47:48,389 - main - ERROR - RefundExtractTaskExecutor.submitTask(81) | Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:245) 13:47:48 at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) 13:47:48 at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskExecutor.submitTask(RefundExtractTaskExecutor.java:61) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskExecutor.submitTask(RefundExtractTaskExecutor.java:21) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator$1.process(RefundExtractTaskCreator.java:69) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator$1.process(RefundExtractTaskCreator.java:62) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3$1.doInTransaction(LoaderTableManager.java:554) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3$1.doInTransaction(LoaderTableManager.java:551) 13:47:48 at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3.processRow(LoaderTableManager.java:551) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate$RowCallbackHandlerResultSetExtractor.extractData(JdbcTemplate.java:1571) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:463) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:408) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:474) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:479) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager.scrollThroughEntitiesWithWhereClause(LoaderTableManager.java:535) 13:47:48 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 13:47:48 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) 13:47:48 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 13:47:48 at java.lang.reflect.Method.invoke(Method.java:606) 13:47:48 at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) 13:47:48 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) 13:47:48 at com.sun.proxy.$Proxy8.scrollThroughEntitiesWithWhereClause(Unknown Source) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator.createTasks(RefundExtractTaskCreator.java:82) 13:47:48 at com.mantiki.daemon.TaskCreator.executeTasks(TaskCreator.java:45) 13:47:48 at com.mantiki.daemon.MantikiDaemon.trigger(MantikiDaemon.java:208) 13:47:48 at com.mantiki.daemon.runner.SingleRunner.start(SingleRunner.java:19) 13:47:48 at com.mantiki.daemon.MantikiDaemon.run(MantikiDaemon.java:153) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.run(DreamExec.java:61) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.runAllExtractors(DreamExec.java:30) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.main(DreamExec.java:22) 13:47:48 Caused by: java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:2294) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createDataSource(BasicDataSource.java:2039) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533) 13:47:48 at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:204) 13:47:48 ... 31 more 13:47:48 Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.". 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerException.ConvertConnectExceptionToSQLServerException(SQLServerException.java:241) 13:47:48 at com.microsoft.sqlserver.jdbc.SocketFinder.findSocket(IOBuffer.java:2243) 13:47:48 at com.microsoft.sqlserver.jdbc.TDSChannel.open(IOBuffer.java:491) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:1310) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:992) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:828) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:1012) 13:47:48 at org.apache.commons.dbcp2.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:39) 13:47:48 at org.apache.commons.dbcp2.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:256) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.validateConnectionFactory(BasicDataSource.java:2304) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:2290) 13:47:48 ... 34 more 13:47:48 2018-09-19 13:47:48,406 - main - INFO - MantikiDaemon.onStopTasks(315) | Daemon process Credit Refund Dreams Extract Daemon has finished running tasks 13:47:48 2018-09-19 13:47:48,406 - main - INFO - MantikiDaemon.onStopTrigger(268) | Daemon process Credit Refund Dreams Extract Daemon is idling 13:47:48 2018-09-19 13:47:48,415 - main - INFO - MantikiDaemon.onStopDaemon(241) | 13:47:48 13:47:48 Daemon process Credit Refund Dreams Extract Daemon has stopped with state 'Stopped'.
The transaction is marked as processed and I can see it in the temporary tables in Mantiki but it is not in Dream Extractor. What's the problem?
The Dream Extractor daemons are a series of 2 part daemons. First a transaction is copied into a temporary table within Mantiki. From there it is accessed a second time upon which it is written to the Dream Extractor tables. On a very rare occasion, the entry may be copied to the temporary tables but access may fail when attempting to write to the Dream Extractor table. Because there is only one trigger for both actions, this results in the transaction being marked as processed when it has not been successfully transferred to the Dream Extractor tables. It's unfortunate that this is a weakness of the methodology used with these paired daemons. At this time, the solution is that Finance remedies these transactions manually and they always appear to spot them themselves but they will ask for an investigation when one occurs to ensure that there is no other problem with the transaction.
In the logs/rundeck, such a failure will look like this:
2018-09-19 13:47:48,389 - main - ERROR - RefundExtractTaskExecutor.submitTask(81) | Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:245) 13:47:48 at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) 13:47:48 at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskExecutor.submitTask(RefundExtractTaskExecutor.java:61) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskExecutor.submitTask(RefundExtractTaskExecutor.java:21) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator$1.process(RefundExtractTaskCreator.java:69) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator$1.process(RefundExtractTaskCreator.java:62) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3$1.doInTransaction(LoaderTableManager.java:554) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3$1.doInTransaction(LoaderTableManager.java:551) 13:47:48 at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager$3.processRow(LoaderTableManager.java:551) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate$RowCallbackHandlerResultSetExtractor.extractData(JdbcTemplate.java:1571) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:463) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:408) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:474) 13:47:48 at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:479) 13:47:48 at com.mantiki.daemon.loader.LoaderTableManager.scrollThroughEntitiesWithWhereClause(LoaderTableManager.java:535) 13:47:48 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 13:47:48 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) 13:47:48 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 13:47:48 at java.lang.reflect.Method.invoke(Method.java:606) 13:47:48 at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) 13:47:48 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) 13:47:48 at com.sun.proxy.$Proxy8.scrollThroughEntitiesWithWhereClause(Unknown Source) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.refundextractor.RefundExtractTaskCreator.createTasks(RefundExtractTaskCreator.java:82) 13:47:48 at com.mantiki.daemon.TaskCreator.executeTasks(TaskCreator.java:45) 13:47:48 at com.mantiki.daemon.MantikiDaemon.trigger(MantikiDaemon.java:208) 13:47:48 at com.mantiki.daemon.runner.SingleRunner.start(SingleRunner.java:19) 13:47:48 at com.mantiki.daemon.MantikiDaemon.run(MantikiDaemon.java:153) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.run(DreamExec.java:61) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.runAllExtractors(DreamExec.java:30) 13:47:48 at uk.co.virginwines.daemon.dreamsfinance.execrunner.DreamExec.main(DreamExec.java:22) 13:47:48 Caused by: java.sql.SQLException: Cannot create PoolableConnectionFactory (The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:2294) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createDataSource(BasicDataSource.java:2039) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533) 13:47:48 at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:204) 13:47:48 ... 31 more 13:47:48 Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host 10.20.0.29, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.". 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerException.ConvertConnectExceptionToSQLServerException(SQLServerException.java:241) 13:47:48 at com.microsoft.sqlserver.jdbc.SocketFinder.findSocket(IOBuffer.java:2243) 13:47:48 at com.microsoft.sqlserver.jdbc.TDSChannel.open(IOBuffer.java:491) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:1310) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:992) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:828) 13:47:48 at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:1012) 13:47:48 at org.apache.commons.dbcp2.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:39) 13:47:48 at org.apache.commons.dbcp2.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:256) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.validateConnectionFactory(BasicDataSource.java:2304) 13:47:48 at org.apache.commons.dbcp2.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:2290) 13:47:48 ... 34 more 13:47:48 2018-09-19 13:47:48,406 - main - INFO - MantikiDaemon.onStopTasks(315) | Daemon process Credit Refund Dreams Extract Daemon has finished running tasks 13:47:48 2018-09-19 13:47:48,406 - main - INFO - MantikiDaemon.onStopTrigger(268) | Daemon process Credit Refund Dreams Extract Daemon is idling 13:47:48 2018-09-19 13:47:48,415 - main - INFO - MantikiDaemon.onStopDaemon(241) | 13:47:48 13:47:48 Daemon process Credit Refund Dreams Extract Daemon has stopped with state 'Stopped'.