SSH max arg length choke on SSH banner

[protist]

I'm backing up to my ssh server, and testing Smart remove > Run in background on remote Host. EXPERIMENTAL!. On my local computer, backintime is stuck on the Smart remove step, according to the system tray and backintime GUI. It's been stuck for several hours, which is much longer than it normally takes to smart remove when locally directed, over ssh.

However, as far as I can tell, the server isn't doing anything. I wasn't exactly sure what process to look for, so I tried searching sudo ps aux for rsync, screen, backintime and nohup. However, none of those were running.

On the local computer, I can see a few backintime and screen processes, as follows.

/usr/bin/python /usr/share/backintime/qt4/serviceHelper.py
python /usr/share/backintime/common/backintime.py pw-cache start
/bin/sh /usr/bin/backintime-qt4
python /usr/share/backintime/qt4/app.py
ssh-agent python /usr/share/backintime/qt4/app.py
ssh -p 123 -o ServerAliveInterval=240 -c arcfour -o IdentityFile=/root/.ssh/root@pi_rsa root@192.168.1.1 screen -d -m bash -c "(flock -x 9; ) 9>\"/media/Wells/backintime/hostname/root/1/smartremove.lck\""
/bin/sh /usr/sbin/backintime backup-job
python /usr/share/backintime/common/backintime.py backup-job
ssh-agent python /usr/share/backintime/common/backintime.py backup-job
sshfs -p 123 -o ServerAliveInterval=240 -o IdentityFile=/root/.ssh/root@pi_rsa -o Ciphers=arcfour -o idmap=user root@192.168.1.1:/media/Wells /root/.local/share/backintime/mnt/6A5D466C/mountpoint
/usr/bin/python /usr/share/backintime/qt4/qt4systrayicon.py 1

[Germar]

ssh -p 123 -o ServerAliveInterval=240 -c arcfour -o IdentityFile=/root/.ssh/root@pi_rsa root@192.168.1.1 screen -d -m bash -c "(flock -x 9; ) 9>\"/media/Wells/backintime/hostname/root/1/smartremove.lck\""

That command should be much longer. Please run a new snapshot with backintime backup --debug and post the output starting at smart-remove here.

[protist]

Hm… I wonder if that process name got truncated somehow. After posting the initial comment, my scheduled backup ran the next two nights, completing successfully. I guess I'll just have to wait for it to fail again. Is there a way to use --debug with scheduled backups?

[Germar]

Nope, it's missing in the middle. Not at the end. ...(flock -x 9; COMMANDS MISSING) 9>\"/media/Wells/...

If you open GUI with backintime-qt4 --debug and open/close Settingsdialog once BIT will change all scheduled backups to run with --debug, too.

[protist]

I think I have something informative. Before I got your reply about debugging, I ran my monthly checksum backup, this time over ssh. The snapshot part worked, but then I got this.

INFO: [smart remove] remove snapshots in background: ['20160523-183012-257', '20160518-210851-523', '20160311-174630-164']
Traceback (most recent call last):
  File "/usr/share/backintime/common/backintime.py", line 865, in <module>
    start_app()
  File "/usr/share/backintime/common/backintime.py", line 450, in start_app
    args.func(args)
  File "/usr/share/backintime/common/backintime.py", line 626, in backup
    ret = take_snapshot(cfg, force)
  File "/usr/share/backintime/common/backintime.py", line 70, in take_snapshot
    ret = snapshots.Snapshots( cfg ).take_snapshot( force )
  File "/usr/share/backintime/common/snapshots.py", line 1059, in take_snapshot
    self._free_space( now )
  File "/usr/share/backintime/common/snapshots.py", line 1679, in _free_space
    self.smart_remove( now, keep_all, keep_one_per_day, keep_one_per_week, keep_one_per_month )
  File "/usr/share/backintime/common/snapshots.py", line 1596, in smart_remove
    maxLength = self.config.ssh_max_arg_length()
  File "/usr/share/backintime/common/config.py", line 547, in ssh_max_arg_length
    raise ValueError('SSH max arg length %s is to low to run commands' % value)
ValueError: SSH max arg length 6 is to low to run commands

There were no snapshots removed. Having said this, the error was different from the one I first reported, as it crashed cleanly.

If you open GUI with backintime-qt4 --debug and open/close Settingsdialog once BIT will change all scheduled backups to run with --debug, too.

I then tried to do this, but I couldn't click OK after changing the settings. I had a similar error on the command line.

Traceback (most recent call last):
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1698, in accept
    if self.validate():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1452, in validate
    if not self.save_profile():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1327, in save_profile
    mnt.pre_mount_check(mode = mode, first_run = True, **mount_kwargs)
  File "/usr/share/backintime/common/mount.py", line 130, in pre_mount_check
    return tools.pre_mount_check(first_run)
  File "/usr/share/backintime/common/sshtools.py", line 152, in pre_mount_check
    self.check_remote_commands()
  File "/usr/share/backintime/common/sshtools.py", line 493, in check_remote_commands
    maxLength = self.config.ssh_max_arg_length(self.profile_id)
  File "/usr/share/backintime/common/config.py", line 547, in ssh_max_arg_length
    raise ValueError('SSH max arg length %s is to low to run commands' % value)
