Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update logging code. #7314

Merged
merged 9 commits into from
Apr 21, 2024
Merged

Update logging code. #7314

merged 9 commits into from
Apr 21, 2024

Conversation

Articdive
Copy link
Member

Description:

Update the Logging to Log4J 2.19.0 (which is included in the spigot jar) and does not use deprecated methods anymore.
Switches the TownyLogger to a util-class and not a singleton.
Attaches the debug logger to the standard towny logger and logs all debug messages to debug.log
Standard towny logger's info messages now go to towny.log, including those from Towny.getPlugin().getLogger().


New Nodes/Commands/ConfigOptions:

None


Relevant Towny Issue ticket:

At least on my machine this fixed #5855.


  • I have tested this pull request for defects on a server.

By making this pull request, I represent that I have the right to waive copyright and related rights to my contribution, and agree that all copyright and related rights in my contributions are waived, and I acknowledge that the TownyAdvanced organization has the copyright to use and modify my contribution under the Towny License for perpetuity.

@LlmDl
Copy link
Member

LlmDl commented Mar 19, 2024

This looks pretty good so far, I have a couple of small complaints though:

Currently the debug.log has a very long-winded prefix to it, and I'm not certain how useful it would ever be:

2024-03-19 10:03:31,928 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Status: TOWN_RESIDENT
2024-03-19 10:03:31,964 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Destroy: true
2024-03-19 10:03:31,985 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Cache created for LlmDl using minecraft:sculk:destroy:TOWN_RESIDENT = true
2024-03-19 10:03:32,364 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:32,665 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:32,965 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Status: TOWN_RESIDENT
2024-03-19 10:03:32,966 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Destroy: true
2024-03-19 10:03:32,974 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Cache created for LlmDl using minecraft:dirt:destroy:TOWN_RESIDENT = true
2024-03-19 10:03:33,365 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:33,714 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,114 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,415 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,765 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:35,115 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:43,033 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Day
2024-03-19 10:03:43,036 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendGlobalMessage:879]: [Global Message] A new day is here! Taxes and rent have been collected
2024-03-19 10:03:43,037 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Town Taxes
2024-03-19 10:03:43,049 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Nation Taxes
2024-03-19 10:03:43,050 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Town Costs
2024-03-19 10:03:43,051 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Nation Costs
2024-03-19 10:03:43,054 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Cleaning up old backups...
2024-03-19 10:03:43,054 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN4: Because of non-peaceful status, LTOWN4 has received a war token.
2024-03-19 10:03:43,070 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN5: Because of non-peaceful status, LTOWN5 has received a war token.
2024-03-19 10:03:43,072 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN: Because of non-peaceful status, LTOWN has received a war token.
2024-03-19 10:03:43,089 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN8: Because of non-peaceful status, LTOWN8 has received a war token.
2024-03-19 10:03:43,097 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Successfully cleaned backups.
2024-03-19 10:03:43,105 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Making backup...
2024-03-19 10:03:43,119 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] ltown9: Because of non-peaceful status, ltown9 has received a war token.
2024-03-19 10:03:43,133 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN6: Because of non-peaceful status, LTOWN6 has received a war token.
2024-03-19 10:03:43,137 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Finished New Day Code
2024-03-19 10:03:43,139 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Universe Stats:
2024-03-19 10:03:43,154 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Residents: 20
2024-03-19 10:03:43,168 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Towns: 6
2024-03-19 10:03:43,170 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Nations: 2
2024-03-19 10:03:43,171 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world (townblocks): 31
2024-03-19 10:03:43,185 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world_the_end (townblocks): 0
2024-03-19 10:03:43,187 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world_nether (townblocks): 0
2024-03-19 10:03:43,199 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Memory (Java Heap):
2024-03-19 10:03:43,201 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     4096 Mb (max)
2024-03-19 10:03:43,202 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      920 Mb (total)
2024-03-19 10:03:43,203 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      355 Mb (free)
2024-03-19 10:03:43,218 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      564 Mb (used=total-free)
2024-03-19 10:03:43,221 [Folia Async Scheduler Thread #10] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Towny DailyTimerTask took 188ms to process.
2024-03-19 10:03:44,195 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Towny flatfiles and settings successfully backed up.

Can it be reduced to not carry the class and line number its called from?

The second thing I've spotted is in relation to the backups made at the startup and the logs which are backed up.

Currently when Towny loads we make a backup zip/tar that includes the log files. We also make a backup at the end of each towny-new-day.

The loggers are starting up and appear to be wiping any existing log file, so that when the backup is made on startup, its backing up an empty log, or in the case of the towny.log the towny startup sequence. All of the logging in between the last towny-new-day and new startup is lost.

Also it is probably best we set our pom.xml to use the latest and greatest log4j version instead of showing an older version.

@Articdive
Copy link
Member Author

This looks pretty good so far, I have a couple of small complaints though:

Currently the debug.log has a very long-winded prefix to it, and I'm not certain how useful it would ever be:

2024-03-19 10:03:31,928 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Status: TOWN_RESIDENT
2024-03-19 10:03:31,964 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Destroy: true
2024-03-19 10:03:31,985 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Cache created for LlmDl using minecraft:sculk:destroy:TOWN_RESIDENT = true
2024-03-19 10:03:32,364 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:32,665 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:32,965 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Status: TOWN_RESIDENT
2024-03-19 10:03:32,966 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: LlmDl (world,-1, -1) Cached Destroy: true
2024-03-19 10:03:32,974 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Cache created for LlmDl using minecraft:dirt:destroy:TOWN_RESIDENT = true
2024-03-19 10:03:33,365 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:33,714 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,114 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,415 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:34,765 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:35,115 [Server thread] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Cache permissions for LlmDl using minecraft:sculk:destroy = true
2024-03-19 10:03:43,033 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: New Day
2024-03-19 10:03:43,036 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendGlobalMessage:879]: [Global Message] A new day is here! Taxes and rent have been collected
2024-03-19 10:03:43,037 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Town Taxes
2024-03-19 10:03:43,049 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Nation Taxes
2024-03-19 10:03:43,050 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Town Costs
2024-03-19 10:03:43,051 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Collecting Nation Costs
2024-03-19 10:03:43,054 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Cleaning up old backups...
2024-03-19 10:03:43,054 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN4: Because of non-peaceful status, LTOWN4 has received a war token.
2024-03-19 10:03:43,070 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN5: Because of non-peaceful status, LTOWN5 has received a war token.
2024-03-19 10:03:43,072 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN: Because of non-peaceful status, LTOWN has received a war token.
2024-03-19 10:03:43,089 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN8: Because of non-peaceful status, LTOWN8 has received a war token.
2024-03-19 10:03:43,097 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Successfully cleaned backups.
2024-03-19 10:03:43,105 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Making backup...
2024-03-19 10:03:43,119 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] ltown9: Because of non-peaceful status, ltown9 has received a war token.
2024-03-19 10:03:43,133 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendPrefixedTownMessage:904]: [Town Msg] LTOWN6: Because of non-peaceful status, LTOWN6 has received a war token.
2024-03-19 10:03:43,137 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Finished New Day Code
2024-03-19 10:03:43,139 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Universe Stats:
2024-03-19 10:03:43,154 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Residents: 20
2024-03-19 10:03:43,168 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Towns: 6
2024-03-19 10:03:43,170 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     Nations: 2
2024-03-19 10:03:43,171 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world (townblocks): 31
2024-03-19 10:03:43,185 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world_the_end (townblocks): 0
2024-03-19 10:03:43,187 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     world_nether (townblocks): 0
2024-03-19 10:03:43,199 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug: Memory (Java Heap):
2024-03-19 10:03:43,201 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:     4096 Mb (max)
2024-03-19 10:03:43,202 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      920 Mb (total)
2024-03-19 10:03:43,203 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      355 Mb (free)
2024-03-19 10:03:43,218 [Folia Async Scheduler Thread #10] [com.palmergames.bukkit.towny.TownyMessaging#sendDebugMsg:182]: [Towny] Debug:      564 Mb (used=total-free)
2024-03-19 10:03:43,221 [Folia Async Scheduler Thread #10] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Towny DailyTimerTask took 188ms to process.
2024-03-19 10:03:44,195 [ForkJoinPool.commonPool-worker-3] [org.bukkit.craftbukkit.v1_20_R2.util.ForwardLogHandler#publish:36]: Towny flatfiles and settings successfully backed up.

Can it be reduced to not carry the class and line number its called from?

The second thing I've spotted is in relation to the backups made at the startup and the logs which are backed up.

Currently when Towny loads we make a backup zip/tar that includes the log files. We also make a backup at the end of each towny-new-day.

The loggers are starting up and appear to be wiping any existing log file, so that when the backup is made on startup, its backing up an empty log, or in the case of the towny.log the towny startup sequence. All of the logging in between the last towny-new-day and new startup is lost.

Also it is probably best we set our pom.xml to use the latest and greatest log4j version instead of showing an older version.

In the latest commit I have removed the Class, Method and Line number.

The loggers only wipe any existing log file as according to the Config setting: PLUGIN_RESET_LOG_ON_BOOT.
This is also true for the debugger, but this can overriden if you would like it so.

And the log4j version is older on purpose as it is matched to the log4j2 version included in Minecraft 1.16.5 (our oldest supported version).

@LlmDl LlmDl added this to the 0.100.3.0 milestone Mar 29, 2024
@LlmDl
Copy link
Member

LlmDl commented Apr 12, 2024

This PR needs a rebase.

# Conflicts:
#	Towny/src/main/java/com/palmergames/bukkit/towny/db/TownyFlatFileSource.java
@Articdive
Copy link
Member Author

This PR needs a rebase.

Done.

@LlmDl LlmDl merged commit 8c6673d into master Apr 21, 2024
6 checks passed
@LlmDl LlmDl deleted the update-logging branch April 21, 2024 17:07
LlmDl added a commit that referenced this pull request Apr 21, 2024
    - Drops the usage of deprecated methods and begins using the
towny.log file again.
    - Closes #5855.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Suggestion: Use towny.log again for logging Towny actions
2 participants