Page MenuHomeSchine - Phabricator

Starmade | Frequent reconnects results in hung player session, unable to kick, and error [SERVER] Exception (CRITICAL)
Open, HighPublic

Description

QUESTION: Is there a way to leverage NT_SPAM_PROTECT_TIME_MS and/or NT_SPAM_PROTECT_MAX_ATTEMPTS to at least temporarily block, hinder, or otherwise delay reconnect patterns like this?

DESCRIPTION:
Player "frequently" reconnects (apparent networking issue on their end, as server had no issues with other players coming, staying and/or going during this time).

[2016-05-08 16:29:16] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:29:16] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462724768268] -> protected = true
[2016-05-08 16:29:16] [LOGIN] logged in RegisteredClient: Exitar (73) [vulsilthur]connected: true (/109.240.88.111:9190)
[2016-05-08 16:32:02] [DISCONNECT] Client 'RegisteredClient: Exitar (73) [vulsilthur]connected: true' IP(/109.240.88.111:9190) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 539
[2016-05-08 16:32:02] [LOGOUT] logging out client ID RegisteredClient: Exitar (73) [vulsilthur]connected: true
[2016-05-08 16:32:15] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:32:16] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462724956575] -> protected = true
[2016-05-08 16:32:16] [LOGIN] logged in RegisteredClient: Exitar (75) [vulsilthur]connected: true (/109.240.88.111:9202)
[2016-05-08 16:33:09] [DISCONNECT] Client 'RegisteredClient: Exitar (75) [vulsilthur]connected: true' IP(/109.240.88.111:9202) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 546
[2016-05-08 16:33:09] [LOGOUT] logging out client ID RegisteredClient: Exitar (75) [vulsilthur]connected: true
[2016-05-08 16:39:54] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:39:55] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462725136004] -> protected = true
[2016-05-08 16:39:55] [LOGIN] logged in RegisteredClient: Exitar (79) [vulsilthur]connected: true (/109.240.88.111:9392)
[2016-05-08 16:41:59] [SPAWN] Exitar spawned new ship: "exitur"
[2016-05-08 16:47:17] [DISCONNECT] Client 'RegisteredClient: Exitar (79) [vulsilthur]connected: true' IP(/109.240.88.111:9392) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 563
[2016-05-08 16:47:18] [LOGOUT] logging out client ID RegisteredClient: Exitar (79) [vulsilthur]connected: true
[2016-05-08 16:47:41] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:47:41] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462725595369] -> protected = true
[2016-05-08 16:47:41] [LOGIN] logged in RegisteredClient: Exitar (82) [vulsilthur]connected: true (/109.240.88.111:9424)
[2016-05-08 16:49:11] [DISCONNECT] Client 'RegisteredClient: Exitar (82) [vulsilthur]connected: true' IP(/109.240.88.111:9424) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 579
[2016-05-08 16:49:11] [LOGOUT] logging out client ID RegisteredClient: Exitar (82) [vulsilthur]connected: true
[2016-05-08 16:55:09] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:55:10] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462726061860] -> protected = true
[2016-05-08 16:55:10] [LOGIN] logged in RegisteredClient: Exitar (85) [vulsilthur]connected: true (/109.240.88.111:9480)
[2016-05-08 16:55:58] [DISCONNECT] Client 'RegisteredClient: Exitar (85) [vulsilthur]connected: true' IP(/109.240.88.111:9480) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 595
[2016-05-08 16:55:58] [LOGOUT] logging out client ID RegisteredClient: Exitar (85) [vulsilthur]connected: true
[2016-05-08 16:56:31] [AUTH] authenticating Exitar; useAuth: true; requireAuth: true
[2016-05-08 16:56:32] [AUTH] Protection status of Exitar is ProtectedUplinkName [username=vulsilthur, timeProtected=1462726510118] -> protected = true
[2016-05-08 16:56:32] [LOGIN] logged in RegisteredClient: Exitar (87) [vulsilthur]connected: true (/109.240.88.111:9493)
[2016-05-08 16:57:15] [DISCONNECT] Client 'RegisteredClient: Exitar (87) [vulsilthur]connected: true' IP(/109.240.88.111:9493) HAS BEEN DISCONNECTED . PROBE: false; ProcessorID: 597
[2016-05-08 16:57:15] [LOGOUT] logging out client ID RegisteredClient: Exitar (87) [vulsilthur]connected: true

Eventually, server hangs one of their login sessions, reports 0ms latency via [TAB], and player cannot be kicked. Server also spams logs with error:

[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:13] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:14] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:15] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:16] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:17] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:18] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:18] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:18] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:18] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)
[2016-05-08 19:20:18] [SERVER] Exception (CRITICAL) player PlS[Exitar [vulsilthur]; id(17337)(67)f(0)] is in an unloaded sector (17338) attempting reload of (2, 86, 2)

Above log entry was pruned to focus only on the player's name, and illustrate frequency of log entries. Other related entry, shown everyt was:

[2016-05-08 19:21:13] [SERVER] reloaded sector successfully. overwriting sector ids to 18729

Once every 10 seconds (SECTOR_INACTIVE_TIMEOUT=10), we also saw the message:

[2016-05-08 19:21:02] [SERVER] SERVER SECTOR WRITING STARTED #18729 active: true at (2, 86, 2) (ents: 0)

Server restart is the only cure.

Other symptom was that while player was logged-in, their faction homebase showed an empty sector. I observed an empty sector when visiting just prior to the restart. After restart, sector was populated with player's spawned station, but entities were associated with "unknown faction". Still checking with player on status of that faction.

Details

Task Type
Bug
Testing Results
Affected Gamemode(s)
none/unspecified
Reproducible
uncertain
Category
none/unspecified
Hardware/Software/System
OS-Specific
No
Hardware-Specific
No
Video Card Vendor
uncertain
Steps to reproduce

Excessively relog.

Serverconfig (server.cfg)
<replace this line with the file content>
Clientconfig (settings.cfg)
<replace this line with the file content>

Event Timeline

Restricted Application added a project: Issue Navigation. · View Herald TranscriptMay 8 2016, 8:51 PM
erthparadine updated the task description. (Show Details)May 8 2016, 8:57 PM
AndyP shifted this object from the S1 Public space to the S3 Starmade space.Jul 5 2016, 3:02 PM
AndyP changed the visibility from "Custom Policy" to "Public (No Login Required)".
AndyP changed the edit policy from "Task Author" to "Starmade (Project)".
AndyP claimed this task.
Restricted Application added a project: Starmade. · View Herald TranscriptJul 5 2016, 3:03 PM
AndyP added a subscriber: AndyP.
AndyP removed AndyP as the assignee of this task.
AndyP triaged this task as High priority.

-Validated-