New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crash on light merging when on multiplayer #1969

Closed
Josharias opened this Issue Oct 10, 2015 · 6 comments

Comments

Projects
None yet
2 participants
@Josharias
Contributor

Josharias commented Oct 10, 2015

I was walking around when this happened:

https://gist.github.com/Josharias/05e8b859e87594cadd39

@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Oct 11, 2015

Member

Should be able to try the latest Omega after the current engine build finishes and connect to the server to retest and hopefully reproduce this with more logging.

Should still work with the listed server as no version info has changed.

Member

Cervator commented Oct 11, 2015

Should be able to try the latest Omega after the current engine build finishes and connect to the server to retest and hopefully reproduce this with more logging.

Should still work with the listed server as no version info has changed.

@Cervator Cervator added the Bug label Oct 11, 2015

@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Oct 31, 2015

Member

Oho, interesting update in the forum: http://forum.terasology.org/threads/game-crashes.1402/

Hit the same error and it looks like the log is expanded!

http://pastebin.com/sGhD08qK

16:55:35.099 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (2589), capping to 1000
16:55:45.146 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 4262, netId = 125, prefab = 'engine:blockItemPickup'}
16:57:02.886 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.RuntimeException: Error completing lighting merge
        at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:79) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.completeUpdate(RemoteChunkProvider.java:268) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.RenderableWorldImpl.update(RenderableWorldImpl.java:164) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:271) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:289) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.modes.StateIngame.render(StateIngame.java:211) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:187) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:423) ~[engine-0.54.3.jar:59, origin/master, 59]
        at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) ~[engine-0.54.3.jar:59, origin/master, 59]
        at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:59, origin/master, 59]
Caused by: java.util.concurrent.ExecutionException: java.lang.NullPointerException
        at java.util.concurrent.FutureTask.report(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.FutureTask.get(Unknown Source) ~[na:1.8.0_65]
        at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:75) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        ... 9 common frames omitted
Caused by: java.lang.NullPointerException: null
        at org.terasology.world.chunks.internal.ChunkImpl.getLight(ChunkImpl.java:264) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightPropagationRules.getValue(LightPropagationRules.java:50) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.StandardBatchPropagator.propagateSide(StandardBatchPropagator.java:297) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.StandardBatchPropagator.propagateBetween(StandardBatchPropagator.java:248) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger.merge(LightMerger.java:119) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger.access$000(LightMerger.java:44) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger$1.call(LightMerger.java:66) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at java.util.concurrent.FutureTask.run(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_65]
        at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_65]
16:57:02.887 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
16:57:02.898 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
Member

Cervator commented Oct 31, 2015

Oho, interesting update in the forum: http://forum.terasology.org/threads/game-crashes.1402/

Hit the same error and it looks like the log is expanded!

http://pastebin.com/sGhD08qK

16:55:35.099 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (2589), capping to 1000
16:55:45.146 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 4262, netId = 125, prefab = 'engine:blockItemPickup'}
16:57:02.886 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.RuntimeException: Error completing lighting merge
        at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:79) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.completeUpdate(RemoteChunkProvider.java:268) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.RenderableWorldImpl.update(RenderableWorldImpl.java:164) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:271) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:289) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.modes.StateIngame.render(StateIngame.java:211) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:187) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:423) ~[engine-0.54.3.jar:59, origin/master, 59]
        at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) ~[engine-0.54.3.jar:59, origin/master, 59]
        at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:59, origin/master, 59]
Caused by: java.util.concurrent.ExecutionException: java.lang.NullPointerException
        at java.util.concurrent.FutureTask.report(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.FutureTask.get(Unknown Source) ~[na:1.8.0_65]
        at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:75) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        ... 9 common frames omitted
Caused by: java.lang.NullPointerException: null
        at org.terasology.world.chunks.internal.ChunkImpl.getLight(ChunkImpl.java:264) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightPropagationRules.getValue(LightPropagationRules.java:50) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.StandardBatchPropagator.propagateSide(StandardBatchPropagator.java:297) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.StandardBatchPropagator.propagateBetween(StandardBatchPropagator.java:248) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger.merge(LightMerger.java:119) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger.access$000(LightMerger.java:44) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at org.terasology.world.propagation.light.LightMerger$1.call(LightMerger.java:66) ~[engine-0.54.3.jar:59, master, 59, pre-alpha]
        at java.util.concurrent.FutureTask.run(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_65]
        at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_65]
