search

deltachat / deltachat-desktop

Email-based instant messaging for Desktop.
GNU General Public License v3.0
906 stars 167 forks source link

Crash when trying to go back from "Add Account" or "Delete Account" on Microsoft Store version #3959

Open WofWca opened 2 months ago

WofWca commented 2 months ago

This works fine on a manually downloaded 1.46.1, which is also built from 899f196d. Note that the manually installed one is 32 bit, and the Mircosoft Store is 64. Idk if this matters.

Here I clicked "Add Account" at 08:43:00, then clicked "back" at 08:44:09, then "back" again at 08:46:00, then "back" again at 08:49:00, then "Let's get started" at 08:49:19, after which the crash occurs:

2024-06-19T08:42:36.599Z    core/event              INFO    ""  1   "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-19T08:42:36.662Z    core/event              INFO    ""  1   "src/imap/idle.rs:64: INBOX: Idle entering wait-on-remote state"
2024-06-19T08:43:00.709Z    core/event              INFO    ""  64  "src/sql/migrations.rs:950: Created new database; [migration] v68-v114"
2024-06-19T08:43:00.710Z    core/event              INFO    ""  64  "src/sql.rs:294: Opened database \"C:\\\\Users\\\\wofwc\\\\AppData\\\\Local\\\\DeltaChat\\\\accounts\\\\redacted-aaaaaaaa-aaaaaaa-aaaaaaa\\\\dc.db\"."
2024-06-19T08:43:00.724Z    renderer/stores/SettingsStore   INFO    ""  "cleared settings store"
2024-06-19T08:43:00.731Z    core/event              INFO    ""  1   "src/scheduler.rs:108: stopping IO"
2024-06-19T08:43:00.733Z    core/event              INFO    ""  1   "src/scheduler.rs:826: Shutting down SMTP loop."
2024-06-19T08:43:00.769Z    core/event              INFO    ""  1   "src/scheduler.rs:429: shutting down inbox loop"
2024-06-19T08:43:00.774Z    core/event              WARNING ""  64  "src/context.rs:465: can not start io on a context that is not configured"
2024-06-19T08:43:00.774Z    renderer/ScreenController   INFO    ""  "system_info"   {"arch":"64","deltachat_core_version":"v1.140.2","level":"awesome","num_cpus":"redacted","sqlite_version":"redacted"}
2024-06-19T08:43:00.777Z    renderer/ScreenController   INFO    ""  "account_info"  {"arch":"64","redacted":"redacted","blobdir":"C:\\Users\\me\\AppData\\Local\\DeltaChat\\accounts\\redacted-aaaaaaaa-aaaaaaa-aaaaaaa\\dc.db-blobs","redacted": "redacted","database_dir":"C:\\Users\\me\\AppData\\Local\\DeltaChat\\accounts\\redacted-aaaaaaaa-aaaaaaa-aaaaaaa\\dc.db"}
2024-06-19T08:43:01.775Z    main/state              INFO    ""  "Saving state to C:\\Users\\me\\AppData\\Local\\DeltaChat\\config.json"
2024-06-19T08:44:09.278Z    renderer/stores/SettingsStore   INFO    ""  "cleared settings store"
2024-06-19T08:44:10.286Z    main/state              INFO    ""  "Saving state to C:\\Users\\me\\AppData\\Local\\DeltaChat\\config.json"
2024-06-19T08:45:10.567Z    renderer/components/OnboardingScreen    ERROR   "\ni (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/components/screens/WelcomeScreen/OnboardingScreen.tsx:53:13)"   "unexpected error type" {"code":-1,"message":"failed to remove account data\n\nCaused by:\n    The process cannot access the file because it is being used by another process. (os error 32)"}
2024-06-19T08:45:10.569Z    renderer                ERROR   "\nfile:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/App.tsx:109:10"    "Unhandled Rejection:"  {"isTrusted":true}  {"code":-1,"message":"failed to remove account data\n\nCaused by:\n    The process cannot access the file because it is being used by another process. (os error 32)"}
2024-06-19T08:46:00.000Z    renderer/components/OnboardingScreen    ERROR   "\ni (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/components/screens/WelcomeScreen/OnboardingScreen.tsx:53:13)"   "unexpected error type" {"code":-1,"message":"account with id 64 doesn't exist anymore"}
2024-06-19T08:46:00.001Z    renderer                ERROR   "\nfile:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/App.tsx:109:10"    "Unhandled Rejection:"  {"isTrusted":true}  {"code":-1,"message":"account with id 64 doesn't exist anymore"}
2024-06-19T08:49:00.488Z    renderer/components/OnboardingScreen    ERROR   "\ni (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/components/screens/WelcomeScreen/OnboardingScreen.tsx:53:13)"   "unexpected error type" {"code":-1,"message":"account with id 64 doesn't exist anymore"}
2024-06-19T08:49:00.488Z    renderer                ERROR   "\nfile:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/App.tsx:109:10"    "Unhandled Rejection:"  {"isTrusted":true}  {"code":-1,"message":"account with id 64 doesn't exist anymore"}
2024-06-19T08:49:19.612Z    renderer/react-crashhandler ERROR   "\nhf.componentDidCatch (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/components/screens/CrashScreen.tsx:17:9),\nhf.o.componentDidCatch.n.callback (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:217:345),\nEg (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:131:408),\nYi (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:220:84),\nb (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:259:160),\nNf (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/scheduler/cjs/scheduler.production.min.js:18:343),\ngg (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:122:325),\ndr (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:252:279)"   "The app encountered an react error"    {"stack":"Error: no context selected\n    at selectedAccountId (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/ScreenController.tsx:365:11)\n    at c (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/src/renderer/components/helpers/ClickableLink.tsx:13:21)\n    at Ch (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:157:137)\n    at ck (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:267:460)\n    at bk (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:250:347)\n    at ak (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:250:278)\n    at Tj (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:250:138)\n    at c (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:243:163)\n    at b (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/react-dom/cjs/react-dom.production.min.js:123:115)\n    at Lt.unstable_runWithPriority (file:///C:/Program%20Files/WindowsApps/merlinux.DeltaChat_1.46.1.0_x64__v2ry5hvxhdhyy/app/resources/app.asar/node_modules/scheduler/cjs/scheduler.production.min.js:18:343)","message":"no context selected"}

