You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by Dmitry Lazurkin <di...@gmail.com> on 2018/11/20 12:44:28 UTC
Client stucks and doesn't connect
Hello.
Ignite client stops connecting to server after exception:
2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
(Connection refused)
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
at
org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
[addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
Connection refused (Connection refused)]]
2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
[msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], addr=/10.48.14.1:47500,
rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
[addr=/10.48.14.1:47500, res=100]
2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
[msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], addr=/10.48.14.1:47500,
rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
[addr=/10.48.14.1:47500, res=1]
2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
[success=false, msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
pendingIdx=0, failedNodes=null, isClient=true]]]
2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
tcp-client-disco-reconnector-#5
2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
will try to reconnect [networkTimeout=360000, joinTimeout=0, failMsg=null]
2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
[node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
addrs=[10.37.92.216],
sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
type=CLIENT_NODE_DISCONNECTED, topVer=6]
2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
will try to reconnect with new id
[newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
[id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=false,
locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
java.lang.NullPointerException: null
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
tcp-client-disco-msg-worker-#4
2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
[super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], failureDetectionTimeout=360000]
2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
java.io.IOException: Failed to get acknowledge for message:
TcpDiscoveryClientMetricsUpdateMessage
[super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]]
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
Re: Client stucks and doesn't connect
Posted by Dmitry Lazurkin <di...@gmail.com>.
Hello.
I use version 2.6.0#20180710-sha1:669feacc and I can not reproduce this
issue. I have seen it at least 2 times, and I don't have full log =/ .
My cluster has lazy disk so restoration of partition states is too slow.
So I think there is race condition between ClientImpl and call of
TcpDiscoverySpi.onContextInitialized on client when it try to connect to
server which restores partition states.
On 11/29/18 14:03, Stanislav Lukyanov wrote:
>
> Hi,
>
>
>
> The interesting (and disappointing) part is the NPE:
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
>
>
> Which version do you use?
>
> Is this reproducible? Every time?
>
>
>
> Thanks,
>
> Stan
>
>
>
>
>
> *From: *Dmitry Lazurkin <ma...@gmail.com>
> *Sent: *20 ноября 2018 г. 15:44
> *To: *user@ignite.apache.org <ma...@ignite.apache.org>
> *Subject: *Client stucks and doesn't connect
>
>
>
> Hello.
>
>
>
> Ignite client stops connecting to server after exception:
>
>
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
>
> (Connection refused)
>
> java.net.ConnectException: Connection refused (Connection refused)
>
> at java.net.PlainSocketImpl.socketConnect(Native Method)
>
> at
>
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
>
> at
>
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
>
> at
>
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
>
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
>
> at java.net.Socket.connect(Socket.java:589)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
>
> [addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
>
> Connection refused (Connection refused)]]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=100]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
>
> 2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=1]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
>
> [success=false, msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
>
> pendingIdx=0, failedNodes=null, isClient=true]]]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-reconnector-#5
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
>
> will try to reconnect [networkTimeout=360000, joinTimeout=0, failMsg=null]
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
>
> [node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
>
> type=CLIENT_NODE_DISCONNECTED, topVer=6]
>
> 2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
>
> will try to reconnect with new id
>
> [newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
>
> prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
>
> [id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=false,
>
> locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
>
> runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-msg-worker-#4
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
>
> will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], failureDetectionTimeout=360000]
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
>
> java.io.IOException: Failed to get acknowledge for message:
>
> TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]]
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
>
>
>
>
Re: Client stucks and doesn't connect
Posted by Dmitry Lazurkin <di...@gmail.com>.
Issue with patch: https://issues.apache.org/jira/browse/IGNITE-10513
On 12/3/18 17:43, Dmitry Lazurkin wrote:
> OK. I have found steps to reproduce.
>
> For reproducing we need Ignite with slow disk. Or I known how to
> emulate slow hard disk:
>
> Add to partitions cycle in
> GridCacheDatabaseSharedManager#restorePartitionStates:
> //...
> for (int i = 0; i < grp.affinity().partitions(); i++) {
> try {
> log.error("Wait");
> Thread.sleep(10000);
> } catch (InterruptedException e) {
> e.printStackTrace();
> }
> //...
>
> - Now we can start server
> - Then start client
> - Wait message "Join cluster while cluster state transition is in
> progress, waiting when transition finish."
> - Kill server
> - Wait repeatable exception java.net.ConnectException: Connection
> refused (Connection refused)
> - Start server and I have 100% chance to reproduce on my computer
>
> Thank you.
>
> On 11/29/18 14:03, Stanislav Lukyanov wrote:
>>
>> Hi,
>>
>>
>>
>> The interesting (and disappointing) part is the NPE:
>>
>> java.lang.NullPointerException: null
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>>
>>
>>
>> Which version do you use?
>>
>> Is this reproducible? Every time?
>>
>>
>>
>> Thanks,
>>
>> Stan
>>
>>
>>
>>
>>
>> *From: *Dmitry Lazurkin <ma...@gmail.com>
>> *Sent: *20 ноября 2018 г. 15:44
>> *To: *user@ignite.apache.org <ma...@ignite.apache.org>
>> *Subject: *Client stucks and doesn't connect
>>
>>
>>
>> Hello.
>>
>>
>>
>> Ignite client stops connecting to server after exception:
>>
>>
>>
>> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>>
>> [/10.48.14.1:47500]
>>
>> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>>
>> [addr=/10.48.14.1:47500, reconnect=true,
>>
>> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>>
>> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
>>
>> (Connection refused)
>>
>> java.net.ConnectException: Connection refused (Connection refused)
>>
>> at java.net.PlainSocketImpl.socketConnect(Native Method)
>>
>> at
>>
>> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
>>
>> at
>>
>> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
>>
>> at
>>
>> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
>>
>> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
>>
>> at java.net.Socket.connect(Socket.java:589)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
>>
>> at
>>
>> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>>
>> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
>>
>> [addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
>>
>> Connection refused (Connection refused)]]
>>
>> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>>
>> [/10.48.14.1:47500]
>>
>> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>>
>> [addr=/10.48.14.1:47500, reconnect=true,
>>
>> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>>
>> 2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>>
>> [msg=TcpDiscoveryClientReconnectMessage
>>
>> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>>
>> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>>
>> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>>
>> id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>>
>> isClient=true]], addr=/10.48.14.1:47500,
>>
>> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>>
>> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>>
>> [addr=/10.48.14.1:47500, res=100]
>>
>> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
>>
>> 2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>>
>> [addr=/10.48.14.1:47500, reconnect=true,
>>
>> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>>
>> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>>
>> [msg=TcpDiscoveryClientReconnectMessage
>>
>> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>>
>> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>>
>> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>>
>> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>>
>> isClient=true]], addr=/10.48.14.1:47500,
>>
>> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>>
>> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>>
>> [addr=/10.48.14.1:47500, res=1]
>>
>> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
>>
>> [success=false, msg=TcpDiscoveryClientReconnectMessage
>>
>> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>>
>> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>>
>> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>>
>> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
>>
>> pendingIdx=0, failedNodes=null, isClient=true]]]
>>
>> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>>
>> tcp-client-disco-reconnector-#5
>>
>> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
>>
>> will try to reconnect [networkTimeout=360000, joinTimeout=0,
>> failMsg=null]
>>
>> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
>>
>> [node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> addrs=[10.37.92.216],
>>
>> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>>
>> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>>
>> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
>>
>> type=CLIENT_NODE_DISCONNECTED, topVer=6]
>>
>> 2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
>>
>> will try to reconnect with new id
>>
>> [newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
>>
>> prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
>>
>> [id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
>>
>> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>>
>> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>>
>> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
>>
>> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>>
>> [/10.48.14.1:47500]
>>
>> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>>
>> [addr=/10.48.14.1:47500, reconnect=false,
>>
>> locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
>>
>> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
>>
>> runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
>>
>> java.lang.NullPointerException: null
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>>
>> at
>>
>> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>>
>> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>>
>> tcp-client-disco-msg-worker-#4
>>
>> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
>>
>> will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
>>
>> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>>
>> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>>
>> isClient=true]], failureDetectionTimeout=360000]
>>
>> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
>>
>> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
>>
>> java.io.IOException: Failed to get acknowledge for message:
>>
>> TcpDiscoveryClientMetricsUpdateMessage
>>
>> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>>
>> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>>
>> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>>
>> isClient=true]]
>>
>> at
>>
>> org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
>>
>> at
>>
>> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>>
>>
>>
>>
>>
>
Re: Client stucks and doesn't connect
Posted by Dmitry Lazurkin <di...@gmail.com>.
OK. I have found steps to reproduce.
For reproducing we need Ignite with slow disk. Or I known how to emulate
slow hard disk:
Add to partitions cycle in
GridCacheDatabaseSharedManager#restorePartitionStates:
//...
for (int i = 0; i < grp.affinity().partitions(); i++) {
try {
log.error("Wait");
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
//...
- Now we can start server
- Then start client
- Wait message "Join cluster while cluster state transition is in
progress, waiting when transition finish."
- Kill server
- Wait repeatable exception java.net.ConnectException: Connection
refused (Connection refused)
- Start server and I have 100% chance to reproduce on my computer
Thank you.
On 11/29/18 14:03, Stanislav Lukyanov wrote:
>
> Hi,
>
>
>
> The interesting (and disappointing) part is the NPE:
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
>
>
> Which version do you use?
>
> Is this reproducible? Every time?
>
>
>
> Thanks,
>
> Stan
>
>
>
>
>
> *From: *Dmitry Lazurkin <ma...@gmail.com>
> *Sent: *20 ноября 2018 г. 15:44
> *To: *user@ignite.apache.org <ma...@ignite.apache.org>
> *Subject: *Client stucks and doesn't connect
>
>
>
> Hello.
>
>
>
> Ignite client stops connecting to server after exception:
>
>
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
>
> (Connection refused)
>
> java.net.ConnectException: Connection refused (Connection refused)
>
> at java.net.PlainSocketImpl.socketConnect(Native Method)
>
> at
>
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
>
> at
>
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
>
> at
>
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
>
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
>
> at java.net.Socket.connect(Socket.java:589)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
>
> [addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
>
> Connection refused (Connection refused)]]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=100]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
>
> 2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=1]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
>
> [success=false, msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
>
> pendingIdx=0, failedNodes=null, isClient=true]]]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-reconnector-#5
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
>
> will try to reconnect [networkTimeout=360000, joinTimeout=0, failMsg=null]
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
>
> [node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
>
> type=CLIENT_NODE_DISCONNECTED, topVer=6]
>
> 2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
>
> will try to reconnect with new id
>
> [newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
>
> prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
>
> [id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=false,
>
> locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
>
> runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-msg-worker-#4
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
>
> will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], failureDetectionTimeout=360000]
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
>
> java.io.IOException: Failed to get acknowledge for message:
>
> TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]]
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
>
>
>
>
Re: Client stucks and doesn't connect
Posted by Dmitry Lazurkin <di...@gmail.com>.
Hello.
I use version 2.6.0#20180710-sha1:669feacc and I can not reproduce this
issue. I have seen it at least 2 times, and I don't have full log =/ .
My cluster has lazy disk so restoration of partition states is too slow.
So I think there is race condition between ClientImpl and call of
TcpDiscoverySpi.onContextInitialized on client when it try to connect to
server which restores partition states.
PS. Sorry for duplicated messages.
On 11/29/18 14:03, Stanislav Lukyanov wrote:
>
> Hi,
>
>
>
> The interesting (and disappointing) part is the NPE:
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
>
>
> Which version do you use?
>
> Is this reproducible? Every time?
>
>
>
> Thanks,
>
> Stan
>
>
>
>
>
> *From: *Dmitry Lazurkin <ma...@gmail.com>
> *Sent: *20 ноября 2018 г. 15:44
> *To: *user@ignite.apache.org <ma...@ignite.apache.org>
> *Subject: *Client stucks and doesn't connect
>
>
>
> Hello.
>
>
>
> Ignite client stops connecting to server after exception:
>
>
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
>
> (Connection refused)
>
> java.net.ConnectException: Connection refused (Connection refused)
>
> at java.net.PlainSocketImpl.socketConnect(Native Method)
>
> at
>
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
>
> at
>
> java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
>
> at
>
> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
>
> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
>
> at java.net.Socket.connect(Socket.java:589)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
>
> [addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
>
> Connection refused (Connection refused)]]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=100]
>
> 2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
>
> 2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=true,
>
> locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
>
> [msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], addr=/10.48.14.1:47500,
>
> rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
>
> 2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
>
> [addr=/10.48.14.1:47500, res=1]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
>
> [success=false, msg=TcpDiscoveryClientReconnectMessage
>
> [routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
>
> lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
>
> super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
>
> pendingIdx=0, failedNodes=null, isClient=true]]]
>
> 2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-reconnector-#5
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
>
> will try to reconnect [networkTimeout=360000, joinTimeout=0, failMsg=null]
>
> 2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
>
> [node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
>
> type=CLIENT_NODE_DISCONNECTED, topVer=6]
>
> 2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
>
> will try to reconnect with new id
>
> [newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
>
> prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
>
> [id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
>
> sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
>
> discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
>
> loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
>
> [/10.48.14.1:47500]
>
> 2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
>
> [addr=/10.48.14.1:47500, reconnect=false,
>
> locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
>
> runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
>
> java.lang.NullPointerException: null
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
> 2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
>
> tcp-client-disco-msg-worker-#4
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
>
> will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]], failureDetectionTimeout=360000]
>
> 2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
>
> o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
>
> java.io.IOException: Failed to get acknowledge for message:
>
> TcpDiscoveryClientMetricsUpdateMessage
>
> [super=TcpDiscoveryAbstractMessage [sndNodeId=null,
>
> id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
>
> verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
>
> isClient=true]]
>
> at
>
> org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
>
> at
>
> org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
>
>
>
>
>
RE: Client stucks and doesn't connect
Posted by Stanislav Lukyanov <st...@gmail.com>.
Hi,
The interesting (and disappointing) part is the NPE:
java.lang.NullPointerException: null
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
Which version do you use?
Is this reproducible? Every time?
Thanks,
Stan
From: Dmitry Lazurkin
Sent: 20 ноября 2018 г. 15:44
To: user@ignite.apache.org
Subject: Client stucks and doesn't connect
Hello.
Ignite client stops connecting to server after exception:
2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:49,257 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Exception on joining: Connection refused
(Connection refused)
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1450)
at
org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.openSocket(TcpDiscoverySpi.java:1413)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:637)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$Reconnector.body(ClientImpl.java:1408)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
2018-11-19 16:00:49,258 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to join to address
[addr=/10.48.14.1:47500, recon=true, errs=[java.net.ConnectException:
Connection refused (Connection refused)]]
2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:51,344 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:51,364 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
[msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=48722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], addr=/10.48.14.1:47500,
rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
[addr=/10.48.14.1:47500, res=100]
2018-11-19 16:00:51,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Will wait before retry join.
2018-11-19 16:00:53,365 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=true,
locNodeId=cd323c53-d1de-4608-8eec-e373b1f68b71]
2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Message has been sent to address
[msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], addr=/10.48.14.1:47500,
rmtNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20]
2018-11-19 16:00:53,368 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received response to join request
[addr=/10.48.14.1:47500, res=1]
2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Received reconnect response
[success=false, msg=TcpDiscoveryClientReconnectMessage
[routerNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20,
lastMsgId=c42b1bc2761-bbc61e78-97e8-49cd-844e-2dc3e8aacc68,
super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=a8722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=9c68d70f-883e-4a21-938b-05f3f6f98d20, topVer=0,
pendingIdx=0, failedNodes=null, isClient=true]]]
2018-11-19 16:00:53,372 [tcp-client-disco-reconnector-#5] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
tcp-client-disco-reconnector-#5
2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to restore closed connection,
will try to reconnect [networkTimeout=360000, joinTimeout=0, failMsg=null]
2018-11-19 16:00:53,373 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Discovery notification
[node=TcpDiscoveryNode [id=cd323c53-d1de-4608-8eec-e373b1f68b71,
addrs=[10.37.92.216],
sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true],
type=CLIENT_NODE_DISCONNECTED, topVer=6]
2018-11-19 16:00:53,443 [tcp-client-disco-msg-worker-#4] INFO
o.a.i.s.d.tcp.TcpDiscoverySpi - Client node disconnected from cluster,
will try to reconnect with new id
[newId=af2e6c3b-7d68-44f6-ad64-e403e560b800,
prevId=cd323c53-d1de-4608-8eec-e373b1f68b71, locNode=TcpDiscoveryNode
[id=cd323c53-d1de-4608-8eec-e373b1f68b71, addrs=[10.37.92.216],
sockAddrs=[kafka-ignite-streamer-5bdb96f7d6-dfbhc/10.37.92.216:0],
discPort=0, order=5, intOrder=0, lastExchangeTime=1542643135842,
loc=true, ver=2.6.0#20180710-sha1:669feacc, isClient=true]]
2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Resolved addresses from IP finder:
[/10.48.14.1:47500]
2018-11-19 16:00:53,482 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Send join request
[addr=/10.48.14.1:47500, reconnect=false,
locNodeId=af2e6c3b-7d68-44f6-ad64-e403e560b800]
2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Runtime error caught during grid
runnable execution: IgniteSpiThread [name=tcp-client-disco-msg-worker-#4]
java.lang.NullPointerException: null
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.sendJoinRequest(ClientImpl.java:666)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.joinTopology(ClientImpl.java:546)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl.access$900(ClientImpl.java:128)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.tryJoin(ClientImpl.java:1846)
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$MessageWorker.body(ClientImpl.java:1757)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
2018-11-19 16:00:53,553 [tcp-client-disco-msg-worker-#4] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Grid runnable finished normally:
tcp-client-disco-msg-worker-#4
2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] DEBUG
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to get acknowledge for message,
will try to reconnect [msg=TcpDiscoveryClientMetricsUpdateMessage
[super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]], failureDetectionTimeout=360000]
2018-11-19 16:06:27,487 [tcp-client-disco-sock-writer-#2] ERROR
o.a.i.s.d.tcp.TcpDiscoverySpi - Failed to send message: null
java.io.IOException: Failed to get acknowledge for message:
TcpDiscoveryClientMetricsUpdateMessage
[super=TcpDiscoveryAbstractMessage [sndNodeId=null,
id=47722bc2761-cd323c53-d1de-4608-8eec-e373b1f68b71,
verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null,
isClient=true]]
at
org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1302)
at
org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)