search

signalapp / Signal-Desktop

A private messenger for Windows, macOS, and Linux.
https://signal.org/download
GNU Affero General Public License v3.0
14.66k stars 2.67k forks source link

Crashes with "JavaScript heap out of memory" #6016

Closed sajith closed 2 years ago

sajith commented 2 years ago

Bug Description

Signal Desktop has been crashing for me for the past couple of months. (Do not have exact dates or versions, sorry.) The earlier crashes were with Illegal instruction (core dumped) and the such, but the latest version crashes with an out of memory error. Please see below.

I get to see an unresponsive app window for a few minutes, and eventually it crashes, before I am actually able to do anything with the app.

I do have a fairly large database, from the beginning of my Signal Desktop usage:

$ ls -sh ~/.config/Signal/sql/db.sqlite 
705M /home/user/.config/Signal/sql/db.sqlite

I suspect that I might be able to run Signal if I close Firefox, but then I won't be able to submit this bug report. :-)

Steps to Reproduce

Launch it, and wait for it to crash. There are some hints when launching signal-desktop from the command line:

$ signal-desktop 
Set Windows Application User Model ID (AUMID) { appUserModelId: 'org.whispersystems.signal-desktop' }
NODE_ENV production
NODE_CONFIG_DIR /opt/Signal/resources/app.asar/config
NODE_CONFIG {}
ALLOW_CONFIG_MUTATIONS undefined
HOSTNAME undefined
NODE_APP_INSTANCE undefined
SUPPRESS_NO_CONFIG_WARNING undefined
SIGNAL_ENABLE_HTTP undefined
userData: /home/user/.config/Signal
config/get: Successfully read user config file
config/get: Successfully read ephemeral config file
making app single instance
{"level":30,"time":"2022-07-07T21:49:08.456Z","pid":333212,"hostname":"localghost","msg":"app ready"}
{"level":30,"time":"2022-07-07T21:49:08.458Z","pid":333212,"hostname":"localghost","msg":"starting version 5.47.0"}
{"level":30,"time":"2022-07-07T21:49:08.458Z","pid":333212,"hostname":"localghost","msg":"media access status [object Undefined] [object Undefined]"}
{"level":30,"time":"2022-07-07T21:49:08.459Z","pid":333212,"hostname":"localghost","msg":"got fast theme-setting value system"}
{"level":30,"time":"2022-07-07T21:49:08.465Z","pid":333212,"hostname":"localghost","msg":"got fast theme-setting value system"}
{"level":30,"time":"2022-07-07T21:49:08.465Z","pid":333212,"hostname":"localghost","msg":"got fast spellcheck setting true"}
{"level":30,"time":"2022-07-07T21:49:08.467Z","pid":333212,"hostname":"localghost","msg":"getSystemTraySetting had no flags and did no DB lookups. Returning DoNotUseSystemTray"}
{"level":30,"time":"2022-07-07T21:49:08.468Z","pid":333212,"hostname":"localghost","msg":"Initializing BrowserWindow config: {\"show\":false,\"width\":1120,\"height\":797,\"minWidth\":712,\"minHeight\":550,\"autoHideMenuBar\":false,\"titleBarStyle\":\"default\",\"titleBarOverlay\":false,\"backgroundColor\":\"#121212\",\"webPreferences\":{\"devTools\":false,\"spellcheck\":true,\"nodeIntegration\":false,\"nodeIntegrationInWorker\":false,\"contextIsolation\":false,\"preload\":\"[REDACTED]/preload.bundle.js\",\"backgroundThrottling\":false,\"enablePreferredSizeMode\":true,\"disableBlinkFeatures\":\"Accelerated2dCanvas,AcceleratedSmallCanvases\"},\"icon\":\"[REDACTED]/images/signal-logo-desktop-linux.png\",\"x\":196,\"y\":412}"}
libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
{"level":30,"time":"2022-07-07T21:49:08.663Z","pid":333212,"hostname":"localghost","msg":"spellcheck: user locale: en"}
{"level":30,"time":"2022-07-07T21:49:08.664Z","pid":333212,"hostname":"localghost","msg":"spellcheck: available spellchecker languages:  [\"af\",\"bg\",\"ca\",\"cs\",\"cy\",\"da\",\"de\",\"de-DE\",\"el\",\"en\",\"en-AU\",\"en-CA\",\"en-GB\",\"en-GB-oxendict\",\"en-US\",\"es\",\"es-419\",\"es-AR\",\"es-ES\",\"es-MX\",\"es-US\",\"et\",\"fa\",\"fo\",\"fr\",\"fr-FR\",\"he\",\"hi\",\"hr\",\"hu\",\"hy\",\"id\",\"it\",\"it-IT\",\"ko\",\"lt\",\"lv\",\"nb\",\"nl\",\"pl\",\"pt\",\"pt-BR\",\"pt-PT\",\"ro\",\"ru\",\"sh\",\"sk\",\"sl\",\"sq\",\"sr\",\"sv\",\"ta\",\"tg\",\"tr\",\"uk\",\"vi\"]"}
{"level":30,"time":"2022-07-07T21:49:08.664Z","pid":333212,"hostname":"localghost","msg":"spellcheck: setting languages to:  [\"en\"]"}
{"level":30,"time":"2022-07-07T21:49:08.664Z","pid":333212,"hostname":"localghost","msg":"got fast theme-setting value system"}
{"level":30,"time":"2022-07-07T21:49:08.683Z","pid":333212,"hostname":"localghost","msg":"MainSQL: updateSchema:\n  Current user_version: 60;\n  Most recent db schema: 60;\n  SQLite version: 3.37.2;\n  SQLCipher version: 4.5.1 community;\n  (deprecated) schema_version: 215;\n"}
{"level":30,"time":"2022-07-07T21:49:08.683Z","pid":333212,"hostname":"localghost","msg":"got fast spellcheck setting true"}
{"level":30,"time":"2022-07-07T21:49:08.711Z","pid":333212,"hostname":"localghost","msg":"System tray service: created"}
{"level":30,"time":"2022-07-07T21:49:08.711Z","pid":333212,"hostname":"localghost","msg":"System tray service: updating main window. Previously, there was not a window, and now there is"}
{"level":30,"time":"2022-07-07T21:49:08.711Z","pid":333212,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-07T21:49:08.711Z","pid":333212,"hostname":"localghost","msg":"Begin ensuring permissions"}
{"level":30,"time":"2022-07-07T21:49:08.726Z","pid":333212,"hostname":"localghost","msg":"Ensuring file permissions for 4 files"}
{"level":30,"time":"2022-07-07T21:49:08.728Z","pid":333212,"hostname":"localghost","msg":"Finish ensuring permissions in 17ms"}
{"level":30,"time":"2022-07-07T21:49:10.713Z","pid":333212,"hostname":"localghost","msg":"main window is ready-to-show"}
{"level":30,"time":"2022-07-07T21:49:10.714Z","pid":333212,"hostname":"localghost","msg":"showing main window"}
{"level":30,"time":"2022-07-07T21:49:10.715Z","pid":333212,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-07T21:49:11.229Z","pid":333212,"hostname":"localghost","msg":"Updating BrowserWindow config: %s {\"maximized\":false,\"autoHideMenuBar\":false,\"fullscreen\":false,\"width\":1120,\"height\":800,\"x\":196,\"y\":434}"}
{"level":30,"time":"2022-07-07T21:49:11.233Z","pid":333212,"hostname":"localghost","msg":"config/set: Saving ephemeral config to disk"}
{"level":30,"time":"2022-07-07T21:49:11.235Z","pid":333212,"hostname":"localghost","msg":"config/set: Saved ephemeral config to disk"}
{"level":30,"time":"2022-07-07T21:49:12.157Z","pid":333212,"hostname":"localghost","msg":"sending `database-ready`"}
{"level":30,"time":"2022-07-07T21:49:17.728Z","pid":333212,"hostname":"localghost","msg":"Prevent display sleep service: allowing display sleep"}
{"level":30,"time":"2022-07-07T21:49:31.140Z","pid":333212,"hostname":"localghost","msg":"updater/start: Updates disabled - not starting new version checks"}
{"level":30,"time":"2022-07-07T21:49:31.143Z","pid":333212,"hostname":"localghost","msg":"System tray service: setting unread count to 11"}
{"level":30,"time":"2022-07-07T21:49:31.143Z","pid":333212,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-07T21:49:31.662Z","pid":333212,"hostname":"localghost","msg":"App loaded - time: 23221"}
{"level":30,"time":"2022-07-07T21:49:31.662Z","pid":333212,"hostname":"localghost","msg":"SQL init - time: 243"}
{"level":30,"time":"2022-07-07T21:49:31.663Z","pid":333212,"hostname":"localghost","msg":"Preload - time: 987"}
{"level":30,"time":"2022-07-07T21:49:31.663Z","pid":333212,"hostname":"localghost","msg":"WebSocket connect - time: 7897"}
{"level":30,"time":"2022-07-07T21:49:31.663Z","pid":333212,"hostname":"localghost","msg":"Processed count: 758"}
{"level":30,"time":"2022-07-07T21:49:31.663Z","pid":333212,"hostname":"localghost","msg":"Messages per second: 52.87019599637302"}
{"level":30,"time":"2022-07-07T21:49:32.298Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query saveMessages duration=56ms"}
{"level":30,"time":"2022-07-07T21:49:33.692Z","pid":333212,"hostname":"localghost","msg":"System tray service: setting unread count to 12"}
{"level":30,"time":"2022-07-07T21:49:33.692Z","pid":333212,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-07T21:50:12.212Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=14921ms"}
{"level":30,"time":"2022-07-07T21:50:34.922Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=15537ms"}
{"level":30,"time":"2022-07-07T21:50:59.312Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=17422ms"}
{"level":30,"time":"2022-07-07T21:51:23.259Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=15517ms"}
{"level":30,"time":"2022-07-07T21:51:37.728Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=16233ms"}
{"level":30,"time":"2022-07-07T21:52:10.658Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=20331ms"}
{"level":30,"time":"2022-07-07T21:52:44.132Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=22586ms"}
{"level":30,"time":"2022-07-07T21:53:01.844Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=19119ms"}
{"level":30,"time":"2022-07-07T21:58:05.080Z","pid":333212,"hostname":"localghost","msg":"MainSQL: slow query saveMessages duration=191723ms"}

<--- Last few GCs --->

[333212:0x3e100063c000]   547740 ms: Scavenge 2911.6 (2957.3) -> 2910.9 (2964.6) MB, 45.6 / 0.0 ms  (average mu = 0.988, current mu = 0.985) allocation failure; 
[333212:0x3e100063c000]   547831 ms: Scavenge 2918.6 (2964.6) -> 2919.3 (2965.3) MB, 47.9 / 0.0 ms  (average mu = 0.988, current mu = 0.985) allocation failure; 
[333212:0x3e100063c000]   547915 ms: Scavenge 2919.4 (2965.3) -> 2918.8 (2970.6) MB, 83.5 / 0.0 ms  (average mu = 0.988, current mu = 0.985) allocation failure; 

<--- JS stacktrace --->

FATAL ERROR: Scavenger: semi-space copy Allocation failed - JavaScript heap out of memory
Aborted (core dumped)

Actual Result:

Crash a few minutes after launching Signal Desktop. This is consistent.

Expected Result:

Working Signal Desktop, with no crashes, no high CPU/memory usage, angels singing, and a world without anymore new Electron apps. And oh, a choice of light-weight Signal apps, third-party or otherwise. ;-)

(Sorry, could not help. Signal has been pretty great until it wasn't, but this recent experience is making me question my choices.)

Screenshots

Before the crash:

signal-screenshot

Platform Info

Signal Version:

5.47.0

Operating System:

Debian 11.3.

Linked Device Version:

5.41.14

Link to Debug Log

Cannot submit logs from the app because it crashes before it becomes usable.

sajith commented 2 years ago

Sometimes the window looks like this:

Screenshot from 2022-07-07 18-02-20

sajith commented 2 years ago

Just for fun, I added some swap (with fallocate -l 32G 32G.bin; sudo chmod 0600 32G.bin; sudo chown 0 32G.bin; sudo swapon 32G.bin, because I went with Debian installer's defaults and ended up with 1G of swap), launched signal-desktop again, and got the same crash.

Also timed it with time signal-desktop:

real    9m40.866s
user    7m30.017s
sys 1m11.246s
sajith commented 2 years ago

I closed Firefox, which freed up some memory, and launched Signal Desktop again. According to free -h, I had 18Gi free RAM and 32Gi free swap at that time. The first time I got to see this fun window for the first time:

Screenshot from 2022-07-07 18-46-14

Upon running again, Signal Desktop crashed with these now-familiar messages:

[...]

{"level":30,"time":"2022-07-07T23:47:53.075Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=11114ms"}
{"level":30,"time":"2022-07-07T23:48:13.882Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=12033ms"}
{"level":30,"time":"2022-07-07T23:48:30.770Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=13918ms"}
{"level":30,"time":"2022-07-07T23:48:52.873Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=13480ms"}
{"level":30,"time":"2022-07-07T23:49:13.999Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=14433ms"}
{"level":30,"time":"2022-07-07T23:49:32.708Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=14300ms"}
{"level":30,"time":"2022-07-07T23:54:46.283Z","pid":340948,"hostname":"nonzen","msg":"MainSQL: slow query saveMessages duration=170360ms"}

<--- Last few GCs --->

[340948:0x3c00644000]   462305 ms: Scavenge 2911.5 (2957.3) -> 2910.8 (2964.6) MB, 50.4 / 0.0 ms  (average mu = 0.974, current mu = 0.978) allocation failure; 
[340948:0x3c00644000]   462408 ms: Scavenge 2918.5 (2964.6) -> 2919.2 (2965.3) MB, 49.8 / 0.0 ms  (average mu = 0.974, current mu = 0.978) allocation failure; 
[340948:0x3c00644000]   462491 ms: Scavenge 2919.2 (2965.3) -> 2918.7 (2970.6) MB, 82.1 / 0.0 ms  (average mu = 0.974, current mu = 0.978) allocation failure; 

<--- JS stacktrace --->

FATAL ERROR: Scavenger: semi-space copy Allocation failed - JavaScript heap out of memory
Aborted (core dumped)
scottnonnenberg-signal commented 2 years ago

I see that you're on 5.47. We just released 5.49 with fixes that might help out, and even 5.48 had a change that might help you out, here: https://github.com/signalapp/Signal-Desktop/commit/63679f5af6b47a90734e56035cc61b5c6551cc14

Let us know what you see!

sajith commented 2 years ago

Upgraded, and Signal Desktop is still crashing. With 5.49.0, I am getting this:

[...]
{"level":30,"time":"2022-07-08T13:31:39.389Z","pid":360612,"hostname":"nonzen","msg":"App loaded - time: 8315"}
{"level":30,"time":"2022-07-08T13:31:39.389Z","pid":360612,"hostname":"nonzen","msg":"SQL init - time: 197"}
{"level":30,"time":"2022-07-08T13:31:39.389Z","pid":360612,"hostname":"nonzen","msg":"Preload - time: 945"}
{"level":30,"time":"2022-07-08T13:31:39.389Z","pid":360612,"hostname":"nonzen","msg":"WebSocket connect - time: 5787"}
{"level":30,"time":"2022-07-08T13:31:39.390Z","pid":360612,"hostname":"nonzen","msg":"Processed count: 6"}
{"level":30,"time":"2022-07-08T13:31:39.390Z","pid":360612,"hostname":"nonzen","msg":"Messages per second: 3.790271636133923"}
{"level":30,"time":"2022-07-08T13:32:11.738Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=11879ms"}
{"level":30,"time":"2022-07-08T13:32:35.513Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=13474ms"}
{"level":30,"time":"2022-07-08T13:32:58.437Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=16067ms"}
{"level":30,"time":"2022-07-08T13:33:29.107Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=18976ms"}
{"level":30,"time":"2022-07-08T13:33:57.156Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=20663ms"}
{"level":30,"time":"2022-07-08T13:34:20.439Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=15656ms"}
{"level":30,"time":"2022-07-08T13:34:35.561Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=16423ms"}
{"level":30,"time":"2022-07-08T13:38:48.810Z","pid":360612,"hostname":"nonzen","msg":"MainSQL: slow query saveMessages duration=172472ms"}
Unhandled Error: Error [ERR_WORKER_OUT_OF_MEMORY]: Worker terminated due to reaching memory limit: JS heap out of memory
    at new NodeError (node:internal/errors:371:5)
    at [kOnExit] (node:internal/worker:277:26)
    at Worker.<computed>.onexit (node:internal/worker:199:20)
{"level":50,"time":"2022-07-08T13:39:11.255Z","pid":360612,"hostname":"nonzen","msg":"Unhandled Error: Error [ERR_WORKER_OUT_OF_MEMORY]: Worker terminated due to reaching memory limit: JS heap out of memory\n    at new NodeError (node:internal/errors:371:5)\n    at [kOnExit] (node:internal/worker:277:26)\n    at Worker.<computed>.onexit (node:internal/worker:199:20)"}
{"level":30,"time":"2022-07-08T13:49:01.809Z","pid":360612,"hostname":"nonzen","msg":"System tray service: updating main window. Previously, there was a window, and now there is not"}
{"level":30,"time":"2022-07-08T13:49:01.810Z","pid":360612,"hostname":"nonzen","msg":"System tray service: rendering no tray"}

Render process is gone: Error: Reason: crashed, Exit Code: 133
    at App.<anonymous> (/opt/Signal/resources/app.asar/app/global_errors.js:75:43)
    at App.emit (node:events:538:35)
    at EventEmitter.<anonymous> (node:electron/js2c/browser_init:161:12109)
    at EventEmitter.emit (node:events:526:28)
{"level":50,"time":"2022-07-08T13:49:29.324Z","pid":360612,"hostname":"nonzen","msg":"Render process is gone: Error: Reason: crashed, Exit Code: 133\n    at App.<anonymous> ([REDACTED]/app/global_errors.js:75:43)\n    at App.emit (node:events:538:35)\n    at EventEmitter.<anonymous> (node:electron/js2c/browser_init:161:12109)\n    at EventEmitter.emit (node:events:526:28)"}

Those two error messages also appear in their own child windows.

scottnonnenberg-signal commented 2 years ago

Be on the lookout for 5.50.0 next week - we believe that it will fix your startup issues.

sajith commented 2 years ago

Upgraded Signal Desktop to 5.50.0. It does not crash anymore, but it isn't in useful state either: the Window is unresponsive most of the time. It does display the latest messages, but there are only some brief intervals when I can select a conversation or send a response. There's an almost constant CPU usage of >100%.

I could submit some logs this time: https://debuglogs.org/desktop/5.50.0/88849e91a18816d6adc5dba87db4c3899f46e261b321661bf7b03c526ee5f0ac.gz

There are some error messages in the messages signal-desktop prints on the console (sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message). I believe this is the interesting part:

{"level":30,"time":"2022-07-14T12:50:38.366Z","pid":366544,"hostname":"localghost","msg":"App loaded - time: 42187"}
{"level":30,"time":"2022-07-14T12:50:38.367Z","pid":366544,"hostname":"localghost","msg":"SQL init - time: 437"}
{"level":30,"time":"2022-07-14T12:50:38.367Z","pid":366544,"hostname":"localghost","msg":"Preload - time: 1009"}
{"level":30,"time":"2022-07-14T12:50:38.367Z","pid":366544,"hostname":"localghost","msg":"WebSocket connect - time: 2750"}
{"level":30,"time":"2022-07-14T12:50:38.367Z","pid":366544,"hostname":"localghost","msg":"Processed count: 677"}
{"level":30,"time":"2022-07-14T12:50:38.367Z","pid":366544,"hostname":"localghost","msg":"Messages per second: 17.617362339960444"}
{"level":30,"time":"2022-07-14T12:50:38.434Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getUnreadByConversationAndMarkRead duration=64ms"}
{"level":30,"time":"2022-07-14T12:50:39.630Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query saveMessages duration=52ms"}
{"level":30,"time":"2022-07-14T12:51:17.999Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=16303ms"}
{"level":30,"time":"2022-07-14T12:55:19.763Z","pid":366544,"hostname":"localghost","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":30,"time":"2022-07-14T12:55:20.786Z","pid":366544,"hostname":"localghost","msg":"System tray service: setting unread count to 1"}
{"level":30,"time":"2022-07-14T12:55:20.786Z","pid":366544,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-14T12:55:21.785Z","pid":366544,"hostname":"localghost","msg":"System tray service: setting unread count to 0"}
{"level":30,"time":"2022-07-14T12:55:21.786Z","pid":366544,"hostname":"localghost","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-14T12:56:19.064Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=18597ms"}
{"level":30,"time":"2022-07-14T13:00:46.561Z","pid":366544,"hostname":"localghost","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":30,"time":"2022-07-14T13:01:38.634Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=18910ms"}
{"level":30,"time":"2022-07-14T13:05:43.097Z","pid":366544,"hostname":"localghost","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":40,"time":"2022-07-14T13:05:43.111Z","pid":366544,"hostname":"localghost","msg":"MainSQL: getAllUnprocessedAndIncrementAttempts: deleting 2 invalid unprocessed envelopes"}
{"level":30,"time":"2022-07-14T13:06:37.321Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=22754ms"}
{"level":30,"time":"2022-07-14T13:10:46.686Z","pid":366544,"hostname":"localghost","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":30,"time":"2022-07-14T13:11:47.584Z","pid":366544,"hostname":"localghost","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=23038ms"}
Rowaaaaan commented 2 years ago

I am getting very similar issues as you are. Ever since I updated to 5.47, I've been having these issues. I hadn't updated for a while before then, so I wasn't experiencing it. I'd say the problem began close to around that version.

Set Windows Application User Model ID (AUMID) { appUserModelId: 'org.whispersystems.signal-desktop' }
NODE_ENV production
NODE_CONFIG_DIR /usr/lib/signal-desktop/resources/app.asar/config
NODE_CONFIG {}
ALLOW_CONFIG_MUTATIONS undefined
HOSTNAME undefined
NODE_APP_INSTANCE undefined
SUPPRESS_NO_CONFIG_WARNING undefined
SIGNAL_ENABLE_HTTP undefined
userData: /home/localuser/.config/Signal
config/get: Successfully read user config file
config/get: Successfully read ephemeral config file
making app single instance
[8474:0721/162341.100626:ERROR:bus.cc(398)] Failed to connect to the bus: Could not parse server address: Unknown address type (examples of valid types are "tcp" and on UNIX "unix")
[8474:0721/162341.100771:ERROR:bus.cc(398)] Failed to connect to the bus: Could not parse server address: Unknown address type (examples of valid types are "tcp" and on UNIX "unix")
{"level":30,"time":"2022-07-21T08:23:41.315Z","pid":8474,"hostname":"thevoid","msg":"app ready"}
{"level":30,"time":"2022-07-21T08:23:41.319Z","pid":8474,"hostname":"thevoid","msg":"starting version 5.50.1"}
{"level":30,"time":"2022-07-21T08:23:41.320Z","pid":8474,"hostname":"thevoid","msg":"media access status [object Undefined] [object Undefined]"}
{"level":30,"time":"2022-07-21T08:23:41.322Z","pid":8474,"hostname":"thevoid","msg":"got fast theme-setting value dark"}
{"level":30,"time":"2022-07-21T08:23:41.331Z","pid":8474,"hostname":"thevoid","msg":"got fast theme-setting value dark"}
{"level":30,"time":"2022-07-21T08:23:41.332Z","pid":8474,"hostname":"thevoid","msg":"got fast spellcheck setting true"}
{"level":30,"time":"2022-07-21T08:23:41.334Z","pid":8474,"hostname":"thevoid","msg":"getSystemTraySetting had no flags and did no DB lookups. Returning DoNotUseSystemTray"}
{"level":30,"time":"2022-07-21T08:23:41.337Z","pid":8474,"hostname":"thevoid","msg":"Initializing BrowserWindow config: {\"show\":false,\"width\":1362,\"height\":724,\"minWidth\":712,\"minHeight\":550,\"autoHideMenuBar\":true,\"titleBarStyle\":\"default\",\"titleBarOverlay\":false,\"backgroundColor\":\"#121212\",\"webPreferences\":{\"devTools\":false,\"spellcheck\":true,\"nodeIntegration\":false,\"nodeIntegrationInWorker\":false,\"contextIsolation\":false,\"preload\":\"[REDACTED]/preload.bundle.js\",\"backgroundThrottling\":false,\"enablePreferredSizeMode\":true,\"disableBlinkFeatures\":\"Accelerated2dCanvas,AcceleratedSmallCanvases\"},\"icon\":\"[REDACTED]/images/signal-logo-desktop-linux.png\",\"x\":2,\"y\":42}"}
[8474:0721/162341.472430:ERROR:bus.cc(398)] Failed to connect to the bus: Could not parse server address: Unknown address type (examples of valid types are "tcp" and on UNIX "unix")
{"level":30,"time":"2022-07-21T08:23:41.534Z","pid":8474,"hostname":"thevoid","msg":"spellcheck: user locale: en"}
{"level":30,"time":"2022-07-21T08:23:41.534Z","pid":8474,"hostname":"thevoid","msg":"spellcheck: available spellchecker languages:  [\"af\",\"bg\",\"ca\",\"cs\",\"cy\",\"da\",\"de\",\"de-DE\",\"el\",\"en\",\"en-AU\",\"en-CA\",\"en-GB\",\"en-GB-oxendict\",\"en-US\",\"es\",\"es-419\",\"es-AR\",\"es-ES\",\"es-MX\",\"es-US\",\"et\",\"fa\",\"fo\",\"fr\",\"fr-FR\",\"he\",\"hi\",\"hr\",\"hu\",\"hy\",\"id\",\"it\",\"it-IT\",\"ko\",\"lt\",\"lv\",\"nb\",\"nl\",\"pl\",\"pt\",\"pt-BR\",\"pt-PT\",\"ro\",\"ru\",\"sh\",\"sk\",\"sl\",\"sq\",\"sr\",\"sv\",\"ta\",\"tg\",\"tr\",\"uk\",\"vi\"]"}
{"level":30,"time":"2022-07-21T08:23:41.535Z","pid":8474,"hostname":"thevoid","msg":"spellcheck: setting languages to:  [\"en\"]"}
{"level":30,"time":"2022-07-21T08:23:41.542Z","pid":8474,"hostname":"thevoid","msg":"got fast theme-setting value dark"}
{"level":30,"time":"2022-07-21T08:23:41.567Z","pid":8474,"hostname":"thevoid","msg":"MainSQL: updateSchema:\n  Current user_version: 63;\n  Most recent db schema: 63;\n  SQLite version: 3.37.2;\n  SQLCipher version: 4.5.1 community;\n  (deprecated) schema_version: 276;\n"}
{"level":30,"time":"2022-07-21T08:23:41.571Z","pid":8474,"hostname":"thevoid","msg":"got fast spellcheck setting true"}
[8474:0721/162341.605678:ERROR:bus.cc(398)] Failed to connect to the bus: Could not parse server address: Unknown address type (examples of valid types are "tcp" and on UNIX "unix")
{"level":30,"time":"2022-07-21T08:23:41.607Z","pid":8474,"hostname":"thevoid","msg":"System tray service: created"}
{"level":30,"time":"2022-07-21T08:23:41.608Z","pid":8474,"hostname":"thevoid","msg":"System tray service: updating main window. Previously, there was not a window, and now there is"}
{"level":30,"time":"2022-07-21T08:23:41.608Z","pid":8474,"hostname":"thevoid","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-21T08:23:41.608Z","pid":8474,"hostname":"thevoid","msg":"Begin ensuring permissions"}
{"level":30,"time":"2022-07-21T08:23:41.672Z","pid":8474,"hostname":"thevoid","msg":"Ensuring file permissions for 4 files"}
{"level":30,"time":"2022-07-21T08:23:41.677Z","pid":8474,"hostname":"thevoid","msg":"Finish ensuring permissions in 69ms"}
{"level":30,"time":"2022-07-21T08:23:42.169Z","pid":8474,"hostname":"thevoid","msg":"Updating BrowserWindow config: %s {\"maximized\":true,\"autoHideMenuBar\":true,\"fullscreen\":false,\"width\":1362,\"height\":724,\"x\":2,\"y\":42}"}
{"level":30,"time":"2022-07-21T08:23:42.171Z","pid":8474,"hostname":"thevoid","msg":"config/set: Saving ephemeral config to disk"}
{"level":30,"time":"2022-07-21T08:23:42.172Z","pid":8474,"hostname":"thevoid","msg":"config/set: Saved ephemeral config to disk"}
{"level":30,"time":"2022-07-21T08:23:44.129Z","pid":8474,"hostname":"thevoid","msg":"main window is ready-to-show"}
{"level":30,"time":"2022-07-21T08:23:44.129Z","pid":8474,"hostname":"thevoid","msg":"showing main window"}
{"level":30,"time":"2022-07-21T08:23:44.130Z","pid":8474,"hostname":"thevoid","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-21T08:23:45.577Z","pid":8474,"hostname":"thevoid","msg":"sending `database-ready`"}
{"level":30,"time":"2022-07-21T08:23:47.423Z","pid":8474,"hostname":"thevoid","msg":"Prevent display sleep service: allowing display sleep"}
{"level":30,"time":"2022-07-21T08:23:48.193Z","pid":8474,"hostname":"thevoid","msg":"updater/start: Updates disabled - not starting new version checks"}
{"level":30,"time":"2022-07-21T08:23:48.196Z","pid":8474,"hostname":"thevoid","msg":"System tray service: setting unread count to 4"}
{"level":30,"time":"2022-07-21T08:23:48.197Z","pid":8474,"hostname":"thevoid","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"App loaded - time: 7517"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"SQL init - time: 269"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"Preload - time: 1420"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"WebSocket connect - time: 4213"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"Processed count: 0"}
{"level":30,"time":"2022-07-21T08:23:48.819Z","pid":8474,"hostname":"thevoid","msg":"Messages per second: 0"}
{"level":30,"time":"2022-07-21T08:24:01.545Z","pid":8474,"hostname":"thevoid","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=5973ms"}
{"level":30,"time":"2022-07-21T08:24:22.861Z","pid":8474,"hostname":"thevoid","msg":"Updating BrowserWindow config: %s {\"maximized\":true,\"autoHideMenuBar\":true,\"fullscreen\":false,\"width\":1362,\"height\":724,\"x\":2,\"y\":42}"}
{"level":30,"time":"2022-07-21T08:24:22.862Z","pid":8474,"hostname":"thevoid","msg":"config/set: Saving ephemeral config to disk"}
{"level":30,"time":"2022-07-21T08:24:22.862Z","pid":8474,"hostname":"thevoid","msg":"config/set: Saved ephemeral config to disk"}
{"level":30,"time":"2022-07-21T08:24:52.275Z","pid":8474,"hostname":"thevoid","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":30,"time":"2022-07-21T08:24:52.297Z","pid":8474,"hostname":"thevoid","msg":"System tray service: setting unread count to 0"}
{"level":30,"time":"2022-07-21T08:24:52.297Z","pid":8474,"hostname":"thevoid","msg":"System tray service: rendering no tray"}
{"level":30,"time":"2022-07-21T08:25:24.196Z","pid":8474,"hostname":"thevoid","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=5890ms"}

With the latter part of the logs being repeated. Something about attempting to save a hydrated message.

{"level":30,"time":"2022-07-21T08:31:26.508Z","pid":8474,"hostname":"thevoid","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n    at [REDACTED]/ts/sql/Server.js:1350:37\n    at sqliteTransaction ([REDACTED]/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at Object.saveMessages ([REDACTED]/ts/sql/Server.js:1352:5)\n    at MessagePort.<anonymous> ([REDACTED]/ts/sql/mainWorker.js:87:35)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)\n    at Worker.<anonymous> ([REDACTED]/ts/sql/main.js:55:26)\n    at Worker.emit (node:events:526:28)\n    at MessagePort.<anonymous> (node:internal/worker:233:53)\n    at [nodejs.internal.kHybridDispatch] (node:internal/event_target:647:20)\n    at exports.emitMessage (node:internal/per_context/messageport:23:28)"}
{"level":30,"time":"2022-07-21T08:31:48.552Z","pid":8474,"hostname":"thevoid","msg":"MainSQL: slow query getMessagesNeedingUpgrade duration=6048ms"}
{"level":30,"time":"2022-07-21T08:32:41.851Z","pid":8474,"hostname":"thevoid","msg":"sql channel error with call saveMessages: Error: Error: Attempting to save a hydrated message\n    at strictAssert ([REDACTED]/ts/util/assert.js:55:11)\n    at saveMessageSync ([REDACTED]/ts/sql/Server.js:1208:36)\n

This just kept on repeating over and over, until Signal finally crashed. While this was happening, Signal could still display messages, but remained unresponsive and unclickable until it did crash.

Rowaaaaan commented 2 years ago

Also, after I tested Signal again, immediately after I closed my Signal instance, I got this error. I ran signal-desktop --verbose, and killed the terminal. Should I put this down in a separate issue?

Unhandled Error

Error: write EIO
    at afterWriteDispatched (node:internal/stream_base_commons:160:15)
    at writeGeneric (node:internal/stream_base_commons:151:3)
    at Socket._writeGeneric (node:net:795:11)
    at Socket._write (node:net:807:8)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Writable.write (node:internal/streams/writable:334:10)
    at console.value (node:internal/console/constructor:286:16)
    at console.warn (node:internal/console/constructor:365:26)
    at handleError ([REDACTED]/app/global_errors.js:36:13
Unhandled Error

Error: write EIO
    at afterWriteDispatched (node:internal/stream_base_commons:160:15)
    at writeGeneric (node:internal/stream_base_commons:151:3)
    at Socket._writeGeneric (node:net:795:11)
    at Socket._write (node:net:807:8)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Writable.write (node:internal/streams/writable:334:10)
    at Object.write ([REDACTED]/node_modules/pino-multi-stream/multistream.js:68:18)
    at Pino.write ([REDACTED]/node_modules/pino/lib/proto.js:177:15)
    at Pino.LOG [as error] ([REDACTED]/node_modules/pino/lib/tools.js:57:21)
scottnonnenberg-signal commented 2 years ago

@Rowaaaaan Please try 5.51.0, released yesterday. It should prevent the 'Attempting to save a hydrated message' error you're seeing.

sajith commented 2 years ago

Signal 5.51.0 has solved the problems I've reported above. Thank you!

Rowaaaaan commented 2 years ago

Just upgraded to 5.51.0 too. Can confirm that the issue was resolved for me as well. Thanks!