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

Looses all setup when running while disk go full #2255

Open petterreinholdtsen opened 6 years ago

petterreinholdtsen commented 6 years ago

Bug description

The Signal desktop application do not handle a full disk. I had several contacts and was using Signal happily when the user home disk was filled by some unrelated program. After making more space on the disk and restarting Signal, all contacts are gone and the Signal app behave as if it had never been configured at all.

Steps to reproduce

  1. Run Signal
  2. Fill up $HOME disk
  3. (possibly receive some message)
  4. Stop Signal
  5. Make some spare room on the disk
  6. Start Signal again

Actual result:

Lost all configuration, wished there were backup to restore.

Expected result:

Should have received a message about a full disk and the system should not have lost configuration. Should have option to make regular backup to not loose the configuration completely.

Platform info

Signal version: 1.7.1 Operating System: Debian GNU/Linux Stretch Linked device version: None

Link to debug log

https://debuglogs.org/c772a4c225a4a6d92bd2c663ef906e5b3a35b8c7df9c203b921a30e33f38de4d

This message seem relevant: Top-level unhandled promise rejection: QuotaExceededError: Encountered disk full while committing transaction.

petterreinholdtsen commented 6 years ago

To make the situation worse, all the configuration and messages in ~/.config/Signal/ seem to be removed now (the content is a lot smaller than it used to be), and it is impossible to import my old setup using the old export I started with initially.

petterreinholdtsen commented 6 years ago

I ran into this problem again. This time it is still in the state after the full disk, I have not exited the program yet. I visited the developer tools log, and see these messages when I suspect the disk filled up:


