search

MovingBlocks / Terasology

Terasology - open source voxel world
http://terasology.org
Apache License 2.0
3.68k stars 1.34k forks source link

Seemingly benign stacktrace on selecting a server entry in a client #3794

Open Cervator opened 4 years ago

Cervator commented 4 years ago

What you were trying to do

Test things! By joining a server, the first step of which is selecting an item in the server browser list. This should happen nice and gracefully with no angry errors in the logs.

Edit: This may only happen when using the baked in custom server entry for localhost?

What actually happened

Angry errors in the log! That don't seem to actually matter as a working server will connect just fine. Likely either overzealous logging or we aren't gracefully doing the "hello" check the client attempts to get server info from a selected item in the UI. This has happened for months if not years.

The log snippet should provide enough clues to dig around a bit to find out if it matters or is just a throwaway event that should have its logging suppressed. Maybe we need to close something more gracefully? We've traditionally bumped into network-related failures to dispose the game pretty readily, leaving a networking thread open for some reason. Could be something to look for, especially in the case of actual failures to connect rather than just some throwaway handshaking.

How to reproduce

Log details

20:54:26.456 [main] INFO  o.t.logic.console.ConsoleImpl - [NOTIFICATION] Identity storage service: No configuration data is present, staying logged out.
20:54:54.440 [New I/O worker #1] INFO  o.t.n.i.ServerHandshakeHandler - Sending Server Hello
20:54:54.502 [New I/O worker #2] INFO  o.t.n.i.ServerHandshakeHandler - Sending Server Hello
20:54:54.503 [New I/O worker #1] WARN  o.t.network.internal.ServerHandler - Unexpected exception from client
java.io.IOException: An established connection was aborted by the software in your host machine
    at sun.nio.ch.SocketDispatcher.read0(Native Method)
    at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:192)
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:64)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
20:54:54.504 [New I/O worker #1] WARN  o.t.network.internal.ServerHandler - Unexpected exception from client
java.io.IOException: An established connection was aborted by the software in your host machine
    at sun.nio.ch.SocketDispatcher.write0(Native Method)
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:51)
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
    at sun.nio.ch.IOUtil.write(IOUtil.java:51)
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
    at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSendBuffer.transferTo(SocketSendBufferPool.java:203)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(AbstractNioWorker.java:201)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromUserCode(AbstractNioWorker.java:146)
    at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:99)
    at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:779)
    at org.terasology.network.internal.MetricRecordingHandler.writeRequested(MetricRecordingHandler.java:53)
    at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:254)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)
    at org.jboss.netty.channel.Channels.write(Channels.java:725)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.doEncode(OneToOneEncoder.java:71)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:59)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)
    at org.jboss.netty.channel.Channels.write(Channels.java:725)
    at org.jboss.netty.channel.Channels.write(Channels.java:686)
    at org.jboss.netty.handler.codec.compression.ZlibEncoder.finishEncode(ZlibEncoder.java:390)
    at org.jboss.netty.handler.codec.compression.ZlibEncoder.handleDownstream(ZlibEncoder.java:326)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)
    at org.jboss.netty.channel.Channels.close(Channels.java:812)
    at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:206)
    at org.terasology.network.internal.ServerHandler.exceptionCaught(ServerHandler.java:69)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.exceptionCaught(SimpleChannelUpstreamHandler.java:153)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.exceptionCaught(SimpleChannelUpstreamHandler.java:153)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:60)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:377)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.channel.SimpleChannelHandler.exceptionCaught(SimpleChannelHandler.java:156)
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:130)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:74)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
20:54:54.599 [New I/O worker #2] INFO  o.t.n.i.ServerHandshakeHandler - Received new identity request
20:54:56.389 [New I/O worker #3] INFO  o.t.n.i.ServerHandshakeHandler - Sending Server Hello
20:54:56.452 [New I/O worker #3] INFO  o.t.n.i.ServerHandshakeHandler - Received client certificate
SoniEx2 commented 4 years ago

please attach client configs. can't reproduce.

Java Version:

$ java -version
openjdk version "1.8.0_232"
OpenJDK Runtime Environment (build 1.8.0_232-b09)
OpenJDK 64-Bit Server VM (build 25.232-b09, mixed mode)

OS: Arch Linux (last updated 2019-12-22T22:38:42-0300)

Relevant logs:

``` 18:16:17.503 [ServerList Downloader] INFO o.t.r.n.l.m.ServerListDownloader - Retrieved game server ServerInfo [name=Official Stable, address=mmo.to, port=25777, owner=qwc (served with docker), active=true] 18:16:17.762 [ServerList Downloader] INFO o.t.r.n.l.m.ServerListDownloader - Retrieved game server ServerInfo [name=Official Event Host, address=testserver.terasology.net, port=25777, owner=Cervator, active=true] 18:16:18.013 [ServerList Downloader] INFO o.t.r.n.l.m.ServerListDownloader - Retrieved game server ServerInfo [name=Enchanted Forest, address=terasology.hopto.org, port=25777, owner=znh, active=true] 18:16:18.263 [ServerList Downloader] INFO o.t.r.n.l.m.ServerListDownloader - Retrieved game server ServerInfo [name=Official Unstable, address=mmo.to, port=25778, owner=qwc (served with docker), active=true] 18:16:18.514 [ServerList Downloader] INFO o.t.r.n.l.m.ServerListDownloader - Retrieved game server ServerInfo [name=tuffkidtek, address=terasology.tuffkidtek.com, port=25777, owner=minnesotags, active=true] 18:16:21.744 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Received Server Hello 18:16:21.747 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Sending client certificate 18:16:22.014 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Received server verification 18:16:22.068 [New I/O worker #1] INFO o.t.n.i.ServerInfoRequestHandler - Received server info 18:16:25.999 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Received Server Hello 18:16:26.000 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Sending client certificate 18:16:26.039 [New I/O worker #1] INFO o.t.n.i.ClientHandshakeHandler - Received server verification 18:16:26.054 [New I/O worker #1] INFO o.t.n.i.ServerInfoRequestHandler - Received server info ```
Cervator commented 4 years ago

@SoniEx2: Thanks for trying. It might be OS specific? Not sure which client configs you mean. I can reproduce thusly:

1) Start a headless server via headless run config in IntelliJ 2) Start a game client via run config in IntelliJ 3) Go to join a multiplayer server and click the localhost entry then check the server console for the stacktrace (important - the stacktrace doesn't appear client side, only on the server)

SoniEx2 commented 4 years ago

can't reproduce. OS info?

Cervator commented 4 years ago

Windows 10, so that's probably it.

Edit: Plus I have a bunch of virtual NICs due to having VirtualBox and so on set up. Unsure if that'd matter. Actually takes the game a while to start hosting a multiplayer session since it tries to listen on every defined NIC one at a time ...