Shopkeepers

Shopkeepers

2M Downloads

Failed to spawn shopkeeper

FatherWh0 opened this issue ยท 27 comments

commented

Preliminaries:

  • Shopkeepers version: <Insert Shopkeepers version>
    2.7.2
  • Spigot version: <Insert output of /version command>
    paper 1.14.3 build 126

  • I have checked that my issue/question does not get answered by:
  • I have checked all open and closed issues, but none seems to fit my issue/question.

Reproduction on a fresh and up-to-date Spigot server:

I was able to reproduce my issue on a freshly setup and up-to-date Spigot server (currently <Insert output of /version command on up-to-date Spigot server>) with the latest version of Shopkeepers (currently <Insert latest tested Shopkeepers version>), with no other plugins and with no kinds of other server or client mods.

The issue:

Provide a detailed description of your problem and add as much information as possible which could help reproducing the issue.

Include:

  • Description of the issue.
  • Step-by-step instructions on how to reproduce the issue.
  • Observed behavior.
  • Expected behavior.
  • If items with special attributes are involved: Include instructions on how to create those items.
  • Server logs (from server startup until issue). Consider enabling debug mode in the config for additional console output.
  • If modified from default: Plugin configurations.
  • .. Anything else that might be useful to reproduce and identify the issue.
    After my server has been running for hours shopkeepers will suddenly disappear and msgs appear on the console " [Server thread/WARN]: [Shopkeepers] Failed to spawn shopkeeper at world,-617,92,-2330".
    https://pastebin.com/9JAb0Cz1
    Reloading the plugin does not bring back the missing shopkeepers. Only restarting the server will restore the missing shopkeepers. A few hours later the errors return and the shopkeepers disappear again. Noteworthy that not all shopkeepers on the server disappear nor do all in one world but the ones that do are always located near each other.
commented

My guess is that there might be chunk loading related issues going on on the server.
It would be interesting to know whether this affects regular Spigot as well.

If you turn on debug mode in the config, do you get any other notices in the server log (like 'Chunk was silently unloaded before!')?

commented

Enabling debug mode added these messages to the log:
12:22:06 AM Shopkeepers: Unloading 1 shopkeepers in chunk world,-36,-144
12:22:11 AM Shopkeepers: Loading 1 shopkeepers in chunk world,-36,-144
https://pastebin.com/mEwPTmtJ

commented

I don't notice anything unusual in your logs. Would you mind testing this on the latest version of Spigot? They have pushed a few chunk related fixes recently. And Paper has some additional chunk related changes on top of Spigot, so testing on Spigot would rule out those being the issue here.

Offtopic: The next version will include a fix for the 'Shopkeeper entity-spawning seems to be out of sync' warning inside your second log.

commented

I am sorry but I am unable to test with Spigot. I tried but I quickly had to change back to Paper as my server, with Spigot, never ran faster than 15tps and kept dropping as low as 5tps with as few as 12 players online. I would try on my test server but I have been unable to reproduce the error there. I have logged into the test server and tped into and out of chunks containing shopkeepers but the error doesn't appear to occur unless there are a number of players going about normal gameplay. I will continue to try to reproduce the errors on my test server because I really need this issue sorted out. My players are getting upset because they are losing sales with missing shopkeepers.
Pls let me know if you have any other ideas that I might try or if you have any theories as to why the error doesn't occur on my test server. Sorry to be so much trouble to you.
Thank you greatly for your time and help.

commented

You mentioned that only certain shopkeepers are disappearing. Are those disappearing shopkeepers located near a chunk border? Could you post the coordinates of the disappearing shopkeepers?

I assume your test server is using different shopkeepers (at different locations). Could you copy those shopkeepers over to your test server (to the same coordinates) and then try there again? I will do the same then.

commented

I may have caused a misunderstanding. All shopkeepers on the server have disappeared at some point, both player shopkeepers and admin shopkeepers, they just don't disappear at the same time. I was wrong about my first statement that the ones that disappear tend to be close to each other. It seemed that way at the time but now I can see it just appears random.

The test server is an identical copy of my online server.

My server is live now with missing shopkeepers. I just looked into their locations and I don't see any pattern that the missing ones are near chunk borders.

Here is the current list of errors which include the coordinates: https://pastebin.com/DkG1wbk1

commented

I added some additional debug output to the latest snapshot, in case some shopkeeper mob cannot be spawned. Could you run this, turn debug mode on, and report back the output you get once the shopkeepers fail to spawn?

