Plugin keeps timing out, can't see why
Closed this issue · 21 comments
Hi, I believe I've got the plugin configured correctly, with arguments:
-rv /storage/emulated/0/DCIM/Camera Pi@192.168.1.169:/media/chudrive/Camera
and have copied public key to the server, but when I try to run the sync I get the error message "Error: 2" and "Plugin did not respond before timing out" - this happens even if I increase timeout to 3 or 4 minutes. Nothing showing in dmesg or in auth.log on the destination server to indicate the connection's been blocked and nothing comes through on %errmsg. Battery optimisation is disabled. Any ideas?
Hmm, bit of a tricky one to debug but probably worth trying the dbclient action with arguments something like:
-vvv Pi@192.168.1.169 true
With a bit of luck that will dump out a load of logging about what it's doing, however if that hangs until timeout as well I'll probably need to do a bit more head-scratching 😄. Let me know how you get on.
Hi Matt, thankyou for that. Unfortunately it didn't indeed hang until abort so no way to get any output. Here's the full error code from Tasker, don't know if it helps at all?
14.03.30/E FIRE PLUGIN: dbclient / com.twofortyfouram.locale.intent.action.FIRE_SETTING: 8 bundle keys
14.03.30/E dbclient: plugin comp: com.nerdoftheherd.tasker.rsync/com.joaomgcd.taskerpluginlibrary.action.IntentServiceAction
14.03.30/Ew add wait type Plugin1 time 6
14.03.30/Ew add wait type Plugin1 done
14.03.30/E handlePluginFinish: taskExeID: 1 result 3
14.03.30/E pending result code
14.03.30/E add wait task
14.03.36/E Error: 2
14.03.36/E Plugin did not respond before timing out. You can change the timeout value in the action's configuration.
I feared that might be the case... A couple of other things to try which might shed (a little) light on the subject:
Try running the dbclient action with just the argument -h (to just show the help and exit). That should let us work out if the hang is related to trying to connect to the network or just from running the binary at all.
Check the adb logcat output after running the dbclient task from Tasker, the plugin writes a message before and after executing the binary (when things are working correctly):
06-08 20:38:03.977 13145 13162 D DbclientRunner: About to run dbclient
...
06-08 20:38:04.018 13145 13162 D DbclientRunner: Run completed, exit code 0
There might be a useful error shown shortly after the About to run dbclient message in your case that gives us a clue. Keep me posted 🙂
Hi Matt, thanks for your time and one to one support on this :) -h gives the dropbear help text on %stderr, nothing comes through on the other variables so looks like the binary is running.
Running -h gives the following output on logcat:
06-09 14:25:24.117 12916 15495 D DbclientRunner: About to run dbclient
06-09 14:25:24.132 12916 15495 D DbclientRunner: Run completed, exit code 0
Running -vvv just gives:
06-09 14:27:41.025 12916 15736 D DbclientRunner: About to run dbclient
No followup line appears after the process times out.
Okay, good to narrow down that calling the binary works okay 👍. Think the issue is that as the plugin is capturing the output, waiting for the binary to exit which for whatever reason never happens so the debug output is lost too. I'll mull over how best to enhance the plugin to avoid this.
Right, I've just released a new version which adds a Timeout option to the dbclient action - if you set this to a bit less than the Tasker timeout for the action it should then kill the dbclient binary and return the standard error output from dbclient as part of the exception it throws before Tasker times out the action.
It's a bit annoying having a separate timeout setting in this plugin to the Tasker one but the library I'm using to interface easily with Tasker doesn't appear to support fetching this information, although I think that Tasker makes it available - I've raised joaomgcd/TaskerPluginSample#21 to see if this can be added.
Could you give this a try with the command -vvv Pi@192.168.1.169 true and see if that gives you any more information to go on? Let me know how you get on...
Hi Matt, thank you very much for that, that's definitely helped clarify - key error message seems to be that host is not in the trusted hosts file. Now this is probably me being thick, I'm used to connecting to a host via SSH, getting that prompt but then being given the option to add the host to the file automatically hence why I wasn't expecting this. However, I've copied the key from the error message to the "Known host keys" line in the dbclient page (see pics), but it's still throwing the same error. Assuming I'm still being thick but what am I missing?
Ah, that's great news! Thanks for the update and glad it made the issue less unfathomable. The format for the known host key is the same format as in ~/.ssh/known_hosts if you're using OpenSSH on another machine to connect (what you've entered is the key fingerprint rather than the key itself). I'm away from my PC today but can give you some more info tomorrow.
Ah, that's great news! Thanks for the update and glad it made the issue less unfathomable. The format for the known host key is the same format as in ~/.ssh/known_hosts if you're using OpenSSH on another machine to connect (what you've entered is the key fingerprint rather than the key itself). I'm away from my PC today but can give you some more info tomorrow.
Okay, got there in the end, after some experimentation ran ssh-keyscan -t ssh-ed25519 192.168.1.169 from another machine, copied the key over and looked like it matched but now there's a different issue 😆
`09.44.26/E FIRE PLUGIN: dbclient / com.twofortyfouram.locale.intent.action.FIRE_SETTING: 9 bundle keys
09.44.26/E dbclient: plugin comp: com.nerdoftheherd.tasker.rsync/com.joaomgcd.taskerpluginlibrary.action.IntentServiceAction
09.44.26/Ew add wait type Plugin1 time 34
09.44.26/Ew add wait type Plugin1 done
09.44.26/E handlePluginFinish: taskExeID: 1 result 3
09.44.26/E pending result code
09.44.26/E add wait task
09.44.27/E Error: 2
09.44.27/E TRACE1 (27500) 0.000000: connect to: user=pi host=192.168.1.169/22
TRACE1 (27500) 0.010487: cli_connected
TRACE1 (27500) 0.067367: remoteident: SSH-2.0-OpenSSH_8.4p1 Debian-5+deb11u1
TRACE3 (27500) 0.074973: buf_match_algo: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256
TRACE3 (27500) 0.075043: kex algo curve25519-sha256
TRACE3 (27500) 0.075053: buf_match_algo: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519
TRACE2 (27500) 0.075060: hostkey algo ssh-ed25519
TRACE3 (27500) 0.075068: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
TRACE2 (27500) 0.075076: enc c2s is chacha20-poly1305@openssh.com
TRACE3 (27500) 0.075082: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
TRACE2 (27500) 0.075089: enc s2c is chacha20-poly1305@openssh.com
TRACE3 (27500) 0.075095: buf_match_algo: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
TRACE2 (27500) 0.075103: hmac c2s is
TRACE3 (27500) 0.075110: buf_match_algo: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
TRACE2 (27500) 0.075117: hmac s2c is
TRACE3 (27500) 0.075125: buf_match_algo: none,zlib@openssh.com
TRACE2 (27500) 0.075132: comp c2s is zlib@openssh.com
TRACE3 (27500) 0.075138: buf_match_algo: none,zlib@openssh.com
TRACE2 (27500) 0.075144: comp s2c is zlib@openssh.com
TRACE1 (27500) 0.095731: server match SHA256:RALBitDJNd1WuCSFc+hP59zDIvz+Ppl9Pu0edq7C22w
TRACE1 (27500) 0.159194: enter send_msg_userauth_pubkey ssh-ed25519
/data/app/~~zYqJbOxmVD6cvO8NluDyFw==/com.nerdoftheherd.tasker.rsync-z-enmSmLtTnhw7PAOV1Phg==/lib/arm64/libdbclient.so: Connection to pi@192.168.1.169:22 exited: No auth methods could be used.`
Great, glad you got past that hurdle. I'd suggest checking the server side logs at this stage, might be a permissions issue on ~/.ssh/authorized_keys (or just that the key doesn't match).
Okay, sorry mate, it's not a permissions issue because other machines are connecting fine to the target. Neither dmesg or auth.log shows anything after either failed attempt.
ssh-keyscan to 192.168.1.169 from another machine which can connect to it gives three keys:
192.168.1.169 ssh-rsa AAAAB3NzaC1yc2EAAAADAQAB...etc...
192.168.1.169 ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbm...etc....
192.168.1.169 ssh-ed25519 AAAAC3NzaC1lZDI1NTE5...etc...
I have copied the whole of each line into the Known Host Keys line for a dbclient connect and got the same errors (the first two time out with "Host 192.168.1.169 is not in the trusted hosts file", the third one gives the "No auth methods could be used" error. I have also tried just copying the key portion (e.g. AAAAB3 etc) into the line and that doesn't work.
You say it needs to be in the same format as known_hosts, the only matching line in known_hosts on the machine which can connect is:
|1|DIYFwL6vOxzX1uXkfvKn3L+PadA=|hvsMv0iG+6b315YgkKf0ycHesPg= ecdsa-sha2-nistp256 AAAAE2VjZHNhLXN...etc... - I have copied this line into the Known Host Keys field and that also gives the 192.168.1.169 is not in the trusted hosts file" error.
Sorry, probably wasn't clear - the log in your last but one comment above shows dbclient successfully accepting the host key, the issue after that is related to the client's private key not being accepted by the server, that's what you need to figure out now. (The public key produced by the Get Public Key plugin action needs to be present in ~/.ssh/authorized_keys for the pi user)
You say it needs to be in the same format as known_hosts, the only matching line in known_hosts on the machine which can connect is:
|1|DIYFwL6vOxzX1uXkfvKn3L+PadA=|hvsMv0iG+6b315YgkKf0ycHesPg= ecdsa-sha2-nistp256 AAAAE2VjZHNhLXN...etc... - I have copied this line into the Known Host Keys field and that also gives the 192.168.1.169 is not in the trusted hosts file" error.
Looks like OpenSSH on the other machine you're using has the HashKnownHosts option enabled but dbclient needs the host name itself in the file.
Sorry, probably wasn't clear - the log in your last but one comment above shows
dbclientsuccessfully accepting the host key, the issue after that is related to the client's private key not being accepted by the server, that's what you need to figure out now. (The public key produced by the Get Public Key plugin action needs to be present in ~/.ssh/authorized_keys for the pi user)
Oh my god it worked - and the rsync did too :D Thank you so much for patiently working me through this, Matt - not having had to deal with manual ssh authentication before it was so hard to tell what was standard and what was specific to the plugin, I really appreciate it :) Donation link on your site's broken, let me know when you get it fixed as I'd like to buy you a thank you beer!
Hahaha, I spoke too soon :D I'm sure this one isn't me: I'm running it with the following args:
-av "/storage/emulated/0/DCIM/Camera/" "pi@192.168.1.169:/media/pi/Seagate Backup Plus Drive/Camera/"
I'm getting this to %stderrr:
WARNING: Ignoring unknown option -4
And then it's creating directories, but not transferring files. Have tried with just -r instead of -a and same result. It's definitely creating the directories because if I delete a dir in the destination folder it creates it again.
Donation link on your site's broken, let me know when you get it fixed as I'd like to buy you a thank you beer!
Ha, thanks for the heads-up - I wonder how long it's been since PayPal silently broke that 🤦. I've updated it to their latest donate URL and button ID format so it should be working again now.
For your folder (but no files) issue, it's a little tricky to diagnose from here but I'd suggest passing the verbose flag twice (e.g. -avv or -rvv) to rsync as that should produce output (to stdout) explaining why it skipped transferring files on top of the usual verbose output listing what was transferred.
That 'WARNING: Ignoring unknown option -4' output is most odd though...
Okay, -avv didn't say much so I pushed it to -avvv :D Looks like the -4 is the ipv4 only switch sent to ssh rather than sent to rsync but not sure why it's causing the error. For the rest I really can't see why it's not moving the files - there are definitely files in /Camera and in /Camera/Added folder 2 which aren't in the destination, but they're not getting transferred!
`opening connection using: ssh -l pi -4 192.168.1.169 rsync --server -vvvlogDtpre.iLfxCIvu . "/media/pi/Seagate\ Backup\ Plus\ Drive/Camera/" (10 args)
sending incremental file list
[sender] make_file(.,,0)
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/
[sender] make_file(Original size,,2)
[sender] make_file(cache,,2)
[sender] make_file(Added folder 2,,2)
[sender] make_file(Added folder 1,,2)
send_file_list done
send_files starting
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/Added folder 1/
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/Added folder 2/
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/Original size/
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/cache/
[sender] make_file(cache/latest,,2)
[sender] pushing local filters for /storage/emulated/0/DCIM/Camera/cache/latest/
server_recv(2) starting pid=114389
recv_file_name(.)
recv_file_name(Original size)
recv_file_name(cache)
recv_file_name(Added folder 2)
recv_file_name(Added folder 1)
received 5 names
recv_file_list done
get_local_name count=5 /media/pi/Seagate Backup Plus Drive/Camera/
generator starting pid=114389
delta-transmission enabled
recv_generator(.,0)
recv_generator(.,1)
recv_generator(Added folder 1,2)
recv_generator(Added folder 2,3)
recv_generator(Original size,4)
recv_generator(cache,5)
send_files(0, /storage/emulated/0/DCIM/Camera/.)
recv_files(5) starting
[receiver] receiving flist for dir 1
received 0 names
recv_file_list done
[receiver] receiving flist for dir 2
received 0 names
recv_file_list done
[receiver] receiving flist for dir 3
received 0 names
recv_file_list done
[receiver] receiving flist for dir 4
recv_file_name(cache/latest)
received 1 names
recv_file_list done
[receiver] receiving flist for dir 5
received 0 names
recv_file_list done
recv_files(.)
[generator] receiving flist for dir 1
received 0 names
recv_file_list done
recv_generator(Added folder 1,6)
[generator] receiving flist for dir 2
received 0 names
recv_file_list done
recv_generator(Added folder 2,7)
[generator] receiving flist for dir 3
received 0 names
recv_file_list done
recv_generator(Original size,8)
[generator] receiving flist for dir 4
recv_file_name(cache/latest)
received 1 names
recv_file_list done
recv_generator(cache,9)
recv_generator(cache/latest,10)
[generator] receiving flist for dir 5
received 0 names
recv_file_list done
recv_generator(cache/latest,11)
generate_files phase=1
send_files(6, /storage/emulated/0/DCIM/Camera/Added folder 1)
send_files(7, /storage/emulated/0/DCIM/Camera/Added folder 2)
send_files(8, /storage/emulated/0/DCIM/Camera/Original size)
send_files(9, /storage/emulated/0/DCIM/Camera/cache)
send_files(11, /storage/emulated/0/DCIM/Camera/cache/latest)
send_files phase=1
recv_files(Added folder 1)
recv_files(Added folder 2)
recv_files(Original size)
recv_files(cache)
recv_files(cache/latest)
recv_files phase=1
generate_files phase=2
send_files phase=2
send files finished
total: matches=0 hash_hits=0 false_alarms=0 data=0
recv_files phase=2
recv_files finished
generate_files phase=3
generate_files finished
sent 232 bytes received 2,003 bytes 1,490.00 bytes/sec
total size is 0 speedup is 0.00
[sender] _exit_cleanup(code=0, file=main.c, line=1336): about to call exit(0)`
My diagnosis based on that verbose output (although I've never debugged rsync using that level of verbosity before) is that for some reason, it looks like Android is telling the rsync binary that the folders exist but that none of them contain any files, really strange. The 'total size 0' message at the end also seems to support this.
Out of interest, what's the device and Android version and do you have a third party ROM installed?
:D Typical that I would get the absolutely inexplicable error! It's just a vanilla Samsung Note 10, Android 12, no ROM, the file sizes seem to read fine to every other app. No worries, I'll just have to find another way round it, you've gone way above and beyond :)
😄 Just one last thing I'd suggest checking before giving up is if you've granted 'All files access' to Rsync for Tasker. This shows up on my phone under the (I think deliberately) obscure location Apps -> Special app access -> All files access. I'm pretty sure I remember that this prevents access to the directories too on my phone but just a final shot in the dark...
Many thanks indeed for the donation, much appreciated 👍
smile Just one last thing I'd suggest checking before giving up is if you've granted 'All files access' to Rsync for Tasker. This shows up on my phone under the (I think deliberately) obscure location Apps -> Special app access -> All files access. I'm pretty sure I remember that this prevents access to the directories too on my phone but just a final shot in the dark...
Many thanks indeed for the donation, much appreciated +1
Oh my god, you utter legend, that fixed it! 😆 I'd actually checked all the permissions for the plugin but obviously that one doesn't show up if you go in via the app - bloody modern Android system design 🙄 I guess rsync is essentially creating the target dirs based on a directory listing but to create the files it needs proper read access...happy days!