Game crash from OpenAL buffer unqueue - invalid value

[Cervator]

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]

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]

Noticed this was reported during Alpha 7 testing as well (by me, no wonder it seemed familiar) as well: #2766 (comment)

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

[Cervator]

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]

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]

Happened to me during Omega multiplayer test.

https://pastebin.com/8qjdWCwP

[keturn]

Fixed or otherwise no longer relevant, you say?

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

[Cervator]

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]

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]

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

[Cervator]

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]

This happens when the location is nan or infinite.

[Cervator]

@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]

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