search

enonic / xp

Enonic XP
https://enonic.com
GNU General Public License v3.0
202 stars 34 forks source link

On cluster creation ScheduleTaskOperation runs multiple times #8873

Closed gbbirkisson closed 3 years ago

gbbirkisson commented 3 years ago

In clustered mode, when cluster is first created you get errors on all but one node:

2021-06-03 13:59:16,160 ERROR c.h.s.i.o.ScheduleTaskOperation - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] There is already a task with the same name 'rescheduleTask' in 'scheduler'
com.hazelcast.scheduledexecutor.DuplicateTaskException: There is already a task with the same name 'rescheduleTask' in 'scheduler'
    at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.checkNotDuplicateTask(ScheduledExecutorContainer.java:331)
    at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.schedule(ScheduledExecutorContainer.java:91)
    at com.hazelcast.scheduledexecutor.impl.operations.ScheduleTaskOperation.run(ScheduleTaskOperation.java:45)
    at com.hazelcast.spi.Operation.call(Operation.java:170)
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:210)
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:199)
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:412)
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:153)
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:123)
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.run(OperationThread.java:110)

Full logs from cluster:

node3_1  |                          _____
node3_1  | ____________________________(_)______   ____  _________
node3_1  | _  _ \_  __ \  __ \_  __ \_  /_  ___/   __  |/_/__  __ \
node3_1  | /  __/  / / / /_/ /  / / /  / / /__     __>  < __  /_/ /
node3_1  | \___//_/ /_/\____//_/ /_//_/  \___/     /_/|_| _  .___/
node3_1  |                                                /_/
node3_1  | 
node3_1  | # Enonic XP 7.7.0-B2
node3_1  | # Built on 2021-05-21T13:27:56Z (hash = 4e94ea3811b47e8f2f1c17c4e2b08004bc368355, branch = 7.7)
node3_1  | # OpenJDK 64-Bit Server VM 11.0.11 (AdoptOpenJDK)
node3_1  | # Linux 5.4.118-1-MANJARO (amd64)
node3_1  | # Install directory is /enonic-xp
node3_1  | # Home directory is /enonic-xp/home
node3_1  | 
node2_1  |                          _____
node2_1  | ____________________________(_)______   ____  _________
node2_1  | _  _ \_  __ \  __ \_  __ \_  /_  ___/   __  |/_/__  __ \
node2_1  | /  __/  / / / /_/ /  / / /  / / /__     __>  < __  /_/ /
node2_1  | \___//_/ /_/\____//_/ /_//_/  \___/     /_/|_| _  .___/
node2_1  |                                                /_/
node2_1  | 
node2_1  | # Enonic XP 7.7.0-B2
node2_1  | # Built on 2021-05-21T13:27:56Z (hash = 4e94ea3811b47e8f2f1c17c4e2b08004bc368355, branch = 7.7)
node2_1  | # OpenJDK 64-Bit Server VM 11.0.11 (AdoptOpenJDK)
node2_1  | # Linux 5.4.118-1-MANJARO (amd64)
node2_1  | # Install directory is /enonic-xp
node2_1  | # Home directory is /enonic-xp/home
node2_1  | 
node1_1  |                          _____
node1_1  | ____________________________(_)______   ____  _________
node1_1  | _  _ \_  __ \  __ \_  __ \_  /_  ___/   __  |/_/__  __ \
node1_1  | /  __/  / / / /_/ /  / / /  / / /__     __>  < __  /_/ /
node1_1  | \___//_/ /_/\____//_/ /_//_/  \___/     /_/|_| _  .___/
node1_1  |                                                /_/
node1_1  | 
node1_1  | # Enonic XP 7.7.0-B2
node1_1  | # Built on 2021-05-21T13:27:56Z (hash = 4e94ea3811b47e8f2f1c17c4e2b08004bc368355, branch = 7.7)
node1_1  | # OpenJDK 64-Bit Server VM 11.0.11 (AdoptOpenJDK)
node1_1  | # Linux 5.4.118-1-MANJARO (amd64)
node1_1  | # Install directory is /enonic-xp
node1_1  | # Home directory is /enonic-xp/home
node1_1  | 
node3_1  | 2021-06-03 13:58:31,581 INFO  c.e.x.l.i.framework.FrameworkService - Starting Enonic XP...
node2_1  | 2021-06-03 13:58:31,817 INFO  c.e.x.l.i.framework.FrameworkService - Starting Enonic XP...
node1_1  | 2021-06-03 13:58:31,861 INFO  c.e.x.l.i.framework.FrameworkService - Starting Enonic XP...
node3_1  | 2021-06-03 13:58:31,972 INFO  c.e.x.l.i.p.ProvisionActivator - Installing 94 bundles...
node1_1  | 2021-06-03 13:58:32,195 INFO  c.e.x.l.i.p.ProvisionActivator - Installing 94 bundles...
node2_1  | 2021-06-03 13:58:32,215 INFO  c.e.x.l.i.p.ProvisionActivator - Installing 94 bundles...
node3_1  | 2021-06-03 13:58:33,305 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10) Starting with globalExtender setting: false
node3_1  | 2021-06-03 13:58:33,316 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10)  Version = 2.1.26
node1_1  | 2021-06-03 13:58:33,635 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10) Starting with globalExtender setting: false
node2_1  | 2021-06-03 13:58:33,652 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10) Starting with globalExtender setting: false
node1_1  | 2021-06-03 13:58:33,667 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10)  Version = 2.1.26
node2_1  | 2021-06-03 13:58:33,667 INFO  ROOT - bundle org.apache.felix.scr:2.1.26 (10)  Version = 2.1.26
node3_1  | 2021-06-03 13:58:34,411 INFO  c.h.osgi.HazelcastOSGiService - HazelcastOSGiServiceImpl{ownerBundle=com.hazelcast [21], hazelcastInstance=null, active=false, id=3.12.12#OSS} has been registered as OSGI service and activated now
node2_1  | 2021-06-03 13:58:34,915 INFO  c.h.osgi.HazelcastOSGiService - HazelcastOSGiServiceImpl{ownerBundle=com.hazelcast [21], hazelcastInstance=null, active=false, id=3.12.12#OSS} has been registered as OSGI service and activated now
node1_1  | 2021-06-03 13:58:35,370 INFO  c.h.osgi.HazelcastOSGiService - HazelcastOSGiServiceImpl{ownerBundle=com.hazelcast [21], hazelcastInstance=null, active=false, id=3.12.12#OSS} has been registered as OSGI service and activated now
node3_1  | 2021-06-03 13:58:36,092 WARN  org.apache.tika.parsers.PDFParser - TIFFImageWriter not loaded. tiff files will not be processed
node3_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node3_1  | for optional dependencies.
node3_1  | J2KImageReader not loaded. JPEG2000 files will not be processed.
node3_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node3_1  | for optional dependencies.
node3_1  | 
node3_1  | 2021-06-03 13:58:36,323 WARN  org.apache.tika.parser.SQLite3Parser - org.xerial's sqlite-jdbc is not loaded.
node3_1  | Please provide the jar on your classpath to parse sqlite files.
node3_1  | See tika-parsers/pom.xml for the correct version.
node2_1  | 2021-06-03 13:58:36,479 WARN  org.apache.tika.parsers.PDFParser - TIFFImageWriter not loaded. tiff files will not be processed
node2_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node2_1  | for optional dependencies.
node2_1  | J2KImageReader not loaded. JPEG2000 files will not be processed.
node2_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node2_1  | for optional dependencies.
node2_1  | 
node1_1  | 2021-06-03 13:58:36,574 WARN  org.apache.tika.parsers.PDFParser - TIFFImageWriter not loaded. tiff files will not be processed
node1_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node1_1  | for optional dependencies.
node1_1  | J2KImageReader not loaded. JPEG2000 files will not be processed.
node1_1  | See https://pdfbox.apache.org/2.0/dependencies.html#jai-image-io
node1_1  | for optional dependencies.
node1_1  | 
node2_1  | 2021-06-03 13:58:36,583 WARN  org.apache.tika.parser.SQLite3Parser - org.xerial's sqlite-jdbc is not loaded.
node2_1  | Please provide the jar on your classpath to parse sqlite files.
node2_1  | See tika-parsers/pom.xml for the correct version.
node3_1  | 2021-06-03 13:58:36,696 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.cluster]
node3_1  | 2021-06-03 13:58:36,701 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.hazelcast]
node3_1  | 2021-06-03 13:58:36,705 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.app.main]
node3_1  | 2021-06-03 13:58:36,714 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.elasticsearch]
node3_1  | 2021-06-03 13:58:36,747 INFO  c.e.x.s.shell.impl.ShellActivator - Remote shell access is disabled
node1_1  | 2021-06-03 13:58:36,794 WARN  org.apache.tika.parser.SQLite3Parser - org.xerial's sqlite-jdbc is not loaded.
node1_1  | Please provide the jar on your classpath to parse sqlite files.
node1_1  | See tika-parsers/pom.xml for the correct version.
node2_1  | 2021-06-03 13:58:36,959 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.cluster]
node2_1  | 2021-06-03 13:58:36,966 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.hazelcast]
node2_1  | 2021-06-03 13:58:36,971 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.app.main]
node2_1  | 2021-06-03 13:58:36,978 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.elasticsearch]
node2_1  | 2021-06-03 13:58:37,010 INFO  c.e.x.s.shell.impl.ShellActivator - Remote shell access is disabled
node3_1  | 2021-06-03 13:58:37,068 INFO  c.e.x.s.internal.trace.TraceService - Call tracing is disabled in config
node1_1  | 2021-06-03 13:58:37,146 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.cluster]
node1_1  | 2021-06-03 13:58:37,154 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.hazelcast]
node1_1  | 2021-06-03 13:58:37,163 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.app.main]
node1_1  | 2021-06-03 13:58:37,168 INFO  c.e.x.s.i.config.ConfigInstallerImpl - Loaded config for [com.enonic.xp.elasticsearch]
node1_1  | 2021-06-03 13:58:37,207 INFO  c.e.x.s.shell.impl.ShellActivator - Remote shell access is disabled
node3_1  | 2021-06-03 13:58:37,244 INFO  c.e.x.c.i.a.c.AuditLogConfigImpl - Audit log is enabled and mappings updated.
node3_1  | 2021-06-03 13:58:37,311 INFO  c.e.x.i.blobstore.BlobStoreActivator - Waiting for blobstore-provider [file]
node3_1  | 2021-06-03 13:58:37,314 INFO  c.e.x.i.blobstore.BlobStoreActivator - Found blobstore-provider [file]
node3_1  | 2021-06-03 13:58:37,340 INFO  c.e.x.i.blobstore.BlobStoreActivator - Registered blobstore [file] successfully
node2_1  | 2021-06-03 13:58:37,360 INFO  c.e.x.s.internal.trace.TraceService - Call tracing is disabled in config
node1_1  | 2021-06-03 13:58:37,726 INFO  c.e.x.s.internal.trace.TraceService - Call tracing is disabled in config
node2_1  | 2021-06-03 13:58:37,750 INFO  c.e.x.c.i.a.c.AuditLogConfigImpl - Audit log is enabled and mappings updated.
node2_1  | 2021-06-03 13:58:37,868 INFO  c.e.x.i.blobstore.BlobStoreActivator - Waiting for blobstore-provider [file]
node2_1  | 2021-06-03 13:58:37,869 INFO  c.e.x.i.blobstore.BlobStoreActivator - Found blobstore-provider [file]
node2_1  | 2021-06-03 13:58:37,954 INFO  c.e.x.i.blobstore.BlobStoreActivator - Registered blobstore [file] successfully
node1_1  | 2021-06-03 13:58:38,184 INFO  c.e.x.c.i.a.c.AuditLogConfigImpl - Audit log is enabled and mappings updated.
node1_1  | 2021-06-03 13:58:38,263 INFO  c.e.x.i.blobstore.BlobStoreActivator - Waiting for blobstore-provider [file]
node1_1  | 2021-06-03 13:58:38,267 INFO  c.e.x.i.blobstore.BlobStoreActivator - Found blobstore-provider [file]
node1_1  | 2021-06-03 13:58:38,334 INFO  c.e.x.i.blobstore.BlobStoreActivator - Registered blobstore [file] successfully
node3_1  | 2021-06-03 13:58:38,606 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Interfaces is enabled, trying to pick one address matching to one of: [192.123.0.13, 192.123.0.13]
node3_1  | 2021-06-03 13:58:38,606 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Prefer IPv4 stack is true, prefer IPv6 addresses is false
node3_1  | 2021-06-03 13:58:38,629 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Picked [192.123.0.13]:5701, using socket ServerSocket[addr=/0.0.0.0,localport=5701], bind any local is true
node3_1  | 2021-06-03 13:58:38,682 INFO  com.hazelcast.system - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Hazelcast 3.12.12 (20210209 - 35096ec) starting at [192.123.0.13]:5701
node3_1  | 2021-06-03 13:58:38,682 INFO  com.hazelcast.system - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Copyright (c) 2008-2020, Hazelcast, Inc. All Rights Reserved.
node3_1  | 2021-06-03 13:58:39,296 INFO  c.h.s.i.o.impl.BackpressureRegulator - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Backpressure is disabled
node1_1  | 2021-06-03 13:58:39,716 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Interfaces is enabled, trying to pick one address matching to one of: [192.123.0.11, 192.123.0.11]
node1_1  | 2021-06-03 13:58:39,716 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Prefer IPv4 stack is true, prefer IPv6 addresses is false
node2_1  | 2021-06-03 13:58:39,717 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Interfaces is enabled, trying to pick one address matching to one of: [192.123.0.12, 192.123.0.12]
node2_1  | 2021-06-03 13:58:39,718 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Prefer IPv4 stack is true, prefer IPv6 addresses is false
node1_1  | 2021-06-03 13:58:39,734 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Picked [192.123.0.11]:5701, using socket ServerSocket[addr=/0.0.0.0,localport=5701], bind any local is true
node2_1  | 2021-06-03 13:58:39,741 INFO  com.hazelcast.instance.AddressPicker - [LOCAL] [3.12.12#OSS] [3.12.12] Picked [192.123.0.12]:5701, using socket ServerSocket[addr=/0.0.0.0,localport=5701], bind any local is true
node1_1  | 2021-06-03 13:58:39,766 INFO  com.hazelcast.system - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Hazelcast 3.12.12 (20210209 - 35096ec) starting at [192.123.0.11]:5701
node1_1  | 2021-06-03 13:58:39,767 INFO  com.hazelcast.system - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Copyright (c) 2008-2020, Hazelcast, Inc. All Rights Reserved.
node2_1  | 2021-06-03 13:58:39,776 INFO  com.hazelcast.system - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Hazelcast 3.12.12 (20210209 - 35096ec) starting at [192.123.0.12]:5701
node2_1  | 2021-06-03 13:58:39,776 INFO  com.hazelcast.system - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Copyright (c) 2008-2020, Hazelcast, Inc. All Rights Reserved.
node3_1  | 2021-06-03 13:58:40,097 INFO  com.hazelcast.instance.Node - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Creating TcpIpJoiner
node1_1  | 2021-06-03 13:58:40,206 INFO  c.h.s.i.o.impl.BackpressureRegulator - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Backpressure is disabled
node2_1  | 2021-06-03 13:58:40,336 INFO  c.h.s.i.o.impl.BackpressureRegulator - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Backpressure is disabled
node3_1  | 2021-06-03 13:58:40,496 INFO  c.h.s.i.o.impl.OperationExecutorImpl - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Starting 8 partition threads and 5 generic threads (1 dedicated for priority tasks)
node3_1  | 2021-06-03 13:58:40,545 INFO  c.h.internal.diagnostics.Diagnostics - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
node3_1  | 2021-06-03 13:58:40,556 INFO  com.hazelcast.core.LifecycleService - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.13]:5701 is STARTING
node3_1  | 2021-06-03 13:58:40,646 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.12:5701, timeout: 10000, bind-any: true
node3_1  | 2021-06-03 13:58:40,648 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.11:5701, timeout: 10000, bind-any: true
node1_1  | 2021-06-03 13:58:41,010 INFO  com.hazelcast.instance.Node - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Creating TcpIpJoiner
node2_1  | 2021-06-03 13:58:41,102 INFO  com.hazelcast.instance.Node - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Creating TcpIpJoiner
node1_1  | 2021-06-03 13:58:41,382 INFO  c.h.s.i.o.impl.OperationExecutorImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Starting 8 partition threads and 5 generic threads (1 dedicated for priority tasks)
node1_1  | 2021-06-03 13:58:41,426 INFO  c.h.internal.diagnostics.Diagnostics - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
node1_1  | 2021-06-03 13:58:41,439 INFO  com.hazelcast.core.LifecycleService - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.11]:5701 is STARTING
node2_1  | 2021-06-03 13:58:41,481 INFO  c.h.s.i.o.impl.OperationExecutorImpl - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Starting 8 partition threads and 5 generic threads (1 dedicated for priority tasks)
node2_1  | 2021-06-03 13:58:41,494 INFO  c.h.internal.diagnostics.Diagnostics - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
node2_1  | 2021-06-03 13:58:41,506 INFO  com.hazelcast.core.LifecycleService - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.12]:5701 is STARTING
node1_1  | 2021-06-03 13:58:41,532 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.12:5701, timeout: 10000, bind-any: true
node1_1  | 2021-06-03 13:58:41,539 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.13:5701, timeout: 10000, bind-any: true
node1_1  | 2021-06-03 13:58:41,573 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.11:5701 and /192.123.0.13:44323
node3_1  | 2021-06-03 13:58:41,582 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.13:44323 and /192.123.0.11:5701
node3_1  | 2021-06-03 13:58:41,587 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.13:5701 and /192.123.0.11:58137
node1_1  | 2021-06-03 13:58:41,590 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.11:58137 and /192.123.0.13:5701
node2_1  | 2021-06-03 13:58:41,595 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.13:5701, timeout: 10000, bind-any: true
node2_1  | 2021-06-03 13:58:41,622 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.12:5701 and /192.123.0.13:41267
node2_1  | 2021-06-03 13:58:41,625 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.12:5701 and /192.123.0.11:54383
node3_1  | 2021-06-03 13:58:41,629 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.13:41267 and /192.123.0.12:5701
node1_1  | 2021-06-03 13:58:41,631 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.11:54383 and /192.123.0.12:5701
node3_1  | 2021-06-03 13:58:41,633 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.13:5701 and /192.123.0.12:43923
node2_1  | 2021-06-03 13:58:41,639 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.12:43923 and /192.123.0.13:5701
node2_1  | 2021-06-03 13:58:41,648 INFO  com.hazelcast.nio.tcp.TcpIpConnector - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Connecting to /192.123.0.11:5701, timeout: 10000, bind-any: true
node1_1  | 2021-06-03 13:58:41,655 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.11:5701 and /192.123.0.12:55043
node2_1  | 2021-06-03 13:58:41,661 INFO  c.hazelcast.nio.tcp.TcpIpConnection - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] Initialized new cluster connection between /192.123.0.12:55043 and /192.123.0.11:5701
node1_1  | 2021-06-03 13:58:46,551 INFO  c.h.internal.cluster.ClusterService - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] 
node1_1  | 
node1_1  | Members {size:1, ver:1} [
node1_1  |  Member [192.123.0.11]:5701 - 26c870e3-29bb-45eb-a6d2-8efd7e837ea5 this
node1_1  | ]
node1_1  | 
node1_1  | 2021-06-03 13:58:46,565 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:46,572 INFO  c.h.i.diagnostics.HealthMonitor - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] processors=8, physical.memory.total=23.2G, physical.memory.free=1.5G, swap.space.total=0, swap.space.free=0, heap.memory.used=71.6M, heap.memory.free=375.4M, heap.memory.total=447.0M, heap.memory.max=5.8G, heap.memory.used/total=15.92%, heap.memory.used/max=1.20%, minor.gc.count=0, minor.gc.time=0ms, major.gc.count=0, major.gc.time=0ms, load.process=60.00%, load.system=66.67%, load.systemAverage=3.75, thread.count=73, thread.peakCount=73, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=10, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=0, clientEndpoint.count=0, connection.active.count=4, client.connection.count=0, connection.count=2
node1_1  | 2021-06-03 13:58:47,565 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:48,566 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:49,567 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:50,568 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:51,569 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:52,570 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:52,658 INFO  c.h.internal.cluster.ClusterService - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] 
node1_1  | 
node1_1  | Members {size:3, ver:3} [
node1_1  |  Member [192.123.0.11]:5701 - 26c870e3-29bb-45eb-a6d2-8efd7e837ea5 this
node1_1  |  Member [192.123.0.12]:5701 - e0ca000e-4a10-42b4-ab8e-b9a18e2f4c15
node1_1  |  Member [192.123.0.13]:5701 - a1360911-b8e2-4cd0-a70b-820be2277662
node1_1  | ]
node1_1  | 
node2_1  | 2021-06-03 13:58:52,665 INFO  c.h.internal.cluster.ClusterService - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] 
node2_1  | 
node2_1  | Members {size:3, ver:3} [
node2_1  |  Member [192.123.0.11]:5701 - 26c870e3-29bb-45eb-a6d2-8efd7e837ea5
node2_1  |  Member [192.123.0.12]:5701 - e0ca000e-4a10-42b4-ab8e-b9a18e2f4c15 this
node2_1  |  Member [192.123.0.13]:5701 - a1360911-b8e2-4cd0-a70b-820be2277662
node2_1  | ]
node2_1  | 
node3_1  | 2021-06-03 13:58:52,665 INFO  c.h.internal.cluster.ClusterService - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] 
node3_1  | 
node3_1  | Members {size:3, ver:3} [
node3_1  |  Member [192.123.0.11]:5701 - 26c870e3-29bb-45eb-a6d2-8efd7e837ea5
node3_1  |  Member [192.123.0.12]:5701 - e0ca000e-4a10-42b4-ab8e-b9a18e2f4c15
node3_1  |  Member [192.123.0.13]:5701 - a1360911-b8e2-4cd0-a70b-820be2277662 this
node3_1  | ]
node3_1  | 
node1_1  | 2021-06-03 13:58:53,572 INFO  c.h.i.p.impl.PartitionStateManager - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] Initializing cluster partition table arrangement...
node1_1  | 2021-06-03 13:58:53,609 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance starting after waiting for cluster size of 2
node1_1  | 2021-06-03 13:58:53,609 INFO  com.hazelcast.core.LifecycleService - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.11]:5701 is STARTED
node2_1  | 2021-06-03 13:58:53,709 INFO  c.h.i.diagnostics.HealthMonitor - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] processors=8, physical.memory.total=23.2G, physical.memory.free=1.5G, swap.space.total=0, swap.space.free=0, heap.memory.used=72.5M, heap.memory.free=403.5M, heap.memory.total=476.0M, heap.memory.max=5.8G, heap.memory.used/total=15.14%, heap.memory.used/max=1.22%, minor.gc.count=0, minor.gc.time=0ms, major.gc.count=0, major.gc.time=0ms, load.process=28.57%, load.system=100.00%, load.systemAverage=3.25, thread.count=78, thread.peakCount=78, cluster.timeDiff=-7, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=25, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=0, clientEndpoint.count=0, connection.active.count=4, client.connection.count=0, connection.count=2
node1_1  | 2021-06-03 13:58:53,844 INFO  org.elasticsearch.node - [node1] version[2.4.6], pid[1], build[NA/NA]
node1_1  | 2021-06-03 13:58:53,844 INFO  org.elasticsearch.node - [node1] initializing ...
node1_1  | 2021-06-03 13:58:53,847 INFO  org.elasticsearch.plugins - [node1] modules [], plugins [], sites []
node1_1  | 2021-06-03 13:58:53,859 INFO  org.elasticsearch.env - [node1] using [1] data paths, mounts [[/enonic-xp/home/repo/index (/dev/nvme0n1p5)]], net usable_space [38.8gb], net total_space [233.1gb], spins? [possibly], types [ext4]
node1_1  | 2021-06-03 13:58:53,859 INFO  org.elasticsearch.env - [node1] heap size [5.7gb], compressed ordinary object pointers [true]
node1_1  | 2021-06-03 13:58:54,149 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.system bundle 89
node1_1  | 2021-06-03 13:58:54,161 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.applications bundle 91
node1_1  | 2021-06-03 13:58:54,171 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.main bundle 92
node1_1  | 2021-06-03 13:58:54,181 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.standardidprovider bundle 93
node1_1  | 2021-06-03 13:58:54,187 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.users bundle 94
node1_1  | 2021-06-03 13:58:54,189 INFO  E.F.org.apache.felix.framework - FrameworkEvent STARTLEVEL CHANGED
node1_1  | 2021-06-03 13:58:54,189 INFO  c.e.x.l.i.framework.FrameworkService - Started Enonic XP in 22333 ms
node1_1  | 2021-06-03 13:58:54,876 INFO  org.elasticsearch.node - [node1] initialized
node1_1  | 2021-06-03 13:58:54,876 INFO  org.elasticsearch.node - [node1] starting ...
node1_1  | 2021-06-03 13:58:54,927 INFO  org.elasticsearch.transport - [node1] publish_address {192.123.0.11:9300}, bound_addresses {192.123.0.11:9300}
node1_1  | 2021-06-03 13:58:54,930 INFO  org.elasticsearch.discovery - [node1] mycluster/2rrUvx8ZS7eTs4BZv_vyng
node3_1  | 2021-06-03 13:58:56,699 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance starting after waiting for cluster size of 2
node3_1  | 2021-06-03 13:58:56,700 INFO  com.hazelcast.core.LifecycleService - [192.123.0.13]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.13]:5701 is STARTED
node2_1  | 2021-06-03 13:58:56,703 INFO  c.h.instance.HazelcastInstanceImpl - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] HazelcastInstance starting after waiting for cluster size of 2
node2_1  | 2021-06-03 13:58:56,703 INFO  com.hazelcast.core.LifecycleService - [192.123.0.12]:5701 [3.12.12#OSS] [3.12.12] [192.123.0.12]:5701 is STARTED
node2_1  | 2021-06-03 13:58:57,006 INFO  org.elasticsearch.node - [node2] version[2.4.6], pid[1], build[NA/NA]
node2_1  | 2021-06-03 13:58:57,007 INFO  org.elasticsearch.node - [node2] initializing ...
node2_1  | 2021-06-03 13:58:57,011 INFO  org.elasticsearch.plugins - [node2] modules [], plugins [], sites []
node2_1  | 2021-06-03 13:58:57,077 INFO  org.elasticsearch.env - [node2] using [1] data paths, mounts [[/enonic-xp/home/repo/index (/dev/nvme0n1p5)]], net usable_space [38.8gb], net total_space [233.1gb], spins? [possibly], types [ext4]
node2_1  | 2021-06-03 13:58:57,077 INFO  org.elasticsearch.env - [node2] heap size [5.7gb], compressed ordinary object pointers [true]
node3_1  | 2021-06-03 13:58:57,092 INFO  org.elasticsearch.node - [node3] version[2.4.6], pid[1], build[NA/NA]
node3_1  | 2021-06-03 13:58:57,093 INFO  org.elasticsearch.node - [node3] initializing ...
node3_1  | 2021-06-03 13:58:57,107 INFO  org.elasticsearch.plugins - [node3] modules [], plugins [], sites []
node3_1  | 2021-06-03 13:58:57,201 INFO  org.elasticsearch.env - [node3] using [1] data paths, mounts [[/enonic-xp/home/repo/index (/dev/nvme0n1p5)]], net usable_space [38.8gb], net total_space [233.1gb], spins? [possibly], types [ext4]
node3_1  | 2021-06-03 13:58:57,204 INFO  org.elasticsearch.env - [node3] heap size [5.7gb], compressed ordinary object pointers [true]
node2_1  | 2021-06-03 13:58:57,789 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.system bundle 89
node2_1  | 2021-06-03 13:58:57,816 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.applications bundle 91
node2_1  | 2021-06-03 13:58:57,854 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.main bundle 92
node2_1  | 2021-06-03 13:58:57,860 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.standardidprovider bundle 93
node2_1  | 2021-06-03 13:58:57,863 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.users bundle 94
node2_1  | 2021-06-03 13:58:57,864 INFO  E.F.org.apache.felix.framework - FrameworkEvent STARTLEVEL CHANGED
node2_1  | 2021-06-03 13:58:57,864 INFO  c.e.x.l.i.framework.FrameworkService - Started Enonic XP in 26049 ms
node3_1  | 2021-06-03 13:58:57,939 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.system bundle 89
node3_1  | 2021-06-03 13:58:57,973 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.applications bundle 91
node3_1  | 2021-06-03 13:58:58,002 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.main bundle 92
node3_1  | 2021-06-03 13:58:58,012 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.standardidprovider bundle 93
node3_1  | 2021-06-03 13:58:58,020 INFO  c.e.x.c.i.a.ApplicationRegistryImpl - Registering configured application com.enonic.xp.app.users bundle 94
node3_1  | 2021-06-03 13:58:58,021 INFO  E.F.org.apache.felix.framework - FrameworkEvent STARTLEVEL CHANGED
node3_1  | 2021-06-03 13:58:58,022 INFO  c.e.x.l.i.framework.FrameworkService - Started Enonic XP in 26443 ms
node2_1  | 2021-06-03 13:58:58,874 INFO  org.elasticsearch.node - [node2] initialized
node2_1  | 2021-06-03 13:58:58,874 INFO  org.elasticsearch.node - [node2] starting ...
node3_1  | 2021-06-03 13:58:58,894 INFO  org.elasticsearch.node - [node3] initialized
node3_1  | 2021-06-03 13:58:58,895 INFO  org.elasticsearch.node - [node3] starting ...
node2_1  | 2021-06-03 13:58:58,931 INFO  org.elasticsearch.transport - [node2] publish_address {192.123.0.12:9300}, bound_addresses {192.123.0.12:9300}
node2_1  | 2021-06-03 13:58:58,934 INFO  org.elasticsearch.discovery - [node2] mycluster/S4ik9zIBTYGdbvRvGEl2fw
node3_1  | 2021-06-03 13:58:58,959 INFO  org.elasticsearch.transport - [node3] publish_address {192.123.0.13:9300}, bound_addresses {192.123.0.13:9300}
node3_1  | 2021-06-03 13:58:58,962 INFO  org.elasticsearch.discovery - [node3] mycluster/0lIX_ICnTPibQkRoUIovwg
node3_1  | 2021-06-03 13:59:02,009 INFO  org.elasticsearch.cluster.service - [node3] new_master {node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}, added {{node1}{2rrUvx8ZS7eTs4BZv_vyng}{192.123.0.11}{192.123.0.11:9300}{local=false, master=true},}, reason: zen-disco-join(elected_as_master, [1] joins received)
node1_1  | 2021-06-03 13:59:02,025 INFO  org.elasticsearch.cluster.service - [node1] detected_master {node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}, added {{node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true},}, reason: zen-disco-receive(from master [{node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}])
node1_1  | 2021-06-03 13:59:02,040 INFO  org.elasticsearch.http - [node1] publish_address {192.123.0.11:9200}, bound_addresses {192.123.0.11:9200}
node1_1  | 2021-06-03 13:59:02,040 INFO  org.elasticsearch.node - [node1] started
node3_1  | 2021-06-03 13:59:02,042 INFO  org.elasticsearch.gateway - [node3] delaying initial state recovery for [5m]. expecting [3] nodes, but only have [2]
node3_1  | 2021-06-03 13:59:02,043 INFO  org.elasticsearch.cluster.service - [node3] added {{node2}{S4ik9zIBTYGdbvRvGEl2fw}{192.123.0.12}{192.123.0.12:9300}{local=false, master=true},}, reason: zen-disco-join(pending joins after accumulation stop [election closed])
node2_1  | 2021-06-03 13:59:02,056 INFO  org.elasticsearch.cluster.service - [node2] detected_master {node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}, added {{node1}{2rrUvx8ZS7eTs4BZv_vyng}{192.123.0.11}{192.123.0.11:9300}{local=false, master=true},{node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true},}, reason: zen-disco-receive(from master [{node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}])
node3_1  | 2021-06-03 13:59:02,057 INFO  org.elasticsearch.http - [node3] publish_address {192.123.0.13:9200}, bound_addresses {192.123.0.13:9200}
node3_1  | 2021-06-03 13:59:02,057 INFO  org.elasticsearch.node - [node3] started
node1_1  | 2021-06-03 13:59:02,058 INFO  org.elasticsearch.cluster.service - [node1] added {{node2}{S4ik9zIBTYGdbvRvGEl2fw}{192.123.0.12}{192.123.0.12:9300}{local=false, master=true},}, reason: zen-disco-receive(from master [{node3}{0lIX_ICnTPibQkRoUIovwg}{192.123.0.13}{192.123.0.13:9300}{local=false, master=true}])
node2_1  | 2021-06-03 13:59:02,103 INFO  org.elasticsearch.http - [node2] publish_address {192.123.0.12:9200}, bound_addresses {192.123.0.12:9200}
node2_1  | 2021-06-03 13:59:02,103 INFO  org.elasticsearch.node - [node2] started
node3_1  | 2021-06-03 13:59:02,177 INFO  org.elasticsearch.gateway - [node3] recovered [0] indices into cluster_state
node3_1  | 2021-06-03 13:59:02,258 INFO  com.enonic.xp.init.Initializer - Initializing System-repo
node1_1  | 2021-06-03 13:59:02,301 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:02,303 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index search-system-repo
node2_1  | 2021-06-03 13:59:02,351 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:02,446 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:02,663 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index search-system-repo created with status true
node3_1  | 2021-06-03 13:59:02,664 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index storage-system-repo
node3_1  | 2021-06-03 13:59:02,677 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system-repo] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:02,852 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index storage-system-repo created with status true
node3_1  | 2021-06-03 13:59:02,858 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index search-system-repo
node3_1  | 2021-06-03 13:59:02,982 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[storage-system-repo][0]] ...]).
node3_1  | 2021-06-03 13:59:03,068 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] create_mapping [_default_]
node3_1  | 2021-06-03 13:59:03,159 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index search-system-repo applied
node3_1  | 2021-06-03 13:59:03,160 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system-repo
node3_1  | 2021-06-03 13:59:03,160 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[storage-system-repo][0], [search-system-repo][0], [storage-system-repo][0], [search-system-repo][0]] ...]).
node3_1  | 2021-06-03 13:59:03,193 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system-repo] create_mapping [branch]
node3_1  | 2021-06-03 13:59:03,247 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system-repo applied
node3_1  | 2021-06-03 13:59:03,248 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system-repo
node3_1  | 2021-06-03 13:59:03,264 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system-repo] create_mapping [version]
node3_1  | 2021-06-03 13:59:03,289 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system-repo applied
node3_1  | 2021-06-03 13:59:03,290 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system-repo
node3_1  | 2021-06-03 13:59:03,302 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system-repo] create_mapping [commit]
node1_1  | 2021-06-03 13:59:03,327 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:03,330 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system-repo applied
node2_1  | 2021-06-03 13:59:03,385 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:03,737 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] create_mapping [master]
node3_1  | 2021-06-03 13:59:04,026 INFO  c.e.x.r.i.r.RepositoryServiceImpl - Created root node with id [000-000-000-000] in repository [system-repo]
node3_1  | 2021-06-03 13:59:04,096 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node3_1  | 2021-06-03 13:59:04,326 INFO  com.enonic.xp.init.Initializer - System-repo successfully initialized
node3_1  | 2021-06-03 13:59:04,385 INFO  com.enonic.xp.init.Initializer - Initializing system.auditlog repo
node3_1  | 2021-06-03 13:59:04,403 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index search-system.auditlog
node3_1  | 2021-06-03 13:59:04,454 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.auditlog] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:04,589 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index search-system.auditlog created with status true
node3_1  | 2021-06-03 13:59:04,591 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[search-system.auditlog][0]] ...]).
node3_1  | 2021-06-03 13:59:04,592 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index storage-system.auditlog
node3_1  | 2021-06-03 13:59:04,724 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.auditlog] creating index, cause [api], templates [], shards [1]/[1], mappings []
node1_1  | 2021-06-03 13:59:04,824 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:04,831 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index storage-system.auditlog created with status true
node3_1  | 2021-06-03 13:59:04,834 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[search-system.auditlog][0], [search-system.auditlog][0], [storage-system.auditlog][0]] ...]).
node3_1  | 2021-06-03 13:59:04,834 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index search-system.auditlog
node3_1  | 2021-06-03 13:59:04,942 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.auditlog] create_mapping [_default_]
node2_1  | 2021-06-03 13:59:04,989 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo to be initialized
node3_1  | 2021-06-03 13:59:05,006 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index search-system.auditlog applied
node3_1  | 2021-06-03 13:59:05,007 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.auditlog
node3_1  | 2021-06-03 13:59:05,011 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[storage-system.auditlog][0], [storage-system.auditlog][0]] ...]).
node3_1  | 2021-06-03 13:59:05,079 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.auditlog] create_mapping [branch]
node3_1  | 2021-06-03 13:59:05,113 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.auditlog applied
node3_1  | 2021-06-03 13:59:05,116 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.auditlog
node3_1  | 2021-06-03 13:59:05,142 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.auditlog] create_mapping [version]
node3_1  | 2021-06-03 13:59:05,175 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.auditlog applied
node3_1  | 2021-06-03 13:59:05,176 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.auditlog
node3_1  | 2021-06-03 13:59:05,204 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.auditlog] create_mapping [commit]
node3_1  | 2021-06-03 13:59:05,235 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.auditlog applied
node3_1  | 2021-06-03 13:59:05,328 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.auditlog] create_mapping [master]
node3_1  | 2021-06-03 13:59:05,475 INFO  c.e.x.r.i.r.RepositoryServiceImpl - Created root node with id [000-000-000-000] in repository [system.auditlog]
node3_1  | 2021-06-03 13:59:05,605 INFO  com.enonic.xp.init.Initializer - system.auditlog repo successfully initialized
node3_1  | 2021-06-03 13:59:05,719 INFO  com.enonic.xp.init.Initializer - Initializing System-repo [security] layout
node3_1  | 2021-06-03 13:59:05,722 INFO  c.e.x.c.i.s.SecurityInitializer - Initializing [/identity] folder
node3_1  | 2021-06-03 13:59:05,859 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node3_1  | 2021-06-03 13:59:05,952 INFO  c.e.x.c.i.s.SecurityInitializer - Initializing [/identity/roles] folder
node3_1  | 2021-06-03 13:59:06,056 INFO  c.e.x.c.i.s.SecurityInitializer - Initializing id provider [system]
node1_1  | 2021-06-03 13:59:06,142 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [security] layout to be initialized
node3_1  | 2021-06-03 13:59:06,199 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node2_1  | 2021-06-03 13:59:06,266 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [applications] layout to be initialized
node3_1  | 2021-06-03 13:59:06,902 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node3_1  | 2021-06-03 13:59:07,012 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.admin
node3_1  | 2021-06-03 13:59:07,120 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.authenticated
node1_1  | 2021-06-03 13:59:07,170 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [security] layout to be initialized
node3_1  | 2021-06-03 13:59:07,245 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.everyone
node2_1  | 2021-06-03 13:59:07,282 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [applications] layout to be initialized
node3_1  | 2021-06-03 13:59:07,366 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.admin.login
node3_1  | 2021-06-03 13:59:07,509 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.user.app
node3_1  | 2021-06-03 13:59:07,654 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.user.admin
node3_1  | 2021-06-03 13:59:07,764 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:cms.cm.app
node3_1  | 2021-06-03 13:59:07,870 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:cms.expert
node3_1  | 2021-06-03 13:59:08,029 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:cms.admin
node3_1  | 2021-06-03 13:59:08,144 INFO  c.e.x.c.i.s.SecurityInitializer - Role created: role:system.auditlog
node1_1  | 2021-06-03 13:59:08,192 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [security] layout to be initialized
node3_1  | 2021-06-03 13:59:08,234 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node2_1  | 2021-06-03 13:59:08,296 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for System-repo [applications] layout to be initialized
node3_1  | 2021-06-03 13:59:08,343 INFO  c.e.x.c.i.s.SecurityInitializer - User created: user:system:anonymous
node3_1  | 2021-06-03 13:59:08,440 INFO  c.e.x.c.i.s.SecurityInitializer - User created: user:system:su
node3_1  | 2021-06-03 13:59:08,499 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node3_1  | 2021-06-03 13:59:08,598 INFO  c.e.x.c.i.s.SecurityInitializer - Added user:system:su as member of role:system.admin
node3_1  | 2021-06-03 13:59:08,599 INFO  com.enonic.xp.init.Initializer - System-repo [security] layout successfully initialized
node3_1  | 2021-06-03 13:59:08,646 INFO  com.enonic.xp.init.Initializer - Initializing System-repo [applications] layout
node3_1  | 2021-06-03 13:59:08,647 INFO  c.e.x.c.i.a.ApplicationRepoInitializer - Initializing [/applications] folder
node3_1  | 2021-06-03 13:59:08,692 INFO  com.enonic.xp.init.Initializer - System-repo [applications] layout successfully initialized
node3_1  | 2021-06-03 13:59:09,121 INFO  com.enonic.xp.init.Initializer - Initializing system.scheduler repo
node3_1  | 2021-06-03 13:59:09,124 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index search-system.scheduler
node3_1  | 2021-06-03 13:59:09,151 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.scheduler] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:09,230 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index search-system.scheduler created with status true
node3_1  | 2021-06-03 13:59:09,231 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index storage-system.scheduler
node3_1  | 2021-06-03 13:59:09,231 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[search-system.scheduler][0]] ...]).
node3_1  | 2021-06-03 13:59:09,312 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.scheduler] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:09,358 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index storage-system.scheduler created with status true
node3_1  | 2021-06-03 13:59:09,359 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index search-system.scheduler
node3_1  | 2021-06-03 13:59:09,361 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[storage-system.scheduler][0]] ...]).
node3_1  | 2021-06-03 13:59:09,415 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.scheduler] create_mapping [_default_]
node3_1  | 2021-06-03 13:59:09,472 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index search-system.scheduler applied
node3_1  | 2021-06-03 13:59:09,474 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.scheduler
node3_1  | 2021-06-03 13:59:09,482 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.scheduler] create_mapping [branch]
node3_1  | 2021-06-03 13:59:09,529 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.scheduler applied
node3_1  | 2021-06-03 13:59:09,530 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.scheduler
node3_1  | 2021-06-03 13:59:09,600 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.scheduler] create_mapping [version]
node3_1  | 2021-06-03 13:59:09,665 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.scheduler applied
node3_1  | 2021-06-03 13:59:09,667 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-system.scheduler
node3_1  | 2021-06-03 13:59:09,674 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-system.scheduler] create_mapping [commit]
node3_1  | 2021-06-03 13:59:09,721 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-system.scheduler applied
node3_1  | 2021-06-03 13:59:09,900 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.scheduler] create_mapping [master]
node3_1  | 2021-06-03 13:59:09,970 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[search-system.scheduler][0]] ...]).
node3_1  | 2021-06-03 13:59:10,065 INFO  c.e.x.r.i.r.RepositoryServiceImpl - Created root node with id [000-000-000-000] in repository [system.scheduler]
node3_1  | 2021-06-03 13:59:10,208 INFO  com.enonic.xp.init.Initializer - system.scheduler repo successfully initialized
node1_1  | 2021-06-03 13:59:10,233 ERROR c.h.s.i.o.ScheduleTaskOperation - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] There is already a task with the same name 'rescheduleTask' in 'scheduler'
node1_1  | com.hazelcast.scheduledexecutor.DuplicateTaskException: There is already a task with the same name 'rescheduleTask' in 'scheduler'
node1_1  |  at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.checkNotDuplicateTask(ScheduledExecutorContainer.java:331)
node1_1  |  at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.schedule(ScheduledExecutorContainer.java:91)
node1_1  |  at com.hazelcast.scheduledexecutor.impl.operations.ScheduleTaskOperation.run(ScheduleTaskOperation.java:45)
node1_1  |  at com.hazelcast.spi.Operation.call(Operation.java:170)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:210)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:199)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:412)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:153)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:123)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.run(OperationThread.java:110)
node3_1  | 2021-06-03 13:59:10,510 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.scheduler] update_mapping [master]
node2_1  | 2021-06-03 13:59:10,572 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo to be initialized
node3_1  | 2021-06-03 13:59:11,055 INFO  com.enonic.xp.init.Initializer - Initializing com.enonic.cms.default repo
node3_1  | 2021-06-03 13:59:11,066 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index search-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:11,080 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system.auditlog] update_mapping [master]
node3_1  | 2021-06-03 13:59:11,247 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] creating index, cause [api], templates [], shards [1]/[1], mappings []
node3_1  | 2021-06-03 13:59:11,478 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[search-com.enonic.cms.default][0]] ...]).
node3_1  | 2021-06-03 13:59:11,480 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index search-com.enonic.cms.default created with status true
node3_1  | 2021-06-03 13:59:11,481 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - creating index storage-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:11,657 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-com.enonic.cms.default] creating index, cause [api], templates [], shards [1]/[1], mappings []
node1_1  | 2021-06-03 13:59:11,761 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo to be initialized
node3_1  | 2021-06-03 13:59:11,802 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Index storage-com.enonic.cms.default created with status true
node3_1  | 2021-06-03 13:59:11,804 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index search-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:11,909 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] create_mapping [_default_]
node3_1  | 2021-06-03 13:59:12,010 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[search-com.enonic.cms.default][0], [storage-com.enonic.cms.default][0], [search-com.enonic.cms.default][0], [storage-com.enonic.cms.default][0]] ...]).
node3_1  | 2021-06-03 13:59:12,010 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index search-com.enonic.cms.default applied
node3_1  | 2021-06-03 13:59:12,014 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:12,078 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-com.enonic.cms.default] create_mapping [branch]
node2_1  | 2021-06-03 13:59:12,083 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo to be initialized
node3_1  | 2021-06-03 13:59:12,115 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-com.enonic.cms.default applied
node3_1  | 2021-06-03 13:59:12,117 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:12,131 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-com.enonic.cms.default] create_mapping [version]
node3_1  | 2021-06-03 13:59:12,175 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-com.enonic.cms.default applied
node3_1  | 2021-06-03 13:59:12,175 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Apply mapping for index storage-com.enonic.cms.default
node3_1  | 2021-06-03 13:59:12,182 INFO  org.elasticsearch.cluster.metadata - [node3] [storage-com.enonic.cms.default] create_mapping [commit]
node3_1  | 2021-06-03 13:59:12,209 INFO  c.e.x.r.i.e.IndexServiceInternalImpl - Mapping for index storage-com.enonic.cms.default applied
node3_1  | 2021-06-03 13:59:12,348 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] create_mapping [master]
node3_1  | 2021-06-03 13:59:12,427 INFO  c.e.x.r.i.r.RepositoryServiceImpl - Created root node with id [000-000-000-000] in repository [com.enonic.cms.default]
node3_1  | 2021-06-03 13:59:12,464 INFO  org.elasticsearch.cluster.metadata - [node3] [search-system-repo] update_mapping [master]
node3_1  | 2021-06-03 13:59:12,647 INFO  o.e.cluster.routing.allocation - [node3] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[storage-com.enonic.cms.default][0]] ...]).
node3_1  | 2021-06-03 13:59:12,784 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] create_mapping [draft]
node1_1  | 2021-06-03 13:59:12,788 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo to be initialized
node3_1  | 2021-06-03 13:59:13,089 INFO  c.e.x.c.i.p.init.ContentInitializer - Content root-node not found, creating
node2_1  | 2021-06-03 13:59:13,155 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo to be initialized
node3_1  | 2021-06-03 13:59:13,217 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] update_mapping [draft]
node3_1  | 2021-06-03 13:59:13,312 INFO  c.e.x.c.i.p.init.ContentInitializer - Created content root-node: /content
node3_1  | 2021-06-03 13:59:13,543 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] update_mapping [master]
node3_1  | 2021-06-03 13:59:13,710 INFO  com.enonic.xp.init.Initializer - com.enonic.cms.default repo successfully initialized
node3_1  | 2021-06-03 13:59:13,735 INFO  com.enonic.xp.init.Initializer - Initializing com.enonic.cms.default repo [issue] layout
node3_1  | 2021-06-03 13:59:13,742 INFO  c.e.x.c.i.p.init.IssueInitializer - Issue root-node not found, creating
node1_1  | 2021-06-03 13:59:13,840 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo [issue] layout to be initialized
node3_1  | 2021-06-03 13:59:13,881 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] update_mapping [draft]
node3_1  | 2021-06-03 13:59:13,998 INFO  c.e.x.c.i.p.init.IssueInitializer - Created issue root-node: /issues
node3_1  | 2021-06-03 13:59:14,181 INFO  org.elasticsearch.cluster.metadata - [node3] [search-com.enonic.cms.default] update_mapping [master]
node2_1  | 2021-06-03 13:59:14,234 INFO  com.enonic.xp.init.Initializer - Waiting [1000ms] for com.enonic.cms.default repo [issue] layout to be initialized
node3_1  | 2021-06-03 13:59:14,418 INFO  com.enonic.xp.init.Initializer - com.enonic.cms.default repo [issue] layout successfully initialized
node3_1  | 2021-06-03 13:59:15,163 INFO  c.e.x.c.impl.ClusterManagerImpl - Adding cluster-provider: elasticsearch
node3_1  | 2021-06-03 13:59:15,220 INFO  org.eclipse.jetty.util.log - Logging initialized @44429ms to org.eclipse.jetty.util.log.Slf4jLog
node1_1  | 2021-06-03 13:59:15,417 INFO  c.e.x.c.impl.ClusterManagerImpl - Adding cluster-provider: elasticsearch
node3_1  | 2021-06-03 13:59:15,470 INFO  org.eclipse.jetty.server.Server - jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9
node1_1  | 2021-06-03 13:59:15,487 INFO  org.eclipse.jetty.util.log - Logging initialized @44491ms to org.eclipse.jetty.util.log.Slf4jLog
node3_1  | 2021-06-03 13:59:15,582 INFO  org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=
node3_1  | 2021-06-03 13:59:15,583 INFO  org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
node3_1  | 2021-06-03 13:59:15,586 INFO  org.eclipse.jetty.server.session -  Scavenging every 660000ms
node3_1  | 2021-06-03 13:59:15,631 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@61d1e094{/,null,AVAILABLE,@xp}
node3_1  | 2021-06-03 13:59:15,633 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@252707ab{/,null,AVAILABLE,@api}
node3_1  | 2021-06-03 13:59:15,636 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@6cd686fa{/,null,AVAILABLE,@status}
node3_1  | 2021-06-03 13:59:15,673 INFO  o.e.jetty.server.AbstractConnector - Started xp@221ca105{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
node3_1  | 2021-06-03 13:59:15,712 INFO  o.e.jetty.server.AbstractConnector - Started api@7316324b{HTTP/1.1, (http/1.1)}{0.0.0.0:4848}
node3_1  | 2021-06-03 13:59:15,750 INFO  o.e.jetty.server.AbstractConnector - Started status@d90f9f0{HTTP/1.1, (http/1.1)}{0.0.0.0:2609}
node3_1  | 2021-06-03 13:59:15,752 INFO  org.eclipse.jetty.server.Server - Started @44961ms
node1_1  | 2021-06-03 13:59:15,826 INFO  org.eclipse.jetty.server.Server - jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9
node1_1  | 2021-06-03 13:59:15,875 INFO  org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=
node1_1  | 2021-06-03 13:59:15,876 INFO  org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
node1_1  | 2021-06-03 13:59:15,879 INFO  org.eclipse.jetty.server.session -  Scavenging every 660000ms
node1_1  | 2021-06-03 13:59:15,908 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@6b68a2ab{/,null,AVAILABLE,@xp}
node1_1  | 2021-06-03 13:59:15,913 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@2dbaca2a{/,null,AVAILABLE,@api}
node1_1  | 2021-06-03 13:59:15,915 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@5ed64c5d{/,null,AVAILABLE,@status}
node3_1  | 2021-06-03 13:59:15,940 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Searching for installed applications
node1_1  | 2021-06-03 13:59:15,956 INFO  o.e.jetty.server.AbstractConnector - Started xp@be633be{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
node3_1  | 2021-06-03 13:59:15,975 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Found [0] installed applications
node3_1  | 2021-06-03 13:59:15,992 INFO  c.e.xp.web.jetty.impl.JettyActivator - Started Jetty
node3_1  | 2021-06-03 13:59:15,992 INFO  c.e.xp.web.jetty.impl.JettyActivator - Listening on ports [8080](xp), [4848](management) and [2609](monitoring)
node1_1  | 2021-06-03 13:59:15,995 INFO  o.e.jetty.server.AbstractConnector - Started api@487f450a{HTTP/1.1, (http/1.1)}{0.0.0.0:4848}
node1_1  | 2021-06-03 13:59:16,041 INFO  o.e.jetty.server.AbstractConnector - Started status@3cba5675{HTTP/1.1, (http/1.1)}{0.0.0.0:2609}
node1_1  | 2021-06-03 13:59:16,042 INFO  org.eclipse.jetty.server.Server - Started @45048ms
node1_1  | 2021-06-03 13:59:16,160 ERROR c.h.s.i.o.ScheduleTaskOperation - [192.123.0.11]:5701 [3.12.12#OSS] [3.12.12] There is already a task with the same name 'rescheduleTask' in 'scheduler'
node1_1  | com.hazelcast.scheduledexecutor.DuplicateTaskException: There is already a task with the same name 'rescheduleTask' in 'scheduler'
node1_1  |  at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.checkNotDuplicateTask(ScheduledExecutorContainer.java:331)
node1_1  |  at com.hazelcast.scheduledexecutor.impl.ScheduledExecutorContainer.schedule(ScheduledExecutorContainer.java:91)
node1_1  |  at com.hazelcast.scheduledexecutor.impl.operations.ScheduleTaskOperation.run(ScheduleTaskOperation.java:45)
node1_1  |  at com.hazelcast.spi.Operation.call(Operation.java:170)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:210)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:199)
node1_1  |  at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:412)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:153)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:123)
node1_1  |  at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.run(OperationThread.java:110)
node1_1  | 2021-06-03 13:59:16,224 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Searching for installed applications
node1_1  | 2021-06-03 13:59:16,263 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Found [0] installed applications
node1_1  | 2021-06-03 13:59:16,289 INFO  c.e.xp.web.jetty.impl.JettyActivator - Started Jetty
node1_1  | 2021-06-03 13:59:16,289 INFO  c.e.xp.web.jetty.impl.JettyActivator - Listening on ports [8080](xp), [4848](management) and [2609](monitoring)
node2_1  | 2021-06-03 13:59:16,362 INFO  c.e.x.c.impl.ClusterManagerImpl - Adding cluster-provider: elasticsearch
node2_1  | 2021-06-03 13:59:16,424 INFO  org.eclipse.jetty.util.log - Logging initialized @45430ms to org.eclipse.jetty.util.log.Slf4jLog
node2_1  | 2021-06-03 13:59:16,631 INFO  org.eclipse.jetty.server.Server - jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9
node2_1  | 2021-06-03 13:59:16,656 INFO  org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=
node2_1  | 2021-06-03 13:59:16,656 INFO  org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
node2_1  | 2021-06-03 13:59:16,658 INFO  org.eclipse.jetty.server.session -  Scavenging every 600000ms
node2_1  | 2021-06-03 13:59:16,682 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@50e85e7f{/,null,AVAILABLE,@xp}
node2_1  | 2021-06-03 13:59:16,683 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@3889a211{/,null,AVAILABLE,@api}
node2_1  | 2021-06-03 13:59:16,684 INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@2c0c620e{/,null,AVAILABLE,@status}
node2_1  | 2021-06-03 13:59:16,696 INFO  o.e.jetty.server.AbstractConnector - Started xp@1e74cf45{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
node2_1  | 2021-06-03 13:59:16,699 INFO  o.e.jetty.server.AbstractConnector - Started api@3c6c9783{HTTP/1.1, (http/1.1)}{0.0.0.0:4848}
node2_1  | 2021-06-03 13:59:16,707 INFO  o.e.jetty.server.AbstractConnector - Started status@4697e43c{HTTP/1.1, (http/1.1)}{0.0.0.0:2609}
node2_1  | 2021-06-03 13:59:16,708 INFO  org.eclipse.jetty.server.Server - Started @45714ms
node2_1  | 2021-06-03 13:59:16,827 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Searching for installed applications
node2_1  | 2021-06-03 13:59:16,855 INFO  c.e.x.c.i.app.ApplicationServiceImpl - Found [0] installed applications
node2_1  | 2021-06-03 13:59:16,860 INFO  c.e.xp.web.jetty.impl.JettyActivator - Started Jetty
node2_1  | 2021-06-03 13:59:16,861 INFO  c.e.xp.web.jetty.impl.JettyActivator - Listening on ports [8080](xp), [4848](management) and [2609](monitoring)
rymsha commented 3 years ago

Just annoying error message. Not something to worry about. But because it looks scary, we'll give it higher priority.

rymsha commented 3 years ago

Unfortunately for us HZ fires a log message with ERROR level when actually in our case it is a desired behavior - if "rescheduleTask" already exists we are happy - means another XP node managed to schedule it already.

The easiest solution is to check that rescheduleTask task already exists. It does not prevent races and error may still appear, but hopefully not so often anymore.