aza547 / wow-recorder

A desktop screen recorder application that records and saves videos of in-game World of Warcraft encounters, and provides a graphical user interface to view the replays. It is free, open source and contains no adverts.
http://www.warcraftrecorder.com
Other
151 stars 31 forks source link

5 seconds isn't enough for OBS responses #271

Closed aza547 closed 1 year ago

aza547 commented 1 year ago

Interesting bug a user hit in discord.

Currently we allow 5s for OBS to do what we tell it, and if it fails then we will crash the app and throw an error.

This user had calls down to OBS that took 6 seconds. I've no idea why. The give-away was the long_calls.txt file.

Tesaron — Yesterday at 10:17 PM Hi, i still instantly get fatal error on the new 3.3.1 version. It opens without issue but as soon as i launch wow, or attempt to launch it with wow open it crashes. [2023-01-03 00:15:26.957] [info] [Main] Detected WoW is running [2023-01-03 00:15:26.958] [info] [Recorder] Configuring OBS audio sources [2023-01-03 00:15:26.960] [info] [Recorder] Start recording buffer [2023-01-03 00:15:31.961] [error] UnhandledPromiseRejectionWarning: OBS didn't signal start in time [2023-01-03 00:15:31.962] [error] (node:28860) UnhandledPromiseRejectionWarning: OBS didn't signal start in time (Use WarcraftRecorder --trace-warnings ... to show where the warning was created) [2023-01-03 00:15:31.963] [error] (node:28860) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)

These are the OBS and recorder Logs

As i explained earlier, app runs fine until i launch the game, the moment wow is open it gives me the fatal error screen (attached image)

I can open the app and adjust settings when WoW is not open but it crashes the moment WoW opens

I also will attach the settings i use as screen shots

aza547 commented 1 year ago

Increasing the timeout from 5s to 30s resolved the issue.

His long_calls file: long_calls (1).txt

My long_calls file: long_calls.txt

aza547 commented 1 year ago

I had a look at how streamlabs desktop does this.

They don't have a timeout, and simply react to signals when they arrive.

private handleOBSOutputSignal(info: IOBSOutputSignalInfo) {
    console.debug('OBS Output signal: ', info);

    const time = new Date().toISOString();

    if (info.type === EOBSOutputType.Streaming) {
      if (info.signal === EOBSOutputSignal.Start) {
        this.SET_STREAMING_STATUS(EStreamingState.Live, time);
        this.resolveStartStreaming();
        this.streamingStatusChange.next(EStreamingState.Live);

        let streamEncoderInfo: Partial<IOutputSettings> = {};
        let game: string = '';

        try {
          streamEncoderInfo = this.outputSettingsService.getSettings();
          game = this.views.game;
        } catch (e: unknown) {
          console.error('Error fetching stream encoder info: ', e);
        }

        const eventMetadata: Dictionary<any> = {
          ...streamEncoderInfo,
          game,
        };

        if (this.videoEncodingOptimizationService.state.useOptimizedProfile) {
          eventMetadata.useOptimizedProfile = true;
        }

        const streamSettings = this.streamSettingsService.settings;

        eventMetadata.streamType = streamSettings.streamType;
        eventMetadata.platform = streamSettings.platform;
        eventMetadata.server = streamSettings.server;

        this.usageStatisticsService.recordEvent('stream_start', eventMetadata);
        this.usageStatisticsService.recordAnalyticsEvent('StreamingStatus', {
          code: info.code,
          status: EStreamingState.Live,
          service: streamSettings.service,
        });
        this.usageStatisticsService.recordFeatureUsage('Streaming');
      } else if (info.signal === EOBSOutputSignal.Starting) {
        this.SET_STREAMING_STATUS(EStreamingState.Starting, time);
        this.streamingStatusChange.next(EStreamingState.Starting);
      } else if (info.signal === EOBSOutputSignal.Stop) {
        this.SET_STREAMING_STATUS(EStreamingState.Offline, time);
        this.RESET_STREAM_INFO();
        this.rejectStartStreaming();
        this.streamingStatusChange.next(EStreamingState.Offline);
        this.usageStatisticsService.recordAnalyticsEvent('StreamingStatus', {
          code: info.code,
          status: EStreamingState.Offline,
        });
      } else if (info.signal === EOBSOutputSignal.Stopping) {
        this.sendStreamEndEvent();
        this.SET_STREAMING_STATUS(EStreamingState.Ending, time);
        this.streamingStatusChange.next(EStreamingState.Ending);
      } else if (info.signal === EOBSOutputSignal.Reconnect) {
        this.SET_STREAMING_STATUS(EStreamingState.Reconnecting);
        this.streamingStatusChange.next(EStreamingState.Reconnecting);
        this.sendReconnectingNotification();
      } else if (info.signal === EOBSOutputSignal.ReconnectSuccess) {
        this.SET_STREAMING_STATUS(EStreamingState.Live);
        this.streamingStatusChange.next(EStreamingState.Live);
        this.clearReconnectingNotification();
      }
    } else if (info.type === EOBSOutputType.Recording) {
      const nextState: ERecordingState = ({
        [EOBSOutputSignal.Start]: ERecordingState.Recording,
        [EOBSOutputSignal.Starting]: ERecordingState.Starting,
        [EOBSOutputSignal.Stop]: ERecordingState.Offline,
        [EOBSOutputSignal.Stopping]: ERecordingState.Stopping,
        [EOBSOutputSignal.Wrote]: ERecordingState.Wrote,
      } as Dictionary<ERecordingState>)[info.signal];

      // We received a signal we didn't recognize
      if (!nextState) return;

      if (info.signal === EOBSOutputSignal.Start) {
        this.usageStatisticsService.recordFeatureUsage('Recording');
        this.usageStatisticsService.recordAnalyticsEvent('RecordingStatus', {
          status: nextState,
          code: info.code,
        });
      }

      if (info.signal === EOBSOutputSignal.Wrote) {
        const filename = obs.NodeObs.OBS_service_getLastRecording();
        this.recordingModeService.addRecordingEntry(filename);
        // Wrote signals come after Offline, so we return early here
        // to not falsely set our state out of Offline
        return;
      }

      this.SET_RECORDING_STATUS(nextState, time);
      this.recordingStatusChange.next(nextState);
    } else if (info.type === EOBSOutputType.ReplayBuffer) {
      const nextState: EReplayBufferState = ({
        [EOBSOutputSignal.Start]: EReplayBufferState.Running,
        [EOBSOutputSignal.Stopping]: EReplayBufferState.Stopping,
        [EOBSOutputSignal.Stop]: EReplayBufferState.Offline,
        [EOBSOutputSignal.Wrote]: EReplayBufferState.Running,
        [EOBSOutputSignal.WriteError]: EReplayBufferState.Running,
      } as Dictionary<EReplayBufferState>)[info.signal];

      if (nextState) {
        this.SET_REPLAY_BUFFER_STATUS(nextState, time);
        this.replayBufferStatusChange.next(nextState);
      }

      if (info.signal === EOBSOutputSignal.Wrote) {
        this.usageStatisticsService.recordAnalyticsEvent('ReplayBufferStatus', {
          status: 'wrote',
          code: info.code,
        });
        this.replayBufferFileWrite.next(obs.NodeObs.OBS_service_getLastReplay());
      }
    }

    if (info.code) {
      if (this.outputErrorOpen) {
        console.warn('Not showing error message because existing window is open.', info);
        return;
      }

      let errorText = '';
      let extendedErrorText = '';
      let linkToDriverInfo = false;
      let showNativeErrorMessage = false;

      if (info.code === obs.EOutputCode.BadPath) {
        errorText = $t(
          'Invalid Path or Connection URL.  Please check your settings to confirm that they are valid.',
        );
      } else if (info.code === obs.EOutputCode.ConnectFailed) {
        errorText = $t(
          'Failed to connect to the streaming server.  Please check your internet connection.',
        );
      } else if (info.code === obs.EOutputCode.Disconnected) {
        errorText = $t(
          'Disconnected from the streaming server.  Please check your internet connection.',
        );
      } else if (info.code === obs.EOutputCode.InvalidStream) {
        errorText = $t(
          'Could not access the specified channel or stream key. Please log out and back in to refresh your credentials. If the problem persists, there may be a problem connecting to the server.',
        );
      } else if (info.code === obs.EOutputCode.NoSpace) {
        errorText = $t('There is not sufficient disk space to continue recording.');
      } else if (info.code === obs.EOutputCode.Unsupported) {
        errorText =
          $t(
            'The output format is either unsupported or does not support more than one audio track.  ',
          ) + $t('Please check your settings and try again.');
      } else if (info.code === obs.EOutputCode.OutdatedDriver) {
        linkToDriverInfo = true;
        errorText = $t(
          'An error occurred with the output. This is usually caused by out of date video drivers. Please ensure your Nvidia or AMD drivers are up to date and try again.',
        );
      } else {
        // -4 is used for generic unknown messages in OBS. Both -4 and any other code
        // we don't recognize should fall into this branch and show a generic error.
        errorText = $t(
          'An error occurred with the output. Please check your streaming and recording settings.',
        );
        if (info.error) {
          showNativeErrorMessage = true;
          extendedErrorText = errorText + '\n\n' + $t('System error message:') + info.error + '"';
        }
      }
      const buttons = [$t('OK')];

      const title = {
        [EOBSOutputType.Streaming]: $t('Streaming Error'),
        [EOBSOutputType.Recording]: $t('Recording Error'),
        [EOBSOutputType.ReplayBuffer]: $t('Replay Buffer Error'),
      }[info.type];

      if (linkToDriverInfo) buttons.push($t('Learn More'));
      if (showNativeErrorMessage) buttons.push($t('More'));

      this.outputErrorOpen = true;
      const errorType = 'error';
      remote.dialog
        .showMessageBox(Utils.getMainWindow(), {
          buttons,
          title,
          type: errorType,
          message: errorText,
        })
        .then(({ response }) => {
          if (linkToDriverInfo && response === 1) {
            this.outputErrorOpen = false;
            remote.shell.openExternal(
              'https://howto.streamlabs.com/streamlabs-obs-19/nvidia-graphics-driver-clean-install-tutorial-7000',
            );
          } else {
            let expectedResponse = 1;
            if (linkToDriverInfo) {
              expectedResponse = 2;
            }
            if (showNativeErrorMessage && response === expectedResponse) {
              const buttons = [$t('OK')];
              remote.dialog
                .showMessageBox({
                  buttons,
                  title,
                  type: errorType,
                  message: extendedErrorText,
                })
                .then(({ response }) => {
                  this.outputErrorOpen = false;
                })
                .catch(() => {
                  this.outputErrorOpen = false;
                });
            } else {
              this.outputErrorOpen = false;
            }
          }
        })
        .catch(() => {
          this.outputErrorOpen = false;
        });
      this.windowsService.actions.closeChildWindow();
    }
  }
aza547 commented 1 year ago

Going to make the change to allow up to 30s for a response.

Risk is that OBS is genuinely taking that long to start and we might see videos that are clipped from the start.

After taking a rebuilt version with this change, the user reported it was working fine. Here's logs from after the change:

long_calls (2).txt WarcraftRecorder-2023-01-03 (6).log

Notice 6 seconds to signal start:

[2023-01-03 22:42:44.862] [info]  [Recorder] Start recording buffer
[2023-01-03 22:42:44.990] [info]  [Main] New version available: 3.3.1
[2023-01-03 22:42:45.107] [info]  [CombatLogParser] Detected latest/new log file 'G:\WoW DF\World of Warcraft\_retail_\Logs\WoWCombatLog-010323_220453.txt'
[2023-01-03 22:42:50.900] [debug] [Recorder] Asserted OBS signal: start

3 seconds to signal stop:

[2023-01-03 22:47:08.608] [info]  [Recorder] Stop called
[2023-01-03 22:47:08.609] [info]  [Recorder] Over-running by 3 seconds
[2023-01-03 22:47:11.664] [debug] [Recorder] Asserted OBS signal: stopping
[2023-01-03 22:47:12.171] [debug] [Recorder] Asserted OBS signal: stop
[2023-01-03 22:47:12.217] [debug] [Recorder] Asserted OBS signal: wrote