league-observer-tool [ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions

Describe the bug The prod toolkit updates the info on screen too slowly (such as in-game timers, etc) The reason I think this is a league-observer-tool issue and not related to the league-prod-toolkit is that I have 2 PCs at home (connecting to the same LPT instance), and this issue only happens on one of them (my league-prod-toolkit is running on a separate ubuntu instance).

This means that the in-game overlay on LPT is always delayed compared to the actual game.

Other relevant info is that when this issue happens, if I close the observer tool, but keep the LPT scoreboard still open, you can see it still updates (while delayed compared to the gameplay). So I don't know if the observer tool is sending too much data and LPT can't keep up with it or if it's something else.

To Reproduce Steps to reproduce the behavior:

Just run the observer tool and connect to LPT
See error

Expected behavior LPT scoreboard should keep up with the actual game data

Screenshots

System:

OS: Windows 11
Node: Whatever is in the latest Docker image
Prod Tool Version: v1.8.6
Observer Tool Version: v6.8.1

Additional context The issue happens on my Windows 11 machine. The other PC where it runs smoothly is running Windows 10, I don't know if Windows 11 has to do somthing with it.

I tried running the observer tool with compatibility mode set to windows 8 and it didn't help. Running as admin also didn't help.

Logs didn't show any relevant info:

logs

[2024-01-03 17:46:56.938] [info]  (updater)          Checking for update
[2024-01-03 17:49:23.256] [info]  (updater)          Checking for update
[2024-01-03 17:49:24.738] [info]  (updater)          Update for version 6.8.1 is not available (latest version: 6.8.1, downgrade is disallowed).
[2024-01-03 17:51:45.134] [info]  (in-game-live-events) {
	"eventname": "OnKillDragon_Spectator",
	"other": "SRU_Dragon_Chemtech",
	"otherTeam": "Neutral",
	"source": "woshibt196",
	"sourceID": "6",
	"sourceTeam": "Chaos"
}
[2024-01-03 17:51:45.135] [info]  (in-game-live-events) [
{
eventname: 'OnKillDragon_Spectator',
other: 'SRU_Dragon_Chemtech',
otherTeam: 'Neutral',
source: 'woshibt196',
sourceID: '6',
sourceTeam: 'Chaos'
}
]
[2024-01-03 17:51:50.647] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T1_L_03_A",
"otherTeam": "Order",
"source": "woshibt196",
"sourceID": "6",
"sourceTeam": "Chaos"
}
[2024-01-03 17:51:50.648] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T1_L_03_A',
otherTeam: 'Order',
source: 'woshibt196',
sourceID: '6',
sourceTeam: 'Chaos'
}
]
[2024-01-03 17:51:50.649] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T1_L_03_A",
"otherTeam": "Order",
"source": "woshibt196",
"sourceID": "6",
"sourceTeam": "Chaos"
}
[2024-01-03 17:51:50.649] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T1_L_03_A',
otherTeam: 'Order',
source: 'woshibt196',
sourceID: '6',
sourceTeam: 'Chaos'
}
]
[2024-01-03 17:51:50.733] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T1_L_03_A",
"otherTeam": "Order",
"source": "Minion_T200L2S00N0077",
"sourceTeam": "Chaos"
}
[2024-01-03 17:51:50.733] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T1_L_03_A',
otherTeam: 'Order',
source: 'Minion_T200L2S00N0077',
sourceTeam: 'Chaos'
}
]
[2024-01-03 17:51:50.768] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T1_R_03_A",
"otherTeam": "Order",
"source": "Minion_T200L0S00N0088",
"sourceTeam": "Chaos"
}
[2024-01-03 17:51:50.769] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T1_R_03_A',
otherTeam: 'Order',
source: 'Minion_T200L0S00N0088',
sourceTeam: 'Chaos'
}
]
[2024-01-03 17:52:10.536] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T2_R_03_A",
"otherTeam": "Chaos",
"source": "凌 宝",
"sourceID": "3",
"sourceTeam": "Order"
}
[2024-01-03 17:52:10.536] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T2_R_03_A',
otherTeam: 'Chaos',
source: '凌 宝',
sourceID: '3',
sourceTeam: 'Order'
}
]
[2024-01-03 17:52:20.737] [info]  (in-game-live-events) {
"eventname": "OnTurretPlateDestroyed",
"other": "Turret_T2_R_03_A",
"otherTeam": "Chaos",
"source": "凌 宝",
"sourceID": "3",
"sourceTeam": "Order"
}
[2024-01-03 17:52:20.738] [info]  (in-game-live-events) [
{
eventname: 'OnTurretPlateDestroyed',
other: 'Turret_T2_R_03_A',
otherTeam: 'Chaos',
source: '凌 宝',
sourceID: '3',
sourceTeam: 'Order'
}
]

Is there anything I can do to help reproduce this bug?

Jan 03 '24 21:01 saadbruno

