oddlama / minecraft-server

A simple but fully-featured minecraft server installer for linux. Comes with autostart, 3d online map, vane, account multiplexing, update script and more.
MIT License
66 stars 9 forks source link

Server is offline error when trying to connect for the first time #9

Closed GodderE2D closed 1 year ago

GodderE2D commented 1 year ago

image

This error shows up when trying to connect for the first time. I tried this with both a fabric and vanilla client.

I haven't changed any config files myself, and the proxy has no errors. However, the server logs just shows this:

Blocking on start.block

Which I assume is when a player has never connected to the server yet.

This is running on an arm64 architecture oracle cloud VM. I have set my local firewall rules and permitted TCP traffic from oracle cloud dashboard. I'm on OpenJDK version 17.0.5. I have restarted proxy and server through systemctl many times.

Proxy logs:

Starting process ['./start.sh'] ...
Executing proxy server
[01:56:40 INFO]: Using standard Java JCE cipher.
[01:56:40 INFO]: Using standard Java compressor.
[01:56:40 INFO]: Enabled Waterfall version git:Waterfall-Bootstrap:1.19-R0.1-SNAPSHOT:dca72c2:511
[01:56:40 INFO]: Not on Windows, attempting to use enhanced EpollEventLoop
[01:56:40 INFO]: Epoll is working, utilising it!
[01:56:40 INFO]: Discovered module: ModuleSpec(name=cmd_alert, file=modules/cmd_alert.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Discovered module: ModuleSpec(name=cmd_find, file=modules/cmd_find.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Discovered module: ModuleSpec(name=cmd_list, file=modules/cmd_list.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Discovered module: ModuleSpec(name=cmd_send, file=modules/cmd_send.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Discovered module: ModuleSpec(name=cmd_server, file=modules/cmd_server.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Discovered module: ModuleSpec(name=reconnect_yaml, file=modules/reconnect_yaml.jar, provider=JenkinsModuleSource())
[01:56:40 INFO]: Loaded plugin reconnect_yaml version git:reconnect_yaml:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Loaded plugin cmd_find version git:cmd_find:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Loaded plugin cmd_server version git:cmd_server:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Loaded plugin vane-waterfall version 1.10.3 by oddlama
[01:56:40 INFO]: Loaded plugin cmd_alert version git:cmd_alert:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Loaded plugin cmd_send version git:cmd_send:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Loaded plugin cmd_list version git:cmd_list:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin reconnect_yaml version git:reconnect_yaml:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin cmd_find version git:cmd_find:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin cmd_server version git:cmd_server:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin vane-waterfall version 1.10.3 by oddlama
[01:56:40 INFO]: Enabled plugin cmd_alert version git:cmd_alert:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin cmd_send version git:cmd_send:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Enabled plugin cmd_list version git:cmd_list:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[01:56:40 INFO]: Listening on /0.0.0.0:25566
[01:56:40 INFO]: Listening on /0.0.0.0:25565
[01:56:47 INFO]: [/xx.xx.xx.xxx:57034] <-> InitialHandler has pinged
[01:56:53 INFO]: [/xx.xx.xx.xxx:57038] <-> InitialHandler has connected
[01:57:56 INFO]: [/xx.xxx.xx.xxx:58674] <-> InitialHandler has pinged
[01:58:15 INFO]: [/xx.xxx.xx.xxx:57093] <-> InitialHandler has pinged
[01:58:30 INFO]: [/xx.xxx.xx.xxx:57106] <-> InitialHandler has pinged
[01:58:46 INFO]: [/xx.xxx.xx.xxx:57114] <-> InitialHandler has connected
[02:02:35 INFO]: [/xx.xxx.xx.xxx:57370] <-> InitialHandler has connected
oddlama commented 1 year ago

Everything seems fine from what I can see here. Although I never tested amd64 with this, but technically there shouldn't be anything depending on x86. To me the most likely issue would be related to the free Oracle VMs which might have weird (and to me unknown) firewall rules or other non-standard configuration.

Blocking on start.block

Which I assume is when a player has never connected to the server yet.

Yes, mostly. This mechanism is to ensure that multiple players connecting to your server all interact with the same instance and don't start multiple servers by accident. There is a single instance managed by the systemd unit minecraft-server which sleeps until a specified file (start.block) is deleted.

You can manually start the server by deleting this file using rm /var/lib/minecraft/deploy/server/start.block as root to test if it is an issue with your firewall (in which case you will not be able connect even if it is started manually this way) or a permission issue with deleting the blockfile (in which case you will be able to connect).

Your proxy seems to be reachable at least to some degree as is evident from the "InitialHandler has connected" messages. If deleting the blockfile manually helps, please make sure that the processes all run as the same user. If it doesn't help, there might be some firewall rule in place that prevents the proxy from talking to the server via the loopback interface 127.0.0.1 on the specified internal port.

GodderE2D commented 1 year ago

I can connect to the server after removing the file manually. The file has the correct permissions, 744. Even after setting it to 766 and trying to connect to the server, it still does not delete the file.

The server works fine until it restarts. I'm unsure if this is a permission issue as this is a regular Ubuntu 22.04 instance, as Oracle Cloud shouldn't modify permissions.

oddlama commented 1 year ago

The file permissions don't matter that much, since both processes should run as the same user (and you can delete a file of arbitrary permissions if you are the owner). Since you can connect after starting, it clearly indicates that there's a problem with the start command. Since this is a standard setup that has already worked many times, it must be either because of a customized system/installation or (unlikely) an incompatible waterfall update has been released that I missed. Let's see:

GodderE2D commented 1 year ago

Yes, the installer created the minecraft user.

Grep returns this:

347271 minecra+ minecra+ java -Xms1G -Xmx1G -jar waterfall.jar nogui
381785 ubuntu   ubuntu   grep --color=auto java

I didn't change any of the config files, but here they are anyways:

config.yml

enforce_secure_profile: false
listeners:
- bind_local_address: true
  force_default_server: false
  forced_hosts: {}
  host: 0.0.0.0:25565
  max_players: 6666
  motd: ''
  ping_passthrough: false
  priorities:
  - server
  proxy_protocol: false
  query_enabled: false
  query_port: 25565
  tab_list: GLOBAL_PING
  tab_size: 60
- bind_local_address: true
  force_default_server: false
  forced_hosts: {}
  host: 0.0.0.0:25566
  max_players: 6666
  motd: ''
  ping_passthrough: false
  priorities:
  - server
  proxy_protocol: false
  query_enabled: false
  query_port: 25565
  tab_list: GLOBAL_PING
  tab_size: 60
remote_ping_cache: -1
network_compression_threshold: 256
permissions:
  default:
  - bungeecord.command.server
  - vane_waterfall.command.ping
  - vane_waterfall.auth_multiplexer.1
log_pings: true
connection_throttle_limit: 3
server_connect_timeout: 15000
timeout: 30000
player_limit: -1
prevent_proxy_connections: false
ip_forward: true
groups: {}
remote_ping_timeout: 5000
connection_throttle: 1000
log_commands: true
stats: 34da5747-a165-48df-8c2d-2ad66089faff
online_mode: true
forge_support: false
disabled_commands: []
servers:
  server:
    address: 127.0.0.1:25501
    motd: ''
    restricted: false

waterfall.yml

throttling:
  tab_complete: 200
log_initial_handler_connections: true
registered_plugin_channels_limit: 128
use_netty_dns_resolver: true
game_version: ''
disable_tab_list_rewrite: true
disable_entity_metadata_rewrite: false
disable_modern_tab_limiter: true
plugin_channel_name_limit: 128
oddlama commented 1 year ago

I didn't change any of the config files

Then the issue can't be there. What you can try instead is to use another start command so we can see whether it is executed at all. In proxy/plugins/vane-waterfall.yml perform the following edit:

    start:
      #cmd: ["rm", "../%SERVER%/start.block"]
      # Instead use this temporarily:
      cmd: ["sh", "-c", "echo \"$(date): tried starting server %SERVER% in $(cwd) as user $(id)\" >> /tmp/server_start_log; rm ../%SERVER%/start.block"]

Then restart the proxy and see what happens when you connect to it. If everything is successful, it will append a line to the file /tmp/server_start_log. Use cat /tmp/server_start_log afterwards as root to see what it wrote. If the file doesn't exist after trying to connect while the actual server is offline, we'll know that the problem is with the proxy. If it shows up, then it must be a permission issue.

GodderE2D commented 1 year ago

After changing the config file in proxy/plugins/vane-waterfall/config.yml and connecting to the server, there isn't a file called "server_start_log" in /tmp.

oddlama commented 1 year ago

Very interesting, I've spotted something in the latest update that might have caused this (something seems to have messed with the default permissions on waterfall). I think you can work around this for now by adding the following line to your proxy/config.yml (and don't forget to revert the start command):

permissions:
  default:
    # add this line:
    - vane_proxy.start_server.*

Thanks for debugging it with me :)

GodderE2D commented 1 year ago

I tried adding that line in the proxy config and reverting the start command in the vane-waterfall config, however a new error "Could not start server" pops up when trying to connect: image

Start command part of my proxy/plugins/vane-waterfall/config.yml:

    start:
      cmd: ["rm", "../%SERVER%/start.block"]
      kick_msg: "%SERVER_DISPLAY_NAME% §7is being started.\n\
        §7Try again in §b10 Seconds§7 \\(^-^)/"

Permissions part of my proxy/config.yml:

permissions:
  default:
  - bungeecord.command.server
  - vane_waterfall.command.ping
  - vane_waterfall.auth_multiplexer.1
  - vane_proxy.start_server.*

I did try restarting both the proxy and the server through systemctl but it didn't work.

GodderE2D commented 1 year ago

Oh, and these are the proxy logs:

Starting process ['./start.sh'] ...
Executing proxy server
[02:17:56 INFO]: Using standard Java JCE cipher.
[02:17:56 INFO]: Using standard Java compressor.
[02:17:56 INFO]: Enabled Waterfall version git:Waterfall-Bootstrap:1.19-R0.1-SNAPSHOT:dca72c2:511
[02:17:56 INFO]: Not on Windows, attempting to use enhanced EpollEventLoop
[02:17:56 INFO]: Epoll is working, utilising it!
[02:17:57 INFO]: Discovered module: ModuleSpec(name=cmd_alert, file=modules/cmd_alert.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Discovered module: ModuleSpec(name=cmd_find, file=modules/cmd_find.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Discovered module: ModuleSpec(name=cmd_list, file=modules/cmd_list.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Discovered module: ModuleSpec(name=cmd_send, file=modules/cmd_send.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Discovered module: ModuleSpec(name=cmd_server, file=modules/cmd_server.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Discovered module: ModuleSpec(name=reconnect_yaml, file=modules/reconnect_yaml.jar, provider=JenkinsModuleSource())
[02:17:57 INFO]: Loaded plugin reconnect_yaml version git:reconnect_yaml:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Loaded plugin cmd_find version git:cmd_find:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Loaded plugin cmd_server version git:cmd_server:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Loaded plugin vane-waterfall version 1.10.3 by oddlama
[02:17:57 INFO]: Loaded plugin cmd_alert version git:cmd_alert:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Loaded plugin cmd_send version git:cmd_send:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Loaded plugin cmd_list version git:cmd_list:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin reconnect_yaml version git:reconnect_yaml:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin cmd_find version git:cmd_find:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin cmd_server version git:cmd_server:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin vane-waterfall version 1.10.3 by oddlama
[02:17:57 INFO]: Enabled plugin cmd_alert version git:cmd_alert:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin cmd_send version git:cmd_send:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Enabled plugin cmd_list version git:cmd_list:1.19-R0.1-SNAPSHOT:dca72c2:511 by WaterfallMC
[02:17:57 INFO]: Listening on /0.0.0.0:25565
[02:17:57 INFO]: Listening on /0.0.0.0:25566
[02:19:56 INFO]: [/xx.xx.xx.xxx:55714] <-> InitialHandler has connected
[02:19:57 ERROR] [vane-waterfall]: Could not start server 'server', no start command was set!

Server logs still say it's blocking on start.block

oddlama commented 1 year ago

Ah I just wanted to post an edit:

It seems like there was a breaking change pulled in which was intended for minecraft 1.20. Sorry for the inconveniences, I'll have to push a separate fix for this tomorrow :/

oddlama commented 1 year ago

@GodderE2D I've just double checked and you can actually work around it right now:

Just write the following to plugins/vane-waterfall/config.toml and delete plugins/vane-waterfall/config.yml.

[auth_multiplex.1]
port = 25566
# [] = anyone
allowed_uuids = []

[managed_servers.server]
display_name = "§6◊ §6§lMY SERVER§6 ◊"

[managed_servers.server.online]
favicon = "../{SERVER}/server-icon.png"
motd = "{SERVER_DISPLAY_NAME}\n§a\\(^-^)/§7 | {QUOTE}"
quotes = ["Yay, already online!"]

[managed_servers.server.offline]
quotes = [ "Simply connect to start the server!", "Nobody here yet." ]
motd = "{SERVER_DISPLAY_NAME}\n§c~(°·°)~§7 | {QUOTE}"

[managed_servers.server.start]
cmd = ["rm", "../{SERVER}/start.block"]
kick_msg = "{SERVER_DISPLAY_NAME} §7is being started.\n§7Try again in §b10 Seconds§7 \\(^-^)/"
GodderE2D commented 1 year ago

It works! Thanks for helping me going through this. I appended that to my vane-waterfall's config.toml file and deleted the config.yml file as well.