Forums › English Language Forums › Technical › Technical Issues

Search

Client freezing after lagout; possible desync issues on reconnect (log included)

3 replies [Last post]
Mon, 09/16/2013 - 15:41
Warp-Master's picture
Warp-Master

I have a chronic, sporadic, yet annoyingly common issue where without warning my client's display will turn into a slideshow, display about 3 frames 2 seconds apart, then freeze while java.exe pegs whatever CPU it's running on at 100% CPU time. At this point, java.exe invariably needs killed. After reconnecting my character is usually stuck in place, rubberbanded in place, or stuck eternally re-enacting whatever commands I was issuing when the game froze. This invariably needs either a logout or extended GM assistance to clear up.

Here's a log of what this looks like from the game client's perspective:

2013/09/16 18:13:58:640 INFO J$a.b: Logging to 'C:\Program Files (x86)\Steam\steamapps\common\Spiral Knights\.\projectx.log'.
2013/09/16 18:14:07:465 INFO J$a.b: Steam initialized.
2013/09/16 18:14:11:650 INFO J$a.b: Connecting [host=game.spiralknights.com/184.73.171.156, port=47624]
2013/09/16 18:14:11:665 INFO DefaultControllerEnvironment.getControllers: Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
2013/09/16 18:14:12:035 INFO J$a.b: IME created [Thread=18]
2013/09/16 18:14:12:794 INFO J$a.b: Datagram connection established [port=47624]
2013/09/16 18:14:17:028 INFO J$a.b: Moving at request of server [zoneId=83886080, sceneId=2147483647]
2013/09/16 18:14:17:137 INFO J$a.b: Issuing zoned moveTo(5:0, 2147483647, 1).
2013/09/16 18:14:29:961 WARNING J$a.b: Long invoker unit [unit=News Reader (class com.threerings.projectx.client.cu), time=754ms].
2013/09/16 18:14:58:390 INFO J$a.b: Connecting [host=/184.73.171.156, port=47626]
2013/09/16 18:14:58:693 INFO J$a.b: Datagram connection established [port=47626]
2013/09/16 18:14:59:323 INFO J$a.b: Issuing zoned moveTo(2:346, 351, 64).
2013/09/16 18:14:59:378 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/16 18:16:02:741 INFO J$a.b: Moving at request of server [zoneId=33554432, sceneId=1073741890]
2013/09/16 18:16:02:746 INFO J$a.b: Issuing zoned moveTo(2:0, 1073741890, 0).
2013/09/16 18:16:03:069 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/16 18:16:03:309 INFO J$a.b: Got updated scene model [placeId=2578, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741890/%dungeon:m.candlestick_keep_vanilla_whipping_mishandling/1]
2013/09/16 18:30:15:301 INFO J$a.b: Moving at request of server [sceneId=1073741894]
2013/09/16 18:30:15:318 INFO J$a.b: Issuing moveTo(1073741894, 0).
2013/09/16 18:30:15:836 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/16 18:30:15:942 INFO J$a.b: Got updated scene model [placeId=2740, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741894/%dungeon:m.ct_fiend_whipping_mishandling/1]
2013/09/16 18:31:48:554 WARNING J$a.b: Frame index went negative! [anim=throw, fidx=-11, accum=-0.015999794, elapsed=-0.459, frames=-11]
2013/09/16 18:31:50:026 WARNING J$a.b: Frame index went negative! [anim=throw, fidx=-10, accum=-0.94400024, elapsed=-0.456, frames=-10]
2013/09/16 18:40:58:516 INFO J$a.b: Idle state changed. [idle=true]
2013/09/16 18:40:58:517 INFO J$a.b: Idle state changed. [idle=false]

