bug when scripts recognizes a new serverVersion

[gekigek99]

I am currently testing some different configurations and encountered a different bug in the main go script.
@gekigek99 should I open a new issue for this?
I am using 1.16.2 and with the current code and only changed debug to true.

Originally posted by @lubocode in #31 (comment)

[gekigek99]

@lubocode I update 10 minutes ago the script with major changes for that exact part of the script, could you try with the new version? (since it's worthless solving a problem if it does not exist anymore ahaha)

[lubocode]

2020/10/01 21:27:56  server version found! serverVersion: 1.14.4 serverProtocol: 498
2020/10/01 21:27:56 saved to config.json
panic: runtime error: index out of range [1] with length 1

goroutine 75 [running]:
main.forwardSync(0x345220, 0xc0000060b8, 0x345220, 0xc0000060b0, 0x31ff01)
        C:/Users/Lukas/Code/minecraft-vanilla-server-hibernation/go-version/minecraft-vanilla-server-hibernation.go:317 +0xfc5
main.serverToClient(0x345220, 0xc0000060b8, 0x345220, 0xc0000060b0)
        C:/Users/Lukas/Code/minecraft-vanilla-server-hibernation/go-version/minecraft-vanilla-server-hibernation.go:280 +0x55
created by main.connectSocketsAsync
        C:/Users/Lukas/Code/minecraft-vanilla-server-hibernation/go-version/minecraft-vanilla-server-hibernation.go:260 +0xa8

[lubocode]

I have only encountered this problem on Windows for now.
I do not (yet) have a separate Linux installation and WSL has some other problems already during connection establishment.

[lubocode]

Same error, but this time without any version detection. Still running under Win 10.
After disconnecting there is a server join message without any actual players joining.

2020/10/01 21:37:42 *** MINECRAFT SERVER IS UP!
2020/10/01 21:37:49 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/01 21:37:49 *** A PLAYER JOINED THE SERVER! - 1 players online
2020/10/01 21:37:49 data/s:    0.169 KB/s to clients |    0.291 KB/s to server
...
2020/10/01 21:37:57 data/s:   31.998 KB/s to clients |    0.074 KB/s to server
2020/10/01 21:37:57 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/01 21:37:57 *** A PLAYER LEFT THE SERVER! - 0 players online
2020/10/01 21:37:57 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/01 21:37:57 *** A PLAYER JOINED THE SERVER! - 1 players online
panic: runtime error: index out of range [1] with length 1

[lubocode]

2020/10/01 21:27:56 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/01 21:27:56 *** A PLAYER LEFT THE SERVER! - 0 players online
2020/10/01 21:27:56 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/01 21:27:56 *** A PLAYER JOINED THE SERVER! - 1 players online
2020/10/01 21:27:56  server version found! serverVersion: 1.14.4 serverProtocol: 498
2020/10/01 21:27:56 saved to config.json
panic: runtime error: index out of range [1] with length 1

The same seems to have happened before the other two crashes

[gekigek99]

I have only encountered this problem on Windows for now.
I do not (yet) have a separate Linux installation and WSL has some other problems already during connection establishment.

aaaaa ok ok... because on linux it works normally

i'll try to reproduce the issue

[gekigek99]

logger(
	"server version found!",
	"serverVersion:", config.Advanced.ServerVersion,
	"serverProtocol:", config.Advanced.ServerProtocol)
	
configData, err := json.MarshalIndent(config, "", "  ")
if err != nil {
	logger("forwardSync: could not marshal configuration")
	continue
}
err = ioutil.WriteFile("config.json", configData, 0644)
if err != nil {
	logger("forwardSync: could not update config.json")
	continue
}
logger("saved to config.json")

so, we know that it works until "server version found!"... you could try to remove the part after and see what happens?

Does it always throw this error or just sometimes?

[lubocode]

logger(
	"server version found!",
	"serverVersion:", config.Advanced.ServerVersion,
	"serverProtocol:", config.Advanced.ServerProtocol)
	
configData, err := json.MarshalIndent(config, "", "  ")
if err != nil {
	logger("forwardSync: could not marshal configuration")
	continue
}
err = ioutil.WriteFile("config.json", configData, 0644)
if err != nil {
	logger("forwardSync: could not update config.json")
	continue
}
logger("saved to config.json")

so, we know that it works until "server version found!"... you could try to remove the part after and see what happens?

Does it always throw this error or just sometimes?

Yes and no. As stated above, I had one instance, where there was no server version detected and it still crashed.
It seems to be registering a user who connects, when there is none.

I will try out removing some code tomorrow.

[gekigek99]

I had one instance, where there was no server version detected and it still crashed.

keep in mind that the message is shown only the firt time and if the captured version is different from the json data

It seems to be registering a user who connects, when there is none.

i remind you that when serverStatus == "online" and info are requested to server the script will interpret the connection as a player joining and leaving for half a second --> is that the case?

I will try out removing some code tomorrow.

ok but i would not count a lot on that since is not very repetible... still it's worth trying

[lubocode]

I had one instance, where there was no server version detected and it still crashed.

keep in mind that the message is shown only the firt time and if the captured version is different from the json data

Ah, ok, that would explain that.

It seems to be registering a user who connects, when there is none.

i remind you that when serverStatus == "online" and info are requested to server the script will interpret the connection as a player joining and leaving for half a second --> is that the case?

Useful info. After leaving the server, that would indeed happen every time as one is coming back to the server overview window for which the info gets requested automatically.

Judging by the error message, the problem occurs on line 317 newServerVersion := string(bytes.Split(bytes.Split(data[:dataLen], []byte("{\"name\":\""))[1], []byte("\","))[0]) during the second entry of that if conditional.
Upon first entering the conditional, the server version and protocol get registered normally and saved into the config, but for whatever reason, the conditional is entered again and the byte array []byte("{\"name\":\""))[1] doesn't have two elements anymore, such that an access with [1] is out of range. Maybe the conditions for entering are insufficient in guarding or a variable that should be changed/reset at the end of that if bracket is not changed.
Without comments in the code it would take me too long to go through the whole function manually right now, so I have to leave you with my (possibly completely wrong) thoughts before coming back mid next week, where we can also talk about this in more detail.

