Skip to content
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

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

Open
Cervator opened this issue Sep 6, 2020 · 4 comments
Open

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

Cervator opened this issue Sep 6, 2020 · 4 comments
Labels
Type: Bug Issues reporting and PRs fixing problems

Comments

@Cervator
Copy link
Member

Cervator commented Sep 6, 2020

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
Copy link
Contributor

keturn commented Sep 6, 2020

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

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
Copy link
Member Author

Cervator commented Sep 7, 2020

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
Copy link
Contributor

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
Copy link
Member Author

Cervator commented Sep 7, 2020

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!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Bug Issues reporting and PRs fixing problems
Projects
None yet
Development

No branches or pull requests

3 participants