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

Guard against infinite loops - add timeout somehow if a test gets stuck? #25

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

Comments

@Cervator
Copy link
Member

Cervator commented Sep 6, 2020

Specific example: Terasology/SimpleFarming#97

One theory is something goes weird and the MTE test just keeps generating chunks forever, which prints one of those log snippets about compacting the chunk cache every tick, which might be the only indication that something is still happening, otherwise it would just appear to hang.

I've seen similar cases elsewhere. For instance http://jenkins.terasology.io/teraorg/job/Terasology/job/engine/view/change-requests/job/PR-4036/ related to MovingBlocks/Terasology#4036 for some reason got stuck several times for hours on end. One example printed this a bunch (although not nearly as much as the SimpleFarming PR):

11:50:39.535 [Test worker] ERROR o.t.w.b.internal.BlockManagerImpl - Attempt to fetch block with unknown uri 'engine:air'

It may not be an issue specific to the MTE, could be some underlying issue with environment-based tests. Not sure which actual test stalls for SimpleFarming, although the engine one is StorageManagerTest extends TerasologyTestingEnvironment so yeah not MTE, but maybe both hit that environment class?

@4Denthusiast
Copy link
Collaborator

If BlockManagerImpl doesn't have engine:air loaded, when it fails to retreive something, it'll try to return air as a default, then fail to retreive that, then try to return air as a default, and so on. This isn't a problem under ordinary circumstances, but during tests where the block assets are listed explicitly, it might be missed. It might be better to catch that error earlier at least.

@Cervator
Copy link
Member Author

Cervator commented Oct 4, 2020

Saw another case of an MTE test getting stuck, this time in Rails, with a bit more maybe-interesting logging (I've snipped some "compacting cache" blocks - after this stage it just gets worse with the same stuff and eventually shows nothing else):

22:17:16.622 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered BlockFamily[symmetric,engine:air]
22:17:16.622 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block engine:air with id 2
22:17:16.626 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered BlockFamily[freeform,CoreAssets:Dirt]
22:17:16.626 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block CoreAssets:Dirt with id 3
22:17:16.654 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered BlockFamily[rails,rails:rails]
22:17:16.654 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.50 with id 4
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.38 with id 5
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.36 with id 6
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.34 with id 7
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.33 with id 8
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.32 with id 9
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.52 with id 10
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.22 with id 11
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.20 with id 12
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.18 with id 13
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.17 with id 14
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.16 with id 15
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.54 with id 16
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.6 with id 17
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.5 with id 18
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.4 with id 19
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.3 with id 20
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.2 with id 21
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.48 with id 22
22:17:16.655 [main] INFO org.terasology.world.block.internal.BlockManagerImpl - Registered Block rails:rails.0 with id 23
22:17:16.691 [main] WARN org.terasology.engine.internal.TimeBase - Delta too great (2874), capping to 1000
22:17:16.694 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
...
22:17:17.002 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.033 [Chunk-Processing-5] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -2, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.035 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.068 [Chunk-Processing-1] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -1, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.068 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.071 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.072 [Chunk-Processing-2] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -1, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.072 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.073 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.074 [Chunk-Processing-3] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, 0, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.076 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.079 [Chunk-Processing-6] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -1, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.081 [Chunk-Processing-4] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -1, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.084 [Chunk-Processing-0] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -1, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.085 [Chunk-Processing-7] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -1, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.086 [Chunk-Processing-5] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -2, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.093 [Chunk-Processing-2] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -1, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.094 [Chunk-Processing-1] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, 0, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.099 [Chunk-Processing-3] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -2, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.107 [Chunk-Processing-6] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, 0, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.107 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.108 [Chunk-Processing-4] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -2, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.109 [Chunk-Processing-7] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -1, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.111 [Chunk-Processing-5] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, -2, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.111 [Chunk-Processing-0] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -1, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.116 [Chunk-Processing-3] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, 0, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.117 [Chunk-Processing-2] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, 0, -1): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.118 [Chunk-Processing-1] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-1, 0, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.123 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.125 [Chunk-Processing-4] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, 0, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.125 [Chunk-Processing-6] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -2, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.126 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.127 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.127 [Chunk-Processing-5] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -2, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.127 [Chunk-Processing-7] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, -2, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.128 [Chunk-Processing-0] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, 0, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.129 [Chunk-Processing-3] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (-2, 0, 0): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.129 [Chunk-Processing-2] DEBUG org.terasology.world.chunks.internal.ChunkImpl - chunk (0, -2, -2): size-before: 327,744 bytes, size-after: 131,123 bytes, total-deflated-by: 59.99%, blocks-deflated-by=99.99%, light-deflated-by=99.99%, extra-data-deflated-by=�%
22:17:17.129 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
...
22:17:17.183 [main] DEBUG org.terasology.world.chunks.localChunkProvider.LocalChunkProvider - Compacting cache
22:17:17.195 [Chunk-Processing-1] WARN org.terasology.world.propagation.LocalChunkView - Position is out of chunks
22:17:17.195 [Chunk-Processing-1] WARN org.terasology.world.propagation.LocalChunkView - Position is out of chunks
22:17:17.195 [Chunk-Processing-1] WARN org.terasology.world.propagation.LocalChunkView - Position is out of chunks

@keturn
Copy link
Contributor

keturn commented Mar 21, 2021

I tried to do this at the Jupiter configuration level in MovingBlocks/Terasology#4579

Even though I thought I confirmed it would cancel tests (I set it to a very short value to check), it's been ineffective when I ran in to stalling ItemPipes tests in real test runs.

Don't know if I goofed up the configuration somehow, or if there's something specific about the way those tests get stuck that make Jupiter's methods unsuccessful.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants