Logging and Debug Modules

What this page covers: the logger every plugin gets for free, the {} message format and its exact contract, the debug switches an admin flips in config.yml, and the file logger for an audit trail of your own.

One rule sits above all of them: a log call reports a problem, it must not become one. Nothing on this page throws - not a missing argument, not a hostile toString(), not a file that cannot be opened, not a call made before the server finished booting.

Getting a logger

ECLogger is per plugin. You never construct one in normal code: the plugin's ECPluginData builds it once and hands the same instance to everybody.

// inside anything implementing IECPluginBootstrap (ECBukkitPlugin / ECHytalePlugin)
getLog().info("Loaded {} arenas", arenas.size());

// from an ECPluginData you already hold
ecPluginData.getLog().warning("No arena named {}", name);

// the core's own logger - works from a static initializer, and never returns null
EverNifeCore.getLog().info("...");

Call	What it answers
`IECPluginBootstrap.getLog()`	shorthand for `getPluginData().getLog()`
`ECPluginData.getLog()`	this plugin's logger, created with the plugin data
`EverNifeCore.getLog()`	EverNifeCore's own logger - falls back to `ECFallbackLog` while no plugin data is plugged in
`new ECLogger(ecPluginData)`	a second logger for the same plugin; there is no reason to want one

ECLogger.getEcPluginData() gives the plugin back, and answers null on the fallback logger, which speaks for no plugin.

The `LOG` constant

A plugin that logs from static helpers usually wants one short name. Resolve it in onInstantiate(), which runs from the base class's instance initializer - before onEnable(), so nothing can read the field before it is set:

public class MyPlugin extends ECBukkitPlugin {

    public static MyPlugin instance;
    public static ECLogger LOG;

    @Override
    public void onInstantiate() {
        instance = this;
        LOG = getLog();
    }

    // ... onECPluginEnable() / onECPluginShutdown() / onECPluginReload()
}

// anywhere, including a static context
MyPlugin.LOG.severe("Could not read {}", file.getName(), failure);

EverNifeCore itself does not use this shape - the core logs through EverNifeCore.getLog(), which is its own equivalent. This is a pattern for downstream plugins, not a core API.

The four verbs

log.info   ("Loaded {} arenas for {}", count, world);
log.warning("Could not parse {}", file.getName(), failure);   // message + stack trace
log.severe ("Storage is unreachable");
log.debug  ("Player {} entered region {}", player, region);   // only while DebugMode is on

All four take (String message, Object... params). debug is the only one gated: it asks the plugin's DebugMode switch first and stays silent when it is off. That is also why only debug has a supplier form - on any other verb the get() would always run:

log.debug(() -> "Full region dump: " + region.describeEverything());

A logger with no plugin behind it - EverNifeCore.getLog() before the core loaded - has no DebugMode block to ask, so the debug line goes out and the sink's own level decides.

`ECLogLevel`, the secondary outlet

Below the four verbs there is one more method, for a caller holding the level in a variable instead of naming it:

ECLogLevel level = failure == null ? ECLogLevel.INFO : ECLogLevel.SEVERE;
log.log(level, "Import finished: {}", report);

ECLogLevel has four values - DEBUG, INFO, WARNING, SEVERE - and it is what the whole stack speaks: every verb funnels into log(...), and log(...) is the only thing an ILogAdapter ever receives. That is the point of the enum: common imports no logging framework, and each platform's adapter maps the four values onto whatever the server actually logs with.

⚠️ log(ECLogLevel.DEBUG, ...) is the raw channel and is not gated by DebugMode. The verb debug(...) is the one that asks. Reach for log(...) when the level is a variable, never as a shortcut for debug.

The `{}` message format

Messages carry {} placeholders, filled left to right. There is no printf: a % in a message is ordinary text.

log.info("Loaded {} arenas for {}", 12, "world");   // -> Loaded 12 arenas for world
log.info("Progress: 100% done");                    // -> Progress: 100% done

