Server will run for a bit longer after this, but ultimately all sockets timeout. Seen this happen about a half-dozen times on our public server during the past week...following error is the only apparent consistent element.
Am analyzing a packet trace now - will followup with more info.
[2016-06-05 22:41:55] java.lang.IllegalArgumentException: java.net.SocketTimeoutException: Read timed out [2016-06-05 22:41:55] at obfuscated.Rf.a(SourceFile:94) [2016-06-05 22:41:55] at org.schema.game.server.controller.GameServerController.authenticate(SourceFile:781) [2016-06-05 22:41:55] at org.schema.schine.network.commands.LoginRequest.login(SourceFile:54) [2016-06-05 22:41:55] at org.schema.schine.network.commands.LoginRequest.run(SourceFile:202) [2016-06-05 22:41:55] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [2016-06-05 22:41:55] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [2016-06-05 22:41:55] at java.lang.Thread.run(Thread.java:745) [2016-06-05 22:41:55] Caused by: java.net.SocketTimeoutException: Read timed out [2016-06-05 22:41:55] at java.net.SocketInputStream.socketRead0(Native Method) [2016-06-05 22:41:55] at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [2016-06-05 22:41:55] at java.net.SocketInputStream.read(SocketInputStream.java:170) [2016-06-05 22:41:55] at java.net.SocketInputStream.read(SocketInputStream.java:141) [2016-06-05 22:41:55] at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) [2016-06-05 22:41:55] at sun.security.ssl.InputRecord.read(InputRecord.java:503) [2016-06-05 22:41:55] at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973) [2016-06-05 22:41:55] at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930) [2016-06-05 22:41:55] at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) [2016-06-05 22:41:55] at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) [2016-06-05 22:41:55] at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) [2016-06-05 22:41:55] at java.io.BufferedInputStream.read(BufferedInputStream.java:345) [2016-06-05 22:41:55] at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:704) [2016-06-05 22:41:55] at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:647) [2016-06-05 22:41:55] at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1536) [2016-06-05 22:41:55] at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441) [2016-06-05 22:41:55] at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480) [2016-06-05 22:41:55] at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:338) [2016-06-05 22:41:55] at org.schema.game.common.api.ApiOauthController.a(SourceFile:136) [2016-06-05 22:41:55] at org.schema.game.common.api.ApiOauthController.a(SourceFile:277) [2016-06-05 22:41:55] at obfuscated.Rf.a(SourceFile:47) [2016-06-05 22:41:55] ... 6 more
This is the auth event that corresponds with the error:
[2016-06-05 22:41:56] [LOGIN] login failed for /172.75.151.41:54217 (ERROR_AUTHENTICATION_FAILED) [2016-06-05 22:41:56] [DISCONNECT] Client 'null' IP(/172.75.151.41:54217) HAS BEEN DISCONNECTED . PROBE: true; ProcessorID: 814
From log.txt.0
[2016-06-05 22:41:56] [SERVER][LOGIN] login failed (ERROR_AUTHENTICATION_FAILED): SET CLIENT TO NULL [2016-06-05 22:41:56] [SERVER] SCHEDULED DISCONNECT EXECUTING [2016-06-05 22:41:56] [SERVER] Executing scheduled disconnect!; ProcessorID: 814 [2016-06-05 22:41:56] [SERVER][DISCONNECT] Client 'null' HAS BEEN DISCONNECTED . PROBE: true; ProcessorID: 814 [2016-06-05 22:41:56] [SERVER] COULD NOT UNREGISTER CLIENT null [2016-06-05 22:41:56] [SERVER] PROBE SUCCESSFULLY EXECUTED. STOPPING PROCESSOR. (Ping of a Starter to start server): PID 814
Another entry from a few days ago...resulted in the same java error shown above (there's more from other crashes, I'm just too lazy to copy/paste them all right now):
[2016-06-02 11:58:41] [LOGIN] login failed for /90.208.141.74:50193 (ERROR_AUTHENTICATION_FAILED) [2016-06-02 11:58:41] [DISCONNECT] Client 'null' IP(/90.208.141.74:50193) HAS BEEN DISCONNECTED . PROBE: true; ProcessorID: 2577
Timing of error corresponds with heap size increase shown here:
Retries eventually reaches 0, at which point all players are kicked, and nobody can relog until a server restart. Server will not shutdown cleanly: must kill java process.
To illustrate part-way through its death:
[2016-06-05 22:48:38] RETRY STATUS: Retries: 7; waiting for pong true (1465166918276/1465166926276); ProcessorID: 841 [2016-06-05 22:48:38] RETRY STATUS: Retries: 7; waiting for pong true (1465166918586/1465166927586); ProcessorID: 700 [2016-06-05 22:48:38] RETRY STATUS: Retries: 7; waiting for pong true (1465166918587/1465166927587); ProcessorID: 609 [2016-06-05 22:48:38] RETRY STATUS: Retries: 7; waiting for pong true (1465166918607/1465166927607); ProcessorID: 300 [2016-06-05 22:48:38] RETRY STATUS: Retries: 7; waiting for pong true (1465166918608/1465166927608); ProcessorID: 635 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919175/1465166928175); ProcessorID: 838 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919276/1465166926276); ProcessorID: 841 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919586/1465166927586); ProcessorID: 700 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919588/1465166927587); ProcessorID: 609 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919608/1465166928607); ProcessorID: 633 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919608/1465166927607); ProcessorID: 300 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919608/1465166927608); ProcessorID: 635 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919609/1465166928609); ProcessorID: 713 [2016-06-05 22:48:39] RETRY STATUS: Retries: 7; waiting for pong true (1465166919612/1465166928611); ProcessorID: 709 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920175/1465166928175); ProcessorID: 838 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920277/1465166926276); ProcessorID: 841 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920586/1465166927586); ProcessorID: 700 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920588/1465166927587); ProcessorID: 609 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920605/1465166929605); ProcessorID: 331 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920608/1465166928607); ProcessorID: 633 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920608/1465166927607); ProcessorID: 300 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920608/1465166927608); ProcessorID: 635 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920608/1465166929608); ProcessorID: 294 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920609/1465166928609); ProcessorID: 713 [2016-06-05 22:48:40] RETRY STATUS: Retries: 7; waiting for pong true (1465166920612/1465166928611); ProcessorID: 709 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921176/1465166928175); ProcessorID: 838 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921277/1465166926276); ProcessorID: 841 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921586/1465166927586); ProcessorID: 700 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921588/1465166927587); ProcessorID: 609 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921606/1465166929605); ProcessorID: 331 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921608/1465166928607); ProcessorID: 633 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921608/1465166927607); ProcessorID: 300 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921608/1465166927608); ProcessorID: 635 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921608/1465166929608); ProcessorID: 294 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921609/1465166928609); ProcessorID: 713 [2016-06-05 22:48:41] RETRY STATUS: Retries: 7; waiting for pong true (1465166921612/1465166928611); ProcessorID: 709 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922176/1465166928175); ProcessorID: 838 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922277/1465166926276); ProcessorID: 841 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922587/1465166927586); ProcessorID: 700 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922588/1465166927587); ProcessorID: 609 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922606/1465166929605); ProcessorID: 331 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922608/1465166928607); ProcessorID: 633 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922608/1465166927607); ProcessorID: 300 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922608/1465166927608); ProcessorID: 635 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922608/1465166929608); ProcessorID: 294 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922610/1465166928609); ProcessorID: 713 [2016-06-05 22:48:42] RETRY STATUS: Retries: 7; waiting for pong true (1465166922612/1465166928611); ProcessorID: 709 [2016-06-05 22:48:43] RETRY STATUS: Retries: 7; waiting for pong true (1465166923176/1465166928175); ProcessorID: 838 [2016-06-05 22:48:43] RETRY STATUS: Retries: 7; waiting for pong true (1465166923277/1465166926276); ProcessorID: 841 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925588/1465166927586); ProcessorID: 700 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925589/1465166927587); ProcessorID: 609 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925606/1465166929605); ProcessorID: 331 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925609/1465166928607); ProcessorID: 633 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925609/1465166927607); ProcessorID: 300 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925609/1465166927608); ProcessorID: 635 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925609/1465166929608); ProcessorID: 294 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925610/1465166928609); ProcessorID: 713 [2016-06-05 22:48:45] RETRY STATUS: Retries: 7; waiting for pong true (1465166925613/1465166928611); ProcessorID: 709 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926177/1465166928175); ProcessorID: 838 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926588/1465166927586); ProcessorID: 700 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926589/1465166927587); ProcessorID: 609 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926607/1465166929605); ProcessorID: 331 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926609/1465166928607); ProcessorID: 633 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926609/1465166927607); ProcessorID: 300 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926609/1465166927608); ProcessorID: 635 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926609/1465166929608); ProcessorID: 294 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926610/1465166928609); ProcessorID: 713 [2016-06-05 22:48:46] RETRY STATUS: Retries: 7; waiting for pong true (1465166926613/1465166928611); ProcessorID: 709 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927177/1465166928175); ProcessorID: 838 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927607/1465166929605); ProcessorID: 331 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927609/1465166928607); ProcessorID: 633 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927609/1465166929608); ProcessorID: 294 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927610/1465166928609); ProcessorID: 713 [2016-06-05 22:48:47] RETRY STATUS: Retries: 7; waiting for pong true (1465166927613/1465166928611); ProcessorID: 709 [2016-06-05 22:48:48] RETRY STATUS: Retries: 7; waiting for pong true (1465166928607/1465166929605); ProcessorID: 331