Paper: Light Queue crash

[aikar]

[22:08:42] [Server thread/ERROR]: Encountered an unexpected exception
java.lang.NullPointerException
        at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$MapIterator.nextEntry(Long2ObjectOpenHashMap.java:511) ~[smp2.jar:git-Paper-"f3da24a"]
        at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$ValueIterator.next(Long2ObjectOpenHashMap.java:706) ~[smp2.jar:git-Paper-"f3da24a"]
        at net.minecraft.server.v1_9_R2.PaperLightingQueue.processQueue(PaperLightingQueue.java:23) ~[smp2.jar:git-Paper-"f3da24a"]
        at net.minecraft.server.v1_9_R2.MinecraftServer.C(MinecraftServer.java:787) ~[smp2.jar:git-Paper-"f3da24a"]
        at net.minecraft.server.v1_9_R2.MinecraftServer.run(MinecraftServer.java:634) [smp2.jar:git-Paper-"f3da24a"]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_72]

need to debug how this could happen (potentially async access, but should in theory be a CME not NPE)

[kashike]

Please use the issue template.

[TNTUP]

@aikar Is it related to this? My server crashed today on 1.9.4 http://pastebin.com/er33Ma1R

At this time I can't update to 1.10.2, but I guess it wont be fixable for 1.9.4

[aikar]

@TNTUP unrelated. You appear to of had a lot of chunks unload that had light updates pending.

[TNTUP]

Oh sorry, that's the first time I see that kind of error, haha^^'

[zachbr]

Still occurring on 1.10

[19:26:06] [Server thread/ERROR]: Encountered an unexpected exception
java.lang.NullPointerException
    at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$MapIterator.nextEntry(Long2ObjectOpenHashMap.java:511) ~[patched_1.10.2.jar:git-Paper-821]
    at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$ValueIterator.next(Long2ObjectOpenHashMap.java:706) ~[patched_1.10.2.jar:git-Paper-821]
    at net.minecraft.server.v1_10_R1.PaperLightingQueue.processQueue(PaperLightingQueue.java:23) ~[patched_1.10.2.jar:git-Paper-821]
    at net.minecraft.server.v1_10_R1.MinecraftServer.C(MinecraftServer.java:775) ~[patched_1.10.2.jar:git-Paper-821]
    at net.minecraft.server.v1_10_R1.MinecraftServer.run(MinecraftServer.java:624) [patched_1.10.2.jar:git-Paper-821]
    at java.lang.Thread.run(Unknown Source) [?:1.8.0_101]

[zachbr]

Still occurring on 1.11

java.lang.NullPointerException: Exception in server tick loop
    at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$MapIterator.nextEntry(Long2ObjectOpenHashMap.java:511)
    at it.unimi.dsi.fastutil.longs.Long2ObjectOpenHashMap$ValueIterator.next(Long2ObjectOpenHashMap.java:706)
    at net.minecraft.server.v1_11_R1.PaperLightingQueue.processQueue(PaperLightingQueue.java:23)
    at net.minecraft.server.v1_11_R1.MinecraftServer.C(MinecraftServer.java:801)
    at net.minecraft.server.v1_11_R1.MinecraftServer.run(MinecraftServer.java:648)
    at java.lang.Thread.run(Thread.java:745)

[Spottedleaf]

Under what circumstances does this happen?

[aikar]

It's an extremely rare race condition, but under heavy light updates, it can trigger more often.

I've only had it twice ever since we added this patch, over 10 servers, and the 2nd one was during a period that I had a bug bombing the server with light updates.

Though I'm absolutely perplexed on what could cause this.

[aikar]

Oh, I think I see.

The error is in the chunk iteration. So it seems somethings messing with the chunks set during lighting updates that causes this weird error.

[Spottedleaf]

@aikar
Thanks for the circumstance. I will eventually get around to testing heavily within the next few days.

From what I can tell, I have not seen any concurrent (async specifically) modifications of the chunk map in the paper or vanilla code, so I do not believe a race condition is the cause here.

What I do know is that while iterating, there appears to be a disagreement with the iterator's number of entries left vs how many are actually contained within the map, with the iterator's number being greater than the actual count (can't be less than!). Effectively it's _as if_ an entry was removed under the iterator's nose.

I have not ruled out a faulty map yet, but I'm not yet finished on determining async modifications either.

[aikar]

@Spottedleaf it appears Long hash maps do not perform the same CME logic.

[Spottedleaf]

@aikar
I have found a bug, however I was unable to produce the NPE.

My fork, https://github.com/Spottedleaf/Concrete/tree/issue-313, detected a modification while iteration.

Here's the stacktrace:
http://pastebin.com/eaNezJcA (OUTDATED)
http://pastebin.com/1u4F3g9i (As of https://github.com/Spottedleaf/Concrete/commit/8483e6753aaeabf0c17d2bc071b61af9f989f725)

Plugins:
None

Server configuration:
http://pastebin.com/1BaLggXL - bukkit.yml
http://pastebin.com/ukjJ5dDe - paper.yml
http://pastebin.com/15Q6EYn2 - spigot.yml
http://pastebin.com/nCMd6u2U - server.properties

Note that the server.properties includes the world seed.

Produced by _starting_ the server. I do not know of how many more of these there may be, if any, or even if this was the cause. Note that this occurs on world generation, i.e after deleting world folders.

EDIT: Note that the issue-313 branch is not intended to be used for long periods of time, as all modifications to the chunk map are stored in memory forever. Be aware of this if you test.

EDIT2: This occurs on chunk generation as well, simply flying around on the generated world produced the same stack trace.

[Spottedleaf]

Looking briefly over the source of Long2ObjectOpenHashMap, adding an entry whilst iterating can cause an NPE. This is likely the issue here, or at least one of them.