View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0003074 | SymmetricDS | Bug | public | 2017-04-26 14:27 | 2017-05-01 18:02 |
| Reporter | woehrl01 | Assigned To | chenson | ||
| Priority | normal | ||||
| Status | closed | Resolution | fixed | ||
| Product Version | 3.8.21 | ||||
| Target Version | 3.8.22 | Fixed in Version | 3.8.22 | ||
| Summary | 0003074: Extracted request gets stuck if connection failes while sending batch | ||||
| Description | If an extract is running and tries to send the batch, and it crashes before the status gets updated in the database due to OUTGOING_BATCH_UPDATE_STATUS_MILLIS, it causes the full extraction process to stuck for that node. The reason is that the status for the batch is still RQ, while it is in fact done. So it loops with: 2017-04-26 15:46:24,598 INFO [central-0] [DataExtractorService] [central-0-data-extractor-1] Batch 23-8570801 is not ready for delivery. It is currently scheduled for extraction | ||||
| Additional Information | 2017-04-26 15:08:09,615 ERROR [central-0] [DataExtractorService] [qtp327177752-53026] Failed to extract batch 23-8570737 java.lang.RuntimeException: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 90002/90000 ms at org.jumpmind.symmetric.service.impl.DataExtractorService.transferFromStaging(DataExtractorService.java:1174) at org.jumpmind.symmetric.service.impl.DataExtractorService.sendOutgoingBatch(DataExtractorService.java:1050) at org.jumpmind.symmetric.service.impl.DataExtractorService.extract(DataExtractorService.java:669) at org.jumpmind.symmetric.service.impl.DataExtractorService.extract(DataExtractorService.java:511) at org.jumpmind.symmetric.web.PullUriHandler.pull(PullUriHandler.java:130) at org.jumpmind.symmetric.web.PullUriHandler.handleWithCompression(PullUriHandler.java:100) at org.jumpmind.symmetric.web.AbstractCompressionUriHandler.handle(AbstractCompressionUriHandler.java:84) at org.jumpmind.symmetric.web.SymmetricServlet.service(SymmetricServlet.java:114) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669) at org.jumpmind.symmetric.web.HttpMethodFilter.doFilter(HttpMethodFilter.java:62) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at org.eclipse.jetty.server.Server.handle(Server.java:499) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) at java.lang.Thread.run(Unknown Source) Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 90002/90000 ms at org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:234) at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:141) at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:383) at java.util.zip.DeflaterOutputStream.deflate(Unknown Source) at java.util.zip.DeflaterOutputStream.write(Unknown Source) at java.util.zip.GZIPOutputStream.write(Unknown Source) at org.jumpmind.symmetric.web.compression.CompressionResponseStream.write(CompressionResponseStream.java:168) at sun.nio.cs.StreamEncoder.writeBytes(Unknown Source) at sun.nio.cs.StreamEncoder.implWrite(Unknown Source) at sun.nio.cs.StreamEncoder.write(Unknown Source) at java.io.OutputStreamWriter.write(Unknown Source) at java.io.BufferedWriter.write(Unknown Source) at org.jumpmind.symmetric.service.impl.DataExtractorService.transferFromStaging(DataExtractorService.java:1121) ... 29 more Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 90002/90000 ms at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:161) at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50) at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) at java.util.concurrent.FutureTask.run(Unknown Source) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ... 1 more | ||||
| Tags | No tags attached. | ||||
|
|
The exception inside the transport is caused to the following exception on the node: 2017-04-26 16:40:06,455 INFO [mobil-NB-16112214957] [DefaultDatabaseWriter] [mobil-nb-16112214957-pull-default-1] Failed to process insert event in batch 8580237. Failed sql was: insert into "DLG_KURZ" ("sym_row_id", "dlg_kurz_id", "dlg_art", "dlg_id", "dlgteil_id", "ident_num", "sort_nr", "ModifiedBy", "ModifiedDate", "CreatedBy", "CreatedDate", "DeletedBy", "DeletedDate") values (?,?,?,?,?,?,?,?,?,?,?,?,?) Failed sql parameters: [33086FEA-2E27-E611-80DF-0050569A617F, 33204, 4, 3095, 19269, 32, 5, null, null, null, null, null, null] Failed sql parameters types: [12, 4, 4, 4, 4, 4, 4, 12, 93, 12, 93, 12, 93] Failed row data was: "34086FEA-2E27-E611-80DF-0050569A617F","33205","4","3095","192F44439","24","28","33190","4","3842","16428","39","5","1","4","423\"","19145","1","240569A617F","33190","4","3842","16428","36","5","1","32940","1","1423","19148F-0050569A617F","33192","4","3842","1235247","5","1","32942","2","1424","19140DF-0050569A617F","33193","4","3842","129,","3",,,,,, StackTraceKey.init [RuntimeException:3776605271] java.lang.RuntimeException: Could not convert a value of 192F44439 for column dlgteil_id of type INTEGER at org.jumpmind.db.platform.AbstractDatabasePlatform.getObjectValues(AbstractDatabasePlatform.java:379) at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.execute(DefaultDatabaseWriter.java:822) at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.insert(DefaultDatabaseWriter.java:175) at org.jumpmind.symmetric.io.data.writer.AbstractDatabaseWriter.write(AbstractDatabaseWriter.java:159) at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64) at org.jumpmind.symmetric.model.ProcessInfoDataWriter.write(ProcessInfoDataWriter.java:65) at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64) at org.jumpmind.symmetric.io.data.writer.TransformWriter.write(TransformWriter.java:207) at org.jumpmind.symmetric.io.data.DataProcessor.forEachDataInTable(DataProcessor.java:200) at org.jumpmind.symmetric.io.data.DataProcessor.forEachTableInBatch(DataProcessor.java:170) at org.jumpmind.symmetric.io.data.DataProcessor.process(DataProcessor.java:116) at org.jumpmind.symmetric.service.impl.DataLoaderService.loadDataFromTransport(DataLoaderService.java:537) at org.jumpmind.symmetric.service.impl.DataLoaderService.loadDataFromPull(DataLoaderService.java:291) at org.jumpmind.symmetric.service.impl.PullService.execute(PullService.java:135) at org.jumpmind.symmetric.service.impl.NodeCommunicationService$1.run(NodeCommunicationService.java:499) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: java.lang.NumberFormatException: For input string: "192F44439" at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) at java.lang.Integer.parseInt(Integer.java:580) at java.math.BigInteger.<init>(BigInteger.java:470) at java.math.BigInteger.<init>(BigInteger.java:606) at org.jumpmind.db.platform.AbstractDatabasePlatform.parseInteger(AbstractDatabasePlatform.java:484) at org.jumpmind.db.platform.sqlite.SqliteDatabasePlatform.parseInteger(SqliteDatabasePlatform.java:117) at org.jumpmind.db.platform.AbstractDatabasePlatform.getObjectValue(AbstractDatabasePlatform.java:412) at org.jumpmind.db.platform.AbstractDatabasePlatform.getObjectValues(AbstractDatabasePlatform.java:374) It recieves the following Row: 2017-04-26 16:40:06,455 INFO [mobil-NB-16112214957] [DefaultDatabaseWriter] [mobil-nb-16112214957-pull-default-1] Failed to process insert event in batch 8580237. Failed row data was: "34086FEA-2E27-E611-80DF-0050569A617F","33205","4","3095","192F44439","24","28","33190","4","3842","16428","39","5","1","4","423\"","19145","1","240569A617F","33190","4","3842","16428","36","5","1","32940","1","1423","19148F-0050569A617F","33192","4","3842","1235247","5","1","32942","2","1424","19140DF-0050569A617F","33193","4","3842","129,","3",,,,,, StackTraceKey [RuntimeException:3776605271] while the actuall values are (batch on the server): insert,"34086FEA-2E27-E611-80DF-0050569A617F","33205","4","3095","19270","33","9",,,,,, it seems like there are multiple batches overlapping? Maybe written to the client stream simultaniously? |
|
|
As I can't edit the issue, the productversion is the latest 3.8.21 |
|
|
Looks like the root cause is related to: https://www.symmetricds.org/issues/view.php?id=2984 |
|
|
Is this two different issues? The initial issue seemed to be on the extract side, but then the comment is talking about failures on the load side. |
|
|
you're right, these are two issues. The extract side is the same as 0002984. Just wanted to show the full picture. What is happening on both sides at that time. |
|
SymmetricDS: 3.8 d20cf3fa 2017-04-28 16:54:34 Details Diff |
0003074: Extracted request gets stuck if connection failes while sending batch |
Affected Issues 0003074 |
|
| mod - symmetric-core/src/main/java/org/jumpmind/symmetric/service/impl/DataExtractorService.java | Diff File | ||
| mod - symmetric-core/src/main/java/org/jumpmind/symmetric/service/impl/MultiBatchStagingWriter.java | Diff File | ||
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2017-04-26 14:27 | woehrl01 | New Issue | |
| 2017-04-27 07:17 | woehrl01 | Note Added: 0001025 | |
| 2017-04-27 07:30 | woehrl01 | Note Added: 0001026 | |
| 2017-04-28 12:04 | chenson | Assigned To | => chenson |
| 2017-04-28 12:04 | chenson | Status | new => assigned |
| 2017-04-28 12:04 | chenson | Product Version | => 3.8.22 |
| 2017-04-28 13:03 | chenson | Product Version | 3.8.22 => 3.8.21 |
| 2017-04-28 13:07 | woehrl01 | Note Added: 0001027 | |
| 2017-04-28 14:53 | chenson | Note Added: 0001029 | |
| 2017-04-28 15:11 | woehrl01 | Note Added: 0001030 | |
| 2017-04-28 15:12 | woehrl01 | Note Edited: 0001030 | View Revisions |
| 2017-04-28 20:54 | chenson | Fixed in Version | => 3.8.22 |
| 2017-04-28 20:54 | chenson | Target Version | => 3.8.22 |
| 2017-04-28 20:55 | chenson | Status | assigned => resolved |
| 2017-04-28 20:55 | chenson | Resolution | open => fixed |
| 2017-04-28 21:00 | chenson42 | Changeset attached | => SymmetricDS 3.8 d20cf3fa |
| 2017-05-01 18:02 | chenson | Status | resolved => closed |