View Issue Details

Related ChangesetsJump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0003540SymmetricDSBugpublic2018-05-03 19:012018-10-31 18:59
Reporterwoehrl01 Assigned Tommichalek  
Priorityhigh 
Status closedResolutionfixed 
Product Version3.9.6 
Target Version3.9.15Fixed in Version3.9.15 
Summary0003540: Registration gets lost during the registration when File Sync is enabled
DescriptionI experience the following race condition, if I register a node, it sometimes gets unregistered during the registration process.

It looks like that the FileSyncService is removing the identity, because it is running during the time where the sym_node_identity is created on the client and it has been acknowledged on the server.

see https://sourceforge.net/p/symmetricds/discussion/739236/thread/4923acfa/
Steps To ReproduceReproduced using 3.9.13.

Register client node as usual (e.g., node id 003)
Turn on file sync.
set file sync push/pull to 10 secs (not sure if this is needed)
On corp database, run:
delete from sym_node_security where node_id='003';
delete from sym_node where node_id='003';

wait a minute or two.
node will show up in request screen
"Allow" registration

If timing is right, the node identity gets deleted and the registration gets lost, as described above.

Had to run it multiple to get the symptom to appear. Also, make note of the NullPointer that occurred afterwards, as well as the Ack failures.
TagsNo tags attached.

Activities

woehrl01

2018-05-03 19:05

reporter   ~0001172

see PR https://github.com/JumpMind/symmetric-ds/pull/73

hanes

2018-09-19 18:18

developer   ~0001243

My approach to creating this issue:

Register client node as usual (e.g., node id 003)
Turn on file sync.
set file sync push/pull to 10 secs (not sure if this is needed)
On corp database, run:
delete from sym_node_security where node_id='003';
delete from sym_node where node_id='003';

wait a minute or two.
node will show up in request screen
"Allow" registration

If timing is right, the node identity gets deleted and the registration gets lost, as described above.

Had to run it twice to get the symptom to appear.

hanes

2018-09-19 18:36

developer   ~0001244

[store-003] - DataLoaderService - Using registration URL of http://localhost:31000/sync/corp-000/registration?nodeGroupId=store&externalId=003&syncURL=http%3A%2F%2Flocalhost%3A31030%2Fsync%2Fstore-003&schemaVersion=%3F&databaseType=H2&databaseVersion=1.3&symmetricVersion=3.9.13&deploymentType=professional&hostName=turing-2.local&ipAddress=192.168.42.103
[store-003] - PullService - Registration was not open at corp:000:000



[store-003] - FileSyncService - Sync was not enabled for corp:000:000 at http://localhost:31000/sync/corp-000
[store-003] - PullService - Sync was not enabled for corp:000:000 at http://localhost:31000/sync/corp-000
[store-003] - DefaultOfflineClientListener - Removing identity because sync has been disabled