Every shape below is pinned by a test, including the ugly ones - because the ugly ones are what used to end a log call with an exception:

Written like this	Comes out as
`"a {} c"`, `"b"`	`a b c`
`"a {} {}"`, `"b"`	`a b {}` - a placeholder with no argument left stays literal
`"a {}"`, `"b"`, `"c"`	`a b [c]` - surplus arguments are appended
`"a"`, `"b"`	`a [b]`
`"a \\{} b"`, `"x"`	`a {} b [x]` - the escape makes it literal and consumes nothing
`"a \\\\{} b"`, `"x"`	`a \x b` - an escaped backslash leaves the placeholder real
`"{}"`, `new int[]{1, 2}`	`[1, 2]` - arrays render their contents, nested included
`"value: {}"`, object whose `toString()` throws	`value: <toString failed: com.foo.Bar>`
`"fail: {}"`, an `IOException`	`fail: java.io.IOException: boom` - consumed, so no stack trace
`"fail"`, an `IOException`	`fail`, then the stack trace on the next line
`null`	`null`
`"a {} c"`, `(Object) null`	`a null c`

The backslash rows are Java source: "a \\{} b" is the message a \{} b, and "a \\\\{} b" is a \\{} b. The message is read by these rules whether or not any argument follows it - an escape means the same thing either way.

The trailing throwable

A Throwable in the last position that no placeholder consumed is the failure the line is about, so its stack trace is appended - at any level.

try {
    config.load();
} catch (IOException failure) {
    log.warning("Could not read {}", file.getName(), failure);
}

There is no severe(String, Throwable) overload anywhere, and none is needed: the rule is the formatter's, so it works on info, warning, severe, debug and log alike. Consume the throwable with a {} and you get its toString() and no stack - which is the way to log a failure as a value.

Text you did not write goes in a parameter

The message is a format string. Anything the call site did not write itself - a player name, a path, a command line, a value out of a config, whatever somebody typed - goes in a parameter, never concatenated into the message.

// NO: the sender's text becomes part of the format string
log.severe("Failed to execute the FinalCMD: " + commandInfo, cause);

// YES: the message is fixed, the external text is a value
log.severe("Failed to execute the FinalCMD: {}", commandInfo, cause);

Concatenate, and the external text is the message, read by the same rules as the rest of it: a {} that happens to be inside it is a placeholder like any other and consumes an argument. When the argument it reaches is the trailing Throwable, the throwable is no longer trailing, the rule above stops firing, and the stack trace never reaches the line. Nothing looks wrong afterwards - the exception's toString() is right there in the text. Only the part that says where it failed is missing, on the one line that existed to explain it.

Passing the same text as a parameter is what closes it: a parameter is rendered into the output, not re-read, so a {} inside it is just two characters and consumes nothing. Placeholders are counted in the message alone.

None of this needs a hostile caller. /mycommand {} is a legal thing for a player to type, and a config value or a file name can carry braces just as easily. The louder version of the same bug is a pasted {} shifting every later placeholder onto the wrong argument - same cause, and the one you actually notice.

Debug modules

A plugin with more than one noisy subsystem does not want one switch. IDebugModule is one switch in the plugin's DebugMode.DebugModules block and the door everything behind that switch logs through. Implement it with an enum, one constant per switch:

public enum MyDebug implements IDebugModule {

    ARENA("Logs arena state machine transitions.", true),
    LOOT ("Logs every loot roll and its seed.",    false),
    ;

    private final String comment;
    private final boolean enabledByDefault;
    private boolean enabled;

    MyDebug(String comment, boolean enabledByDefault) {
        this.comment = comment;
        this.enabledByDefault = enabledByDefault;
        this.enabled = enabledByDefault;
    }

