Logout reactivates held wand after Mage cleanup, leaving a stale Mage and breaking player state after rejoin.

[JToTl]

Hi. Thanks for maintaining this great plugin. Magic lets us create many interesting items on our server. However, I found a complex logout-related Mage lifecycle bug.

English is not my first language, so I apologize if any part of this report comes across as unclear or impolite.

Summary:

• When a player logs out while holding a wand whose cast_spell starts a spell with an infinite Interval containing a caster-targeting action, the wand is reactivated after the Mage cleanup process has begun, causing the spell to be cast again.
• The newly created pending batch remains associated with the stale Mage instance and continues running after logout. This causes an offline Mage instance to be loaded and can break the player’s state after rejoining, including swap-action casting.

Environment:

• Magic 11.2.4-0de17b2
• Paper 1.21.8-60-main@29c8822

Minimal reproduction configuration:

wands:
The wand must use cast_spell to automatically cast test_interval_spell when the wand is activated.

test_interval_wand:
  cast_interval: 99999999
  cast_spell: test_interval_spell

# This wand is used to verify that swap casting stops working.
test_swap_cast_wand:
  swap: alt_cast
  alternate_spell: test_swap_spell

spells:
The spell cast by cast_spell must contain an Interval action with duration: infinite. The interval must execute an action that targets the caster.

test_interval_spell:
  actions:
    cast:
    - class: Interval
      duration: infinite
      interval: 500
      actions:
      - class: Message
        message_target: true
        message: "This message targets the caster."
  parameters:
    target: self

# This spell is used to verify that swap casting stops working.
test_swap_spell:
  actions:
    cast:
    - class: Message
      message: "You cast this spell!"
  parameters:
    target: self

Steps to reproduce:

• Obtain test_interval_wand and hold it in the main hand. Confirm that its cast_spell has started test_interval_spell.
• Log out of the server while still holding test_interval_wand.
• When the interval executes again after logout, the following warning and stack trace appear:

[22:28:11 WARN]: [Magic]  Player data for 130eca88-a007-3e3f-bfd5-07605c92dfa0 (JToTl) loaded while offline!
[22:28:11 WARN]: java.lang.Exception: Stack trace
[22:28:11 WARN]: 	at java.base/java.lang.Thread.dumpStack(Thread.java:2148)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMage(MagicController.java:853)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMage(MagicController.java:797)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMageFromEntity(MagicController.java:763)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMage(MagicController.java:804)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMage(MagicController.java:820)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.getMage(MagicController.java:298)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.builtin.MessageAction.sendMessage(MessageAction.java:110)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.builtin.MessageAction.perform(MessageAction.java:85)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.ActionContext.perform(ActionContext.java:43)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.ActionHandler.perform(ActionHandler.java:221)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.CompoundAction.perform(CompoundAction.java:109)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.builtin.IntervalAction.perform(IntervalAction.java:52)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.ActionContext.perform(ActionContext.java:43)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.action.ActionHandler.perform(ActionHandler.java:221)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.batch.ActionBatch.process(ActionBatch.java:38)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.Mage.processPendingBatches(Mage.java:2034)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.magic.MagicController.processPendingBatches(MagicController.java:1623)
[22:28:11 WARN]: 	at Magic-11.2.4.jar//com.elmakers.mine.bukkit.tasks.BatchUpdateTask.run(BatchUpdateTask.java:14)
[22:28:11 WARN]: 	at org.bukkit.craftbukkit.scheduler.CraftTask.run(CraftTask.java:78)
[22:28:11 WARN]: 	at org.bukkit.craftbukkit.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:474)
[22:28:11 WARN]: 	at net.minecraft.server.MinecraftServer.tickChildren(MinecraftServer.java:1663)
[22:28:11 WARN]: 	at net.minecraft.server.MinecraftServer.tickServer(MinecraftServer.java:1531)
[22:28:11 WARN]: 	at net.minecraft.server.MinecraftServer.runServer(MinecraftServer.java:1253)
[22:28:11 WARN]: 	at net.minecraft.server.MinecraftServer.lambda$spin$2(MinecraftServer.java:310)
[22:28:11 WARN]: 	at java.base/java.lang.Thread.run(Thread.java:1575)

