8.8.0 update broke SSH authentication from terminal

cricalix
cricalix
Community Member
in Linux

I've been using the SSH key integration for a few months, and it's been working flawlessly.

Yesterday, before the v8.8.0 update, everything worked. This morning, after the 8.8.0 upgrade, the agent is refusing to work properly.

Now:

debug1: Authentications that can continue: publickey
debug3: start over, passed a different list publickey
debug3: preferred gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering public key: key1 RSA SHA256:dZSTh+A6+jTz6jfe85gurShcr/hxUFS2iydVOuwYoJM agent
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: key1 RSA SHA256:dZSTh+A6+jTz6jfe85gurShcr/hxUFS2iydVOuwYoJM agent
debug3: sign_and_send_pubkey: using publickey with RSA SHA256:dZSTh+A6+jTz6jfe85gurShcr/hxUFS2iydVOuwYoJM
debug3: sign_and_send_pubkey: signing using rsa-sha2-512 SHA256:dZSTh+A6+jTz6jfe85gurShcr/hxUFS2iydVOuwYoJM
sign_and_send_pubkey: signing failed for RSA "key1" from agent: agent refused operation
debug1: Offering public key: key2 ED25519 SHA256:5d30JiqdyMnFOHeGJJK3U9JGjuvc9XeN9tBca1x6rk0 agent
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: key2 ED25519 SHA256:5d30JiqdyMnFOHeGJJK3U9JGjuvc9XeN9tBca1x6rk0 agent
debug3: sign_and_send_pubkey: using publickey with ED25519 SHA256:5d30JiqdyMnFOHeGJJK3U9JGjuvc9XeN9tBca1x6rk0
debug3: sign_and_send_pubkey: signing using ssh-ed25519 SHA256:5d30JiqdyMnFOHeGJJK3U9JGjuvc9XeN9tBca1x6rk0
sign_and_send_pubkey: signing failed for ED25519 "key2" from agent: agent refused operation

Client SSH: OpenSSH_8.9p1 Ubuntu-3, OpenSSL 3.0.2 15 Mar 2022

Remote SSH: OpenSSH_8.4p1 Debian-5+deb11u1

I'm using the stable/production channel.

1Password Version: 8.8.0
Extension Version: Not Provided
OS Version: Ubuntu 22.04 LTS
Browser:_ Not Provided

Comments

  • cricalix
    cricalix
    Community Member

    The agent is clearly working well enough to respond to an identities request, but fails on the sign request.

  • cricalix
    cricalix
    Community Member

    Started the binary as /usr/bin/1password --log trace:

    DEBUG 2022-07-22T07:22:30.096 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:194] connection received
DEBUG 2022-07-22T07:22:30.097 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: RequestIdentities
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #71 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #71 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#71(get_objects_by)
DEBUG 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#71(get_objects_by))
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#71(get_objects_by) (0.000s)
DEBUG 2022-07-22T07:22:30.211 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: SignRequest
DEBUG 2022-07-22T07:22:30.211 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-sys-info/src/process_information/linux.rs:57] no process path could be found during verification
DEBUG 2022-07-22T07:22:30.213 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-linux-window/src/linux.rs:49] failed to connect to swaywm
DEBUG 2022-07-22T07:22:30.213 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:400] process info for client: SessionProcess { pid: 5550, tty_pid: Some(5586), executable_path: /usr/bin/konsole, command_line: <Vec < String >>, application_name: <String> }
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #72 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #72 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#72(get_objects_by)
DEBUG 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#72(get_objects_by))
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#72(get_objects_by) (0.000s)
TRACE 2022-07-22T07:22:30.214 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26)))
TRACE 2022-07-22T07:22:30.214 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26))) (0.000s)
TRACE 2022-07-22T07:22:30.218 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92)))
TRACE 2022-07-22T07:22:30.218 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92))) (0.000s)
TRACE 2022-07-22T07:22:30.218 tokio-runtime-worker(ThreadId(2)) [1P:op-data-layer/src/unlock.rs:214] >unlock_with_key
TRACE 2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:op-data-layer/src/unlock.rs:214] <unlock_with_key (0.005s)
DEBUG 2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:op-automated-unlock/src/lib.rs:552] Denied
INFO  2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:419] Session was not authorized
DEBUG 2022-07-22T07:22:30.250 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: SignRequest
DEBUG 2022-07-22T07:22:30.250 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-sys-info/src/process_information/linux.rs:57] no process path could be found during verification
DEBUG 2022-07-22T07:22:30.251 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-linux-window/src/linux.rs:49] failed to connect to swaywm
DEBUG 2022-07-22T07:22:30.251 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:400] process info for client: SessionProcess { pid: 5550, tty_pid: Some(5586), executable_path: /usr/bin/konsole, command_line: <Vec < String >>, application_name: <String> }
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #73 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #73 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#73(get_objects_by)
DEBUG 2022-07-22T07:22:30.252 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#73(get_objects_by))
TRACE 2022-07-22T07:22:30.252 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#73(get_objects_by) (0.000s)
TRACE 2022-07-22T07:22:30.252 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26)))
TRACE 2022-07-22T07:22:30.252 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26))) (0.000s)
TRACE 2022-07-22T07:22:30.255 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92)))
TRACE 2022-07-22T07:22:30.255 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92))) (0.000s)
TRACE 2022-07-22T07:22:30.255 tokio-runtime-worker(ThreadId(23)) [1P:op-data-layer/src/unlock.rs:214] >unlock_with_key
TRACE 2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:op-data-layer/src/unlock.rs:214] <unlock_with_key (0.005s)
DEBUG 2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:op-automated-unlock/src/lib.rs:552] Denied
INFO  2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:ssh/op-ssh-agent/src/lib.rs:419] Session was not authorized
TRACE 2022-07-22T07:22:47.419 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(External(CheckForOnlineUpdate(<CheckForOnlineUpdateRequest>)))
TRACE 2022-07-22T07:22:47.419 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(External(CheckForOnlineUpdate(<CheckForOnlineUpdateRequest>))) (0.000s)
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #74 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #74 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#74(get_config)
DEBUG 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#74(get_config))
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#74(get_config) (0.000s)
  • cricalix
    cricalix
    Community Member

    Started the binary as /usr/bin/1password --log trace:

    DEBUG 2022-07-22T07:22:30.096 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:194] connection received
DEBUG 2022-07-22T07:22:30.097 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: RequestIdentities
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #71 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #71 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#71(get_objects_by)
DEBUG 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#71(get_objects_by))
TRACE 2022-07-22T07:22:30.097 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#71(get_objects_by) (0.000s)
DEBUG 2022-07-22T07:22:30.211 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: SignRequest
DEBUG 2022-07-22T07:22:30.211 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-sys-info/src/process_information/linux.rs:57] no process path could be found during verification
DEBUG 2022-07-22T07:22:30.213 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-linux-window/src/linux.rs:49] failed to connect to swaywm
DEBUG 2022-07-22T07:22:30.213 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:400] process info for client: SessionProcess { pid: 5550, tty_pid: Some(5586), executable_path: /usr/bin/konsole, command_line: <Vec < String >>, application_name: <String> }
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #72 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #72 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#72(get_objects_by)
DEBUG 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#72(get_objects_by))
TRACE 2022-07-22T07:22:30.214 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#72(get_objects_by) (0.000s)
TRACE 2022-07-22T07:22:30.214 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26)))
TRACE 2022-07-22T07:22:30.214 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26))) (0.000s)
TRACE 2022-07-22T07:22:30.218 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92)))
TRACE 2022-07-22T07:22:30.218 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92))) (0.000s)
TRACE 2022-07-22T07:22:30.218 tokio-runtime-worker(ThreadId(2)) [1P:op-data-layer/src/unlock.rs:214] >unlock_with_key
TRACE 2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:op-data-layer/src/unlock.rs:214] <unlock_with_key (0.005s)
DEBUG 2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:op-automated-unlock/src/lib.rs:552] Denied
INFO  2022-07-22T07:22:30.224 tokio-runtime-worker(ThreadId(2)) [1P:ssh/op-ssh-agent/src/lib.rs:419] Session was not authorized
DEBUG 2022-07-22T07:22:30.250 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:379] Handling SSH agent message: SignRequest
DEBUG 2022-07-22T07:22:30.250 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-sys-info/src/process_information/linux.rs:57] no process path could be found during verification
DEBUG 2022-07-22T07:22:30.251 tokio-runtime-worker(ThreadId(23)) [1P:foundation/op-linux-window/src/linux.rs:49] failed to connect to swaywm
DEBUG 2022-07-22T07:22:30.251 tokio-runtime-worker(ThreadId(23)) [1P:ssh/op-ssh-agent/src/lib.rs:400] process info for client: SessionProcess { pid: 5550, tty_pid: Some(5586), executable_path: /usr/bin/konsole, command_line: <Vec < String >>, application_name: <String> }
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #73 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #73 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:30.251 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#73(get_objects_by)
DEBUG 2022-07-22T07:22:30.252 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#73(get_objects_by))
TRACE 2022-07-22T07:22:30.252 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#73(get_objects_by) (0.000s)
TRACE 2022-07-22T07:22:30.252 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26)))
TRACE 2022-07-22T07:22:30.252 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:26))) (0.000s)
TRACE 2022-07-22T07:22:30.255 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92)))
TRACE 2022-07-22T07:22:30.255 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(Internal(NextTick(op-app/src/app/backend/automated_unlock.rs:92))) (0.000s)
TRACE 2022-07-22T07:22:30.255 tokio-runtime-worker(ThreadId(23)) [1P:op-data-layer/src/unlock.rs:214] >unlock_with_key
TRACE 2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:op-data-layer/src/unlock.rs:214] <unlock_with_key (0.005s)
DEBUG 2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:op-automated-unlock/src/lib.rs:552] Denied
INFO  2022-07-22T07:22:30.261 tokio-runtime-worker(ThreadId(12)) [1P:ssh/op-ssh-agent/src/lib.rs:419] Session was not authorized
TRACE 2022-07-22T07:22:47.419 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] >blocking event loop invoke Invocation(External(CheckForOnlineUpdate(<CheckForOnlineUpdateRequest>)))
TRACE 2022-07-22T07:22:47.419 op_executor:invocation_loop(ThreadId(31)) [1P:op-app/src/app/backend.rs:192] <blocking event loop invoke Invocation(External(CheckForOnlineUpdate(<CheckForOnlineUpdateRequest>))) (0.000s)
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/db.rs:284] >transaction #74 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite))
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/db.rs:284] <transaction #74 (db:Db(0x7fe880ba65a0, /home/cricalix/.config/1Password/1password.sqlite)) (0.000s)
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] >transaction #tx#74(get_config)
DEBUG 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db/src/transaction.rs:57] COMMIT(tx#74(get_config))
TRACE 2022-07-22T07:22:47.419 ThreadId(29) [1P:op-db-queue/src/operations.rs:1277] <transaction #tx#74(get_config) (0.000s)
  • cricalix
    cricalix
    Community Member

    Well, it's solved itself this morning with no action by me (other than a reboot, which I probably should have tried earlier). Now I'm getting the challenge popup for system auth when I ssh, and signing is working).

This discussion has been closed.