Client hangs at loading landscape

[L3P3]

I am using the latest released binary on latest debian bullseye. I run the client on my big machine only. When I run the feather-server on localhost, it works. Now I run the same binary on my netbook, ancient low-powered Intel Atom. It starts very fast, as can be seen in the log below. When I join entering the netbook's IP, the client connects and it gets stuck on "Loading landscape...". After about one second after that screen is shown, both server's and client's cpus go idle (0%), nothing will happen, I waited many minutes. Much memory is left on that machine. I did not touch the generated config file. The server log so far looks like this:

l3p3@l3p3-rkk:~/feather$ ./feather-server
Loading configuration
2020-11-10 11:31:18,859 INFO  [feather_server::init] Loading world save
2020-11-10 11:31:19,069 INFO  [feather_server_chunk::chunk_worker] Starting chunk worker
2020-11-10 11:31:19,129 INFO  [feather_server::init] Queueing spawn chunks for loading
2020-11-10 11:31:19,229 INFO  [feather_server::init] Creating RSA keypair
2020-11-10 11:31:21,852 INFO  [feather_server::init] Initializing block ID mappings
2020-11-10 11:31:21,926 INFO  [feather_server::init] Starting networking task
2020-11-10 11:31:21,965 INFO  [feather_server::init] Listening on 0.0.0.0:25565
2020-11-10 11:31:22,049 INFO  [feather_server] Server started
2020-11-10 11:31:22,143 DEBUG [feather_server_chunk::chunk_manager] Optimizing chunks
2020-11-10 11:31:22,146 DEBUG [feather_server_chunk::chunk_manager] Optimized 0 chunk sections (took 1ms - infms/section)
2020-11-10 11:32:55,542 INFO  [feather_server_network::listener] Connection received from 192.168.1.11:41274
2020-11-10 11:32:57,581 DEBUG [reqwest::connect] starting new connection: https://sessionserver.mojang.com/
2020-11-10 11:32:57,636 DEBUG [hyper::client::connect::dns] resolving host="sessionserver.mojang.com"
2020-11-10 11:32:57,844 DEBUG [hyper::client::connect::http] connecting to 52.222.176.101:443
2020-11-10 11:32:57,876 DEBUG [hyper::client::connect::http] connected to 52.222.176.101:443
2020-11-10 11:32:58,610 DEBUG [hyper::proto::h1::io] flushed 170 bytes
2020-11-10 11:32:58,766 DEBUG [hyper::proto::h1::io] read 1644 bytes
2020-11-10 11:32:58,841 DEBUG [hyper::proto::h1::io] parsed 10 headers
2020-11-10 11:32:58,843 DEBUG [hyper::proto::h1::conn] incoming body is content-length (1246 bytes)
2020-11-10 11:32:58,862 DEBUG [hyper::proto::h1::conn] incoming body completed
2020-11-10 11:32:58,890 DEBUG [hyper::client::pool] pooling idle connection for ("https", sessionserver.mojang.com)
2020-11-10 11:32:58,897 DEBUG [reqwest::async_impl::client] response '200 OK' for https://sessionserver.mojang.com/session/minecraft/hasJoined?username=L3P3&serverId=[hidden]&unsigned=false
2020-11-10 11:32:59,041 DEBUG [feather_server_network::worker] Loading player data for UUID [hidden]

When the client gets closed, there is nothing happening in the server log. When I restart the client, I can try to join again and the same thing happens as above. When I press CTRL+C in the server terminal, the client says "Connection closed" but the server gets stuck at:

2020-11-10 11:42:52,054 INFO  [feather_server] Shutting down
2020-11-10 11:42:52,062 INFO  [feather_server] Disconnecting players
2020-11-10 11:42:52,077 INFO  [feather_server] Shutting down workers
2020-11-10 11:42:52,106 INFO  [feather_server_lighting] Lighting worker shutting down
2020-11-10 11:42:52,125 INFO  [feather_server] Saving chunks
2020-11-10 11:42:52,146 INFO  [feather_server_chunk::chunk_worker] Chunk worker terminating

When I press CTRL+C again, nothing happens, have to kill the process from process manager. To me, it looks like a lock-up.

[itsTyrion]

Maybe an unsupported CPU feature? 🤔 Or a dynamically linkes native library that is too old/new?

[itsTyrion]

I wonder what OS these binaries are built on/what they're linked against. @L3P3 what os/distro + version is inning on the netbook? What Atom is in it?

[L3P3]

Hello, sorry for not replying earlier, missed the notification. The netbook is having first generation atom, 32 bits. As stated, I use debian bullseye. Since there is only a 64 bits binary, qemu-static is used as a wrapper by binfmt. So probably the actual cpu here is in qemu, no idea how it is called. Would still be nice to understand what is happening.

[L3P3]

Do you have an idea what is happening, just by looking at the logs/behaviour?

[itsTyrion]

Do you have an idea what is happening, just by looking at the logs/behaviour? No idea

32 bit; Since there is only a 64 bits binary, qemu-static is used as a wrapper by binfmt

So you're basically executing a x86_64 binary on x86? o.ô

[L3P3]

Yes, in qemu's virtual 64 bit processor used by binfmt. Other apps run without problems usually in this way. But let us forcus on the issue here... Is there a more verbose settings for feather so we get a more detailled log or something?

[L3P3]

To me, it looks like some deadlock. Something gets opened that is blocking other stuff to happen but it never gets closed.

[kallekankaanpaa]

You could set the log level to trace to get more detailed logs.

You can do that by changing the level parameter under log from debug to trace in the feather.toml file.

You could also try to compile the project on your laptop and run it without qemu.

[Schuwi]

Looking at the shutdown function https://github.com/feather-rs/feather/blob/9539a21c9c0fbe681ec1e8851519280438dd583f/server/src/lib.rs#L120-L144 and the ChunkWorker loop https://github.com/feather-rs/feather/blob/9539a21c9c0fbe681ec1e8851519280438dd583f/server/chunk/src/chunk_worker.rs#L131-L147 comparing that to the log output I would suspect that the server hangs in line 46 of the save_chunks function on shutdown https://github.com/feather-rs/feather/blob/9539a21c9c0fbe681ec1e8851519280438dd583f/server/src/shutdown.rs#L33-L49

Though I am not sure why that happens.

[Schuwi]

Could you still do a run with log level trace so we can potentially get a better idea where it hangs when joining?

[L3P3]

Sorry, was busy and had no time...

~/feather$ ./feather-server 
Loading configuration
2021-01-14 17:41:59,236 INFO  [feather_server::init] Loading world save
2021-01-14 17:41:59,431 INFO  [feather_server_chunk::chunk_worker] Starting chunk worker
2021-01-14 17:41:59,476 INFO  [feather_server::init] Queueing spawn chunks for loading
2021-01-14 17:41:59,542 INFO  [feather_server::init] Creating RSA keypair
2021-01-14 17:42:02,188 INFO  [feather_server::init] Initializing block ID mappings
2021-01-14 17:42:02,268 INFO  [feather_server::init] Starting networking task
2021-01-14 17:42:02,302 TRACE [mio::poll] registering with poller
2021-01-14 17:42:02,308 INFO  [feather_server::init] Listening on 0.0.0.0:25565
2021-01-14 17:42:02,394 INFO  [feather_server] Server started
2021-01-14 17:42:02,474 DEBUG [feather_server_chunk::chunk_manager] Optimizing chunks
2021-01-14 17:42:02,477 DEBUG [feather_server_chunk::chunk_manager] Optimized 0 chunk sections (took 1ms - infms/section)

Then, I try to join: server.log