    @Override public ECPluginData getPluginData()     { return MyPlugin.instance.getPluginData(); }
    @Override public String getComment()              { return comment; }
    @Override public boolean isEnabledByDefault()     { return enabledByDefault; }
    @Override public boolean isEnabled()              { return enabled; }
    @Override public void setEnabled(boolean enabled) { this.enabled = enabled; }
}

Only getPluginData(), isEnabled() and setEnabled(boolean) are abstract - everything else has a default. getName() answers the enum constant's own name, which is the config key.

Declare the set once, and do it in onInstantiate() so the block is complete before the enable reads it:

getPluginData().defineDebugModules(MyDebug.values());

Declaring modules touches no file. Declaring them after the block was already read re-seeds it on the spot, so a late declaration still reaches the config - it just costs a second read.

Logging through a module

MyDebug.ARENA.debug("Arena {} moved to {}", arena.getId(), newState);
MyDebug.ARENA.debug(() -> "Full arena dump: " + arena.describeEverything());
MyDebug.ARENA.warning("Arena {} has no spawn point", arena.getId());

Verb	Gated?	Line looks like
`debug(String, Object...)` / `debug(Supplier<String>)`	yes - plugin switch and module switch	`[Debug (ARENA)] Arena 3 moved to RUNNING`
`info` / `warning` / `severe`	no	`[ARENA] Arena 3 has no spawn point`

debug is the only verb the switch gates. The other three are tagging: they name the module in the line and always log, because a warning does not become less true when the operator is not debugging.

A module logs through its plugin's logger - or, while that plugin has no runtime yet, through the core's.

The core's own modules

EverNifeCore declares its own switches as ECDebugModule, and they are the reference implementation:

Module	Turns on
`ARG_PARSER`	the command system's `@Arg` context checks
`CONTEXTUAL_ARG_PARSER`	the command system's `@Arg.Contextual` context checks
`SV_WORLD_DATA`	what every `SVWorldDataManager` block store preloads and flushes
`COMMAND_REGISTRY`	every command path removed, and every alias overridden, by a `commands/<PluginName>.yml` file
`HYTALE_FPLAYER`	the `HytaleFPlayer` implementation - Hytale only

Platform gating

A module can declare the platforms it exists on. ECDebugModule does it with a String... of PlatformId constants compared against IPlatform.getPlatformProviderId(); your own enum overrides isAvailable(IPlatform) however it likes.

A module the running platform does not have is not merely ignored:

it is never seeded into that server's config.yml;
a key that got there anyway - a file copied from another platform, or written by an older build - is removed from the file, on its own, the next time the block is read;
it is forced off in memory, so it cannot log even if the file says the switch is on.

The `DebugMode` block

Every plugin's config.yml grows one block, seeded with whatever it lacks:

# -----------------------
#      Debug System
# -----------------------
DebugMode:
  # If 'MyPlugin' should log debug messages on the console!
  enabled: false
  # List of DebugModules that are enabled!
  # These debug modules bellow will only work when 'DebugMode.enabled' is 'true'
  DebugModules:
    # Logs arena state machine transitions.
    ARENA: true
    # Logs every loot roll and its seed.
    LOOT: false

The master switch and the per-module switch are and-ed, so an operator turns debug off in one place and tunes it in another.

flowchart TD
    A["module.debug(...)"] --> B{"is the module<br/>available on this platform?"}
    B -- "no" --> X["nothing is logged"]
    B -- "yes" --> C{"DebugMode.enabled?"}
    C -- "no" --> X
    C -- "yes" --> D{"DebugModules.NAME?"}
    D -- "no" --> X
    D -- "yes" --> E["the line goes out, tagged with the module name"]

When the file is read

loadDebugConfig() reads the block into memory. It is called for you from two places:

by runECPluginEnable(), before the first hook, so the whole enable already logs under the switches the file asks for;
by the plugin reload, up front, so the debug lines the reload itself emits obey the edited file.

It always re-reads - both callers want the file's current word - and it writes the file back only when it completed it with defaults or took an orphan key out. After it has run, isDebugEnabled() answers from memory and touches no disk, so an edit made while the server is up is invisible until a reload. A query that somehow arrives before the enable triggers exactly one read, however many threads race it.