/opt/Signal/resources/app.asar/js/logging.js:34 INFO  2018-05-20T11:27:05.367Z Sending a keepalive message
/opt/Signal/resources/app.asar/js/logging.js:34 INFO  2018-05-20T11:28:00.473Z Sending a keepalive message
/opt/Signal/resources/app.asar/js/logging.js:34 INFO  2018-05-20T11:28:55.606Z Sending a keepalive message
/opt/Signal/resources/app.asar/js/logging.js:34 INFO  2018-05-20T11:29:17.377Z DOMException: Failed to execute 'transaction' on 'IDBDatabase': The database connection is closing.
    at Driver.query (file:///opt/Signal/resources/app.asar/js/components.js:21751:44)
    at Driver.execute (file:///opt/Signal/resources/app.asar/js/components.js:21583:26)
    at ExecutionQueue.execute (file:///opt/Signal/resources/app.asar/js/components.js:21941:29)
    at next (file:///opt/Signal/resources/app.asar/js/components.js:22021:34)
    at child.sync (file:///opt/Signal/resources/app.asar/js/components.js:22027:13)
    at child.sync (file:///opt/Signal/resources/app.asar/js/components.js:20399:28)
    at child.fetch (file:///opt/Signal/resources/app.asar/js/components.js:20636:19)
    at file:///opt/Signal/resources/app.asar/js/models/conversations.js:521:35
    at Promise (<anonymous>)
    at child.getUnread (file:///opt/Signal/resources/app.asar/js/models/conversations.js:520:16)
/opt/Signal/resources/app.asar/js/logging.js:110 ERROR 2018-05-20T11:29:17.383Z Top-level unhandled promise rejection: InvalidStateError: Failed to execute 'transaction' on 'IDBDatabase': The database connection is closing.

Is there anything I can to do reopen the database connection to get the state saved and not have to loose all messages?

petterreinholdtsen commented 6 years ago

I had to move on and get my Signal back, so I exited the running process and restarted, and this time I did not loose all my configuration. No idea how it was different from earlier tries, but suspect it might be because I was trying to send a message instead of Signal receiving a message.

hgsommer commented 6 years ago

I ran into the same issue today (v1.15.5 on Linux Mint 18.3) - the files in ~/.config/Signal are still there, but the program displays only the sync qr-code screen.

scottnonnenberg-signal commented 6 years ago

@hgsommer If you go into the logs directory inside that configuration directory, that might help us track down what went wrong.

hgsommer commented 6 years ago

I put the logfile created during the event into this gist.

scottnonnenberg-signal commented 6 years ago

@hgsommer Well, it looks like you normally shut down, and then when you restarted again the IndexedDB had reset completely, while SQLCipher was still there:

2018-08-21T18:20:50.161Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]493
2018-08-21T18:20:50.404Z GET https://cdn.signal.org/profiles/op3h0EbBZBrwJl_MwpmQBA 403 Error
2018-08-21T18:20:50.407Z GET https://cdn.signal.org/profiles/zxggn_maaLo2H48kMWNoYg 403 Error
2018-08-21T18:20:50.453Z GET https://cdn.signal.org/profiles/-q5RaKzRQqcmSsjA6fxOUQ 403 Error
2018-08-21T18:20:51.169Z done with status fetch
2018-08-21T18:20:51.312Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]493 200 Success
2018-08-21T18:20:58.085Z SQL channel job 61 (getUnreadByConversation) succeeded in 2ms
--- Looks like things were shut down normally
2018-08-21T18:20:58.373Z unloading conversation group([REDACTED]t9Ý) due to: windows closed
2018-08-21T18:20:58.764Z Update notifications: {\"shouldClearNotifications\":false,\"shouldPlayNotificationSound\":false,\"shouldShowNotifications\":false,\"type\":\"noNotifications\",\"isNotificationGroupingSupported\":true}
2018-08-21T18:46:11.193Z app ready
2018-08-21T18:46:11.233Z Ensure attachments directory exists
--- SQLCipher is still all set up properly
2018-08-21T18:46:11.290Z updateSchema: Current schema version: 3; Most recent schema version: 3; SQLite version: 3.20.1; SQLCipher version: 3.4.2;
2018-08-21T18:46:11.297Z Initializing BrowserWindow config: {\"show\":true,\"width\":1364,\"height\":718,\"minWidth\":640,\"minHeight\":360,\"autoHideMenuBar\":false,\"webPreferences\":{\"nodeIntegration\":false,\"nodeIntegrationInWorker\":false,\"preload\":\"/opt/Signal/resources/app.asar/preload.js\",\"nativeWindowOpen\":true},\"icon\":\"/opt/Signal/resources/app.asar/images/icon_256.png\",\"maximized\":false,\"x\":1,\"y\":24}
2018-08-21T18:46:18.005Z Detected Linux. Setting up spell check with locale de_DE and dictionary location /usr/share/hunspell
2018-08-21T18:46:19.215Z pre-main prep time: 7 ms
2018-08-21T18:46:19.279Z Build expires:  2018-11-14T00:17:09.000Z
2018-08-21T18:46:19.503Z background page reloaded
2018-08-21T18:46:19.504Z environment: production
2018-08-21T18:46:19.508Z Start IndexedDB migrations
2018-08-21T18:46:19.508Z Run migrations on database with attachment data
--- Starting over from scratch with the IndexedDB database
2018-08-21T18:46:25.692Z Database status {\"firstMigrationVersion\":12,\"lastMigrationVersion\":18,\"databaseVersion\":1,\"isAlreadyUpgraded\":false}
2018-08-21T18:46:25.696Z Migration 12
2018-08-21T18:46:25.696Z creating object stores
2018-08-21T18:46:25.759Z creating debug log
2018-08-21T18:46:25.761Z Migration 13

What can you tell me about what happened on your computer or to Signal Desktop during the time covered by these log entries?

hgsommer commented 6 years ago

Sorry that i didn't mention it explicitly until now: As in the first post in this issue my home directory got completely full due to a script downloading multiple huge files in parallel. This happened several times, since i tried to free enough space without exactly calculating the amount needed.

scottnonnenberg-signal commented 6 years ago

Ah, so you had filled up your home directory, and then closed Signal, and at that point it likely wasn't able to save necessary updates to the filesystem. I see.

petterreinholdtsen commented 6 years ago

[Scott Nonnenberg]

Ah, so you had filled up your home directory, and then closed Signal, and at that point it likely wasn't able to save necessary updates to the filesystem. I see.

Note, when I experienced this problem, I did not have to close Signal while the disk was full to have problems. I only had to receive a message while the disk was full. After this, whatever I did, for example if I made space on the disk before closing Signal, I would still have no setup after the first restart.

-- Happy hacking Petter Reinholdtsen

benjaoming commented 5 years ago

Deleting .config/Signal/logs worked for me and I had no further data loss. But there doesn't seem to be much consistency to what fails when disk errors occur.

My fault seems to be related somehow to logging in JSON format and then crashing if somehow the log file isn't correctly written. This could be filed as an issue with the way logs are written: Other software I've seen will just append to a log and not assume anything about its format, nor even read and parse it. Logging formats may also change over time, logging in JSON is a bit annoying since it's not very human readable. So even assuming that a log is in a specific format is a bad assumption, as you might change the format, add or remove information etc.

Symptoms: Ran out of disk space and Signal died while sending a message. Subsequently, it started with some message "Optimizing application..." and nothing happened.

CLI output:

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
userData: /home/user/.config/Signal
config/get: Successfully read user config file
config/get: Successfully read ephemeral config file
making app single instance
error parsing log line SyntaxError: Unexpected end of JSON input
    at JSON.parse (<anonymous>)
    at isLineAfterDate (/opt/Signal/resources/app.asar/app/logging.js:140:23)
    at Promise.all.then.results (/opt/Signal/resources/app.asar/app/logging.js:163:15) {"name":"log","hostname":"host123","pid":22409,"level":30,"msg":"Update notifications: {\"shouldClearNotifications\":true,\"shouldPlayNotificationSound\":false,\"should
{"name":"log","hostname":"host123","pid":22493,"level":30,"msg":"app ready","time":"2019-09-03T12:49:43.428Z","v":0}
{"name":"log","hostname":"host123","pid":22493,"level":30,"msg":"starting version 1.26.2","time":"2019-09-03T12:49:43.428Z","v":0}
{"name":"log","hostname":"host123","pid":22493,"level":50,"msg":"Unhandled Error: Error: ENOSPC: no space left on device, write","time":"2019-09-03T12:49:43.442Z","v":0}
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
    at doWrite (_stream_writable.js:406:19)
    at writeOrBuffer (_stream_writable.js:394:5)
    at WriteStream.Writable.write (_stream_writable.js:294:11)
    at RotatingFileStream.write (/opt/Signal/resources/app.asar/node_modules/bunyan/lib/bunyan.js:1535:28)
    at Logger._emit (/opt/Signal/resources/app.asar/node_modules/bunyan/lib/bunyan.js:923:22)
    at Logger.error (/opt/Signal/resources/app.asar/node_modules/bunyan/lib/bunyan.js:1045:24)
    at Console.logAtLevel (/opt/Signal/resources/app.asar/app/logging.js:262:18)
    at apply (/opt/Signal/resources/app.asar/node_modules/lodash/lodash.js:476:27)
    at Console.wrapper [as error] (/opt/Signal/resources/app.asar/node_modules/lodash/lodash.js:5317:16)
    at handleError (/opt/Signal/resources/app.asar/app/global_errors.js:13:11)