(If it helps, I was throwing some Oil Pots at a Howlitzer before moving to engage Kats when the crash occurred.

Wed, 09/18/2013 - 16:43
#1
Warp-Master's picture
Warp-Master

After going through the logs, I've hypothesized that the issue that's causing this mess is linked to three log warnings: "Frame index went negative!", "Someone call Einstein! The clock is running backwards", and "ControllerEnvironment.log: Failed to poll device: Failed to poll device (8007000c)".

It would be nice if someone actually read this and did their job.

Wed, 09/18/2013 - 18:04
#2
Dead-Giveaway's picture
Dead-Giveaway
you're not the only one who

you're not the only one who thinks they should

Sat, 09/21/2013 - 10:25
#3
Warp-Master's picture
Warp-Master
More logging!

2013/09/21 12:22:07:396 INFO J$a.b: Logging to 'C:\Program Files (x86)\Steam\steamapps\common\Spiral Knights\.\projectx.log'.
2013/09/21 12:22:14:393 INFO J$a.b: Steam initialized.
2013/09/21 12:22:17:987 INFO J$a.b: Connecting [host=game.spiralknights.com/184.73.214.58, port=47624]
2013/09/21 12:22:18:019 INFO DefaultControllerEnvironment.getControllers: Loading: net.java.games.input.DirectAndRawInputEnvironmentPlugin
2013/09/21 12:22:18:150 INFO J$a.b: IME created [Thread=17]
2013/09/21 12:22:18:689 INFO J$a.b: Redirected to another node. [hostname=23.22.65.134, ports=(47624), datagramPorts=(47624)]
2013/09/21 12:22:18:691 INFO J$a.b: Connecting [host=/23.22.65.134, port=47624]
2013/09/21 12:22:19:634 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 12:22:19:703 INFO J$a.b: Datagram connection established [port=47624]
2013/09/21 12:22:19:996 INFO J$a.b: Issuing zoned moveTo(2:0, 1073741940, 0).
2013/09/21 12:22:21:014 INFO J$a.b: Got updated scene model [placeId=1664, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741940/%dungeon:m.lichenous_lair_poison_sewer_stash/1]
2013/09/21 12:25:04:658 INFO J$a.b: Submitting bug report 'Stuck with rubberband affect after client freeze; JRE7u40 32-bit'.
2013/09/21 12:34:12:086 INFO J$a.b: Moving at request of server [sceneId=1073741950]
2013/09/21 12:34:12:106 INFO J$a.b: Issuing moveTo(1073741950, 0).
2013/09/21 12:34:12:575 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 12:34:12:825 INFO J$a.b: Got updated scene model [placeId=1788, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741950/%dungeon:m.ww_construct_sewer_stash/1]
2013/09/21 12:59:29:980 INFO J$a.b: Moving at request of server [sceneId=1073741964]
2013/09/21 12:59:29:998 INFO J$a.b: Issuing moveTo(1073741964, 0).
2013/09/21 12:59:30:421 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 12:59:30:497 INFO J$a.b: Got updated scene model [placeId=1937, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741964/%dungeon:m.bp_ww_gremlin_sewer_stash/1]
2013/09/21 13:01:20:274 WARNING J$a.b: Frame index went negative! [anim=Open, fidx=-1, accum=-0.84800005, elapsed=-0.154, frames=-1]
2013/09/21 13:12:48:294 INFO J$a.b: Moving at request of server [zoneId=16777217, sceneId=3]
2013/09/21 13:12:48:504 INFO J$a.b: Issuing zoned moveTo(1:1, 3, 181).
2013/09/21 13:12:48:872 INFO J$a.b: Connecting [host=/23.22.65.134, port=47625]
2013/09/21 13:12:49:486 INFO J$a.b: Datagram connection established [port=47625]
2013/09/21 13:12:49:685 INFO J$a.b: Issuing zoned moveTo(1:1, 3, 181).
2013/09/21 13:12:50:030 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=15]
2013/09/21 13:14:29:539 INFO J$a.b: Moving at request of server [sceneId=2]
2013/09/21 13:14:30:899 INFO J$a.b: Issuing moveTo(2, 181).
2013/09/21 13:14:30:944 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=15]
2013/09/21 13:17:41:791 INFO J$a.b: Connecting [host=/107.22.9.103, port=47624]
2013/09/21 13:17:41:832 WARNING J$a.b: Unable to dispatch event on non-proxied object [DELTA:targetOid=4003, sourceOid=-1, transport=[type=UNRELIABLE_ORDERED, channel=0], sceneOid=557, acknowledge=14091987, ping=49, reference=14090898, timestamp=14091992, elapsed=53, addedActors=null, updatedActorDeltas=([class=com.threerings.tudey.data.actor.Agent, _translation=[11.528922, 8.507563]], [class=com.threerings.tudey.data.actor.Agent, _rotation=1.355989, _flags=8], [class=com.threerings.projectx.data.actor.Knight, _translation=[-26.838396, 4.3727756], _rotation=1.9452902, _flags=2, _direction=1.9452902, _activity=0, _activityStarted=14091524, _actionDesc=[], _actionEntity=[actorId=24], _description=[name=Shop/Haven/Spiral Quartermaster, arguments={}]], [class=com.threerings.tudey.data.actor.Agent, _translation=[-0.4543473, 15.227393], _maxStep=0.333], [class=com.threerings.projectx.data.actor.Knight, _activity=4, _activityStarted=14091276], [class=com.threerings.tudey.data.actor.Agent, _translation=[-7.749208, 14.277533], _maxStep=0.33299994], [class=com.threerings.projectx.data.actor.Knight, _translation=[-26.859264, 2.2528706], _rotation=-2.5479994, _flags=0], [class=com.threerings.projectx.dungeon.data.actor.Switch, _rotation=-2.6709037], [class=com.threerings.projectx.dungeon.data.actor.Switch, _rotation=-3.0051656], [class=com.threerings.projectx.dungeon.data.actor.Switch, _rotation=0.6180546], [class=com.threerings.projectx.dungeon.data.actor.Switch, _rotation=-1.7840403]), removedActorIds=null, effectsFired=null].
2013/09/21 13:17:42:486 INFO J$a.b: Datagram connection established [port=47624]
2013/09/21 13:17:42:805 INFO J$a.b: Issuing zoned moveTo(2:351, 356, 64).
2013/09/21 13:17:43:056 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 13:28:19:036 INFO J$a.b: Submitting bug report 'Sudden and inexplicable slowdown'.
2013/09/21 13:19:29:359 WARNING J$a.b: Someone call Einstein! The clock is running backwards [dt=-557245]
2013/09/21 13:19:43:356 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8235, accum=-0.6904297, elapsed=-550.229, frames=-8252]
2013/09/21 13:19:43:356 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8236, accum=-0.6904297, elapsed=-550.229, frames=-8252]
2013/09/21 13:19:43:357 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8214, accum=-0.4404297, elapsed=-550.229, frames=-8252]
2013/09/21 13:19:43:357 WARNING af.isLoggable: Previous message repeated 1 times.
2013/09/21 13:19:43:357 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8224, accum=-0.4404297, elapsed=-550.229, frames=-8252]
2013/09/21 13:19:43:358 WARNING J$a.b: Frame index went negative! [anim=hands_closed, fidx=-16506, accum=-0.13085938, elapsed=-550.229, frames=-16506]
2013/09/21 13:19:43:358 WARNING J$a.b: Frame index went negative! [anim=ready_sword, fidx=-16502, accum=-0.13085938, elapsed=-550.229, frames=-16506]
2013/09/21 13:19:43:359 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8222, accum=-0.78027344, elapsed=-550.229, frames=-8252]
2013/09/21 13:19:43:359 WARNING J$a.b: Frame index went negative! [anim=null, fidx=-8249, accum=-0.3408203, elapsed=-550.229, frames=-8253]

And then someone apparently joined my party while my client wasn't responding, I got logged out, and that fixed it somehow.

2013/09/21 13:21:36:443 INFO J$a.b: Connecting [host=game.spiralknights.com/184.73.214.58, port=47624]
2013/09/21 13:21:36:663 INFO J$a.b: Redirected to another node. [hostname=107.22.9.103, ports=(47624), datagramPorts=(47624)]
2013/09/21 13:21:36:664 INFO J$a.b: Connecting [host=/107.22.9.103, port=47624]
2013/09/21 13:21:37:396 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 13:21:37:437 INFO J$a.b: Datagram connection established [port=47624]
2013/09/21 13:21:37:629 INFO J$a.b: Issuing zoned moveTo(2:0, 1073741914, 0).
2013/09/21 13:21:37:863 INFO J$a.b: Updating outgoing message throttle [msgsPerSec=45]
2013/09/21 13:21:37:929 INFO J$a.b: Got updated scene model [placeId=1673, config=[type=data.LevelSceneConfig, aAi=null, aAj=true], scene=1073741914/%dungeon:m.cc_undead/1]

And then my character got stuck in the "on elevator" pose.

Powered by Drupal, an open source content management system