ValueError: SSH max arg length 6 is to low to run commands

[Germar]

Please run

sed '/snapshots.ssh.max_arg_length/d' -i ~/.config/backintime/config

and try again.

[protist]

Hm… I think it's happening fairly consistently now. I've never had anything removed yet. I tried to backup with backintime backup --debug.

...
INFO: [common/snapshots.py:1593 Snapshots.smart_remove] [smart remove] remove snapshots in background: ['20160526-093627-980', '20160523-183012-257', '20160518-210851-523', '20160311-174630-164']
Check length 1048320:   python exception: Argument list too long
Check length 524160:    python exception: Argument list too long
Check length 262080:    python exception: Argument list too long
Check length 131040:    is to long
Check length 65520: is to long
Check length 32760: is to long
Check length 16380: is to long
Check length 8190:  is to long
Check length 4095:  is to long
Check length 2047:  is to long
Check length 1023:  is to long
Check length 511:   is to long
Check length 255:   is to long
Check length 127:   is to long
Check length 63:    is to long
Check length 31:    is to long
Check length 15:    is to long
Check length 7: is to long
Check length 3: is to long
Check length 1: is to long
Maximum SSH argument length between <hostname> and root@192.168.1.1 is 6

I then get caught in the following loop.

DEBUG: [common/snapshots.py:1640 Snapshots.smart_remove] Call command "ssh -p 123 -o ServerAliveInterval=240 -c arcfour -o IdentityFile=/root/.ssh/root@pi_rsa root@192.168.1.1 'screen -d -m bash -c "(logger -t \"backintime smart-remove [$BASHPID]\" \"start\"; flock -x 9; logger -t \"backintime smart-remove [$BASHPID]\" \"got exclusive flock\"; ) 9>\"/media/Wells/backintime/hostname/root/1/smartremove.lck\""'"
<<<SSH login boilerplate>>>
DEBUG: [common/snapshots.py:1640 Snapshots.smart_remove] Command "ssh -p 709 -o Se..." returns 0

This just kept repeating. After a few hundred times I killed it. I checked the config file before and during the backup, and confirmed the removal of the line snapshots.ssh.max_arg_length. However, I also checked when backintime was stuck in the loop, and this line had reappeared!

[Germar]

Okay, for some reason the check for the argument length is going crazy on your system. Please add a line

profile1.snapshots.ssh.max_arg_length=1024

to your config and try again.

Also please post the output of

ssh USER@HOST printf foobar

[protist]

I'll test again later today. As for the output, it's as expected.

root@hostname:~# ssh pi printf foobar
<ssh boilerplate>
foobarroot@hostname:~#

[protist]

After modifying profile1.snapshots.ssh.max_arg_length=1024, I ran the backup again. It didn't throw any errors locally, and the config file stayed with the new setting. The local output said

INFO: [common/snapshots.py:1593 Snapshots.smart_remove] [smart remove] remove snapshots in background: ['20160526-093627-980', '20160523-200035-539', '20160523-183012-257', '20160518-210851-523', '20160318-174403-248', '20160311-174630-164']

The server seems to working remotely, but ridiculously slow. Two hours later, only two snapshots were removed remotely, 20160526-093627-980 and 20160523-183012-257 (not the first two, is that important?).

I looked at htop on the server, filtering for backintime. The SCREEN and/or logger processes were S interruptible sleep (waiting for an event to complete), but the only one that was D uninterruptible sleep (usually IO) was

find /media/Wells/backintime/hostname/root/1/20160523-200035-539 -type d -exec chmod u+wx {} +

which was only using ~5% of one core. I guess it's the storage medium that is slow, but I'm a bit surprised that it is that slow. The backup itself took exactly 35 minutes, which is quite normal. However, (I think) the smart-removes are normally much quicker than that. Somewhere between 2:08 and 2:29, the third snapshot was removed, so it's taking 42–50 minutes to remove a single snapshot.

I just checked htop on the server at another point, and it progressed to rm -rf…. I wonder if the find… chmod step is the slowest? (As per the other thread) if I'm logging into the server as root I'd not need to chmod before rm -rf. I realise this is not "recommended", so I'm not suggesting you modify code (unless it's easy to do, or for me to pass a simple option to) but it's more from curiosity…

[Germar]

Current master (next version 1.2.0) will use rsync to remove the files remote. It won't need find -type d -exec chmod ... anymore and is much faster. You can give it a try from backintime-git package.

Oh, and what is this <ssh boilerplate>? Could be the reason for the test to fail...

[protist]

Thanks for that. I've updated and I'll consider this fixed, then. If you'd like me to troubleshoot more, then I'm more than happy to help out. Just let me know what I can do (and reopen the issue).

Oh, <ssh boilerplate> is just the ssh greeting from my server, as defined in /etc/ssh/sshd_config's Banner.

[Germar]

Okay, so the check for max_arg_length chokes on SSH banners...