[Thinlinc-technical] ruToken, Signature operation failed (112)

vfh at swemel.ru vfh at swemel.ru
Wed Oct 22 06:00:50 CEST 2014 

Hello. I trying to auth on tl-server by Aladdin eToken 72K Pro (safenet
etoken) and ruToken ECP (
https://github.com/OpenSC/OpenSC/wiki/Aktiv-Co.-Rutoken-ECP ) from
windows client . First working fine, but i can't connect with rutoken
(log file in attach). Token have two certficate (public CA and client),
tl-client select correct cert for identification, but show an error
after pin entered. This token working correct with thunderbird/firefox
(windows) and with linux ssh clients (pkcs#11) and putty-sc on windows,
but return signature operation failed with thinlinc client. Token
enrolled same as Aladdin eToken, just with different token library. Any
idea how to debug this issue?

-- 
vlad f halilov
swemel

-------------- next part --------------
2014-10-22T07:30:05: Log file2014-10-22T07:30:05: Log file created
2014-10-22T07:30:05: ThinLinc client release 4.2.0 build 4356
2014-10-22T07:30:06: Loaded PKCS#11 module 'c:\windows\system32\rtPKCS11ECP.dll'
2014-10-22T07:30:06: Fetching tokens...
2014-10-22T07:30:06: Found 1 slots.
2014-10-22T07:30:06: Getting token for slot 0 on 'Aktiv Rutoken ECP 0'
2014-10-22T07:30:06: Found token "tokenname"
2014-10-22T07:30:06: Getting certificates for slot 0
2014-10-22T07:30:07: Getting certificate with id -1036960184
2014-10-22T07:30:07: Getting certificate with id -1036960023
2014-10-22T07:30:07: Found certificate for "cn=vlad f halilov,organizationalUnitName=IT,o=Company,L=Moscow,st=Moscow,c=RU"
2014-10-22T07:30:07: CA: No
2014-10-22T07:30:07: Serial: 0d
2014-10-22T07:30:07: Key length: 2048 bits
2014-10-22T07:30:07: Found certificate for "1.2.840.113549.1.9.1=#160c6361407377656d656c2e7275,cn=cert auth common,organizationalUnitName=cert auth,o=Company,L=Moscow,c=RU"
2014-10-22T07:30:07: CA: Yes
2014-10-22T07:30:07: Serial: 0084292d7cbf97069e
2014-10-22T07:30:07: Key length: 4096 bits
2014-10-22T07:31:02: Finding certificate with serial 0d
2014-10-22T07:31:02: Getting certificates for slot 0
2014-10-22T07:31:02: Getting certificate with id -2100234531
2014-10-22T07:31:02: Certificate found
2014-10-22T07:31:02: SSH command: "C:\Program Files\ThinLinc Client\ssh.exe" -N -o GlobalKnownHostsFile=nul -o UserKnownHostsFile=nul -o PasswordAuthentication=no -o ChallengeResponseAuthentication=no -o KbdInteractiveAuthentication=no -o CheckHostIP=no -o NumberOfPasswordPrompts=1 -v vlad at hostname.ru -p 22 thinlinc-login master
2014-10-22T07:31:02: WinPopenProcess: Started process 5924 (ssh.exe)
2014-10-22T07:31:02: ssh[E]: OpenSSH_6.3, OpenSSL 1.0.1e 11 Feb 2013
2014-10-22T07:31:02: ssh[E]: debug1: Connecting to hostname.ru [192.168.1.1] port 22.
2014-10-22T07:31:02: ssh[E]: debug1: Connection established.
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_rsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_rsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_dsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_dsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_ecdsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_ecdsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: Enabling compatibility mode for protocol 2.0
2014-10-22T07:31:02: ssh[E]: debug1: Local version string SSH-2.0-OpenSSH_6.3
2014-10-22T07:31:02: ssh[E]: debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
2014-10-22T07:31:02: ssh[E]: debug1: match: OpenSSH_5.3 pat OpenSSH_5*
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEXINIT sent
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEXINIT received
2014-10-22T07:31:02: ssh[E]: debug1: kex: server->client aes128-ctr hmac-md5 none
2014-10-22T07:31:02: ssh[E]: debug1: kex: client->server aes128-ctr hmac-md5 none
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
2014-10-22T07:31:02: ssh[E]: debug1: Server host key: RSA 22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6
2014-10-22T07:31:02: ssh[E]: CONFIRM HOST KEY: hostname.ru 192.168.1.1 22 AAAAB3NzaC1yc2EAAAABIwAAAQEAxc1zPpyN9kld7T8KBjBMpJ6awGz1Ep+BOWk27ebuHatU+3/fiRrpDJwnSNf0NOi9M9WxiGRs6fdikYRkxZNTthl80Izs8mKR4AERtDaUAoABEHuZxNSAkPaLhFtKpupFTRHTdmQbirVnFvtdHN3CS4Ty12bKbjhlAactYIMt1Bpj+2uPnxo8SJR2Cyzzl0UsSzd+0MUw8m9isAfozW9Yc3yAr90/oUVqIlix7bcV/IipV7FcIHyjehf1rsUu/kUhZ9zsA2l5s+fgNMJTF/lDoWKoqBOWuoKYrj1WRnKGurM5RiC285rb60BXOeovckQrP3lYj19t3TPnfBu7eSNiEw==
2014-10-22T07:31:02: Fingerprint from server: |22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6|
2014-10-22T07:31:02: Invalid host key registry entry.
2014-10-22T07:31:02: Known host key fingerprints:
2014-10-22T07:31:02:     |22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6|
2014-10-22T07:31:02: Host key previously known.
2014-10-22T07:31:02: ssh[E]: debug1: ssh_rsa_verify: signature correct
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_NEWKEYS sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_NEWKEYS
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_NEWKEYS received
2014-10-22T07:31:02: ssh[E]: debug1: Roaming not allowed by server
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_SERVICE_REQUEST sent
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_SERVICE_ACCEPT received
2014-10-22T07:31:02: SSH agent request: SSH2_AGENTC_REQUEST_IDENTITIES
2014-10-22T07:31:02: SSH agent response: 1 keys
2014-10-22T07:31:02: ssh[E]: NEXT AUTHMETHOD: none
2014-10-22T07:31:02: ssh[E]: AUTH FAILURE
2014-10-22T07:31:02: ssh[E]: debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
2014-10-22T07:31:02: ssh[E]: NEXT AUTHMETHOD: publickey
2014-10-22T07:31:02: ssh[E]: debug1: Offering RSA public key:
2014-10-22T07:31:02: ssh[E]: debug1: Server accepts key: pkalg ssh-rsa blen 279
2014-10-22T07:31:02: SSH agent request: SSH2_AGENTC_SIGN_REQUEST
2014-10-22T07:31:02: Preparing signature operation...
2014-10-22T07:31:02: Finding certificate with serial 0d
2014-10-22T07:31:02: Getting certificates for slot 0
2014-10-22T07:31:03: Getting certificate with id 1109660452
2014-10-22T07:31:03: Certificate found
2014-10-22T07:31:03: Logging in...
2014-10-22T07:31:03: Querying user for passphrase...
2014-10-22T07:31:08: Finding private key...
2014-10-22T07:31:08: Signing data...
2014-10-22T07:31:08: Signature operation failed (112) created
2014-10-22T07:30:05: ThinLinc client release 4.2.0 build 4356
2014-10-22T07:30:06: Loaded PKCS#11 module 'c:\windows\system32\rtPKCS11ECP.dll'
2014-10-22T07:30:06: Fetching tokens...
2014-10-22T07:30:06: Found 1 slots.
2014-10-22T07:30:06: Getting token for slot 0 on 'Aktiv Rutoken ECP 0'
2014-10-22T07:30:06: Found token "tokenname"
2014-10-22T07:30:06: Getting certificates for slot 0
2014-10-22T07:30:07: Getting certificate with id -1036960184
2014-10-22T07:30:07: Getting certificate with id -1036960023
2014-10-22T07:30:07: Found certificate for "cn=vlad f halilov,organizationalUnitName=IT,o=Company,L=Moscow,st=Moscow,c=RU"
2014-10-22T07:30:07: CA: No
2014-10-22T07:30:07: Serial: 0d
2014-10-22T07:30:07: Key length: 2048 bits
2014-10-22T07:30:07: Found certificate for "1.2.840.113549.1.9.1=#160c6361407377656d656c2e7275,cn=cert auth common,organizationalUnitName=cert auth,o=Company,L=Moscow,c=RU"
2014-10-22T07:30:07: CA: Yes
2014-10-22T07:30:07: Serial: 0084292d7cbf97069e
2014-10-22T07:30:07: Key length: 4096 bits
2014-10-22T07:31:02: Finding certificate with serial 0d
2014-10-22T07:31:02: Getting certificates for slot 0
2014-10-22T07:31:02: Getting certificate with id -2100234531
2014-10-22T07:31:02: Certificate found
2014-10-22T07:31:02: SSH command: "C:\Program Files\ThinLinc Client\ssh.exe" -N -o GlobalKnownHostsFile=nul -o UserKnownHostsFile=nul -o PasswordAuthentication=no -o ChallengeResponseAuthentication=no -o KbdInteractiveAuthentication=no -o CheckHostIP=no -o NumberOfPasswordPrompts=1 -v vlad at hostname.ru -p 22 thinlinc-login master
2014-10-22T07:31:02: WinPopenProcess: Started process 5924 (ssh.exe)
2014-10-22T07:31:02: ssh[E]: OpenSSH_6.3, OpenSSL 1.0.1e 11 Feb 2013
2014-10-22T07:31:02: ssh[E]: debug1: Connecting to hostname.ru [192.168.1.1] port 22.
2014-10-22T07:31:02: ssh[E]: debug1: Connection established.
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_rsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_rsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_dsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_dsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_ecdsa type -1
2014-10-22T07:31:02: ssh[E]: debug1: identity file C:\\Users\\vlad\\AppData\\Roaming/ThinLinc/id_ecdsa-cert type -1
2014-10-22T07:31:02: ssh[E]: debug1: Enabling compatibility mode for protocol 2.0
2014-10-22T07:31:02: ssh[E]: debug1: Local version string SSH-2.0-OpenSSH_6.3
2014-10-22T07:31:02: ssh[E]: debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
2014-10-22T07:31:02: ssh[E]: debug1: match: OpenSSH_5.3 pat OpenSSH_5*
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEXINIT sent
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEXINIT received
2014-10-22T07:31:02: ssh[E]: debug1: kex: server->client aes128-ctr hmac-md5 none
2014-10-22T07:31:02: ssh[E]: debug1: kex: client->server aes128-ctr hmac-md5 none
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
2014-10-22T07:31:02: ssh[E]: debug1: Server host key: RSA 22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6
2014-10-22T07:31:02: ssh[E]: CONFIRM HOST KEY: hostname.ru 192.168.1.1 22 AAAAB3NzaC1yc2EAAAABIwAAAQEAxc1zPpyN9kld7T8KBjBMpJ6awGz1Ep+BOWk27ebuHatU+3/fiRrpDJwnSNf0NOi9M9WxiGRs6fdikYRkxZNTthl80Izs8mKR4AERtDaUAoABEHuZxNSAkPaLhFtKpupFTRHTdmQbirVnFvtdHN3CS4Ty12bKbjhlAactYIMt1Bpj+2uPnxo8SJR2Cyzzl0UsSzd+0MUw8m9isAfozW9Yc3yAr90/oUVqIlix7bcV/IipV7FcIHyjehf1rsUu/kUhZ9zsA2l5s+fgNMJTF/lDoWKoqBOWuoKYrj1WRnKGurM5RiC285rb60BXOeovckQrP3lYj19t3TPnfBu7eSNiEw==
2014-10-22T07:31:02: Fingerprint from server: |22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6|
2014-10-22T07:31:02: Invalid host key registry entry.
2014-10-22T07:31:02: Known host key fingerprints:
2014-10-22T07:31:02:     |22:a4:e4:b3:64:01:26:70:9a:d4:9b:f3:03:f4:17:f6|
2014-10-22T07:31:02: Host key previously known.
2014-10-22T07:31:02: ssh[E]: debug1: ssh_rsa_verify: signature correct
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_NEWKEYS sent
2014-10-22T07:31:02: ssh[E]: debug1: expecting SSH2_MSG_NEWKEYS
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_NEWKEYS received
2014-10-22T07:31:02: ssh[E]: debug1: Roaming not allowed by server
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_SERVICE_REQUEST sent
2014-10-22T07:31:02: ssh[E]: debug1: SSH2_MSG_SERVICE_ACCEPT received
2014-10-22T07:31:02: SSH agent request: SSH2_AGENTC_REQUEST_IDENTITIES
2014-10-22T07:31:02: SSH agent response: 1 keys
2014-10-22T07:31:02: ssh[E]: NEXT AUTHMETHOD: none
2014-10-22T07:31:02: ssh[E]: AUTH FAILURE
2014-10-22T07:31:02: ssh[E]: debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
2014-10-22T07:31:02: ssh[E]: NEXT AUTHMETHOD: publickey
2014-10-22T07:31:02: ssh[E]: debug1: Offering RSA public key:
2014-10-22T07:31:02: ssh[E]: debug1: Server accepts key: pkalg ssh-rsa blen 279
2014-10-22T07:31:02: SSH agent request: SSH2_AGENTC_SIGN_REQUEST
2014-10-22T07:31:02: Preparing signature operation...
2014-10-22T07:31:02: Finding certificate with serial 0d
2014-10-22T07:31:02: Getting certificates for slot 0
2014-10-22T07:31:03: Getting certificate with id 1109660452
2014-10-22T07:31:03: Certificate found
2014-10-22T07:31:03: Logging in...
2014-10-22T07:31:03: Querying user for passphrase...
2014-10-22T07:31:08: Finding private key...
2014-10-22T07:31:08: Signing data...
2014-10-22T07:31:08: Signature operation failed (112)

More information about the Thinlinc-technical mailing list