2.8.1 : INFO org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted incoming communication connection

[VeenaMithare]

Hi ,

If I stop and start a client application that is connected to a 3 node
server cluster within the failure detection timeout, I see a lot of these
messages on the console :

INFO  org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] -
Accepted incoming communication connection

The count of these messages varies between 600 to 800 .  I did not see these
messages coming in 2.7.6. Why are they showing up in 2.8.1. Do I need to
tune anything to avoid this ?

A sample of the same below :

2020-08-28 08:43:03,614 [main] INFO
com.company.project.projectstore.client.ListenerClient [] - Test message
2020-08-28 08:43:03,644
[grid-nio-worker-tcp-comm-15-#87%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52883]
2020-08-28 08:43:03,644
[grid-nio-worker-tcp-comm-0-#72%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52884]
2020-08-28 08:43:03,695
[grid-nio-worker-tcp-comm-1-#73%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52885]
2020-08-28 08:43:03,695
[grid-nio-worker-tcp-comm-2-#74%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52886]
2020-08-28 08:43:03,747
[grid-nio-worker-tcp-comm-3-#75%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52887]
2020-08-28 08:43:03,748
[grid-nio-worker-tcp-comm-4-#76%client-null-igniteclient-SINGLE%] INFO
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted
incoming communication connection [locAddr=/127.0.0.1:47105,
rmtAddr=/127.0.0.1:52888]



regards,
Veena.





--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[akurbanov]

Hello Veena,

It would make sense to check for the other node logs, because it's the other
node that tries to initiate communication connection with this one.

The clue for the reason why is it trying to connect might be in other node
log.

Best regards,
Anton



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

HI Anton,

The setup I am working on is as below :
server nodes : 3
client : 1

I get these logs when I start the client node within 10 secs of stopping it.
There is no clue on the server nodes as to why these logs are printed.

It looks as if the client node that was killed, is trying to join back ,
since it was not marked as DEAD yet by the servers.

It is very easy to reproduce this. Stop and start any client node within 10
seconds of stopping it.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

Can you please perhaps share a reproducer project?

Regards,

вт, 29 сент. 2020 г. в 19:34, VeenaMithare <[hidden email]>:

HI Anton,

The setup I am working on is as below :
server nodes : 3
client : 1

I get these logs when I start the client node within 10 secs of stopping it.
There is no clue on the server nodes as to why these logs are printed.

It looks as if the client node that was killed, is trying to join back ,
since it was not marked as DEAD yet by the servers.

It is very easy to reproduce this. Stop and start any client node within 10
seconds of stopping it.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Hi Ilya,

This is easy to reproduce. Have a server node and a client node in a
cluster. Stop and start the client immediately so that the start happens
within the failure detection timeout ( 10 sec typically ). You will see
these messages in the client log as it is starting up the second time.

Let me know if you still need a reproducer.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

We have a lot of tests which do exactly that, and they don't seem to exhibit that behavior. Please provide a reproducer.

Regards,

вт, 3 нояб. 2020 г. в 11:13, VeenaMithare <[hidden email]>:

Hi Ilya,

This is easy to reproduce. Have a server node and a client node in a
cluster. Stop and start the client immediately so that the start happens
within the failure detection timeout ( 10 sec typically ). You will see
these messages in the client log as it is starting up the second time.

Let me know if you still need a reproducer.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Hi Ilya,

Please find the reproducer project attached.

Steps to reproduce :
1. Run the server.java
2. Run the ListenerClient.java. Wait till it starts fully.
3. Stop and start the client again ( within the failuredetectiontimeout of
10 secs. )

You will see these logs on the console.

Another thing I noticed today is that , the logs seem to be connected to
this code in Server.java
            ignite.active(true);
            addPersistentCacheConfiguration(
                    ignite);

If I comment out the above lines and try the steps above, I dont get those
logs.

regards,
Veena. ClientConnectProject.zip
<http://apache-ignite-users.70518.x6.nabble.com/file/t2757/ClientConnectProject.zip>  







--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Hi Ilya,

Did you get a chance to look in to this ..?

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

This issue is also observed if two different clients exist on the same box.
Steps to reproduce  :

1. Both the clients are not running
2. Start the client1
3. Stop the client 1 and start client 2 .
4. The huge set of logs are visible on client 2 logs.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

Maybe it's some kind of Windows thing or otherwise depends on your environment? I have tried to run your reproducer, but I never get these exceptions. Instead, I will only see:

янв 13, 2021 6:38:56 PM org.apache.ignite.logger.java.JavaLogger info
INFO: Accepted incoming communication connection [locAddr=/0:0:0:0:0:0:0:1:47100, rmtAddr=/0:0:0:0:0:0:0:1:34890]

Once on the server node after client restart.

Regards,

вт, 12 янв. 2021 г. в 18:11, VeenaMithare <[hidden email]>:

This issue is also observed if two different clients exist on the same box.
Steps to reproduce  :

1. Both the clients are not running
2. Start the client1
3. Stop the client 1 and start client 2 .
4. The huge set of logs are visible on client 2 logs.

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Kindly confirm the below :

a. Are you on :2.8.1
b. Is this code uncommented :
     ignite.active(true);
            addPersistentCacheConfiguration(
                    ignite);
c. using both server and client on the reproducer?
d. Did the client start and stop happen within in 10 secs.

I get this on all env. ( even in our linux env. )
Also I am able to reproduce this consistently on the attached reproducer. The only time I dont get this is when ignite.active or control.sh --activate is not invoked ( Since ignite.active(true); is deprecated, a manual activation can be done as well . This issue is observed even with a manual activation )


--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

I am using your reproducer and I did not change dependencies, so I assume it's on 2.8.1 if your reproducer uses it.

Yes, I'm running both server and client from the reproducer.

Maybe you could record a screencast where you run it and get the result that you describe?

Regards,

ср, 13 янв. 2021 г. в 19:14, VeenaMithare <[hidden email]>:

Kindly confirm the below :

a. Are you on :2.8.1
b. Is this cod uncommented :
     ignite.active(true);
            addPersistentCacheConfiguration(
                    ignite);
c. using both server and client on the reproducer?

I get this on all env. ( even in our linux env. )



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Hi Ilya,

Please find the video recording of the issue I face.

https://drive.google.com/file/d/1fDqxmgjiL3o_eenHoUosdiYlMMBJ4xVj/view?usp=sharing

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

It's interesting, but I still can't reproduce the issue. Does not seem to happen to me.

Maybe somebody else will chime in.

Regards,

чт, 14 янв. 2021 г. в 20:47, VeenaMithare <[hidden email]>:

Hi Ilya,

Please find the video recording of the issue I face.

https://drive.google.com/file/d/1fDqxmgjiL3o_eenHoUosdiYlMMBJ4xVj/view?usp=sharing

regards,
Veena.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

The reproducer code works fine on my home mac ( I dont see the 100s of logs)
- so not sure if the issue is because of
a. Change in OS - at home I use mac and office it is windows/linux.
b. Change in the network ( between my home and office )

Any thoughts on how I can debug further  ?



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[ilya.kasnacheev]

Hello!

Network may be relevant here.

Can you try disconnect from your network (turn off wi/fi, unplug ethernet) and re-try?

Regards,

вт, 19 янв. 2021 г. в 12:45, VeenaMithare <[hidden email]>:

The reproducer code works fine on my home mac ( I dont see the 100s of logs)
- so not sure if the issue is because of
a. Change in OS - at home I use mac and office it is windows/linux.
b. Change in the network ( between my home and office )

Any thoughts on how I can debug further  ?



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[VeenaMithare]

Unfortunately , will be difficult to try this - since we are working from
home and are connected to office network through citrix .



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[alexey.plotnik]

VeenaMithare wrote

The reproducer code works fine on my home mac ( I dont see the 100s of logs) - so not sure if the issue is because of a. Change in OS - at home I use mac and office it is windows/linux. b. Change in the network ( between my home and office ) Any thoughts on how I can debug further ? -- Sent from: http://apache-ignite-users.70518.x6.nabble.com/

Hi there. It's reproduced both in Intellij Idea and from cmd on Win 10. It's NOT reproduced on Linux cli. What happens here: server node does not receive TcpDiscoveryNodeLeftMessage to let client node left the cluster. Instead client app is killed, server node understands it and try to reconnect, client node continues stay in topology and if yo start it in short time you will see in server logs a lot of handshake errors

DEBUG org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Client creation failed [addr=/127.0.0.1:47101, err=class org.apache.ignite.spi.communication.tcp.internal.HandshakeException: Remote node ID is not as expected [expected=f3038b2c-78d1-4a9d-80ef-800f06a92a8b, rcvd=bc6ae633-b643-44ba-afab-321dbf01aaf1]]

and in client log a lot of

INFO  org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Accepted incoming communication connection ...
INFO  org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Sending local node ID (bc6ae633-b643-44ba-afab-321dbf01aaf1 to newly accepted session ...
DEBUG org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi [] - Remote client closed connection ...

You can see client node sends old Node ID. It looks like server node does not receive "TcpDiscoveryNodeLeftMessage" message from client when you stop the client app. When stopped from Idea or by closing CMD window the target process does not receive SIGINT signal. You can try to stop the client app on windows with "Ctrl-C" shortcut, then client will send left node message, you will see it in client logs:

[INFO ][Thread-4][G] Invoking shutdown hook...

then in server logs:

[TcpDiscoverySpi] Message has been received: TcpDiscoveryNodeLeftMessage

When using IDEA please try to run client app in debug mode, it sends SIGINT signal to app when you click "Stop" button. Anyway when running on Linux I cant reproduce the same behaviour when stopping the client process with something like "kill -9". I'll try the situation whne number of client nodes is more than one.

---

Sent from the Apache Ignite Users mailing list archive at Nabble.com.

[VeenaMithare]

Hi Alexey,

I am able to reproduce this on my linux env. by doing a kill -9 .  Please
find the logs from my linux env. attached.
temp.log
<http://apache-ignite-users.70518.x6.nabble.com/file/t2757/temp.log>  
Also note in our linux env. we have dual ip for our boxes - not sure if that
contributes to this issue.

Also I do not see this log in the INFO mode in our client logs :
Sending local node ID (bc6ae633-b643-44ba-afab-321dbf01aaf1 to newly
accepted session ...

I will try shutting down the client with ctrl+c on windows and check if that
helps.

regards,
Veena.





--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

[alexey.plotnik]

Could you plz attach DEBUG log of the server node running on Linux machine
from the moment server starts until client re-connect after being stopped?
So, full logs basically



-----
Alexey Plotnik
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/