gh tries to use hosts.yml after initial boot and fails, then tries keyring and succeeds

[tdhooten]

gh tries to use hosts.yml after initial boot and fails, then tries keyring and succeeds

[williammartin]

We released v2.46.0 today which includes the fix. If you run into issues please re-open.

[williammartin]

@tdhooten Please pull, build and and try again, I had one wild idea before giving up for this evening. Looking at the code for the zalando secret service I see a request to prompt, then registration of a rule to match on the response. However, in the dbus output you sent me we see that the prompt response comes back, and then the rule match is added:

method call time=1710441095.362970 sender=:1.77 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',path='/org/freedesktop/secrets/prompt/p0',interface='org.freedesktop.Secret.Prompt'"

signal time=1710441095.362967 sender=:1.18 -> destination=:1.77 serial=44 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Completed
   boolean false
   variant       array [
         object path "/org/freedesktop/secrets/aliases/default"
      ]

I don't know enough about dbus rule matching to know the exact semantics but it does look kind of racy to me. I made an attempt to swap the ordering in a fork: williammartin/go-keyring@928f5e8

Since I'm not sure how to get my own system to request a prompt, I haven't been able to test this this evening so it may just fall over or deadlock in some other way but I thought it was worth an attempt in case you are around.

I added a couple of prints that you may see in the output.

[tdhooten]

@tdhooten Please pull, build and and try again, I had one wild idea before giving up for this evening. Looking at the code for the zalando secret service I see a request to prompt, then registration of a rule to match on the response. However, in the dbus output you sent me we see that the prompt response comes back, and then the rule match is added:

method call time=1710441095.362970 sender=:1.77 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',path='/org/freedesktop/secrets/prompt/p0',interface='org.freedesktop.Secret.Prompt'"

signal time=1710441095.362967 sender=:1.18 -> destination=:1.77 serial=44 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Completed
   boolean false
   variant       array [
         object path "/org/freedesktop/secrets/aliases/default"
      ]

I don't know enough about dbus rule matching to know the exact semantics but it does look kind of racy to me. I made an attempt to swap the ordering in a fork: williammartin/go-keyring@928f5e8

Since I'm not sure how to get my own system to request a prompt, I haven't been able to test this this evening so it may just fall over or deadlock in some other way but I thought it was worth an attempt in case you are around.

I added a couple of prints that you may see in the output.

That did it!

unlocking
Adding match signal
Prompting
everything seems good :)

[siniarskimar]

Seems to be fixed on my end. Did three reboots to make sure and gh auth status works first-time every time.

[yutanagano]

I also gave it a try and can confirm that this new build works where the current version does not. Thank you so much @williammartin for the very speedy response and fix, and @tdhooten for active testing :) you guys are awesome

[williammartin]

@siniarskimar @yutanagano thank you very much for taking the time to try this out.

I've created an issue and PR to the zalando/go-keyring library that we depend upon. I'm not sure what their maintenance approach is for this library. Hopefully the maintainers will be responsive as they have accepted contributions from us in the past. If we don't get a timely response then we have two options:

1. Fork the library into cli/go-keyring
2. Proceed with an open PR that moves away from this library

I'm hopeful that we'll get a review because I have limited confidence that I didn't accidentally break something else with this change! 😅

I'll update this issue when we know more.

[williammartin]

The folks over at zalando have agreed with our assessment and have merged the PR. I've asked whether they will cut a release or if we should pin to the sha. Ideally we could get this fixed in our next release which on our usual schedule would be on Tuesday.

[williammartin]

This has had some discussion over in #8729 (comment) but I'm not 100% sure these issues are the same.

I don't think the title is quite correct, I think the error message is an artifact of gh falling back to hosts.yml after failing to use the keyring but this is still to be confirmed. It's interesting that this has come up a few times in the past few weeks, I don't think we changed anything around the secret handling, and I don't think we updated any dependencies there but I'll have to check.

Would you be willing to try a few older versions to see whether this issue persists? I wouldn't go back before 2.40.0 unless you're ok with running into some strangeness around the multi-account switchover (which might require you to delete your config.yml and hosts.yml file to start afresh).

