1847619 - Updating from 115 to 116 with OPFS entries regresses file access

Status: RESOLVED FIXED

(Core :: DOM: File, defect)

Description

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Not sure exactly how and there's no minimal repro yet, but the known repro steps are:

1. Get a 115.0.3 profile by mozregression --repo mozilla-release --launch 115.0.3 --arg https://creativecloud.adobe.com/photoshop --profile-persistence reuse --profile $env:USERPROFILE/adobe-photoshop-profile (set your own --profile directory)
2. Sign in to Photoshop https://creativecloud.adobe.com/photoshop and create a document
3. Close, and this time use the profile with 116.0.1 by mozregression --repo mozilla-release --launch 116.0.1 --arg https://creativecloud.adobe.com/photoshop --profile-persistence clone --profile $env:USERPROFILE/adobe-photoshop-profile
4. Open the same document. This triggers a warning without call stack: worker sent an error! https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:10571474: RuntimeError: index out of bounds
5. Refresh the tab, which triggers an error:

Could not open "jumping-man (3)" Failed to write server bindings of component:3022a490-aac5-470f-8870-3252bb59e00c to pushJournal. apollo_web.a1f4fd4e2846bbfd72ed.js:1:47963
    19408354 https://photoshop.adobe.com/apollo-assets/apollo_web.a1f4fd4e2846bbfd72ed.js:1
    runEmAsmFunction https://photoshop.adobe.com/apollo-assets/apollo_web.a1f4fd4e2846bbfd72ed.js:1
    _emscripten_asm_const_int https://photoshop.adobe.com/apollo-assets/apollo_web.a1f4fd4e2846bbfd72ed.js:1
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:4490639
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:663750
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:1422137
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:19406492
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:33955730
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:35387012
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:19182023
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:33252422
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:10579147
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:2874324
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:35870335
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:871126
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:5183294
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:14963066
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:30122636
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:6989989
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:29911142
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:16848868
    <anonymous> https://photoshop.adobe.com/apollo-assets/apollo_web.283f2fd4b87ecc0a5763.wasm:24772395
    invokeEntryPoint https://photoshop.adobe.com/apollo-assets/apollo_web.a1f4fd4e2846bbfd72ed.js:1
    handleMessage https://photoshop.adobe.com/apollo-assets/apollo_web.worker.a81cf4cdc29.js:1

This doesn't happen with a fresh profile made from 116.

Per my test bug 1818718 first caused the issue and then bug 1824305 slightly changed the behavior.

Comment 1

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Attachment: firefox-adobe-photoshop-logs-115.zip

This is the log with MOZ_LOG=OPFS:5 from 115,

Comment 2

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Attachment: firefox-adobe-photoshop-logs-116.zip

And this for 116. I don't immediately see what's wrong there via these logs, though.

Comment 3

[Mike Conca [:mconca]]

[Tracking Requested - why for this release]:
This issue appears to be affecting all Firefox users of Adobe Photoshop online who upgrade from Fx115 to 116, preventing them accessing old or creating new files.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

The bug is marked as tracked for firefox116 (release). However, the bug still isn't assigned.

:jstutte, could you please find an assignee for this tracked bug? Given that it is a regression and we know the cause, we could also simply backout the regressor. If you disagree with the tracking decision, please talk with the release managers.

For more information, please visit BugBot documentation.

Comment 5

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

I think this is more of S2 per comment #3. There's a known workaround: to wipe the OPFS storage, but that's not satisfactory.

Comment 6

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Following the repro steps in comment #0 on debug build triggers a failure from DOM Worker, which crashes the tab but does not give a good call stack info because the worker is in WASM.

And refreshing the tab causes parent process assertion failure:

xul.dll!mozilla::dom::fs::data::FileSystemDatabaseManagerVersion001::SetUsageTracking::<lambda_0>::operator()<nsresult>(const nsresult & aRv) Line 1159 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\datamodel\FileSystemDatabaseManagerVersion001.cpp:1159)
xul.dll!mozilla::dom::fs::data::`anonymous namespace'::SetUsageTrackingImpl<`lambda at C:/Users/sasch/Documents/GitHub/gecko-dev/dom/fs/parent/datamodel/FileSystemDatabaseManagerVersion001.cpp:1152:24' &>(const nsCOMPtr<mozIStorageConnection> & aConnection, const mozilla::dom::fs::FileId & aFileId, bool aTracked, mozilla::dom::fs::data::FileSystemDatabaseManagerVersion001::SetUsageTracking::<lambda_0> & aOnMissingFile) Line 277 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\datamodel\FileSystemDatabaseManagerVersion001.cpp:277)
xul.dll!mozilla::dom::fs::data::FileSystemDatabaseManagerVersion001::SetUsageTracking(const mozilla::dom::fs::FileId & aFileId, bool aTracked) Line 1162 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\datamodel\FileSystemDatabaseManagerVersion001.cpp:1162)
xul.dll!mozilla::dom::fs::data::FileSystemDatabaseManagerVersion001::BeginUsageTracking(const mozilla::dom::fs::FileId & aFileId) Line 1065 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\datamodel\FileSystemDatabaseManagerVersion001.cpp:1065)
xul.dll!mozilla::dom::fs::data::FileSystemDataManager::LockExclusive(const nsTString<char> & aEntryId) Line 418 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\datamodel\FileSystemDataManager.cpp:418)
xul.dll!mozilla::dom::FileSystemAccessHandle::BeginInit() Line 172 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\FileSystemAccessHandle.cpp:172)
xul.dll!mozilla::dom::FileSystemAccessHandle::Create(RefPtr<mozilla::dom::fs::data::FileSystemDataManager> aDataManager, const nsTString<char> & aEntryId) Line 55 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\FileSystemAccessHandle.cpp:55)
xul.dll!mozilla::dom::FileSystemManagerParent::RecvGetAccessHandle(mozilla::dom::fs::FileSystemGetAccessHandleRequest && aRequest, std::function<void (mozilla::dom::fs::FileSystemGetAccessHandleResponse &&)> && aResolver) Line 126 (c:\Users\sasch\Documents\GitHub\gecko-dev\dom\fs\parent\FileSystemManagerParent.cpp:126)
xul.dll!mozilla::dom::PFileSystemManagerParent::OnMessageReceived(const IPC::Message & msg__) Line 589 (c:\Users\sasch\Documents\GitHub\gecko-dev\obj-dbg\ipc\ipdl\PFileSystemManagerParent.cpp:589)
xul.dll!mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy * aProxy, const IPC::Message & aMsg) Line 1811 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\glue\MessageChannel.cpp:1811)
xul.dll!mozilla::ipc::MessageChannel::DispatchMessage(mozilla::ipc::ActorLifecycleProxy * aProxy, mozilla::UniquePtr<IPC::Message,mozilla::DefaultDelete<IPC::Message>> aMsg) Line 1739 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\glue\MessageChannel.cpp:1739)
xul.dll!mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::ActorLifecycleProxy * aProxy, mozilla::ipc::MessageChannel::MessageTask & aTask) Line 1537 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\glue\MessageChannel.cpp:1537)
xul.dll!mozilla::ipc::MessageChannel::MessageTask::Run() Line 1642 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\glue\MessageChannel.cpp:1642)
xul.dll!mozilla::TaskQueue::Runner::Run() Line 264 (c:\Users\sasch\Documents\GitHub\gecko-dev\xpcom\threads\TaskQueue.cpp:264)
xul.dll!nsThreadPool::Run() Line 345 (c:\Users\sasch\Documents\GitHub\gecko-dev\xpcom\threads\nsThreadPool.cpp:345)
xul.dll!nsThread::ProcessNextEvent(bool aMayWait, bool * aResult) Line 1194 (c:\Users\sasch\Documents\GitHub\gecko-dev\xpcom\threads\nsThread.cpp:1194)
xul.dll!NS_ProcessNextEvent(nsIThread * aThread, bool aMayWait) Line 480 (c:\Users\sasch\Documents\GitHub\gecko-dev\xpcom\threads\nsThreadUtils.cpp:480)
xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate * aDelegate) Line 300 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\glue\MessagePump.cpp:300)
xul.dll!MessageLoop::RunInternal() Line 370 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\chromium\src\base\message_loop.cc:370)
xul.dll!MessageLoop::RunHandler() Line 364 (c:\Users\sasch\Documents\GitHub\gecko-dev\ipc\chromium\src\base\message_loop.cc:364)

I'll check whether this happens with fresh 116 profile or not. (Edit: it does not)

One noticeable thing is that I get a lot of "Exception thrown at 0x0000004BC7ED689D in firefox.exe: 0xC000001D: Illegal Instruction." from wasm, I wonder this is related? (Edit: It happens on a fresh profile, so probably not)

Comment 7

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Attachment: WIP: Bug 1847619 - Add more OPFS logs

Comment 8

[Kagami Rosylight [:saschanaz] (they/them) (OOO until 2024-10-06)]

Attachment: WIP: Bug 1847619 - Reverse the check return value

Depends on D185821

Comment 9

[Jan Varga [:janv]]

https://treeherder.mozilla.org/jobs?repo=try&revision=f933ecd39e9c21c26e950bfa19b79055417af026

Comment 10

[Jens Stutte [:jstutte]]

Assigning to Jan (though this is really a joint debugging effort).

Comment 11

[Dianna Smith [:diannaS]]

fixed by bug 1847989 for 117.0b8 and 116.0.3 dot release