Illegal Instruction (Core Dump)

[internalkernel]

Hi and thanks for a great app... I recently switched to email-securely from protonmail-desktop but I'm having problems running the app.

It continuously crashes with an Illegal Instruction and Core Dump. I've increased logging but there doesn't seem to be anything useful in there. The only error I see, is if I launch securely from a terrminal - the Illegal Instruction occurs on the command line but there's no evidence of errors in the actual log. In fact the log file isn't created unless I set output to info. I'm running Ubuntu 18.10 & KDE 5.15.

Command Line output:
`
<--- Last few GCs --->

[10038:0x21d53cdbd000] 189186 ms: Mark-sweep 1088.5 (1533.4) -> 1088.5 (1481.4) MB, 26.0 / 0.0 ms (average mu = 0.975, current mu = 0.001) last resort GC in old space requested
[10038:0x21d53cdbd000] 189212 ms: Mark-sweep 1088.5 (1481.4) -> 1088.5 (1459.9) MB, 26.6 / 0.0 ms (average mu = 0.948, current mu = 0.001) last resort GC in old space requested

<--- JS stacktrace --->

==== JS stack trace =========================================

0: ExitFrame [pc: 0x55685777ab2e]

Security context: 0x0aa1b4aa29d9
1: fromString(aka fromString) [0x284e8e39ec39] [buffer.js:341] [bytecode=0x3001a242361 offset=53](this=0x12445d2026f1 ,0x15a0e7e8b711 <Very long string[340707643]>,0x0aa1b4aca891 <String[4]: utf8>)
2: from [0x1d53f4b15f31] [buffer.js:202] [bytecode=0x3001a241f61 offset=11](this=0x151bc08043f1 <JSFunction Buffer (sfi = 0x1d53f4b0c639)>,0x15...

Illegal instruction (core dumped)
`

Log File Output:
[2019-02-19 09:03:51.586] [debug] [WEBVIEW:protonmail] [lib/api] resolveService() queueing rate limited method: "Contact.get" [2019-02-19 09:03:51.586] [verbose] [WEBVIEW:protonmail] [lib/api] resolveService() calling rate limited method: Contact.get {"waitTime":0,"rateLimitedMethodsCallCount":348} [2019-02-19 09:03:51.955] [debug] [WEBVIEW:protonmail] [lib/api] resolveService() queueing rate limited method: "Contact.get" [2019-02-19 09:03:51.955] [verbose] [WEBVIEW:protonmail] [lib/api] resolveService() calling rate limited method: Contact.get {"waitTime":0,"rateLimitedMethodsCallCount":349} [2019-02-19 09:03:52.452] [debug] [WEBVIEW:protonmail] [lib/api] resolveService() queueing rate limited method: "Contact.get" [2019-02-19 09:03:52.453] [verbose] [WEBVIEW:protonmail] [lib/api] resolveService() calling rate limited method: Contact.get {"waitTime":0,"rateLimitedMethodsCallCount":350} [2019-02-19 09:03:52.849] [info] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> bootstrapDbPatch() fetched 349 contacts [2019-02-19 09:03:52.849] [verbose] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> bootstrapDbPatch() start fetching folders [2019-02-19 09:03:52.849] [debug] [WEBVIEW:protonmail] [lib/api] resolveService() queueing rate limited method: "Label.query" [2019-02-19 09:03:52.849] [verbose] [WEBVIEW:protonmail] [lib/api] resolveService() calling rate limited method: Label.query {"waitTime":0,"rateLimitedMethodsCallCount":351} [2019-02-19 09:03:53.236] [info] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> bootstrapDbPatch() fetched 54 folders [2019-02-19 09:03:53.237] [verbose] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> bootstrapDbPatch() construct initial database patch [2019-02-19 09:03:53.245] [verbose] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> bootstrapDbPatch() trigger initial storing [2019-02-19 09:03:53.245] [info] [WEBVIEW:protonmail] [api/build-db-patch] api:buildDbPatch() <[account.component][0]> persist() start [2019-02-19 09:03:53.257] [info] [electron-main/api/endpoints-builders/database] dbPatch() [2019-02-19 09:03:53.382] [info] [electron-main/api/endpoints-builders/database] patchMetadata() [2019-02-19 09:03:53.382] [verbose] [electron-main/api/endpoints-builders/database] dbPatch() {"entitiesModified":true,"metadataModified":false,"modified":true} [2019-02-19 09:03:53.382] [info] [electron-main/database] saveToFile() [2019-02-19 09:03:53.383] [verbose] [preload: database-indexer] [index] dbIndexerNotification.next, action.type: ipc_main_api_db_indexer_notification_actions:Index [2019-02-19 09:03:53.383] [info] [preload: database-indexer] [index] action.Index() Received mails to remove/add: 0/0 [2019-02-19 09:03:53.383] [info] [electron-main/api/endpoints-builders/database] dbIndexerOn() action.type: ipc_main_api_db_indexer_on:ProgressState [2019-02-19 09:03:53.383] [verbose] [electron-main/api/endpoints-builders/database] dbIndexerOn() ProgressState.status: {"indexing":true} [2019-02-19 09:03:53.384] [info] [electron-main/database] dump() [2019-02-19 09:03:53.384] [info] [electron-main/database] iterateAccounts() [2019-02-19 09:03:53.397] [info] [electron-main/api/endpoints-builders/database] dbIndexerOn() action.type: ipc_main_api_db_indexer_on:ProgressState [2019-02-19 09:03:53.397] [verbose] [electron-main/api/endpoints-builders/database] dbIndexerOn() ProgressState.status: {"indexing":false}

