[DayZ] one instance connecting multiple times?

[PhilPhonic]

Hey,

opening the connection before the gameserver is ready (sometimes) seems to lead to multiple connections.

The code I'm using (excerpt):

try
{
	RconClient beClient = new(server.Ip, server.Port, server.Password);
	beClient.ReconnectInterval = 5000;
	beClient.Connected += (sender, args) => NetworkClient_Connected(sender, args);
	beClient.Disconnected += (sender, args) => NetworkClient_Disconnected(sender, args);
	beClient.MessageReceived += (sender, args) => NetworkClient_MessageReceived(sender, args);
	beClient.PlayerConnected += (sender, args) => NetworkClient_PlayerConnected(sender, args);
	beClient.PlayerDisconnected += (sender, args) => NetworkClient_PlayerDisconnected(sender, args);
	beClient.PlayerRemoved += (sender, args) => NetworkClient_PlayerRemoved(sender, args);

	bool initialConnectSuccessful = beClient.Connect();

	bool terminate = false;
	while (!terminate)
	{
		beClient.WaitUntilConnected();

		// [...]
		// do some stuff...
		// [...]

		Thread.Sleep(restartDelay * 1000);

		logger.Info("shutdown server...");
		beClient.Send(new ShutdownCommand());

		// the gameserver will be restarted by another program...

		Thread.Sleep(30000);
	}
}
catch (Exception ex)
{
	logger.Error(ex.ToString());
}

program output:

2022-11-04 08:53:03.266 INFO: Connected
2022-11-04 08:53:03.468 INFO: Server message: RCon admin #0 (127.0.0.1:57631) logged in
2022-11-04 08:53:03.468 INFO: Server message: RCon admin #0 (127.0.0.1:57631) logged in
2022-11-04 08:53:03.890 INFO: Server message: RCon admin #1 (127.0.0.1:37491) logged in
2022-11-04 08:53:03.890 INFO: Server message: RCon admin #1 (127.0.0.1:37491) logged in

gameserver output:

 8:53:03 Mission read.
 8:53:03 Connected to Steam
 8:53:03 Steam policy response
 8:53:03 BattlEye Server: RCon admin #0 (127.0.0.1:57631) logged in
 8:53:03 BattlEye Server: RCon admin #1 (127.0.0.1:37491) logged in

Both connections seem to be "alive", because both receive the NetworkClient_MessageReceived event (duplicates in program output).
However, one of those connections seems to "die", because after X seconds (can't tell exactly) there are no more duplicate log messages, just one per event (as expected).

Any ideas?

Thanks

[RyanTT]

Hi,

I noticed the client does not dispose of the network connection correctly if the connection is faulty/no longer used. Please try the following preview build if it manages to handle this better, unfortunately I currently have no server to test this myself yet:

https://www.nuget.org/packages/BytexDigital.BattlEye.Rcon/1.0.3-preview.1667557328

[PhilPhonic]

Hey,

thanks for the quick response. Running into an exception now:

A task was canceled.
   at BytexDigital.BattlEye.Rcon.NetworkConnection.Heartbeat()
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()

BytexDigital.BattlEye.Rcon
   bei BytexDigital.BattlEye.Rcon.NetworkConnection.<Heartbeat>d__22.MoveNext()
   bei System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs: Zeile1917
   bei System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs: Zeile979
   bei System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs: Zeile790
   bei System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs: Zeile63
   bei System.Threading.Thread.StartCallback() in /_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs: Zeile106

[RyanTT]

Hi, where exactly is this exception being thrown? From the call to Connect()?

[RyanTT]

Please let me know if this build fixes it for you https://www.nuget.org/packages/BytexDigital.BattlEye.Rcon/1.0.3-preview.1667665039

[PhilPhonic]

Hey,

that build seems to fix the issue. The exception is gone and I'm no longer seeing those multiple connections in my first tests.

[PhilPhonic]

Hey again,

seems like it's not completely fixed. Sometimes those multiple connections still appear. But only one seems to be alive, cause the NetworkClient_MessageReceived is only received once per login.

2022-11-06 16:01:29.073 INFO: Connected
2022-11-06 16:01:29.265 INFO: Server message: RCon admin #0 (127.0.0.1:43875) logged in
2022-11-06 16:01:29.573 INFO: Server message: RCon admin #1 (127.0.0.1:46393) logged in

2022-11-06 20:01:36.670 INFO: Connected
2022-11-06 20:01:37.038 INFO: Server message: RCon admin #0 (127.0.0.1:59162) logged in
2022-11-06 20:01:37.573 INFO: Server message: RCon admin #1 (127.0.0.1:49233) logged in
2022-11-06 20:01:37.762 INFO: Server message: RCon admin #2 (127.0.0.1:57370) logged in

[RyanTT]

I'm not sure how to handle this case, as I believe it is the OS/underlying code that has the UDP package be sent despite the .NET socket already being closed.

My assumption is that when the datagram is outbound for a localhost port, then Windows does not send the datagram until the port is available to receive it, and the package is buffered despite the UdpClient already being closed.

[RyanTT]

Please try this build https://www.nuget.org/packages/BytexDigital.BattlEye.Rcon/1.0.3-preview.1667929841

[PhilPhonic]

Thanks, will try that build.

ps: The tool and gameserver is running on Debian Linux

[PhilPhonic]

The problem still exists in the latest build.

2022-11-08 20:01:29.388 INFO: [livonia] Connected
2022-11-08 20:01:29.622 INFO: [livonia] Server message: RCon admin #0 (127.0.0.1:41556) logged in
2022-11-08 20:01:29.998 INFO: [livonia] Server message: RCon admin #1 (127.0.0.1:55404) logged in
2022-11-08 20:01:36.208 INFO: [chernarus] Connected
2022-11-08 20:01:36.442 INFO: [chernarus] Server message: RCon admin #0 (127.0.0.1:36568) logged in
2022-11-08 20:01:36.885 INFO: [chernarus] Server message: RCon admin #1 (127.0.0.1:44482) logged in
2022-11-08 20:01:37.089 INFO: [chernarus] Server message: RCon admin #2 (127.0.0.1:52965) logged in

[RyanTT]

I'm afraid I'm out of options to try. Is there any negative side effect from this happening?

[PhilPhonic]

No worries. I don't think there are any negative side effects (except those multiple logins). Only one of those connections seems to be alive since the events are only received once.

Thanks for fixing the main issue ;)