• Rejoin the server.
• Hold any wand configured to cast using the swap action and attempt to trigger it.
• No visible cast result occurs.

Root cause:

The root cause is a bit complex. It involves the ordering of the logout cleanup process and InventoryCloseEvent.

When a player logs out, Paper's PlayerList.remove() dispatches a PlayerQuitEvent:

callEvent(playerQuitEvent);
player.getBukkitEntity().disconnect(...);

Source: PlayerList.remove()

Magic's PlayerController.onPlayerQuit() handles the PlayerQuitEvent and starts the Mage cleanup process. MagicController.mageQuit() calls Mage.deactivate(), which deactivates the active wand and cancels the original interval batches. It then marks the Mage as unloading and schedules its removal for the next tick.

After the PlayerQuitEvent has been handled, PlayerList.remove() later removes the player entity by calling serverLevel.removePlayerImmediately().

serverLevel.removePlayerImmediately(player, Entity.RemovalReason.UNLOADED_WITH_PLAYER);

Source: PlayerList.remove()

Only after that does the same method remove the player from playersByUUID.

if (serverPlayer == player) {
    this.playersByUUID.remove(uuid);
}

Source: PlayerList.remove()

Removing the entity invokes ServerLevel.EntityCallbacks.onTrackingEnd(). Because the player is an InventoryHolder, Paper closes the inventories of its viewers with the UNLOADED reason. The player is included in this viewer list: Paper explicitly populates the player inventory with its own viewer during login in PlayerList.placeNewPlayer().

if (entity.getBukkitEntity() instanceof InventoryHolder
        && (!(entity instanceof ServerPlayer) || entity.getRemovalReason() != Entity.RemovalReason.KILLED)) {
    for (HumanEntity h : Lists.newArrayList(
            ((InventoryHolder) entity.getBukkitEntity()).getInventory().getViewers())) {
        h.closeInventory(InventoryCloseEvent.Reason.UNLOADED);
    }
}

Source: ServerLevel.EntityCallbacks.onTrackingEnd()

CraftHumanEntity.closeInventory() delegates this call to ServerPlayer.closeContainer(). That method calls CraftEventFactory.handleInventoryCloseEvent(), which fires an InventoryCloseEvent.

CraftEventFactory.handleInventoryCloseEvent(this, reason);

Source: ServerPlayer.closeContainer()

Magic's InventoryController.onInventoryClosed() handles this event and calls Mage.checkWand(). As a result, test_interval_wand is activated again through Wand.activate(), and test_interval_spell is cast again via cast_spell in Wand.updateEffects().

The first interval step runs immediately. At this point, the old Mage is still registered in Magic, so MagicController.getMage(oldPlayer) resolves to that Mage without entering the new-Mage branch that produces the offline warning. Paper has also not yet removed the player's UUID mapping, so CraftPlayer.isOnline() still returns true during this immediate step. Since the interval remains active, the recast creates a new pending ActionBatch on this unloading Mage after the original batches have already been cancelled.

The old Mage is already present in pendingConstruction from the original batches. Mage.cancelPending() removes cancelled batches from the Mage, but removal of the Mage from pendingConstruction occurs later when MagicController.processPendingBatches() observes that it has no pending batches. Before that processing pass occurs, the logout-time recast adds a new batch. Mage.addBatch() calls MagicController.addPending(), so the Mage remains in pendingConstruction with the new batch.

On the next tick, MageQuitTask.run() calls MagicController.finalizeMageQuit(). MagicController.removeMage() removes the Mage from the registered Mage map, but not from pendingConstruction. Therefore, the old Mage remains referenced, and MagicController.processPendingBatches() continues processing its newly created interval batch after logout.