[store-003] - RouterJob - Did not run the 'Routing' job because the engine is not registered.
[store-003] - PushJob - Did not run the 'Push' job because the engine is not registered.
[store-003] - FileSyncPullJob - Did not run the 'File Sync Pull' job because the engine is not registered.
[store-003] - InitialLoadExtractorJob - Did not run the 'Initial Load Extract' job because the engine is not registered.
[store-003] - FileSyncPushJob - Did not run the 'File Sync Push' job because the engine is not registered.
[store-003] - RegistrationService - This node is unregistered. It will attempt to register using the registration.url
[store-003] - DataLoaderService - Using registration URL of http://localhost:31000/sync/corp-000/registration?nodeGroupId=store&externalId=003&syncURL=http%3A%2F%2Flocalhost%3A31030%2Fsync%2Fstore-003&schemaVersion=%3F&databaseType=H2&databaseVersion=1.3&symmetricVersion=3.9.13&deploymentType=professional&hostName=turing-2.local&ipAddress=192.168.42.103
[store-003] - DataService - Deleted 86 data rows that were on the config channel
[store-003] - ConfigurationChangedDatabaseWriterFilter - Grouplets flushed because new grouplet config came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - Load filters flushed because new filter config came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - Channels flushed because new channels came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to refresh the cache of conflict settings because new configuration came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to refresh the cache of parameters because new configuration came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to refresh the cache of node security because new configuration came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to refresh the cache of transformation because new configuration came through the data loader
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to clear the staging area because new transform configuration came through the data loader
[store-003] - StagingManager - Purged 4 from stage, freeing 5 kbytes of space
[store-003] - ClusterService - Failed to release lock for action:Stage Management server:turing-2.local
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to restart jobs because new configuration came through the data loader
[store-003] - RouterJob - The 'Routing' job has been cancelled
[store-003] - PushJob - The 'Push' job has been cancelled
[store-003] - PullJob - The 'Pull' job has been cancelled
[store-003] - OutgoingPurgeJob - The 'Purge Outgoing' job has been cancelled
[store-003] - IncomingPurgeJob - The 'Purge Incoming' job has been cancelled
[store-003] - StatisticFlushJob - The 'Stat Flush' job has been cancelled
[store-003] - SyncTriggersJob - The 'SyncTriggers' job has been cancelled
[store-003] - HeartbeatJob - The 'Heartbeat' job has been cancelled
[store-003] - WatchdogJob - The 'Watchdog' job has been cancelled
[store-003] - StageManagementJob - The 'Stage Management' job has been cancelled
[store-003] - FileSyncTrackerJob - The 'File Sync Tracker' job has been cancelled
[store-003] - FileSyncPullJob - The 'File Sync Pull' job has been cancelled
[store-003] - FileSyncPushJob - The 'File Sync Push' job has been cancelled
[store-003] - InitialLoadExtractorJob - The 'Initial Load Extract' job has been cancelled
[store-003] - MonitorJob - The 'Monitor' job has been cancelled
[store-003] - RouterJob - Starting Routing on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - PushJob - Starting Push on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - PullJob - Starting Pull on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - JobManager - Job Offline Push not configured for auto start
[store-003] - JobManager - Job Offline Pull not configured for auto start
[store-003] - OutgoingPurgeJob - Starting job 'Purge Outgoing' with cron expression: '0 0 0 * * *'
[store-003] - IncomingPurgeJob - Starting job 'Purge Incoming' with cron expression: '0 0 0 * * *'
[store-003] - StatisticFlushJob - Starting job 'Stat Flush' with cron expression: '0 0/5 * * * *'
[store-003] - SyncTriggersJob - Starting job 'SyncTriggers' with cron expression: '0 0 0 * * *'
[store-003] - HeartbeatJob - Starting Heartbeat on periodic schedule: every 900000ms with the first run at Wed Sep 19 14:32:59 EDT 2018
[store-003] - WatchdogJob - Starting Watchdog on periodic schedule: every 3600000ms with the first run at Wed Sep 19 15:02:57 EDT 2018
[store-003] - StageManagementJob - Starting job 'Stage Management' with cron expression: '0 0 * * * *'
[store-003] - JobManager - Job Refresh Cache not configured for auto start
[store-003] - FileSyncTrackerJob - Starting job 'File Sync Tracker' with cron expression: '0 0/5 * * * *'
[store-003] - FileSyncPullJob - Starting File Sync Pull on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - FileSyncPushJob - Starting File Sync Push on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - InitialLoadExtractorJob - Starting Initial Load Extract on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:23:59 EDT 2018
[store-003] - MonitorJob - Starting Monitor on periodic schedule: every 60000ms with the first run at Wed Sep 19 14:24:09 EDT 2018
[store-003] - JobManager - Job Report Status not configured for auto start
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to syncTriggers because new configuration came through the data loader
[store-003] - TriggerRouterService - Synchronizing triggers
[store-003] - TriggerRouterService - Could not find any database tables matching 'SALE_TENDER_LINE_ITEM' in the datasource that is configured
[store-003] - TriggerRouterService - Could not find any database tables matching 'SALE_RETURN_LINE_ITEM' in the datasource that is configured
[store-003] - TriggerRouterService - Could not find any database tables matching 'SALE_TRANSACTION' in the datasource that is configured
[store-003] - TriggerRouterService - Done synchronizing triggers
[store-003] - ConfigurationChangedDatabaseWriterFilter - About to syncTriggers for file snapshot because the file sync parameter has changed
[store-003] - ExtensionService - Found 0 extension points from the database that will be registered
[store-003] - ClientExtensionService - Found 14 extension points from spring that will be registered
[store-003] - RouterJob - The 'Routing' job has been cancelled
[store-003] - PushJob - The 'Push' job has been cancelled
[store-003] - PullJob - The 'Pull' job has been cancelled
[store-003] - OutgoingPurgeJob - The 'Purge Outgoing' job has been cancelled
[store-003] - IncomingPurgeJob - The 'Purge Incoming' job has been cancelled
[store-003] - StatisticFlushJob - The 'Stat Flush' job has been cancelled
[store-003] - SyncTriggersJob - The 'SyncTriggers' job has been cancelled
[store-003] - HeartbeatJob - The 'Heartbeat' job has been cancelled
[store-003] - WatchdogJob - The 'Watchdog' job has been cancelled
[store-003] - StageManagementJob - The 'Stage Management' job has been cancelled
[store-003] - FileSyncTrackerJob - The 'File Sync Tracker' job has been cancelled
[store-003] - FileSyncPullJob - The 'File Sync Pull' job has been cancelled
[store-003] - FileSyncPushJob - The 'File Sync Push' job has been cancelled
[store-003] - InitialLoadExtractorJob - The 'Initial Load Extract' job has been cancelled
[store-003] - MonitorJob - The 'Monitor' job has been cancelled
[store-003] - RouterJob - Starting Routing on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - PushJob - Starting Push on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - PullJob - Starting Pull on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - JobManager - Job Offline Push not configured for auto start
[store-003] - JobManager - Job Offline Pull not configured for auto start
[store-003] - OutgoingPurgeJob - Starting job 'Purge Outgoing' with cron expression: '0 0 0 * * *'
[store-003] - IncomingPurgeJob - Starting job 'Purge Incoming' with cron expression: '0 0 0 * * *'
[store-003] - StatisticFlushJob - Starting job 'Stat Flush' with cron expression: '0 0/5 * * * *'
[store-003] - SyncTriggersJob - Starting job 'SyncTriggers' with cron expression: '0 0 0 * * *'
[store-003] - HeartbeatJob - Starting Heartbeat on periodic schedule: every 900000ms with the first run at Wed Sep 19 14:32:59 EDT 2018
[store-003] - WatchdogJob - Starting Watchdog on periodic schedule: every 3600000ms with the first run at Wed Sep 19 15:02:57 EDT 2018
[store-003] - StageManagementJob - Starting job 'Stage Management' with cron expression: '0 0 * * * *'
[store-003] - JobManager - Job Refresh Cache not configured for auto start
[store-003] - FileSyncTrackerJob - Starting job 'File Sync Tracker' with cron expression: '0 0/5 * * * *'
[store-003] - FileSyncPullJob - Starting File Sync Pull on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - FileSyncPushJob - Starting File Sync Push on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - InitialLoadExtractorJob - Starting Initial Load Extract on periodic schedule: every 10000ms with the first run at Wed Sep 19 14:24:00 EDT 2018
[store-003] - MonitorJob - Starting Monitor on periodic schedule: every 60000ms with the first run at Wed Sep 19 14:24:09 EDT 2018
[store-003] - JobManager - Job Report Status not configured for auto start
[store-003] - TriggerRouterService - Synchronizing triggers for DATABASENAME.PUBLIC.SYM_FILE_SNAPSHOT
[store-003] - TriggerRouterService - Done synchronizing triggers for DATABASENAME.PUBLIC.SYM_FILE_SNAPSHOT
[store-003] - DataLoaderService - Ack was not sent successfully on try number 1 of 5. statusCode=658
[store-003] - FileSyncService - Sync was not enabled for corp:000:000 at http://localhost:31000/sync/corp-000
[store-003] - DefaultOfflineClientListener - Removing identity because sync has been disabled
[store-003] - RouterService - Routed 88 data events in 82 ms
[store-003] - DataLoaderService - Ack was not sent successfully on try number 2 of 5. statusCode=658
[store-003] - RegistrationService - Node identity is missing after registration. The registration server may be misconfigured or have an error
[store-003] - RegistrationService - Could not register. Sleeping for 20000ms before attempting again.
[store-003] - MonitorJob - Did not run the 'Monitor' job because the engine is not registered.
[store-003] - PushJob - Did not run the 'Push' job because the engine is not registered.
[store-003] - FileSyncPushJob - Did not run the 'File Sync Push' job because the engine is not registered.
[store-003] - InitialLoadExtractorJob - Did not run the 'Initial Load Extract' job because the engine is not registered.
[store-003] - FileSyncPullJob - Did not run the 'File Sync Pull' job because the engine is not registered.
[store-003] - RouterJob - Did not run the 'Routing' job because the engine is not registered.
[store-003] - RegistrationService - This node is unregistered. It will attempt to register using the registration.url
[store-003] - DataLoaderService - Using registration URL of http://localhost:31000/sync/corp-000/registration?nodeGroupId=store&externalId=003&syncURL=http%3A%2F%2Flocalhost%3A31030%2Fsync%2Fstore-003&schemaVersion=%3F&databaseType=H2&databaseVersion=1.3&symmetricVersion=3.9.13&deploymentType=professional&hostName=turing-2.local&ipAddress=192.168.42.103
[store-003] - RegistrationService - Waiting for registration to be accepted by the server. Registration is not open.
[store-003] - RegistrationService - Could not register. Sleeping for 7000ms before attempting again.
[store-003] - RegistrationService - This node is unregistered. It will attempt to register using the registration.url
[store-003] - DataLoaderService - Using registration URL of http://localhost:31000/sync/corp-000/registration?nodeGroupId=store&externalId=003&syncURL=http%3A%2F%2Flocalhost%3A31030%2Fsync%2Fstore-003&schemaVersion=%3F&databaseType=H2&databaseVersion=1.3&symmetricVersion=3.9.13&deploymentType=professional&hostName=turing-2.local&ipAddress=192.168.42.103
[store-003] - RegistrationService - Waiting for registration to be accepted by the server. Registration is not open.
[store-003] - RegistrationService - Could not register. Sleeping for 26000ms before attempting again.



