Crashes and didn't know where to put the error

[2spoopy4meh]

http://www.mediafire.com/view/tfombcfrkdrre4e/crash-2015-07-25_11.02.43-server.txt

Couldn't find another way to share the crash report. I don't exactly know why I'm crashing, but it started happening when I switched over to minetick.

[Poweruser]

Hello 2spoopy4meh, thank you for reporting this crash.

This crash happened during a PlayerQuitEvent when the server was processing the player connections. The plugin MassiveCore handled the quit event and tried to check the date of the last modification of a file on the disk (probably a player data file within it's plugin folder). While checking if that file handle is actually a file, the error occurred. The thrown exception does not exactly tell what went wrong, as it happened in the native implementation of the method UnixFileSystem.getBooleanAttributes0, and I do not have a source code available of it.

Top of the stacktrace:

java.lang.Error
at java.io.UnixFileSystem.getBooleanAttributes0(Native Method)
at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:242)
at java.io.File.isFile(File.java:882)
at com.massivecraft.massivecore.store.DriverFlatfile.getMtime(DriverFlatfile.java:82)
at com.massivecraft.massivecore.store.Coll.examineId(Coll.java:687)
at com.massivecraft.massivecore.store.Coll.examineId(Coll.java:667)
at com.massivecraft.massivecore.store.Coll.syncId(Coll.java:747)
at com.massivecraft.massivecore.MassiveCoreEngineMain.syncAllForPlayer(MassiveCoreEngineMain.java:351)
at com.massivecraft.massivecore.MassiveCoreEngineMain.syncOnPlayerLeave(MassiveCoreEngineMain.java:338)

The location of the isFile() call in MassiveCore: com.massivecraft.massivecore.store.DriverFlatfile.getMtime(DriverFlatfile.java:82)
The file that was accessed can probably be derived from the player, his name or his uuid, who disconnected right before the crash. If you can figure out which one it was, check it's validity.

As all this happened during the processing of the player connections, the threaded worlds feature can be ruled out, as connection processing is done between world ticks. All the other threads of MinetickMod (MinetickMod_NBTFileSaver, MinetickMod_PacketBuilder, MinetickMod_PathFinder, MinetickMod_TimerService) were according of the crash report in the waiting state at the time of the crash, meaning that they could not have done something that caused the crash.
I have tagged all the threads and thread pools, that I am responsible for, with the prefix "MinetickMod_" exactly for such cases.
Example for the nbt file saver (Line 23216 in the crashreport):
"MinetickMod_NBTFileSaver-0" Id=165 WAITING

While checking the details of the other active threads I noticed two things:

1. MassiveCore is running an extra thread called MStore ExamineThread, which just at that moment of the crash was accessing the file system as well. This is worth to be investigated.

At line 23739 in the crash report:

"MStore ExamineThread" Id=36 RUNNABLE
at java.io.UnixFileSystem.list(Native Method)
at java.io.File.list(File.java:1122)
at java.io.File.listFiles(File.java:1286)
at com.massivecraft.massivecore.store.DriverFlatfile.getId2mtime(DriverFlatfile.java:113)
at com.massivecraft.massivecore.store.Coll.findSuspects(Coll.java:828)
at com.massivecraft.massivecore.store.ExamineThread.run(ExamineThread.java:46)

2. Something on your server is creating a ton of unnamed thread pools with just one thread in each.
   From line 115 on, you'll find their stacktraces with the names "pool-#-thread-1". All the threads that are listed there, were active at that time. A text search for -thread-1" Id= counts 1947 thread pools. That's way too much. Some of them are surely legit and have their purpose, but most are not. You should be able to confirm this, just by checking the thread count of the server process at runtime.

[Poweruser]

On MassiveCraft's help page for MassiveCore I'm reading that some effort has been done to allow multiple servers to access the same data store (mstore) files.

Quote from http://www.massivecraft.com/massivecore#the-data-store-system-mstore

An especially nice feature is that the storage system polls for changes in the backend. You can change the “.json”-flatfiles during runtime and the changes will be loaded into the server. It is thus possible to point two servers to the same database although data may get lost every once in a while due to write conflicts.

