CLI error "unexpected response from 1P" when 1Password itself is still locked

lieverse

Hi,

When running op run I regularly get following error:

[ERROR] 2023/05/24 15:57:20 error initializing client: RequestDelegatedSession: received unexpected response from 1Password app. Please make sure 1Password CLI and the 1Password app are up-to-date.

This happens when 1Password app is running but locked. The error occurs after having done the actual authentication (using fingerprint).

Retrying the same command again then runs without issue.

Possibly relevant settings:

• Developer section:

  • Ask approval for each new: application and terminal session
  • Remember key approval: until 1Password locks
  • Connect with 1Password CLI

• Security section:

  • Unlock using system authentication service: enabled

Log when this occurs (with account id masked)

INFO  2023-05-24T14:10:01.560 tokio-runtime-worker(ThreadId(4)) [1P:native-messaging/op-native-core-integration/src/lib.rs:353] Extension connecting.
INFO  2023-05-24T14:10:01.560 tokio-runtime-worker(ThreadId(4)) [1P:native-messaging/op-native-core-integration/src/lib.rs:355] Extension connection accepted.
WARN  2023-05-24T14:10:02.566 invocation_loop(ThreadId(25)) [1P:op-app/src/app/backend.rs:244] operation blocking event loop invoke Invocation(External(NativeMessaging { invocation: NmRequestAuthorization(<NmRequestAuthorizationRequest>), client_info: NmClientInfo { pid: Some(178540), session: Cli(Tty { session_id: 178240, session_start_time: <U53> }) } })) took more than 50 ms (1004 ms)
INFO  2023-05-24T14:10:05.084 tokio-runtime-worker(ThreadId(9)) [1P:data/ext/op-account-ext-items/src/lib.rs:236] loaded *** items in * vaults for account: ****
INFO  2023-05-24T14:10:05.088 invocation_loop(ThreadId(25)) [1P:op-app/src/app/backend/unlock.rs:151] Lock state changed: Unlocked
ERROR 2023-05-24T14:10:05.362 tokio-runtime-worker(ThreadId(4)) [1P:native-messaging/op-native-core-integration/src/connection_handler.rs:62] message from b5x was None: EndConnection
ERROR 2023-05-24T14:10:05.362 tokio-runtime-worker(ThreadId(4)) [1P:native-messaging/op-native-core-integration/src/connection_handler.rs:31] Dropping connection with b5x due to error handling incoming message: EndConnection
INFO  2023-05-24T14:10:05.474 tokio-runtime-worker(ThreadId(4)) [1P:op-syncer/src/sync_job.rs:306] synced account **** (0.077690312s)
INFO  2023-05-24T14:10:05.475 tokio-runtime-worker(ThreadId(4)) [1P:data/op-file-transfer/src/lib.rs:565] find_and_complete_pending_uploads: '****'
INFO  2023-05-24T14:10:05.506 tokio-runtime-worker(ThreadId(15)) [1P:data/ext/op-account-ext-syncer/src/lib.rs:256] The B5 Notifier for (**** has connected, now monitoring for events.

Is this expected behavior (in which case at least the error message is confusing)?

Thanks,
Paul

---

1Password Version: 8.10.6 (81006027)
Extension Version: 2.18.0
OS Version: Ubuntu 22.04
Browser:_ Not Provided

lieverse

Additional info: it seems to always occur when 1Password app is locked, but it also occurs sometimes when the app is not locked (I think when it has been a while since last op run invocation - but not sure if that is the determining factor).

Joris_1P

Hey @lieverse,

Thanks for reaching out. What you are seeing curious and definitely something that should not be happening. How reliably can you reproduce this problem? If it's possible to run the command with the --debug flag when it returns this error, that would provide us with some useful extra info. Let me know if that is possible.

Joris

lieverse

Hi @Joris_1P , sorry for the delayed update.

The case with the 1P app locked is 100% reproducible.

When running op --debug read op://vault/item/field with the 1P app locked, I get

5:52PM | DEBUG | Session delegation enabled
5:52PM | DEBUG | NM request: NmRequestAccounts
5:52PM | DEBUG | NM response: Success
5:52PM | DEBUG | NM request: NmRequestAccounts
5:52PM | DEBUG | NM response: Success
5:52PM | DEBUG | account not signed in, filter= latest_signin_user=*****
5:52PM | DEBUG | NM request: NmRequestAccounts
5:52PM | DEBUG | NM response: Success
5:52PM | DEBUG | NM request: NmRequestAuthorization
5:52PM | DEBUG | NM response: Success
5:52PM | DEBUG | NM request: NmRequestAccounts
5:52PM | DEBUG | NM response: Notification
5:52PM | DEBUG | NM response: Success
5:52PM | DEBUG | NM request: NmRequestDelegatedSession
5:52PM | WARN | Cannot unmarshal into NmhResponse: unexpected end of JSON input
[ERROR] 2023/06/01 17:52:14 could not read secret op://vault/item/field: error initializing client: RequestDelegatedSession: received unexpected response from 1Password app. Please make sure 1Password CLI and the 1Password app are up-to-date.

The OS's authentication prompt occurs after the NmRequestAuthorization message, and I did successfully authenticate.

Paul

tristan957

I am experiencing this issue as well. It is an insanely annoying issue for my email client, which calls out to op to get the imap/smtp password I saved in there.

I can reproduce 100% of the time as well on Fedora 38. The logs are the exact same as what has already been posted.

Joris_1P

@lieverse Thanks for providing those debug logs, and @tristan957 for confirming that you're seeing the exact same. That allowed me to reproduce the problem locally. I am pretty sure I've found the problem, which seems to be caused by a subtle change in how the 1Password app communicates to the CLI when it transitions from the locked to the unlocked state.

We're going to work on a fix and I will let you know when that has been released.

ArunV1P

Hi again @lieverse and @tristan957, this issue should be resolved in op CLI 2.19.0. Would you be able to give it a try and let us know how it works for you?

Thank you,
Arun

tristan957

Yep, everything works. I haven't hit this bug for about a week at this point. Thanks for the update. I am a new 1Password user, and this was by far my biggest issue. Thanks for the fix!

lieverse

Same here, not seen the issue since that CLI update last week. Thanks!

Joris_1P

That's great to hear! Thanks for letting us know.