search

MovingBlocks / Terasology

Terasology - open source voxel world
http://terasology.org
Apache License 2.0
3.66k stars 1.33k forks source link

Game crash from OpenAL buffer unqueue - invalid value #2940

Open Cervator opened 7 years ago

Cervator commented 7 years ago

May be difficult to analyze, but maybe we can improve the logging.

Happened to @arpan98 and I think I've seen another OpenAL crash in the recent few months, but it seems so vague and inconsistent I'm not sure what to do with it. Maybe it relates to having a large amount of concurrent audio sources? We were in multiplayer with several players around, a ton of deer walking (triggering footstep sfx), and so on.

Full log at: https://pastebin.com/qDrWbMkG

Snippet:

23:59:13.518 [main] INFO  o.t.logic.console.ConsoleImpl - [CHAT] Cervator: sometimes we make tweaks but then later completely overhaul a system which then changes everything
23:59:18.013 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
org.terasology.audio.openAL.OpenALException: OpenAL Error (40963) at Buffer unqueue - Invalid Value
    at org.terasology.audio.openAL.streamingSound.OpenALStreamingSoundSource.update(OpenALStreamingSoundSource.java:80)
    at org.terasology.audio.openAL.BaseSoundPool.lambda$update$360(BaseSoundPool.java:114)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
    at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1548)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
    at org.terasology.audio.openAL.BaseSoundPool.update(BaseSoundPool.java:114)
    at org.terasology.audio.openAL.OpenALManager.update(OpenALManager.java:263)
    at org.terasology.engine.subsystem.lwjgl.LwjglAudio.postUpdate(LwjglAudio.java:64)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:438)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:394)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:370)
    at org.terasology.engine.Terasology.main(Terasology.java:153)
23:59:18.014 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
23:59:18.167 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
Cervator commented 7 years ago

Happened a second time, for @0shine0 this time - so probably a game issue rather than OpenAL itself.

https://pastebin.com/vVQ1nDgs

It happened after a bunch of dwarf hall requests to Gooey. That causes particle effects each time for sure, I am not sure if maybe it causes sfx? Or maybe just some heavy processing for a moment

Cervator commented 7 years ago

Noticed this was reported during Alpha 7 testing as well (by me, no wonder it seemed familiar) as well: https://github.com/MovingBlocks/Terasology/issues/2766#issuecomment-284208798

So maybe it is an issue we can try to find a way to address.

Cervator commented 6 years ago

Still happening, random report via IRC. Unclear what the user was doing but supposedly just standing around not moving, maybe in JS with skill training going.

This seems to be a rare but not very picky issue about environment. Maybe just a rare bug in OpenAL itself? Or a rare game condition the related logic can't handle.

No real reason this should be a fatal issue, we could probably try to catch that specific exception and attempt to gracefully recover and continue.

11:33:42.722 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
org.terasology.audio.openAL.OpenALException: OpenAL Error (40963) at Buffer unqueue - Invalid Value
    at org.terasology.audio.openAL.streamingSound.OpenALStreamingSoundSource.update(OpenALStreamingSoundSource.java:80)
    at org.terasology.audio.openAL.BaseSoundPool.lambda$update$65(BaseSoundPool.java:114)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
    at java.util.HashMap$KeySpliterator.forEachRemaining(Unknown Source)
    at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at org.terasology.audio.openAL.BaseSoundPool.update(BaseSoundPool.java:114)
    at org.terasology.audio.openAL.OpenALManager.update(OpenALManager.java:278)
    at org.terasology.engine.subsystem.lwjgl.LwjglAudio.postUpdate(LwjglAudio.java:64)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:444)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:400)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:376)
    at org.terasology.engine.Terasology.main(Terasology.java:153)
11:33:42.724 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
Cervator commented 6 years ago

A slight variant of this just happened to me while merging entirely unrelated PRs locally in a mega-workspace. Even on just loading the game during OpenAL initialization my Java hard crashed. I had music running off Soundcloud in a Chrome window, no other known sound sources at the moment. It may have also happened right around as I moved focus away from IntelliJ but that seems less likely to matter.

Next game execution with no changes at all worked fine. I wonder if these intermittent issues would go away with a later version of OpenAL

...
18:27:23.020 [main] INFO  o.t.audio.openAL.OpenALManager - Initializing OpenAL audio manager
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x00000000226e1066, pid=7060, tid=0x0000000000002d68
#
# JRE version: Java(TM) SE Runtime Environment (8.0_112-b15) (build 1.8.0_112-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.112-b15 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C  [OpenAL64.dll+0x11066]
#
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# An error report file with more information is saved as:
# C:\Dev\Terasology\Git\ModuleMegaWorkspace\Terasology\hs_err_pid7060.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#
AL lib: (EE) alc_cleanup: 1 device not closed

Process finished with exit code 1

The dump file that came along with it is embedded at https://gist.github.com/Cervator/9a85f1630a61920d63fa391466fcab63

mkienenb commented 6 years ago

Happened to me during Omega multiplayer test.

