Yellow-Dog-Man
Resonite gets stuck at "Syncing X items" whenever I close it
Describe the bug?
Whenever I close resonite, it gets stuck on a "syncing 1-2 items" screen, until I force close it.
To Reproduce
Simply close resonite.
Expected behavior
Close in a reasonably short time.
Screenshots
Resonite Version Number
Beta 2025.3.25.1348
What Platforms does this occur on?
Windows
What headset if any do you use?
Desktop (also occurs in VR)
Log Files
DESKTOP-0GAEIM3 - 2025.3.25.1348 - 2025-03-25 22_25_21.log
Resonite was stuck saving with no progress for 2-3 minutes, I then closed it again to obtain this log.
Additional Context
This has happened for me since I first started using resonite, and has persisted across multiple OS reinstalls, so I suspect it's something wrong with my account...?
Reporters
Resonite username: bd_
Looking at the logs, I see a large chunk of unsynced asset changes to your home world. Do you also a sync error on the top on your menu?
6:38:01 PM.914 ( 60 FPS) Exception deserializing SkyFrost.Base.CloudflareChunkResult response from PUT:https://skyfrost-archive.resonite.com/assets/20726:20726:fd19cfa341564a898d854fe10fb4429f:U-1Nj73SRfaDY:6636cff36e443df77e6bdbb9a9bb307e03d4ce0bfcf9ed76b945aefc4357ec10
Exception:
System.Text.Json.JsonException: The input does not contain any JSON tokens. Expected the input to start with a valid JSON token, when isFinalBlock is true. Path: $ | LineNumber: 0 | BytePositionInLine: 0. ---> System.Text.Json.JsonReaderException: The input does not contain any JSON tokens. Expected the input to start with a valid JSON token, when isFinalBlock is true. LineNumber: 0 | BytePositionInLine: 0.
at System.Text.Json.ThrowHelper.ThrowJsonReaderException (System.Text.Json.Utf8JsonReader& json, System.Text.Json.ExceptionResource resource, System.Byte nextByte, System.ReadOnlySpan`1[T] bytes) [0x00009] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
at System.Text.Json.Utf8JsonReader.Read () [0x00035] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
at System.Text.Json.Serialization.JsonConverter`1[T].ReadCore (System.Text.Json.Utf8JsonReader& reader, T& value, System.Text.Json.JsonSerializerOptions options, System.Text.Json.ReadStack& state) [0x00018] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
--- End of inner exception stack trace ---
at System.Text.Json.ThrowHelper.ReThrowWithPath (System.Text.Json.ReadStack& state, System.Text.Json.JsonReaderException ex) [0x0007c] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
at System.Text.Json.Serialization.JsonConverter`1[T].ReadCore (System.Text.Json.Utf8JsonReader& reader, T& value, System.Text.Json.JsonSerializerOptions options, System.Text.Json.ReadStack& state) [0x000f0] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
at System.Text.Json.Serialization.Metadata.JsonTypeInfo`1[T].ContinueDeserialize (System.Text.Json.Serialization.ReadBufferState& bufferState, System.Text.Json.JsonReaderState& jsonReaderState, System.Text.Json.ReadStack& readStack, T& value) [0x00029] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
at System.Text.Json.Serialization.Metadata.JsonTypeInfo`1+<DeserializeAsync>d__1[T].MoveNext () [0x000df] in <0f8ebac6194c4d218f18b1491bfdbbc0>:0
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <9577ac7a62ef43179789031239ba8798>:0
at System.Run
Seems suspicious?
(note, the log currently is truncated, so I have a partial stack trace here...)
Hmm. This time when I left it on an empty local session for a while, it eventually finished syncing and shut down quickly. Loading into my home at next startup, it again got stuck on syncing 1 item on shutdown.
One thing of note (from the logs when it succeeded at syncing):
6:38:02 PM.121 ( 60 FPS) Asset 6636cff36e443df77e6bdbb9a9bb307e03d4ce0bfcf9ed76b945aefc4357ec10 uploaded in 00:00:01.1712400. Average rate: 17.28 kB/s
That seems like a very slow upload rate (I have 1gbit internet at home)...
DESKTOP-0GAEIM3 - 2025.3.25.1348 - 2025-03-26 18_42_25.log
Hmm. After trying again - apparently my home is a very large asset? Though, an upload rate of 5.50 MB/s does seem low.
6:47:43 PM.579 ( 60 FPS) Preprocessing record: U-1Nj73SRfaDY:R-Home
6:47:47 PM.120 ( 60 FPS) Asset e38d7cb68924a87e79f930a3fbcaf289acd1d682f3263b25226b3e9919200eba uploaded in 00:00:01.5798907. Average rate: 5.50 MB/s
6:47:47 PM.522 ( 60 FPS) Finished sync for U-1Nj73SRfaDY:R-Home. Local: 33, Global: 30
Oops, read those timestamps wrong. So it's not a very large asset, it just got... stuck for a while, but eventually succeeded?
And... it's still reproducible. Even if it succeeds at syncing once, the next time around it's waiting for multiple minutes again.
does this happen if you exit and discard homes? if you're using the default cloud home, it has a lot of stuff in it, causing it to take a couple minutes to sync fully when you exit while saving homes (pressing the "x" button is the same as exiting while saving homes)
Does this issue still occur? Cloudflare had an incident recently and it looks like that might've broken the sync temporarily based on some of the logs.
Still occurring. I'll post another log after waiting many minutes for it to finish...
DESKTOP-0GAEIM3 - 2025.3.27.1177 - 2025-03-27 17_37_53.log
This time it took about four minutes on "syncing 1 item"
I see a large chunk of unsynced asset changes to your home world
I was going to say, if it happens every time, are you telling it to "save and exit homes" and its just resyncing your home world every time your exiting which makes it feel like its taking forever?
I've reproed this in sessions where I didn't even open my home world. I also tried creating a new home world, and was still having this issue. However - as of yesterday, this is no longer an issue (for now, at least?). Not sure if something changed on the server side?
Edit: Happening again :/
Still happening. What more information is needed here? Also possibly related: #4483
Here's a more recent log if it helps:
DESKTOP-0GAEIM3 - 2025.5.23.1096 - 2025-05-27 19_54_33.log
It did shut down eventually, but took a very long time to do so.
I think this has what it needs, but we haven't been able to look at it yet.
@Gawdl3y Would you have interest into looking into this one?
Note that after letting it fully drain, then clearing my cache, it's shutting down quickly again. However, given that it's gone away and come back a few times, I'm sure it'll be back again :/
I instrumented my client with a mod to measure the time spend on various parts of the sync process. Here's what I found:
I opened my home world, saved, and exited, and resonite proceeded to spend ~5 minutes here:
3:51:02 PM.744 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<System.Boolean> FrooxEngine.EngineRecordUploadTask::CollectAssets(System.Threading.CancellationToken cancelationToken) took 291615 ms
Looking into what CollectAssets is doing in more detail, it seems to be processing each asset serially.
4:06:37 PM.976 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<SkyFrost.Base.CloudResult`1<SkyFrost.Base.AssetInfo>> SkyFrost.Base.AssetInterface::GetGlobalAssetInfo(System.String hash) took 196 ms
4:06:37 PM.978 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<FrooxEngine.Store.AssetRecord> FrooxEngine.Store.LocalDB::TryFetchAssetRecordAsync(System.Uri assetURL) took 1 ms
4:06:37 PM.978 ( 60 FPS) [SlowSync] AssetRecord resdb:///REDACTED fetched with record == null? True
4:06:38 PM.178 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<SkyFrost.Base.CloudResult`1<SkyFrost.Base.AssetInfo>> SkyFrost.Base.AssetInterface::GetGlobalAssetInfo(System.String hash) took 200 ms
4:06:38 PM.179 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<FrooxEngine.Store.AssetRecord> FrooxEngine.Store.LocalDB::TryFetchAssetRecordAsync(System.Uri assetURL) took 0 ms
4:06:38 PM.179 ( 60 FPS) [SlowSync] AssetRecord resdb:///REDACTED fetched with record == null? False
4:06:38 PM.181 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task FrooxEngine.Store.LocalDB::StoreAssetRecordAsync(System.Uri assetURL, System.String path, System.Byte[] encryptionKey) took 0 ms
[several 0ms lines skipped]
4:06:38 PM.201 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<System.String> FrooxEngine.Store.LocalDB::StoreCacheRecordAsync(System.Uri assetURL, System.String path, System.Boolean encrypt) took 0 ms
4:06:38 PM.203 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task FrooxEngine.Store.LocalDB::StoreAssetRecordAsync(System.Uri assetURL, System.String path, System.Byte[] encryptionKey) took 0 ms
4:06:38 PM.203 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<System.String> FrooxEngine.Store.LocalDB::StoreCacheRecordAsync(System.Uri assetURL, System.String path, System.Boolean encrypt) took 0 ms
4:06:38 PM.337 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task FrooxEngine.Store.LocalDB::StoreAssetRecordAsync(System.Uri assetURL, System.String path, System.Byte[] encryptionKey) took 133 ms
4:06:38 PM.337 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<System.String> FrooxEngine.Store.LocalDB::StoreCacheRecordAsync(System.Uri assetURL, System.String path, System.Boolean encrypt) took 133 ms
4:06:38 PM.340 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task FrooxEngine.Store.LocalDB::StoreAssetRecordAsync(System.Uri assetURL, System.String path, System.Byte[] encryptionKey) took 1 ms
[several 0ms lines skipped]
4:06:38 PM.348 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<System.String> FrooxEngine.Store.LocalDB::StoreCacheRecordAsync(System.Uri assetURL, System.String path, System.Boolean encrypt) took 0 ms
4:06:38 PM.350 ( 60 FPS) [SlowSync] AssetRecord resdb:///REDACTED fetched with record == null? True
4:06:38 PM.350 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<FrooxEngine.Store.AssetRecord> FrooxEngine.Store.LocalDB::TryFetchAssetRecordAsync(System.Uri assetURL) took 1 ms
4:06:38 PM.544 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<SkyFrost.Base.CloudResult`1<SkyFrost.Base.AssetInfo>> SkyFrost.Base.AssetInterface::GetGlobalAssetInfo(System.String hash) took 193 ms
4:06:38 PM.547 ( 60 FPS) [SlowSync] System.Threading.Tasks.Task`1<FrooxEngine.Store.AssetRecord> FrooxEngine.Store.LocalDB::TryFetchAssetRecordAsync(System.Uri assetURL) took 1 ms
It appears to me that the main problem here is that EngineRecordUploadTask.CollectAssets is calling GetGlobalAssetInfo serially for each of these records, at 200ms latency each (presumably this isn't as bad if you're in the EU, closer to the backend...). Additionally, we're calling this even though we should already know that these assets exist (because they were present in the prior version of the record).
Concrete suggestions:
- Reuse asset metadata from the prior version of the record, if a matching asset URI is present (which will be the case for most assets)
- Parallelize, and/or batch the GetGlobalAssetInfo call
I've created a mod that seems to resolve this issue for me. This works by parallelizing and prefetching the GetGlobalAssetInfo calls. It reduces the CollectAssets step from ~300 seconds to about 20 seconds. Feel free to reference it as a proof of concept here.
I considered reusing assets from the prior record version, but it appears GetRecord does not return the Manifest or AssetManifest fields, so this would need API server changes.
Before I make binary builds for this available, I would appreciate feedback on my throttling configuration, to make sure this isn't too heavy for the Resonite servers; I've got it currently limited to one call per 4ms, with at most 64 calls in-flight at a time. If I don't get feedback I'll probably release it in a week or so as a stop-gap solution for folks living far away (latency-wise) from the API servers.