Inconsistent "end" event emit behaviour - Not emitted (sometimes) when playing multiple tracks simultaniously

[IgalOgonov]

The Problem

Let me preface this by saying two things:

1. The problem is quite complex to reproduce, so I'll have to share more context on how I encountered it, including some of the related code (I'll do my best to keep it brief).
2. I've spend way too many hours over the last few days until I finally made sure that the cause of the bug is somewhere within this library - It's 2am as of writing this, tomorrow I'll rewrite the relevant 'onend' code with setInterval instead, and soon afterwards I'll squash that temporary commit and forget about it like a bad dream. I won't waste any time on convincing anyone of the importance of this bug, or doing any deeper analysis on my side than I already have. The last time I spend on this problem (aside from the refactor) is writing this bug report.

The problem itself is as described in the title, but it requires more context to explain in detail.
To summarize, either the "end" event is being emitted late by itself, or the "duration" of one of the tracks suddenly becomes much longer (the actual music ends, does not loop, no event emitted until much later).

Context

The code is part of a singleton called SoundManager (A class written in VanillaJS).
One of the functions of SoundManager is to manage music, with Howler.js at its base,
Two specific features are the support for "Reverb Tail" (playing the track over itself $rt seconds before the end, where the number can be a float), and "Intensity" (playing multiple tracks simultaneously, with the ability to switch between them on the fly, and overlay any two "neighboring" tracks).
You can visit "ovanisound.com" if you wish to learn more about the above.

The code (which will be provided shortly) seemingly worked, but after some time (sometimes ten minutes, sometimes closer to an hour) it suddenly broke - as I later found, due to Howler not emitting its "end" event on time.

Relevant Code

The following are partial snippets of the code from SoundManager, which is a much larger class:

1. The following is the structure which is referred to as musicGroup in the next function. This is just the copy-pasted comment, since each group is initiated dynamically.

sounds: {
      /* id: {
           sounds: Howl[], default null - Instances of Howl (https://github.com/goldfire/howler.js).
                   The first one is the default sound - any subsequent sound, if it exists, should be the "intensity modifier".
                   This feature supports merging multiple tracks which represent different intensity levels of the same track.
                   You may use the intensity meter setting below to merge tracks, or outright switch between them.
                   The first track is the "base", the higher tracks are more intense.
                   Higher tracks may also be overlaid on top of lower ones (e.g. track 0 is most stuff, 1 is drums & snare, 2 is choir)
           playing: Array of sound IDs, same length as Sounds, used when sounds are playing.
           playingRT: Array of sound IDs, same length as Sounds, used when sounds with RT are playing.
           _subTrackLoading: int, default 0 - used when loading multiple tracks
           _subTrackLoaded: int, default 0 - used when loading multiple tracks
           _subTrackErrors: int, default 0 - used when loading multiple tracks
           _subTrackLoadingResults: object, default {} - used when loading multiple tracks
           _singleTrack: bool, default true - used to quickly indicate we only have a single track
           _currentMainSound: int, default 1 - used to support RT
           _handledSounds: obj,  used to support RT in multi-track
           _preRT: bool, default false - used to support RT
           _inRT: bool, default false - used to support RT
           _fading: bool, default false - used to support fading RT
           intensity: float, default 0 - Goes from 0 to <number of sounds - 1>. When a round number, indicates that track
                      should be playing.
                      When a fraction, plays both tracks above and below the fraction (e.g 1.5 plays track 1 and 2, not 0).
                      TODO Implement partial mixing based on exact fraction
           intensitySwitchType: string, default 'switch' - Will play both tracks on fraction by default. 'merge' will
                                merge all tracks below the intensity level (not above, and fractions are meaningless).
           intensityFadeTime: int, default 1000 - Fade time when switching / merging intensity tracks. Can be overriden. TODO
           rt: float, default 0.00 - "Reverb Tail" is a concept relevant to looping.
               When set, will play <RT> seconds into itself when looping. For example, rt of 3.75 means the this
               track will loop 3.75 seconds before the last loop iteration has finished.
               Will only apply on loops, not switching (manually or in queue).
               Technically, this is achieved by playing both sounds with the "second" one starting muted, and RT seconds
               ahead.
               When the second sound loops, it unmutes, and _currentMainSound changes to indicate it.
               When the first sound loops, it mutes, and is sent RT x 2 seconds ahead, as it becomes the "second".
               This is done because the only function in Hawler with millisecond precision is the set function of `seek()`,
               so we have to leverage it, and looping, even if it's probably a few milliseconds off in total.
           status: string, 'loading', 'loaded' or 'play-error'
           error: int, see play/load error codes on the above page
         }
      * */
    },

2. The current code which starts playing a specific musicGroup.

_startMusic(musicId, fadeIn = null) {

    this.bgm.meta.currentlyPlaying = musicId;
    const context = this;
    const meta = this.bgm.meta;
    const options = this.bgm.options;
    const musicGroup = this.bgm.sounds[musicId];
    if (!musicGroup) {
      debugMessage('Trying to start non existent track ' + musicId, {msgType: 'error'});
      return false;
    }
    const hasMultipleTracks = !musicGroup._singleTrack;
    const targetVolume = this._calcTargetMusicVolume();
    const reverbTail = meta.loopCurrent ? musicGroup.rt : 0;
    const timeoutMargin = 100;
    const checkAndReplaceOnEnd = () =>{
      const replaceOnEnd = meta.nextPlayReplace.id;
      if (replaceOnEnd) {
        const clone = _.clone(meta.nextPlayReplace);
        meta.nextPlayReplace = {
          id: null,
          options: null
        }
        context.playMusic(clone.id, clone.options);
        return true;
      }
      return false;
    }
    const getRTConfig = (index = 0) => {
      let thisSoundGroup = (musicGroup._currentMainSound === 1) ? musicGroup.playingRT : musicGroup.playing;
      let id = (musicGroup._currentMainSound % 2 + 1);
      return {
        id: id,
        thisSoundGroup: thisSoundGroup
      }
    }
    //Simple case, when only one track - not generalized for performance reasons
    if (!hasMultipleTracks) {
      const relevantTrack = musicGroup.sounds[0];
      const handleRT = (self) => {
        const isNextMain = !musicGroup['_inRT'];
        let {thisSoundGroup, id} = getRTConfig();

        const replaceOnEnd = meta.nextPlayReplace.id;

        if(musicGroup._handledSounds[id][self])
          return;
        else
          musicGroup._handledSounds[id][self] = true;

        if (isNextMain) {
          //If we are fading, no need to unmute - we'll stop soon anyway
          if (musicGroup['_fading'] || replaceOnEnd)
            return;
          relevantTrack.mute(options.mute,self);
          musicGroup['_inRT'] = Date.now();
          musicGroup['_currentMainSound'] = id;
          debugMessage('[Music ' + musicId + '] Track RT switch' + id);
        }
        else {
          const delta = (Date.now() - musicGroup['_inRT']) / 1000;
          let self = thisSoundGroup[0];
          relevantTrack.mute(true,self);
          //If we are fading, we only need to mute the volume
          if (checkAndReplaceOnEnd() || musicGroup['_fading'])
            return;
          relevantTrack.seek(_.round(reverbTail + delta, 4),self);
          setTimeout(()=>{
            musicGroup['_inRT'] = null;
            musicGroup._handledSounds = {1:{},2:{}};
            debugMessage('[Music ' + musicId + '] T-RT-' + id + ' end, op-' + _.round(delta, 2) + '/' + _.round(reverbTail + delta, 4));
          },timeoutMargin)
        }

      }
      relevantTrack.seek(0);
      relevantTrack.volume(fadeIn ? 0 : targetVolume);
      relevantTrack.mute(options.mute);
      relevantTrack.loop(meta.loopCurrent);
      musicGroup.playing[0] = relevantTrack.play();
      if (reverbTail) {
        musicGroup.playingRT[0] = relevantTrack.play();
        relevantTrack.mute(true, musicGroup.playingRT[0]);
        relevantTrack.seek(reverbTail, musicGroup.playingRT[0]);
      }
      if (fadeIn)
        relevantTrack.fade(0, targetVolume, fadeIn, musicGroup.playing[0]);
      if (meta.loopCurrent && reverbTail){
        relevantTrack.on('end', (sId) => {
          handleRT(sId);
        });
      }
      //Applies in every case except if we have an RT, which handles this
      else(!relevantTrack.onend)
        relevantTrack.on('end', () => {
          checkAndReplaceOnEnd();
        });
    }
    //Multiple tracks
    else {

      const handleRT = (index, self) => {
        const isNextMain = !musicGroup['_inRT'];
        const replaceOnEnd = meta.nextPlayReplace.id;
        const relevantTracks = this._calcRelevantTracks(musicGroup);
        const tracksLength = musicGroup.sounds.length;
        let {thisSoundGroup, id} = getRTConfig(index);

        if (musicGroup._handledSounds[id][self])
          return;
        else
          musicGroup._handledSounds[id][self] = true;

        if (isNextMain) {
          musicGroup['_preRT'] = Date.now();
          //In those cases, don't unmute, just indicate the switch once all tracks are handled
          if (musicGroup['_fading'] || replaceOnEnd){
            setTimeout(() => {
              musicGroup['_inRT'] = Date.now();
            }, timeoutMargin)
            return;
          }
          if(relevantTracks[index])
            musicGroup.sounds[index].mute(options.mute, self);
          //Let god sort them out (We handled all sounds, only 1 will pass the 'if' check, but even if more - wont matter)
          setTimeout(() => {
            if (Object.keys(musicGroup._handledSounds[id]).length < tracksLength)
              return;
            musicGroup._handledSounds[id] = {};
            musicGroup['_handledSounds'][id] = {};
            musicGroup['_inRT'] = Date.now();
            musicGroup['_currentMainSound'] = id;
            debugMessage('[Music ' + musicId + '] T-RT-' + id + ' switch');
          }, ( (index + 1) / tracksLength * timeoutMargin) )
        } else {
          musicGroup.sounds[index].mute(true, self);
          //If we are fading, we only need to mute the volume
          if (checkAndReplaceOnEnd() || musicGroup['_fading'])
            return;
          //Same logic as before
          setTimeout(() => {
            if (Object.keys(musicGroup._handledSounds[id]).length < tracksLength)
              return;
            musicGroup._handledSounds[id] = {};
            const delta = (Date.now() - musicGroup['_preRT'] + timeoutMargin) / 1000;
            for (let i in musicGroup.sounds) {
              musicGroup.sounds[i].seek(_.round(reverbTail + delta, 4), thisSoundGroup[i])
            }
            musicGroup['_inRT'] = false;
            musicGroup['_preRT'] = null;
            debugMessage('[Music ' + musicId + '] T-RT-' + id + ' end, op-' + _.round(delta, 2) + '/'+ _.round(reverbTail + delta, 4));
          }, timeoutMargin * (index + 1))
        }
      }

      const relevantTracks = this._calcRelevantTracks(musicGroup);
      //Separated due to the importance of simultaneous start time
      for (let index in musicGroup.sounds) {
        if (typeof musicGroup.sounds[index] !== 'object') {
          debugMessage('Invalid index ' + index + 'in music track ' + musicId, {msgType: 'error'});
          delete relevantTracks[index];
          continue;
        }
        musicGroup.sounds[index].seek(0);
        musicGroup.sounds[index].volume((fadeIn || !relevantTracks[index]) ? 0 : targetVolume);
        musicGroup.sounds[index].mute(options.mute);
        if (meta.loopCurrent)
          musicGroup.sounds[index].loop(true);
        //Already handled if we have RT
        if(!musicGroup.sounds[index].onend)
          musicGroup.sounds[index].onend = () => {
            checkAndReplaceOnEnd();
          };
      }

      if (!Object.keys(relevantTracks).length) {
        debugMessage(
          'No valid indexes to play in multi-track group ' + musicId + ', switchType ' + (musicGroup.intensitySwitchType ?? 'switch'),
          'error'
        );
        this.bgm.meta.currentlyPlaying = null;
        return false;
      }

      for (let index in musicGroup.sounds) {
        musicGroup.playing[index] = musicGroup.sounds[index].play();
        if (meta.loopCurrent && reverbTail) {
          musicGroup.playingRT[index] = musicGroup.sounds[index].play();
          musicGroup.sounds[index].mute(true, musicGroup.playingRT[index]);
          musicGroup.sounds[index].seek(reverbTail, musicGroup.playingRT[index]);
          musicGroup.sounds[index].on('end', (sId) => {
            handleRT(index, sId);
          });
        }
        else
          musicGroup.sounds[0].on('end', () => {
            checkAndReplaceOnEnd();
          });
      }

      if (fadeIn)
        for (let index in relevantTracks) {
          musicGroup.sounds[index].fade(0, targetVolume, fadeIn, musicGroup.playing[index]);
        }
    }
    return true;
  }

In the 2nd part:

• debugMessage is a function that generates the logs I'll post ahead (the current logs are back to what they were before the debugging session and adding tons of more precise ones, but they are enough to demonstrate the problem).
• _calcTargetMusicVolume calculates volume from settings, and is irrelevant.
• checkAndReplaceOnEnd, meta and various options are also irrelevant, as they were never triggered or changed during the debugging sessions, apart from the loopCurrent option, which is true.
• The parts that play the sounds were separated into one part that handles single tracks (with or without RT), and one that handles multiple tracks (aka "intensity" supporting tracks. Both reproduced the bug in Howler (aka the end event not being emitted when expected).

Logs

The following logs are produced by the handleRT function in the relevant section (remember, one definition for single tracks, another for multiple tracks).
Reminder:
An RT track is played twice with a delay, the "faster" track starts muted.
Once the "faster" track reaches the end it switches and becomes the "main track" (unmutes), and the music group enters an "RT" state.
Once the previous "main track" reaches the end it ends (becomes muted), and seeks RT seconds ahead (including some technical delay) of where the new main track currently is (op-<other track's time>/<seek time> in the logs).
The initial main track has the ID 1, the other - 2.
The functions that produce those logs can be seen in the 2nd part of the code, above.

Log 1 - ~32 second single track with RT 5.781s

You can see it break after ~31 minutes, between 55:37 and 57:11

[DEBUG@21:58.0913]Music sound loaded - test-music-c30
[DEBUG@22:30.0967][Music test-music-c30] Track RT switch2
[DEBUG@22:36.0819][Music test-music-c30] T-RT-1 end, op-5.74/11.488
...
[DEBUG@53:29.0660][Music test-music-c30] Track RT switch2
[DEBUG@53:35.0509][Music test-music-c30] T-RT-1 end, op-5.74/11.494
[DEBUG@54:03.0423][Music test-music-c30] Track RT switch1
[DEBUG@54:10.0436][Music test-music-c30] T-RT-2 end, op-6/11.75
[DEBUG@55:37.0424][Music test-music-c30] Track RT switch2
[DEBUG@57:11.0536][Music test-music-c30] T-RT-1 end, op-60/65.749
[DEBUG@57:11.0537][Music test-music-c30] T-RT-1 end, op-60/65.75
[DEBUG@57:15.0221][Music test-music-c30] Track RT switch1
[DEBUG@57:53.0125][Music test-music-c30] T-RT-2 end, op-37.8/43.55

Log 2 - ~92 second multi track with RT 5.76s

You can see it break after ~20 minutes, between 35:37 and 38:37 (on the exact second & millisecond).

[DEBUG@16:50.0895][Music default-main-menu] T-RT-1 switch
[DEBUG@16:56.0806][Music default-main-menu] T-RT-2 end, op-6.04/11.796
[DEBUG@18:22.0976][Music default-main-menu] T-RT-2 switch
[DEBUG@18:28.0890][Music default-main-menu] T-RT-1 end, op-6.04/11.799
...
[DEBUG@32:12.0043][Music default-main-menu] T-RT-1 switch
[DEBUG@32:17.0964][Music default-main-menu] T-RT-2 end, op-6.05/11.808
[DEBUG@35:37.0424][Music default-main-menu] T-RT-2 switch
[DEBUG@38:37.0424][Music default-main-menu] T-RT-1 end, op-240.1/245.86
[DEBUG@40:37.0423][Music default-main-menu] T-RT-1 switch
[DEBUG@42:37.0424][Music default-main-menu] T-RT-2 end, op-180.1/185.86
[DEBUG@44:37.0423][Music default-main-menu] T-RT-2 switch
[DEBUG@46:37.0423][Music default-main-menu] T-RT-1 end, op-180.1/185.86
[DEBUG@48:37.0423][Music default-main-menu] T-RT-1 switch
[DEBUG@50:37.0424][Music default-main-menu] T-RT-2 end, op-180.1/185.86

Log 3 - ~92 second multi track with RT 5.76s (same as before)

This is an earlier function which only kept track of the other tracks playtime (so only the 1st half of what you see above).
You can see it break after ~14 minutes, between 36:13 and 40:35 (notice the subsequent events seem to be emitted on the same exact millisecond again, in 2 minute intervals, up until 00:10, which is the next hour).

[DEBUG@22:24.0149][Music default-main-menu] T-RT-2 switch
[DEBUG@22:29.0909][Music default-main-menu] T-RT-1 end, op-6.2
...
[DEBUG@34:36.0017][Music default-main-menu] T-RT-1 switch
[DEBUG@34:41.0783][Music default-main-menu] T-RT-2 end, op-6.22
[DEBUG@36:08.0166][Music default-main-menu] T-RT-2 switch
[DEBUG@36:13.0947][Music default-main-menu] T-RT-1 end, op-6.21
[DEBUG@40:35.0585][Music default-main-menu] T-RT-1 switch
[DEBUG@40:35.0585][Music default-main-menu] T-RT-2 switch
[DEBUG@42:35.0585][Music default-main-menu] T-RT-1 end, op-120
[DEBUG@42:35.0585][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@44:35.0585][Music default-main-menu] T-RT-1 switch
[DEBUG@44:35.0585][Music default-main-menu] T-RT-2 switch
[DEBUG@46:35.0584][Music default-main-menu] T-RT-2 end, op-119.53
[DEBUG@48:35.0584][Music default-main-menu] T-RT-2 switch
[DEBUG@50:35.0585][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@52:35.0584][Music default-main-menu] T-RT-2 switch
[DEBUG@54:35.0584][Music default-main-menu] T-RT-2 end, op-119.95
[DEBUG@56:35.0585][Music default-main-menu] T-RT-2 switch
[DEBUG@58:35.0584][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@00:10.0834][Music default-main-menu] T-RT-2 switch
[DEBUG@00:14.0584][Music default-main-menu] T-RT-2 end, op-1.07
[DEBUG@04:35.0585][Music default-main-menu] T-RT-2 switch
[DEBUG@06:35.0584][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@08:37.0423][Music default-main-menu] T-RT-2 switch
[DEBUG@10:37.0423][Music default-main-menu] T-RT-2 end, op-119.97
[DEBUG@12:37.0424][Music default-main-menu] T-RT-2 switch
[DEBUG@14:37.0424][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@16:37.0424][Music default-main-menu] T-RT-2 switch
[DEBUG@18:37.0423][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@20:37.0423][Music default-main-menu] T-RT-2 switch
[DEBUG@22:37.0423][Music default-main-menu] T-RT-2 end, op-120
[DEBUG@24:37.0423][Music default-main-menu] T-RT-2 switch
[DEBUG@26:37.0424][Music default-main-menu] T-RT-2 end, op-118.25
[DEBUG@28:37.0423][Music default-main-menu] T-RT-2 switch
[DEBUG@30:37.0437][Music default-main-menu] T-RT-2 end, op-114.51
[DEBUG@31:09.0320][Music default-main-menu] T-RT-2 switch
[DEBUG@32:15.0799][Music default-main-menu] T-RT-2 end, op-0.44
[DEBUG@33:53.0744][Music default-main-menu] T-RT-2 switch
[DEBUG@35:31.0688][Music default-main-menu] T-RT-2 end, op-0.47
[DEBUG@37:09.0622][Music default-main-menu] T-RT-2 switch
[DEBUG@38:47.0564][Music default-main-menu] T-RT-2 end, op-0.49

Summary

As you can see, this is not a usual bug report, but it has to do with the sneaky and hard-to-reproduce nature of the bug. As of writing this, I have the multi-track group that produced the first 2 logs running perfectly fine for nearly an hour.
However, the fact that it's very rare is also what makes it extremely hard to track, and it has the potential to ruin certain projects.
I wish you the best of luck tracking this down.

Reproducible Example

No response

Reproduction Steps

Provided logs and code examples.
You may try to create the outlined structure, hard-code Howl sounds into that structure, and use the _startMusic code to play it.

Otherwise, create any structure that uses a single Howler sound to implement Reverb Tail as outlined in the above code, and explained earlier.
Note that a previous version of the code used multiple distinct Howler instances, rather than playing the same sound twice with different IDs, and encountered the exact same problem.

Possible Solution

No response

Context

No response

Howler.js Version

v2.2.4

Affected Browser(s)/Versiuon(s)

Chrome@latest, Librewolf@latest

[IgalOgonov]

Adding to this after having implemented it myself, this behavior seems tied to how browsers handle the suppression ("resource saving mode") of inactive tabs after some time, and the fact that this libraries' implementation seems to rely on timeouts (or intervals), just like my own initial implementation does.

The solution I personally came to was to detect this suppression (based on the time since previous interval surpassing a certain error margin, and the tab not being in focus), and react accordingly.

You might want to resolve this by implementing a similar detection, and provide appropriate hooks (such as "onprocesssupression") and allowing individual implementations to do with it what they will.

By the way, this problem can be solved on Electron, as outlined in this SO answer

[mogamoga1024]

もう少しシンプルな再現コードがあると、アプリ側の問題なのかライブラリの問題なのか判断しやすくなるかもね？

[IgalOgonov]

もう少しシンプルな再現コードがあると、アプリ側の問題なのかライブラリの問題なのか判断しやすくなるかもね？

That code was a transition state - I did not commit it.
All I can say is that this happened while:

1. The tab was not focused.
2. The audio was muted.

And that in a later implementation with my own timeouts/intervals, I clearly found this issue persists with them, and is a browser issue.

My point here is - this issue can be detected in-code, and solved, as I already did. This library should provide its own solution to this issue as well, not for me, but for future people who might want to use it and face it.

[mogamoga1024]

関係する？

#245