search

Yellow-Dog-Man / Resonite-Issues

Issue repository for Resonite.
https://resonite.com
135 stars 2 forks source link

LNL Relay drops connection instantly after establishing, LNL NAT doesn't work #44

Open shadowpanther opened 11 months ago

shadowpanther commented 11 months ago

Describe the bug?

Sometimes (looks like it happens after Resonite client was running for some time) when attempting to join some sessions, the connection panel shows going through LNL 1-4, then LNL Relay, the Relay seems to connect, then immediately disconnects.

To Reproduce

Attempt to join random open session

Expected behavior

Able to join any session that is open

Screenshots

No response

Resonite Version Number

2023.10.10.1407

What Platforms does this occur on?

Windows

What headset if any do you use?

No response

Log Files

Tried to do the clean replication, connection did not fail. Attached is the log when connection did fail:

VIXEN - 2023.10.10.1407 - 2023-10-12 22_27_50.log

Connection starts at log line 18004:

23:43:28.922 ( 59 FPS)  Joining session: lnl-nat://799d09c58c27452dac6cc436407642fd/S-c0a162a1-0707-4926-9d8f-8a441148bd0c

  at System.Environment.get_StackTrace () [0x00000] in <9577ac7a62ef43179789031239ba8798>:0 
  at Elements.Core.UniLog.Log (System.String message, System.Boolean stackTrace) [0x00000] in <9c21f0e5c97b48d9b393bb518dd53389>:0 
  at FrooxEngine.World.JoinSession (FrooxEngine.WorldManager manager, System.Collections.Generic.IEnumerable`1[T] addresses) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.WorldManager.JoinSession (System.Collections.Generic.IEnumerable`1[T] addresses) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Userspace.JoinSession (System.Collections.Generic.IEnumerable`1[T] addresses, FrooxEngine.IWorldLink sourceLink, System.Boolean focusWhenReady) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Userspace+<OpenWorldInternal>d__184.MoveNext () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[TResult].Start[TStateMachine] (TStateMachine& stateMachine) [0x00000] in <9577ac7a62ef43179789031239ba8798>:0 
  at FrooxEngine.Userspace.OpenWorldInternal (FrooxEngine.WorldStartSettings startInfo) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Userspace+<>c__DisplayClass183_0+<<OpenWorld>b__0>d.MoveNext () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[TResult].Start[TStateMachine] (TStateMachine& stateMachine) [0x00000] in <9577ac7a62ef43179789031239ba8798>:0 
  at FrooxEngine.Userspace+<>c__DisplayClass183_0.<OpenWorld>b__0 () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.CoroutineManager.StartTask[T] (System.Func`1[TResult] task, FrooxEngine.IUpdatable updatable) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Worker.StartTask[T] (System.Func`1[TResult] task) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Userspace+<OpenWorld>d__183.MoveNext () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[TResult].Start[TStateMachine] (TStateMachine& stateMachine) [0x00000] in <9577ac7a62ef43179789031239ba8798>:0 
  at FrooxEngine.Userspace.OpenWorld (FrooxEngine.WorldStartSettings startInfo) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.WorldDetail+<>c__DisplayClass83_0+<<OnOpen>b__1>d.MoveNext () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine] (TStateMachine& stateMachine) [0x00000] in <9577ac7a62ef43179789031239ba8798>:0 
  at FrooxEngine.WorldDetail+<>c__DisplayClass83_0.<OnOpen>b__1 () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.CoroutineManager.StartTask (System.Func`1[TResult] task, FrooxEngine.IUpdatable updatable) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Worker.StartTask (System.Func`1[TResult] task) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.WorldDetail.OnOpen (FrooxEngine.IButton button, FrooxEngine.ButtonEventData eventData) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.Button.RunPressed (FrooxEngine.ButtonEventData eventData) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.Button.OnPressBegin (FrooxEngine.UIX.Canvas+InteractionData eventData) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.InteractionElement.ProcessEvent (FrooxEngine.UIX.Canvas+InteractionData eventData) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.Canvas.ProcessTouchEvent (FrooxEngine.TouchEventInfo& eventInfo, System.Collections.Generic.List`1[T] filters) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.Canvas.OnTouch (FrooxEngine.TouchEventInfo& eventInfo) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.UIX.Canvas.FrooxEngine.ITouchable.OnTouch (FrooxEngine.TouchEventInfo& eventInfo) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.TouchSource.SendTouchEvent (FrooxEngine.ITouchable touchable, FrooxEngine.TouchEventInfo& touchInfo) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.TouchSource.UpdateCurrentTouchable (FrooxEngine.ITouchable touchable, Elements.Core.float3& point, Elements.Core.float3& direction, Elements.Core.float3& directHitPoint, System.Boolean touch) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.TouchSource.UpdateTouch () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.PointerInteractionController.UpdatePointer (FrooxEngine.Pointer pointer, Elements.Core.float2 axisDelta) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.PointerInteractionController.ProcessUserspacePointers () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.PointerInteractionController.BeforeInputUpdate () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.InputBindingManager+<>c.<.cctor>b__44_0 (FrooxEngine.IInputUpdateReceiver i) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.InputBindingManager.SendInputUpdateEvents (System.Action`1[T] action, System.Collections.Generic.HashSet`1[T] sentEvents) [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.InputBindingManager.Update () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.World.RefreshStep () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.World.Refresh () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.WorldManager.UpdateStep () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.WorldManager.RunUpdateLoop () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Engine.UpdateStep () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at FrooxEngine.Engine.RunUpdateLoop () [0x00000] in <56db7f41640e4f47b59069c1bf92a3c4>:0 
  at UnityFrooxEngineRunner.FrooxEngineRunner.UpdateFrooxEngine () [0x00000] in <792bfcc7f76a49a9b6c08d912e29a7b8>:0 
  at UnityFrooxEngineRunner.FrooxEngineRunner.Update () [0x00000] in <792bfcc7f76a49a9b6c08d912e29a7b8>:0 
23:43:28.926 ( 59 FPS)  NetworkInitStart
23:43:28.926 ( 59 FPS)  Network manager: FrooxEngine.LNL_Manager - priority: 0
23:43:28.926 ( 59 FPS)  Network manager: FrooxEngine.SteamNetworkManager - priority: -100
23:43:28.928 ( 59 FPS)  Connecting to: lnl-nat://799d09c58c27452dac6cc436407642fd/S-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:28.928 ( 59 FPS)  Punchthrough attempt: 0
23:43:29.188 ( 59 FPS)  NAT INTRODUCTION SUCCESS: 174.58.24.62:61655, token: s-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:29.441 ( 59 FPS)  Session updated, forcing status update
23:43:29.541 ( 60 FPS)  Session updated, forcing status update
23:43:29.934 ( 60 FPS)  Punchthrough attempt: 1
23:43:30.189 ( 60 FPS)  NAT INTRODUCTION SUCCESS: 174.58.24.62:61655, token: s-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:30.941 ( 61 FPS)  Punchthrough attempt: 2
23:43:31.189 ( 60 FPS)  NAT INTRODUCTION SUCCESS: 174.58.24.62:61655, token: s-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:31.443 ( 60 FPS)  Session updated, forcing status update
23:43:31.945 ( 60 FPS)  Punchthrough attempt: 3
23:43:32.198 ( 60 FPS)  NAT INTRODUCTION SUCCESS: 174.58.24.62:61655, token: s-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:32.951 ( 60 FPS)  Punchthrough attempt: 4
23:43:33.196 ( 60 FPS)  NAT INTRODUCTION SUCCESS: 174.58.24.62:61655, token: s-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:33.246 ( 60 FPS)  SendStatusToUser: U-kokoa0429. OnlineStatus: Online
23:43:33.246 ( 60 FPS)  SIGNALR: BroadcastSession SessionInfo. Id: S-99925668-752b-4be1-ad8b-7e81bb5d5f56, Name: The_R4K_ World, Host: The_R4K_, CorrespondingWorldId: , URLs: res-steam://76561198128021056/3/S-99925668-752b-4be1-ad8b-7e81bb5d5f56, lnl-nat://f41715902b864aee81aad3ba039eb2a0/S-99925668-752b-4be1-ad8b-7e81bb5d5f56, IsExpired: False to SpecificContacts (U-kokoa0429)
23:43:33.246 ( 60 FPS)  SIGNALR: BroadcastStatus - Contact status for U-Shadow-Panther.
    UserSessionId: b3e342e8-6f42-4aaf-b5c7-4e1d3ea4b68b.
    Type: GraphicalClient
    OutputDevice: Screen
    IsMobile: False
    OnlineStatus: Online
    IsPresent: True
    LastPresenceTimestamp: 12/10/2023 21:41:57
    LastStatusChange: 12/10/2023 21:41:57
    AppVersion: 2023.10.10.1407
    CompatibilityHash: MUCMAhUUW2SqXWzI/WuKPw==
    CurrentSessionIndex: 1 to SpecificContacts (U-kokoa0429)
23:43:33.957 ( 59 FPS)  NAT Punchthrough failed, Connecting to Relay
23:43:33.963 ( 59 FPS)  Using relay. Available relay count: 3
23:43:34.150 ( 55 FPS)  NETWORK RECEIVE UNCONNECTED: 5.78.110.95:59462, token: PONG, connection token: S-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:34.228 ( 55 FPS)  NETWORK RECEIVE UNCONNECTED: 20.70.130.78:41252, token: PONG, connection token: S-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:34.230 ( 55 FPS)  NETWORK RECEIVE UNCONNECTED: 20.243.107.97:51966, token: PONG, connection token: S-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:34.266 ( 55 FPS)  Relay 5.78.110.95:59462 (5.78.110.95): 187.74 ms
23:43:34.266 ( 55 FPS)  Relay 20.243.107.97:51966 (20.243.107.97): 265.83 ms
23:43:34.266 ( 55 FPS)  Relay 20.70.130.78:41252 (20.70.130.78): 263.82 ms
23:43:34.266 ( 55 FPS)  Found best relay:  5.78.110.95:59462 - Endpoint: 5.78.110.95:59462
23:43:34.452 ( 55 FPS)  LNL_Connection OnPeerConnected: 5.78.110.95:59462, IsOpen: False
23:43:34.851 ( 51 FPS)  Session updated, forcing status update
23:43:34.859 ( 51 FPS)  Connected to: lnl-nat://799d09c58c27452dac6cc436407642fd/S-c0a162a1-0707-4926-9d8f-8a441148bd0c
23:43:34.859 ( 51 FPS)  Waiting for join grant
23:43:35.181 ( 62 FPS)  Disconnected: 174.58.24.62:61655, reason: ConnectionFailed, socketErrorCode: Success

Additional Context

Looks like the SNS connection is not attempted in the attached log. When trying to reproduce, the SNS connection was attempted and succeeded.

Reporters

Shadow Panther

InconsolableCellist commented 11 months ago

I don't have logs, but I've found this happens to me with a friend that is on a T-Mobile home internet connection, which I'm also on. I think it has something to do with the number of network punchthroughs that are necessary, or perhaps the method.

shadowpanther commented 11 months ago

I've tried to reproduce by going to the same session that I was unable to join previously, so the number of NATs is the same, the variable is the restart of the client.

I have at least two NATs on my side of the connection currently.

shadowpanther commented 10 months ago

If SNS is given priority in settings, it works almost all the time. Except I had a case recently when SNS was tried and did timeout (I suspect the host of the session had problems with Steam/SNS), and after that all LNL NAT failed, LNL Relay connected and dropped instantly.

I wasn't able to use LNL NAT and LNL Relay properly even once since the release.

shiftyscales commented 10 months ago

Are you aware of any other users that are experiencing this issue, or any shared conditions/variables you have with other users that have experienced this issue, @shadowpanther?

The fact that it seemingly can fix itself upon a restart seems bizarre- my expectation would be that it should try to go through all available protocols/means of connecting, and upon failing throw an error message- and if all possible routes to the host are blocked/non-functional, I wouldn't expect a restart to fix that.

Did the join indicator have an error message upon this happening, or did it just disappear outright?

This issue needs more information I believe- in specific commonality/replication conditions under which this issue can be observed consistently.

shadowpanther commented 10 months ago

I'm not aware of other users having the same issue. No one left a reaction here.

The SNS fixing itself upon restart would probably be some transient issue between Resonite and Steam itself. Several days ago I wasn't able to connect to a certain host via SNS, but after they restarted, their SNS worked and I was able to join.

Currently I have Prefer SNS set in Settings, that's why I'm able to connect at all. When SNS fails, LNL NAT 1-4 also fails, then LNL Relay connects and disconnects. The host would see me connecting and leaving the session at this time.

With Prefer SNS not set, LNL NAT 1-4 fail, LNL Relay connects and disconnects, and because there was a connection, SNS is not tried at all.

The join indicator did not have any error, because the connection succeeded, then dropped. See: Disconnected: 174.58.24.62:61655, reason: ConnectionFailed, socketErrorCode: Success. Connection failed successfully. The indicator just disappears because the connection is dropped. The last message on the indicator is "getting world state" before it disappears.

The issue could be observed with my internet provider, Serbian SBB. The connection is coaxial DSL, the DSL router has NAT, then the provider itself has another NAT (at least one). I have 4 internal hops in my traceroute:

traceroute to ya.ru (77.88.55.242), 64 hops max, 52 byte packets
 1  192.168.0.1 (192.168.0.1)  4.035 ms  2.205 ms  2.631 ms. <--- DSL Router
 2  100.65.224.1 (100.65.224.1)  8.449 ms  9.298 ms  7.968 ms
 3  172.31.254.2 (172.31.254.2)  9.157 ms  10.810 ms  10.051 ms
 4  172.31.254.2 (172.31.254.2)  9.322 ms  9.180 ms  11.119 ms
 5  bg-tp-m-0-be4-100.sbb.rs (89.216.12.0)  10.063 ms  11.442 ms  9.966 ms   <--- First external hop
 6  de-fra-r-1-be1.sbb.rs (89.216.5.97)  29.897 ms  31.302 ms  29.742 ms

I'm not sure what other info I could provide for replication conditions. If you have any suggestions or tests I could run on my side, I'm all ears.

The main issue here is that the LNL Relay disconnects without giving any indication why. From my understanding, the connection goes from me to the relay, so it should always work, unlike NAT punchthrough which relies on guessing how the incoming packets would interact with the NAT and sending outgoing traffic to "punch" the two-way hole.

shadowpanther commented 9 months ago

Right now this issue is gamebreaking for me because I can't connect to most of the headless servers - they don't have Steam running, thus no SNS.

VIXEN - 2023.12.13.87 - 2023-12-13 21_05_24.log

At least resonite-relay-eu-1 seems to hate me for no apparent reason.

If someone could look into the relay logs, that might help with the investigation, @shiftyscales . Times are GMT+1 (CET).

21:07:05.129 ( 60 FPS)  NAT Punchthrough failed, Connecting to Relay
21:07:05.132 ( 60 FPS)  Using relay. Available relay count: 4
21:07:05.192 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 95.217.33.19:51388, token: PONG, connection token: S-8f840613-7b73-44e1-8225-eb7403f58710
21:07:05.327 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 5.78.110.95:43661, token: PONG, connection token: S-8f840613-7b73-44e1-8225-eb7403f58710
21:07:05.366 ( 60 FPS)  Session updated, forcing status update
21:07:05.376 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.243.107.97:44939, token: PONG, connection token: S-8f840613-7b73-44e1-8225-eb7403f58710
21:07:05.436 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.70.130.78:56914, token: PONG, connection token: S-8f840613-7b73-44e1-8225-eb7403f58710
21:07:05.533 ( 60 FPS)  Relay 20.243.107.97:44939 (20.243.107.97): 244.11 ms
21:07:05.533 ( 60 FPS)  Relay 95.217.33.19:51388 (95.217.33.19): 60.59 ms
21:07:05.533 ( 60 FPS)  Relay 20.70.130.78:56914 (20.70.130.78): 303.56 ms
21:07:05.533 ( 60 FPS)  Relay 5.78.110.95:43661 (5.78.110.95): 193.80 ms
21:07:05.534 ( 60 FPS)  Found best relay: resonite-relay-eu-1 95.217.33.19:51388 - Endpoint: 95.217.33.19:51388
21:07:05.594 ( 60 FPS)  LNL_Connection OnPeerConnected: 95.217.33.19:51388, IsOpen: False
21:07:06.151 ( 60 FPS)  Connected to: lnl-nat://5251b0ff6e90484497798a5d52413bfc/S-8f840613-7b73-44e1-8225-eb7403f58710
21:07:06.154 ( 60 FPS)  Waiting for join grant
21:07:06.369 ( 60 FPS)  Session updated, forcing status update
21:07:06.501 ( 60 FPS)  Disconnected: 135.148.150.40:60755, reason: ConnectionFailed, socketErrorCode: Success

...

21:07:39.183 ( 60 FPS)  NAT Punchthrough failed, Connecting to Relay
21:07:39.183 ( 60 FPS)  Using relay. Available relay count: 4
21:07:39.241 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 95.217.33.19:51388, token: PONG, connection token: S-62e92e0c-4c43-4eda-86b4-bea8bc7cf74c
21:07:39.374 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 5.78.110.95:43661, token: PONG, connection token: S-62e92e0c-4c43-4eda-86b4-bea8bc7cf74c
21:07:39.449 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.243.107.97:44939, token: PONG, connection token: S-62e92e0c-4c43-4eda-86b4-bea8bc7cf74c
21:07:39.457 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.70.130.78:56914, token: PONG, connection token: S-62e92e0c-4c43-4eda-86b4-bea8bc7cf74c
21:07:39.483 ( 60 FPS)  Relay 20.243.107.97:44939 (20.243.107.97): 266.12 ms
21:07:39.483 ( 60 FPS)  Relay 95.217.33.19:51388 (95.217.33.19): 58.09 ms
21:07:39.483 ( 60 FPS)  Relay 20.70.130.78:56914 (20.70.130.78): 274.79 ms
21:07:39.483 ( 60 FPS)  Relay 5.78.110.95:43661 (5.78.110.95): 191.86 ms
21:07:39.483 ( 60 FPS)  Found best relay: resonite-relay-eu-1 95.217.33.19:51388 - Endpoint: 95.217.33.19:51388
21:07:39.542 ( 60 FPS)  LNL_Connection OnPeerConnected: 95.217.33.19:51388, IsOpen: False
21:07:39.997 ( 60 FPS)  Connected to: lnl-nat://1246aaf9e20444679c095a0ee6181820/S-62e92e0c-4c43-4eda-86b4-bea8bc7cf74c
21:07:39.997 ( 60 FPS)  Waiting for join grant
21:07:40.374 ( 60 FPS)  Disconnected: 173.16.65.96:60313, reason: ConnectionFailed, socketErrorCode: Success

...

21:10:34.446 ( 60 FPS)  NAT Punchthrough failed, Connecting to Relay
21:10:34.446 ( 60 FPS)  Using relay. Available relay count: 4
21:10:34.504 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 95.217.33.19:51388, token: PONG, connection token: S-f800085f-3585-4fa2-89b7-c4ad382e1bb7
21:10:34.639 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 5.78.110.95:43661, token: PONG, connection token: S-f800085f-3585-4fa2-89b7-c4ad382e1bb7
21:10:34.734 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.70.130.78:56914, token: PONG, connection token: S-f800085f-3585-4fa2-89b7-c4ad382e1bb7
21:10:34.738 ( 60 FPS)  NETWORK RECEIVE UNCONNECTED: 20.243.107.97:44939, token: PONG, connection token: S-f800085f-3585-4fa2-89b7-c4ad382e1bb7
21:10:34.746 ( 60 FPS)  Relay 20.243.107.97:44939 (20.243.107.97): 291.85 ms
21:10:34.746 ( 60 FPS)  Relay 95.217.33.19:51388 (95.217.33.19): 58.18 ms
21:10:34.746 ( 60 FPS)  Relay 20.70.130.78:56914 (20.70.130.78): 288.00 ms
21:10:34.746 ( 60 FPS)  Relay 5.78.110.95:43661 (5.78.110.95): 192.83 ms
21:10:34.746 ( 60 FPS)  Found best relay: resonite-relay-eu-1 95.217.33.19:51388 - Endpoint: 95.217.33.19:51388
21:10:34.804 ( 60 FPS)  LNL_Connection OnPeerConnected: 95.217.33.19:51388, IsOpen: False
21:10:35.126 ( 60 FPS)  Session updated, forcing status update
21:10:35.309 ( 60 FPS)  Connected to: lnl-nat://1d16728aea4f44049bddbd7d5ab9cddf/S-f800085f-3585-4fa2-89b7-c4ad382e1bb7
21:10:35.309 ( 60 FPS)  Waiting for join grant
21:10:36.070 ( 60 FPS)  Join Granted, Begin Data Model Init
21:10:36.228 ( 60 FPS)  Session updated, forcing status update
21:10:36.628 ( 60 FPS)  Session updated, forcing status update
21:10:36.731 ( 60 FPS)  Disconnected: 135.148.150.40:54569, reason: ConnectionFailed, socketErrorCode: Success

If any further diagnostics is required from me for resolving this, please specify.

ProbablePrime commented 9 months ago

I found ShadowPanther in the EU relay's logs. They list a connection that is terminated by the remote side.

Not sharing here because there's IP addresses everywhere and I might accidentally include someone elses.

shadowpanther commented 9 months ago

While investigating with Prime, I've found that different "what is my IP" services see me as different IP addresses (from the same provider pool), so my provider's NAT might be at fault.

How that affects the Relay connection depends on how the Relay actually functions - whether if connects and proxies all the traffic through itself or just facilitates a direct connection between peers like a STUN server.

shiftyscales commented 8 months ago

Does this issue still occur following the LNL library updates, @shadowpanther?

ProbablePrime commented 6 months ago

It just occurred to me that https://github.com/ProbablePrime/LiteNetLibDebugApp might help you in Debugging @shadowpanther you can deploy it to any machine and see all the connections back and forth. I could even coordinate with you and put a copy of it on the LNL Relay nodes for a little bit.

So if this issue is still occurring let me know.

shadowpanther commented 5 months ago

It just occurred to me that https://github.com/ProbablePrime/LiteNetLibDebugApp might help you in Debugging @shadowpanther you can deploy it to any machine and see all the connections back and forth. I could even coordinate with you and put a copy of it on the LNL Relay nodes for a little bit.

So if this issue is still occurring let me know.

Hey, @ProbablePrime, the issue still happens for me, just caught it (times are UTC+2):

22:17:42.252 (121 FPS)  NAT Punchthrough failed, Connecting to Relay
22:17:42.254 (121 FPS)  Using relay. Available relay count: 4, with preference Any
22:17:42.328 (121 FPS)  NETWORK RECEIVE UNCONNECTED: 95.217.33.19:54037, token: PONG, connection token: S-90686e25-8750-41e8-a3ee-752a13129237
22:17:42.467 (121 FPS)  NETWORK RECEIVE UNCONNECTED: 5.78.110.95:41726, token: PONG, connection token: S-90686e25-8750-41e8-a3ee-752a13129237
22:17:42.550 (121 FPS)  NETWORK RECEIVE UNCONNECTED: 20.243.107.97:45503, token: PONG, connection token: S-90686e25-8750-41e8-a3ee-752a13129237
22:17:42.655 ( 96 FPS)  NETWORK RECEIVE UNCONNECTED: 20.70.130.78:41117, token: PONG, connection token: S-90686e25-8750-41e8-a3ee-752a13129237
22:17:42.698 ( 96 FPS)  Relay 95.217.33.19:54037 (95.217.33.19): 72.58 ms
22:17:42.698 ( 96 FPS)  Relay 20.243.107.97:45503 (20.243.107.97): 281.67 ms
22:17:42.698 ( 96 FPS)  Relay 20.70.130.78:41117 (20.70.130.78): 386.02 ms
22:17:42.698 ( 96 FPS)  Relay 5.78.110.95:41726 (5.78.110.95): 197.10 ms
22:17:42.699 ( 96 FPS)  Found best relay: resonite-relay-eu-1 95.217.33.19:54037 - Endpoint: 95.217.33.19:54037
22:17:42.760 ( 96 FPS)  LNL_Connection OnPeerConnected: 95.217.33.19:54037, IsOpen: False
22:17:42.761 ( 96 FPS)  Configuring Relay to connect to lnl-nat://d4400e66fd5746f1bb249d60ef688495/S-90686e25-8750-41e8-a3ee-752a13129237
22:17:42.997 ( 96 FPS)  Session updated, forcing status update
22:17:43.198 (121 FPS)  Session updated, forcing status update
22:17:43.499 (121 FPS)  Session updated, forcing status update
22:17:48.808 (120 FPS)  Session updated, forcing status update
22:17:49.511 (120 FPS)  Session updated, forcing status update
22:17:49.701 (120 FPS)  SIGNALR: ListenOnKey - U-c2c67bc2-efb6-4692-b240-49408ab18150:e76192d6-91c2-436f-bc69-bc08874578f4
22:17:49.711 (120 FPS)  Session updated, forcing status update
22:17:50.011 (120 FPS)  Session updated, forcing status update
22:17:54.033 (120 FPS)  Disconnected: 95.217.33.19:54037, reason: RemoteConnectionClose, socketErrorCode: Success
22:17:54.034 (120 FPS)  Connection failed: RemoteConnectionClose

VIXEN - 2024.5.1.68 - 2024-05-01 22_13_57.log

Would your app debug the ongoing traffic of other apps or is it just a separate utility like iperf? Because I think that you need all three sides (me, host and relay) to participate in the test and you need the Resonite traffic (connecting through the relay), not the test one.

ProbablePrime commented 2 months ago

Would your app debug the ongoing traffic of other apps or is it just a separate utility like iperf? Separate utility, with its own traffic, it just sorta debugs the connection that's all.

We recently added port number restrictions, which may also help here diagnostically as firewalls and routers can know in advanced what port range is being used for LNL, you can read about these here: https://wiki.resonite.com/Startup_Config_File#Ports

ProbablePrime commented 2 weeks ago

With the Relay and Bridge upgrade over and the previously mentioned items in this issue it would be great to try to reproduce again.

We've changed so much :)

@shadowpanther can you test?