backintime icon indicating copy to clipboard operation
backintime copied to clipboard
verified publisher icon bit-team

Problem with unmounting remote filesystem after backup / command "status" involved

Open etyurin opened this issue 1 month ago • 6 comments

Describe the problem, feature or ask a question:

This is with the version backintime 1.6.0-dev.9b8291cf, which is the most up-to-date version available in ArchLinux AUR archive.

My backup destination is mounted using sshfs. If I just open backintime and do not do a backup, there is no error. I get clean mount/unmount. However, if I start a backup, it never finishes, because of unmounting problems:


``
INFO: Released suspend mode inhibition
Traceback (most recent call last):
  File "/usr/share/backintime/common/backintime.py", line 173, in <module>
    startApp()
    ~~~~~~~~^^
  File "/usr/share/backintime/common/backintime.py", line 155, in startApp
    args.func(args)
    ~~~~~~~~~^^^^^^
  File "/usr/share/backintime/common/clicommands.py", line 110, in backup
    _do_backup(args, force)
    ~~~~~~~~~~^^^^^^^^^^^^^
  File "/usr/share/backintime/common/clicommands.py", line 132, in _do_backup
    ret = snapshots.Snapshots(cfg).backup(force)
  File "/usr/share/backintime/common/snapshots.py", line 1058, in backup
    .umount(self.config.current_hash_id)
     ~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/share/backintime/common/mount.py", line 269, in umount
    backend.umount()
    ~~~~~~~~~~~~~~^^
  File "/usr/share/backintime/common/mount.py", line 597, in umount
    self.removeSymlink()
    ~~~~~~~~~~~~~~~~~~^^
  File "/usr/share/backintime/common/mount.py", line 1070, in removeSymlink
    os.remove(self.config.snapshotsPath(
    ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
        profile_id=profile_id,
        ^^^^^^^^^^^^^^^^^^^^^^
        mode=self.mode,
        ^^^^^^^^^^^^^^^
        tmp_mount=tmp_mount))
        ^^^^^^^^^^^^^^^^^^^^^
FileNotFoundError: [Errno 2] No such file or directory: '/home/xxxxxxxxx/.local/share/backintime/mnt/1_5011'
``

etyurin avatar Nov 10 '25 18:11 etyurin

Hello etyurin,

Thank you for taking the time to report the bug and providing the details. I appreciate your feedback, will investigate the issue, and work on a solution to the best of my ability.

INFO: Released suspend mode inhibition
...
  File "/usr/share/backintime/common/mount.py", line 597, in umount
    self.removeSymlink()
    ~~~~~~~~~~~~~~~~~~^^
  File "/usr/share/backintime/common/mount.py", line 1070, in removeSymlink
    os.remove(self.config.snapshotsPath(
    ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
        profile_id=profile_id,
        ^^^^^^^^^^^^^^^^^^^^^^
        mode=self.mode,
        ^^^^^^^^^^^^^^^
        tmp_mount=tmp_mount))
        ^^^^^^^^^^^^^^^^^^^^^
FileNotFoundError: [Errno 2] No such file or directory: '/home/xxxxxxxxx/.local/share/backintime/mnt/1_5011'

The error message seems familiar to me. But I was never able to reproduce it for sure.

This is with the version backintime 1.6.0-dev.9b8291cf, which is the most up-to-date version available in ArchLinux AUR archive.

You can reproduce that problem with this version all the time?

Are you using this version for your real backups or just for testing?

Can you switch to the latest stable release in AUR (must be 1.5.6) and try to reproduce the problem.

If you have any more details to share, feel free to reach out.

Not sure when we'll find the time to work on it. Please see the projects background information to get an idea about our workflow and priorities:

Best regards, Christian

buhtz avatar Nov 10 '25 20:11 buhtz

Hi! I have used backintime for a long time, and never had a mount problem (or any problem!). So, now that I am back on version 1.5.6 - again no problems!

etyurin avatar Nov 10 '25 21:11 etyurin

Thanks for the hint. This helps with diagnosing.

By the way: I would not recommend to use the latest dev version (backintime-git in AUR) for regular backups. It is extreme unstable.

buhtz avatar Nov 11 '25 07:11 buhtz