[williammartin]

In either case I'm definitely going to look into this a bit more today, I wasn't able to reproduce it on a VM last week but that could have been user error 😅

[tdhooten]

It looks to me like it is probably the same issue. FWIW, I am using libsecret as the backend for git-credential-helper. I don't know if gh relies on git's configuration or not.

[williammartin]

gh uses https://github.com/zalando/go-keyring to interact with the system keyring directly, beyond that I'll need to do more digging.

[yutanagano]

I am having the exact same issue as OP.

If this is of any help, the issue happens for me on a Fedora linux machine using KDE plasma (and thus the keyring is managed by KDE wallet I think?).

I have a second Fedora linux machine using GNOME and this is not an issue there. I thought maybe the GNOME keyring and KDE wallet do something slightly different and that causes these issues?

[tdhooten]

Yes it seems like everyone affected is running KDE.

[williammartin]

If y'all run busctl --user | grep secrets what do you see?

[williammartin]

I created a VM today running Debian and using KDE, I configured the secret service to be accessible via dbus (but I'm not sure if I did it totally in line with your configuration, hence my question above ^). I was not able to replicate this.

In the mean time, another idea I had was to create a debug version of the CLI that would expose the error that I believe is currently being hidden. If you clone https://github.com/cli/cli/tree/wm/debug-8802 and run make, you should then be able to run ./bin/gh auth debug and it will either print the error or say that everything is good i.e.:

➜  cli git:(wm/debug-8802) ./bin/gh auth debug
everything seems good :)
...
➜  cli git:(wm/debug-8802) ./bin/gh auth debug
secret not found in keyring

If you are unable to build the CLI locally, let me know your architecture and I can build a binary for you.

[tdhooten]

If y'all run busctl --user | grep secrets what do you see?

org.freedesktop.secrets 1989 .kwalletd6-wrap USERNAME :1.41 [email protected] -

[tdhooten]

I created a VM today running Debian and using KDE, I configured the secret service to be accessible via dbus (but I'm not sure if I did it totally in line with your configuration, hence my question above ^). I was not able to replicate this.

In the mean time, another idea I had was to create a debug version of the CLI that would expose the error that I believe is currently being hidden. If you clone https://github.com/cli/cli/tree/wm/debug-8802 and run make, you should then be able to run ./bin/gh auth debug and it will either print the error or say that everything is good i.e.:

➜  cli git:(wm/debug-8802) ./bin/gh auth debug
everything seems good :)
...
➜  cli git:(wm/debug-8802) ./bin/gh auth debug
secret not found in keyring

If you are unable to build the CLI locally, let me know your architecture and I can build a binary for you.

I get a repository not found error when trying to clone. I'm on amd64.

[williammartin]

I get a repository not found error when trying to clone. I'm on amd64.

gh repo clone cli/cli && cd cli && git checkout wm/debug-8802 && make

[tdhooten]

I get a repository not found error when trying to clone. I'm on amd64.

gh repo clone cli/cli && cd cli && git checkout wm/debug-8802 && make

First run: timeout while trying to get secret from keyring

Second run: everything seems good :)

[williammartin]

Interesting. I pushed a commit that bumps the timeout to a ridiculous amount if you can pull, make and try again.

Specifically, I'd like to know whether it's hanging forever.

[williammartin]

Also, re:

org.freedesktop.secrets 1989 .kwalletd6-wrap USERNAME :1.41 [email protected] -

That's good to know. My debian is using the gnome-keyring-daemon here and I cannot figure out how to make it stop 😅 . It's been a long time since I delved into services on linux.

[tdhooten]

Interesting. I pushed a commit that bumps the timeout to a ridiculous amount if you can pull, make and try again.

Specifically, I'd like to know whether it's hanging forever.

Yep, hangs perpetually.

[williammartin]

Quite annoying. Challenging that I don't have an environment to investigate this in.

It seems like gh is doing the right thing here and they keyring service isn't available. Could you maybe collect the output of dbus-monitor? If you start it running before the first gh auth status and stop if after the second we might get some insight into what is going on on dbus. Be careful because I think the second auth status command might result in your token appearing in the dbus-monitor output.

[tdhooten]

signal time=1710441087.030272 sender=org.freedesktop.DBus -> destination=:1.76 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.76"
signal time=1710441087.030324 sender=org.freedesktop.DBus -> destination=:1.76 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.76"
method call time=1710441095.361593 sender=:1.77 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1710441095.361603 sender=org.freedesktop.DBus -> destination=:1.77 serial=1 reply_serial=1
   string ":1.77"
signal time=1710441095.361606 sender=org.freedesktop.DBus -> destination=(null destination) serial=71 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.77"
   string ""
   string ":1.77"
signal time=1710441095.361610 sender=org.freedesktop.DBus -> destination=:1.77 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.77"
method call time=1710441095.361697 sender=:1.77 -> destination=org.freedesktop.secrets serial=2 path=/org/freedesktop/secrets; interface=org.freedesktop.DBus.Properties; member=Get
   string "org.freedesktop.Secret.Service"
   string "Collections"
method return time=1710441095.361955 sender=:1.18 -> destination=:1.77 serial=38 reply_serial=2
   variant       array [
         object path "/org/freedesktop/secrets/collection/kdewallet"
      ]
method call time=1710441095.362390 sender=:1.77 -> destination=org.freedesktop.secrets serial=3 path=/org/freedesktop/secrets; interface=org.freedesktop.Secret.Service; member=Unlock
   array [
      object path "/org/freedesktop/secrets/aliases/default"
   ]
method return time=1710441095.362684 sender=:1.18 -> destination=:1.77 serial=39 reply_serial=3
   array [
   ]
   object path "/org/freedesktop/secrets/prompt/p0"
method call time=1710441095.362792 sender=:1.77 -> destination=org.freedesktop.secrets serial=4 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Prompt
   string ""
method return time=1710441095.362801 sender=:1.18 -> destination=:1.77 serial=40 reply_serial=4
signal time=1710441095.362957 sender=:1.18 -> destination=(null destination) serial=41 path=/modules/kwalletd5; interface=org.kde.KWallet; member=walletAsyncOpened
   int32 1
   int32 1966752915
signal time=1710441095.362963 sender=:1.18 -> destination=(null destination) serial=42 path=/modules/kwalletd6; interface=org.kde.KWallet; member=walletAsyncOpened
   int32 1
   int32 1966752915
signal time=1710441095.362965 sender=:1.18 -> destination=(null destination) serial=43 path=/org/freedesktop/secrets; interface=org.freedesktop.Secret.Service; member=CollectionChanged
   object path "/org/freedesktop/secrets/collection/kdewallet"
signal time=1710441095.362967 sender=:1.18 -> destination=:1.77 serial=44 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Completed
   boolean false
   variant       array [
         object path "/org/freedesktop/secrets/aliases/default"
      ]
method call time=1710441095.362970 sender=:1.77 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',path='/org/freedesktop/secrets/prompt/p0',interface='org.freedesktop.Secret.Prompt'"
method return time=1710441095.362972 sender=org.freedesktop.DBus -> destination=:1.77 serial=3 reply_serial=5
signal time=1710441098.632789 sender=org.freedesktop.DBus -> destination=:1.77 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.77"
signal time=1710441098.632838 sender=org.freedesktop.DBus -> destination=(null destination) serial=72 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.77"
   string ":1.77"
   string ""
method call time=1710441103.840776 sender=:1.78 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1710441103.840787 sender=org.freedesktop.DBus -> destination=:1.78 serial=1 reply_serial=1
   string ":1.78"
signal time=1710441103.840803 sender=org.freedesktop.DBus -> destination=(null destination) serial=73 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.78"
   string ""
   string ":1.78"
signal time=1710441103.840807 sender=org.freedesktop.DBus -> destination=:1.78 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.78"
method call time=1710441103.840847 sender=:1.78 -> destination=org.freedesktop.secrets serial=2 path=/org/freedesktop/secrets; interface=org.freedesktop.DBus.Properties; member=Get
   string "org.freedesktop.Secret.Service"
   string "Collections"
method return time=1710441103.841219 sender=:1.18 -> destination=:1.78 serial=45 reply_serial=2
   variant       array [
         object path "/org/freedesktop/secrets/collection/kdewallet"
      ]
method call time=1710441103.841232 sender=:1.78 -> destination=org.freedesktop.secrets serial=3 path=/org/freedesktop/secrets; interface=org.freedesktop.Secret.Service; member=Unlock
   array [
      object path "/org/freedesktop/secrets/aliases/default"
   ]
method return time=1710441103.841579 sender=:1.18 -> destination=:1.78 serial=46 reply_serial=3
   array [
      object path "/org/freedesktop/secrets/aliases/default"
   ]
   object path "/"
method call time=1710441103.841591 sender=:1.78 -> destination=org.freedesktop.secrets serial=4 path=/org/freedesktop/secrets/aliases/default; interface=org.freedesktop.Secret.Collection; member=SearchItems
   array [
      dict entry(
         string "username"
         string ""
      )
      dict entry(
         string "service"
         string "gh:github.com"
      )
   ]
method return time=1710441103.841886 sender=:1.18 -> destination=:1.78 serial=47 reply_serial=4
   array [
      object path "/org/freedesktop/secrets/collection/kdewallet/0"
   ]
method call time=1710441103.841893 sender=:1.78 -> destination=org.freedesktop.secrets serial=5 path=/org/freedesktop/secrets; interface=org.freedesktop.Secret.Service; member=OpenSession
   string "plain"
   variant       string ""
method call time=1710441103.842137 sender=:1.18 -> destination=org.freedesktop.DBus serial=48 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0=':1.78'"
method return time=1710441103.842293 sender=:1.18 -> destination=:1.78 serial=49 reply_serial=5
   variant       array [
      ]
   object path "/org/freedesktop/secrets/session/1"
method call time=1710441103.842300 sender=:1.78 -> destination=org.freedesktop.secrets serial=6 path=/org/freedesktop/secrets/collection/kdewallet/0; interface=org.freedesktop.Secret.Item; member=GetSecret
   object path "/org/freedesktop/secrets/session/1"
method return time=1710441103.842411 sender=:1.18 -> destination=:1.78 serial=50 reply_serial=6
   struct {
      object path "/org/freedesktop/secrets/session/1"
      array [
      ]
      array of bytes "TOKEN-REDACTED"
      string "text/plain; charset=utf8"
   }
method call time=1710441103.842426 sender=:1.78 -> destination=org.freedesktop.secrets serial=7 path=/org/freedesktop/secrets/session/1; interface=org.freedesktop.Secret.Session; member=Close
method return time=1710441103.842569 sender=:1.18 -> destination=:1.78 serial=51 reply_serial=7
method call time=1710441103.842574 sender=:1.18 -> destination=org.freedesktop.DBus serial=52 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0=':1.78'"
method call time=1710441103.842576 sender=:1.18 -> destination=org.freedesktop.DBus serial=53 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0='org.freedesktop.DBus'"
error time=1710441103.842578 sender=org.freedesktop.DBus -> destination=:1.18 error_name=org.freedesktop.DBus.Error.MatchRuleNotFound reply_serial=53
   string "The given match rule wasn't found and can't be removed"
signal time=1710441104.135900 sender=org.freedesktop.DBus -> destination=:1.78 serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.78"
signal time=1710441104.135944 sender=org.freedesktop.DBus -> destination=(null destination) serial=74 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.78"
   string ":1.78"
   string ""

[williammartin]

I'm not a dbus expert (never looked at it before yesterday) but what I'm seeing here are two connections saying "hello" which is something that happens when we connect to DBUS from the keyring library.

method call time=1710441095.361593 sender=:1.77 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
...
method call time=1710441103.840776 sender=:1.78 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello

These are about 8 seconds apart (which I assume is about the length of time you waited between the auth status commands?).

The second one looks like I'd expect, with a request for and response with the secrets:

