Cannot log in using WebAuthn

[carloscabanero]

I turned up my logging verbosity and I’ll paste what I have below. I think you’re right that the “key type 15” error is not stopping anything and the problem is elsewhere.

Here is the tail end of my server logs when I try to connect with my sk key from Blink. I’ve replaced some things with [CAPITAL LETTERS IN BRACKETS] for privacy. There is no more log content for a few minutes after this before sshd throws a timeout message for the connection.

Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: receive packet: type 50 [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: userauth-request for user [USERNAME] service ssh-connection method publickey [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: attempt 1 failures 0 [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug2: input_userauth_request: try method publickey [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug2: userauth_pubkey: valid user [USERNAME] querying public key sk-ecdsa-sha2-nistp256@openssh.com [KEY ID] [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: userauth_pubkey: publickey test pkalg sk-ecdsa-sha2-nistp256@openssh.com pkblob ECDSA-SK SHA256:[KEY ID] [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_key_allowed: entering [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_request_send: entering, type 22 [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_request_receive_expect: entering, type 23 [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_request_receive: entering [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_request_receive: entering Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: monitor_read: checking request 22 Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_answer_keyallowed: entering Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: temporarily_use_uid: 1000/1000 (e=0/0) Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: trying public key file /home/[USERNAME]/.ssh/authorized_keys Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: fd 5 clearing O_NONBLOCK Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: /home/[USERNAME]/.ssh/authorized_keys:1: matching key found: ECDSA-SK SHA256:[KEY ID] Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: /home/[USERNAME]/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: /home/[USERNAME]/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding Mar 10 15:00:16 raspberrypi sshd[15387]: Accepted key ECDSA-SK SHA256:[KEY ID] found at /home/[USERNAME]/.ssh/authorized_keys:1 Mar 10 15:00:16 raspberrypi sshd[15387]: debug2: auth_check_authkeys_file: /home/[USERNAME]/.ssh/authorized_keys: processed 1/2 lines Mar 10 15:00:16 raspberrypi sshd[15387]: debug1: restore_uid: 0/0 Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_answer_keyallowed: publickey authentication test: ECDSA-SK key is allowed Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: mm_request_send: entering, type 23 Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: send packet: type 60 [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug2: userauth_pubkey: authenticated 0 pkalg sk-ecdsa-sha2-nistp256@openssh.com [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: user_specific_delay: user specific delay 0.000ms [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: debug3: ensure_minimum_time_since: elapsed 6.482ms, delaying 0.560ms (requested 7.042ms) [preauth] Mar 10 15:00:16 raspberrypi sshd[15387]: Postponed publickey for [USERNAME] from [REMOTE IP]

Here is the tail end of the output from Blink with a -vvvv flag when I try that connection.

Trying publickey... agent_talk: Request length: 1 ssh_agent_get_ident_count: Answer type: 12, expected answer: 12 ssh_agent_get_ident_count: Agent count: 1 ssh_userauth_agent: Trying identity [KEY NAME] ssh_key_type_to_hash: Digest algorithm to be used with key type 15 is not defined ssh_key_algorithm_allowed: Checking sk-ecdsa-sha2-nistp256@openssh.com with list packet_send2: packet: wrote [type=50, len=224, padding_size=4, comp=219, payload=219] ssh_packet_socket_callback: packet: read type 60 [len=192,padding=12,comp=179,payload=179] ssh_packet_process: Dispatching handler for packet type 60 ssh_packet_userauth_pk_ok: Received SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE ssh_packet_userauth_pk_ok: Assuming SSH_USERAUTH_PK_OK ssh_userauth_agent: Public key of [KEY NAME] accepted by server ssh_key_type_to_hash: Digest algorithm to be used with key type 15 is not defined ssh_key_algorithm_allowed: Checking sk-ecdsa-sha2-nistp256@openssh.com with list agent_talk: Request length: 404

Originally posted by @Tahpo2 in https://github.com/blinksh/blink/discussions/1875#discussioncomment-8736329

[carloscabanero]

From the Blink logs, it looks like Blink is blocked after the request is sent to the agent. And as I understand from @Tahpo2 it looks like the prompt is not shown. The block is intentional in the Sign function (https://github.com/blinksh/blink/blob/df04676bc07fde94b57a9cc7aedf2430ab996e07/BlinkConfig/WebAuthnKey.swift#L87). No idea why iOS is not displaying the prompt though.

I created a TestFlight version that adds additional logging, and I also removed .preferImmediatelyAvailableCredentials from performRequests, because there are not that many points where things can fail, and if maybe there is a configuration issue the delegate fails immediately but that happens before the semaphore is even waiting?https://developer.apple.com/forums/thread/737010

[Tahpo2]

I’m on TestFlight. Sometimes I can get the iOS security key prompt to come up when I try to connect, but it still stalls out at that “agent_talk: Request length: 404” line.

[Tahpo2]

Do I need to do something special to access this TestFlight version, or will it show up eventually as a new build for 17.2.1?

[carloscabanero]

It will show, but I will give you a heads up here too. We are wrapping up one more thing before pushing this. Should be tomorrow/wednesday.

[carloscabanero]

Hi @Tahpo2 ! Please let me know if you got a chance to try this with the -vvvv flag so we can get a more detailed overview of where things stop.

Thanks!

[Tahpo2]

Yes. I get the same output but it ends with some WebAuthn Controller messages.

Here is end of the blink output when the connection hangs now

ssh_userauth_agent: Public key of [KEY NAME] accepted by server ssh_key_type_to_hash: Digest algorithm to be used with key type 15 is not defined ssh_key_algorithm_allowed: Checking sk-ecdsa-sha2-nistp256@openssh.com with list agent_talk: Request length: 402 WebAuthn signature requested. WebAuthn Controller awaiting response. WebAuthn Controller called to perform request. WebAuthn Controller received response.

If I do not use -vvvv flags, the iOS security key prompt often does not ever display. However, it did this time and the last line appears after I follow the prompts to enter my pin and touch the key after which the process stalls indefinitely.

[Tahpo2]

Just installed build (889) and tried again.

There is one new line of output.

Trying publickey... agent_talk: Request length: 1 ssh_agent_get_ident_count: Answer type: 12, expected answer: 12 ssh_agent_get_ident_count: Agent count: 1 ssh_userauth_agent: Trying identity [KEY NAME] ssh_key_type_to_hash: Digest algorithm to be used with key type 15 is not defined ssh_key_algorithm_allowed: Checking sk-ecdsa-sha2-nistp256@openssh.com with list packet_send2: packet: wrote [type=50, len=224, padding_size=4, comp=219, payload=219] ssh_packet_socket_callback: packet: read type 60 [len=192,padding=12,comp=179,payload=179] ssh_packet_process: Dispatching handler for packet type 60 ssh_packet_userauth_pk_ok: Received SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE ssh_packet_userauth_pk_ok: Assuming SSH_USERAUTH_PK_OK ssh_userauth_agent: Public key of [KEY NAME] accepted by server ssh_key_type_to_hash: Digest algorithm to be used with key type 15 is not defined ssh_key_algorithm_allowed: Checking sk-ecdsa-sha2-nistp256@openssh.com with list agent_talk: Request length: 404 WebAuthn signature requested. WebAuthn signature publisher cancelled WebAuthn Controller awaiting response. WebAuthn Controller called to perform request. WebAuthn Controller received response. WebAuthn Controller sending signature

[carloscabanero]

Thanks for the prompt response! I think we got it :). The Combine flow is being cancelled while the signature process is in-progress, and that is why we don't have an option to receive a signature. Super weird that in your case the Combine flow is being cancelled consistently (probably because the object itself is being collected?), but not in my case.

In any case, fix coming up.

[carloscabanero]

I think I have a fix. Can I push a TF version just for you? If you don't mind, please send me your email to Carlos at blink.sh. Thank you!

[mistakenideas]

Aha, I was just trying WebAuthn for the first time and couldn’t get it to work, seeing similar problems and intermittent iOS prompts as @Tahpo2 Would some more info/logs help? Otherwise I shall just wait until the fix gets into TestFlight and be an extra set of eyes on confirming the fix.

[carloscabanero]

Please send me an email as well and if I will add you two to the branch. That way we don’t disturb everybody else for this.

[carloscabanero]

Just pushed. Let's see if this goes through now🤞

[Tahpo2]

Just installed build (891) and WebAuthn seems to work! I was able to access my two servers with the key I put on my Yubikey with Blink in 2022.

Here are the logs from near the old failure point:

agent_talk: Request length: 404 WebAuthn signature requested. WebAuthn Controller awaiting response. WebAuthn Controller called to perform request. WebAuthn Controller received response. WebAuthn Controller sending signature WebAuthn signature received. WebAuthn received signature publisher completed with finished WebAuthn signature completed. packet_send2: packet: wrote [type=50, len=800, padding_size=13, comp=786, payload=786] ssh_packet_socket_callback: packet: read type 52 [len=16,padding=14,comp=1,payload=1] ssh_packet_process: Dispatching handler for packet type 52 ssh_packet_userauth_success: Authentication successful ssh_packet_userauth_success: Received SSH_USERAUTH_SUCCESS ssh_packet_userauth_success: Enabling delayed compression OUT ssh_packet_userauth_success: Enabling delayed compression IN ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=65, in_blocks=30 Connected to [REMOTE IP ADDRESS] SHELL Opening channel

[carloscabanero]

Will wait for more confirmations, but…

[mistakenideas]

I feel very late to the party and haven’t contributed much but… Looking good here on a quick test using build 891 connecting to a server running OpenSSH_9.2p1 :)

(I’ll just add I’m using an on device passkey)

[carloscabanero]

Everything counts. Thanks everyone! This one took a bit of back and forth but I’m glad we figured it out.

I will add key sync from the app to other Blink instances and we should be able to put this out of beta.

[mistakenideas]

I’ve been trying ssh and mosh and most of the time it has been fine. I did see this error once but retrying worked: authError(msg: "ssh_userauth_agent_publickey: Out of memory

[carloscabanero]

I’ve been trying ssh and mosh and most of the time it has been fine. I did see this error once but retrying worked: authError(msg: "ssh_userauth_agent_publickey: Out of memory

Can you post the logs for when that happens? Is that before or after key request?

[mistakenideas]

That was the only message that appeared. I’ll test some more with ssh/mosh verbosity turned up and see if I can repro. Or are there any other blink logs that would help? I couldn’t see anything in .blink

[carloscabanero]

Did it show before or after the prompt? I think it may be an issue with the libssh agent, so knowing if before (pubkey listing) or after (sig request) will help me 📌

[mistakenideas]

Sorry, I didn’t reply to that question as I couldn’t be sure of my memory and am wary of giving incorrect leads.

But I’ve just recreated it in mosh! The error is before being shown the prompt and mosh gives this error: authError(msg: "ssh_userauth_agent_publickey: Out of memory") - The operation couldn’t be completed. (SSH.SSHError error 4.)

I don’t have clear steps to repro other than just repeatedly entering and exiting mosh and ssh sessions in quick succession.

[mistakenideas]

Managed to repro with ssh again and more verbose logging, hopefully verbose enough!

I think this is the relevant bit:

WebAuthn signature requested.
WebAuthn Controller awaiting response.
WebAuthn Controller called to perform request.
WebAuthn signature failed or cancelled - Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named com.apple.AuthenticationServicesCore.AuthenticationServicesAgent" UserInfo={NSDebugDescription=connection to service named com.apple.AuthenticationServicesCore.AuthenticationServicesAgent}
WebAuthn received signature publisher completed with failure(Error Domain=NSCocoaErrorDomain Code=4097 "connection to service named com.apple.AuthenticationServicesCore.AuthenticationServicesAgent" UserInfo={NSDebugDescription=connection to service named com.apple.AuthenticationServicesCore.AuthenticationServicesAgent})
ssh_agent_sign_data: Agent reports failure in signing the key
Error connecting to <SERVER>. authError(msg: "ssh_userauth_agent_publickey: Out of memory")
SSH Session deinit

[carloscabanero]

Thanks! Will try to get this fixed before final release.

[carloscabanero]

Done 17.3.0