Just for documentation. I can confirm that the problem did not exist in v1.5.6 (Debian 13) but was introduced after that in exist in latest dev.

DEBUG: [common/tools.py:265 set_locale_by_language_code] Determined normalized locale code "en_US.UTF-8" (from language code "en") not available (or invalid). The code will be ignored. This might lead to unusual display of dates and timestamps, but it does not affect the functionality of the application. Used locale is "('de_DE', 'UTF-8')".
DEBUG: [common/tools.py:227 initiate_translation] Language code used: "en"
DEBUG: [common/configfile.py:585 Config.setCurrentProfile] Change current profile to Main profile(1)
DEBUG: [qt/qttools.py:532 _show_qt_debug_info] {"QT QPA platform plugin": "xcb", "QT_QPA_PLATFORMTHEME": "<not set>", "QT_STYLE_OVERRIDE": "<not set>", "QT active style": "fusion", "QT fallback style": "", "QT supported styles": ["Breeze", "HighContrastInverse", "HighContrast", "Adwaita-HighContrastInverse", "Adwaita-HighContrast", "Adwaita-Dark", "Adwaita", "qt5ct-style", "qt6ct-style", "Windows", "Fusion"], "themeSearchPaths": ["/usr/local/share/icons", "/usr/share/icons", ":/icons"], "fallbackSearchPaths": [], "Is SystemTray available": true}
DEBUG: [qt/qttools.py:616 initiate_translator] Language code "en".
DEBUG: [common/tools.py:265 set_locale_by_language_code] Determined normalized locale code "en_US.UTF-8" (from language code "en") not available (or invalid). The code will be ignored. This might lead to unusual display of dates and timestamps, but it does not affect the functionality of the application. Used locale is "('de_DE', 'UTF-8')".
DEBUG: [qt/icon.py:40 <module>] Icon "document-save" found in installed theme: {QIcon.themeName()}
DEBUG: [common/snapshots.py:986 Snapshots.backup] Command "rsync --recursiv" returned 0
INFO: [common/snapshots.py:1180 Snapshots.backupConfig] Saving config file
INFO: [common/snapshots.py:1261 Snapshots.backupPermissions] Saving permissions
DEBUG: [common/config.py:727 Config.sshCommand] SSH command: ['ssh', '-o', 'ServerAliveInterval=240', '-o', 'LogLevel=Error', '-o', 'IdentityFile=/home/user/.ssh/id_ed25519', '-p', '22']
DEBUG: [common/tools.py:2330 run] Starting command: "rsync --dry-run -s -r --out-format=%n --rsh=ssh -o ServerAliveInterval=240 -o LogLevel=Error -o IdentityFile=/home/user/.ssh/id_ed25519 -p 22 user@localhost:/home/user/Vorlagen/backintime/quark/user22/1/new_snapshot/backup/ /tmp/tmpa1q17mab/"
DEBUG: [common/snapshots.py:1581 Snapshots.takeSnapshot] Command "rsync --dry-run " returned 0
DEBUG: [common/snapshots.py:1230 Snapshots._backup_info_file] Create info file for snapshot "2025-11-12 13:16:54".
DEBUG: [common/snapshots.py:2324 Snapshots.createLastSnapshotSymlink] Create symlink /home/user/.local/share/backintime/mnt/1_24033/backintime/quark/user22/1/last_snapshot => 20251112-131654-523
INFO: [common/status.py:160 _create_profile_status] Connecting to: Main profile
DEBUG: [common/sshtools.py:293 SSH.startSshAgent] ssh-agent already running. Skip starting a new one.
DEBUG: [common/sshtools.py:488 SSH.unlockSshAgent] Private key /home/user/.ssh/id_ed25519 is already unlocked in ssh agent
DEBUG: [common/mount.py:807 SSH.mountProcessLockAcquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
INFO: [common/mount.py:523 SSH.mount] Mountpoint /home/user/.local/share/backintime/mnt/A452AC5F/mountpoint is already mounted
DEBUG: [common/mount.py:831 SSH.mountLockAquire] Set mount lock /home/user/.local/share/backintime/mnt/A452AC5F/locks/24033.lock
DEBUG: [common/mount.py:818 SSH.mountProcessLockRelease] Release mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
DEBUG: [common/configfile.py:585 Config.setCurrentProfile] Change current profile to Main profile(1)
DEBUG: [common/mount.py:807 SSH.mountProcessLockAcquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
INFO: [common/mount.py:574 SSH.umount] Mountpoint /home/user/.local/share/backintime/mnt/A452AC5F/mountpoint still in use. Keep mounted.
DEBUG: [common/mount.py:854 SSH.mountLockRelease] Remove mount lock /home/user/.local/share/backintime/mnt/A452AC5F/locks/24033.lock
DEBUG: [common/mount.py:818 SSH.mountProcessLockRelease] Release mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
DEBUG: [plugins/usercallbackplugin.py:71 UserCallbackPlugin.callback] Call user-callback: /home/user/.config/backintime/user-callback 1 Main profile 3 20251112-131654-523 /home/user/.local/share/backintime/mnt/1_24033/backintime/quark/user22/1/20251112-131654-523
DEBUG: [plugins/usercallbackplugin.py:71 UserCallbackPlugin.callback] Call user-callback: /home/user/.config/backintime/user-callback 1 Main profile 2
DEBUG: [common/tools.py:1539 keyringSupported] Keyring config file directory: /home/user/.config/python_keyring
DEBUG: [common/tools.py:1554 keyringSupported] Available keyring backends:
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.SecretService.Keyring (priority: 5)
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.fail.Keyring (priority: 0)
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.chainer.ChainerBackend (priority: -1)
DEBUG: [common/tools.py:1615 keyringSupported] Not found Metaclasses: ['keyring.backends.Gnome.Keyring', 'keyring.backends.kwallet.Keyring', 'keyring.backend.SecretServiceKeyring', 'keyring.backend.GnomeKeyring', 'keyring.backend.KDEWallet']
DEBUG: [common/tools.py:1616 keyringSupported] Available supported backends: [<class 'keyring.backends.SecretService.Keyring'>, <class 'keyring.backends.kwallet.DBusKeyring'>, <class 'keyring.backends.chainer.ChainerBackend'>]
DEBUG: [common/tools.py:1620 keyringSupported] Found appropriate keyring 'keyring.backends.SecretService'
DEBUG: [plugins/usercallbackplugin.py:71 UserCallbackPlugin.callback] Call user-callback: /home/user/.config/backintime/user-callback 1 Main profile 8
DEBUG: [common/sshtools.py:293 SSH.startSshAgent] ssh-agent already running. Skip starting a new one.
DEBUG: [common/sshtools.py:488 SSH.unlockSshAgent] Private key /home/user/.ssh/id_ed25519 is already unlocked in ssh agent
DEBUG: [common/mount.py:807 SSH.mountProcessLockAcquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
INFO: [common/mount.py:574 SSH.umount] Mountpoint /home/user/.local/share/backintime/mnt/A452AC5F/mountpoint still in use. Keep mounted.
DEBUG: [common/mount.py:818 SSH.mountProcessLockRelease] Release mountprocess lock /home/user/.local/share/backintime/mnt/24033.lock
Traceback (most recent call last):
  File "/usr/share/backintime/common/backintime.py", line 173, in <module>
    startApp()
    ~~~~~~~~^^
  File "/usr/share/backintime/common/backintime.py", line 155, in startApp
    args.func(args)
    ~~~~~~~~~^^^^^^
  File "/usr/share/backintime/common/clicommands.py", line 110, in backup
    _do_backup(args, force)
    ~~~~~~~~~~^^^^^^^^^^^^^
  File "/usr/share/backintime/common/clicommands.py", line 132, in _do_backup
    ret = snapshots.Snapshots(cfg).backup(force)
  File "/usr/share/backintime/common/snapshots.py", line 1058, in backup
    .umount(self.config.current_hash_id)
     ~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/share/backintime/common/mount.py", line 269, in umount
    backend.umount()
    ~~~~~~~~~~~~~~^^
  File "/usr/share/backintime/common/mount.py", line 597, in umount
    self.removeSymlink()
    ~~~~~~~~~~~~~~~~~~^^
  File "/usr/share/backintime/common/mount.py", line 1070, in removeSymlink
    os.remove(self.config.snapshotsPath(
    ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
        profile_id=profile_id,
        ^^^^^^^^^^^^^^^^^^^^^^
        mode=self.mode,
        ^^^^^^^^^^^^^^^
        tmp_mount=tmp_mount))
        ^^^^^^^^^^^^^^^^^^^^^
FileNotFoundError: [Errno 2] Datei oder Verzeichnis nicht gefunden: '/home/user/.local/share/backintime/mnt/1_24033'
DEBUG: [common/tools.py:1539 keyringSupported] Keyring config file directory: /home/user/.config/python_keyring
DEBUG: [common/tools.py:1554 keyringSupported] Available keyring backends:
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.SecretService.Keyring (priority: 5)
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.fail.Keyring (priority: 0)
DEBUG: [common/tools.py:1558 keyringSupported] keyring.backends.chainer.ChainerBackend (priority: -1)
DEBUG: [common/tools.py:1615 keyringSupported] Not found Metaclasses: ['keyring.backends.Gnome.Keyring', 'keyring.backends.kwallet.Keyring', 'keyring.backend.SecretServiceKeyring', 'keyring.backend.GnomeKeyring', 'keyring.backend.KDEWallet']
DEBUG: [common/tools.py:1616 keyringSupported] Available supported backends: [<class 'keyring.backends.SecretService.Keyring'>, <class 'keyring.backends.kwallet.DBusKeyring'>, <class 'keyring.backends.chainer.ChainerBackend'>]
DEBUG: [common/tools.py:1620 keyringSupported] Found appropriate keyring 'keyring.backends.SecretService'
DEBUG: [plugins/usercallbackplugin.py:71 UserCallbackPlugin.callback] Call user-callback: /home/user/.config/backintime/user-callback 1 Main profile 8
DEBUG: [common/sshtools.py:293 SSH.startSshAgent] ssh-agent already running. Skip starting a new one.
DEBUG: [common/sshtools.py:488 SSH.unlockSshAgent] Private key /home/user/.ssh/id_ed25519 is already unlocked in ssh agent
DEBUG: [common/mount.py:807 SSH.mountProcessLockAcquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/23915.lock
INFO: [common/mount.py:587 SSH.umount] unmount ssh: user@localhost:/home/user/Vorlagen from /home/user/.local/share/backintime/mnt/A452AC5F/mountpoint
DEBUG: [common/mount.py:854 SSH.mountLockRelease] Remove mount lock /home/user/.local/share/backintime/mnt/A452AC5F/locks/23915.lock
DEBUG: [common/mount.py:818 SSH.mountProcessLockRelease] Release mountprocess lock /home/user/.local/share/backintime/mnt/23915.lock
DEBUG: [qt/statedata.py:177 save] Save state data.
DEBUG: [qt/statedata.py:148 file_path] State file path: /home/user/.local/state/backintime-qt.json
DEBUG: [plugins/usercallbackplugin.py:71 UserCallbackPlugin.callback] Call user-callback: /home/user/.config/backintime/user-callback 1 Main profile 6

buhtz avatar Nov 12 '25 12:11 buhtz

I debugged a lot and compared 1.5.6 with 1.6.0-dev. But I am not able to find the real problem. For some reason the symlink is deleted more often than it should. Might sounds easy to be found, but it is not.

So PR #2299 is just a workaround, catching the FileNotFoundException and just logging it as an error.

The mounting code incl. the locking mechanic is hard to understand. I have not written it. I need to dive deeper into it to improve my understanding. I'll do so in context of the #1734 (Transition from EncFS to Gocrypt).

Because of planed refactoring I am assuming that the problem will vanish in the long run without every being identified. 😅

buhtz avatar Nov 12 '25 14:11 buhtz

Hello Samuel (@s4moore), would you mind to join us here please. I would appreciate it. It seems to me that the new "status" command (PR #2019 fd323df) is involved in this issue.

When I remove the two uses of BackupStatus in this piece of code the error is gone.

https://github.com/bit-team/backintime/blob/3bda7b4f3c29da6e6b4b0687dbb5ac591d96af78/common/snapshots.py#L981-L992

Can you please have a look at it?

Regards, Christian

buhtz avatar Nov 12 '25 16:11 buhtz