Hello Ilya, I have a look at your logs and thread dumps. This definitely a bug. The data structure processor does not properly initialize when a client node connects to a cluster that changes its own state (state transition from the inactive state to active). I have created a ticket in order to address this issue https://issues.apache.org/jira/browse/IGNITE-13348
Thanks, S. вт, 11 авг. 2020 г. в 05:00, Ilya Roublev <[email protected]>: > Hello, Ilya, > > In the post above one week ago I've attached necessary thread dumps. Could > you please say whether do you have sufficient information to investigate > the > problem with hanging of IgniteAtomicLong? I think the issue not all that > harmless, it concerns the last Ignite 2.8.1 and its fixing may be IMHO > important for the community (I think the cause is in initialization of > ignite-sys-atomic-cache simultaneously in several nodes, but certainly I > may > be mistaken). But unfortunately I see no reaction on this since a week. > Could you please give at least a hint that the problem is under > investigation and there is a slightest chance that the problem can be > resolved? Or it is better to work out some workarounds? > > Thank you very much in advance for any response. > > My best regards, > Ilya > > > ilya.kasnacheev wrote > > 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 < > > > iroublev@ > > > >: > > > >> 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. > >> > > > > > > -- > Sent from: http://apache-ignite-users.70518.x6.nabble.com/ >
