Difficult to debug 'Destination not ready to receive commands.' errors even with '--debug' flag.

[t-gh-ctrl]

[apologies for spamming you with issues; this issue is somehow related to #232 but with a specific problem that I don't manage to debug]

wyng 20250121 on QubesOS 4.2.3

All of a sudden I began to have 'Destination not ready to receive commands.' errors when backup'ing volumes with a qubes-ssh destination ([edit: I get the issue with a local filesytem destination too ; logs appended]). That setup has been working well for the past month or so (automated backups running while the machine becomes idle), even while doing many tests over the last week when testing new versions.

The only two things that I remember that have changed are 1/ the ssh host got restarted after a nightly kernel update (there weren't any other updates) and 2/ I removed a user on that host, but it wasn't related to wyng.

So, I'm quite puzzled, as I can't manage to find/debug what's going on.

For the sake of debugging, I'm starting from scratch with arch-init but I get the same thing while sending volumes (I haven't tried other commands though).

$ sudo wyng arch-init --debug --dest="qubes-ssh://vm-backup:sshuser@sshhost:/backup/wyng"

Python 3.11.6 (main, Oct  3 2023, 00:00:00) [GCC 12.3.1 20230508 (Red Hat 12.3.1-1)]
 posix.uname_result(sysname='Linux', nodename='dom0', release='6.6.68-1.qubes.fc37.x86_64', version='#1 SMP PREEMPT_DYNAMIC Thu Jan  2 07:00:16 GMT 2025', machine='x86_64')

 {'action': 'arch-init', 'volumes': [], 'unattended': False, 'authmin': '-1', 'allbefore': False, 'all': False, 'session': None, 'session_strict': 'on', 'tag': [], 'keep': [], 'volex': [], 'autoprune': 'full', 'apdays': '180:8:1:1', 'save_to': None, 'sparse': False, 'sparse_write': False, 'skip_corrupt_chunks': False, 'use_snapshot': False, 'import_other_from': [], 'remap': False, 'send_unchanged': False, 'dest': 'qubes-ssh://vm-backup:sshuser@sshhost:/backup/wyng', 'local': 'qubes_dom0/vm-pool', 'local_from': None, 'encrypt': None, 'compression': '', 'hashtype': '', 'chfactor': None, 'vid': None, 'passcmd': '', 'metadir': '', 'meta_reduce': 'on:3000', 'json': False, 'force': False, 'clean': False, 'purge': None, 'maxsync': False, 'upgrade_format': False, 'tar_bypass': False, 'opt_ssh': [], 'opt_qubes': [], 'change_uuid': False, 'dry_run': False, 'debug': True, 'quiet': False, 'verbose': 0, 'dedup': True, 'voldesc': ''}

Wyng 0.8 beta release 20250121

Dest detect:
wyng_dir_exists
Python 3.9.21
Linux sshhost 5.14.0-503.22.1.el9_5.x86_64 #1 SMP PREEMPT_DYNAMIC Fri Jan 24 03:55:12 EST 2025 x86_64 x86_64 x86_64 GNU/Linux
wyng_online
wyng_check_free /dev/mapper/luks-ff723f92-1442-4127-b9f2-50261ac94f30 xfs  13670277120 9100576064 4569701056      67%
wyng_archive_ini none
wyng_writable
wyng_hlink

SSH & VM opts: ['-x', '-T', '-e', 'none', '-o', 'ControlPath=~/.ssh/ctrl-%C', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=300', '-o', 'ServerAliveInterval=120', '-o', 'ConnectTimeout=60', '-o', 'Compression=no']
 ['--no-color-stderr', '--no-color-output', '--nogui', '--no-filter-escape-chars']

Destination not ready to receive commands.

Yet, ssh to the ssh host with the options used by wyng works, the folder on the ssh host is writeable, wyng has even created an archive there:

$ qvm-run -p vm-backup "ssh -x -T -e none -o ControlPath="~/.ssh/ctrl-%C" -o ControlMaster=auto -o ControlPersist=300 -o ServerAliveInterval=120 -o ConnectTimeout=60 -o Compression=no sshuser@sshhost 'ls -l /backup/wyng'"
total 0
-rw-r--r-- 2 sshuser wyng 0 Jan 27 06:26 archive.dat

Any tip on how to debug this further?

[edit] - I thought the problem would be because of something that may have changed on the remote host, but I just tried with a "blank" installation and a local destination, and it fails too:

Cleanup:

$ sudo rm -fr /tmp/test*
$ sudo mv /etc/wyng/wyng.ini somewhereelse

arch-init:

$ sudo wyng arch-init --debug --dest="file:/tmp/test"
Python 3.11.6 (main, Oct  3 2023, 00:00:00) [GCC 12.3.1 20230508 (Red Hat 12.3.1-1)]
 posix.uname_result(sysname='Linux', nodename='dom0', release='6.6.68-1.qubes.fc37.x86_64', version='#1 SMP PREEMPT_DYNAMIC Thu Jan  2 07:00:16 GMT 2025', machine='x86_64')

 {'action': 'arch-init', 'volumes': [], 'unattended': False, 'authmin': '5', 'allbefore': False, 'all': False, 'session': None, 'session_strict': 'on', 'tag': [], 'keep': [], 'volex': [], 'autoprune': 'off', 'apdays': None, 'save_to': None, 'sparse': False, 'sparse_write': False, 'skip_corrupt_chunks': False, 'use_snapshot': False, 'import_other_from': [], 'remap': False, 'send_unchanged': False, 'dest': 'file:/tmp/test', 'local': '', 'local_from': None, 'encrypt': None, 'compression': '', 'hashtype': '', 'chfactor': None, 'vid': None, 'passcmd': '', 'metadir': '', 'meta_reduce': 'on:3000', 'json': False, 'force': False, 'clean': False, 'purge': None, 'maxsync': False, 'upgrade_format': False, 'tar_bypass': False, 'opt_ssh': [], 'opt_qubes': [], 'change_uuid': False, 'dry_run': False, 'debug': True, 'quiet': False, 'verbose': 0, 'dedup': False, 'voldesc': ''}

Wyng 0.8 beta release 20250121

Dest detect:
wyng_dir_exists
Python 3.11.6
Linux dom0 6.6.68-1.qubes.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Jan  2 07:00:16 GMT 2025 x86_64 x86_64 x86_64 GNU/Linux
wyng_online
wyng_check_free tmpfs          tmpfs     1996452    32   1996420       1% /tmp
wyng_archive_ini none
wyng_writable
wyng_hlink

SSH & VM opts: ['-x', '-T', '-e', 'none', '-o', 'ControlPath=~/.ssh/ctrl-%C', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=300', '-o', 'ServerAliveInterval=120', '-o', 'ConnectTimeout=60', '-o', 'Compression=no']
 ['--no-color-stderr', '--no-color-output', '--nogui', '--no-filter-escape-chars']

Destination not ready to receive commands.

wyng created files in the dest folder:

$ ls -al /tmp/test
total 0
drwxr-xr-x  2 root root  80 Jan 27 07:01 .
drwxrwxrwt 14 root root 320 Jan 27 07:01 ..
-rw-r--r--  2 root root   0 Jan 27 07:01 archive.dat
-rw-r--r--  2 root root   0 Jan 27 07:01 .hardlink

[tasket]

@t-gh-ctrl It is looking for 'archive.ini' file in the destination dir.

I'll try to reproduce the arch-init missing ini condition.

[t-gh-ctrl]

It is looking for 'archive.ini' file in the destination dir

I'm not sure that's the culprit: I took arch-init as an example to rule out issues with my main archive, but 'archive.ini' does exist in my main archive's folder (along with archive.dat, archive.salt, salt.bak and Vol_xxxxxx dirs).

[edit] - here's a log with the archive that used to work:

$ sudo wyng send dom0-backup --debug

Python 3.11.6 (main, Oct  3 2023, 00:00:00) [GCC 12.3.1 20230508 (Red Hat 12.3.1-1)]
 posix.uname_result(sysname='Linux', nodename='dom0', release='6.6.68-1.qubes.fc37.x86_64', version='#1 SMP PREEMPT_DYNAMIC Thu Jan  2 07:00:16 GMT 2025', machine='x86_64')

 {'action': 'send', 'volumes': ['dom0-backup'], 'unattended': False, 'authmin': '-1', 'allbefore': False, 'all': False, 'session': None, 'session_strict': 'on', 'tag': [], 'keep': [], 'volex': [], 'autoprune': 'full', 'apdays': '180:8:1:1', 'save_to': None, 'sparse': False, 'sparse_write': False, 'skip_corrupt_chunks': False, 'use_snapshot': False, 'import_other_from': [], 'remap': False, 'send_unchanged': False, 'dest': 'qubes-ssh://vm-backup:sshuser@sshhost:/backup/sshuser', 'local': 'qubes_dom0/vm-pool', 'local_from': None, 'encrypt': None, 'compression': '', 'hashtype': '', 'chfactor': None, 'vid': None, 'passcmd': '', 'metadir': '', 'meta_reduce': 'on:3000', 'json': False, 'force': False, 'clean': False, 'purge': None, 'maxsync': False, 'upgrade_format': False, 'tar_bypass': False, 'opt_ssh': [], 'opt_qubes': [], 'change_uuid': False, 'dry_run': False, 'debug': True, 'quiet': False, 'verbose': 0, 'dedup': True, 'voldesc': ''}

Wyng 0.8 beta release 20250121

Dest detect:
wyng_dir_exists
Python 3.9.21
Linux sshhost 5.14.0-503.22.1.el9_5.x86_64 #1 SMP PREEMPT_DYNAMIC Fri Jan 24 03:55:12 EST 2025 x86_64 x86_64 x86_64 GNU/Linux
wyng_online
wyng_check_free /dev/mapper/luks-ff723f92-1442-4127-b9f2-50261ac94f30 xfs  13670277120 9100576064 4569701056      67%
wyng_archive_ini 45c5af5f2e8372f47941c83624ba89eec7689bc4072b9f89acce9edcf2441c1e  archive.ini
wyng_writable
wyng_hlink

SSH & VM opts: ['-x', '-T', '-e', 'none', '-o', 'ControlPath=~/.ssh/ctrl-%C', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=300', '-o', 'ServerAliveInterval=120', '-o', 'ConnectTimeout=60', '-o', 'Compression=no']
 ['--no-color-stderr', '--no-color-output', '--nogui', '--no-filter-escape-chars']

Destination not ready to receive commands.

[tasket]

@t-gh-ctrl I've been trying to improved detection at the dest location. Pushed an update to 08wip.

Also, when you run Wyng with --debug (use -w debug from the util) you can access temp data files it was using at /tmp/wyng-debug.

[t-gh-ctrl]

Pushed an update to 08wip.

Yes, that's fixed!

(by the way I tested 20250117 meanwhile - it works - so one of the recent changes in v20250121 broke something; but why it worked for a couple days and then stopped working out of the blue is a mistery).

Also, when you run Wyng with --debug (use -w debug from the util) you can access temp data files it was using at /tmp/wyng-debug

Oh, I didn't know, that will be helpful.

Thank you!

[edit - you rock; I donated via liberapay but I realized after making my payment that instead of receiving the whole amount you'll get a fraction of it each week over the next 12 months. So you'll drink only one coffee/beer a week from me :) ]

[tasket]

Thank you for the donation! :)