Log Spam for skull cache

[luismayme]

Versions
Plugin version: 6.19.1
Paper version: 1.21.10

Describe the bug
I get this message spammed quite a few times on every startup.
[06:00:49 INFO]: [VotingPlugin] VotingPlugin is up to date! Version: 6.19.1
[06:01:05 INFO]: [VotingPlugin] Pausing skull caching due to hitting rate limit or an error, increasing delay for caching
[06:16:26 INFO]: [VotingPlugin] Pausing skull caching due to hitting rate limit or an error, increasing delay for caching

To Reproduce
Steps to reproduce the behavior:
Just startup the server with the mentioned versions and watch the log.

Expected behavior
Not sure if it's causing any issue really, but I would guess it does?

Screenshots/Configs

Additional context
Add any other context about the problem here.

[BenCodez]

Increase the skull load time in the config and see if that helps

[BlvckBytes]

I'm facing a similar issue - and it certainly isn't due to hitting rate-limiting. I've added some additional debug-logging to SimpleAPI > SkullCache.java:

@SuppressWarnings("deprecation")
public static String getSkinUrl(String uuid) throws IOException {
	String json = getContent(api_profile_link + uuid);
	// v- Debug
	System.out.println("json=" + json + ", url=" + api_profile_link + uuid);
	JsonObject o = parser.parse(json).getAsJsonObject();
	String jsonBase64 = o.get("properties").getAsJsonArray().get(0).getAsJsonObject().get("value").getAsString();

	o = parser.parse(new String(Base64.getDecoder().decode(jsonBase64))).getAsJsonObject();
	String skinUrl = o.get("textures").getAsJsonObject().get("SKIN").getAsJsonObject().get("url").getAsString();
	return skinUrl;
}

Which prints the following:

[01:20:05 INFO]: [VotingPlugin] Successfully hooked into vault economy!
[01:20:05 INFO]: [VotingPlugin] Hooked into vault permissions
[01:20:07 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "1722b99ba2244fd29fce936a334dfd99",  "name" : "_Gor_",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/1722b99b-a224-4fd2-9fce-936a334dfd99
[01:20:07 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "1722b99ba2244fd29fce936a334dfd99",  "name" : "_Gor_",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/1722b99b-a224-4fd2-9fce-936a334dfd99
[01:20:10 INFO]: [WorldGuard] Region data changes made in 'world' have been background saved
[01:20:10 INFO]: [WorldGuard] Region data changes made in 'creative' have been background saved
[01:20:11 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "16b94c2798c447728192730ae2677738",  "name" : "Cola1222",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/16b94c27-98c4-4772-8192-730ae2677738
[01:20:11 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "16b94c2798c447728192730ae2677738",  "name" : "Cola1222",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/16b94c27-98c4-4772-8192-730ae2677738
[01:20:15 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "7e1ca9f6e93640aab90f473c0131737b",  "name" : "Kesrin",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/7e1ca9f6-e936-40aa-b90f-473c0131737b
[01:20:15 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "7e1ca9f6e93640aab90f473c0131737b",  "name" : "Kesrin",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/7e1ca9f6-e936-40aa-b90f-473c0131737b
[01:20:19 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "9688533cbc8a49cbb0c0b1aaae310b8a",  "name" : "PeterPan01",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/9688533c-bc8a-49cb-b0c0-b1aaae310b8a
[01:20:19 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "9688533cbc8a49cbb0c0b1aaae310b8a",  "name" : "PeterPan01",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/9688533c-bc8a-49cb-b0c0-b1aaae310b8a
[01:20:23 INFO]: [VotingPlugin] [STDOUT] json=, url=https://sessionserver.mojang.com/session/minecraft/profile/00000000-0000-0000-0009-01f2e3399c45
[01:20:23 WARN]: java.lang.IllegalStateException: Not a JSON Object: null
[01:20:23 WARN]: 	at com.google.gson.JsonElement.getAsJsonObject(JsonElement.java:165)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.getSkinUrl(SkullCache.java:218)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.itemWithUuid(SkullCache.java:390)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.cacheSkull(SkullCache.java:82)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCacheHandler$2.run(SkullCacheHandler.java:124)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[01:20:23 WARN]: 	at java.base/java.lang.Thread.run(Thread.java:1575)
[01:20:23 INFO]: [VotingPlugin] Pausing skull caching due to hitting rate limit or an error, increasing delay for caching

As you can see, an error occurs while trying to read the JSON-response from Mojang's REST-API. While in this case, the plugin is trying to resolve the skin of a Bedrock-user (notice the zero-prefixed UUID), there are probably multiple reasons as to why the UUID of a cached player may be invalid.

To be honest, just increasting the delay without differentiating on the underlying error is not an ideal solution. If error-handling was to be improved, we could probably get rid of this console-spam in a clean manner.

(Also, requests seem to always be made twice?)

[BlvckBytes]

I took the liberty of experimenting with the project myself and hereby propose the following changes regarding the SimpleAPI-project:

diff --git a/SimpleAPI/src/main/java/com/bencodez/simpleapi/skull/SkullCache.java b/SimpleAPI/src/main/java/com/bencodez/simpleapi/skull/SkullCache.java
index f0494df..c3d5b77 100644
--- a/SimpleAPI/src/main/java/com/bencodez/simpleapi/skull/SkullCache.java
+++ b/SimpleAPI/src/main/java/com/bencodez/simpleapi/skull/SkullCache.java
@@ -29,6 +29,7 @@ import com.google.gson.JsonParser;
 
 import lombok.Getter;
 import lombok.Setter;
+import org.jetbrains.annotations.Nullable;
 
 public class SkullCache {
 
@@ -191,10 +192,15 @@ public class SkullCache {
                flush(604800000);
        }
 
-       public static String getContent(String link) throws IOException {
+       public static @Nullable String getContent(String link) throws IOException {
                try {
                        URL url = new URL(link);
                        HttpsURLConnection conn = (HttpsURLConnection) url.openConnection();
+
+                       // The UUID of this profile does not exist
+                       if (conn.getResponseCode() == 204)
+                               return null;
+
                        BufferedReader br = new BufferedReader(new InputStreamReader(conn.getInputStream()));
                        String outputLine = "";
 
@@ -204,7 +210,6 @@ public class SkullCache {
                        }
                        br.close();
                        return outputLine;
-
                } catch (MalformedURLException e) {
                        e.printStackTrace();
                }
@@ -212,8 +217,12 @@ public class SkullCache {
        }
 
        @SuppressWarnings("deprecation")
-       public static String getSkinUrl(String uuid) throws IOException {
+       public static @Nullable String getSkinUrl(String uuid) throws IOException {
                String json = getContent(api_profile_link + uuid);
+
+               if (json == null)
+                       return null;
+
                JsonObject o = parser.parse(json).getAsJsonObject();
                String jsonBase64 = o.get("properties").getAsJsonArray().get(0).getAsJsonObject().get("value").getAsString();
 
@@ -263,14 +272,14 @@ public class SkullCache {
                return skull;
        }
 
-       public static ItemStack getSkull(String url, UUID uuid) throws MalformedURLException, IOException {
+       public static ItemStack getSkull(@Nullable String url, UUID uuid) throws MalformedURLException, IOException {
                ItemStack skull = new ItemStack(Material.PLAYER_HEAD);
                if (url == null || url.isEmpty()) {
                        return skull;
                }
                SkullMeta skullMeta = (SkullMeta) skull.getItemMeta();
                PlayerProfile profile = Bukkit.getServer().createPlayerProfile(uuid);
-               profile.getTextures().setSkin(new URL(getSkinUrl(uuid.toString())));
+               profile.getTextures().setSkin(new URL(url));
                skullMeta.setOwnerProfile(profile);
                skull.setItemMeta(skullMeta);
                return skull;

As per the official API-docs at https://mojang-api-docs.gapple.pw/no-auth/uuid-to-profile, a status-code of 204 refers to an unknown UUID. I represent this state with getContent being null, passing it through in getSkinUrl with another null-check. Last but not least, I removed the redundant call to getSkinUrl in getSkull - a null-check was already in place.

My console has been clear of these warnings ever since. I'd advise to handle this case without additional logging, as I did above - simply fall back to the default head-texture.

[BenCodez]

I'm facing a similar issue - and it certainly isn't due to hitting rate-limiting. I've added some additional debug-logging to SimpleAPI > SkullCache.java:

@SuppressWarnings("deprecation")
public static String getSkinUrl(String uuid) throws IOException {
String json = getContent(api_profile_link + uuid);
// v- Debug
System.out.println("json=" + json + ", url=" + api_profile_link + uuid);
JsonObject o = parser.parse(json).getAsJsonObject();
String jsonBase64 = o.get("properties").getAsJsonArray().get(0).getAsJsonObject().get("value").getAsString();

o = parser.parse(new String(Base64.getDecoder().decode(jsonBase64))).getAsJsonObject();
String skinUrl = o.get("textures").getAsJsonObject().get("SKIN").getAsJsonObject().get("url").getAsString();
return skinUrl;
}
Which prints the following:

[01:20:05 INFO]: [VotingPlugin] Successfully hooked into vault economy!
[01:20:05 INFO]: [VotingPlugin] Hooked into vault permissions
[01:20:07 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "1722b99ba2244fd29fce936a334dfd99",  "name" : "_Gor_",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/1722b99b-a224-4fd2-9fce-936a334dfd99
[01:20:07 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "1722b99ba2244fd29fce936a334dfd99",  "name" : "_Gor_",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/1722b99b-a224-4fd2-9fce-936a334dfd99
[01:20:10 INFO]: [WorldGuard] Region data changes made in 'world' have been background saved
[01:20:10 INFO]: [WorldGuard] Region data changes made in 'creative' have been background saved
[01:20:11 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "16b94c2798c447728192730ae2677738",  "name" : "Cola1222",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/16b94c27-98c4-4772-8192-730ae2677738
[01:20:11 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "16b94c2798c447728192730ae2677738",  "name" : "Cola1222",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/16b94c27-98c4-4772-8192-730ae2677738
[01:20:15 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "7e1ca9f6e93640aab90f473c0131737b",  "name" : "Kesrin",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/7e1ca9f6-e936-40aa-b90f-473c0131737b
[01:20:15 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "7e1ca9f6e93640aab90f473c0131737b",  "name" : "Kesrin",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/7e1ca9f6-e936-40aa-b90f-473c0131737b
[01:20:19 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "9688533cbc8a49cbb0c0b1aaae310b8a",  "name" : "PeterPan01",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/9688533c-bc8a-49cb-b0c0-b1aaae310b8a
[01:20:19 INFO]: [VotingPlugin] [STDOUT] json={  "id" : "9688533cbc8a49cbb0c0b1aaae310b8a",  "name" : "PeterPan01",  "properties" : [ {    "name" : "textures",    "value" : "..."  } ],  "profileActions" : [ ]}, url=https://sessionserver.mojang.com/session/minecraft/profile/9688533c-bc8a-49cb-b0c0-b1aaae310b8a
[01:20:23 INFO]: [VotingPlugin] [STDOUT] json=, url=https://sessionserver.mojang.com/session/minecraft/profile/00000000-0000-0000-0009-01f2e3399c45
[01:20:23 WARN]: java.lang.IllegalStateException: Not a JSON Object: null
[01:20:23 WARN]: 	at com.google.gson.JsonElement.getAsJsonObject(JsonElement.java:165)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.getSkinUrl(SkullCache.java:218)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.itemWithUuid(SkullCache.java:390)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCache.cacheSkull(SkullCache.java:82)
[01:20:23 WARN]: 	at votingplugin-6.19.2-SNAPSHOT.jar//com.bencodez.votingplugin.simpleapi.skull.SkullCacheHandler$2.run(SkullCacheHandler.java:124)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[01:20:23 WARN]: 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[01:20:23 WARN]: 	at java.base/java.lang.Thread.run(Thread.java:1575)
[01:20:23 INFO]: [VotingPlugin] Pausing skull caching due to hitting rate limit or an error, increasing delay for caching

As you can see, an error occurs while trying to read the JSON-response from Mojang's REST-API. While in this case, the plugin is trying to resolve the skin of a Bedrock-user (notice the zero-prefixed UUID), there are probably multiple reasons as to why the UUID of a cached player may be invalid.

To be honest, just increasting the delay without differentiating on the underlying error is not an ideal solution. If error-handling was to be improved, we could probably get rid of this console-spam in a clean manner.

(Also, requests seem to always be made twice?)

Bedrock players were already ignored with the prefix, but not without. I added your changes: https://bencodez.com/job/VotingPlugin/

[BlvckBytes]

Bedrock players were already ignored with the prefix, but not without. I added your changes: https://bencodez.com/job/VotingPlugin/

Thank you! As I've said, there may be multiple reasons as to why a UUID is unknown to Mojang. If the latest build you've linked also solves the console-spam for @luismayme, we may close this issue.

[BenCodez]

Bedrock players were already ignored with the prefix, but not without. I added your changes: https://bencodez.com/job/VotingPlugin/

Thank you! As I've said, there may be multiple reasons as to why a UUID is unknown to Mojang. If the latest build you've linked also solves the console-spam for @luismayme, we may close this issue.

Yeah, I guess I never accounted for that, or atleast I thought I did. I'll wait until @luismayme confirms it's fixed

[luismayme]

Thanks for your replies and quick fix! I will try to download the latest artifact and come back to you guys ASAP. Likely this afternoon.

[luismayme]

Update: I have downloaded the latest artifact and indeed the error no longer appears, thanks for everything :)

[luismayme]

Sorry for the confussion but it just happened again after a reset... Same output, I can't give any more debug info I believe. I don't know if there is an option to enable debug for the message.

[BlvckBytes]

I didn't get any more messages, even after multiple restarts. To rule out a confusion on jars, please zip and attach the exact version of your plugin and make sure that you do not upload some other old version on your disk.

If needed, I can provide you with a version that logs details later on today.

[luismayme]

Here you go:

VotingPlugin.zip

[BlvckBytes]

Please give the following build with added debug-logs a shot and paste as much of the output as possible (preferred - just upload the latest.log).

DebugVotingPlugin.zip