setDebugEnabled(boolean) forces the switch and marks the block as loaded, so no file is read afterwards. It is a hook for tests and tooling; a later loadDebugConfig() still overrides it with the file's word.

`FCFileLogger` - an audit log of its own file

For the lines that belong in a file rather than in the console: UTF-8, appended, flushed per line, and formatted by the same {} rules.

FCFileLogger trades = FCFileLogger.of(getPluginData(), "trades.log")
        .withTimestamps()
        .rollOnOpen()
        .build();

trades.log("{} bought {} for {}", player, item, price);

Three ports open a builder; nothing touches the disk until build():

Port	Where the file lands	Who closes it
`of(File logFile)`	exactly that file	you
`of(File rootFolder, String name)`	`name` inside `rootFolder`	you
`of(ECPluginData owner, String name)`	`<dataFolder>/logs/<name>`	the plugin's shutdown, after the last teardown hook

The two ownerless ports are AutoCloseable, so try-with-resources works. The owned port is tracked by the plugin, and runECPluginShutdown() closes whatever is left open after the last shutdown hook - so a plugin still writes its closing lines during its own teardown, and a handle it closed itself is no problem for the sweep.

Builder options:

Call	Effect
`withTimestamps()`	prefixes every line with `[yyyy-MM-dd HH:mm:ss]`
`withTimestamps(String pattern)`	the same, with your `SimpleDateFormat` pattern used whole - it carries its own brackets and trailing space, because it is the prefix
`rollOnOpen()`	archives the file already at the target before opening, the way a server treats `latest.log`. The archived name is `{date}-{n}.<ext>`, `{date}` being `yyyy-MM-dd-HH-mm` and `{n}` counting from 1
`rollOnOpen(String pattern)`	the same over your own name, with the tokens `{date}` and `{n}`. A pattern with no `{n}` still gets a counter the moment it would overwrite - `previous.log` becomes `previous-2.log`. The roll never overwrites
`build()`	opens the file, and on the owned port hands the handle over to be closed

On the instance: log(String, Object...), close(), isOpen() and getFile() - the file it is actually writing to, which is the one the port resolved.

It never stops the caller. A file that cannot be opened or written reports once at severe on the owner's console log and then degrades to a no-op; close() may be called as often as you like; a write after the close says nothing at all.

⚠️ There is no periodic rotation and no retention policy. The roll happens on open, once. Size caps, age caps and deleting old archives are the operator's business.

Before the core is up

EverNifeCore.getLog() never returns null and never throws. While no plugin data is plugged in - a static initializer that beat the bootstrap, a plugin that reached EverNifeCore before it loaded, a bare JUnit run - it answers with ECFallbackLog, which needs no platform and no config.

Its lines go to the JUL logger named EverNifeCore (the constant ECFallbackLog.LOGGER_NAME), which is where an operator points a logging.properties handler. There debug maps to Level.FINE: there is no plugin to own a DebugMode block, so JUL's own threshold is what keeps it quiet.

On a real server the mapping is the platform adapter's: both the Bukkit and the Hytale adapter map DEBUG onto INFO, because those consoles filter everything below it and dropping the line would silently defeat the switch the operator just turned on.

Logging and Debug Modules

Logging and Debug Modules

Getting a logger

The LOG constant

The four verbs

ECLogLevel, the secondary outlet

The {} message format

The trailing throwable

Text you did not write goes in a parameter

Debug modules

Logging through a module

The core's own modules

Platform gating

The DebugMode block

When the file is read

FCFileLogger - an audit log of its own file

Before the core is up

See also

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

EverNifeCore

Clone this wiki locally

The `LOG` constant

`ECLogLevel`, the secondary outlet

The `{}` message format

The `DebugMode` block

`FCFileLogger` - an audit log of its own file