search

Terasology / SimpleFarming

Easy to understand growing of foods
11 stars 27 forks source link

Seeming infinite loop possible in one of the MTE tests? #97

Open Cervator opened 4 years ago

Cervator commented 4 years ago

This might be more about the MTE than any one test here, but I did see Jenkins trying to test a SimpleFarming PR twice in a row eventually get stuck just printing [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache over and over forever, apparently doing so as that logs once per tick, and nothing else was happening.

It might trigger based on the world seed causing something the MTE can't handle? As it seems to happen inconsistently. I've seen similar rare infinite loops elsewhere, will start trying to gather more details.

The test here resulted in this logging on pastebin

Snippet right as it started:

  15:59:51.016 [Test worker] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block CoreAssets:Stone with id 128
    15:59:51.017 [Test worker] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered BlockFamily[symmetric,CoreAssets:BigBrownShroom]
    15:59:51.017 [Test worker] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block CoreAssets:BigBrownShroom with id 129
    15:59:51.018 [Test worker] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered BlockFamily[freeform,CoreAssets:CoalOre]
    15:59:51.018 [Test worker] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block CoreAssets:CoalOre with id 130
    15:59:51.024 [Test worker] DEBUG org.terasology.engine.modes.StateLoading - ${engine:menu#catching-world}
    15:59:56.028 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Registering event handler org.terasology.rendering.nui.internal.NUIManagerInternal
    15:59:56.030 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Found method: public void org.terasology.rendering.nui.internal.NUIManagerInternal.mouseWheelEvent(org.terasology.input.events.MouseWheelEvent,org.terasology.entitySystem.entity.EntityRef)
    15:59:56.032 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Found method: public void org.terasology.rendering.nui.internal.NUIManagerInternal.mouseAxisEvent(org.terasology.input.events.MouseAxisEvent,org.terasology.entitySystem.entity.EntityRef)
    15:59:56.032 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Found method: public void org.terasology.rendering.nui.internal.NUIManagerInternal.mouseButtonEvent(org.terasology.input.events.MouseButtonEvent,org.terasology.entitySystem.entity.EntityRef)
    15:59:56.032 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Found method: public void org.terasology.rendering.nui.internal.NUIManagerInternal.bindEvent(org.terasology.input.BindButtonEvent,org.terasology.entitySystem.entity.EntityRef)
    15:59:56.033 [Test worker] DEBUG org.terasology.entitySystem.event.internal.EventSystemImpl - Found method: public void org.terasology.rendering.nui.internal.NUIManagerInternal.keyEvent(org.terasology.input.events.KeyEvent,org.terasology.entitySystem.entity.EntityRef)
    15:59:56.082 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:56.085 [Test worker] INFO org.terasology.logic.console.ConsoleImpl - [NOTIFICATION] Identity storage service: No configuration data is present, staying logged out.
    15:59:57.073 [Test worker] ERROR org.terasology.world.block.internal.BlockManagerImpl - Family not available: CoreBlocks:Dirt
    15:59:57.106 [Test worker] WARN org.terasology.engine.internal.TimeBase - Delta too great (1072), capping to 1000
    15:59:57.154 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.160 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.201 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.205 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.213 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.228 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.232 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.245 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    15:59:57.249 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache

Also maybe worth noting was the occasional chunk generator thread fail over some ore generation issue (which itself is a bit of a "huh" for SimpleFarming):

    16:00:04.520 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    16:00:04.527 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    16:00:04.532 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    16:00:04.534 [Chunk-Generator-2] ERROR org.terasology.utilities.concurrency.TaskProcessor - Error in thread Chunk-Generator-2
    java.lang.NullPointerException: null
        at org.terasology.oreGeneration.generation.PocketDensityOreGen.canReplaceBlock(PocketDensityOreGen.java:39)
        at org.terasology.oreGeneration.generation.OreRasterizer.generateChunk(OreRasterizer.java:52)
        at org.terasology.world.generation.WorldImpl.rasterizeChunk(WorldImpl.java:64)
        at org.terasology.world.generation.BaseFacetedWorldGenerator.createChunk(BaseFacetedWorldGenerator.java:75)
        at org.terasology.world.chunks.localChunkProvider.LocalChunkProvider$1.run(LocalChunkProvider.java:517)
        at org.terasology.utilities.concurrency.TaskProcessor.run(TaskProcessor.java:50)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
    16:00:04.534 [Chunk-Generator-7] ERROR org.terasology.utilities.concurrency.TaskProcessor - Error in thread Chunk-Generator-7
    java.lang.NullPointerException: null
        at org.terasology.oreGeneration.generation.PocketDensityOreGen.canReplaceBlock(PocketDensityOreGen.java:39)
        at org.terasology.oreGeneration.generation.OreRasterizer.generateChunk(OreRasterizer.java:52)
        at org.terasology.world.generation.WorldImpl.rasterizeChunk(WorldImpl.java:64)
        at org.terasology.world.generation.BaseFacetedWorldGenerator.createChunk(BaseFacetedWorldGenerator.java:75)
        at org.terasology.world.chunks.localChunkProvider.LocalChunkProvider$1.run(LocalChunkProvider.java:517)
        at org.terasology.utilities.concurrency.TaskProcessor.run(TaskProcessor.java:50)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
    16:00:04.538 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    16:00:04.541 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
    16:00:04.549 [Test worker] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache

Maybe the MTE test somehow gets stuck just trying to generate world forever and just once in a while that results in a chunk that fails due to ore gen?

keturn commented 4 years ago

“fixing” catastrophically failing tests by disabling them is scary. :grimacing:

Do we know what brought this on? i.e. did it start happening after a particular change in this module, or was it something in MTE or engine?

Cervator commented 4 years ago

Agreed on scary - but sadly before these tests broke this way they seemingly mostly broke in creative other ways so ... not really sure what happened when. There are a few clues in the older builds in Jenkins, perhaps, but I didn't dig around extensively

DarkWeird commented 4 years ago

Odd. it must take maximum 60+60+(60* waiter count) seconds. Also MTE didn't throw assert in one timeout case. Oh... waiters in loop 

@Test
 public void bushShouldGrowInOrder() { // <-- +120 seconds on setup test,
        for (int i = 0; i < getFinalGrowthStageIndex(); i++) {
            assertBushInStage(i);
            waitForGrowth(); // <-- +60 sec
        }
    }
Cervator commented 4 years ago

Oh boy. Yeah that would totally do it - if that test actually breaks in a particular way it'll just keep waiting forever rather than fail the assert ... 😅

Needs one of those little timeouts I think somebody mentioned are an option now!