[store-003] - StatisticFlushJob - Did not run the 'Stat Flush' job because the engine is not registered.
[store-003] - FileSyncTrackerJob - Did not run the 'File Sync Tracker' job because the engine is not registered.
[store-003] - FileSyncTrackerJob - Exception while executing job 'File Sync Tracker'
java.lang.NullPointerException
    at org.jumpmind.symmetric.service.impl.FileSyncService.trackChanges(FileSyncService.java:150)
    at org.jumpmind.symmetric.job.FileSyncTrackerJob.doJob(FileSyncTrackerJob.java:49)
    at org.jumpmind.symmetric.job.AbstractJob.invoke(AbstractJob.java:226)
    at org.jumpmind.symmetric.job.AbstractJob.run(AbstractJob.java:297)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
[store-003] - RegistrationService - This node is unregistered. It will attempt to register using the registration.url
[store-003] - DataLoaderService - Using registration URL of http://localhost:31000/sync/corp-000/registration?nodeGroupId=store&externalId=003&syncURL=http%3A%2F%2Flocalhost%3A31030%2Fsync%2Fstore-003&schemaVersion=%3F&databaseType=H2&databaseVersion=1.3&symmetricVersion=3.9.13&deploymentType=professional&hostName=turing-2.local&ipAddress=192.168.42.103