https://pastebin.com/8qjdWCwP

keturn commented 5 years ago

Fixed or otherwise no longer relevant, you say?

https://drive.google.com/uc?id=1tfnO7-fKyFVoKDmIb7_7AOwBPpwP8nqv&export=download

Cervator commented 5 years ago

Heya @keturn - yeah the "no longer relevant" part within the context of notable Alpha 9 issues, yes :-)

Good part is that this seems relatively rare, but is a definite issue. Hoping a later upgrade of underlying libraries will make it go away.

Just hit it once more myself. Had two different games running and Terasology with music active on a multiplayer session.

14:11:33.427 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
org.terasology.audio.openAL.OpenALException: OpenAL Error (40963) at Buffer unqueue - Invalid Value
    at org.terasology.audio.openAL.streamingSound.OpenALStreamingSoundSource.update(OpenALStreamingSoundSource.java:80)
    at org.terasology.audio.openAL.BaseSoundPool.lambda$update$1(BaseSoundPool.java:114)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
    at java.util.HashMap$KeySpliterator.forEachRemaining(Unknown Source)
    at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at org.terasology.audio.openAL.BaseSoundPool.update(BaseSoundPool.java:114)
    at org.terasology.audio.openAL.OpenALManager.update(OpenALManager.java:278)
    at org.terasology.engine.subsystem.lwjgl.LwjglAudio.postUpdate(LwjglAudio.java:64)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:467)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:421)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:397)
    at org.terasology.engine.Terasology.main(Terasology.java:156)
14:11:33.427 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
Cervator commented 4 years ago

Still happens - usual play test today


13:28:01.888 [main] INFO  o.t.logic.console.ConsoleImpl - [CONSOLE] Message sent
13:28:06.282 [main] INFO  o.t.musicdirector.MusicDirectorImpl - Removed ShootingStars
13:28:06.282 [main] INFO  o.t.musicdirector.MusicDirectorImpl - Removed OrcFortress
13:28:06.282 [main] INFO  o.t.musicdirector.MusicDirectorImpl - Removed PeacefulWorld
13:28:29.322 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
org.terasology.audio.openAL.OpenALException: OpenAL Error (40963) at Buffer unqueue - Invalid Value
    at org.terasology.audio.openAL.streamingSound.OpenALStreamingSoundSource.update(OpenALStreamingSoundSource.java:80)
    at org.terasology.audio.openAL.BaseSoundPool.lambda$update$1(BaseSoundPool.java:114)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at java.util.stream.ReferencePipeline$2$1.accept(Unknown Source)
    at java.util.HashMap$KeySpliterator.forEachRemaining(Unknown Source)
    at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at org.terasology.audio.openAL.BaseSoundPool.update(BaseSoundPool.java:114)
    at org.terasology.audio.openAL.OpenALManager.update(OpenALManager.java:271)
    at org.terasology.engine.subsystem.lwjgl.LwjglAudio.postUpdate(LwjglAudio.java:63)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:471)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:425)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:401)
    at org.terasology.engine.Terasology.main(Terasology.java:156)
13:28:29.322 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
13:28:29.331 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
13:28:29.333 [main] INFO  o.t.musicdirector.MusicDirectorImpl - Song 'PeacefulWorld' ended
``
Cervator commented 4 years ago

Still there but I wonder if this might go away after we merge #3969 which seems imminent 🤔

Cervator commented 3 years ago

Still there, although a shorter log this time. Was testing out Lost, activated an angel statue, and subsequently died from fall damage, then the game crashed on trying to respawn. Unsure if that crashed quietly and caused the OpenAL issue on the way down or if it just coincidentally played some SFX that caused the crash:

15:50:05.639 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
org.terasology.audio.openAL.OpenALException: OpenAL Error (40963) at Setting listener orientation - Invalid Value
    at org.terasology.audio.openAL.OpenALManager.updateListener(OpenALManager.java:284)
    at org.terasology.audio.openAL.OpenALManager.updateListener(OpenALManager.java:266)
    at org.terasology.audio.system.AudioSystem.update(AudioSystem.java:113)
    at org.terasology.engine.modes.StateIngame.update(StateIngame.java:171)
    at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:479)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:442)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:418)
    at org.terasology.engine.Terasology.main(Terasology.java:182)
15:50:05.639 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
pollend commented 3 years ago

This happens when the location is nan or infinite.

Cervator commented 3 years ago

@pollend

This happens when the location is nan or infinite.

You think that could be the cause here? In the case of respawning maybe it could be a timing issue of playing sfx before the player has a valid position to deal with positional audio or something?

Right off the top of my head I don't remember the past cases well enough to wonder if it could be the same issue every time, but at least it could be plausible. I wonder if we could harden related usages of LocationComponent to check the value ahead of time and log a better reason if invalid than just crash.

pollend commented 3 years ago

I was just looking at the code, I don't think its a null problem case umm.

Cervator commented 3 years ago

Caught a similar error today while testing #4454 - although this log again differs, yet happens both times I tried my test run.