16:57:02.887 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
16:57:02.898 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Dec 17, 2015

Member

Still a thing. Just happened on @minnesotags' server, with JoshariasSurvival + Caves active. Had crashed once previously (#2067). Had delved deep in a big cave system with only a few trusted torches, both held and thrown (and further back placed). Also noted multiple chunk loads mentioned a lot earlier in the log (much more than in the snippet below):

23:57:35.164 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-3, -2, -4)
23:57:35.204 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (4, -2, -4)
23:57:35.291 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 0, -4)
23:57:35.345 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, -1, -4)
23:57:35.393 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, 1, -4)
23:57:35.445 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -1, -4)
23:57:35.502 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 1, -4)
23:57:35.562 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, 2, -4)
23:57:35.576 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, -2, -4)
23:57:35.649 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -2, -4)
23:57:35.704 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 2, -4)
23:58:59.591 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 62989, netId = 2294}
23:59:00.796 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63000, netId = 2295}
23:59:03.303 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63016, netId = 2298}
23:59:03.352 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63018, netId = 2299, prefab = 'engine:blockItemBase'}
23:59:03.352 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63019, netId = 2300, prefab = 'engine:blockItemPickup'}
23:59:05.840 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63035, netId = 2301}
23:59:08.348 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63050, netId = 2304}
23:59:08.386 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63053, netId = 2306, prefab = 'engine:blockItemPickup'}
23:59:08.387 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63052, netId = 2305, prefab = 'engine:blockItemBase'}
23:59:10.844 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63067, netId = 2307}
23:59:13.549 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63097, netId = 2311}
23:59:15.331 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63106, netId = 2312}
23:59:16.035 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63086, netId = 2310}
23:59:16.442 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63109, netId = 2314, prefab = 'engine:blockItemPickup'}
23:59:18.896 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63123, netId = 2315}
23:59:19.382 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63140, netId = 2316}
23:59:21.929 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63157, netId = 2319}
23:59:21.988 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63160, netId = 2321, prefab = 'engine:blockItemPickup'}
23:59:21.989 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63159, netId = 2320, prefab = 'engine:blockItemBase'}
23:59:24.553 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63175, netId = 2322}
23:59:26.983 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63189, netId = 2325}
23:59:29.445 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63204, netId = 2328}
23:59:32.149 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63221, netId = 2331}
23:59:56.903 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.RuntimeException: Error completing lighting merge
    at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:78) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.completeUpdate(RemoteChunkProvider.java:268) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.RenderableWorldImpl.update(RenderableWorldImpl.java:164) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:267) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:285) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:189) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:423) ~[engine-0.54.5.jar:62, origin/master, 62]
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) ~[engine-0.54.5.jar:62, origin/master, 62]
    at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:62, origin/master, 62]
Caused by: java.util.concurrent.ExecutionException: java.lang.NullPointerException
    at java.util.concurrent.FutureTask.report(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.FutureTask.get(Unknown Source) ~[na:1.8.0_45]
    at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:74) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    ... 9 common frames omitted
Caused by: java.lang.NullPointerException: null
    at org.terasology.world.chunks.internal.ChunkImpl.getLight(ChunkImpl.java:263) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightPropagationRules.getValue(LightPropagationRules.java:49) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.StandardBatchPropagator.propagateSide(StandardBatchPropagator.java:296) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.StandardBatchPropagator.propagateBetween(StandardBatchPropagator.java:247) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger.merge(LightMerger.java:118) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger.access$000(LightMerger.java:43) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger$1.call(LightMerger.java:65) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at java.util.concurrent.FutureTask.run(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_45]
    at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_45]
23:59:56.904 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
23:59:56.913 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
23:59:56.928 [main] WARN  org.reflections.Reflections - given scan urls are empty. set urls in the configuration
23:59:57.239 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'emptyIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UIIconBar","id":"breathBar","icon":"engine:icons#bubble","family":"breathBar","emptyIcon":"engine:icons#burstBubble","halfIconMode":"shrink","spacing":2,"maxIcons":10,"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-left":{"target":"CENTER"},"position-right":{"target":"RIGHT","widget":"toolbar"},"position-bottom":{"target":"TOP","widget":"toolbar","offset":1}}}
23:59:57.240 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'crosshairIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UICrosshair","id":"crosshair","crosshairIcon":"engine:gui#crosshair","chargeStages":["engine:gui#crosshairCharge1","engine:gui#crosshairCharge2","engine:gui#crosshairCharge3","engine:gui#crosshairCharge4","engine:gui#crosshairCharge5","engine:gui#crosshairCharge6","engine:gui#crosshairCharge7","engine:gui#crosshairCharge8"],"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-horizontal-center":{},"position-vertical-center":{}}}