Related Changesets

SymmetricDS: 3.9 4da2a5de

2018-10-29 15:20:06

mmichalek

Details Diff 		0003540: Registration gets lost during the registration when File Sync is enabled Affected Issues
0003540
mod - symmetric-core/src/main/java/org/jumpmind/symmetric/service/impl/FileSyncService.java Diff File

Issue History

Date Modified Username Field Change
2018-05-03 19:01 woehrl01 New Issue
2018-05-03 19:05 woehrl01 Note Added: 0001172
2018-09-19 18:18 hanes Note Added: 0001243
2018-09-19 18:19 hanes Status new => confirmed
2018-09-19 18:36 hanes Note Added: 0001244
2018-09-19 18:36 hanes Priority normal => high
2018-09-19 18:36 hanes Steps to Reproduce Updated View Revisions
2018-09-19 18:39 hanes Steps to Reproduce Updated View Revisions
2018-10-03 16:53 hanes Summary Registration gets lost during the registration => Registration gets lost during the registration when File Sync is enabled
2018-10-03 17:25 hanes Target Version => 3.9.15
2018-10-29 18:28 mmichalek Assigned To => mmichalek
2018-10-29 18:28 mmichalek Status confirmed => assigned
2018-10-29 19:20 mmichalek Status assigned => resolved
2018-10-29 19:20 mmichalek Resolution open => fixed
2018-10-29 19:20 mmichalek Fixed in Version => 3.9.15
2018-10-29 20:00 mmichalek Changeset attached => SymmetricDS 3.9 4da2a5de
2018-10-31 18:59 mmichalek Status resolved => closed