No idea if the original error reported in this issue went away with LWJGL 3, but it does seem like OpenAL gets caught up in an abnormal game termination quite frequently. The game also failed to fully close in at least one case, had to terminate its orphan process manually.

22:03:39.552 [main] INFO  o.t.i18n.TranslationSystemImpl - Discovered engine:menu_ru
22:03:39.579 [main] INFO  o.t.l.p.ThirdPersonRemoteClientSystem - Somehow ended up in the else during linkHeldItemLocationForRemotePlayer - current item was EntityRef{id=0} and new item EntityRef{id=0}
22:03:39.829 [main] ERROR o.t.engine.modes.StateLoading - Error while loading org.terasology.engine.modes.loadProcesses.PrepareWorld@736b21ee
java.lang.ArrayIndexOutOfBoundsException: -13
        at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.createWorldView(RemoteChunkProvider.java:228)
        at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.getLocalView(RemoteChunkProvider.java:202)
        at org.terasology.world.internal.WorldProviderCoreImpl.getLocalView(WorldProviderCoreImpl.java:154)
        at org.terasology.world.internal.AbstractWorldProviderDecorator.getLocalView(AbstractWorldProviderDecorator.java:78)
        at org.terasology.world.internal.AbstractWorldProviderDecorator.getLocalView(AbstractWorldProviderDecorator.java:78)
        at org.terasology.rendering.world.RenderableWorldImpl.pregenerateChunks(RenderableWorldImpl.java:175)
        at org.terasology.rendering.world.WorldRendererImpl.pregenerateChunks(WorldRendererImpl.java:263)
        at org.terasology.engine.modes.loadProcesses.PrepareWorld.step(PrepareWorld.java:46)
        at org.terasology.engine.modes.StateLoading.update(StateLoading.java:237)
        at org.terasology.engine.TerasologyEngine.tick(TerasologyEngine.java:496)
        at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:459)
        at org.terasology.engine.TerasologyEngine.runMain(TerasologyEngine.java:435)
        at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:401)
        at org.terasology.engine.Terasology.main(Terasology.java:174)
22:03:40.884 [main] WARN  org.terasology.nui.WidgetUtil - Contents of org.terasology.rendering.nui.layers.mainMenu.MainMenuScreen@5c1b89ac missing button with id 'storageServiceAction'
22:03:40.904 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (1100), capping to 1000
22:03:40.909 [o.t.r.n.l.m.a.AdvancedGameSetupScreen-0] INFO  o.t.e.module.ModuleListDownloader - Downloading modules ..
22:03:41.161 [o.t.r.n.l.m.a.AdvancedGameSetupScreen-0] INFO  o.t.e.module.ModuleListDownloader - Parsing content ..
22:03:41.994 [o.t.r.n.l.m.a.AdvancedGameSetupScreen-0] INFO  o.t.e.module.ModuleListDownloader - Retrieved 185 entries
22:04:49.039 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
22:04:49.076 [Thread-4] INFO  o.t.e.s.d.DiscordRPCSubSystem - Discord RPC >> Disconnected!
22:04:53.128 [nioEventLoopGroup-3-1] ERROR org.terasology.assets.AssetType - Asset instances remained loaded after disposal - [engine:messagePopup!instance]
22:04:53.140 [nioEventLoopGroup-3-1] WARN  o.t.network.internal.ClientHandler - Unexpected exception from client
org.terasology.audio.openAL.OpenALException: OpenAL Error (40964) at Stop playback - null
        at org.terasology.audio.openAL.BaseSoundSource.stop(BaseSoundSource.java:76)
        at org.terasology.audio.openAL.streamingSound.OpenALStreamingSoundSource.stop(OpenALStreamingSoundSource.java:51)
        at java.util.HashMap$KeySet.forEach(HashMap.java:932)
        at org.terasology.audio.openAL.BaseSoundPool.stopAll(BaseSoundPool.java:109)
        at org.terasology.audio.openAL.OpenALManager.playMusic(OpenALManager.java:206)
        at org.terasology.audio.openAL.OpenALManager.loopMusic(OpenALManager.java:234)
        at org.terasology.audio.openAL.OpenALManager.loopMusic(OpenALManager.java:224)
        at org.terasology.engine.modes.StateMainMenu.playBackgroundMusic(StateMainMenu.java:186)
        at org.terasology.engine.modes.StateMainMenu.init(StateMainMenu.java:122)
        at org.terasology.engine.TerasologyEngine.switchState(TerasologyEngine.java:584)
        at org.terasology.engine.TerasologyEngine.changeState(TerasologyEngine.java:567)
        at org.terasology.network.internal.ClientHandler.channelInactive(ClientHandler.java:48)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:745)
pollend commented 3 years ago

similar issues:

https://github.com/MovingBlocks/Terasology/issues/4392 https://github.com/MovingBlocks/Terasology/issues/3984 https://github.com/MovingBlocks/Terasology/issues/3927 https://github.com/MovingBlocks/Terasology/issues/4551