View Issue Details

IDProjectCategoryView StatusLast Update
0003074SymmetricDSBugpublic2017-05-01 14:02
Reporterwoehrl01Assigned Tochenson 
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Product Version3.8.21 
Target Version3.8.22Fixed in Version3.8.22 
Summary0003074: Extracted request gets stuck if connection failes while sending batch
DescriptionIf 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 Information2017-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
TagsNo tags attached.

Activities

woehrl01

2017-04-27 03:17

reporter   ~0001025

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?

woehrl01

2017-04-27 03:30

reporter   ~0001026

As I can't edit the issue, the productversion is the latest 3.8.21

woehrl01

2017-04-28 09:07

reporter   ~0001027

Looks like the root cause is related to: https://www.symmetricds.org/issues/view.php?id=2984

chenson

2017-04-28 10:53

administrator   ~0001029

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.

woehrl01

2017-04-28 11:11

reporter   ~0001030

Last edited: 2017-04-28 11:12

View 2 revisions

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.

Related Changesets

SymmetricDS: 3.8 d20cf3fa

2017-04-28 16:54:34

chenson42

Details Diff
0003074: Extracted request gets stuck if connection failes while sending
batch

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

Issue History

Date Modified Username Field Change
2017-04-26 10:27 woehrl01 New Issue
2017-04-27 03:17 woehrl01 Note Added: 0001025
2017-04-27 03:30 woehrl01 Note Added: 0001026
2017-04-28 08:04 chenson Assigned To => chenson
2017-04-28 08:04 chenson Status new => assigned
2017-04-28 08:04 chenson Product Version => 3.8.22
2017-04-28 09:03 chenson Product Version 3.8.22 => 3.8.21
2017-04-28 09:07 woehrl01 Note Added: 0001027
2017-04-28 10:53 chenson Note Added: 0001029
2017-04-28 11:11 woehrl01 Note Added: 0001030
2017-04-28 11:12 woehrl01 Note Edited: 0001030 View Revisions
2017-04-28 16:54 chenson Fixed in Version => 3.8.22
2017-04-28 16:54 chenson Target Version => 3.8.22
2017-04-28 16:55 chenson Status assigned => resolved
2017-04-28 16:55 chenson Resolution open => fixed
2017-04-28 17:00 chenson42 Changeset attached => SymmetricDS 3.8 d20cf3fa
2017-05-01 14:02 chenson Status resolved => closed