Thanks for your time!

[vladimiry]

Looks like out of memory failure at first glance. I guess your account has got a lot of emails? The app by design keeps the entire local store feature related database in memory (main app process), some details.

Does it fail only if the local store feature is enabled for the account (app restart is needed if option got toggled off)?

Does it fail soon after app starting or after a while?

Can you try running the app in console this way for now:

ELECTRON_ENABLE_LOGGING=true `which email-securely-app` 2>&1 | tee ~/email-securely-app.log

It will print extended logs to ~/email-securely-app.log so you could locate some useful information there.

I'm going to enable configurable max_old_space_size option support, defaults to 2048 (2GB).

[vladimiry]

Can you also try the app with another account that doesn't have a lot of emails, if you have such account?

[vladimiry]

To recap, in your case the app fails after 189.19 seconds (~ 3 minutes) since default node memory limit (~ 1GB) is to low to hold the entire emails database.

Can you try running the app using the following way and let me know how it goes?

`which email-securely-app` --js-flags="--max-old-space-size=4096"

This will set memory limit to 4GB for the main process which holds the emails database.

If that won't be enough I will be ready to provide a solution for increasing memory limit for the renderer processes too.

[vladimiry]

Besides I didn't initially notice this stuff <Very long string[340707643]>. So the failure could happen because a too long string was used as currently the database file is being serialized/deserialized as just JSON.stringify/JSON.parse calls and Node.js has limit for the string size. Handling this issue will require introducing stream database file processing.

[vladimiry]

@internalkernel can you try this build? This build got improved local database serialization.

If it still fails please run the app the following way and send log file to the email specified here in author property:

ELECTRON_ENABLE_LOGGING=true `which email-securely-app` --js-flags="--max-old-space-size=5120"  2>&1 | tee ~/email-securely-app.log

Plus change --max-old-space-size=2048 to --max-old-space-size=3072 or --max-old-space-size=4096 in the config.json.

[internalkernel]

Sorry about the slow reply here... and thanks for your attention! I'll try to address everything in order.

Indeed it works fine when Local Store is disabled. Running the app with:

ELECTRON_ENABLE_LOGGING=true which email-securely-app 2>&1 | tee ~/email-securely-app.log

results in a out of memory error:

[12521:0220/202508.806543:INFO:CONSOLE(16)] "[20:25:08.805] [preload: database-indexer] [index] dbIndexerNotification.next, action.type: ipc_main_api_db_indexer_notification_actions:Index", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202508.806559:INFO:CONSOLE(16)] "[20:25:08.805] [preload: database-indexer] [index] action.Index() Received mails to remove/add: 0/0", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202508.806571:INFO:CONSOLE(16)] "[20:25:08.806] [electron-main/api/endpoints-builders/database] dbIndexerOn() action.type: ipc_main_api_db_indexer_on:ProgressState", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [12521:0220/202508.806587:INFO:CONSOLE(16)] "[20:25:08.806] [electron-main/api/endpoints-builders/database] dbIndexerOn() action.type: ipc_main_api_db_indexer_on:ProgressState", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202508.806598:INFO:CONSOLE(16)] "[20:25:08.806] [electron-main/api/endpoints-builders/database] dbIndexerOn() ProgressState.status: {"indexing":true}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [12521:0220/202508.806614:INFO:CONSOLE(16)] "[20:25:08.806] [electron-main/api/endpoints-builders/database] dbIndexerOn() ProgressState.status: {"indexing":true}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202508.822278:INFO:CONSOLE(16)] "[20:25:08.807] [electron-main/database] dump()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [12521:0220/202508.822304:INFO:CONSOLE(16)] "[20:25:08.807] [electron-main/database] iterateAccounts()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [12521:0220/202508.822647:INFO:CONSOLE(16)] "[20:25:08.807] [electron-main/database] dump()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202508.822664:INFO:CONSOLE(16)] "[20:25:08.807] [electron-main/database] iterateAccounts()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/database-indexer.js (16) [12521:0220/202509.988898:ERROR:atom_bindings.cc(48)] Fatal error in V8: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory

The second suggestion to increase max_memory helped:

which email-securely-app --js-flags="--max-old-space-size=4096"

It ran for a good hour or two, indexed many of the messages and then crashed with the same error as before, i.e. <Very long string[340707643]>

The new build you linked (thanks by the way), unfortunately didn't make it past the login window initially. I deleted all my settings for the app and installed clean and it is currently working. I'll update with more progress later...

Thanks!

[vladimiry]

The new build you linked (thanks by the way), unfortunately didn't make it past the login window initially.

The provided build is supposed to be backward compatible (means no breaking changes have been made). Did you happen to keep the log file with the failed login window action?

[internalkernel]

I did, it was brief... In hindsight, it might have been parsing the current database? I did keep the old profile, I can always restore and try to run it again.

[26138:0221/055632.202985:ERROR:sandbox_linux.cc(379)] InitializeSandbox() called with multiple threads in process gpu-process. [26109:0221/055632.303610:WARNING:app_indicator_icon.cc(279)] Could not encode icon [26109:0221/055632.540899:INFO:CONSOLE(16)] "[05:56:32.534] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.540943:INFO:CONSOLE(16)] "[05:56:32.535] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"} {"path":[{"outlets":{"settings-outlet":"settings"}}]}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.561601:INFO:CONSOLE(16)] "[05:56:32.560] [WEB] [options.effects] <angular> {"actionType":"options:InitRequest"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.573671:INFO:CONSOLE(16)] "[05:56:32.570] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.573685:INFO:CONSOLE(16)] "[05:56:32.570] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"} {"path":[{"outlets":{"settings-outlet":"settings"}}]}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.573696:INFO:CONSOLE(16)] "[05:56:32.572] [WEB] [options.effects] <angular> {"actionType":"options:GetConfigRequest"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.577445:INFO:CONSOLE(16)] "[05:56:32.574] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.577456:INFO:CONSOLE(16)] "[05:56:32.574] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"} {"path":[{"outlets":{"settings-outlet":"settings"}}]}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.577470:INFO:CONSOLE(16)] "[05:56:32.576] [WEB] [options.effects] <angular> {"actionType":"options:GetSettingsRequest"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.625973:INFO:CONSOLE(16)] "[05:56:32.577] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.626007:INFO:CONSOLE(16)] "[05:56:32.577] [WEB] [navigation.effects.ts] <angular> {"actionType":"navigation:Go"} {"path":[{"outlets":{"settings-outlet":"settings/login"}}]}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.703478:INFO:CONSOLE(16)] "[05:56:32.589] [WEB] [options.effects] <angular> {"actionType":"options:SignInRequest"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.915625:INFO:CONSOLE(16)] "[05:56:32.915] [electron-main/database] loadFromFile()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16)

2.3.3 is running solid, about a 1/3rd of the emails are indexed so far... Thanks!

[vladimiry]

Would be great to see the lines after these (it's begining of the signing process)

[26109:0221/055632.703478:INFO:CONSOLE(16)] "[05:56:32.589] [WEB] [options.effects] <angular> {"actionType":"options:SignInRequest"}", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16) [26109:0221/055632.915625:INFO:CONSOLE(16)] "[05:56:32.915] [electron-main/database] loadFromFile()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16)

it might have been parsing the current database?

It does parse the database used/created by the previous app version, but I did care about backward compatibility, see read method implementation. Besides that new build loads the database serialized in JSON from the buffer using https://www.npmjs.com/package/oboe instead of just parsing a long string by calling JSON.parse.

Anyway, I'm going to double check the backward compatibility before releasing a new version.

[internalkernel]