If you run multiple servers, do you have such a case in your server landscape?

[2spoopy4meh]

I do not have multiple servers running on the system, so no. I'm actually fairly new to all of this, and don't exactly know how to do anything that you have told me to do. If you want to look into this further, then you could probably guide me through it step by step. If this is just an error with massivecore though, then I don't think it would be worth it. I can send the crash report over to them. Sorry for not being very knowledgeable about all of this. :(

[Poweruser]

If this is just an error with massivecore though, then I don't think it would be worth it. I can send the crash report over to them.

That's what it currently looks like. Report it to them and let's see what they come up with. My suspicion is that the file accesses, that the MStore ExamineThread does, collide with the regular ones of the event handlers. I.e. reading/writing from/to the same file at the same time.

[Poweruser]

... it started happening when I switched over to minetick.

A few more questions:
How many times has it happend yet?
Is it reproducable, like on every disconnect of a certain player?

[2spoopy4meh]

Sorry for the delay. It has happened probably more than 10 times. I am unable to reproduce it. It doesn't always happen when someone logs out.

[Poweruser]

Oh well. I just noticed that it is the watchdog thread

Line 5: Description: Watching Server

that assumes that your server has crashed, as one server tick took longer than the defined maximum tick time (setting max-tick-time in server.properties). What is currently set there? The default value is 60000 (60000 milliseconds = 1 minute).

In your normal server log you should see this entry at the time of the supposed "crash":

A single server tick took X seconds (should be max Y)
Considering it to be crashed, server will forcibly shutdown.

Assuming that you haven't set this setting too low, then there was a serious lag spike. Meaning the main thread was busy on something for at least one minute and wasn't able to start the next tick in time. Check the last two minutes in the log before that for anything unusual, like someone running an worldedit command.

[2spoopy4meh]

I looked at the end of a few logs, and I did not see that what you told me to look for. I also didn't see any huge worldedits in the logs right before the crashes. If you would like me to give you a few of the logs, then I can do so. I will also increase the max tick time a little bit to see if the frequency of the crashes decreases.

[Poweruser]

It has to be in there, the mentioned time in the crash report file name matches exactly the time in the log file.

If you would like me to give you a few of the logs, then I can do so

Please do so, along with the other crash report files. If there's confidential data in the log files, like passwords, make sure to remove it first. You can email me directly, the address is on the main page of my github account

[2spoopy4meh]

Log File: http://www.mediafire.com/download/nzkp1m98u93jxq7/latest.log
First crash report: http://www.mediafire.com/view/w8f67pdm6j02q50/crash-2015-08-01_17.17.45-server.txt
Second crash report: http://www.mediafire.com/view/4n6d5g3w02mfu3c/crash-2015-08-01_17.17.43-server.txt

The most recent crash produced one last error in the logs before crashing, and it produced 2 crash reports. I've also noticed that over the course of all these crashes, only 3 crash reports were created. The server crashed a lot more than 3 times for sure, so this may be strange.

[Poweruser]

There are several things going wrong here. Before I get to them, some questions:

What server software did you previously use (CraftBukkit / Spigot / something other)? And for which Minecraft version?
I'm also still interested in the value of the setting max-tick-time, that was set before you increased it (if you did).

[2spoopy4meh]

I used spigot 1.8.7, and changing that did not do anything.

[Poweruser]

I still fail to identify the causes for all this. I wouldn't be surprised if these are actually compatibilty issues, as MinetickMod is an alternative to CraftBukkit and not to Spigot. Note that Spigot extends the API and several of your plugins are compiled against it, and therefore are meant to be run with Spigot. Sooner or later you will run into trouble again, when one of these plugins is using a new feature that didn't exist in the Bukkit-API yet.
One thing that is not a compatibility issue, are the 2000 idle threadpools that the crash reports list. That's one of your plugins doing something bad (i.e. not re-using and/or not shutting down already created pools)

I'm going create another project, that applies the changes of MinetickMod to Spigot instead of CraftBukkit. I dub it Migot, which is obviously a combination of both project names. It will have its own build tools, too.