method call time=1710441103.841591 sender=:1.78 -> destination=org.freedesktop.secrets serial=4 path=/org/freedesktop/secrets/aliases/default; interface=org.freedesktop.Secret.Collection; member=SearchItems
   array [
      dict entry(
         string "username"
         string ""
      )
      dict entry(
         string "service"
         string "gh:github.com"
      )
   ]
...
method return time=1710441103.842411 sender=:1.18 -> destination=:1.78 serial=50 reply_serial=6
   struct {
      object path "/org/freedesktop/secrets/session/1"
      array [
      ]
      array of bytes "TOKEN-REDACTED"
      string "text/plain; charset=utf8"
   }

But the first one hits some kind of prompt request:

method return time=1710441095.362684 sender=:1.18 -> destination=:1.77 serial=39 reply_serial=3
   array [
   ]
   object path "/org/freedesktop/secrets/prompt/p0"
method call time=1710441095.362792 sender=:1.77 -> destination=org.freedesktop.secrets serial=4 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Prompt
   string ""
method return time=1710441095.362801 sender=:1.18 -> destination=:1.77 serial=40 reply_serial=4
signal time=1710441095.362957 sender=:1.18 -> destination=(null destination) serial=41 path=/modules/kwalletd5; interface=org.kde.KWallet; member=walletAsyncOpened
   int32 1
   int32 1966752915
signal time=1710441095.362963 sender=:1.18 -> destination=(null destination) serial=42 path=/modules/kwalletd6; interface=org.kde.KWallet; member=walletAsyncOpened
   int32 1
   int32 1966752915
signal time=1710441095.362965 sender=:1.18 -> destination=(null destination) serial=43 path=/org/freedesktop/secrets; interface=org.freedesktop.Secret.Service; member=CollectionChanged
   object path "/org/freedesktop/secrets/collection/kdewallet"
signal time=1710441095.362967 sender=:1.18 -> destination=:1.77 serial=44 path=/org/freedesktop/secrets/prompt/p0; interface=org.freedesktop.Secret.Prompt; member=Completed
   boolean false
   variant       array [
         object path "/org/freedesktop/secrets/aliases/default"
      ]
method call time=1710441095.362970 sender=:1.77 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',path='/org/freedesktop/secrets/prompt/p0',interface='org.freedesktop.Secret.Prompt'"

Did you receive any kind of popup? It's possible something else is unlocking the keyring in response to this prompt automatically I suppose. My suspicion is that either:

1. You should be getting a prompt but you aren't (but I don't know why it would succeed a second time)
2. The keyring library doesn't know how to handle whatever is happening with this prompt, though it should

[tdhooten]

Nope, no prompt or anything else. The gh auth status just fails the first time and succeeds the second time with the output I posted before, nothing happens on the desktop or elsewhere.

[williammartin]

@tdhooten wow. That would be quite a solve if we got it. Thank you for your active involvement here, I could not have done it. I suspect what's happening is you have some config that auto unlocks instead of offering the prompt and it happens so fast it's racy. Perhaps you have something like PAM configured: https://wiki.archlinux.org/title/KDE_Wallet

---

@yutanagano @siniarskimar @avivace @glenfletcher would any of you be willing to build and test this change out as described here: #8802 (comment)

gh repo clone cli/cli && cd cli && git checkout wm/debug-8802 && make

Then after restart try ./bin/gh auth status from the cli directory. Where you would expect gh auth status to have previously failed, I would now expect it to succeed.

[tdhooten]

I suspect what's happening is you have some config that auto unlocks instead of offering the prompt and it happens so fast it's racy.

Yes, I do indeed have the wallet set to auto-unlock. The weird thing is that I have tried manually opening the wallet to make sure it's ready before first running gh commands, and yet it would still fail the first time.

Anyway, thank you so much for your work on this.

[tdhooten]

The folks over at zalando have agreed with our assessment and have merged the PR. I've asked whether they will cut a release or if we should pin to the sha. Ideally we could get this fixed in our next release which on our usual schedule would be on Tuesday.

Looks like they already pushed a new release!

Great job finding this fix so quickly, I really appreciate your work.

[williammartin]

I've opened a PR here to bump to the new release of go-keyring: #8833