Pages: Debugging

Debugging

SporeAPI has two tools for this: the main-thread IO guard, which catches the calls that cause lag, and incidents, which turn errors into something you can actually read.

Main-thread IO

The usual reason a server starts lagging is something blocking the main thread - a database read, a file write - somewhere you forgot about. SporeDebug watches for that. Every blocking repository call goes through it, and you can wrap your own with blockingIo:

fun loadSettings(): Settings = blockingIo("settings.load") {
    // reads a file, queries an API, whatever
}

The guard is off by default (IGNORE). It's meant for server admins tracking down lag: they turn it on with /mycommand debug io (see Commands) without a restart, and turn it off again once they're done.

While it's on, a wrapped call that runs on the server thread logs a warning with a stack trace pointing at the caller. Repeats of the same operation are collapsed so one bad call in a loop can't spam your console.

SporeDebug.mainThreadIoPolicy = MainThreadIoPolicy.THROW   // IGNORE (default), WARN, THROW

Setting it in code is for development - THROW fails loudly the first time instead of leaving you to notice the lag later. Startup and shutdown are exempt by default, since blocking there is usually deliberate; set SporeDebug.reportDuringLifecycle = true if you want those too.

Incidents

Every error SporeAPI catches - a listener that throws, a failed database call, a coroutine that crashes - becomes an incident. Instead of a wall of stack trace, you get this:

[MyPlugin] (error) kit.give failed [ref sLOi8] - seen 3x
[MyPlugin] (error)   What:    NumberFormatException: For input string: "abc"
[MyPlugin] (error)   Why:     Some text couldn't be read as a number.
[MyPlugin] (error)   Hint:    Check config values and command arguments that are supposed to be numbers.
[MyPlugin] (error)   Where:   KitService.kt:42 (KitService.give)
[MyPlugin] (error)   Inside:  listener.KitListener.onJoin
[MyPlugin] (error)   Details: player=Steve
[MyPlugin] (error)   Thread:  Server thread (main thread), while running
[MyPlugin] (error)   More:    /mycommand debug error sLOi8
  • Where is the first line of your code in the trace - not Bukkit's, not SporeAPI's.
  • Why and Hint come from a built-in list of common errors, which you can add to.
  • The same error from the same line is grouped: it's logged at most once every 30 seconds, and it keeps the same ref, so the ref a player gave you still works later.

Warnings print just the summary. Errors add a short trace underneath - IncidentReporter.consoleTraceDepth sets how many lines, 0 turns it off.

runDebug

Wrap anything that might fail in runDebug. It returns the result, or null if the block threw (after reporting it), so a fallback is just ?::

val kits = runDebug("kits.load") { loadKits() } ?: emptyList()

Add details and they show up in the report, and use onFailure to tell the player something went wrong:

runDebug(
    "kit.give",
    details = mapOf("player" to player.name, "kit" to kit.id),
    onFailure = { player.error("Couldn't give you that kit (ref ${it.id})") }
) {
    kit.giveTo(player)
}

The default severity is ERROR. Pass Severity.WARNING when there's a fallback and it isn't a big deal, or Severity.CRITICAL when the plugin can't work without it. Name operations like area.action - kits.load, profiles.save - so they read the same as the IO guard's.

Inside coroutines, use runDebugSuspending. Real cancellation still goes through untouched, but a withTimeout that runs out inside the block counts as a failure:

val profile = runDebugSuspending("profiles.load") { profiles.find(uuid) }

runDebug isn't inline on purpose: its block can't suspend, which is what keeps the breadcrumbs below on the right thread.

If you already have a catch, report it directly:

} catch (e: Exception) {
    IncidentReporter.report("shop.purchase", e, Severity.ERROR, mapOf("item" to item.id))
}

Incidents remember what they happened inside of. Listeners, event handlers and runDebug blocks all add themselves, so a failure in kit.give called from a join listener shows Inside: listener.KitListener.onJoin. You can add your own layer without catching anything:

DebugContext.inside("arena.start") {
    // anything reported in here shows "Inside: arena.start"
}

Already covered

You don't need to wrap these - they go through the reporter already:

  • @EventHandler methods registered through SporeListeners (normal and suspend), plus on<T> { } and onAsync<T> { } handlers
  • Coroutines started with SporeCoroutines.launch / launchAsync that throw
  • Every MongoRepository and YamlRepository call
  • Modules, commands, listeners and registry entries that fail to register or enable
  • Async sidebar fetches, webhook sends and SporeSerializer decoding, as warnings

Explanations

The built-in list covers the usual suspects: null pointers, bad numbers, async Bukkit calls, main-thread IO, missing classes, file and network errors, MongoDB timeouts and logins, broken YAML and more. Add your own for your plugin's exceptions:

IncidentExplainers.register<KitNotFoundException> {
    Explanation("That kit doesn't exist.", "Check the kit id in kits.yml.")
}

Yours win over the built-in ones, and returning null passes it on - handy for matching on the message. For a library that might not be installed, register by class name so nothing gets loaded:

IncidentExplainers.register(
    "com.zaxxer.hikari.pool.HikariPool\$PoolInitializationException",
    "Couldn't connect to the SQL database.",
    "Check the host, port and password in config.yml."
)

Commands

Register the debug command:

SporeDebugCommand.register(cloudCommandManager, "mycommand", "myplugin.admin")
CommandWhat it does
/mycommand debugOverview - scheduler load, coroutines, sidebars, tab lists, Mongo, registries, the IO guard, the slowest timings and an incident count
/mycommand debug timingsEvery Timings.timed operation, slowest average first
/mycommand debug timings clearForgets every timing
/mycommand debug errorsThe last 10 incidents, newest first. Click one for details
/mycommand debug error <ref>Everything about one incident: what, why, where, breadcrumbs, how often, and a short trace
/mycommand debug error <ref> tracePrints the full stack trace to the console
/mycommand debug errors clearForgets every incident
/mycommand debug ioToggles the IO guard without a restart

Refs tab-complete, and a lowercase ref still works as long as only one incident matches.

To alert staff in chat when something breaks, pass notifyStaff = true - everyone online with the permission gets a clickable message for every new error:

SporeDebugCommand.register(cloudCommandManager, "mycommand", "myplugin.admin", notifyStaff = true)

On Velocity it's the same command, registered with SporeDebugCommand.register(commandManager, "mycommand", "myplugin.admin") from SporeVelocityPlugin.

Hooking in

IncidentReporter.onIncident { } runs for every incident that gets logged, which is how you'd send them to Discord, a database, or anywhere else:

IncidentReporter.onIncident { incident ->
    if (incident.severity != Severity.WARNING) {
        Webhook(webhookUrl).setMessage("${incident.operation} failed (ref ${incident.id})").sendAsync()
    }
}

It runs on whichever thread reported the error, so keep anything slow off it.