mwilliamson / spur.py

Run commands and manipulate files locally or over SSH using the same interface
BSD 2-Clause "Simplified" License
267 stars 37 forks source link

Spur fails with message "no handlers could be found for logger "paramiko.transport" #83

Closed noafterglow closed 5 years ago

noafterglow commented 5 years ago

I'm not importing logging, paramiko, or anything else other than spur itself, so this is a bug at least in spur, and possibly in the sub packages. Not sure what changed, but its suddenly throwing this error. The connection fails as well, so there might be something else going on as well. Have not done extensive debugging yet.

noafterglow commented 5 years ago

OK... more info. It appears that there is some interaction between spur and a keyring of some kind on this install of ubuntu 18.04. The only key inside ununtu's keyring was for github. It appears that having a github key stored in the password manager on 18.04 suddenly causes spur requests to fail and or logging to be required with messages:

Error creating SSH connection Original error: Authentication failed.

Apparently the keyring issue is the root cause here of the the need for logging. This is clearly a bug, since logging was not enabled, and certainly should not have created "filename.log"

In addition, the keyring interferes with the use of spur, as a window pops up about accessing the keyring.
I would appreciate any help with that.

Now I get a new file present, called "filename.log" This file appears to be the paramiko log....

contents:

DEB [20181218-14:04:42.385] thr=1 paramiko.transport: starting thread (client mode): 0xe71f7190L DEB [20181218-14:04:42.385] thr=1 paramiko.transport: Local version/idstring: SSH-2.0-paramiko_2.4.2 DEB [20181218-14:04:42.451] thr=1 paramiko.transport: Remote version/idstring: SSH-2.0-OpenSSH_7.4p1 Raspbian-10+deb9u4 INF [20181218-14:04:42.452] thr=1 paramiko.transport: Connected (version 2.0, client OpenSSH_7.4p1) DEB [20181218-14:04:42.455] thr=1 paramiko.transport: kex algos:[u'curve25519-sha256', u'curve25519-sha256@libssh.org', u'ecdh-sha2-nistp256', u'ecdh-sha2-nistp384', u'ecdh-sha2-nistp521', u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group16-sha512', u'diffie-hellman-group18-sha512', u'diffie-hellman-group14-sha256', u'diffie-hellman-group14-sha1'] server key:[u'ssh-rsa', u'rsa-sha2-512', u'rsa-sha2-256', u'ecdsa-sha2-nistp256', u'ssh-ed25519'] client encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] server encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] client mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] server mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False DEB [20181218-14:04:42.455] thr=1 paramiko.transport: Kex agreed: ecdh-sha2-nistp256 DEB [20181218-14:04:42.455] thr=1 paramiko.transport: HostKey agreed: ssh-ed25519 DEB [20181218-14:04:42.456] thr=1 paramiko.transport: Cipher agreed: aes128-ctr DEB [20181218-14:04:42.456] thr=1 paramiko.transport: MAC agreed: hmac-sha2-256 DEB [20181218-14:04:42.456] thr=1 paramiko.transport: Compression agreed: none DEB [20181218-14:04:42.527] thr=1 paramiko.transport: kex engine KexNistp256 specified hash_algo DEB [20181218-14:04:42.528] thr=1 paramiko.transport: Switch to new keys ... DEB [20181218-14:04:42.550] thr=2 paramiko.transport: Trying SSH agent key 6ea746e1506666474f1663476459c911 DEB [20181218-14:04:42.573] thr=1 paramiko.transport: userauth is OK ERR [20181218-14:04:45.688] thr=1 paramiko.transport: Exception: key cannot be used for signing ERR [20181218-14:04:45.690] thr=1 paramiko.transport: Traceback (most recent call last): ERR [20181218-14:04:45.690] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 2036, in run ERR [20181218-14:04:45.690] thr=1 paramiko.transport: handler(self.auth_handler, m) ERR [20181218-14:04:45.691] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/auth_handler.py", line 298, in _parse_service_accept ERR [20181218-14:04:45.691] thr=1 paramiko.transport: sig = self.private_key.sign_ssh_data(blob) ERR [20181218-14:04:45.691] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/agent.py", line 418, in sign_ssh_data ERR [20181218-14:04:45.691] thr=1 paramiko.transport: raise SSHException("key cannot be used for signing") ERR [20181218-14:04:45.691] thr=1 paramiko.transport: SSHException: key cannot be used for signing ERR [20181218-14:04:45.691] thr=1 paramiko.transport: DEB [20181218-14:04:45.710] thr=3 paramiko.transport: starting thread (client mode): 0xe71f7390L DEB [20181218-14:04:45.711] thr=3 paramiko.transport: Local version/idstring: SSH-2.0-paramiko_2.4.2 DEB [20181218-14:04:45.773] thr=3 paramiko.transport: Remote version/idstring: SSH-2.0-OpenSSH_7.4p1 Raspbian-10+deb9u4 INF [20181218-14:04:45.773] thr=3 paramiko.transport: Connected (version 2.0, client OpenSSH_7.4p1) DEB [20181218-14:04:45.780] thr=3 paramiko.transport: kex algos:[u'curve25519-sha256', u'curve25519-sha256@libssh.org', u'ecdh-sha2-nistp256', u'ecdh-sha2-nistp384', u'ecdh-sha2-nistp521', u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group16-sha512', u'diffie-hellman-group18-sha512', u'diffie-hellman-group14-sha256', u'diffie-hellman-group14-sha1'] server key:[u'ssh-rsa', u'rsa-sha2-512', u'rsa-sha2-256', u'ecdsa-sha2-nistp256', u'ssh-ed25519'] client encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] server encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] client mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] server mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False DEB [20181218-14:04:45.780] thr=3 paramiko.transport: Kex agreed: ecdh-sha2-nistp256 DEB [20181218-14:04:45.780] thr=3 paramiko.transport: HostKey agreed: ssh-ed25519 DEB [20181218-14:04:45.780] thr=3 paramiko.transport: Cipher agreed: aes128-ctr DEB [20181218-14:04:45.781] thr=3 paramiko.transport: MAC agreed: hmac-sha2-256 DEB [20181218-14:04:45.781] thr=3 paramiko.transport: Compression agreed: none DEB [20181218-14:04:45.832] thr=3 paramiko.transport: kex engine KexNistp256 specified hash_algo DEB [20181218-14:04:45.833] thr=3 paramiko.transport: Switch to new keys ... DEB [20181218-14:04:45.844] thr=2 paramiko.transport: Trying SSH agent key 6ea746e1506666474f1663476459c911 DEB [20181218-14:04:45.883] thr=3 paramiko.transport: userauth is OK ERR [20181218-14:04:47.138] thr=3 paramiko.transport: Exception: key cannot be used for signing ERR [20181218-14:04:47.138] thr=3 paramiko.transport: Traceback (most recent call last): ERR [20181218-14:04:47.138] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 2036, in run ERR [20181218-14:04:47.139] thr=3 paramiko.transport: handler(self.auth_handler, m) ERR [20181218-14:04:47.139] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/auth_handler.py", line 298, in _parse_service_accept ERR [20181218-14:04:47.139] thr=3 paramiko.transport: sig = self.private_key.sign_ssh_data(blob) ERR [20181218-14:04:47.139] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/agent.py", line 418, in sign_ssh_data ERR [20181218-14:04:47.139] thr=3 paramiko.transport: raise SSHException("key cannot be used for signing") ERR [20181218-14:04:47.139] thr=3 paramiko.transport: SSHException: key cannot be used for signing ERR [20181218-14:04:47.139] thr=3 paramiko.transport:

mwilliamson commented 5 years ago

Have you tried passing look_for_private_keys=False?

Spur is a thin wrapper around paramiko, so it'd be useful if you can work out how paramiko should be invoked to avoid the error.

On Tue, 18 Dec 2018 15:54:01 -0800 noafterglow notifications@github.com wrote:

OK... more info. It appears that there is some interaction between spur and a keyring of some kind on this install of ubuntu 18.04. The only key inside ununtu's keyring was for github. It appears that having a github key stored in the password manager on 18.04 suddenly causes spur requests to fail and or logging to be required with messages:

Error creating SSH connection Original error: Authentication failed.

Apparently the keyring issue is the root cause here of the the need for logging. This is clearly a bug, since logging was not enabled, and certainly should not have created "filename.log"

In addition, the keyring interferes with the use of spur, as a window pops up about accessing the keyring. I would appreciate any help with that.

Now I get a new file present, called "filename.log" This file appears to be the paramiko log....

contents:

DEB [20181218-14:04:42.385] thr=1 paramiko.transport: starting thread (client mode): 0xe71f7190L DEB [20181218-14:04:42.385] thr=1 paramiko.transport: Local version/idstring: SSH-2.0-paramiko_2.4.2 DEB [20181218-14:04:42.451] thr=1 paramiko.transport: Remote version/idstring: SSH-2.0-OpenSSH_7.4p1 Raspbian-10+deb9u4 INF [20181218-14:04:42.452] thr=1 paramiko.transport: Connected (version 2.0, client OpenSSH_7.4p1) DEB [20181218-14:04:42.455] thr=1 paramiko.transport: kex algos:[u'curve25519-sha256', u'curve25519-sha256@libssh.org', u'ecdh-sha2-nistp256', u'ecdh-sha2-nistp384', u'ecdh-sha2-nistp521', u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group16-sha512', u'diffie-hellman-group18-sha512', u'diffie-hellman-group14-sha256', u'diffie-hellman-group14-sha1'] server key:[u'ssh-rsa', u'rsa-sha2-512', u'rsa-sha2-256', u'ecdsa-sha2-nistp256', u'ssh-ed25519'] client encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] server encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] client mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] server mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False DEB [20181218-14:04:42.455] thr=1 paramiko.transport: Kex agreed: ecdh-sha2-nistp256 DEB [20181218-14:04:42.455] thr=1 paramiko.transport: HostKey agreed: ssh-ed25519 DEB [20181218-14:04:42.456] thr=1 paramiko.transport: Cipher agreed: aes128-ctr DEB [20181218-14:04:42.456] thr=1 paramiko.transport: MAC agreed: hmac-sha2-256 DEB [20181218-14:04:42.456] thr=1 paramiko.transport: Compression agreed: none DEB [20181218-14:04:42.527] thr=1 paramiko.transport: kex engine KexNistp256 specified hash_algo <built-in function openssl_sha256> DEB [20181218-14:04:42.528] thr=1 paramiko.transport: Switch to new keys ... DEB [20181218-14:04:42.550] thr=2 paramiko.transport: Trying SSH agent key 6ea746e1506666474f1663476459c911 DEB [20181218-14:04:42.573] thr=1 paramiko.transport: userauth is OK ERR [20181218-14:04:45.688] thr=1 paramiko.transport: Exception: key cannot be used for signing ERR [20181218-14:04:45.690] thr=1 paramiko.transport: Traceback (most recent call last): ERR [20181218-14:04:45.690] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 2036, in run ERR [20181218-14:04:45.690] thr=1 paramiko.transport: handler(self.auth_handler, m) ERR [20181218-14:04:45.691] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/auth_handler.py", line 298, in _parse_service_accept ERR [20181218-14:04:45.691] thr=1 paramiko.transport: sig = self.private_key.sign_ssh_data(blob) ERR [20181218-14:04:45.691] thr=1 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/agent.py", line 418, in sign_ssh_data ERR [20181218-14:04:45.691] thr=1 paramiko.transport: raise SSHException("key cannot be used for signing") ERR [20181218-14:04:45.691] thr=1 paramiko.transport: SSHException: key cannot be used for signing ERR [20181218-14:04:45.691] thr=1 paramiko.transport: DEB [20181218-14:04:45.710] thr=3 paramiko.transport: starting thread (client mode): 0xe71f7390L DEB [20181218-14:04:45.711] thr=3 paramiko.transport: Local version/idstring: SSH-2.0-paramiko_2.4.2 DEB [20181218-14:04:45.773] thr=3 paramiko.transport: Remote version/idstring: SSH-2.0-OpenSSH_7.4p1 Raspbian-10+deb9u4 INF [20181218-14:04:45.773] thr=3 paramiko.transport: Connected (version 2.0, client OpenSSH_7.4p1) DEB [20181218-14:04:45.780] thr=3 paramiko.transport: kex algos:[u'curve25519-sha256', u'curve25519-sha256@libssh.org', u'ecdh-sha2-nistp256', u'ecdh-sha2-nistp384', u'ecdh-sha2-nistp521', u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group16-sha512', u'diffie-hellman-group18-sha512', u'diffie-hellman-group14-sha256', u'diffie-hellman-group14-sha1'] server key:[u'ssh-rsa', u'rsa-sha2-512', u'rsa-sha2-256', u'ecdsa-sha2-nistp256', u'ssh-ed25519'] client encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] server encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'] client mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] server mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False DEB [20181218-14:04:45.780] thr=3 paramiko.transport: Kex agreed: ecdh-sha2-nistp256 DEB [20181218-14:04:45.780] thr=3 paramiko.transport: HostKey agreed: ssh-ed25519 DEB [20181218-14:04:45.780] thr=3 paramiko.transport: Cipher agreed: aes128-ctr DEB [20181218-14:04:45.781] thr=3 paramiko.transport: MAC agreed: hmac-sha2-256 DEB [20181218-14:04:45.781] thr=3 paramiko.transport: Compression agreed: none DEB [20181218-14:04:45.832] thr=3 paramiko.transport: kex engine KexNistp256 specified hash_algo <built-in function openssl_sha256> DEB [20181218-14:04:45.833] thr=3 paramiko.transport: Switch to new keys ... DEB [20181218-14:04:45.844] thr=2 paramiko.transport: Trying SSH agent key 6ea746e1506666474f1663476459c911 DEB [20181218-14:04:45.883] thr=3 paramiko.transport: userauth is OK ERR [20181218-14:04:47.138] thr=3 paramiko.transport: Exception: key cannot be used for signing ERR [20181218-14:04:47.138] thr=3 paramiko.transport: Traceback (most recent call last): ERR [20181218-14:04:47.138] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 2036, in run ERR [20181218-14:04:47.139] thr=3 paramiko.transport: handler(self.auth_handler, m) ERR [20181218-14:04:47.139] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/auth_handler.py", line 298, in _parse_service_accept ERR [20181218-14:04:47.139] thr=3 paramiko.transport: sig = self.private_key.sign_ssh_data(blob) ERR [20181218-14:04:47.139] thr=3 paramiko.transport: File "/usr/local/lib/python2.7/dist-packages/paramiko/agent.py", line 418, in sign_ssh_data ERR [20181218-14:04:47.139] thr=3 paramiko.transport: raise SSHException("key cannot be used for signing") ERR [20181218-14:04:47.139] thr=3 paramiko.transport: SSHException: key cannot be used for signing ERR [20181218-14:04:47.139] thr=3 paramiko.transport:

mwilliamson commented 5 years ago

Closing since I don't think there's anything that I can do without more information.