Logged back in after and all was well, no item loss, thrown torches still on the floor nearby.

Member

Cervator commented Dec 17, 2015

Still a thing. Just happened on @minnesotags' server, with JoshariasSurvival + Caves active. Had crashed once previously (#2067). Had delved deep in a big cave system with only a few trusted torches, both held and thrown (and further back placed). Also noted multiple chunk loads mentioned a lot earlier in the log (much more than in the snippet below):

23:57:35.164 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-3, -2, -4)
23:57:35.204 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (4, -2, -4)
23:57:35.291 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 0, -4)
23:57:35.345 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, -1, -4)
23:57:35.393 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, 1, -4)
23:57:35.445 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -1, -4)
23:57:35.502 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 1, -4)
23:57:35.562 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, 2, -4)
23:57:35.576 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-5, -2, -4)
23:57:35.649 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -2, -4)
23:57:35.704 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 2, -4)
23:58:59.591 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 62989, netId = 2294}
23:59:00.796 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63000, netId = 2295}
23:59:03.303 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63016, netId = 2298}
23:59:03.352 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63018, netId = 2299, prefab = 'engine:blockItemBase'}
23:59:03.352 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63019, netId = 2300, prefab = 'engine:blockItemPickup'}
23:59:05.840 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63035, netId = 2301}
23:59:08.348 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63050, netId = 2304}
23:59:08.386 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63053, netId = 2306, prefab = 'engine:blockItemPickup'}
23:59:08.387 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63052, netId = 2305, prefab = 'engine:blockItemBase'}
23:59:10.844 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63067, netId = 2307}
23:59:13.549 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63097, netId = 2311}
23:59:15.331 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63106, netId = 2312}
23:59:16.035 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63086, netId = 2310}
23:59:16.442 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63109, netId = 2314, prefab = 'engine:blockItemPickup'}
23:59:18.896 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63123, netId = 2315}
23:59:19.382 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63140, netId = 2316}
23:59:21.929 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63157, netId = 2319}
23:59:21.988 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63160, netId = 2321, prefab = 'engine:blockItemPickup'}
23:59:21.989 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63159, netId = 2320, prefab = 'engine:blockItemBase'}
23:59:24.553 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63175, netId = 2322}
23:59:26.983 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63189, netId = 2325}
23:59:29.445 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63204, netId = 2328}
23:59:32.149 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 63221, netId = 2331}
23:59:56.903 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.RuntimeException: Error completing lighting merge
    at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:78) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.completeUpdate(RemoteChunkProvider.java:268) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.RenderableWorldImpl.update(RenderableWorldImpl.java:164) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:267) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:285) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:189) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:423) ~[engine-0.54.5.jar:62, origin/master, 62]
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) ~[engine-0.54.5.jar:62, origin/master, 62]
    at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:62, origin/master, 62]
Caused by: java.util.concurrent.ExecutionException: java.lang.NullPointerException
    at java.util.concurrent.FutureTask.report(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.FutureTask.get(Unknown Source) ~[na:1.8.0_45]
    at org.terasology.world.propagation.light.LightMerger.completeMerge(LightMerger.java:74) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    ... 9 common frames omitted
Caused by: java.lang.NullPointerException: null
    at org.terasology.world.chunks.internal.ChunkImpl.getLight(ChunkImpl.java:263) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightPropagationRules.getValue(LightPropagationRules.java:49) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.StandardBatchPropagator.propagateSide(StandardBatchPropagator.java:296) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.StandardBatchPropagator.propagateBetween(StandardBatchPropagator.java:247) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger.merge(LightMerger.java:118) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger.access$000(LightMerger.java:43) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at org.terasology.world.propagation.light.LightMerger$1.call(LightMerger.java:65) ~[engine-0.54.5.jar:62, master, 62, pre-alpha]
    at java.util.concurrent.FutureTask.run(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_45]
    at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_45]
