Bug #1471930 “IndexError on 'check_remote_commands” with 'run ni...” : Bugs : Back In Time

Revision history for this message

Germar (germar) wrote on 2015-07-06:

#1

add debug output Edit (527 bytes, text/plain)

I can't reproduce this here. Please apply the attached patch with
sudo patch /usr/share/backintime/common/sshtools.py < debug.patch

This will print the command and its output. It should look like this:

command: ['ssh', '-p', '22', '-o', 'ServerAliveInterval=240', '-o', 'IdentityFile=/xxxxx', 'test@foo', 'PATH=/opt/bin:/opt/sbin:$PATH', 'tmp=aab/tmp_OWH73R ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err_find; find $tmp -type f -exec chmod u-wx "{}" + >/dev/null; err_gnu_find=$?; echo "rm -rf PATH"; rm -rf $tmp >/dev/null; err_rm=$?; test $err_rm -ne 0 && cleanup $err_rm; echo "nice -n 19"; nice -n 19 true >/dev/null; err_nice=$?; test $err_nice -ne 0 && cleanup $err_nice; test $err_gnu_find -ne 0 && echo "gnu_find not supported" && exit $err_gnu_find; echo "done"']
output: ['cp -aRl SOURCE DEST', '1215254336 aab/tmp_OWH73R/a', '1215254336 aab/tmp_OWH73R/b', 'chmod u+rw FILE', 'find PATH -type f -exec chmod u-wx {} \\;', 'rm -rf PATH', 'nice -n 19', 'done']

Please post both command and output after activating run nice on remote.

--------

Commands which run during snapshot are logged to syslog. But these automatic tests doesn't log at the moment. I'm planning to move all commands to use subprocess.Popen (the old code is still using os.system and os.popen) and add a generic execute command for this which will have debugging, too. But that's a lot of work to do.

I can't reproduce this here. Please apply the attached patch with
sudo patch /usr/share/backintime/common/sshtools.py < debug.patch

This will print the command and its output. It should look like this:

command: ['ssh', '-p', '22', '-o', 'ServerAliveInterval=240', '-o', 'IdentityFile=/xxxxx', 'test@foo', 'PATH=/opt/bin:/opt/sbin:$PATH', 'tmp=aab/tmp_OWH73R ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err_find; find $tmp -type f -exec chmod u-wx "{}" + >/dev/null; err_gnu_find=$?; echo "rm -rf PATH"; rm -rf $tmp >/dev/null; err_rm=$?; test $err_rm -ne 0 && cleanup $err_rm; echo "nice -n 19"; nice -n 19 true >/dev/null; err_nice=$?; test $err_nice -ne 0 && cleanup $err_nice; test $err_gnu_find -ne 0 && echo "gnu_find not supported" && exit $err_gnu_find; echo "done"']
output: ['cp -aRl SOURCE DEST', '1215254336 aab/tmp_OWH73R/a', '1215254336 aab/tmp_OWH73R/b', 'chmod u+rw FILE', 'find PATH -type f -exec chmod u-wx {} \\;', 'rm -rf PATH', 'nice -n 19', 'done']

Please post both command and output after activating run nice on remote.

--------

Commands which run during snapshot are logged to syslog. But these automatic tests doesn't log at the moment. I'm planning to move all commands to use subprocess.Popen (the old code is still using os.system and os.popen) and add a generic execute command for this which will have debugging, too. But that's a lot of work to do.

Revision history for this message

Akki (akki.42) wrote on 2015-07-07:

#2

Download full text (4.9 KiB)

With run nice on remote activated, output is empty:

command: ['ssh', '-p', '622', '-o', 'ServerAliveInterval=240', '-o', '<email address hidden>', '<email address hidden>', 'tmp=/files/backup.encfs/tmp_ETNK4Y ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err_find; find $tmp -type f -exec chmod u-wx "{}" + >/dev/null; err_gnu_find=$?; echo "rm -rf PATH"; rm -rf $tmp >/dev/null; err_rm=$?; test $err_rm -ne 0 && cleanup $err_rm; echo "nice -n 19"; nice -n 19 true >/dev/null; err_nice=$?; test $err_nice -ne 0 && cleanup $err_nice; test $err_gnu_find -ne 0 && echo "gnu_find not supported" && exit $err_gnu_find; echo "done"']
output: []
Traceback (most recent call last):
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1612, in accept
    if self.validate():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1371, in validate
    if not self.save_profile():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1246, in save_profile
    mnt.pre_mount_check(mode = mode, first_run = True, **mount_kwargs)
  File "/usr/share/backintime/common/mount.py", line 118, in pre_mount_check
    return tools.pre_mount_check(first_run)
  File "/usr/share/backintime/common/encfstools.py", line 256, in pre_mount_check
    if self.ssh.pre_mount_check(*args, **kwargs) and \
  File "/usr/share/backintime/common/sshtools.py", line 147, in pre_mount_check
    self.check_remote_commands()
  File "/usr/share/backintime/common/sshtools.py", line 436, in check_remote_commands
    if output_split[-1].startswith(command):
IndexError: list index out of range

Running the above ssh command on console shows the following:

exec request failed on channel 0

With run nice on remote deactived, it's the following output:

command: ['ssh', '-p', '622', '-o', 'ServerAliveInterval=240', '-o', '<email address hidden>', '<email address hidden>', 'tmp=/files/backup.encfs/tmp_EK5H3F ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err...

With run nice on remote activated, output is empty:

command: ['ssh', '-p', '622', '-o', 'ServerAliveInterval=240', '-o', 'IdentityFile=/home/akki/.ssh/id_dsa_user@host.com', 'user@host.com', 'tmp=/files/backup.encfs/tmp_ETNK4Y ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err_find; find $tmp -type f -exec chmod u-wx "{}" + >/dev/null; err_gnu_find=$?; echo "rm -rf PATH"; rm -rf $tmp >/dev/null; err_rm=$?; test $err_rm -ne 0 && cleanup $err_rm; echo "nice -n 19"; nice -n 19 true >/dev/null; err_nice=$?; test $err_nice -ne 0 && cleanup $err_nice; test $err_gnu_find -ne 0 && echo "gnu_find not supported" && exit $err_gnu_find; echo "done"']
output: []
Traceback (most recent call last):
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1612, in accept
    if self.validate():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1371, in validate
    if not self.save_profile():
  File "/usr/share/backintime/qt4/settingsdialog.py", line 1246, in save_profile
    mnt.pre_mount_check(mode = mode, first_run = True, **mount_kwargs)
  File "/usr/share/backintime/common/mount.py", line 118, in pre_mount_check
    return tools.pre_mount_check(first_run)
  File "/usr/share/backintime/common/encfstools.py", line 256, in pre_mount_check
    if self.ssh.pre_mount_check(*args, **kwargs) and \
  File "/usr/share/backintime/common/sshtools.py", line 147, in pre_mount_check
    self.check_remote_commands()
  File "/usr/share/backintime/common/sshtools.py", line 436, in check_remote_commands
    if output_split[-1].startswith(command):
IndexError: list index out of range

Running the above ssh command on console shows the following:

exec request failed on channel 0

With run nice on remote deactived, it's the following output:

command: ['ssh', '-p', '622', '-o', 'ServerAliveInterval=240', '-o', 'IdentityFile=/home/akki/.ssh/id_dsa_user@host.com', 'user@host.com', 'tmp=/files/backup.encfs/tmp_EK5H3F ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; test -e $tmp || mkdir $tmp; touch $tmp/a; echo "cp -aRl SOURCE DEST"; cp -aRl $tmp/a $tmp/b >/dev/null; err_cp=$?; test $err_cp -ne 0 && cleanup $err_cp; ls -i $tmp/a; ls -i $tmp/b; echo "chmod u+rw FILE"; chmod u+rw $tmp/a >/dev/null; err_chmod=$?; test $err_chmod -ne 0 && cleanup $err_chmod; echo "find PATH -type f -exec chmod u-wx "{}" \\;"; find $tmp -type f -exec chmod u-wx "{}" \\; >/dev/null; err_find=$?; test $err_find -ne 0 && cleanup $err_find; find $tmp -type f -exec chmod u-wx "{}" + >/dev/null; err_gnu_find=$?; echo "rm -rf PATH"; rm -rf $tmp >/dev/null; err_rm=$?; test $err_rm -ne 0 && cleanup $err_rm; test $err_gnu_find -ne 0 && echo "gnu_find not supported" && exit $err_gnu_find; echo "done"']
output: ['cp -aRl SOURCE DEST', '7733814 /files/backup.encfs/tmp_EK5H3F/a', '7733814 /files/backup.encfs/tmp_EK5H3F/b', 'chmod u+rw FILE', 'find PATH -type f -exec chmod u-wx {} \\;', 'rm -rf PATH', 'done']

On console, output for this is:

cp -aRl SOURCE DEST
7733836 /files/backup.encfs/tmp_EK5H3F/a
7733836 /files/backup.encfs/tmp_EK5H3F/b
chmod u+rw FILE
find PATH -type f -exec chmod u-wx {} \;
rm -rf PATH
done
find: -exec requires an argument

(The find error at the end results from the 'find $tmp -type f -exec chmod u-wx "{}" \\;' command.)

Using only the nice-related part of the first command

'ssh' '-p' '622' '-o' 'ServerAliveInterval=240' '-o' 'IdentityFile=/home/akki/.ssh/id_dsa_user@host.com' 'user@host.com' 'tmp=/files/backup.encfs/tmp_ETNK4Y ; cleanup(){ test -e $tmp/a && rm $tmp/a >/dev/null 2>&1; test -e $tmp/b && rm $tmp/b >/dev/null 2>&1; test -e smr.lock && rm smr.lock >/dev/null 2>&1; test -e $tmp && rmdir $tmp >/dev/null 2>&1; exit $1; }; echo "nice -n 19"; nice -n 19 true >/dev/null; err_nice=$?; test $err_nice -ne 0 && cleanup $err_nice; echo "done"'

results in the following output:

nice -n 19
done

To me the problem seems to be a limit on the number of characters; some quick & dirty testing with an echo command reveals a limit of 1024 characters. As getconf ARG_MAX on the remote shell (ash / BusyBox v1.19.4) returned 2097152, this  probably is  another bug / limit of the sshd used by my hosting provider, isn't it?

Sorry again for my non-reproducable bug reports...

Revision history for this message

Germar (germar) wrote on 2015-07-07:

#3

Sure, that could be the case. A quick search showed me this script to check out the max_arg for a ssh connection
http://www.theeggeadventure.com/wikimedia/index.php/Ssh_argument_length

With my NAS this is 4106

I'll add a test for this based on the above script and split the sshtools.check_remote_commands script according to max_arg.

I wouldn't see this as a bug on your hosting providers side. It's just a normal limitation.

Changed in backintime:
status:	New → Triaged
importance:	Undecided → Medium
milestone:	none → 1.1.8

Revision history for this message

Akki (akki.42) wrote on 2015-07-08:

#4

That would be great - thanks!

Revision history for this message

Germar (germar) wrote on 2015-07-10:

#5

sshMaxArg Edit (2.7 KiB, text/plain)

I rewrote that script in python and found out that the original script wasn't working correct. The dd command croped the lenght always to 4096 chars.

So, with my script all my hosts have a max arg length of 131064.

Can you please run that script and report your length?

chmod 755 sshMaxArg
./sshMaxArg USER@HOST

Revision history for this message

Akki (akki.42) wrote on 2015-07-11:

#6

Your script reports a correct max arg length of 1018 with my host:

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: can be longer
Check length 767: can be longer
Check length 895: can be longer
Check length 959: can be longer
Check length 991: can be longer
Check length 1007: can be longer
Check length 1015: can be longer
Check length 1019: is to long
Check length 1017: can be longer
Maximum ssh argument lengh between local and remote_host is 1018

(To get the 'full' max arg length, I think you would have to add the 6 characters of 'printf' to that number?)

Revision history for this message

Germar (germar) wrote on 2015-07-20:

#7

Could you please try out our testing PPA?

sudo add-apt-repository ppa:bit-team/testing
sudo apt-get update
sudo apt-get upgrade

I've no idea how to trick my sshd into only accepting max arg = 1024. But I already tested with bulk commands.

Changed in backintime:
status:	Triaged → Fix Committed
assignee:	nobody → Germar (germar)

Revision history for this message

Akki (akki.42) wrote on 2015-07-20:

#8

ssh command and traceback Edit (2.1 KiB, text/plain)

Alas, I'm on opensuse with no (ready) access to your apt-repository.

As you marked this as "fix committed", I did check the current launchpad trunk version (revision 1116). Unfortunately, that version does not solve this bug yet. (When patched as in your comment #1 above, backintime-qt4 returns a command that is twenty characters shorter than before, but still beyond the 1024 limit, cf. attached log.)

Revision history for this message

Germar (germar) wrote on 2015-07-20:

#9

Oh, right. I checked if the output is empty before eliminating blank lines.

Can you please try again with rev 1117?

Revision history for this message

Akki (akki.42) wrote on 2015-07-20:

#10

Revision 1117 works fine! (SSH command is split into two parts with 931 and 357 characters, respectively.)

Many thanks - and keep up your great work! ;-)

Revision history for this message

Germar (germar) wrote on 2015-07-20:

#11

Great. Thanks for testing!

Germar (germar) on 2015-09-28

Changed in backintime:
status:	Fix Committed → Fix Released

Back In Time

IndexError on 'check_remote_commands" with 'run nice on remote host'

Bug Description

Related branches

Other bug subscribers

Bug attachments

Remote bug watches