1.19.2: Sometimes my custom javascript world names don't show up

[malonnnn]

Are you using the latest version of the plugin available?

Yes, the plugin is up-to-date!

Are you using MySQL?

No

Are you using BungeeCord?

No

Error log (if applicable)

No response

"/chc debug" output (strongly recommended)

debug.zip

Information about the issue/bug

What the issue looks like: https://i.imgur.com/QvOizvl.png

CHC version: https://i.imgur.com/GcTbK7v.png

Console has no error messages: https://i.imgur.com/nI4Adn7.png

This bug has been following me since ChatControl 8. It's quite rare, but I figure I better report it. I only see it once every few thousand messages or so.

A sample of my world_nick.yml variable. There are 63 worlds on my server, most are miniature, void worlds with a single minigame platform, but I've shortened the list to 3 for readability Here's variable:

Type: FORMAT
Value: |-

  var worldInfo = {
    waifuarena: "&6Waifu &4Arena",
    superherosurvival: "&6Superhero &2Survival",
    survival_the_end: "&bUN-Modded &0The End &4&lANARCHY"
  }
  var world = player.getWorld().getName();
  worldInfo[world];
Key: "world_nick"

Sender_Condition: ''
Sender_Permission: ''
Receiver_Condition: ''
Receiver_Permission: ''

[ElBananaa]

This looks like a pretty annoying issue. I'm not sure, but I do believe switching to a more recent js engine, at least on java 11 and above (such as GraalVM JS Engine) would be helpful. Especially when GraalVM outruns Nashorn pretty much everywhere. I just had a quick look at Foundation, and it seems like this shouldn't be too hard to implement. I guess it's worth giving it a shot ^^

[malonnnn]

@ElBananaa I'm sorry are you talking to me? I'm guessing not, but I do run a later version of Java, this bug also appeared on Java 1.8 for me when I was running in 1.16 a few years back

$ java --version
java 18.0.1.1 2022-04-22
Java(TM) SE Runtime Environment (build 18.0.1.1+2-6)
Java HotSpot(TM) 64-Bit Server VM (build 18.0.1.1+2-6, mixed mode, sharing)

[ElBananaa]

@ElBananaa I'm sorry are you talking to me? I'm guessing not, but I do run a later version of Java, this bug also appeared on Java 1.8 for me when I was running in 1.16 a few years back

$ java --version
java 18.0.1.1 2022-04-22
Java(TM) SE Runtime Environment (build 18.0.1.1+2-6)
Java HotSpot(TM) 64-Bit Server VM (build 18.0.1.1+2-6, mixed mode, sharing)

Hey, No, my message is actually supposed to be a suggestion for Kangarko ^^

[kangarko]

Thanks, seems JavaScript variables were not replaced at all, this may be a concurrency issue rather than nashorn vs. graal as banana suggested. Going to investigate although I am uncertain how to resolve this at the moment, sorry!

[ElBananaa]

Thanks, seems JavaScript variables were not replaced at all, this may be a concurrency issue rather than nashorn vs. graal as banana suggested. Going to investigate although I am uncertain how to resolve this at the moment, sorry!

Alright! I thought this was somehow related to nashorn being too slow to process the variable before it gets sent in chat ^^ Tho, allowing others JS engine wouldn't be a bad thing at all imo ^^

[kangarko]

I dont think so, it would still process but just lag the server haha.

The real problem might be in here https://github.com/kangarko/Foundation/blob/master/src/main/java/org/mineacademy/fo/model/Variables.java#L264

We use a static field to completely ignore and not parse Javascript variables during the time when they are being parsed to prevent a race condition. My feeling is that somehow when the method is called rapidly async multiple times the field is not synchronized.

I have bad experience using the "synchronized" block so I dont want to push this in production given how many customers we have.

@malonnnn How often it happens? Like 1-2x per day? Try the special version with the synchronized block below: ChatControl-Red-10.13.3.zip

[malonnnn]

Oh crap, I had no idea anyone responded to me, I'm so bad about checking messages. It's extraordinarily rare. The most often I've seen it was maybe twice in one week. Since I made this particular report a year ago, I haven't seen it until today again.

https://i.imgur.com/e7HY6Mu.png

[18:07:02 INFO]: [standard] DreamyStarz: wb
[18:07:06 INFO]: [standard] GillionT: do items stay in your inventory?
[18:07:06 INFO]: [standard] DreamyStarz: nvm

@kangarko should I make a new thread about this?

crap, I'm just now reading above there's really no good way to troubleshoot this, so feel free to ignore my post entirely considering the bug is so rare

[kangarko]

Please test on the next version, we'll be making some changes there.

[malonnnn]

No dice, the error appeared for the 2nd time. I saw it last week but didn't get around to posting the bug report, but it just happened again. Am using latest paper, latest build of ChatControlRed. Happy to provide full logs if you want.

https://i.imgur.com/wSUY4fX.png

[kangarko]

