Hey there,

I'm extracting a table that has upwards of 1.3M rows, but this applies to all generally large tables. At some point, something will happen and an extraction (a .done file) will be deleted or skipped. I do not know what is causing this. It might be worth noting that:

• This has only occurred when running two or more simultaneous initial loads
• The other running initial load appears to have completed just fine
• 1120806 and 1120807 are missing (see files image below), but Symmetric has only noticed 1120806.
• -807 is marked as NE in the outgoing_batch, but -806 is marked RQ.
• Editing the Outgoing_Batch and updating the status of the failed batch to NE causes it to again realize it's deleted and then actually extract it.

Logs/Screenshots

Running SymmetricDS v3.8.31

**Failed Extract_Request**
request_id:12156
node_id:DOCKER-0-AmericanEskimoDogMiniature
queue:default
status:OK
start_batch_id:1120251
end_batch_id:1121284
trigger_id:dbo-mTable-SERVER
router_id:v2--2-cli-dbo-mTable
last_update_time:2018-01-19 17:11:20.450
create_time:2018-01-19 17:11:20.450
**Failed Outgoing_Batch** 
batch_id:1120806
node_id:DOCKER-0-AmericanEskimoDogMiniature
channel_id:reload
status:RQ
load_id:62
extract_job_flag:1
load_flag:1
error_flag:0
common_flag:0
ignore_count:0
byte_count:210235
extract_count:1
sent_count:0
load_count:0
data_event_count:1500
reload_event_count:1
insert_event_count:1500
update_event_count:0
delete_event_count:0
other_event_count:0
router_millis:0
network_millis:0
filter_millis:0
load_millis:0
extract_millis:63
transform_extract_millis:0
transform_load_millis:0
total_extract_millis:0
total_load_millis:0
sql_state:NULL
sql_code:0
sql_message:NULL
failed_data_id:0
failed_line_number:0
last_update_hostname:tmp
last_update_time:2018-01-19
create_time:18:00:49.710
create_by:2018-01-19
summary:17:11:19.940

2018-01-19 17:56:31,503 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-extract-default-17] Extracting batches for request 12156. Starting at batch 1120251. Ending at batch 1121284
2018-01-19 17:58:40,571 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-extract-default-17] Request 12156 has been processing for 129 seconds. BATCHES=0, ROWS=0, BYTES=0, RANGE=1120251-1121284, CURRENT=1120251
2018-01-19 17:59:40,575 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-extract-default-17] Request 12156 has been processing for 189 seconds. BATCHES=425, ROWS=637500, BYTES=95580674, RANGE=1120251-1121284, CURRENT=1120676
2018-01-19 18:00:40,603 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-extract-default-17] Request 12156 has been processing for 249 seconds. BATCHES=859, ROWS=1288500, BYTES=192992225, RANGE=1120251-1121284, CURRENT=1121110
2018-01-19 18:00:49,571 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-4124] Batch DOCKER-0-AmericanEskimoDogMiniature-1120806 is marked as ready but it has been deleted. Rescheduling it for extraction
2018-01-19 18:01:07,337 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-extract-default-17] Done extracting 1034 batches for request 12156
2018-01-19 18:01:51,766 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-4131] Batch DOCKER-0-AmericanEskimoDogMiniature-1120806 is not ready for delivery. It is currently scheduled for extraction

The last italicized line is then where the repeat happens.

Missing Files (image)
Configured Parameters (image)

Let me know if there is anything more information I can provide. Currently, an hour later, the program is still attempting to run the DataExtractorService.

3.8.31 is a bad release to be on in general because of this: https://www.symmetricds.org/issues/view.php?id=3318

Not sure if it is releated to your issue though. I thought issues like what you are describing had been addressed by this point with the parameter settings you have set.

I would suggest trying 3.8.33 and if you still see the issue we'll help you get to the bottom of it.

Hey Chris, thanks for the quick response.

I've went through and upgraded both the server and clients to 3.8.33 (delete/replace lib and web/web-inf/lib), and unfortunately the issue persists. I didn't mention it above but I am going from MS SQL Server -> Sqlite.

I successfully ran through 2 simultaneous initial loads, but when I attempted 3, all 3 of them ended up erroring out.

2018-01-21 03:05:33,323 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-1629] Batch DOCKER-0-SealyhamTerrier-1310082 is marked as ready but it has been deleted.  Rescheduling it for extraction
2018-01-21 03:05:56,510 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-1634] Batch DOCKER-1-BostonTerrier-1298021 is marked as ready but it has been deleted.  Rescheduling it for extraction
2018-01-21 04:03:25,655 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-2323] Batch DOCKER-2-IrishWaterSpaniel-1292907 is marked as ready but it has been deleted.  Rescheduling it for extraction


2018-01-21 04:26:39,311 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-2392] Batch DOCKER-0-SealyhamTerrier-1310082 is not ready for delivery.  It is currently scheduled for extraction
2018-01-21 04:26:58,248 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-2393] Batch DOCKER-2-IrishWaterSpaniel-1292907 is not ready for delivery.  It is currently scheduled for extraction
2018-01-21 04:27:10,295 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-2394] Batch DOCKER-1-BostonTerrier-1298021 is not ready for delivery.  It is currently scheduled for extraction

Here is the outgoing_batch and extract_request in error.
Two .done files are missing.

The other two which are erroring out share similar outgoing_batch and extract_request errors, but they're either missing one or two .done files.

For your convenience I've uploaded the entire output logfile.

Please let me know if there's any way I can help you figure this out. I understand the pain of a recurring bug that won't go away..

Steve,

It looks like your using Docker. Would you mind trying our official Docker image? It runs 3.9.x though. Just curious if it produces the same results.

https://hub.docker.com/r/jumpmind/symmetricds/

I am only using Docker to simulate clients for stress testing. The server instance of symmetric is running on a standard WinServer 2012 box.

For reference I was..fortunate enough to encounter this issue while replicating just a single client. The same story of a batch being mysteriously removed from tmp/outgoing/<client>/batch.done</client>. The service acknowledged the missing batch and changed the statuses to RQ, such that the status of the nearby batchs are:

OK
RQ <-- bad
NE

but the service never re-extracts the batch.

*2018-01-24 16:35:54,692 INFO [v2-mc-0000000] [DataExtractorService] [v2-mc-0000000-dataextractor-133] Batch DOCKER-0-Mastiff-1558217 is not ready for delivery. It is currently scheduled for extraction
*

If you can get us enough information so that we can recreate the issue we'll fix it.

Can we get your configuration, engine.properties settings, a dump of outgoing_batch where load_id={failed load id} and the count of the number of rows in the failed table and the symetricds log file?

Hey Chris,

After implementing this Pull Request that allows me to locally cache most of the larger reload tables, this issue has since stopped appearing. Before I incorporated this change, I was unable to successfully get past 4 simultaneous initial loads. Afterwards I have been able to run 30 simultaneous loads. I am delighted to hear from Austin that initial load performance is on radar for early 2018.

If I run into this issue again I will fulfill your request for additional details. Thank you!