That was the end of the log, the app stalled at that point... I gave it about a minute or two, I could let it sit longer if that's helpful...

[vladimiry]

I could let it sit longer if that's helpful...

Please do if that's possible. I guess https://www.npmjs.com/package/oboe could potentially parse the data slower than regular JSON.parse. The default timeout for signing-in action is 25 seconds by the way which can be tweaked in config.json by editing timeouts.defaultApiCall value (app restart is required). Signing-in action includes the database.bin file loading process. If signing in action fails you will get either timeout error or some logic error.

By the way, what is your database.bin file size?

[internalkernel]

Adjusted timeouts to allow for a 10 min window, it crashed after about 3 min... The auto-login feature is turned on.

Link to the full log: https://pastebin.com/zwvkdDF0

I then tried to go back to the newer profile, but the app crashed almost immediately upon launching. Here's that log: https://pastebin.com/fg2afAre

The good news is that I haven't seen another crash, not since running the 2.3.3 build and increasing max_memory to 3072. Database.bin was about 500MBs. both profiles were comparable.

[vladimiry]

Thanks for the thoughtful report, it helps to make the app work better.

Link to the full log: https://pastebin.com/zwvkdDF0

I see that database file got loaded successfully in 141911ms (~142 sesonds ~ 2.4 minutes which is very slow, hope new serialization in 2.3.3 works faster) but I will need to look into the why the sign-in process finally failed:

[29436:0221/124451.286950:INFO:CONSOLE(16)] "[12:44:51.286] [electron-main/database] loadFromFile()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16)
[29436:0221/124713.203502:INFO:CONSOLE(1)] "Error: Failed to log in", source: file:///opt/email-securely-app/resources/app.asar/app/web/app.js?b8a97f51d83d358bfdc5 (1)
[29436:0221/124714.473179:INFO:CONSOLE(16)] "[12:47:13.197] [electron-main/database] stat()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16)
[29436:0221/124714.473201:INFO:CONSOLE(16)] "[12:47:13.197] [electron-main/database] iterateAccounts()", source: /opt/email-securely-app/resources/app.asar/app/electron-preload/browser-window.js (16)
[29436:0221/124714.473209:INFO:CONSOLE(16)] "[12:47:13.201] [electron-main/database] loadFromFile().stat: {"records":1,"conversationEntries":0,"mails":14165,"folders":60,"contacts":349,"time":141911}", source: /opt/email-securely-

but I will need to look into the why the sign-in process finally failed

Can you try disabling the full-text search feature and give it another try (either via UI or manually in config.json file)? The guess is that sending a huge portion of data from the main process which holds the database to the indexing process is heavily blocking the interaction between processes and so sign-in handler can't respond with completion signal. If so then I will need to chunk the data sending to the parts or enable the search index persisting and the handle the persisted index independently by the indexing process not involving inter-process communication at this stage.

If the bootstrap/initial fetch got completed using the 2.3.3 version (icon stopped blinking in green) does the app work well after the restart with full-text search feature enabled? Asking since the app sends almost the entire database to the indexing process on start and so the interaction between processes would be blocked in the same way.

Database.bin was about 500MBs

Thanks for this info.

I also see that you got 14165 emails saved in the local database ("mails":14165), the biggest database we have seen so far (the previous record was 6161 emails, CC @uberneko), which is a great challenge for the app.

Going to try filling my database with fake data making its size close to 14165 emails and debug the stuff then.

[vladimiry]

Can you try disabling the full-text search feature and give it another try (either via UI or manually in config.json file)?

No need to do this as I tested full-text search bootstrapping on 20k mails database and noticed that issue is in something else. So going to provide updated build.

[vladimiry]

@internalkernel I just have updated the build here. The build comes with the following changes:

• Loading the local database now occurs in a separate from the signing-in API call. The default timeout for this call is set to 5 minutes (300000 ms), see timeouts.databaseLoading value in config.json file (file will be updated with default value on the first app start). This change is aimed to improve backward compatibility, the case when the app loads the database saved in the old format by previous app versions (regular JSON vs enabled with v2.3.3 MessagePack format). The app will show Local database is being loaded... Please wait up to 300 seconds-like message while the database file is being loaded.
• The app should not heavily hang anymore when you switch the account with a huge number of emails to the database view mode (your case). There is still a room for database view mode UI improvement though, especially in the terms of performance improvement on large datasets, but it should be already somehow usable as opposed to v2.3.2.