When the next interval step runs, the ActionBatch reuses its original CastContext. In this reproduction, target: self made the caster's original CraftPlayer the target entity when the spell was cast, and CastContext.getTargetEntity() later returns that original target instance. MessageAction.perform() and MessageAction.sendMessage() obtain that old, now-offline target from the context and pass it to MagicController.getMage().

Since the original Mage has already been removed from the registered Mage map, MagicController.getMage() produces the warning shown above, creates and registers a new Mage for the same UUID, assigns the old offline CraftPlayer to it, and schedules its saved data to be loaded.

When the player rejoins, PlayerController.onPlayerJoin() calls getMage(player) using the new CraftPlayer instance. Since the Mage already exists in the registered Mage map, MagicController.getMage() updates its commandSender, entity, and player to the new instance.

When the player selects a wand configured with a swap action, PlayerController.onPlayerEquip() calls controller.getMage(player) with the current Player. This temporarily updates the registered Mage's commandSender, entity, and player to the current CraftPlayer instance.

However, when the stale interval batch runs again, it passes the old CraftPlayer instance to MagicController.getMage(). The same registered Mage is then updated with the old commandSender, entity, and player again. Since the interval is infinite, selecting the wand only repairs the Mage temporarily; the next interval step overwrites it again.

This is why swap casting stops working. PlayerController.onPlayerSwapItem() receives the current Player, but calls controller.getRegisteredMage(player) rather than controller.getMage(player). Unlike getMage(player), getRegisteredMage(player) only retrieves the Mage from the registered Mage map and does not update its commandSender, entity, or player to the current CraftPlayer.

The handler then obtains the active wand from the Mage and calls its swap action. The swap handler itself runs, but the wand obtains its spell through the Mage whose player-related fields now refer to the old CraftPlayer. In this reproduction, the Message action consequently sends through the stale player instance rather than the currently joined player, so the player sees no cast result.

The old Mage remains referenced through pendingConstruction. The stale interval running on that old Mage repeatedly corrupts the registered Mage's player reference.

Additional notes:

I have only tested this issue with Interval, so I have not confirmed the same behavior with other actions. However, I suspect that it is not specific to Interval.

DelayAction.perform() explicitly returns PENDING while waiting. Repeat and other action sequences may also remain pending when their execution does not finish in the current processing pass. ActionBatch retains its original CastContext while it remains pending, including the Mage and caster state used when the spell was cast.

Based on this, I suspect that other action sequences could cause the same problem if the logout-time recast leaves an ActionBatch pending on the unloading Mage. If a later action obtains the caster from that old context and passes the old CraftPlayer to MagicController.getMage(), it can overwrite the registered Mage in the same way.

An infinite Interval makes the problem persistent because the stale batch never finishes. With a finite Interval, Delay, or another finite pending action, the same overwrite may still occur if a pending step runs after logout or after the player has rejoined, although it may stop after the batch finishes.

This issue is reported through the swap-casting failure, but I suspect that swap casting is not the only possible symptom. The stale batch overwrites the registered Mage's commandSender, entity, and player with old instances. Because these fields are used by many other Mage, wand, inventory, and spell operations, other problems may also be caused by the same stale state. I have not tested those other possible symptoms.

Changing the swap handler from getRegisteredMage(player) to getMage(player) may temporarily fix this particular symptom by rebinding the Mage to the current CraftPlayer when the swap event occurs. However, the stale batch would still exist and could overwrite the Mage again on a later pending step. It would also leave other code paths exposed to the same stale state.

Therefore, it may be better to address the logout-time recast itself rather than only changing the swap handler.

[NathanWolf]

Thank you for the extremely detailed bug report!

You are correct that this whole flow is overly complex. Hopefully I can find an elegant solution, but I really appreciate the reproduction steps and level of effort you put into this report.