FAForever Forums
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Groups
    • Login

    Connectivity problems, timeout. ICE log included

    Scheduled Pinned Locked Moved
    I need help
    connect error ice adapter javafx
    1
    1
    3.1k
    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
      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