Merge pull request #4883 from remotion-dev/fix-runaway-audio-bug

`remotion`: Improve video + audio playback performance

packages/core/src/audio/shared-audio-tags.tsx

@@ -249,6 +249,7 @@ export const SharedAudioContextProvider: React.FC<{
 				onAutoPlayError: null,
 				logLevel,
 				mountTime,
+				reason: 'playing all audios',
 			});
 		});
 	}, [logLevel, mountTime, refs]);

packages/core/src/buffer-until-first-frame.ts

@@ -1,16 +1,22 @@
 import {useCallback, useMemo, useRef} from 'react';
+import type {LogLevel} from './log';
+import {playbackLogging} from './playback-logging';
 import {useBufferState} from './use-buffer-state';
 
 export const useBufferUntilFirstFrame = ({
 	mediaRef,
 	mediaType,
 	onVariableFpsVideoDetected,
 	pauseWhenBuffering,
+	logLevel,
+	mountTime,
 }: {
 	mediaRef: React.RefObject<HTMLVideoElement | HTMLAudioElement | null>;
 	mediaType: 'video' | 'audio';
 	onVariableFpsVideoDetected: () => void;
 	pauseWhenBuffering: boolean;
+	logLevel: LogLevel;
+	mountTime: number | null;
 }) => {
 	const bufferingRef = useRef<boolean>(false);
 	const {delayPlayback} = useBufferState();
@@ -31,12 +37,23 @@ export const useBufferUntilFirstFrame = ({
 				return;
 			}
 
+			if (current.readyState >= current.HAVE_ENOUGH_DATA) {
+				return;
+			}
+
 			if (!current.requestVideoFrameCallback) {
 				return;
 			}
 
 			bufferingRef.current = true;
 
+			playbackLogging({
+				logLevel,
+				message: `Buffering ${mediaRef.current?.src} until the first frame is received`,
+				mountTime,
+				tag: 'buffer',
+			});
+
 			const playback = delayPlayback();
 
 			const unblock = () => {
@@ -75,8 +92,10 @@ export const useBufferUntilFirstFrame = ({
 		},
 		[
 			delayPlayback,
+			logLevel,
 			mediaRef,
 			mediaType,
+			mountTime,
 			onVariableFpsVideoDetected,
 			pauseWhenBuffering,
 		],

packages/core/src/buffering.tsx

@@ -1,4 +1,14 @@
-import React, {useCallback, useEffect, useMemo, useRef, useState} from 'react';
+import React, {
+	useCallback,
+	useContext,
+	useEffect,
+	useMemo,
+	useRef,
+	useState,
+} from 'react';
+import type {LogLevel} from './log';
+import {LogLevelContext} from './log-level-context';
+import {playbackLogging} from './playback-logging';
 
 type Block = {
 	id: string;
@@ -26,7 +36,10 @@ type BufferManager = {
 	buffering: React.MutableRefObject<boolean>;
 };
 
-const useBufferManager = (): BufferManager => {
+const useBufferManager = (
+	logLevel: LogLevel,
+	mountTime: number | null,
+): BufferManager => {
 	const [blocks, setBlocks] = useState<Block[]>([]);
 	const [onBufferingCallbacks, setOnBufferingCallbacks] = useState<
 		OnBufferingCallback[]
@@ -82,6 +95,12 @@ const useBufferManager = (): BufferManager => {
 	useEffect(() => {
 		if (blocks.length > 0) {
 			onBufferingCallbacks.forEach((c) => c());
+			playbackLogging({
+				logLevel,
+				message: 'Player is entering buffer state',
+				mountTime,
+				tag: 'player',
+			});
 		}
 
 		// Intentionally only firing when blocks change, not the callbacks
@@ -94,6 +113,12 @@ const useBufferManager = (): BufferManager => {
 	useEffect(() => {
 		if (blocks.length === 0) {
 			onResumeCallbacks.forEach((c) => c());
+			playbackLogging({
+				logLevel,
+				message: 'Player is exiting buffer state',
+				mountTime,
+				tag: 'player',
+			});
 		}
 		// Intentionally only firing when blocks change, not the callbacks
 		// otherwise a resume callback might remove itself after being called
@@ -113,7 +138,8 @@ export const BufferingContextReact = React.createContext<BufferManager | null>(
 export const BufferingProvider: React.FC<{
 	readonly children: React.ReactNode;
 }> = ({children}) => {
-	const bufferManager = useBufferManager();
+	const {logLevel, mountTime} = useContext(LogLevelContext);
+	const bufferManager = useBufferManager(logLevel ?? 'info', mountTime);
 
 	return (
 		<BufferingContextReact.Provider value={bufferManager}>

packages/core/src/play-and-handle-not-allowed-error.ts

@@ -9,12 +9,14 @@ export const playAndHandleNotAllowedError = ({
 	onAutoPlayError,
 	logLevel,
 	mountTime,
+	reason,
 }: {
 	mediaRef: RefObject<HTMLVideoElement | HTMLAudioElement | null>;
 	mediaType: 'audio' | 'video';
 	onAutoPlayError: null | (() => void);
 	logLevel: LogLevel;
 	mountTime: number;
+	reason: string;
 }) => {
 	const {current} = mediaRef;
 	if (!current) {
@@ -24,7 +26,7 @@ export const playAndHandleNotAllowedError = ({
 	playbackLogging({
 		logLevel,
 		tag: 'play',
-		message: `Attempting to play ${current.src}`,
+		message: `Attempting to play ${current.src}. Reason: ${reason}`,
 		mountTime,
 	});
 	const prom = current.play();

packages/core/src/seek.ts

@@ -21,7 +21,7 @@ export const seek = ({
 	playbackLogging({
 		logLevel,
 		tag: 'seek',
-		message: `Seeking from ${mediaRef.currentTime} to ${timeToSet}. Reason: ${why}`,
+		message: `Seeking from ${mediaRef.currentTime} to ${timeToSet}. src= ${mediaRef.src} Reason: ${why}`,
 		mountTime,
 	});
 

packages/core/src/test/wrap-sequence-context.tsx

@@ -4,6 +4,8 @@ import type {CompositionManagerContext} from '../CompositionManagerContext.js';
 import {CompositionManager} from '../CompositionManagerContext.js';
 import {ResolveCompositionConfig} from '../ResolveCompositionConfig.js';
 import {BufferingProvider} from '../buffering.js';
+import type {LoggingContextValue} from '../log-level-context.js';
+import {LogLevelContext} from '../log-level-context.js';
 
 const Comp: React.FC = () => null;
 
@@ -33,16 +35,23 @@ const mockCompositionContext: CompositionManagerContext = {
 	canvasContent: {type: 'composition', compositionId: 'my-comp'},
 };
 
+const logContext: LoggingContextValue = {
+	logLevel: 'info',
+	mountTime: 0,
+};
+
 export const WrapSequenceContext: React.FC<{
 	readonly children: React.ReactNode;
 }> = ({children}) => {
 	return (
-		<BufferingProvider>
-			<CanUseRemotionHooksProvider>
-				<CompositionManager.Provider value={mockCompositionContext}>
-					<ResolveCompositionConfig>{children}</ResolveCompositionConfig>
-				</CompositionManager.Provider>
-			</CanUseRemotionHooksProvider>
-		</BufferingProvider>
+		<LogLevelContext.Provider value={logContext}>
+			<BufferingProvider>
+				<CanUseRemotionHooksProvider>
+					<CompositionManager.Provider value={mockCompositionContext}>
+						<ResolveCompositionConfig>{children}</ResolveCompositionConfig>
+					</CompositionManager.Provider>
+				</CanUseRemotionHooksProvider>
+			</BufferingProvider>
+		</LogLevelContext.Provider>
 	);
 };

packages/core/src/timeline-position-state.ts

@@ -4,7 +4,7 @@ import {getRemotionEnvironment} from './get-remotion-environment.js';
 import {useVideo} from './use-video.js';
 
 export type PlayableMediaTag = {
-	play: () => void;
+	play: (reason: string) => void;
 	id: string;
 };
 

packages/core/src/use-media-buffering.ts

@@ -59,16 +59,34 @@ export const useMediaBuffering = ({
 		}
 
 		const cleanup = (reason: string) => {
-			cleanupFns.forEach((fn) => fn(reason));
+			let didDoSomething = false;
+			cleanupFns.forEach((fn) => {
+				fn(reason);
+				didDoSomething = true;
+			});
 			cleanupFns = [];
-			setIsBuffering(false);
+			setIsBuffering((previous) => {
+				if (previous) {
+					didDoSomething = true;
+				}
+
+				return false;
+			});
+			if (didDoSomething) {
+				playbackLogging({
+					logLevel,
+					message: `Unmarking as buffering: ${current.src}. Reason: ${reason}`,
+					tag: 'buffer',
+					mountTime,
+				});
+			}
 		};
 
 		const blockMedia = (reason: string) => {
 			setIsBuffering(true);
 			playbackLogging({
 				logLevel,
-				message: `Buffering ${current.src}. Reason: ${reason}`,
+				message: `Marking as buffering: ${current.src}. Reason: ${reason}`,
 				tag: 'buffer',
 				mountTime,
 			});

packages/core/src/use-media-in-timeline.ts

@@ -168,7 +168,7 @@ export const useMediaInTimeline = ({
 	useEffect(() => {
 		const tag: PlayableMediaTag = {
 			id,
-			play: () => {
+			play: (reason) => {
 				if (!imperativePlaying.current) {
 					// Don't play if for example in a <Freeze> state.
 					return;
@@ -184,6 +184,7 @@ export const useMediaInTimeline = ({
 					onAutoPlayError,
 					logLevel,
 					mountTime,
+					reason,
 				});
 			},
 		};

packages/core/src/use-media-playback.ts

@@ -103,6 +103,8 @@ export const useMediaPlayback = ({
 		mediaType,
 		onVariableFpsVideoDetected,
 		pauseWhenBuffering,
+		logLevel,
+		mountTime,
 	});
 
 	const playbackRate = localPlaybackRate * globalPlaybackRate;
@@ -122,11 +124,15 @@ export const useMediaPlayback = ({
 	const isPlayerBuffering = useIsPlayerBuffering(buffering);
 
 	useEffect(() => {
+		if (mediaRef.current?.paused) {
+			return;
+		}
+
 		if (!playing) {
 			playbackLogging({
 				logLevel,
 				tag: 'pause',
-				message: `Pausing ${mediaRef.current?.src} because player is not playing`,
+				message: `Pausing ${mediaRef.current?.src} because ${isPremounting ? 'media is premounting' : 'Player is not playing'}`,
 				mountTime,
 			});
 			mediaRef.current?.pause();
@@ -148,6 +154,7 @@ export const useMediaPlayback = ({
 		isBuffering,
 		isMediaTagBuffering,
 		isPlayerBuffering,
+		isPremounting,
 		logLevel,
 		mediaRef,
 		mediaType,
@@ -217,6 +224,8 @@ export const useMediaPlayback = ({
 						onAutoPlayError,
 						logLevel,
 						mountTime,
+						reason:
+							'player is playing but media tag is paused, and just seeked',
 					});
 				}
 			}
@@ -259,17 +268,23 @@ export const useMediaPlayback = ({
 			return;
 		}
 
-		// We assured we are in playing state
-		if (
-			(mediaRef.current.paused && !mediaRef.current.ended) ||
-			absoluteFrame === 0
-		) {
+		if (!playing || buffering.buffering.current) {
+			return;
+		}
+
+		// We now assured we are in playing state and not buffering
+		const pausedCondition = mediaRef.current.paused && !mediaRef.current.ended;
+		const firstFrameCondition = absoluteFrame === 0;
+		if (pausedCondition || firstFrameCondition) {
+			const reason = pausedCondition
+				? 'media tag is paused'
+				: 'absolute frame is 0';
 			if (makesSenseToSeek) {
 				lastSeek.current = seek({
 					mediaRef: mediaRef.current,
 					time: shouldBeTime,
 					logLevel,
-					why: `is over timeshift threshold (threshold = ${seekThreshold}) is paused OR has reached end of timeline and is starting over`,
+					why: `is over timeshift threshold (threshold = ${seekThreshold}) and ${reason}`,
 					mountTime,
 				});
 			}
@@ -280,11 +295,10 @@ export const useMediaPlayback = ({
 				onAutoPlayError,
 				logLevel,
 				mountTime,
+				reason: `player is playing and ${reason}`,
 			});
-			if (!isVariableFpsVideo) {
-				if (playbackRate > 0) {
-					bufferUntilFirstFrame(shouldBeTime);
-				}
+			if (!isVariableFpsVideo && playbackRate > 0) {
+				bufferUntilFirstFrame(shouldBeTime);
 			}
 		}
 	}, [

packages/docs/docs/player/playback-issues.mdx

@@ -73,7 +73,7 @@ We have implemented exact logging of relevant events so in order to improve how
 We are encouraging you to file feedback. If you would like to report feedback, please:
 
 <div>
-  <Step>1</Step> <span>Ensure you are at least on v4.0.250 of Remotion.</span>
+  <Step>1</Step> <span>Ensure you are at least on v4.0.262 of Remotion. Previous versions had known bugs.</span>
 </div>
 <div>
   <Step>2</Step>{' '}

packages/player/src/use-player.ts

@@ -94,7 +94,9 @@ export const usePlayer = (): UsePlayerMethods => {
 			 * Play audios and videos directly here so they can benefit from
 			 * being triggered by a click
 			 */
-			audioAndVideoTags.current.forEach((a) => a.play());
+			audioAndVideoTags.current.forEach((a) =>
+				a.play('player play() was called and playing audio from a click'),
+			);
 
 			imperativePlaying.current = true;
 			setPlaying(true);