[ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions #75

saadbruno · 2024-01-03T21:00:44Z

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?

The text was updated successfully, but these errors were encountered:

Himyu · 2024-01-08T19:20:45Z

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?

saadbruno · 2024-01-09T14:29:03Z

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:

windows-11-pc-lagged_h264_preview.mp4

On my windows 10 machine, it works flawlessly

windows-10-pc-ok_h264_preview.mp4

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

Himyu · 2024-01-09T15:58:07Z

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?

saadbruno · 2024-01-09T16:49:56Z

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.

Himyu · 2024-01-12T18:04:57Z

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.

saadbruno · 2024-01-12T18:45:45Z

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

Himyu · 2024-01-13T17:06:32Z

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.

Himyu · 2024-01-13T17:53:48Z

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.

saadbruno · 2024-01-14T16:25:03Z

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:

2024-01-14.12-16-28_remux_h264_crf21.-.Copy.mp4

Himyu · 2024-01-16T18:11:30Z

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

saadbruno added the bug Something isn't working label Jan 3, 2024

Himyu self-assigned this Jan 8, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions #75

[ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions #75

saadbruno commented Jan 3, 2024 •

edited

Loading

Himyu commented Jan 8, 2024

saadbruno commented Jan 9, 2024

Himyu commented Jan 9, 2024

saadbruno commented Jan 9, 2024 •

edited

Loading

Himyu commented Jan 12, 2024

saadbruno commented Jan 12, 2024

Himyu commented Jan 13, 2024

Himyu commented Jan 13, 2024

saadbruno commented Jan 14, 2024

Himyu commented Jan 16, 2024

[ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions #75

[ Bug ] Observer tool seems to send information too slowly to the prod toolkit under specific conditions #75

Comments

saadbruno commented Jan 3, 2024 • edited Loading

Himyu commented Jan 8, 2024

saadbruno commented Jan 9, 2024

Himyu commented Jan 9, 2024

saadbruno commented Jan 9, 2024 • edited Loading

Himyu commented Jan 12, 2024

saadbruno commented Jan 12, 2024

Himyu commented Jan 13, 2024

Himyu commented Jan 13, 2024

saadbruno commented Jan 14, 2024

Himyu commented Jan 16, 2024

saadbruno commented Jan 3, 2024 •

edited

Loading

saadbruno commented Jan 9, 2024 •

edited

Loading