23:59:56.904 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
23:59:56.913 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
23:59:56.928 [main] WARN  org.reflections.Reflections - given scan urls are empty. set urls in the configuration
23:59:57.239 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'emptyIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UIIconBar","id":"breathBar","icon":"engine:icons#bubble","family":"breathBar","emptyIcon":"engine:icons#burstBubble","halfIconMode":"shrink","spacing":2,"maxIcons":10,"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-left":{"target":"CENTER"},"position-right":{"target":"RIGHT","widget":"toolbar"},"position-bottom":{"target":"TOP","widget":"toolbar","offset":1}}}
23:59:57.240 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'crosshairIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UICrosshair","id":"crosshair","crosshairIcon":"engine:gui#crosshair","chargeStages":["engine:gui#crosshairCharge1","engine:gui#crosshairCharge2","engine:gui#crosshairCharge3","engine:gui#crosshairCharge4","engine:gui#crosshairCharge5","engine:gui#crosshairCharge6","engine:gui#crosshairCharge7","engine:gui#crosshairCharge8"],"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-horizontal-center":{},"position-vertical-center":{}}}

Logged back in after and all was well, no item loss, thrown torches still on the floor nearby.

@Cervator Cervator added the Rendering label Dec 17, 2015

@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Jan 12, 2016

Member

Grabbed this from the IRC log, seemed like it would be good to save for this :-) Thanks gamemanj!

IRC log (gamemanj):
https://docs.google.com/uc?id=0B5l2RT_UOCXRUWVMTzFkLWluYms&export=download
there is only one reason lightData becomes null, and that's if dispose() gets called...
and you have concurrency going on...
with a dispose method without any form of mutex or such to prevent this...
no mutex, but lighting is done on another thread. What could possibly go wrong...: https://github.com/MovingBlocks/Terasology/blob/fadf43ec1cb321a6cd34ed29a656d025df70d98c/engine/src/main/java/org/terasology/world/chunks/internal/ChunkImpl.java#L539
note: the reason I'm pointing at a given tree is because that's the tree of the version the error came from
ah
something seems quite odd here
this seems a similar issue, but it says about a merged PR that adds a lock https://github.com/MovingBlocks/Terasology/issues/789
ok, so it has a lock, but nobody thought to add it on the dispose()
though I guess dispose() should theoretically only be called after nobody's using it, in practice that doesn't quite seem to have happened
I conclude that concurrency is hell
Member

Cervator commented Jan 12, 2016

Grabbed this from the IRC log, seemed like it would be good to save for this :-) Thanks gamemanj!

IRC log (gamemanj):
https://docs.google.com/uc?id=0B5l2RT_UOCXRUWVMTzFkLWluYms&export=download
there is only one reason lightData becomes null, and that's if dispose() gets called...
and you have concurrency going on...
with a dispose method without any form of mutex or such to prevent this...
no mutex, but lighting is done on another thread. What could possibly go wrong...: https://github.com/MovingBlocks/Terasology/blob/fadf43ec1cb321a6cd34ed29a656d025df70d98c/engine/src/main/java/org/terasology/world/chunks/internal/ChunkImpl.java#L539
note: the reason I'm pointing at a given tree is because that's the tree of the version the error came from
ah
something seems quite odd here
this seems a similar issue, but it says about a merged PR that adds a lock https://github.com/MovingBlocks/Terasology/issues/789
ok, so it has a lock, but nobody thought to add it on the dispose()
though I guess dispose() should theoretically only be called after nobody's using it, in practice that doesn't quite seem to have happened
I conclude that concurrency is hell
@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Feb 15, 2016

Member

Posting just to keep this active live - still happens. Ran into it with local multiplayer testing on a plain Core world.

Member

Cervator commented Feb 15, 2016

Posting just to keep this active live - still happens. Ran into it with local multiplayer testing on a plain Core world.

@Cervator Cervator modified the milestones: Alpha 5, Playability Oct 7, 2016

@Cervator

This comment has been minimized.

Show comment
Hide comment
@Cervator

Cervator Oct 7, 2016

Member

Going to close this finally as hopefully fixed. We have not seen this for a while now, and there have been changes in the area.

Member

Cervator commented Oct 7, 2016

Going to close this finally as hopefully fixed. We have not seen this for a while now, and there have been changes in the area.

@Cervator Cervator closed this Oct 7, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment