Skip to content

Commit 4a205a7

Browse files
eordanoclaude
andcommitted
fix: emote play-timeout watchdog never fires, stranding emote intents
CharacterEmoteIntent.UpdatePlayTimeout had an operator-precedence bug (`playTimeout?.ElapsedTime ?? 0 + dt` parses as `?? (0 + dt)`) that froze ElapsedTime at the first frame's dt, so the #6531 60s unstuck timeout never fired; the tick was also only reachable on one parked sub-path inside CharacterEmoteSystem.ConsumeEmoteIntent. A scene emote that parks (breaks mid-cinematic) and is then evicted from the memory-pressure cache sweep (frequent on Mac) leaves a permanent CharacterEmoteIntent that silently blocks every user emote until client restart. Fixes #9485 Related: #6531 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
1 parent 80ee758 commit 4a205a7

5 files changed

Lines changed: 132 additions & 13 deletions

File tree

Explorer/Assets/DCL/AvatarRendering/Emotes/Components/CharacterEmoteIntent.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,7 @@ public void UpdateRemoteId(URN emoteId)
3131
public bool UpdatePlayTimeout(float dt)
3232
{
3333
// Timeout access returns a temporary value. We need to reassign the field or we lose the changes
34-
playTimeout = new LoadTimeout(playTimeout?.Timeout ?? StreamableLoadingDefaults.TIMEOUT, playTimeout?.ElapsedTime ?? 0 + dt);
34+
playTimeout = new LoadTimeout(playTimeout?.Timeout ?? StreamableLoadingDefaults.TIMEOUT, (playTimeout?.ElapsedTime ?? 0) + dt);
3535
bool result = playTimeout.Value.IsTimeout;
3636
return result;
3737
}

Explorer/Assets/DCL/AvatarRendering/Emotes/Systems/Play/CharacterEmoteSystem.cs

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -280,6 +280,17 @@ private void ConsumeEmoteIntent([Data] float dt, Entity entity,
280280
// it's very important to catch any exception here to avoid not consuming the emote intent, so we don't infinitely create props
281281
try
282282
{
283+
// Fixes https://github.com/decentraland/unity-explorer/issues/6531
284+
// Rarely happens for an unknown reason that emote.AssetResults[bodyShape] is null, provoking the emote intent to never finish,
285+
// thus props of the previous emote cannot be disposed either.
286+
// By setting a timeout we force unstuck the process
287+
if (emoteIntent.UpdatePlayTimeout(dt))
288+
{
289+
ReportHub.LogError(GetReportData(), $"Cant play emote {emoteId} timeout reached.");
290+
World.Remove<CharacterEmoteIntent>(entity);
291+
return;
292+
}
293+
283294
// we wait until the avatar finishes moving to trigger the emote,
284295
// avoid the case where: you stop moving, trigger the emote, the emote gets triggered and next frame it gets cancelled because inertia keeps moving the avatar
285296
// We also avoid triggering the emote while the character is jumping or landing, as the landing animation breaks the emote flow if they have props
@@ -312,17 +323,6 @@ private void ConsumeEmoteIntent([Data] float dt, Entity entity,
312323
return;
313324
}
314325

315-
// Fixes https://github.com/decentraland/unity-explorer/issues/6531
316-
// Rarely happens for an unknown reason that emote.AssetResults[bodyShape] is null, provoking the emote intent to never finish,
317-
// thus props of the previous emote cannot be disposed either.
318-
// By setting a timeout we force unstuck the process
319-
if (emoteIntent.UpdatePlayTimeout(dt))
320-
{
321-
ReportHub.LogError(GetReportData(), $"Cant play emote {emoteId} timeout reached.");
322-
World.Remove<CharacterEmoteIntent>(entity);
323-
return;
324-
}
325-
326326
BodyShape bodyShape = avatarShapeComponent.BodyShape;
327327
StreamableLoadingResult<AttachmentRegularAsset>? assetResult = emote.AssetResults[bodyShape];
328328

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,43 @@
1+
using ECS.StreamableLoading;
2+
using NUnit.Framework;
3+
4+
namespace DCL.AvatarRendering.Emotes.Tests
5+
{
6+
public class CharacterEmoteIntentShould
7+
{
8+
[Test]
9+
public void UpdatePlayTimeout_AccumulateElapsedTimeAcrossCalls_ReturnTrueOnceTotalReachesTimeout()
10+
{
11+
var intent = new CharacterEmoteIntent();
12+
13+
// One call per simulated second, mirroring how ConsumeEmoteIntent ticks this every frame with that frame's dt.
14+
var timedOutBeforeLastSecond = false;
15+
16+
for (var second = 0; second < StreamableLoadingDefaults.TIMEOUT - 1; second++)
17+
timedOutBeforeLastSecond |= intent.UpdatePlayTimeout(1f);
18+
19+
Assert.IsFalse(timedOutBeforeLastSecond,
20+
"Must not report a timeout before StreamableLoadingDefaults.TIMEOUT seconds of elapsed time have accumulated.");
21+
22+
var timedOutAtTimeoutSecond = intent.UpdatePlayTimeout(1f);
23+
24+
Assert.IsTrue(timedOutAtTimeoutSecond,
25+
"Elapsed time must accumulate across calls (each call's dt added to the running total) so IsTimeout fires " +
26+
"once the total reaches StreamableLoadingDefaults.TIMEOUT seconds. This is the #6531 unstuck watchdog for a " +
27+
"stranded CharacterEmoteIntent (see emote-lock-after-fish-catch). Fails at the pin because " +
28+
"`playTimeout?.ElapsedTime ?? 0 + dt` parses as `?? (0 + dt)`: once playTimeout is non-null the right side " +
29+
"of `??` is never evaluated, so ElapsedTime is reassigned to itself and freezes at the first call's dt " +
30+
"forever, and IsTimeout never fires.");
31+
}
32+
33+
[Test]
34+
public void UpdatePlayTimeout_ReturnFalse_OnFirstCallBeforeTimeoutElapsed()
35+
{
36+
var intent = new CharacterEmoteIntent();
37+
38+
var result = intent.UpdatePlayTimeout(1f);
39+
40+
Assert.IsFalse(result);
41+
}
42+
}
43+
}

Explorer/Assets/DCL/AvatarRendering/Emotes/Tests/CharacterEmoteIntentShould.cs.meta

Lines changed: 2 additions & 0 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

Explorer/Assets/DCL/AvatarRendering/Emotes/Tests/CharacterEmoteSystemShould.cs

Lines changed: 75 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,24 @@
11
using Arch.Core;
2+
using CommunicationData.URLHelpers;
3+
using DCL.AvatarRendering.AvatarShape.Components;
24
using DCL.AvatarRendering.AvatarShape.UnityInterface;
35
using DCL.AvatarRendering.Emotes.Play;
6+
using DCL.AvatarRendering.Loading.Assets;
7+
using DCL.AvatarRendering.Loading.Components;
48
using DCL.Character.Components;
59
using DCL.DebugUtilities;
610
using DCL.Diagnostics;
11+
using DCL.ECSComponents;
712
using DCL.Multiplayer.Emotes;
813
using ECS.SceneLifeCycle;
14+
using ECS.StreamableLoading;
15+
using ECS.StreamableLoading.Common.Components;
916
using ECS.TestSuite;
1017
using NSubstitute;
1118
using NUnit.Framework;
1219
using SceneRunner.Scene;
1320
using UnityEngine;
21+
using Utility.Animations;
1422
using Object = UnityEngine.Object;
1523

1624
namespace DCL.AvatarRendering.Emotes.Tests
@@ -22,6 +30,7 @@ public class CharacterEmoteSystemShould : UnitySystemTestBase<CharacterEmoteSyst
2230

2331
private ScenesCache scenesCache = null!;
2432
private IEmotesMessageBus messageBus = null!;
33+
private IEmoteStorage emoteStorage = null!;
2534
private IAvatarView avatarView = null!;
2635
private GameObject poolRoot = null!;
2736
private GameObject audioSourcePrefab = null!;
@@ -38,8 +47,9 @@ public void Setup()
3847

3948
scenesCache = new ScenesCache();
4049
messageBus = Substitute.For<IEmotesMessageBus>();
50+
emoteStorage = Substitute.For<IEmoteStorage>();
4151

42-
system = new CharacterEmoteSystem(world, Substitute.For<IEmoteStorage>(), messageBus, emotePlayer,
52+
system = new CharacterEmoteSystem(world, emoteStorage, messageBus, emotePlayer,
4353
Substitute.For<IDebugContainerBuilder>(), localSceneDevelopment: false, scenesCache);
4454

4555
avatarView = Substitute.For<IAvatarView>();
@@ -91,6 +101,70 @@ public void StopSceneEmoteWhenItsSceneIsNoLongerLoaded()
91101
messageBus.Received().SendStop();
92102
}
93103

104+
/// <summary>
105+
/// Regression for the "emote-lock-after-fish-catch" bug: a scene emote whose asset never resolves
106+
/// (e.g. evicted from the memory-pressure cache sweep before it ever played, as happens with the
107+
/// Genesis Plaza fishing catch/reveal emotes when the cinematic breaks) leaves a stranded
108+
/// CharacterEmoteIntent on the player entity. UpdateEmoteInputSystem.TriggerEmote is
109+
/// [None(typeof(CharacterEmoteIntent))], so a stranded intent silently blocks every user emote
110+
/// (slot shortcuts and the wheel) until the #6531 play-timeout watchdog removes it.
111+
/// </summary>
112+
[Test]
113+
public void RemoveStrandedCharacterEmoteIntentAfterPlayTimeoutElapses()
114+
{
115+
// The fixed watchdog path legitimately emits "[Error] Cant play emote ... timeout reached."
116+
// (pre-existing ReportHub.LogError relocated by potential-fix.patch); without this the
117+
// Unity Test Framework fails the test on the unhandled error log. Set inside the body:
118+
// the framework resets LogAssert state after [SetUp], before the test body runs.
119+
UnityEngine.TestTools.LogAssert.ignoreFailingMessages = true;
120+
121+
// Arrange: a full-body scene emote resolved in the storage but whose per-body-shape asset
122+
// never arrived (AssetResults entry stays null), so ConsumeEmoteIntent keeps parking on the
123+
// "Loading not complete" branch every frame instead of playing or failing outright.
124+
IAvatarView strandedAvatarView = Substitute.For<IAvatarView>();
125+
126+
// Grounded and not jumping/moving: bypasses the animator park gate so the query reaches the
127+
// emote-storage branch below instead of parking earlier for an unrelated reason.
128+
strandedAvatarView.GetAnimatorBool(AnimationHashes.GROUNDED).Returns(true);
129+
130+
IEmote emote = Substitute.For<IEmote>();
131+
emote.IsLoading.Returns(false);
132+
133+
// Empty results: the asset is not resident (e.g. evicted with a zero refcount before it ever
134+
// played), so ConsumeEmoteIntent takes the "assetResult == null" return every frame.
135+
emote.AssetResults.Returns(new StreamableLoadingResult<AttachmentRegularAsset>?[BodyShape.COUNT]);
136+
137+
emoteStorage.TryGetElement(Arg.Any<URN>(), out Arg.Any<IEmote>())
138+
.Returns(call =>
139+
{
140+
call[1] = emote;
141+
return true;
142+
});
143+
144+
Entity strandedEntity = world.Create(
145+
new CharacterEmoteComponent(),
146+
new CharacterEmoteIntent
147+
{
148+
EmoteId = new URN("urn:decentraland:off-chain:scene-emote:pond-fishing_catch-false"),
149+
Mask = AvatarEmoteMask.AemFullBody,
150+
},
151+
strandedAvatarView,
152+
new AvatarShapeComponent { BodyShape = BodyShape.MALE });
153+
154+
// Act: simulate more than StreamableLoadingDefaults.TIMEOUT seconds of frames, one second of
155+
// dt at a time. A single call with a large dt would not reproduce the pin's bug (the very
156+
// first call is unaffected by the precedence bug — see CharacterEmoteIntentShould), so the
157+
// repeated small-dt calls are load-bearing for the regression.
158+
for (var second = 0; second < StreamableLoadingDefaults.TIMEOUT + 1; second++)
159+
system!.Update(1f);
160+
161+
// Assert
162+
Assert.IsFalse(world.Has<CharacterEmoteIntent>(strandedEntity),
163+
"A CharacterEmoteIntent whose asset never resolves must expire after StreamableLoadingDefaults.TIMEOUT " +
164+
"seconds via the #6531 watchdog, instead of permanently blocking UpdateEmoteInputSystem.TriggerEmote's " +
165+
"[None(CharacterEmoteIntent)] gate (the restart-only emote lock from emote-lock-after-fish-catch).");
166+
}
167+
94168
private static ISceneFacade NewSceneFacadeWithName(string name)
95169
{
96170
ISceneData sceneData = Substitute.For<ISceneData>();

0 commit comments

Comments
 (0)