I'll try to add some more debugging in the next version. How often does it happen now?

[malonnnn]

The frequency hasn't changed, still incredibly infrequent

[kangarko]

Can you please attach your /chc debug again?

[malonnnn]

debug.zip

Unfortunately it has been happening more frequently. I have attached a few more screenshots regarding it, but I've seen the error approx 8-10 times in a month

https://i.imgur.com/aQ40p9o.png https://i.imgur.com/yFVJR0T.png https://i.imgur.com/nrfYiGv.png

[kangarko]

Thanks, I need some more days to debug this.

[kangarko]

Try the next version please whether it will happen with the same frequency.

[malonnnn]

It just happened again with the new version and console had no errors to speak of (you pushed 10.22.4 today, but i haven't installed that yet, soon though)

[10:00:59 INFO]: ChatControlRed™ 10.22.3

Visual error:
https://i.imgur.com/NwHc1rs.png

Console:
https://i.imgur.com/GaP6oOX.png

Do you want the debug.zip?

[kangarko]

Ooh so frustrating! No, I assume you did not change anything since the above file. I'll try to add some special debug messages to help me see why this is still happening.

[malonnnn]

You're correct, I have not made any changes that should alter anything. What's more frustrating, I semi-recently upgraded my server to a much faster server and the issue somehow seems even more frequent, which is opposite of what I would expect. This could be coincidence though.

Do you think it could have anything to do with the way I'm writing the code?

Maybe something to do with the Value: part because it uses the weird |- operator?

I don't really write JS much, and the way Value: is calculated feels like there's a ton of stuff going on under the hood, probably within the JS parser. Is there a different way I can write it?

Type: FORMAT
Value: |-

  var worldInfo = {
    world1: "fancy name1",
    world2: "fancy name2",
    world3: "fancy name3"
  }
  if (typeof player.getWorld === "function") { 
    var world = player.getWorld().getName();
    worldInfo[world];
  }
# the above if statement exists because when sending from discord, player.getWorld() does not exist
Key: "world_nick"
Sender_Condition: ''
Sender_Permission: ''
Receiver_Condition: ''
Receiver_Permission: ''

[kangarko]

Please remove the "if (typeof player.getWorld === "function")" as it should always be true on Bukkit. The problem is one layer above so the JS is not even found, that is what I am trying to resolve.

Try this dev build of ChatControl please, I have made some concurrency changes to replacing JS.

ChatControl-Red-10.22.4.zip

[malonnnn]

The console spits a lot of errors about player.getWorld() not existing when players are sending messages from discord, thats why its there. Is there another way I should do it?

I am installing the dev build right now

Edit: just noticed you pushed 10.22.5 live, with updates of "fixed rare concurrency issues of JS variables not being replaced" and also "fixed discord throwing errors regarding the player.getWorld() function", so I'm going to presume I should use 10.22.5 ?

[kangarko]

Oh I see, well the recommended way is to either use Sender_Condition: '{sender_is_player}', or, if you want to replace it to an empty string then what you are doing is correct.

Correct, the newly pushed update contains the dev build changes and some other ones too, you can use that instead.

[malonnnn]

oh okay, i thought sender_is_player would fail due to discord chatters are not actual players, so that's my mistake and I will use sender_is_player. Either way, I'm using the new build for a couple days, no issues so far! thank you!

[malonnnn]

@kangarko just wanted to say I have not seen the issue since the update!

I have been playing extremely frequently recently (i'd rather not say how much, kinda embarassing lol) but everything has been perfect!

Thank you so much for everything

[kangarko]

Thank you so much for taking the time to observe and report, all the best <3

[malonnnn]

Bad news: It happened again

Good news: FINALLY CONSOLE ERROR

More good news: You don't have to worry about this yet, because my dumbass forgot to put sender_is_player and remove the function check. But i truly did it now proof

i'll update if it happens again

[17:34:29] [Async Chat Thread - #40/ERROR]: ChatControlRed 10.22.6 encountered a ScriptException! Please check your error.log and report this issue with the information in that file. Running Paper 1.20.2-R0.1-SNAPSHOT and Java 17.0.5
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed] !-----------------------------------------------------!
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Error executing JavaScript in a variable!
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Variable: world_nick.yml
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Line: var world = player.getWorld().getName();
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Sender: CraftPlayer{name=tt_theangelcals}
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Replacements: {channel=standard, message=IM ON MAKS SIDE, message_uuid=fda09905-b31f-4a5a-9cba-2f4e7e101ebc}
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Error: Report: Unable to parse JavaScript code on line '75' for CraftPlayer{name=tt_theangelcals}. Error: javax.script.ScriptException: TypeError: Cannot read property "getWorld" from undefined in <eval> at line number 75
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  This is likely NOT our plugin bug, check Value key in world_nick.yml
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  that it returns a valid JavaScript code before reporting!
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed] !-----------------------------------------------------!
[17:34:29] [Async Chat Thread - #40/INFO]: Report: Unable to parse JavaScript code on line '75' for CraftPlayer{name=tt_theangelcals}. Error: javax.script.ScriptException: TypeError: Cannot read property "getWorld" from undefined in <eval> at line number 75
[17:34:29] [Async Chat Thread - #40/INFO]: <eval>:75 TypeError: Cannot read property "getWorld" from undefined
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.JavaScriptExecutor.run(JavaScriptExecutor.java:198)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.JavaScriptExecutor.run(JavaScriptExecutor.java:125)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variable.getValue(Variable.java:234)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variable.buildPlain(Variable.java:296)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variables.replaceJavascriptVariables0(Variables.java:310)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variables.replaceJavascriptVariables0(Variables.java:297)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variables.replace(Variables.java:267)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variables.replace(Variables.java:218)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.model.Variables.replace(Variables.java:202)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Format.replaceVariables(Format.java:539)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Format.buildOption(Format.java:427)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Format.build(Format.java:202)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Channel.sendMessage(Channel.java:624)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Channel.sendMessage(Channel.java:527)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.model.Channel.sendMessage(Channel.java:512)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.listener.ChatListener.execute(ChatListener.java:180)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.listener.ChatListener.execute(ChatListener.java:34)
[17:34:29] [Async Chat Thread - #40/INFO]:  at chatcontrol.jar//org.mineacademy.chatcontrol.lib.event.SimpleListener.execute(SimpleListener.java:89)
[17:34:29] [Async Chat Thread - #40/INFO]:  at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:77)
[17:34:29] [Async Chat Thread - #40/INFO]:  at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:70)
[17:34:29] [Async Chat Thread - #40/INFO]:  at io.papermc.paper.plugin.manager.PaperEventManager.callEvent(PaperEventManager.java:54)
[17:34:29] [Async Chat Thread - #40/INFO]:  at io.papermc.paper.plugin.manager.PaperPluginManagerImpl.callEvent(PaperPluginManagerImpl.java:126)
[17:34:29] [Async Chat Thread - #40/INFO]:  at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:615)
[17:34:29] [Async Chat Thread - #40/INFO]:  at io.papermc.paper.adventure.ChatProcessor.post(ChatProcessor.java:416)
[17:34:29] [Async Chat Thread - #40/INFO]:  at io.papermc.paper.adventure.ChatProcessor.process(ChatProcessor.java:102)
[17:34:29] [Async Chat Thread - #40/INFO]:  at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:718)
[17:34:29] [Async Chat Thread - #40/INFO]:  at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482)
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed] !-----------------------------------------------------!
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed]  Unhandled exception listening to AsyncPlayerChatEvent
[17:34:29] [Async Chat Thread - #40/INFO]: [ChatControlRed] !-----------------------------------------------------!

[malonnnn]

Visual Error:
https://i.imgur.com/MSPjTmp.png

Console Error:
https://pastebin.com/raw/FNADTKvn

world_nick.yml:
https://pastebin.com/raw/rhdyhnGV

[kangarko]

Odd enough the player seems to be null. The Altair was ingame as a normal player or was there a difference in how he was connected?

[kangarko]

For now you can just add player ? player.getWorld() : "" or something like that, basically add an "if" condition to your code and show nothing if the player is null

[malonnnn]

Altair was an active online player, nothing strange. Altair is a nickname for the player, provided by chatcontrol (/chc tag nick <player> Altair)

They are a relatively new minecraft player, and claim my server is their first multiplayer server ever. I have helped the player install sodium+lithium in the past for FPS reasons, so I can tell you they are using vanilla launcher and have practically zero modding knowledge.

Like so?

.
.
.
    everglow: "&#8afb6eE&#79eb71v&#68dc75e&#57cc78r&#47bc7bg&#36ac7el&e●&#148d85w",
    voidnexus: "&8V&5o&8id N&ee&8x&du&8s"
  }
  player ? player.getWorld() : "";
  var world = player.getWorld().getName();
  worldInfo[world];
Key: "world_nick"

Sender_Condition: '{sender_is_player}'
Sender_Permission: ''
Receiver_Condition: ''
Receiver_Permission: ''

[kangarko]

I would do something like this:

  var world = player ? player.getWorld().getName() : "def";
  worldInfo[world];

And then add the "def" world which resorts to a fallback for now.

[malonnnn]

@kangarko Update!

It's a race condition!

I've seen it happen 5+ times since I last posted, and I notice a recurring pattern when it happens!

It only happens when 2 people send a chat message at the exact same time!

I hope this helps

[malonnnn]

@kangarko

and it always appears to be the first message that doesnt receive formatting, second one gets formatting

[kangarko]

Try the next version, I have disabled an additional replacement of variables within variables due to a race condition so it might have as well been the same what you are seeing.

[malonnnn]

Issue still persists, I'm sorry :(

[kangarko]

@malonnnn can you please re-post the error? I need to check if it equals to the old one whether things changed