The manually installed version's log (where everything works fine):

024-06-19T08:19:50.124Z core/event              INFO    ""  1   "src/imap/idle.rs:64: INBOX: Idle entering wait-on-remote state"
2024-06-19T08:20:00.676Z    core/event              INFO    ""  62  "src/sql/migrations.rs:950: Created new database; [migration] v68-v114"
2024-06-19T08:20:00.677Z    core/event              INFO    ""  62  "src/sql.rs:294: Opened database redacted
2024-06-19T08:20:00.687Z    renderer/stores/SettingsStore   INFO    ""  "cleared settings store"
2024-06-19T08:20:00.693Z    core/event              INFO    ""  1   "src/scheduler.rs:108: stopping IO"
2024-06-19T08:20:00.695Z    core/event              INFO    ""  1   "src/scheduler.rs:826: Shutting down SMTP loop."
2024-06-19T08:20:00.710Z    core/event              INFO    ""  1   "src/scheduler.rs:429: shutting down inbox loop"
2024-06-19T08:20:00.713Z    core/event              WARNING ""  62  "src/context.rs:465: can not start io on a context that is not configured"
2024-06-19T08:20:00.713Z    renderer/ScreenController   INFO    ""  "system_info"   {"arch":"32","deltachat_core_version":"v1.140.2","level":"awesome",redacted
2024-06-19T08:20:00.716Z    renderer/ScreenController   INFO    ""  "account_info"  {"arch":"32",redacted
2024-06-19T08:20:01.713Z    main/state              INFO    ""  "Saving state to C:\\Users\\me\\AppData\\Local\\DeltaChat\\config.json"
2024-06-19T08:20:09.263Z    renderer/stores/SettingsStore   INFO    ""  "cleared settings store"
2024-06-19T08:20:09.299Z    core/event              INFO    ""  1   "src/chat.rs:4316: Device-message changelog-version-1.46.0-version1 already added."
2024-06-19T08:20:09.311Z    core/event              INFO    ""  1   "src/scheduler.rs:67: starting IO"
2024-06-19T08:20:09.319Z    renderer/ScreenController   INFO    ""  "system_info"   {"arch":"32","deltachat_core_version":"v1.140.2","level":"awesome",redacted
2024-06-19T08:20:09.319Z    core/event              INFO    ""  1   "src/scheduler.rs:389: starting inbox loop"
2024-06-19T08:20:09.323Z    core/event              INFO    ""  1   "src/imap.rs:333: Connecting to IMAP server"
2024-06-19T08:20:09.330Z    core/event              INFO    ""  1   "src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt"
2024-06-19T08:20:09.338Z    core/event              INFO    ""  1   "src/scheduler.rs:752: Starting SMTP loop."
2024-06-19T08:20:09.339Z    renderer/ScreenController   INFO    ""  "account_info"  {"arch":"32",redacted
2024-06-19T08:20:09.339Z    core/event              INFO    ""  1   "src/scheduler.rs:914: scheduler is running"
2024-06-19T08:20:09.348Z    core/event              INFO    ""  1   "src/smtp.rs:694: Selected rows from SMTP queue: []."
2024-06-19T08:20:09.349Z    core/event              INFO    ""  1   "src/smtp.rs:799: Sending MDNs."
2024-06-19T08:20:09.349Z    core/event              INFO    ""  1   "src/contact.rs:1841: Recently seen loop waiting for 0h 4m 34s or interrupt"
2024-06-19T08:20:09.350Z    core/event              INFO    ""  1   "src/scheduler.rs:787: SMTP fake idle started."
2024-06-19T08:20:09.351Z    core/event              INFO    ""  1   "src/scheduler.rs:815: SMTP has no messages to retry, waiting for interrupt."
2024-06-19T08:20:09.352Z    core/event              INFO    ""  1   "src/net.rs:72: Resolved redacted
2024-06-19T08:20:09.353Z    core/event              INFO    ""  1   "src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt"
redacted
2024-06-19T08:20:10.311Z    main/state              INFO    ""  "Saving state to C:\\Users\\me\\AppData\\Local\\DeltaChat\\config.json"
redacted
2024-06-19T08:20:10.694Z    core/event              INFO    ""  1   "src/imap/idle.rs:64: INBOX: Idle entering wait-on-remote state"
2024-06-19T08:20:25.872Z    main/menu               INFO    ""  "rebuilding menu with locale ru"

It appears like Core hangs on first "back" click, then on second click it tries to access the file but fails. But it's just my intuition. After the first "back" click it doesn't take much CPU time.

This is not a recent regression. I have been noticing this for a while, at least from 1.44, maybe earlier.

Simon-Laux commented 2 months ago

The process cannot access the file because it is being used by another process.

windows again (with its only one process can have a file handle at a time rule)... maybe we can just tell core to schedule it for deletion if it gets this error on windows, or somehow force that it become the sole process opening these files?

But now the interesting question would be what files are accessed, I guess blob files, but I'm not sure.

nicodh commented 3 weeks ago

Any progress on this?

WofWca commented 3 weeks ago

Not from me. It looks to me like it requires some core knowledge, which I don't have too much of.

link2xt commented 3 weeks ago

We have try_many_times workaround that we tried to remove at some point and then restored in https://github.com/deltachat/deltachat-core-rust/pull/4873 again because Windows CI failed due to the database not being closed. Now Delta Chat core tries to remove the folder 60 times for a minute, but apparently with microsoft store setup it is still not enough.

We should probably remove this try_many_times and find actual reason the database stays open for some time after the context is dropped.

There was also an old issue discussing similar problem: https://github.com/deltachat/deltachat-core-rust/issues/2695

On desktop the error can be ignored, worst case the database remains on disk but it is a small unconfigured database. Core does not garbage-collect accounts folder, maybe we should do it as well to get rid of such databases that we failed to delete.

I also opened core issue: https://github.com/deltachat/deltachat-core-rust/issues/5809

link2xt commented 3 weeks ago

I made a fix for the core: https://github.com/deltachat/deltachat-core-rust/pull/5814 Probably best thing to do now is to update the core to include this fix.

gerryfrancis commented 3 weeks ago

Basically this is how Windows works: Files stored in the Program Files (sub)folder(s) are protected by user access control (UAC) in a way only an elevated user (who has applied for administrator rights before) is allowed to write into. The above log of the Microsoft Store version of Delta Chat does not seem to write to the current user profile (path C:\Users\[current user]), but into the app folder instead, which is, what I believe, must not be permitted during runtime.

Edit: After looking into the log again, I have recognized that the database has been located in the user profile anyway, so mea culpa, and have a nice day!