From your screenshot, I can see you do not have any theme applied to the LPT yet. I know it's most probably not related, but that's sometimes where the timeouts come from.

Another question is when you compare the machine where the issue is occurring and the LPT server, are the clocks in sync, or are they off? And how is it on your Windows 10 machine?

Jan 08 '24 19:01 Himyu

I also tried with a theme, didn't help. Clocks are in sync, yea.

I did more testing, and it seems to be related to Farsight. I added a line logging the current game time for both the handleData class, and the handleFarsightData:

console.log(`Game Data: ${this.gameState.gameTime}`) to https://github.com/rcv-prod-toolkit/module-league-in-game/blob/f4aaf5578aa869046cc3eb4872147f3d1627c579/controller/InGameState.ts#L197

and console.log(`Farsight: ${farsightData.gameTime}`) to https://github.com/rcv-prod-toolkit/module-league-in-game/blob/f4aaf5578aa869046cc3eb4872147f3d1627c579/controller/InGameState.ts#L267

And it seems that every time I enable farsight on my windows 11 machine, it starts lagging. Here's a video:

https://github.com/RCVolus/league-observer-tool/assets/23201434/e5a2cc20-97b0-4cd5-81f1-8d2cac27020a

On my windows 10 machine, it works flawlessly

https://github.com/RCVolus/league-observer-tool/assets/23201434/c4fb6a23-d159-4d1e-a211-9114f75ae778

In both cases, I'm using the same replay, so it's not a replay issue.

Jan 09 '24 14:01 saadbruno

Your system clocks might be in sync but the time in the observer tool and the Windows clock is at least 2 to 3 seconds off on the windows 11 video. Can you check that again, please?

Could you please provide us with the version and the build of windows you are using?

Jan 09 '24 15:01 Himyu

Gotcha, I see what you mean. I re-synced both the server time and my local time, but it doesn't seem to help either. Here's a screenshot.

LPT is running v1.8.7, observer tool is v6.9.1 Windows 11 version is 22H2 (OS Build 22621.2861)

EDIT: One thing to note, I'm not sure if it's clear from screenshots / videos, is that the problem is not only that the overlay is behind the actual game, is that the overlay is getting updates slower than the game. Like, one update every two or three seconds.

So it starts synced, but slowly gets far behind.

Jan 09 '24 16:01 saadbruno

Ok, could you please change the log you added? Instead of returning just the ingame time from Farsight, please return all the data, there is a benchmark to measure how long the memory reading took. We Would like to have a Look at that.

Jan 12 '24 18:01 Himyu

That's a good idea! I forgot it had a benchmark.

So, i changed the log to

console.log(`Farsight benchmark: ${JSON.stringify(farsightData.benchmark)}`);

But it seems pretty okay, around 2.5ms for full updates

Farsight benchmark: {"readObjectsMs":1.398800015449524,"fullUpdateMs":2.3025999069213867}
Farsight benchmark: {"readObjectsMs":1.4716999530792236,"fullUpdateMs":2.3938000202178955}
Farsight benchmark: {"readObjectsMs":1.3432999849319458,"fullUpdateMs":2.4291999340057373}
Farsight benchmark: {"readObjectsMs":1.5176000595092773,"fullUpdateMs":2.498699903488159}
Farsight benchmark: {"readObjectsMs":1.5752999782562256,"fullUpdateMs":2.541300058364868}
Farsight benchmark: {"readObjectsMs":1.374400019645691,"fullUpdateMs":2.4816999435424805}

Problem still persists.

I'm not sure what else i could do to try to reproduce this bug on other machines, or figure out why this is happening in this case

Jan 12 '24 18:01 saadbruno

From what I can tell it is not 2.5 ms instead, it means 2.5 ticks, and depending on the system that could mean several things. I will try to adjust the code so it will return ms instead of ticks in a small patch. And then we can try again.

Jan 13 '24 17:01 Himyu

could you please download this version and try again on both systems? https://github.com/RCVolus/league-observer-tool/releases/tag/v6.9.2-alpha.0 maybe this gives us a better understanding of what's going on.

Jan 13 '24 17:01 Himyu

So, with this version, windows 10 PC still works fine Windows 11 still has the same issue.

Now, with both systems I started getting errors with the Live Events API, it seems to be a League thing, not a LPT thing. Logs says

[2024-01-14 12:16:35.075] [error] (in-game-live-events) Error: connect ECONNREFUSED 127.0.0.1:34243
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1555:16)

But that's a separate issue.

Now, there's something else I noticed while testing, that might give some clues as to what's happening. When running the observer tool, if I kill it while running (not disconnecting using the "power button", but only when quitting while connected), then suddenly LPT will just catch up to the latest data sent by the observer tool.

Here's a video of it:

https://github.com/RCVolus/league-observer-tool/assets/23201434/d8844e80-68b9-4035-884e-e875a99710d0

Jan 14 '24 16:01 saadbruno

Another question on that Note do you have both observer Tools running at the Same time ?

Jan 16 '24 18:01 Himyu