You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "ff zhou (Jira)" <ji...@apache.org> on 2020/07/30 09:27:00 UTC
[jira] [Created] (IGNITE-13311) Put operation may hang if the cache
is reconnected
ff zhou created IGNITE-13311:
--------------------------------
Summary: Put operation may hang if the cache is reconnected
Key: IGNITE-13311
URL: https://issues.apache.org/jira/browse/IGNITE-13311
Project: Ignite
Issue Type: Bug
Components: cache
Affects Versions: 2.8.1
Environment: # Single-node client (fat node)
# single-node server
# use replicated persistence mode
Reporter: ff zhou
Problem description:
1. Single-node client (fat node), single-node server, and use replicated persistence mode
2) Run the client program and perform the put operation.
3) Kill the server process.
4) The client captures the IgniteClientDisconnectedException exception and invokes cause.reconnectFuture().get(); to wait for reconnection.
5) Start the server process.
6) After the execution（cause.reconnectFuture().get()）is completed, perform the put operation immediately. The put operation is hung on the checkProxyIsValid interface.
7）if i performed sleep operation after reconnectFuture.get() is completed，then do the put operation, it will not hang.（This is a temporary workaround.）
hang stack:
"mq-topic-11-3-4" #253 prio=5 os_prio=0 tid=0x00007fa70275e000 nid=0x2abb waiting on condition [0x00007fa4ad29a000]"mq-topic-11-3-4" #253 prio=5 os_prio=0 tid=0x00007fa70275e000 nid=0x2abb waiting on condition [0x00007fa4ad29a000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304) at org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:178) at org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:141) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.publicJCache(GridCacheProcessor.java:4417) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.publicJCache(GridCacheProcessor.java:4388) at org.apache.ignite.internal.processors.cache.GatewayProtectedCacheProxy.checkProxyIsValid(GatewayProtectedCacheProxy.java:1602) at org.apache.ignite.internal.processors.cache.GatewayProtectedCacheProxy.onEnter(GatewayProtectedCacheProxy.java:1619) at org.apache.ignite.internal.processors.cache.GatewayProtectedCacheProxy.put(GatewayProtectedCacheProxy.java:853) at com.huawei.donau.master.common.repository.storage.cache.impl.ignite.EventCacheDaoIgniteImpl.insertEvent(EventCacheDaoIgniteImpl.java:105) at com.huawei.donau.master.core.repository.service.EventService.addEvent(EventService.java:28) at com.huawei.donau.master.core.jobmanager.task.DonauTask.addEvent(DonauTask.java:234) at com.huawei.donau.master.core.jobmanager.task.TaskManager.recordTaskStateChangeEvent(TaskManager.java:1290) at com.huawei.donau.master.core.jobmanager.task.TaskManager.recordAndPersistStateChange(TaskManager.java:986) at com.huawei.donau.master.core.jobmanager.task.TaskManager.onTaskStateChange(TaskManager.java:941) at com.huawei.donau.master.core.jobmanager.task.TaskManager.onTaskUpdate(TaskManager.java:333) at com.huawei.donau.master.core.jobmanager.task.TaskManager.handleTaskUpdateMessage(TaskManager.java:251) at com.huawei.donau.master.core.jobmanager.task.TaskManager$$Lambda$536/577636327.onReceive(Unknown Source) at com.huawei.donau.common.mq.ConsumerClient$ConsumerThread.run(ConsumerClient.java:141)
Locked ownable synchronizers: - None
client debug log:
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoJul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Router node: TcpDiscoveryNode [id=98a557e1-0638-486d-8939-4e09ce32726a, consistentId=8c821ac6-4bf2-4426-8098-e182f31fd168, addrs=ArrayList [0:0:0:0:0:0:0:1%lo, 10.29.88.134, 127.0.0.1, 192.168.122.1], sockAddrs=HashSet [/192.168.122.1:47500, hghphicprd08301/10.29.88.134:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1595831945590, loc=false, ver=2.8.1#20200521-sha1:86422096, isClient=false]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Stopped cache [cacheName=ignite-sys-cache]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Assigned mvcc coordinator [crd=MvccCoordinator [topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], nodeId=98a557e1-0638-486d-8939-4e09ce32726a, ver=1595831945461, local=false, initialized=false]]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Stopped cache [cacheName=t_migration_jobid]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger warningWARNING: Client node was reconnected after it was already considered failed by the server topology (this could happen after all servers restarted or due to a long network outage between the client and servers). All continuous queries and remote event listeners created by this client will be unsubscribed, consider listening to EVT_CLIENT_NODE_RECONNECTED event to restore them.Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Stopped cache [cacheName=t_submit_id]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Stopped cache [cacheName=tevent]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Client node reconnected to topology: TcpDiscoveryNode [id=2d923f40-61de-4baa-b8c3-e2d7abba8582, consistentId=71df3af8-1955-4047-baa4-9978e4f50e5f, addrs=ArrayList [0:0:0:0:0:0:0:1%lo, 10.29.88.134, 127.0.0.1, 192.168.122.1], sockAddrs=HashSet [/192.168.122.1:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, hghphicprd08301/10.29.88.134:0], discPort=0, order=2, intOrder=0, lastExchangeTime=1595831847434, loc=true, ver=2.8.1#20200521-sha1:86422096, isClient=true]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Topology snapshot [ver=2, locNode=2d923f40, servers=1, clients=1, state=ACTIVE, CPUs=4, offheap=1.0GB, heap=13.0GB]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: ^-- Baseline [id=0, size=1, online=1, offline=0]2020-07-27 14:39:05.639 [mq-topic-11-3-14:103288] - [WARN] [EventCacheDaoIgniteImpl:] [] |ignite reconnect successfully||||2020-07-27 14:39:05.640 [mq-topic-11-3-18:103289] - [WARN] [EventCacheDaoIgniteImpl:] [] |ignite reconnect successfully||||2020-07-27 14:39:05.640 [mq-topic-11-3-16:103289] - [WARN] [EventCacheDaoIgniteImpl:] [] |ignite reconnect successfully||||2020-07-27 14:39:05.640 [mq-topic-11-3-15:103289] - [WARN] [EventCacheDaoIgniteImpl:] [] |ignite reconnect successfully||||2020-07-27 14:39:05.640 [mq-topic-14-7-9:103289] - [WARN] [EventCacheDaoIgniteImpl:] [] |ignite reconnect successfully||||Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger errorSEVERE: Failed to process custom exchange task: ClientCacheChangeDummyDiscoveryMessage [reqId=4796b72f-8291-425f-a9d0-59dbbbe049e6, cachesToClose=null, startCaches= [tevent]]java.lang.NullPointerException at org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.processClientCachesRequests(CacheAffinitySharedManager.java:665) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCustomExchangeTask(GridCacheProcessor.java:405) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.processCustomTask(GridCachePartitionExchangeManager.java:2997) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:3145) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:3063) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120) at java.lang.Thread.run(Thread.java:748)
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger errorSEVERE: Failed to process custom exchange task: ClientCacheChangeDummyDiscoveryMessage [reqId=a2f1a276-8a93-4a03-a6f4-af1ae15034f4, cachesToClose=null, startCaches= [tevent]]java.lang.NullPointerException at org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.processClientCachesRequests(CacheAffinitySharedManager.java:665) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCustomExchangeTask(GridCacheProcessor.java:405) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.processCustomTask(GridCachePartitionExchangeManager.java:2997) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:3145) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:3063) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120) at java.lang.Thread.run(Thread.java:748)
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger errorSEVERE: Failed to process custom exchange task: ClientCacheChangeDummyDiscoveryMessage [reqId=fe75171b-3cb7-41ed-9a4a-4da448a82de9, cachesToClose=null, startCaches= [tevent]]java.lang.NullPointerException at org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.processClientCachesRequests(CacheAffinitySharedManager.java:665) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCustomExchangeTask(GridCacheProcessor.java:405) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.processCustomTask(GridCachePartitionExchangeManager.java:2997) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:3145) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:3063) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120) at java.lang.Thread.run(Thread.java:748)
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger errorSEVERE: Failed to process custom exchange task: ClientCacheChangeDummyDiscoveryMessage [reqId=9ad699e3-89b3-41f1-8d0d-6c61be10f461, cachesToClose=null, startCaches= [tevent]]java.lang.NullPointerException at org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.processClientCachesRequests(CacheAffinitySharedManager.java:665) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCustomExchangeTask(GridCacheProcessor.java:405) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.processCustomTask(GridCachePartitionExchangeManager.java:2997) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:3145) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:3063) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120) at java.lang.Thread.run(Thread.java:748)
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger errorSEVERE: Failed to process custom exchange task: ClientCacheChangeDummyDiscoveryMessage [reqId=85d54eef-897c-4a3e-b9f5-3923afe8dde4, cachesToClose=null, startCaches= [tevent]]java.lang.NullPointerException at org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.processClientCachesRequests(CacheAffinitySharedManager.java:665) at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCustomExchangeTask(GridCacheProcessor.java:405) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.processCustomTask(GridCachePartitionExchangeManager.java:2997) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:3145) at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:3063) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120) at java.lang.Thread.run(Thread.java:748)
Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Received state change finish message: trueJul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Started exchange init [topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=2d923f40-61de-4baa-b8c3-e2d7abba8582, customEvt=null, allowMerge=true, exchangeFreeSwitch=false]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Components activation performed in 0 ms.Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Started cache [name=ignite-sys-cache, id=-2100569601, dataRegionName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Starting caches on local join performed in 0 ms.Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Established outgoing communication connection [locAddr=/0:0:0:0:0:0:0:1:35108, rmtAddr=/0:0:0:0:0:0:0:1%lo:47100]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Finished exchange init [topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], crd=false]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Received full message, will finish exchange [node=98a557e1-0638-486d-8939-4e09ce32726a, resVer=AffinityTopologyVersion [topVer=2, minorTopVer=0]]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Finish exchange future [startVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=false]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Finish proxy initialization, cacheName=ignite-sys-cache, localNodeId=2d923f40-61de-4baa-b8c3-e2d7abba8582Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Completed partition exchange [localNode=2d923f40-61de-4baa-b8c3-e2d7abba8582, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=2d923f40-61de-4baa-b8c3-e2d7abba8582, consistentId=71df3af8-1955-4047-baa4-9978e4f50e5f, addrs=ArrayList [0:0:0:0:0:0:0:1%lo, 10.29.88.134, 127.0.0.1, 192.168.122.1], sockAddrs=HashSet [/192.168.122.1:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, hghphicprd08301/10.29.88.134:0], discPort=0, order=2, intOrder=0, lastExchangeTime=1595831847434, loc=true, ver=2.8.1#20200521-sha1:86422096, isClient=true], done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0]]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Exchange timings [startVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Components activation" (0 ms), stage="Determine exchange type" (19 ms), stage="Waiting for Full message" (65 ms), stage="Affinity recalculation" (3 ms), stage="Full map updating" (1 ms), stage="Detect lost partitions" (0 ms), stage="Exchange done" (0 ms), stage="Total time" (88 ms)]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=2, minorTopVer=0], stage="Affinity initialization (local join) [grp=tevent]" (1 ms) (parent=Affinity recalculation), stage="Affinity initialization (local join) [grp=t_submit_id]" (0 ms) (parent=Affinity recalculation), stage="Affinity initialization (local join) [grp=t_migration_jobid]" (0 ms) (parent=Affinity recalculation)]Jul 27, 2020 2:39:05 PM org.apache.ignite.logger.java.JavaLogger infoINFO: Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=2, minorTopVer=0], rebTopVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], evt=NODE_JOINED, evtNode=2d923f40-61de-4baa-b8c3-e2d7abba8582, client=true]
--
This message was sent by Atlassian Jira
(v8.3.4#803005)