FAForever Forums
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Groups
    • Login
    The current pre-release of the client ("pioneer" in the version) is only compatible to itself. So you can only play with other testers. Please be aware!

    Connectivity problems, timeout. ICE log included

    Scheduled Pinned Locked Moved I need help
    connect errorice adapterjavafx
    1 Posts 1 Posters 3.1k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • FreadyFishF Offline
      FreadyFish Global Moderator
      last edited by

      Problem connecting to games. It gets stuck on the "Setting up automatch" and crashes, with "You caused a problem" and the ensuing timeout.

      Any ideas?

      See file for full log advanced-ice-adapter.log

      First and last part of advanced-ice-adapter.log:

      18:42:37.187 [main] INFO c.f.i.d.TelemetryDebugger - Open the telemetry ui via https://ice-telemetry.faforever.com/app.html?gameId=21064496&playerId=487490
      Eki 26, 2023 6:42:37 �S com.sun.javafx.application.PlatformImpl startup
      WARNING: Unsupported JavaFX configuration: classes were loaded from 'unnamed module @548a102f'
      18:42:38.100 [main] INFO c.f.i.u.TrayIcon - Created tray icon
      18:42:38.101 [main] INFO c.f.i.IceAdapter - Version: SNAPSHOT
      18:42:38.102 [main] INFO c.f.i.g.GPGNetServer - Using GPGNET_PORT: 51544
      18:42:38.108 [main] INFO c.f.i.g.GPGNetServer - Generated LOBBY_PORT: 48442
      18:42:38.109 [main] INFO c.f.i.g.GPGNetServer - GPGNetServer started
      18:42:38.110 [main] INFO c.f.i.r.RPCService - Creating RPC server on port 51543
      18:42:38.112 [main] INFO c.n.j.TcpServer - TCP Server started.
      18:42:38.113 [main] INFO c.f.i.d.TelemetryDebugger - RPC started
      18:42:38.335 [Thread-5] INFO c.n.j.SocketListener - New client connected on port 51556
      18:42:38.337 [Thread-5] INFO c.f.i.d.TelemetryDebugger - RPC connected
      18:42:38.338 [JJsonPeer] INFO c.n.j.JJsonPeer - JJSON Peer listening
      18:42:38.341 [JavaFX Application Thread] INFO c.f.i.d.DebugWindow - Created debug window.
      18:42:38.353 [JJsonPeer] DEBUG c.f.i.r.RPCHandler - LobbyInitMode set to auto
      18:42:38.354 [JJsonPeer] INFO c.n.j.JJsonPeer - Sending Response:{"result":null,"id":0,"jsonrpc":"2.0"}
      18:42:38.427 [WebSocketConnectReadThread-35] INFO c.f.i.d.TelemetryDebugger - Telemetry websocket opened
      18:42:38.689 [JJsonPeer] INFO c.f.i.i.GameSession - Ice Servers set, total addresses: 3
      18:42:38.690 [JJsonPeer] INFO c.n.j.JJsonPeer - Sending Response:{"result":null,"id":1,"jsonrpc":"2.0"}
      18:42:39.385 [JavaFX Application Thread] INFO c.f.i.d.InfoWindow - Created info window.
      18:42:41.689 [Thread-4] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onConnectionStateChanged","params":["Connected"],"jsonrpc":"2.0"}
      18:42:41.689 [Thread-4] INFO c.f.i.g.GPGNetServer - GPGNetClient has connected
      18:42:41.713 [Thread-11] DEBUG c.f.i.g.GPGNetServer - Listening for GPG messages
      18:42:41.729 [Thread-11] DEBUG c.f.i.g.GPGNetServer - New GameState: Idle
      18:42:41.730 [Thread-11] INFO c.f.i.g.GPGNetServer - Sent GPGNet message: CreateLobby 1 48442 commanderbambi 487490 1
      18:42:41.734 [Thread-11] INFO c.f.i.g.GPGNetServer - Received GPGNet message: GameState Idle
      18:42:41.735 [Thread-11] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onGpgNetMessageReceived","params":["GameState",["Idle"]],"jsonrpc":"2.0"}
      18:42:41.952 [Thread-11] DEBUG c.f.i.g.GPGNetServer - New GameState: Lobby
      18:42:41.953 [Thread-11] INFO c.f.i.g.GPGNetServer - Received GPGNet message: GameState Lobby
      18:42:41.953 [Thread-11] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onGpgNetMessageReceived","params":["GameState",["Lobby"]],"jsonrpc":"2.0"}
      18:42:42.034 [JJsonPeer] INFO c.f.i.IceAdapter - onHostGame
      18:42:42.035 [JJsonPeer] INFO c.f.i.g.GPGNetServer - Sent GPGNet message: HostGame neroxis_map_generator_1.9.0_vte3ulqcewrvm_bafa
      18:42:42.036 [JJsonPeer] INFO c.n.j.JJsonPeer - Sending Response:{"result":null,"id":2,"jsonrpc":"2.0"}
      18:42:42.831 [ForkJoinPool.commonPool-worker-1] WARN c.f.i.u.PingWrapper - Failed to ping coturn1.faforever.com
      18:42:48.548 [JJsonPeer] INFO c.f.i.IceAdapter - onConnectToPeer 28275 Guy, offer: true
      18:42:48.552 [JJsonPeer] DEBUG c.f.i.i.Peer - Peer created: 28275, Guy, localOffer: true
      18:42:48.554 [JJsonPeer] DEBUG c.f.i.i.Peer - Now forwarding data to peer Guy(28275)
      18:42:48.556 [Thread-13] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onIceConnectionStateChanged","params":[487490,28275,"gathering"],"jsonrpc":"2.0"}
      18:42:48.564 [JJsonPeer] INFO c.f.i.g.GPGNetServer - Sent GPGNet message: ConnectToPeer 127.0.0.1:49478 Guy 28275
      18:42:48.565 [JJsonPeer] INFO c.n.j.JJsonPeer - Sending Response:{"result":null,"id":3,"jsonrpc":"2.0"}
      18:42:48.574 [Thread-13] INFO c.f.i.i.PeerIceModule - ICE Guy(28275): Initiating ICE for peer
      18:42:48.575 [Thread-11] INFO c.f.i.g.GPGNetServer - Received GPGNet message: Disconnected 28275
      18:42:48.575 [Thread-11] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onGpgNetMessageReceived","params":["Disconnected",["28275"]],"jsonrpc":"2.0"}
      Eki 26, 2023 6:42:49 �S org.ice4j.ice.harvest.MappingCandidateHarvesters initialize
      INFO: Initialized mapping harvesters (delay=504ms). stunDiscoveryFailed=false
      18:42:49.108 [Thread-13] INFO c.f.i.i.PeerIceModule - ICE Guy(28275): Gathering ice candidates
      18:42:49.111 [Thread-13] INFO c.f.i.i.PeerIceModule - Using official ice servers: [94.130.225.99:3478/tcp, 94.130.225.99:3478/udp, 94.130.225.99:3478/udp]
      Eki 26, 2023 6:42:49 �S org.ice4j.util.Logger log
      INFO: Gathering candidates for component faData.RTP. Local ufrag 13dsr1hdmae2ok
      18:42:49.435 [JJsonPeer] INFO c.f.i.IceAdapter - onConnectToPeer 413575 Alcaloz, offer: true
      18:42:49.435 [JJsonPeer] DEBUG c.f.i.i.Peer - Peer created: 413575, Alcaloz, localOffer: true
      18:42:49.435 [JJsonPeer] DEBUG c.f.i.i.Peer - Now forwarding data to peer Alcaloz(413575)
      18:42:49.437 [JJsonPeer] INFO c.f.i.g.GPGNetServer - Sent GPGNet message: ConnectToPeer 127.0.0.1:49480 Alcaloz 413575
      18:42:49.438 [Thread-19] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onIceConnectionStateChanged","params":[487490,413575,"gathering"],"jsonrpc":"2.0"}
      18:42:49.438 [JJsonPeer] INFO c.n.j.JJsonPeer - Sending Response:{"result":null,"id":4,"jsonrpc":"2.0"}
      18:42:49.440 [Thread-19] INFO c.f.i.i.PeerIceModule - ICE Alcaloz(413575): Initiating ICE for peer
      18:42:49.441 [Thread-19] INFO c.f.i.i.PeerIceModule - ICE Alcaloz(413575): Gathering ice candidates
      18:42:49.442 [Thread-19] INFO c.f.i.i.PeerIceModule - Using official ice servers: [94.130.225.99:3478/tcp, 94.130.225.99:3478/udp, 94.130.225.99:3478/udp]
      Eki 26, 2023 6:42:49 �S org.ice4j.util.Logger log
      INFO: Gathering candidates for component faData.RTP. Local ufrag btnle1hdmae3j1
      18:42:49.501 [Thread-11] INFO c.f.i.g.GPGNetServer - Received GPGNet message: Disconnected 413575
      18:42:49.501 [Thread-11] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onGpgNetMessageReceived","params":["Disconnected",["413575"]],"jsonrpc":"2.0"}
      18:42:51.455 [Thread-13] DEBUG c.f.i.i.PeerIceModule - ICE Guy(28275): Sending own candidates to 28275, offered candidates: host(udp)
      18:42:51.455 [Thread-13] INFO c.n.j.JJsonPeer - Sending Notification:{"method":"onIceConnectionStateChanged","params":[487490,28275,"awaitingCandidates"],"jsonrpc":"2.0"}

      ***A LOT CUT OUT, TOO LONG OTHERWISE. SEE ATTACHED FILE FOR COMPLETE LOG ***

      INFO: Closing.
      at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:700)
      at com.faforever.iceadapter.ice.Peer.faListener(Peer.java:81)
      at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.nio.channels.AsynchronousCloseException: null
      at java.base/sun.nio.ch.DatagramChannelImpl.endRead(DatagramChannelImpl.java:523)
      at java.base/sun.nio.ch.DatagramChannelImpl.trustedBlockingReceive(DatagramChannelImpl.java:677)
      at java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:635)
      at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:240)
      ... 3 common frames omitted
      19:24:45.512 [Thread-74] DEBUG c.f.i.i.Peer - Error while reading from local FA as peer (probably disconnecting from peer) dipollwody(348482)
      java.net.SocketException: Socket closed
      at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:252)
      at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:700)
      at com.faforever.iceadapter.ice.Peer.faListener(Peer.java:81)
      at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.nio.channels.AsynchronousCloseException: null
      at java.base/sun.nio.ch.DatagramChannelImpl.endRead(DatagramChannelImpl.java:523)
      at java.base/sun.nio.ch.DatagramChannelImpl.trustedBlockingReceive(DatagramChannelImpl.java:677)
      at java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:635)
      at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:240)
      ... 3 common frames omitted
      19:24:45.513 [Thread-12] DEBUG c.f.i.i.Peer - Error while reading from local FA as peer (probably disconnecting from peer) omega22(403305)
      java.net.SocketException: Socket closed
      at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:252)
      at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:700)
      at com.faforever.iceadapter.ice.Peer.faListener(Peer.java:81)
      at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.nio.channels.AsynchronousCloseException: null
      at java.base/sun.nio.ch.DatagramChannelImpl.endRead(DatagramChannelImpl.java:523)
      at java.base/sun.nio.ch.DatagramChannelImpl.trustedBlockingReceive(DatagramChannelImpl.java:677)
      at java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:635)
      at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:240)
      ... 3 common frames omitted
      19:24:45.514 [JJsonPeer] WARN c.f.i.r.RPCHandler - Close requested, stopping...
      19:24:45.514 [JJsonPeer] INFO c.f.i.IceAdapter - close() - stopping the adapter
      19:24:45.515 [JJsonPeer] INFO c.f.i.g.GPGNetServer - GPGNetServer stopped
      19:24:45.515 [Thread-11] DEBUG c.f.i.g.GPGNetServer - No longer listening for GPGPNET from FA
      java.net.SocketException: Socket closed
      at java.base/sun.nio.ch.NioSocketImpl.endAccept(NioSocketImpl.java:689)
      at java.base/sun.nio.ch.NioSocketImpl.accept(NioSocketImpl.java:762)
      at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:675)
      at java.base/java.net.ServerSocket.platformImplAccept(ServerSocket.java:641)
      at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:617)
      at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:574)
      at java.base/java.net.ServerSocket.accept(ServerSocket.java:532)
      at com.nbarraille.jjsonrpc.SocketListener.run(SocketListener.java:36)
      Eki 26, 2023 7:24:45 �S org.ice4j.util.Logger log
      INFO: Failed to receive: java.net.SocketException: Socket closed
      Eki 26, 2023 7:24:45 �S org.ice4j.util.Logger log
      INFO: Failed to receive: java.net.SocketException: Socket closed

      1 Reply Last reply Reply Quote 0
      • First post
        Last post