A build of this is available here: https://nexus.lichtspiele.org/repository/snapshots/com/nisovin/shopkeepers/Shopkeepers/2.8.0-SNAPSHOT/Shopkeepers-2.8.0-20190724.024509-2.jar
This versions also includes some other not yet released changes (mainly related to plugin compatibility and which hopefully don't cause new issues). See the changelog for a complete list of the changes.

commented

Snapshot debug mode: https://pastebin.com/pyhAGFU4

Btw, I've tried using an alt account as a sort of chunk anchor, keeping it located in the middle of a large number of shopkeepers for two days. In that time none of the shopkeepers that stay loaded all the time have disappeared.

commented

Hm, I went through the server code but could not figure out whether there are situations in which the spawned entity gets instantly removed again / marked 'dead' right after spawning.
My next guess would be that maybe some plugin might be interferring.. Do you have any plugins running which react to mob spawning, remove entities, or which might manually load or unload chunks?
Is your test server (where you can't reproduce the issue) running the same plugins with the same configurations?

Edit: Also, I assume you are not using the use-legacy-mob-behavior setting?

commented

I added even more debugging output when it detects this situations of a just spawned entity being marked dead: 2d1c247

This will retry the spawning and then log all event activity (to hopefully help with tracking down the plugin causing this issue, in case this is caused by a plugin). It will also log whether the entity gets marked as 'dead' by the server already before spawning (in this case this is likely some server issue..).

You can find a build of this here: https://nexus.lichtspiele.org/repository/snapshots/com/nisovin/shopkeepers/Shopkeepers/2.8.0-SNAPSHOT/Shopkeepers-2.8.0-20190726.050352-4.jar

commented

I believe I've found the problem. Following your idea about a plugin despawning mobs I removed Clearlag. That was two days ago and I haven't had a shopkeeper come up missing since or any errors on the console.
I'm not sure where to go from here. I need Clearlag. I've already had someone break my server by letting their grinder build up several hundred mobs. That's one of the very few functions of Clearlag I have enabled. I have no idea why it would despawn or prevent spawning of shopkeepers. It's only set to despawn entities if there's more than 100 in one chunk.
I somehow got behind on my version of Clearlagg. I'll update to the newest and report back.

commented

I looked into ClearLagg and noticed several potential issues affecting shopkeepers. But maybe it's possible to configure it in a way to not cause this issue:

  • Disable 'chunk-limiter'. This attempts to unload chunks from within the chunk load event. I don't believe this works as expected with the changes in minecraft 1.14.
  • The 'chunk-entity-limiter' removes spawned entities on MONITOR priority and does not ignore plugin-spawned mobs, making it impossible for Shopkeepers to bypass it. Though, there seems to be a 'limit' setting that can be tweaked to not hopefully affect your chunks with Shopkeepers in them. There is also a setting for specifying the affected mob types.
  • 'spawn-limiter' seems to count mobs and then prevent spawning of further mobs if a certain limit across all worlds is reached. This might be an issue, but I am not completely sure about this, since this cancels the corresponding CreatureSpawnEvents at LOWEST priority. So Shopkeepers might be able to bypass this spawn prevention, if you have Shopkeeper's 'bypass-spawn-blocking' enabled (it is by default).
  • The clear ('auto-removal'), halt ('auto-removal'), limit ('limit') and maybe also the 'live-time' task (not sure about this one, since shopkeepers have AI disabled and might therefore not age) might be able to periodically remove shopkeeper entities. However, if you have Shopkeeper's spawn verifier enabled, it should at least respawn the Shopkeepers periodically.
  • The same goes for any commands triggering entity removal or attempting chunk unload.

Like you said, the likeliest candidate for causing issues is probably the 'chunk-entity-limiter'. This would also explain why this issue only comes up after a while (once there are for some reason more than 100 entities (mobs, players, dropped item stacks, arrows, experience orbs, projectiles/fireworks (those should disappear again though), particle clouds, pets, minecarts, ..)).

commented

Created a ticket over at ClearLagg about this: https://dev.bukkit.org/projects/clearlagg/issues/222

commented

Updating to the newest Clearlagg didn't help.
As you can see here: https://pastebin.com/CBTtHgJ7 I have most features of CL disabled. Also, I never use clear or halt. I do have limit enabled but set as it is I don't see a possible conflict.

commented

It would be interesting to count those entities whenever spawning doesn't work anymore, to either confirm or rule out this ClearLagg feature from causing thiss issue for you. I could add some debug output to Shopkeepers print the entity counts of the chunk whenever spawning does not work.

commented

Snapshot is available here: https://nexus.lichtspiele.org/repository/snapshots/com/nisovin/shopkeepers/Shopkeepers/2.8.0-SNAPSHOT/Shopkeepers-2.8.0-20190727.164041-5.jar

This will now also print the chunk's entity count (total and by entity type) when debugging a failed spawn attempt.

I can be certain there aren't 75 mobs in the chunks

Then maybe some other plugin might be interfering. But since removing ClearLagg seems to resolve the issue my bet is still on ClearLagg.
The other features you are using are:

  • 'mobspawner': This should however only affect mobs spawned by mob spawners (except if the server has some bug and marks plugin-spawned entities as spawned by a mob spawner).
  • 'limit', tnt-reducer, tnt-minecart: These should not remove mobs at all.
commented

If you mean 'chunk-entity-limiter' I can be certain there aren't 75 mobs in the chunks where the shopkeepers are despawning.

commented

I have no idea if this is relevant or helpful but after about half the shopkeepers were missing I used plugman to unload clearlagg and about a minute later the missing shopkeepers reappeared. It's the first time I've gotten them to reappear without a restart.
https://pastebin.com/LDdNwgVq

commented

Additional debugging: https://pastebin.com/DPMS7K53

commented

Entities of chunk world,-39,-146 (total: 114): {EXPERIENCE_ORB=1, ITEM_FRAME=33, ARMOR_STAND=5, VILLAGER=75}

Apparently there are 75 villagers in that chunk. If you have checked the chunk, and there are not actually 75 villagers there, then my next guesses would be:

  • Maybe there is a server bug causing dead/previously despawned villagers to still be listed for plugins for some reason.
  • Another guess might be that if you have around 38 Shopkeepers villagers there, and they get respawned, maybe the server removes the previous villagers 1 tick afterwards, resulting in there temporarily being twice as many villagers. I would then however assume that the spawn verifier can respawn then later.. which does not seem to be the case according to your descriptions.

Edit: Actually, looking at the log again, the chunks seem to contain 6 shopkeepers, but the chunk gets loaded and unloaded very frequently, somehow causing more than 75 villagers to be spawned at the same time (assuming that the server needs some time (at least 1 tick) to actually remove despawned mobs).

commented

There aren't 75 shopkeepers in any of the chunks, nor 38. In fact, most disappearing shopkeepers only share the chunk with 2 or 3 others and they are not of the same species. The chunk-entity-limiter is looking for 75 of the same species.

commented

See my edit: Somehow the frequently chunk loading and unloading (and shopkeepers spawning and despawning villagers as reaction) causes the server to (temporarily?) contain more than 75 villagers in that chunk. I don't know what is causing the frequent chunk loading/unloading.
Does the issue persist once they can no longer spawn? Or is the spawn verifier able to respawn them after a while (once the load/unload spam has finished and the server had some time to actually remove the despawned entities).

commented

It persists. Once they are gone a server restart is the only way to get them back.

commented

I will have to do further debugging to figure out what the server is doing with the entities spawned and despawned by Shopkeepers when chunks are getting loaded and unloaded that quickly. I think one occasion in which this might be happening is if a player is in his death/respawn screen nearby, but I will have to test this again.

As workaround: In case your shopkeepers have custom names, and you manage to configure ClearLagg to ignore mobs with custom names, I made some changes to actually apply those names prior to spawning the mob.
If ClearLagg adds an option to ignore mobs with certain metadata keys, that will work as well.

A snapshot of this is available here: https://nexus.lichtspiele.org/repository/snapshots/com/nisovin/shopkeepers/Shopkeepers/2.8.0-SNAPSHOT/Shopkeepers-2.8.0-20190728.012752-6.jar

commented

I was able to reproduce ClearLagg running into its chunk entity limit (due to counting dead entities, which the server did not yet remove) when dying inside the chunk containing a few shopkeepers (and causing an chunk load/unload loop by that). I created a Spigot ticket for this chunk load/unload looping (https://hub.spigotmc.org/jira/browse/SPIGOT-5227), however, this might also very well be some vanilla minecraft issue/behavior, so I don't know how good the chances are for this to get resolved / figured out.
Also, there might also be other situations in which chunks get loaded and unloaded frequently and indefinitely. So if this is caused by something else on your server, resolving this won't help.

However, I was not yet able to get into a state where the dead entities do not get removed again at some point. So in all my tests ClearLagg would then (a moment later) allow the spawning again.

I am currently testing with Spigot 1.14.4. I will also test Spigot and Paper 1.14.3 later and see whether there are some differences there.

Edit: Okay, I was able to reproduce the issue differently now on Spigot 1.14.3 (without dying inside the chunk) and with the shopkeepers persistently being gone. I still have to do further testing to check whether this applies to 1.14.4 as well.

Edit: The issue affects Spigot 1.14.4 as well. I believe this is an upstream issue (under some circumstance dead entities do not get properly removed by the server). ClearLagg counting those non-removed dead entities and then preventing spawning of new entities is only a side-effect of that underlying server issue.

Edit: Corresponding Spigot ticket with reproduction steps: https://hub.spigotmc.org/jira/browse/SPIGOT-5228

commented

The linked Spigot issue has been resolved now. This should prevent dead shopkeeper entities from lingering in chunks around the spawn area and never getting properly removed until after the next server restart.

There is still a related issue with regular dead entities getting persisted by Minecraft (https://bugs.mojang.com/browse/MC-135552), but that doesn't apply to the entities spawned by the Shopkeepers plugin and might get resolved in the next Minecraft version.