Change Details

First of all, thanks for your continuous work on maintaining and improving this project! A few days ago I installed `gnupg` on my new MacBook using Homebrew, which comes with version 2.3.1, and trying to use a YubiKey. First I got bitten by T5415, which I fixed as described in that ticket - by adding `disable-ccid` to `~/.gnupg/scdaemon.conf`. After some time of using it, I realized that it asked for the PIN for **every** operation, whereas I remembered the PIN should be cached for some time. To verify this assumption, I installed `gnupg@2.2`, and indeed, the PIN was cached after first entering it. As this didn't seem an intended difference in behavior between versions, I decided to debug it further. I enabled `gpg-agent` debug logging, and noticed some interesting messages: * when writing to the cache: ``` 2021-05-10 23:55:50 gpg-agent[61532] DBG: chan_9 <- S PINCACHE_PUT 0/openpgp/2 *redacted* 2021-05-10 23:55:50 gpg-agent[61532] DBG: handle_pincache_put: caching 'PINCACHE_PUT'->'0/openpgp/2 *redacted*' 2021-05-10 23:55:50 gpg-agent[61532] DBG: agent_put_cache 'PINCACHE_PUT'.-1 (mode 6) requested ttl=-1 ``` * when reading from the cache: ``` 2021-05-11 00:08:24 gpg-agent[61532] DBG: handle_pincache_get: enter '0/openpgp/2' 2021-05-11 00:08:24 gpg-agent[61532] DBG: agent_get_cache '0/openpgp/2'.-1 (mode 6) ... 2021-05-11 00:08:24 gpg-agent[61532] DBG: ... miss ``` So it looked like writing to the cache wasn't working. Taking a look at `handle_pincache_put()`, it should log `handle_pincache_put: caching 'key'->'pin'`, but instead it was logging `handle_pincache_put: caching 'PINCACHE_PUT'->'pin key'`, so somehow it was called with a string including the `PINCACHE_PUT` command. Looking at all the call sites, I noticed [this](https://github.com/gpg/gnupg/blob/gnupg-2.3.1/agent/call-scd.c#L548-L549): * `call-scd.c:548` ``` else if ((s=has_leading_keyword (line, "PINCACHE_PUT"))) err = handle_pincache_put (line); ``` Although it seemed weird to me the `padding_info_cb()` callback would get called when asking for the PIN, this was the only place where `handle_pincache_put()` was called with the whole command line. I downloaded the source, added some debug logging, and confirmed my hunch. Also, changing the call to `handle_pincache_put (s);` fixed the cache writing issue, and asking for the PIN now behaved as expected. If this is not too urgent a fix, I will send a patch later today.

First of all, thanks for your continuous work on maintaining and improving this project! A few days ago I installed `gnupg` on my new MacBook using Homebrew, which comes with version 2.3.1, and trying to use a YubiKey. First I got bitten by T5415, which I fixed as described in that ticket - by adding `disable-ccid` to `~/.gnupg/scdaemon.conf`. After some time of using it, I realized that it asked for the PIN for **every** operation, whereas I remembered the PIN should be cached for some time. To verify this assumption, I installed `gnupg@2.2`, and indeed, the PIN was cached after first entering it. As this didn't seem an intended difference in behavior between versions, I decided to debug it further. I enabled `gpg-agent` debug logging, and noticed some interesting messages: * when writing to the cache: ``` 2021-05-10 23:55:50 gpg-agent[61532] DBG: chan_9 <- S PINCACHE_PUT 0/openpgp/2 *redacted* 2021-05-10 23:55:50 gpg-agent[61532] DBG: handle_pincache_put: caching 'PINCACHE_PUT'->'0/openpgp/2 *redacted*' 2021-05-10 23:55:50 gpg-agent[61532] DBG: agent_put_cache 'PINCACHE_PUT'.-1 (mode 6) requested ttl=-1 ``` * when reading from the cache: ``` 2021-05-10 23:56:05 gpg-agent[61532] DBG: handle_pincache_get: enter '0/openpgp/2' 2021-05-10 23:56:05 gpg-agent[61532] DBG: agent_get_cache '0/openpgp/2'.-1 (mode 6) ... 2021-05-10 23:56:05 gpg-agent[61532] DBG: ... miss ``` So it looked like writing to the cache wasn't working. Taking a look at `handle_pincache_put()`, it should log `handle_pincache_put: caching 'key'->'pin'`, but instead it was logging `handle_pincache_put: caching 'PINCACHE_PUT'->'pin key'`, so somehow it was called with a string including the `PINCACHE_PUT` command. Looking at all the call sites, I noticed [this](https://github.com/gpg/gnupg/blob/gnupg-2.3.1/agent/call-scd.c#L548-L549): * `call-scd.c:548` ``` else if ((s=has_leading_keyword (line, "PINCACHE_PUT"))) err = handle_pincache_put (line); ``` Although it seemed weird to me the `padding_info_cb()` callback would get called when asking for the PIN, this was the only place where `handle_pincache_put()` was called with the whole command line. I downloaded the source, added some debug logging, and confirmed my hunch. Also, changing the call to `handle_pincache_put (s);` fixed the cache writing issue, and asking for the PIN now behaved as expected. If this is not too urgent a fix, I will send a patch later today.

First of all, thanks for your continuous work on maintaining and improving this project! A few days ago I installed `gnupg` on my new MacBook using Homebrew, which comes with version 2.3.1, and trying to use a YubiKey. First I got bitten by T5415, which I fixed as described in that ticket - by adding `disable-ccid` to `~/.gnupg/scdaemon.conf`. After some time of using it, I realized that it asked for the PIN for **every** operation, whereas I remembered the PIN should be cached for some time. To verify this assumption, I installed `gnupg@2.2`, and indeed, the PIN was cached after first entering it. As this didn't seem an intended difference in behavior between versions, I decided to debug it further. I enabled `gpg-agent` debug logging, and noticed some interesting messages: * when writing to the cache: ``` 2021-05-10 23:55:50 gpg-agent[61532] DBG: chan_9 <- S PINCACHE_PUT 0/openpgp/2 *redacted* 2021-05-10 23:55:50 gpg-agent[61532] DBG: handle_pincache_put: caching 'PINCACHE_PUT'->'0/openpgp/2 *redacted*' 2021-05-10 23:55:50 gpg-agent[61532] DBG: agent_put_cache 'PINCACHE_PUT'.-1 (mode 6) requested ttl=-1 ``` * when reading from the cache: ``` 2021-05-11 00:08:240 23:56:05 gpg-agent[61532] DBG: handle_pincache_get: enter '0/openpgp/2' 2021-05-11 00:08:240 23:56:05 gpg-agent[61532] DBG: agent_get_cache '0/openpgp/2'.-1 (mode 6) ... 2021-05-11 00:08:240 23:56:05 gpg-agent[61532] DBG: ... miss ``` So it looked like writing to the cache wasn't working. Taking a look at `handle_pincache_put()`, it should log `handle_pincache_put: caching 'key'->'pin'`, but instead it was logging `handle_pincache_put: caching 'PINCACHE_PUT'->'pin key'`, so somehow it was called with a string including the `PINCACHE_PUT` command. Looking at all the call sites, I noticed [this](https://github.com/gpg/gnupg/blob/gnupg-2.3.1/agent/call-scd.c#L548-L549): * `call-scd.c:548` ``` else if ((s=has_leading_keyword (line, "PINCACHE_PUT"))) err = handle_pincache_put (line); ``` Although it seemed weird to me the `padding_info_cb()` callback would get called when asking for the PIN, this was the only place where `handle_pincache_put()` was called with the whole command line. I downloaded the source, added some debug logging, and confirmed my hunch. Also, changing the call to `handle_pincache_put (s);` fixed the cache writing issue, and asking for the PIN now behaved as expected. If this is not too urgent a fix, I will send a patch later today.