Server Crashing Occasionally (FileNotFoundException)

[jayserp]

Hi,

We're running a StarMade server and noticed that it occasionally crashes with the following error:



[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] [DELETE][Server(0)] Sendable 47210(Ship[STickypiston](47210)) Physically DELETING DONE and Notified!
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] [DELETE][Server(0)] Sendable 47209(Ship[Floating_Duck_MkI](47209)) Physically DELETING DONE and Notified!
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] java.io.FileNotFoundException: ./tmp/ENTITY_SHIP_STickypiston.tmp (Too many open files)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at java.io.FileOutputStream.open(Native Method)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at java.io.FileOutputStream.(FileOutputStream.java:212)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at java.io.FileOutputStream.(FileOutputStream.java:165)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at org.schema.game.server.controller.GameServerController.a(SourceFile:1611)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at va.a(SourceFile:400)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at org.schema.game.server.controller.GameServerController.update(SourceFile:1293)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at org.schema.schine.network.server.ServerController.run(SourceFile:177)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] at java.lang.Thread.run(Thread.java:722)
[Jun 22, 2013 6:10:27 PM] STDERR: [ERR] Exiting because of exception java.io.FileNotFoundException: ./tmp/ENTITY_SHIP_STickypiston.tmp (Too many open files)

Does anyone know what may be causing this?

We're running the server on Linux Ubuntu 12.04.

Thanks

 

[Valck]

This bug is still in the latest build; our dedicated server has been running fine continuously for a few days under little load, with just one or two players on and off.

[Jul 18, 2013 9:51:56 PM] STDERR: [ERR] java.io.FileNotFoundException: ./tmp/ENTITY_SHIP_MOB_Isanth-VI_1372625323463_0.tmp (Too many open files)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at java.io.FileOutputStream.open(Native Method)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at java.io.FileOutputStream.(FileOutputStream.java:194)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at java.io.FileOutputStream.(FileOutputStream.java:145)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at org.schema.game.server.controller.GameServerController.a(SourceFile:1745)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at vh.a(SourceFile:449)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at org.schema.game.server.controller.GameServerController.update(SourceFile:1401)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at org.schema.schine.network.server.ServerController.run(SourceFile:219)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR]         at java.lang.Thread.run(Thread.java:662)
[Jul 18, 2013 9:51:56 PM] STDERR: [ERR] Exiting because of exception java.io.FileNotFoundException: ./tmp/ENTITY_SHIP_MOB_Isanth-VI_1372625323463_0.tmp (Too many open files)

 

[Valck]

Server crashed again, here\'s some additional system information:

$ uname -a
Linux s15info 2.6.32-042stab078.27 #1 SMP Mon Jul 1 20:48:07 MSK 2013 x86_64 GNU/Linux Ubuntu 10.04.3 LTS

$ ulimit -a  
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 20
file size               (blocks, -f) unlimited
pending signals                 (-i) 16382
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) unlimited
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited


$ cat /proc/meminfo |head -n3
MemTotal:        4194304 kB
MemFree:         3993764 kB
Cached:           176048 kB

 

[DracoNB]

http://stackoverflow.com/questions/2272908/java-io-filenotfoundexception-too-many-open-files



Run this command when you get the error:

lsof -p

 

[Valck]

... the JVM is already exiting, and the chances of getting any useful information are slim at best :/

But thanks for the link, I\'ll have a look at it later.

I will try and monitor it more closely, and report back with any findings. Problem is, I\'m not the box\'s admin and can\'t simply restart the StarMade server when it has crashed.

 

[DracoNB]

Maybe run that command every few minutes and save the output to a log file? Then when it crashes you can see what it looked like leading upto the crash

 

[Valck]

... exactly what I\'m going to do, among a few other things

 

[Valck]

So I decided to watch the server process on a local machine (different kernel, ulimit settings, etc., but symptoms are still the same), that way I could start/stop/restart it when needed.


$ watch -n 60 --errexit \'lsof -p $(pidof java) >> javawatch.log 2>>javawatch.err\'

made pretty obvious what is going on server-side. For every player that logs in (one, in my case), the server apparently opens a new file handle for each and every entity (ship, turret, shop, planet, ...) within one sector around the player\'s sector. In my case, that\'s about fifty entities. When the player logs out, those file handles are kept open. With a default ulimit of 1024 open files, that amounts to roughly 20 logins before the server balks, corresponding quite well to the few days of uptime it has achieved between crashes.

Considering you have to relog every half-hour or so because the client becomes unresponsive to control input when crossing sector borders, 20 logins aren\'t exactly much. Even with a higher ulimit of say, 8192, that would give an uptime of maybe one or two weeks at best, for only one player actually logging in to the server.

An immediate workaround might be to restart the server daily, but in the long run, I think it is imperative that the reason is found why those file handles are not closed when they are no longer needed (or more precisely, why the StarMade server thinks those files still have to be kept open although there isn\'t even a player nearby, heck there isn\'t even a player online).

 

[Valck]

Why not 0.09381? Why 0.0938 and not 0.09380, after 0.09378... Whatever...

This update appears to have made quite the difference. There are still tons of files being kept open even without any player connected, but it seems the unrestricted growth has at least been reduced. It remains to be seen how it will play out in the long run, I\'ll be certain to keep an eye on the JVM\'s open file handles.

 

[Endimmion]

Despite the recent updates, I have also this problem on my server. It makes crash the server several times per day.