And again, as said before: The docker problem is indeed quite a fatal problem, but not pressing, as it does not impact the working state of the latest released docker version. This problem right here however, might impact more people that try downloading the script from the repository directly instead of from the release page and run it on Windows.
But in the end it's your repo, so just do whatever you feel like^^ Good luck with everything and until next week.

[gekigek99]

Upon first entering the conditional, the server version and protocol get registered normally and saved into the config, but for whatever reason, the conditional is entered again and the byte array []byte("{"name":""))[1] doesn't have two elements anymore, such that an access with [1] is out of range. Maybe the conditions for entering are insufficient in guarding or a variable that should be changed/reset at the end of that if bracket is not changed.

now that is a very brilliant interpretation! I completely agree and i hope it's just this because in this case should be an easy fix
(still on my setup it does not happen... but I'll change some things so that you can test and see if the problem presents itself again)

Without comments in the code it would take me too long to go through the whole function manually right now

I know I will open an issue regarding documentation ahah (#36)

[gekigek99]

Copyright (C) 2019-2020 gekigek99
v3.4 (Go)
visit my github page: https://github.com/gekigek99
2020/10/02 22:23:04 *** listening for new clients to connect...
2020/10/02 22:23:23 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/02 22:23:23 *** A PLAYER JOINED THE SERVER! - 1 players online
server to client: ����{"description":{"text":"§fServer status:§r\n                  §b§l§oHIBERNATING"},"players":{"max":20,"online":0},"version":{"name":"1.16.3","protocol":753}}
2020/10/02 22:23:23 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/02 22:23:23 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/02 22:23:23 *** A PLAYER LEFT THE SERVER! - 0 players online
2020/10/02 22:23:23 data/s:    0.173 KB/s to clients |    0.028 KB/s to server

this is the log (with capture of the first packet the server is responding with (for an info request))

i really cannot reproduce the issue you are having but I modified a small parameter (commit: d862466)... can you just check if the problem persist now?

[lubocode]

2020/10/07 16:02:21 *** listening for new clients to connect...
2020/10/07 16:02:43 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:02:43 *** player unknown requested server info from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:02:43 closing connection for: 127.0.0.1
2020/10/07 16:02:56 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:02:56 *** MINECRAFT SERVER IS STARTING!
2020/10/07 16:02:56 *** _<user>_ tried to join from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:02:56 closing connection for: 127.0.0.1
2020/10/07 16:03:17 *** MINECRAFT SERVER IS UP!
2020/10/07 16:04:08 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:04:08 *** A PLAYER JOINED THE SERVER! - 1 players online
2020/10/07 16:04:09 data/s:    0.169 KB/s to clients |    0.028 KB/s to server
...
2020/10/07 16:04:41 data/s:    3.239 KB/s to clients |    0.051 KB/s to server
2020/10/07 16:04:41 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/07 16:04:41 *** A PLAYER LEFT THE SERVER! - 0 players online
2020/10/07 16:04:41 *** from 127.0.0.1:25555 to 127.0.0.1:25565
2020/10/07 16:04:41 *** A PLAYER JOINED THE SERVER! - 1 players online
2020/10/07 16:04:41 server version found! serverVersion: 1.16.2 serverProtocol: 751
2020/10/07 16:04:41 saved to config.json
2020/10/07 16:04:41 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/07 16:04:41 closing 127.0.0.1 --> 127.0.0.1 because of: EOF
2020/10/07 16:04:41 *** A PLAYER LEFT THE SERVER! - 0 players online
2020/10/07 16:04:42 data/s:    3.377 KB/s to clients |    0.056 KB/s to server
...
2020/10/07 16:05:01 data/s:    4.634 KB/s to clients |    0.000 KB/s to server
2020/10/07 16:05:01 *** MINECRAFT SERVER IS FORCEFULLY SHUTTING DOWN!

The issue seems to be resolved after some quick testing, though now the server keeps sending information, even though there is no player remaining on the server. At the end I stopped the script with ctrl + c
Or is this intentional for always sending the current server info to the client server overview window? But then, 4MB/s seems a bit much for that...

[gekigek99]

The issue seems to be resolved

very good... let's hope mojang does not change the protocols

now the server keeps sending information, even though there is no player remaining on the server.

Yes i know thanks it's actually an attempt at not cutting off the conncetion abruptly but letting the minecraft server close it...
if you wait for like 20-30 seconds it should stop by itself... (do you think it's better as it was before? (where msh closes connection to client and server by itself?))

4MB/s seems a bit much for that

it's actually 4'000 bytes/s, not 4'000'000 bytes/s... how can i write it better in your opinion?
(as you can see the data to server is 0 because the client is disconnected but the server is still connected to msh... so it thinks that there is a client... After 10-20 second it goes into timeout and suspend the connection)

[lubocode]

Well, I use the dot to denounce thousands and the comma for decimals, but since this is different everywhere in the world, we should probably keep with the "english" way of doing it with a dot for decimals.
For better understandability it could help to print one number less or more after the decimal point such that it is not confused with a thousand, which has three places after the number for counting thousands.

Other than that, I think this issue can now be closed. Go ahead if you think so as well @gekigek99

[gekigek99]

ok i' ll see if i can make it more readable

After 10-20 second it goes into timeout and suspend the connection

have you verified if this works for you?

[lubocode]

Yes it does. Takes about 25-26 seconds.