2019-01-03 18:08:25,751 INFO [startup] [SymmetricUtils] [main] _____ __ _ ____ _____ / ___/ __ _____ __ ___ __ ___ _/ /_ ____(_)___ / __ | / ___/ \__ \ / / / / _ `_ \/ _ `_ \/ _ \/_ __// __/ / __/ / / / / \__ \ ___/ // /_/ / // // / // // / __// / / / / / /_ / /_/ / ___/ / /____/ \__ /_//_//_/_//_//_/\___/ \_/ /_/ /_/\__/ /_____/ /____/ /____/ +-----------------------------------------------------------------+ | Copyright (C) 2007-2018 JumpMind, Inc. | | | | Licensed under the GNU General Public License version 3. | | This software comes with ABSOLUTELY NO WARRANTY. | | See http://www.gnu.org/licenses/gpl.html | +-----------------------------------------------------------------+ 2019-01-03 18:08:25,812 INFO [startup] [SymmetricWebServer] [main] About to start SymmetricDS web server on host:port 0.0.0.0:31415 2019-01-03 18:08:26,686 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] Initializing connection to database 2019-01-03 18:08:26,686 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] Initializing connection to database 2019-01-03 18:08:27,059 INFO [zol-000] [JdbcDatabasePlatformFactory] [symmetric-engine-startup-2] Detected database 'Microsoft SQL Server', version '14', protocol 'jtds' 2019-01-03 18:08:27,089 INFO [zol-000] [JdbcDatabasePlatformFactory] [symmetric-engine-startup-2] The IDatabasePlatform being used is org.jumpmind.db.platform.mssql.MsSql2008DatabasePlatform 2019-01-03 18:08:27,431 INFO [zol-000] [MsSqlSymmetricDialect] [symmetric-engine-startup-2] The DbDialect being used is org.jumpmind.symmetric.db.mssql.MsSqlSymmetricDialect 2019-01-03 18:08:27,669 INFO [zol-000] [ExtensionService] [symmetric-engine-startup-2] Found 0 extension points from the database that will be registered 2019-01-03 18:08:27,679 INFO [zol-000] [StagingManager] [symmetric-engine-startup-2] The staging directory was initialized at the following location: C:\Downloads\symmetric-server-3.9.16\tmp\zol-000 2019-01-03 18:08:27,981 INFO [zapaonline-001] [JdbcDatabasePlatformFactory] [symmetric-engine-startup-1] Detected database 'PostgreSQL', version '9', protocol 'postgresql' 2019-01-03 18:08:27,995 INFO [zapaonline-001] [JdbcDatabasePlatformFactory] [symmetric-engine-startup-1] The IDatabasePlatform being used is org.jumpmind.db.platform.postgresql.PostgreSqlDatabasePlatform 2019-01-03 18:08:28,067 INFO [zapaonline-001] [PostgreSqlSymmetricDialect] [symmetric-engine-startup-1] The DbDialect being used is org.jumpmind.symmetric.db.postgresql.PostgreSqlSymmetricDialect 2019-01-03 18:08:28,107 INFO [zapaonline-001] [ExtensionService] [symmetric-engine-startup-1] Found 0 extension points from the database that will be registered 2019-01-03 18:08:28,108 INFO [zapaonline-001] [StagingManager] [symmetric-engine-startup-1] The staging directory was initialized at the following location: C:\Downloads\symmetric-server-3.9.16\tmp\zapaonline-001 2019-01-03 18:08:28,736 INFO [zapaonline-001] [ExtensionService] [symmetric-engine-startup-1] Found 0 extension points from the database that will be registered 2019-01-03 18:08:28,737 INFO [zapaonline-001] [ClientExtensionService] [symmetric-engine-startup-1] Found 7 extension points from spring that will be registered 2019-01-03 18:08:28,751 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] Initializing SymmetricDS database 2019-01-03 18:08:28,752 INFO [zapaonline-001] [PostgreSqlSymmetricDialect] [symmetric-engine-startup-1] Checking if SymmetricDS tables need created or altered 2019-01-03 18:08:30,255 INFO [startup] [SymmetricWebServer] [main] Starting JMX HTTP console on port 31416 2019-01-03 18:08:30,294 INFO [startup] [SymmetricWebServer] [main] Joining the web server main thread 2019-01-03 18:08:30,303 INFO [zol-000] [ExtensionService] [symmetric-engine-startup-2] Found 0 extension points from the database that will be registered 2019-01-03 18:08:30,307 INFO [zol-000] [ClientExtensionService] [symmetric-engine-startup-2] Found 7 extension points from spring that will be registered 2019-01-03 18:08:30,706 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] Initializing SymmetricDS database 2019-01-03 18:08:30,709 INFO [zol-000] [MsSqlSymmetricDialect] [symmetric-engine-startup-2] Checking if SymmetricDS tables need created or altered 2019-01-03 18:08:30,999 INFO [zapaonline-001] [PostgreSqlSymmetricDialect] [symmetric-engine-startup-1] There are SymmetricDS tables that needed altered 2019-01-03 18:08:31,017 INFO [zapaonline-001] [PostgreSqlSymmetricDialect] [symmetric-engine-startup-1] DDL applied: ALTER TABLE "public"."sym_sequence" ALTER COLUMN "max_value" SET DEFAULT 9999999999 2019-01-03 18:08:31,713 INFO [zapaonline-001] [DataLoaderService] [symmetric-engine-startup-1] Requesting current configuration {symmetricVersion=3.9.16, configVersion=null} 2019-01-03 18:08:31,777 INFO [zol-000] [SymmetricServlet] [qtp973576304-18] Requests for engine zol-000 are being rejected while it is starting 2019-01-03 18:08:31,792 INFO [zapaonline-001] [PullService] [symmetric-engine-startup-1] Remote node null:null:? at http://localhost:31415/sync/zol-000 was unavailable. It may be starting up. 2019-01-03 18:08:31,796 INFO [zapaonline-001] [PostgreSqlSymmetricDialect] [symmetric-engine-startup-1] Done with auto update of SymmetricDS tables 2019-01-03 18:08:31,839 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] Done initializing SymmetricDS database 2019-01-03 18:08:31,840 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] SymmetricDS database version : null 2019-01-03 18:08:31,842 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] SymmetricDS software version : 3.9.16 2019-01-03 18:08:31,876 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] Starting registered node [group=zapaonline, id=001, nodeId=001] 2019-01-03 18:08:31,880 INFO [zapaonline-001] [ClusterService] [symmetric-engine-startup-1] This node picked a server id of LPZWPL000001098 2019-01-03 18:08:31,881 INFO [zapaonline-001] [TriggerRouterService] [symmetric-engine-startup-1] Synchronizing triggers 2019-01-03 18:08:32,972 INFO [zapaonline-001] [TriggerRouterService] [symmetric-engine-startup-1] Done synchronizing triggers 2019-01-03 18:08:32,973 INFO [zapaonline-001] [PushHeartbeatListener] [symmetric-engine-startup-1] Some attribute(s) of node changed. Recording changes 2019-01-03 18:08:32,975 INFO [zapaonline-001] [PushHeartbeatListener] [symmetric-engine-startup-1] Updating my node configuration info according to the symmetric properties 2019-01-03 18:08:33,573 INFO [zapaonline-001] [DataLoaderService] [symmetric-engine-startup-1] Requesting current configuration {symmetricVersion=3.9.16, configVersion=null} 2019-01-03 18:08:33,580 INFO [zapaonline-001] [PullService] [symmetric-engine-startup-1] Remote node null:null:? at http://localhost:31415/sync/zol-000 was unavailable. It may be starting up. 2019-01-03 18:08:33,607 INFO [zapaonline-001] [RouterJob] [symmetric-engine-startup-1] Starting Routing on periodic schedule: every 5000ms with the first run at Thu Jan 03 18:08:40 CET 2019 2019-01-03 18:08:33,613 INFO [zapaonline-001] [PushJob] [symmetric-engine-startup-1] Starting Push on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:40 CET 2019 2019-01-03 18:08:33,618 INFO [zapaonline-001] [PullJob] [symmetric-engine-startup-1] Starting Pull on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:40 CET 2019 2019-01-03 18:08:33,620 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job Offline Push not configured for auto start 2019-01-03 18:08:33,622 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job Offline Pull not configured for auto start 2019-01-03 18:08:33,627 INFO [zapaonline-001] [OutgoingPurgeJob] [symmetric-engine-startup-1] Starting job 'Purge Outgoing' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:33,630 INFO [zapaonline-001] [IncomingPurgeJob] [symmetric-engine-startup-1] Starting job 'Purge Incoming' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:33,632 INFO [zapaonline-001] [StatisticFlushJob] [symmetric-engine-startup-1] Starting job 'Stat Flush' with cron expression: '0 0/5 * * * *' 2019-01-03 18:08:33,634 INFO [zapaonline-001] [SyncTriggersJob] [symmetric-engine-startup-1] Starting job 'SyncTriggers' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:33,638 INFO [zapaonline-001] [HeartbeatJob] [symmetric-engine-startup-1] Starting Heartbeat on periodic schedule: every 900000ms with the first run at Thu Jan 03 18:08:41 CET 2019 2019-01-03 18:08:33,640 INFO [zapaonline-001] [WatchdogJob] [symmetric-engine-startup-1] Starting Watchdog on periodic schedule: every 3600000ms with the first run at Thu Jan 03 18:08:41 CET 2019 2019-01-03 18:08:33,643 INFO [zapaonline-001] [StageManagementJob] [symmetric-engine-startup-1] Starting job 'Stage Management' with cron expression: '0 0 * * * *' 2019-01-03 18:08:33,646 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job Refresh Cache not configured for auto start 2019-01-03 18:08:33,647 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job File Sync Tracker not configured for auto start 2019-01-03 18:08:33,648 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job File Sync Pull not configured for auto start 2019-01-03 18:08:33,650 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job File Sync Push not configured for auto start 2019-01-03 18:08:33,652 INFO [zapaonline-001] [InitialLoadExtractorJob] [symmetric-engine-startup-1] Starting Initial Load Extract on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:41 CET 2019 2019-01-03 18:08:33,655 INFO [zapaonline-001] [MonitorJob] [symmetric-engine-startup-1] Starting Monitor on periodic schedule: every 60000ms with the first run at Thu Jan 03 18:08:41 CET 2019 2019-01-03 18:08:33,658 INFO [zapaonline-001] [JobManager] [symmetric-engine-startup-1] Job Report Status not configured for auto start 2019-01-03 18:08:33,663 INFO [zapaonline-001] [AbstractSymmetricEngine] [symmetric-engine-startup-1] SymmetricDS Node STARTED: nodeId=001 groupId=zapaonline type=server subType=null name=zapaonline-001 softwareVersion=3.9.16 databaseName=PostgreSQL databaseVersion=9.6 driverName=PostgreSQL JDBC Driver driverVersion=42.2.1 uptime=0 sec. 2019-01-03 18:08:33,917 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] Done initializing SymmetricDS database 2019-01-03 18:08:33,918 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] SymmetricDS database version : null 2019-01-03 18:08:33,919 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] SymmetricDS software version : 3.9.16 2019-01-03 18:08:33,949 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] Starting registered node [group=zol, id=000, nodeId=000] 2019-01-03 18:08:33,950 INFO [zol-000] [ClusterService] [symmetric-engine-startup-2] This node picked a server id of LPZWPL000001098 2019-01-03 18:08:33,952 INFO [zol-000] [TriggerRouterService] [symmetric-engine-startup-2] Synchronizing triggers 2019-01-03 18:08:35,384 INFO [zol-000] [TriggerRouterService] [symmetric-engine-startup-2] Done synchronizing triggers 2019-01-03 18:08:35,385 INFO [zol-000] [PushHeartbeatListener] [symmetric-engine-startup-2] Some attribute(s) of node changed. Recording changes 2019-01-03 18:08:35,387 INFO [zol-000] [PushHeartbeatListener] [symmetric-engine-startup-2] Updating my node configuration info according to the symmetric properties 2019-01-03 18:08:35,797 INFO [zol-000] [RouterJob] [symmetric-engine-startup-2] Starting Routing on periodic schedule: every 5000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,800 INFO [zol-000] [PushJob] [symmetric-engine-startup-2] Starting Push on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,803 INFO [zol-000] [PullJob] [symmetric-engine-startup-2] Starting Pull on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,806 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job Offline Push not configured for auto start 2019-01-03 18:08:35,807 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job Offline Pull not configured for auto start 2019-01-03 18:08:35,809 INFO [zol-000] [OutgoingPurgeJob] [symmetric-engine-startup-2] Starting job 'Purge Outgoing' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:35,811 INFO [zol-000] [IncomingPurgeJob] [symmetric-engine-startup-2] Starting job 'Purge Incoming' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:35,814 INFO [zol-000] [StatisticFlushJob] [symmetric-engine-startup-2] Starting job 'Stat Flush' with cron expression: '0 0/5 * * * *' 2019-01-03 18:08:35,816 INFO [zol-000] [SyncTriggersJob] [symmetric-engine-startup-2] Starting job 'SyncTriggers' with cron expression: '0 0 0 * * *' 2019-01-03 18:08:35,818 INFO [zol-000] [HeartbeatJob] [symmetric-engine-startup-2] Starting Heartbeat on periodic schedule: every 900000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,821 INFO [zol-000] [WatchdogJob] [symmetric-engine-startup-2] Starting Watchdog on periodic schedule: every 3600000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,824 INFO [zol-000] [StageManagementJob] [symmetric-engine-startup-2] Starting job 'Stage Management' with cron expression: '0 0 * * * *' 2019-01-03 18:08:35,826 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job Refresh Cache not configured for auto start 2019-01-03 18:08:35,827 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job File Sync Tracker not configured for auto start 2019-01-03 18:08:35,828 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job File Sync Pull not configured for auto start 2019-01-03 18:08:35,830 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job File Sync Push not configured for auto start 2019-01-03 18:08:35,832 INFO [zol-000] [InitialLoadExtractorJob] [symmetric-engine-startup-2] Starting Initial Load Extract on periodic schedule: every 10000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,834 INFO [zol-000] [MonitorJob] [symmetric-engine-startup-2] Starting Monitor on periodic schedule: every 60000ms with the first run at Thu Jan 03 18:08:45 CET 2019 2019-01-03 18:08:35,839 INFO [zol-000] [JobManager] [symmetric-engine-startup-2] Job Report Status not configured for auto start 2019-01-03 18:08:35,841 INFO [zol-000] [AbstractSymmetricEngine] [symmetric-engine-startup-2] SymmetricDS Node STARTED: nodeId=000 groupId=zol type=server subType=null name=zol-000 softwareVersion=3.9.16 databaseName=Microsoft SQL Server databaseVersion=14.0 driverName=jTDS Type 4 JDBC Driver for MS SQL Server and Sybase driverVersion=1.2.8 uptime=0 sec. 2019-01-03 18:08:41,005 INFO [zapaonline-001] [DataGapFastDetector] [zapaonline-001-job-1] Full gap analysis is running 2019-01-03 18:08:41,014 INFO [zapaonline-001] [NodeCommunicationService] [zapaonline-001-job-2] push will use 10 threads 2019-01-03 18:08:41,020 INFO [zapaonline-001] [DataGapFastDetector] [zapaonline-001-job-1] Querying data in gaps from database took 13 ms 2019-01-03 18:08:41,030 INFO [zapaonline-001] [NodeCommunicationService] [zapaonline-001-job-3] pull will use 10 threads 2019-01-03 18:08:41,030 INFO [zapaonline-001] [DataGapFastDetector] [zapaonline-001-job-1] Full gap analysis is done after 23 ms 2019-01-03 18:08:41,084 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-1] The 'config' channel is NOT in common batch mode 2019-01-03 18:08:41,311 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-1] About to refresh the cache of nodes because new configuration came through the data router 2019-01-03 18:08:41,315 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-1] The 'heartbeat' channel is NOT in common batch mode 2019-01-03 18:08:41,393 INFO [zol-000] [RegistrationService] [qtp973576304-16] Completed registration of node zapaonline:001:001 2019-01-03 18:08:41,399 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-1] Routed 2 data events in 395 ms 2019-01-03 18:08:41,449 INFO [zol-000] [MsSqlSymmetricDialect] [qtp973576304-16] This database DOES support disabling triggers during a symmetricds data load 2019-01-03 18:08:43,888 INFO [zapaonline-001] [DataService] [zapaonline-001-dataloader-1] Deleted 43 data rows that were on the config channel 2019-01-03 18:08:44,664 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] Grouplets flushed because new grouplet config came through the data loader 2019-01-03 18:08:44,666 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] Load filters flushed because new filter config came through the data loader 2019-01-03 18:08:44,668 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] Channels flushed because new channels came through the data loader 2019-01-03 18:08:44,671 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] About to refresh the cache of conflict settings because new configuration came through the data loader 2019-01-03 18:08:44,673 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] About to refresh the cache of parameters because new configuration came through the data loader 2019-01-03 18:08:44,687 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-1] About to refresh the cache of node security because new configuration came through the data loader 2019-01-03 18:08:44,691 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-pull-default-1] About to refresh the cache of transformation because new configuration came through the data loader 2019-01-03 18:08:44,692 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-pull-default-1] About to clear the staging area because new transform configuration came through the data loader 2019-01-03 18:08:44,696 INFO [zapaonline-001] [StagingManager] [zapaonline-001-pull-default-1] Cleaning staging... 2019-01-03 18:08:44,710 INFO [zapaonline-001] [StagingManager] [zapaonline-001-pull-default-1] Purged 9 staging files, freed 816 KB of disk space. 2019-01-03 18:08:44,712 INFO [zapaonline-001] [StagingManager] [zapaonline-001-pull-default-1] Finished cleaning staging in 0 seconds. 2019-01-03 18:08:44,713 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-pull-default-1] About to syncTriggers because new configuration came through the data loader 2019-01-03 18:08:44,716 INFO [zapaonline-001] [TriggerRouterService] [zapaonline-001-pull-default-1] Synchronizing triggers 2019-01-03 18:08:45,306 INFO [zapaonline-001] [TriggerRouterService] [zapaonline-001-pull-default-1] Done synchronizing triggers 2019-01-03 18:08:45,326 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-1] Pull data received from zol:000:000 on queue default. 48 rows and 1 batches were processed. (sym_job, sym_notification, sym_monitor, sym_extension, sym_node_identity, sym_file_trigger_router, sym_file_trigger, sym_trigger_router_grouplet, sym_grouplet_link, sym_grouplet, sym_table_reload_request, sym_conflict, sym_transform_column, sym_load_filter, sym_transform_table, sym_trigger_router, sym_router, sym_trigger, sym_node_group_channel_wnd, sym_channel, sym_parameter, sym_node_security, sym_node_host, sym_node, sym_node_group_link, sym_node_group) 2019-01-03 18:08:45,333 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-1] Immediate pull requested while in reload mode 2019-01-03 18:08:45,510 INFO [zol-000] [DataExtractorService] [zol-000-dataextractor-1] Batch 001-15 is marked as ready but it has been deleted. Rescheduling it for extraction 2019-01-03 18:08:45,524 INFO [zol-000] [PullUriHandler] [qtp973576304-15] 1 data and 1 batches sent during pull request from zapaonline:001:001 2019-01-03 18:08:45,554 INFO [zapaonline-001] [IncomingBatchService] [zapaonline-001-dataloader-2] Retrying batch 000-14 2019-01-03 18:08:45,556 INFO [zol-000] [NodeCommunicationService] [zol-000-job-3] pull will use 10 threads 2019-01-03 18:08:45,612 INFO [zapaonline-001] [DefaultDatabaseWriter] [zapaonline-001-dataloader-2] About to create table using the following definition:
2019-01-03 18:08:45,693 INFO [zapaonline-001] [PostgreSqlDatabasePlatform] [zapaonline-001-dataloader-2] Running alter sql: CREATE TABLE "rightsholder_invoice"( "rightsholder_invoice_id" INTEGER NOT NULL, "rightsholder_invoice_datetime" TIMESTAMP NOT NULL, "rightsholder_id" INTEGER NOT NULL, "number" VARCHAR(128) NOT NULL, "income_date" VARCHAR(10) NOT NULL, "invoice_date" VARCHAR(10) NOT NULL, "sale_date" VARCHAR(10) NOT NULL, "rightsholder_invoice_type_id" INTEGER NOT NULL, "status_description" VARCHAR(128), "comment" TEXT, "correcting_rightsholder_invoice_id" INTEGER, "guid" CHAR(36) DEFAULT 'newid()' NOT NULL, "last_update_date_time" TIMESTAMP NOT NULL, PRIMARY KEY ("rightsholder_invoice_id") ); CREATE INDEX "IDX_rightsholder" ON "rightsholder_invoice" ("rightsholder_id"); CREATE INDEX "IDX_rightsholder_invoice_type" ON "rightsholder_invoice" ("rightsholder_invoice_type_id"); 2019-01-03 18:08:45,715 INFO [zol-000] [NodeCommunicationService] [zol-000-job-2] extract will use 20 threads 2019-01-03 18:08:45,800 INFO [zol-000] [DataService] [zol-000-job-1] Queueing up an initial load to node 001 2019-01-03 18:08:45,808 INFO [zol-000] [DataExtractorService] [zol-000-extract-default-1] Extracting batches for request 3. Starting at batch 15. Ending at batch 15 2019-01-03 18:08:45,917 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-1] Pull data received from zol:000:000 on queue default. 1 rows and 1 batches were processed. (sym_job, sym_notification, sym_monitor, sym_extension, sym_node_identity, sym_file_trigger_router, sym_file_trigger, sym_trigger_router_grouplet, sym_grouplet_link, sym_grouplet, sym_table_reload_request, sym_conflict, sym_transform_column, sym_load_filter, sym_transform_table, sym_trigger_router, sym_router, sym_trigger, sym_node_group_channel_wnd, sym_channel, sym_parameter, sym_node_security, sym_node_host, sym_node, sym_node_group_link, sym_node_group, rightsholder_invoice) 2019-01-03 18:08:45,932 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-1] Immediate pull requested while in reload mode 2019-01-03 18:08:46,903 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-1] Channels flushed because new channels came through the data router 2019-01-03 18:08:46,909 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-1] About to refresh the cache of nodes because new configuration came through the data router 2019-01-03 18:08:46,912 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-1] About to refresh the cache of node security because new configuration came through the data router 2019-01-03 18:08:46,917 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-1] About to refresh the cache of node group link because new configuration came through the data router 2019-01-03 18:08:46,986 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-1] Routed 45 data events in 573 ms 2019-01-03 18:08:47,032 INFO [zol-000] [PurgeService] [zol-000-job-1] Purged all 1 incoming batch for node 001 2019-01-03 18:08:47,033 INFO [zol-000] [RouterService] [zol-000-job-1] Inserted reload events for node 001 in 1274 ms 2019-01-03 18:08:47,072 INFO [zol-000] [DataGapFastDetector] [zol-000-job-1] Full gap analysis is running 2019-01-03 18:08:47,126 INFO [zol-000] [DataGapFastDetector] [zol-000-job-1] Querying data in gaps from database took 39 ms 2019-01-03 18:08:47,155 INFO [zol-000] [DataGapFastDetector] [zol-000-job-1] Full gap analysis is done after 68 ms 2019-01-03 18:08:47,191 INFO [zol-000] [RouterService] [zol-000-job-1] The 'config' channel is NOT in common batch mode 2019-01-03 18:08:47,474 INFO [zol-000] [DataExtractorService] [zol-000-extract-default-1] Done extracting 1 batches for request 3 2019-01-03 18:08:47,595 INFO [zol-000] [ConfigurationChangedDataRouter] [zol-000-job-1] Channels flushed because new channels came through the data router 2019-01-03 18:08:47,597 INFO [zol-000] [ConfigurationChangedDataRouter] [zol-000-job-1] About to syncTriggers because new configuration came through the data router 2019-01-03 18:08:47,600 INFO [zol-000] [TriggerRouterService] [zol-000-job-1] Synchronizing triggers 2019-01-03 18:08:49,096 INFO [zol-000] [TriggerRouterService] [zol-000-job-1] Done synchronizing triggers 2019-01-03 18:08:49,097 INFO [zol-000] [ConfigurationChangedDataRouter] [zol-000-job-1] About to refresh the cache of nodes because new configuration came through the data router 2019-01-03 18:08:49,098 INFO [zol-000] [ConfigurationChangedDataRouter] [zol-000-job-1] About to refresh the cache of node security because new configuration came through the data router 2019-01-03 18:08:49,101 INFO [zol-000] [ConfigurationChangedDataRouter] [zol-000-job-1] About to refresh the cache of node group link because new configuration came through the data router 2019-01-03 18:08:49,112 INFO [zol-000] [RouterService] [zol-000-job-1] The 'heartbeat' channel is NOT in common batch mode 2019-01-03 18:08:49,182 INFO [zol-000] [RouterService] [zol-000-job-1] Routed 65 data events in 2111 ms 2019-01-03 18:08:51,132 INFO [zapaonline-001] [PushService] [zapaonline-001-push-default-2] Push data sent to zol:000:000 2019-01-03 18:08:51,210 INFO [zol-000] [DataLoaderService] [qtp973576304-13] 2 data and 2 batches loaded during push request from zapaonline:001:001. 2019-01-03 18:08:51,227 INFO [zapaonline-001] [PushService] [zapaonline-001-push-default-2] Pushed data to node zol:000:000. 2 data and 2 batches were processed. (sym_node_host) 2019-01-03 18:08:51,710 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-3] Channels flushed because new channels came through the data loader 2019-01-03 18:08:51,715 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-3] About to refresh the cache of node security because new configuration came through the data loader 2019-01-03 18:08:51,720 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-3] About to refresh the cache of nodes because new configuration came through the data loader 2019-01-03 18:08:51,771 INFO [zol-000] [DataExtractorService] [zol-000-dataextractor-2] Batch 001-25 is not ready for delivery. It is currently scheduled for extraction 2019-01-03 18:08:51,800 INFO [zol-000] [PullUriHandler] [qtp973576304-16] 4087 data and 5 batches sent during pull request from zapaonline:001:001 2019-01-03 18:08:52,085 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-7] Channels flushed because new channels came through the data router 2019-01-03 18:08:52,086 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-7] About to refresh the cache of nodes because new configuration came through the data router 2019-01-03 18:08:52,091 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-7] About to refresh the cache of node security because new configuration came through the data router 2019-01-03 18:08:52,097 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-7] About to refresh the cache of node group link because new configuration came through the data router 2019-01-03 18:08:52,104 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-7] Routed 46 data events in 92 ms 2019-01-03 18:08:53,179 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-3] About to refresh the cache of node security because new configuration came through the data loader 2019-01-03 18:08:53,189 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-3] About to refresh the cache of nodes because new configuration came through the data loader 2019-01-03 18:08:53,203 INFO [zapaonline-001] [DefaultDatabaseWriter] [zapaonline-001-dataloader-3] About to create table using the following definition:
2019-01-03 18:08:53,294 INFO [zapaonline-001] [PostgreSqlDatabasePlatform] [zapaonline-001-dataloader-3] Tables up to date. No alters found for rightsholder_invoice 2019-01-03 18:08:53,298 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-pull-default-2] About to syncTriggers because new configuration came through the data loader 2019-01-03 18:08:53,300 INFO [zapaonline-001] [TriggerRouterService] [zapaonline-001-pull-default-2] Synchronizing triggers 2019-01-03 18:08:53,943 INFO [zapaonline-001] [TriggerRouterService] [zapaonline-001-pull-default-2] Done synchronizing triggers 2019-01-03 18:08:54,034 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-2] Pull data received from zol:000:000 on queue default. 4087 rows and 5 batches were processed. (sym_trigger_router, sym_trigger, sym_router, sym_channel, sym_node_group_link, sym_node_group, sym_node, sym_node_security, rightsholder_invoice) 2019-01-03 18:08:54,037 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-2] Immediate pull requested while in reload mode 2019-01-03 18:08:54,045 INFO [zol-000] [DataExtractorService] [zol-000-dataextractor-3] Batch 001-25 is not ready for delivery. It is currently scheduled for extraction 2019-01-03 18:08:54,245 INFO [zol-000] [RouterService] [zol-000-job-7] Routed 2 data events in 42 ms 2019-01-03 18:08:55,757 INFO [zol-000] [DataExtractorService] [zol-000-extract-default-2] Extracting batches for request 4. Starting at batch 25. Ending at batch 25 2019-01-03 18:08:56,396 INFO [zol-000] [DataExtractorService] [zol-000-extract-default-2] Done extracting 1 batches for request 4 2019-01-03 18:08:57,157 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-7] About to refresh the cache of node security because new configuration came through the data router 2019-01-03 18:08:57,158 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-7] Routed 1 data events in 45 ms 2019-01-03 18:09:01,273 INFO [zol-000] [PullUriHandler] [qtp973576304-15] 4039 data and 2 batches sent during pull request from zapaonline:001:001 2019-01-03 18:09:03,641 INFO [zapaonline-001] [ConfigurationChangedDatabaseWriterFilter] [zapaonline-001-dataloader-4] About to refresh the cache of node security because new configuration came through the data loader 2019-01-03 18:09:03,698 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-3] Pull data received from zol:000:000 on queue default. 4039 rows and 2 batches were processed. (rightsholder_invoice, sym_node_security) 2019-01-03 18:09:03,732 INFO [zol-000] [PullUriHandler] [qtp973576304-13] 2 data and 1 batches sent during pull request from zapaonline:001:001 2019-01-03 18:09:03,801 INFO [zapaonline-001] [PullService] [zapaonline-001-pull-default-3] Pull data received from zol:000:000 on queue default. 2 rows and 1 batches were processed. (rightsholder_invoice, sym_node_security, sym_node_host) 2019-01-03 18:09:07,188 INFO [zapaonline-001] [ConfigurationChangedDataRouter] [zapaonline-001-job-6] About to refresh the cache of node security because new configuration came through the data router 2019-01-03 18:09:09,256 INFO [zapaonline-001] [RouterService] [zapaonline-001-job-6] Routed 3 data events in 2087 ms 2019-01-03 18:10:49,821 INFO [zol-000] [RouterService] [zol-000-job-5] The 'zol_to_zapaonline' channel is in common batch mode 2019-01-03 18:10:49,821 INFO [zol-000] [RouterService] [zol-000-job-5] The 'zol_to_zapaonline' channel for the 'zol' node group has only default routers assigned to it. Change data won't be selected during routing 2019-01-03 18:10:50,168 INFO [zol-000] [RouterService] [zol-000-job-5] Routed 3815 data events in 378 ms 2019-01-03 18:10:51,776 INFO [zol-000] [PullUriHandler] [qtp973576304-13] 3815 data and 1 batches sent during pull request from zapaonline:001:001 2019-01-03 18:10:51,796 INFO [zapaonline-001] [DefaultDatabaseWriter] [zapaonline-001-dataloader-6] Failed to process update event in batch 000-32 on channel 'zol_to_zapaonline'. Failed sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = 1, "rightsholder_invoice_datetime" = {ts '2012-12-05 12:24:17.433'}, "rightsholder_id" = 5982, "number" = '11/2012', "income_date" = '2012-11-16', "invoice_date" = '2012-11-09', "sale_date" = '2012-11-09', "rightsholder_invoice_type_id" = 1, "status_description" = 'Zaakceptowana', "comment" = 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', "correcting_rightsholder_invoice_id" = null, "guid" = 'EE49EA84-105E-435B-9D79-06558EBEA744', "last_update_date_time" = {ts '2018-11-06 14:43:39.606'} where "rightsholder_invoice_id" = 4285 Failed raw sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = ?, "rightsholder_invoice_datetime" = ?, "rightsholder_id" = ?, "number" = ?, "income_date" = ?, "invoice_date" = ?, "sale_date" = ?, "rightsholder_invoice_type_id" = ?, "status_description" = ?, "comment" = ?, "correcting_rightsholder_invoice_id" = ?, "guid" = ?, "last_update_date_time" = ? where "rightsholder_invoice_id" = ? Failed sql parameters: [1, {ts '2012-12-05 12:24:17.433'}, 5982, '11/2012', '2012-11-16', '2012-11-09', '2012-11-09', 1, 'Zaakceptowana', 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', null, 'EE49EA84-105E-435B-9D79-06558EBEA744', {ts '2018-11-06 14:43:39.606'}, 4285] Failed sql parameters types: [INTEGER, TIMESTAMP, INTEGER, VARCHAR, VARCHAR, VARCHAR, VARCHAR, INTEGER, VARCHAR, LONGVARCHAR, INTEGER, CHAR, TIMESTAMP, INTEGER] Failed sql state and code: 23505 (0) Failed pk data was: "4285" Failed row data was: "1","2012-12-05 12:24:17.433","5982","11/2012","2012-11-16","2012-11-09","2012-11-09","1","Zaakceptowana","wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg",,"EE49EA84-105E-435B-9D79-06558EBEA744","2018-11-06 14:43:39.6066667" Failed old data was: "4285","2018-10-26 14:29:28.987","1469","12/2018","2018-10-26","2018-10-15","2018-10-15","1","Zaakceptowana",,,"0A16CC16-1216-4C59-A3EE-6521517E52F2","2018-11-06 14:43:39.6066667" StackTraceKey.init [UniqueKeyException:2026926579] org.jumpmind.db.sql.UniqueKeyException: org.postgresql.util.PSQLException: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey" Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje. at org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:296) at org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:291) at org.jumpmind.db.sql.JdbcSqlTransaction.addRow(JdbcSqlTransaction.java:466) at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.execute(DefaultDatabaseWriter.java:904) at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.update(DefaultDatabaseWriter.java:488) at org.jumpmind.symmetric.io.data.writer.AbstractDatabaseWriter.write(AbstractDatabaseWriter.java:188) at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64) at org.jumpmind.symmetric.model.ProcessInfoDataWriter.write(ProcessInfoDataWriter.java:84) at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64) at org.jumpmind.symmetric.io.data.writer.TransformWriter.write(TransformWriter.java:201) at org.jumpmind.symmetric.io.data.DataProcessor.forEachDataInTable(DataProcessor.java:210) at org.jumpmind.symmetric.io.data.DataProcessor.forEachTableInBatch(DataProcessor.java:177) at org.jumpmind.symmetric.io.data.DataProcessor.process(DataProcessor.java:123) at org.jumpmind.symmetric.service.impl.DataLoaderService$LoadIntoDatabaseOnArrivalListener$2.call(DataLoaderService.java:1039) at org.jumpmind.symmetric.service.impl.DataLoaderService$LoadIntoDatabaseOnArrivalListener$2.call(DataLoaderService.java:1016) at java.util.concurrent.FutureTask.run(FutureTask.java:266) 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) Caused by: org.postgresql.util.PSQLException: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey" Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje. at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2422) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2167) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306) at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155) at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.jumpmind.db.sql.JdbcSqlTransaction.executePreparedUpdate(JdbcSqlTransaction.java:485) at org.jumpmind.db.sql.JdbcSqlTransaction.addRow(JdbcSqlTransaction.java:463) ... 16 more 2019-01-03 18:10:51,820 ERROR [zapaonline-001] [ManageIncomingBatchListener] [zapaonline-001-dataloader-6] Failed to load batch 000-32 StackTraceKey [UniqueKeyException:2026926579] 2019-01-03 18:10:51,878 ERROR [zol-000] [AcknowledgeService] [qtp973576304-16] The outgoing batch 001-32 failed: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey" Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje. 2019-01-03 18:11:01,716 INFO [zol-000] [PullUriHandler] [qtp973576304-14] 3815 data and 1 batches sent during pull request from zapaonline:001:001 2019-01-03 18:11:01,749 INFO [zapaonline-001] [IncomingBatchService] [zapaonline-001-dataloader-7] Retrying batch 000-32 2019-01-03 18:11:01,762 INFO [zapaonline-001] [DefaultDatabaseWriter] [zapaonline-001-dataloader-7] Failed to process update event in batch 000-32 on channel 'zol_to_zapaonline'. Failed sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = 1, "rightsholder_invoice_datetime" = {ts '2012-12-05 12:24:17.433'}, "rightsholder_id" = 5982, "number" = '11/2012', "income_date" = '2012-11-16', "invoice_date" = '2012-11-09', "sale_date" = '2012-11-09', "rightsholder_invoice_type_id" = 1, "status_description" = 'Zaakceptowana', "comment" = 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', "correcting_rightsholder_invoice_id" = null, "guid" = 'EE49EA84-105E-435B-9D79-06558EBEA744', "last_update_date_time" = {ts '2018-11-06 14:43:39.606'} where "rightsholder_invoice_id" = 4285 Failed raw sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = ?, "rightsholder_invoice_datetime" = ?, "rightsholder_id" = ?, "number" = ?, "income_date" = ?, "invoice_date" = ?, "sale_date" = ?, "rightsholder_invoice_type_id" = ?, "status_description" = ?, "comment" = ?, "correcting_rightsholder_invoice_id" = ?, "guid" = ?, "last_update_date_time" = ? where "rightsholder_invoice_id" = ? Failed sql parameters: [1, {ts '2012-12-05 12:24:17.433'}, 5982, '11/2012', '2012-11-16', '2012-11-09', '2012-11-09', 1, 'Zaakceptowana', 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', null, 'EE49EA84-105E-435B-9D79-06558EBEA744', {ts '2018-11-06 14:43:39.606'}, 4285] Failed sql parameters types: [INTEGER, TIMESTAMP, INTEGER, VARCHAR, VARCHAR, VARCHAR, VARCHAR, INTEGER, VARCHAR, LONGVARCHAR, INTEGER, CHAR, TIMESTAMP, INTEGER] Failed sql state and code: 23505 (0) Failed pk data was: "4285" Failed row data was: "1","2012-12-05 12:24:17.433","5982","11/2012","2012-11-16","2012-11-09","2012-11-09","1","Zaakceptowana","wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg",,"EE49EA84-105E-435B-9D79-06558EBEA744","2018-11-06 14:43:39.6066667" Failed old data was: "4285","2018-10-26 14:29:28.987","1469","12/2018","2018-10-26","2018-10-15","2018-10-15","1","Zaakceptowana",,,"0A16CC16-1216-4C59-A3EE-6521517E52F2","2018-11-06 14:43:39.6066667" StackTraceKey [UniqueKeyException:2026926579] 2019-01-03 18:11:01,827 ERROR [zapaonline-001] [ManageIncomingBatchListener] [zapaonline-001-dataloader-7] Failed to load batch 000-32 StackTraceKey [UniqueKeyException:2026926579] 2019-01-03 18:11:02,058 ERROR [zol-000] [AcknowledgeService] [qtp973576304-13] The outgoing batch 001-32 failed: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey" Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje.