Recently, a bug was submitted about Bok’s Banging Butterflies complaining that there was too much logging by the mod. This might seem unimportant at first, but efficient logging is vital to any project. You ignore bad logging at your peril.
In my role as a server developer, one of the things we would often discuss is logging. Which log outputs should we keep, which should be debug only, which should we get rid of altogether. Maintaining good log output is as important as any other system.
Generally you only want to log everything during development. It can be handy to see what’s going on without having to break into it with a debugger, and allows developers to see what’s happening under the hood. But when you release software to the world, you generally only want to log errors. This allows users to be able to see what an error is, or send the log to a developer who can be clued into the source of a bug.
If you log too much, that information can be lost in a sea of irrelevant text. If a player is using a modpack and the game crashes, they might open up the log and see a bunch of logs from your mod, and think it’s the cause of the bug even if it isn’t.
So when someone opened this ticket in my GitHub project, I took it very seriously. My project should be logging errors and errors only, so I need to make sure it is doing that properly.
Of course, if it is working properly, then that actually means there are bugs in your mod that you have been ignoring. And as it turns out, this was the case with the logspam Bok’s Banging Butterflies was producing.
Stale Butterfly Data
The blogspam that al-wei highlighted in the ticket was mainly to do with invalid butterfly data being received, and there were a lot of errors like this. So this was the first thing I decided to tackle:
[23:00:12] [Netty Local Client IO #0/ERROR]: Received invalid butterfly data. java.util.zip.DataFormatException: Butterfly Data Entry for entity [bluemoon] already exists.
Basically, the game attempts to sync Butterfly Data between client and server to ensure parity. The problem was, that data has already been loaded on all machines, so the network code was complaining that it already existed.
This was actually a bug. The Butterfly Data from the server is supposed to override the client data, but it never did. Another problem was caused by leaving a world, and loading into a new world. The Butterfly Data would remain in memory, causing the next load to log these errors again. If you were editing the data and reloading it, then the new data wouldn’t override the old.
The fix was actually pretty simple. I added a reset() method to the Butterfly Data, and made sure to call it before loading any new Butterfly Data:
/**
* Resets the butterfly data to its unloaded state.
*/
public static void reset() {
ButterflyData.BUTTERFLY_ENTRIES.clear();
ButterflyData.ENTITY_ID_TO_INDEX_MAP.clear();
ButterflyData.NUM_BUTTERFLIES = 0;
ButterflyData.NUM_MOTHS = 0;
}
I ran it through a few test loads and the logs disappeared completely. This got rid of around 99% of the logspam, but I wasn’t done yet. I decided to check what other logs remained to see if I could get rid of them as well.
Allium Stage 7
One small line I found was this:
[22:50:02] [Worker-Main-14/WARN]: Exception loading blockstate definition: 'butterflies:blockstates/bud_allium.json' missing model for variant: 'butterflies:bud_allium#age=7'
This isn’t really an issue since flower buds don’t actually use age=7, instead turning into normal flowers at this age. However, I wanted to see if I could get rid of this line anyway. It wasn’t happening for any of the other flower buds, so it seemed like it would be easy to fix.
Opening up the Blockstate, the problem was immediately obvious:
"age=6": {
"model": "butterflies:block/flower_buds/allium_stage6"
},
"age=6": {
"model": "butterflies:block/flower_buds/allium_stage6"
}
A simple typo giving it two states for age=6. Changing the second one to age=7 fixed the bug, and got rid of one extra line of logspam.
Advancements Fixed
The other logs I noticed were to do with advancements. None of the mod’s advancements were loading. I had to search a little bit, but it turned out the problem was with the root advancement:
[22:54:23] [Render thread/ERROR]: Parsing error loading custom advancement butterflies:butterfly/root: Expected item to be an item, was unknown string 'butterflies:monarch'
This was the item used as the icon for the root advancement. I had used the Butterfly Spawn Egg for the Monarch Butterfly, which was fine, but when I re-implemented the Spawn Eggs, I had given them new Item IDs. This broke the root advancement, which in turn broke all of the advancements.
This was a pretty serious bug, one that I hadn’t noticed because I hadn’t been paying attention to the logs. If al-wei hadn’t opened their ticket, I may never have noticed.
Thankfully, now that I knew of the bug, fixing was as simple as updating the base item to use:
"icon": {
"id": "butterflies:spawn_egg_butterfly_monarch"
},
So there have been a couple of releases where advancements were disabled, but it will be working in future versions again.
Lessons Learned
The lesson here is that you should pay attention to your logs. If you are seeing errors in the logs, you should investigate them because there may actually be some serious bugs in your project. And if the log isn’t needed, you should remove it so that it helps others find the actual causes of problems they may have.
I had let a couple of things slide that I really shouldn’t have, so I’ll be paying more attention to the logs when I test future versions.
