Hello! Can you collect thread dumps from all nodes once you get them hanging?
Can you throw together a reproducer project? Regards, -- Ilya Kasnacheev вт, 4 авг. 2020 г. в 12:51, Ilya Roublev <iroub...@gmail.com>: > We are developing Jira cloud app using Apache Ignite both as data storage > and as job scheduler. This is done via a standard Ignite client node. But > we need to use Atlassian Connect Spring Boot to be able to communicate with > Jira. In short, all is done exactly as in our article Boosting Jira Cloud > app development with Apache Ignite > <https://medium.com/alliedium/boosting-jira-cloud-app-development-with-apache-ignite-7eebc7bb3d48>. > At first we used simple Ignite JDBC driver > <https://apacheignite-sql.readme.io/docs/jdbc-driver> just for Atlassian > Connect Spring Boot along with a separate Ignite client node for our own > purposes. But this turned out to be very unstable being deployed in our > local Kubernetes cluster (built via Kubespray) due to constant exceptions > > java.net.SocketException: Connection reset > > occuring from time to time (in fact, this revealed only in our local > cluster, in AWS EKS all worked fine). To make all this more stable we tried > to use Ignite JDBC Client driver > <https://apacheignite-sql.readme.io/docs/jdbc-client-driver> exactly as > described in the article mentioned above. Thus, now our backend uses two > Ignite client nodes per single JVM: the first one for JDBC used by > Atlassian Connect Spring Boot, the second one for our own purposes. This > solution turned out to be good enough, because our app works now very > stable both in our local cluster and in AWS EKS. But when we deploy our app > in Docker for testing and developing purposes, our Ignite client nodes hang > from time to time. After some investigation we were able to see that this > occurs exactly at the instant when an object of IgniteAtomicLong is > created. Below are logs both for successful initialization of our app and > for the case when Ignite client node hanged. Logs when all is ok > ignite-appclientnode-successful.log > <http://apache-ignite-users.70518.x6.nabble.com/file/t2262/ignite-appclientnode-successful.log> > ignite-jdbcclientnode-successful.log > <http://apache-ignite-users.70518.x6.nabble.com/file/t2262/ignite-jdbcclientnode-successful.log> > Logs > when both client node hang ignite-appclientnode-failed.log > <http://apache-ignite-users.70518.x6.nabble.com/file/t2262/ignite-appclientnode-failed.log> > ignite-jdbcclientnode-failed.log > <http://apache-ignite-users.70518.x6.nabble.com/file/t2262/ignite-jdbcclientnode-failed.log> > Some > analysis and questions From logs one can see that caches default, > tenants, atlassian_host_audit, SQL_PUBLIC_ATLASSIAN_HOST are manipulated, > in fact, default is given in client configuration: client.xml > <http://apache-ignite-users.70518.x6.nabble.com/file/t2262/client.xml>, > the cache SQL_PUBLIC_ATLASSIAN_HOST contains atlassian_host table mentioned > in Boosting Jira Cloud app development with Apache Ignite > <https://medium.com/alliedium/boosting-jira-cloud-app-development-with-apache-ignite-7eebc7bb3d48> > and is created in advance even before the app starts. Further, > atlassian_host_audit is a copy of atlassian_host, in any case it is not yet > created when the app hangs. What concerns other entities processed by > Ignite, they are created by the following code: > > CacheConfiguration<Long, Tenant> tenantCacheCfg = new > CacheConfiguration<>(); > tenantCacheCfg.setName("tenants"); > tenantCacheCfg.setSqlSchema("PROD"); > tenantCacheCfg.setIndexedTypes(Long.class, Tenant.class); > tenantCacheCfg.setAtomicityMode(CacheAtomicityMode.TRANSACTIONAL); > tenantCacheCfg.setEncryptionEnabled(true); > > IgniteCache<Long, Tenant> tenantCache = > ignite.getOrCreateCache(tenantCacheCfg); > IgniteAtomicLong idGen = ignite.atomicLong("PROD_tenants_seq", 0, > true); > > And from the logs of the app itself it is clear that the app hangs exactly > on the last line. This is confirmed by the fact that the in > ignite-jdbcclientnode-successful.log we have the following lines: > > [2020-07-31 09:52:12,237][INFO ][exchange-worker-#43][GridCacheProcessor] > Started cache [name=ignite-sys-atomic-cache@default-ds-group, id=1481046058, > group=default-ds-group, dataRegionName=null, mode=PARTITIONED, > atomicity=TRANSACTIONAL, backups=1, mvcc=false] > [2020-07-31 09:52:12,263][INFO ][exchange-worker-#43][time] Finished exchange > init [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], crd=false] > [2020-07-31 09:52:12,631][INFO > ][sys-#109%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=c7d1e091-da48-46a3-98ea-6971e8a811e0, resVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2]] > [2020-07-31 09:52:12,634][INFO ][sys-#54][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=c7d1e091-da48-46a3-98ea-6971e8a811e0, resVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2]] > [2020-07-31 09:52:12,639][INFO > ][sys-#109%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=6, > minorTopVer=2], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > err=null, rebalanced=true, wasRebalanced=true] > [2020-07-31 09:52:12,645][INFO ][sys-#54][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=6, > minorTopVer=2], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > err=null, rebalanced=true, wasRebalanced=true] > [2020-07-31 09:52:12,645][INFO > ][sys-#109%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=3b6ad97d-0ac9-4b2f-8703-f734968a5ec0, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=292cfc60-bf04-4000-9589-d633f980f06a, > consistentId=292cfc60-bf04-4000-9589-d633f980f06a, addrs=ArrayList > [127.0.0.1, 172.24.0.7], sockAddrs=HashSet [/127.0.0.1:0, > da98724605ca/172.24.0.7:0], discPort=0, order=3, intOrder=3, > lastExchangeTime=1596189127174, loc=false, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2]] > [2020-07-31 09:52:12,646][INFO > ][sys-#109%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=6, > minorTopVer=2], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters > initialization" (0 ms), stage="Update caches registry" (3 ms), stage="Start > caches" (0 ms), stage="Affinity initialization on cache group start" (5 ms), > stage="Determine exchange type" (0 ms), stage="Waiting for Full message" (400 > ms), stage="Affinity recalculation" (0 ms), stage="Full map updating" (6 ms), > stage="Exchange done" (7 ms), stage="Total time" (421 ms)] > [2020-07-31 09:52:12,646][INFO > ][sys-#109%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=6, > minorTopVer=2], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > stage="Affinity initialization on cache group start [grp=default-ds-group]" > (5 ms) (parent=Affinity initialization on cache group start)] > [2020-07-31 09:52:12,646][INFO > ][exchange-worker-#104%ignite-jdbc-driver-e1f562e1-5127-4f55-80d2-18661982769c%][GridCachePartitionExchangeManager] > Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion > [topVer=6, minorTopVer=2], rebTopVer=AffinityTopologyVersion [topVer=-1, > minorTopVer=0], evt=DISCOVERY_CUSTOM_EVT, > evtNode=292cfc60-bf04-4000-9589-d633f980f06a, client=true] > [2020-07-31 09:52:12,659][INFO ][sys-#54][GridCacheProcessor] Finish proxy > initialization, cacheName=ignite-sys-atomic-cache@default-ds-group, > localNodeId=292cfc60-bf04-4000-9589-d633f980f06a > [2020-07-31 09:52:12,660][INFO > ][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping > rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=6, > minorTopVer=2], rebTopVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], > evt=DISCOVERY_CUSTOM_EVT, evtNode=292cfc60-bf04-4000-9589-d633f980f06a, > client=true] > [2020-07-31 09:52:12,660][INFO ][sys-#54][GridDhtPartitionsExchangeFuture] > Completed partition exchange [localNode=292cfc60-bf04-4000-9589-d633f980f06a, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=292cfc60-bf04-4000-9589-d633f980f06a, > consistentId=292cfc60-bf04-4000-9589-d633f980f06a, addrs=ArrayList > [127.0.0.1, 172.24.0.7], sockAddrs=HashSet [/127.0.0.1:0, > da98724605ca/172.24.0.7:0], discPort=0, order=3, intOrder=0, > lastExchangeTime=1596189105382, loc=true, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=6, minorTopVer=2]] > [2020-07-31 09:52:12,660][INFO ][sys-#54][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], stage="Waiting in > exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), > stage="Update caches registry" (0 ms), stage="Start caches" (47 ms), > stage="Affinity initialization on cache group start" (4 ms), stage="Determine > exchange type" (0 ms), stage="Waiting for Full message" (371 ms), > stage="Affinity recalculation" (0 ms), stage="Full map updating" (11 ms), > stage="Exchange done" (15 ms), stage="Total time" (448 ms)] > [2020-07-31 09:52:12,661][INFO ][sys-#54][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=6, > minorTopVer=2], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], > stage="Affinity initialization on cache group start [grp=default-ds-group]" > (4 ms) (parent=Affinity initialization on cache group start)] > > while in ignite-jdbcclientnode-failed.log all the lines starting the first > time the cache ignite-sys-atomic-cache@default-ds-group (the cache used > for atomics) was mentioned are as follows: > > [2020-08-03 21:52:00,386][INFO > ][exchange-worker-#104%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][time] > Started exchange init [topVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, > evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > customEvt=DynamicCacheChangeBatch > [id=2954f46b371-f60b9b4c-244f-458a-bb18-2ff0893c1d05, reqs=ArrayList > [DynamicCacheChangeRequest > [cacheName=ignite-sys-atomic-cache@default-ds-group, hasCfg=true, > nodeId=653143b2-6e80-49ff-9e9a-ae10237b32e8, clientStartOnly=false, > stop=false, destroy=false, disabledAfterStartfalse]], > exchangeActions=ExchangeActions > [startCaches=[ignite-sys-atomic-cache@default-ds-group], stopCaches=null, > startGrps=[default-ds-group], stopGrps=[], resetParts=null, > stateChangeRequest=null], startCaches=false], allowMerge=false, > exchangeFreeSwitch=false] > [2020-08-03 21:52:00,403][INFO > ][exchange-worker-#104%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][time] > Finished exchange init [topVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], crd=false] > [2020-08-03 21:52:00,406][INFO ][exchange-worker-#43][time] Started exchange > init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], crd=false, > evt=DISCOVERY_CUSTOM_EVT, evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > customEvt=DynamicCacheChangeBatch > [id=2954f46b371-f60b9b4c-244f-458a-bb18-2ff0893c1d05, reqs=ArrayList > [DynamicCacheChangeRequest > [cacheName=ignite-sys-atomic-cache@default-ds-group, hasCfg=true, > nodeId=653143b2-6e80-49ff-9e9a-ae10237b32e8, clientStartOnly=false, > stop=false, destroy=false, disabledAfterStartfalse]], > exchangeActions=ExchangeActions > [startCaches=[ignite-sys-atomic-cache@default-ds-group], stopCaches=null, > startGrps=[default-ds-group], stopGrps=[], resetParts=null, > stateChangeRequest=null], startCaches=false], allowMerge=false, > exchangeFreeSwitch=false] > [2020-08-03 21:52:00,415][INFO ][exchange-worker-#43][time] Finished exchange > init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], crd=false] > [2020-08-03 21:52:00,838][INFO ][sys-#52][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=c0138e03-465d-4944-a1ee-8bee59fbf909, resVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,839][INFO > ][sys-#107%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=c0138e03-465d-4944-a1ee-8bee59fbf909, resVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,853][INFO > ][sys-#107%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > err=null, rebalanced=true, wasRebalanced=true] > [2020-08-03 21:52:00,861][INFO ][sys-#52][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > err=null, rebalanced=true, wasRebalanced=true] > [2020-08-03 21:52:00,870][INFO > ][sys-#107%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=467aae9a-d21c-45bf-8184-2837941ba650, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=653143b2-6e80-49ff-9e9a-ae10237b32e8, > consistentId=653143b2-6e80-49ff-9e9a-ae10237b32e8, addrs=ArrayList > [127.0.0.1, 172.23.0.8], sockAddrs=HashSet [/127.0.0.1:0, > d371f9a8ea1f/172.23.0.8:0], discPort=0, order=7, intOrder=6, > lastExchangeTime=1596491518929, loc=false, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,870][INFO > ][sys-#107%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters > initialization" (9 ms), stage="Update caches registry" (0 ms), stage="Start > caches" (0 ms), stage="Affinity initialization on cache group start" (6 ms), > stage="Determine exchange type" (0 ms), stage="Waiting for Full message" (436 > ms), stage="Affinity recalculation" (0 ms), stage="Full map updating" (14 > ms), stage="Exchange done" (16 ms), stage="Total time" (481 ms)] > [2020-08-03 21:52:00,870][INFO > ][sys-#107%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > stage="Affinity initialization on cache group start [grp=default-ds-group]" > (6 ms) (parent=Affinity initialization on cache group start)] > [2020-08-03 21:52:00,870][INFO ][sys-#52][GridDhtPartitionsExchangeFuture] > Completed partition exchange [localNode=3bbe2ea9-7ba5-4de5-84be-be23bd27f312, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=653143b2-6e80-49ff-9e9a-ae10237b32e8, > consistentId=653143b2-6e80-49ff-9e9a-ae10237b32e8, addrs=ArrayList > [127.0.0.1, 172.23.0.8], sockAddrs=HashSet [/127.0.0.1:0, > d371f9a8ea1f/172.23.0.8:0], discPort=0, order=7, intOrder=6, > lastExchangeTime=1596491518929, loc=false, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,871][INFO > ][exchange-worker-#104%ignite-jdbc-driver-31920dc9-8960-4130-8469-3d589aa6e1b4%][GridCachePartitionExchangeManager] > Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion > [topVer=8, minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=-1, > minorTopVer=0], evt=DISCOVERY_CUSTOM_EVT, > evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, client=true] > [2020-08-03 21:52:00,873][INFO > ][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping > rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=8, > minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], > evt=DISCOVERY_CUSTOM_EVT, evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > client=true] > [2020-08-03 21:52:00,873][INFO ][sys-#52][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], stage="Waiting in > exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), > stage="Update caches registry" (0 ms), stage="Start caches" (0 ms), > stage="Affinity initialization on cache group start" (7 ms), stage="Determine > exchange type" (0 ms), stage="Waiting for Full message" (423 ms), > stage="Affinity recalculation" (0 ms), stage="Full map updating" (22 ms), > stage="Exchange done" (9 ms), stage="Total time" (461 ms)] > [2020-08-03 21:52:00,873][INFO ][sys-#52][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=8, > minorTopVer=1], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > stage="Affinity initialization on cache group start [grp=default-ds-group]" > (7 ms) (parent=Affinity initialization on cache group start)] > > In particular, the following line from > ignite-jdbcclientnode-successful.log is absent in > ignite-jdbcclientnode-failed.log: > > [2020-07-31 09:52:12,237][INFO ][exchange-worker-#43][GridCacheProcessor] > Started cache [name=ignite-sys-atomic-cache@default-ds-group, id=1481046058, > group=default-ds-group, dataRegionName=null, mode=PARTITIONED, > atomicity=TRANSACTIONAL, backups=1, mvcc=false] > > But it should be noted that for the failure case there are other client > nodes executed in separate containers executed simultaneously with the > backend app and with the same code creating the cache tenants and > IgniteAtomicLong idGen what concerns the logs below (see above for the > code), their node ids are 653143b2-6e80-49ff-9e9a-ae10237b32e8 and > 30e24e06-ab76-4053-a36e-548e87ffe5d1, respectively (and it can be easily > seen that all the lines in ignite-jdbcclientnode-failed.log with > ignite-sys-atomic-cache@default-ds-group relate namely to these nodes), > the logs for the time segment when the code with tenants and idGen is > executed are as follows: > > [2020-08-03 21:52:00,838: INFO/MainProcess] [2020-08-03 21:52:00,838][INFO > ][sys-#44][GridDhtPartitionsExchangeFuture] Received full message, will > finish exchange [node=c0138e03-465d-4944-a1ee-8bee59fbf909, > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,872: INFO/MainProcess] [2020-08-03 21:52:00,864][INFO > ][sys-#44][GridDhtPartitionsExchangeFuture] Finish exchange future > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], err=null, > rebalanced=true, wasRebalanced=true] > [2020-08-03 21:52:00,909: INFO/MainProcess] [2020-08-03 21:52:00,908][INFO > ][sys-#44][GridCacheProcessor] Finish proxy initialization, > cacheName=ignite-sys-atomic-cache@default-ds-group, > localNodeId=653143b2-6e80-49ff-9e9a-ae10237b32e8 > [2020-08-03 21:52:00,911: INFO/MainProcess] [2020-08-03 21:52:00,910][INFO > ][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping > rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=8, > minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], > evt=DISCOVERY_CUSTOM_EVT, evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > client=true] > [2020-08-03 21:52:00,911: INFO/MainProcess] [2020-08-03 21:52:00,911][INFO > ][sys-#44][GridDhtPartitionsExchangeFuture] Completed partition exchange > [localNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=653143b2-6e80-49ff-9e9a-ae10237b32e8, > consistentId=653143b2-6e80-49ff-9e9a-ae10237b32e8, addrs=ArrayList > [127.0.0.1, 172.23.0.8], sockAddrs=HashSet [/127.0.0.1:0, > d371f9a8ea1f/172.23.0.8:0], discPort=0, order=7, intOrder=0, > lastExchangeTime=1596491517591, loc=true, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,912: INFO/MainProcess] [2020-08-03 21:52:00,912][INFO > ][sys-#44][GridDhtPartitionsExchangeFuture] Exchange timings > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], stage="Waiting in > exchange queue" (1 ms), stage="Exchange parameters initialization" (2 ms), > stage="Update caches registry" (2 ms), stage="Start caches" (33 ms), > stage="Affinity initialization on cache group start" (8 ms), stage="Determine > exchange type" (0 ms), stage="Waiting for Full message" (390 ms), > stage="Affinity recalculation" (1 ms), stage="Full map updating" (24 ms), > stage="Exchange done" (47 ms), stage="Total time" (508 ms)] > [2020-08-03 21:52:00,912: INFO/MainProcess] [2020-08-03 21:52:00,912][INFO > ][sys-#44][GridDhtPartitionsExchangeFuture] Exchange longest local stages > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], stage="Affinity > initialization on cache group start [grp=default-ds-group]" (8 ms) > (parent=Affinity initialization on cache group start)] > [2020-08-03 21:52:01,151: INFO/MainProcess] [2020-08-03 21:52:01,151][INFO > ][grid-nio-worker-tcp-comm-1-#29][TcpCommunicationSpi] Established outgoing > communication connection [locAddr=/172.23.0.8:39978, > rmtAddr=59ec515a30e8/172.23.0.2:47100] > [2020-08-03 21:52:09,305: INFO/MainProcess] [2020-08-03 21:52:09,305][INFO > ][ignite-update-notifier-timer][GridUpdateNotifier] Your version is up to > date. > > [2020-08-03 21:52:00,854: INFO/MainProcess] [2020-08-03 21:52:00,852][INFO > ][sys-#46][GridDhtPartitionsExchangeFuture] Received full message, will > finish exchange [node=c0138e03-465d-4944-a1ee-8bee59fbf909, > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,877: INFO/MainProcess] [2020-08-03 21:52:00,874][INFO > ][sys-#46][GridDhtPartitionsExchangeFuture] Finish exchange future > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], err=null, > rebalanced=true, wasRebalanced=true] > [2020-08-03 21:52:00,881: INFO/MainProcess] [2020-08-03 21:52:00,879][INFO > ][sys-#46][GridDhtPartitionsExchangeFuture] Completed partition exchange > [localNode=30e24e06-ab76-4053-a36e-548e87ffe5d1, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode > [id=653143b2-6e80-49ff-9e9a-ae10237b32e8, > consistentId=653143b2-6e80-49ff-9e9a-ae10237b32e8, addrs=ArrayList > [127.0.0.1, 172.23.0.8], sockAddrs=HashSet [/127.0.0.1:0, > d371f9a8ea1f/172.23.0.8:0], discPort=0, order=7, intOrder=6, > lastExchangeTime=1596491519416, loc=false, ver=2.8.1#20200521-sha1:86422096, > isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion > [topVer=8, minorTopVer=1]] > [2020-08-03 21:52:00,881: INFO/MainProcess] [2020-08-03 21:52:00,880][INFO > ][sys-#46][GridDhtPartitionsExchangeFuture] Exchange timings > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], stage="Waiting in > exchange queue" (89 ms), stage="Exchange parameters initialization" (7 ms), > stage="Update caches registry" (14 ms), stage="Start caches" (1 ms), > stage="Affinity initialization on cache group start" (10 ms), > stage="Determine exchange type" (0 ms), stage="Waiting for Full message" (314 > ms), stage="Affinity recalculation" (2 ms), stage="Full map updating" (19 > ms), stage="Exchange done" (5 ms), stage="Total time" (461 ms)] > [2020-08-03 21:52:00,881: INFO/MainProcess] [2020-08-03 21:52:00,880][INFO > ][sys-#46][GridDhtPartitionsExchangeFuture] Exchange longest local stages > [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], > resVer=AffinityTopologyVersion [topVer=8, minorTopVer=1], stage="Affinity > initialization on cache group start [grp=default-ds-group]" (10 ms) > (parent=Affinity initialization on cache group start)] > [2020-08-03 21:52:00,882: INFO/MainProcess] [2020-08-03 21:52:00,881][INFO > ][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping > rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=8, > minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], > evt=DISCOVERY_CUSTOM_EVT, evtNode=653143b2-6e80-49ff-9e9a-ae10237b32e8, > client=true] > [2020-08-03 21:52:00,894: INFO/MainProcess] [2020-08-03 21:52:00,892][INFO > ][exchange-worker-#43][GridCacheProcessor] Started cache [name=tenants, > id=-1427624695, dataRegionName=null, mode=PARTITIONED, > atomicity=TRANSACTIONAL, backups=1, mvcc=false] > [2020-08-03 21:52:00,968: INFO/MainProcess] [2020-08-03 21:52:00,966][INFO > ][exchange-worker-#43][GridCacheProcessor] Finish proxy initialization, > cacheName=tenants, localNodeId=30e24e06-ab76-4053-a36e-548e87ffe5d1 > [2020-08-03 21:52:01,000: INFO/MainProcess] [2020-08-03 21:52:00,999][INFO > ][exchange-worker-#43][GridCacheProcessor] Started cache > [name=ignite-sys-atomic-cache@default-ds-group, id=1481046058, > group=default-ds-group, dataRegionName=null, mode=PARTITIONED, > atomicity=TRANSACTIONAL, backups=1, mvcc=false] > [2020-08-03 21:52:01,036: INFO/MainProcess] [2020-08-03 21:52:01,035][INFO > ][exchange-worker-#43][GridCacheProcessor] Finish proxy initialization, > cacheName=ignite-sys-atomic-cache@default-ds-group, > localNodeId=30e24e06-ab76-4053-a36e-548e87ffe5d1 > [2020-08-03 21:52:01,212: INFO/MainProcess] [2020-08-03 21:52:01,212][INFO > ][grid-nio-worker-tcp-comm-1-#29][TcpCommunicationSpi] Established outgoing > communication connection [locAddr=/172.23.0.9:53310, > rmtAddr=59ec515a30e8/172.23.0.2:47100] > [2020-08-03 21:52:09,702: INFO/MainProcess] [2020-08-03 21:52:09,701][INFO > ][ignite-update-notifier-timer][GridUpdateNotifier] Your version is up to > date. > > And the code creating tenants and idGen is executed successfully. But is > it possible that this simultaneous creation of idGen may hang some nodes? > (As for the case when all was executed successfully, there we also have two > separate containers, but they are executed strictly after all is done in > the main app, so the simultaneous execution of the same code in several > client nodes may be the reason of hanging, isn't it?) And in the case the > answer is positive, what is to do? Certainly it is possible to set a delay > for those separate containers, but this does not look as a rather safe > solution... And we have another small question, when we have two separate > client nodes in our app, both configured for logging, why starting from > some instant only the log for JDBC client node is used for logging, not > both? > ------------------------------ > Sent from the Apache Ignite Users mailing list archive > <http://apache-ignite-users.70518.x6.nabble.com/> at Nabble.com. >
