Continuing a saved GP causes “last lap” sound to be played many times throughout the race (UPDATE: Bug may be caused by something else!)

[Wuzzy2]

When I continue a saved GP, I will hear the “last lap” sound (or something similar, I am not sure) a lot of time again and again throughout the race.

This bug happens if you continue a saved grand prix. It seems only to happen after you have done so, I have never experienced the bug in other situations.

Also, this bug seems to continue for all future GP races (even non-GP) in the same STK session as well. If you restart STK, the sound weirdness is gone, until you continue a GP again.

Sometimes the sound in question is strangely distorted.

STK version: 0.9

[auriamg]

I am so far unable to reproduce the bug

[hiker]

I can't reproduce either. Do you see any messages on stdout.log? (perhaps we drop some sound effects command, and for whatever reason also drop the 'stop sfx'). Is it playing continuously, i.e. without pause, or does it appear to be started every X seconds again? Do you use the pause menu somehow?

[Wuzzy2]

There is nothing special in stdout.log.
But I can try to provide some more details:

The sound is not played continously, but in a “one-shot” fashion. There does not seem to be a regular interval.
Using the pause menu does not seem to change the outcome. It does not matter if I used the pause menu in that race or not, it seems to appear independently of this.

It seems (!) I can reliably reproduce this by doing this:

• Start Penguin Playground GP (I used 19 AI karts for testing)
• Finish or give up 1st race
• When the 2nd race starts, quit.
• Exit STK
• Start STK
• Continue the GP
• Now you should start on Bovine Barnyard. Hit the “attack” key at lot of times in the race countdown. (Time penalty!) Normally, a car horn sound plays, but at one point, this sound seems to change and sound totally weird.

My guess is that the other karts use the “horn” as well which causes the distorted sound to be played so often.

EDIT: It seems this bug has nothing to do with GPs as well. I just played a non-GP race on Northern Resort where I hammered the attack key before the start (I got a time penalty), and bingo! Again all these distorted sounds again.

[Flakebi]

I was able to reproduce it with Northern Resort and pressing space often after the loading screen appears. After that, every following race was broken in the same way. I seemed like one sound was picked (the second time I got this it sounded like another one) and then multiplied and played in a loop (one sound per space?). Unfortunately I am not able to reproduce it again atm...

[hiker]

I've created a branch fix_2169 (a bit optimistic that name ;) ), which adds some logging feature. To use it, add the command line parameter --log-sfx. Then reproduce the problem. If it happens, click to open the debug menu (artist debug mode necessary of course), and select "Dump sfx data". This will take quite some time! The compress stdout.log, and either send it to me or attach it here.
Note that exiting STK takes significantly longer now (order of 5 to 10 seconds) - it's a pretty hacky log option ;)

[deveee]

I'm preparing builds for STK 0.9.2 and I it was the first time when this bug occured for me. You can hear it in the video:
https://www.youtube.com/watch?v=ByMWr5DcZjE&feature=youtu.be
But I can't reproduce it anymore.

This sound seems to be played instead of engine sound.

I'm affraid that it's a memory corruption somewhere.

[qwertychouskie]

Ohhh... that.... I had this happen once, unfortunately I do not remember many details, as it was around the time I first started playing, here is what I do know:

• Track: overworld
• Sound: last lap
• What the sound should have been: engine
• System: Dell Insprion 3520
• Processor: Core i5-2520M, from lshw:

*-cpu
     product: Intel(R) Core(TM) i5-2520M CPU @ 2.50GHz
     vendor: Intel Corp.
     physical id: 1
     bus info: cpu@0
     size: 1319MHz
     capacity: 3200MHz
     width: 64 bits
     capabilities: fpu fpu_exception wp vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp x86-64 constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm epb tpr_shadow vnmi flexpriority ept vpid xsaveopt dtherm ida arat pln pts cpufreq

• RAM: either 1x4G; 1x4G & 1x1G; or 1x4G & 1x2G
• GPU: Intel integrated, see processor info
• System: Xubuntu 15.10 (I think)
• STK version: 0.9.0, or maybe 0.9.1 from the PPA

[qwertychouskie]

IT IS HAPPENING AGAIN, on a different computer, one I am fixing for a friend. STK 0.9.2, Sound: Last lap, Triggers: Basketball, Plunger, and Cupcake, Computer: Mac Mini, OS: Ubuntu 16.04.1 64-bit, fresh install yesterday. The game is still running, so I can help with the debugging. CC: @auriamg @Benau @hiker @deveee

[qwertychouskie]

System Info:

[deveee]

@qwertychouskie If you are able to reproduce it, try to run it under valgrind. Just run something like valgrind ./build/bin/supertuxkart and then post your log from console. It reports messages similar to this one:

==4687== Conditional jump or move depends on uninitialised value(s)
==4687==    at 0xFF1906: irr::video::CNullDriver::createImageFromFile(irr::io::IReadFile*) (CNullDriver.cpp:1308)
==4687==    by 0xFF76B9: irr::video::CNullDriver::loadTextureFromFile(irr::io::IReadFile*, irr::core::string<char, irr::core::irrAllocator<char> > const&) (CNullDriver.cpp:470)
==4687==    by 0xFFC236: irr::video::CNullDriver::getTexture(irr::core::string<char, irr::core::irrAllocator<char> > const&) (CNullDriver.cpp:418)
==4687==    by 0xBF33D5: IrrDriver::getTexture(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool, bool, bool) (irr_driver.cpp:1634)
==4687==    by 0xE12486: TrackManager::loadTrack(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (track_manager.cpp:214)
==4687==    by 0xE121EB: TrackManager::loadTrackList() (track_manager.cpp:165)
==4687==    by 0xEA3086: initRest() (main.cpp:1348)
==4687==    by 0xEA39BC: main (main.cpp:1463)
==4687== 

If we are lucky, it will report what's wrong. Note that it may run very slow and STK must be compiled in debug mode.

I'm removing can_not_reporoduce, because the problem certainly exists.

[qwertychouskie]

The issue is, I don't know if I can reproduce it or not, and I don't want to relaunch STK just to find that it can't be reproduced.

[qwertychouskie]

I took the risk and relaunched STK under valgrind, and now it won't do it. :(

[deveee]

This is why this bug is that hard to catch. Some things must be prepared before STK starts, and then you must have the hopes that the problem will occur.

You can also use hiker's branch to get more verbose log. If you have some suspections which part of memory is accidentally modified, you can also add a watchpoint under debugger to see which function actually modifies it (but this is not trivial).

Actually it is possible to connect gdb debugger to already running process, which might be sometimes helpful (for example when application stays in infinite loop and we want to see where it is). But it wasn't really helpful for this particular issue, because something wrong already happened earlier.

[qwertychouskie]

This may be applicable:

[qwertychouskie]

(https://scan.coverity.com/projects/supertuxkart)

[hiker]

This is very likely a problem with STK using too many openal sources, which was reported in #2921 and is fixed now. So I am closing this ticket now.

[deveee]

Tbh I don't think, because I always play with very little karts, no Grand Prix etc. and I never received any openal errors in console. But I can't reproduce it on demand, so I can't say that it's not fixed :p

[hiker]

My reasoning was that the leak in (iirc) the gum SFX could have triggered the problem (too many sources), considering that you played a GP that could have accumulated. Anyway, if you should observe it again, please reopen.

[deveee]

And btw. it was happening for me on the first race (just open STK and run a race) so no accumulation, and also in STK 0.9.2 there was only one crash sound, so less sounds sources.

Maybe there is something wrong with threads, no idea... Because I sometimes see other strange errors on startup, for example a crash with "pure virtual method called" or runtime exceptions (cannot write addons.xml or something like this). They are not reproducible, but happened 5-6 times for me.

[deveee]

I just noticed that all these reports are related to release builds that use old openal version. Our package has openal 1.14. Linux mint was based on ubuntu 14.04, so it's openal 1.14 too. Wuzzy reported it for STK 0.9, so probably old openal too. I'm not sure what about Qwerty's report, but ubuntu 16.04 has STK 0.9.1, so he was probably using our 0.9.2 package.

So I will upgrade openal in our linux package, maybe this is the reason.

And btw #2153 seems to be the same bug.

[hiker]

Good catch that. I've opened a new ticket #2926 to add this kind of information to our stack trace reports. Cheers, Joerg

[qwertychouskie]

It also seems like it may be related to first runs. Both times I had the issue, it was just installed from the PPA.

[deveee]

I found one thing that may be related. In MusicInformation::startMusic() it's possible that i.e. fast music is deleted and is not null. I saw some crashes in isPlaying(), so I will prepare a patch anyway.

[deveee]

I did some tests with sounds/music in current git STK and after few races once I received:

[error  ] MusicOgg: OpenAL error at volume music : AL_INVALID_NAME (40961)

when fast music should start playing (for last lap).

And also once fast music wasn't playing at all, and in last lap there were only sounds without music. So there is definitely something wrong somewhere...

It was in cornfield crossing without AI karts.

[qwertychouskie]

Try export ALSOFT_LOGLEVEL=3

[deveee]

One more behavior that happened on Android:
"When i won a normal race and exit to main menu the sounds from race keep playing instead of the menu music"

I was looking at the logs from valgrind --tool=drd --read-var-info=yes and valgrind --tool=helgrind. It prints some warnings related to audio thread, but nothing that is clear enough...

[hiker]

Appears to be rare, so postponing.

[deveee]

Now we don't change current working directory to get files list and also Benau fixed all known issues with thread safety in audio and file manager. So that it's quite possible that the bug is already fixed. Please reopen if it still happens.