Page MenuHome GnuPG
Create Task
Maniphest T3027

gpg-agent crash on macOS Sierra triggerd by ssh
Closed, ResolvedPublic
Actions

Description

{F137114}I've configured gpg2 with enable-ssh-support.

I works nicely when connecting to a host manually. However, when using the
provisioning framework Ansible, in order to configure my servers, the gpg-agent
crashes when I provision more than a few servers in parallel. This happens
during ~50% of my ansible runs, and the frequency increases with the numbers of
servers.

Under the hoods, ansible will initially setup connections to all hosts involved,
before continuing with actual provisioning, meaning lots of connections get
setup in parallel.

By the way, I use the ControlPersist and ProxyCommand options in ssh in order to
reuse connections that pass through a bastion.

Crash report from mac attached.

Details

Version
2.1.19, 2.1.20, 2.1.21

Revisions and Commits

rG GnuPG
D419rGebe12be034f0 agent: Serialize access to passphrase cache.
rC libgcrypt
rC91456759b887 secmem: Fix SEGV and stat calculation.
rCe0958debe1a7 secmem: Fix SEGV and stat calculation.

Related Objects

Event Timeline

landro added a subscriber: landro.Mar 30 2017, 3:22 PM

993_gpg-agent_2017-03-30-142306_mac-stefanlandro.crash26 KBDownload

landro added projects: MacOS, ssh, gnupg, gnupg (gpg21), gpgagent, Bug Report.Mar 30 2017, 3:22 PM
landro set Version to 2.1.19.
marcus moved this task from Backlog to In Progress on the gnupg board.Mar 30 2017, 7:35 PM
marcus moved this task from In Progress to Backlog on the gnupg board.
• gniibe closed this task as Resolved.Apr 4 2017, 2:54 AM
• gniibe claimed this task.
• gniibe added a subscriber: • gniibe.

In 2.1.19, gpg-agent uses getpeerucred for macOS. I changed it (since it seemed not working). In 2.1.20, gpg-agent now uses getsockopt with LOCAL_PEERPID.
It seems for me that the crash occurs by ucred_free. If this is the case, 2.1.20 fixes this issue.

Could you please test with 2.1.20?

• gniibe reopened this task as Open.Apr 4 2017, 2:54 AM
• gniibe added a project: In Progress.
• gniibe added a comment.EditedApr 6 2017, 4:38 AM

While I can't reproduce this problem myself, I think I found an issue of gpg-agent passphrase caching.
Double free may happen when multiple threads enter agent_put_cache, for example.

Here is a patch to serialize the cache access. Smaller lock is not required any more.
D419: gpg-agent cache handling serialization

• gniibe added a comment.Apr 7 2017, 2:15 AM

Applied as ebe12be034f0.

• gniibe removed projects: gnupg (gpg21), ssh, MacOS.Apr 11 2017, 2:43 AM
landro added a comment.Apr 19 2017, 9:18 AM

I finally got around to test this again - sorry for the long wait. I testet with 2.1.20 - same behaviour as in 2.1.19. Crash report attached.

gpg-agent_2017-04-19-090741_mac-stefanlandro.crash19 KBDownload

• gniibe added a comment.Apr 19 2017, 9:58 AM

Yes, 2.1.20 has the issue, too.
The crash report can be explained as: if the double-free can occur when multiple threads access to the cache at the same time, allocation in md_open may crash.

• gniibe added a commit: rGebe12be034f0: agent: Serialize access to passphrase cache..Apr 25 2017, 3:31 AM
• gniibe closed this task as Resolved.May 16 2017, 1:22 AM

Fixed in 2.1.21.

landro reopened this task as Open.May 22 2017, 12:21 PM
landro updated the task description. (Show Details)
landro changed Version from 2.1.19 to 2.1.19, 2.1.20, 2.1.21.

Just retested this with 2.1.21 - unfortunately gpg-agent is still crashing. Se new attached crash log.

gpg-agent_2017-05-22-121424_mac-stefanlandro.crash34 KBDownload

justus added a subscriber: justus.May 22 2017, 4:23 PM

Hi @landro, thanks for the stack trace. Could you please try to resolve this frame

4   libgcrypt.20.dylib            	0x000000010d8b14d2 openpgp_s2k + 594

to a source code location? I believe it can be done this way:

$ atos -o /usr/local/opt/libgcrypt/lib/libgcrypt.20.dylib -arch x86_64 -l 0x10d896000 0x000000010d8b14d2

I tried to reproduce this issue locally but failed.

• gniibe added a comment.May 23 2017, 7:36 AM

In the crash log of 2017-05-22, I can't find any race or violation of shared object. It looks like some malloc related error.
Does gpg-agent emit error message(s)?

It will be helpful for us you can put a line with .gnupg/gpg-agent

log-file SOMEWHERE
debug 160

for possible error messages.

landro added a comment.May 23 2017, 12:19 PM

Here is the output of the log file

2017-05-23 12:15:36 gpg-agent[45635] ssh handler 0x70000902e000 for fd 11 started
2017-05-23 12:15:36 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:36 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:36 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:36 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:36 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000090b1000 for fd 14 started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x700009134000 for fd 15 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000091b7000 for fd 17 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x70000923a000 for fd 18 started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 19 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x700009340000 for fd 20 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 23 started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x700009446000 for fd 24 started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000094c9000 for fd 21 started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x70000954c000 for fd 27 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 29 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x700009652000 for fd 30 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 32 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x700009758000 for fd 34 started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000097db000 for fd 43 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x70000985e000 for fd 45 started
2017-05-23 12:15:43 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 46 started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:43 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009964000 for fd 55 started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000099e7000 for fd 58 started
2017-05-23 12:15:44 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009a6a000 for fd 61 started
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] Warning: using insecure memory!
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009aed000 for fd 68 started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009340000 for fd 20 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000923a000 for fd 18 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009446000 for fd 24 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 19 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000094c9000 for fd 21 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000985e000 for fd 45 terminated
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000923a000 for fd 18 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 19 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009340000 for fd 20 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009446000 for fd 21 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000094c9000 for fd 24 started
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 32 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009758000 for fd 34 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009652000 for fd 30 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 29 terminated
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000099e7000 for fd 58 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009964000 for fd 55 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009aed000 for fd 68 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009a6a000 for fd 61 terminated
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 46 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 38 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009652000 for fd 40 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 41 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009758000 for fd 42 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000985e000 for fd 44 started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000097db000 for fd 43 terminated
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Cannot allocate memory
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <Pinentry>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000954c000 for fd 27 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 23 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 23 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000954c000 for fd 27 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000097db000 for fd 30 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 31 started
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009964000 for fd 32 started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009652000 for fd 40 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 41 terminated
2017-05-23 12:15:44 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009758000 for fd 42 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x70000985e000 for fd 44 terminated
2017-05-23 12:15:44 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009340000 for fd 20 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 19 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x700009446000 for fd 21 terminated
2017-05-23 12:15:44 gpg-agent[45635] ssh handler 0x7000094c9000 for fd 24 terminated
2017-05-23 12:15:44 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:44 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:44 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:44 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 38 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Cannot allocate memory
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 31 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 23 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x70000954c000 for fd 27 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009964000 for fd 32 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000097db000 for fd 30 terminated
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Cannot allocate memory
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <Pinentry>
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x70000923a000 for fd 18 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x70000923a000 for fd 18 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 20 started
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009340000 for fd 21 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 28 started
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009446000 for fd 29 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:45 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 20 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009340000 for fd 21 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 28 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009446000 for fd 29 terminated
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000092bd000 for fd 20 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009340000 for fd 23 started
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000093c3000 for fd 24 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009446000 for fd 28 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000094c9000 for fd 31 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x70000954c000 for fd 29 started
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 30 started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x700009652000 for fd 36 started
2017-05-23 12:15:45 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:45 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 39 started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009758000 for fd 37 started
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000097db000 for fd 40 started
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x70000985e000 for fd 41 started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 38 started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009964000 for fd 42 started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009652000 for fd 36 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 39 terminated
2017-05-23 12:15:46 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009446000 for fd 28 terminated
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 30 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x70000954c000 for fd 29 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:46 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009758000 for fd 37 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x70000985e000 for fd 41 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 38 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x7000097db000 for fd 40 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009964000 for fd 42 terminated
2017-05-23 12:15:46 gpg-agent[45635] ssh handler 0x700009446000 for fd 28 started
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:46 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:46 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:46 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:47 gpg-agent[45635] failed to unprotect the secret key: Cannot allocate memory
2017-05-23 12:15:47 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:47 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <Pinentry>
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh handler 0x700009446000 for fd 28 terminated
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh handler 0x700009446000 for fd 28 started
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:47 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh handler 0x70000954c000 for fd 30 started
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:47 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:47 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x7000095cf000 for fd 33 started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x700009652000 for fd 36 started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x7000096d5000 for fd 38 started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x700009758000 for fd 39 started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x7000097db000 for fd 40 started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x70000985e000 for fd 43 started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 44 started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x700009964000 for fd 46 started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x7000099e7000 for fd 47 started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x700009a6a000 for fd 48 started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x700009a6a000 for fd 48 terminated
2017-05-23 12:15:48 gpg-agent[45635] ssh handler 0x70000985e000 for fd 43 terminated
2017-05-23 12:15:48 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x70000985e000 for fd 48 started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x70000985e000 for fd 48 terminated
2017-05-23 12:15:49 gpg-agent[45635] failed to unprotect the secret key: Cannot allocate memory
2017-05-23 12:15:49 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:49 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <Pinentry>
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 44 terminated
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x70000985e000 for fd 43 started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x7000098e1000 for fd 44 started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009a6a000 for fd 51 started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009aed000 for fd 50 started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009b70000 for fd 54 started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009bf3000 for fd 56 started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009c76000 for fd 57 started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:49 gpg-agent[45635] ssh handler 0x700009cf9000 for fd 58 started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:49 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:50 gpg-agent[45635] ssh handler 0x700009d7c000 for fd 61 started
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) started
2017-05-23 12:15:50 gpg-agent[45635] new connection to SCdaemon established
2017-05-23 12:15:50 gpg-agent[45635] starting a new PIN Entry
2017-05-23 12:15:50 gpg-agent[45635] ssh handler 0x700009c76000 for fd 57 terminated
2017-05-23 12:15:50 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:50 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:50 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:50 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:50 gpg-agent[45635] failed to build S-Exp (off=0): Cannot allocate memory
2017-05-23 12:15:50 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:50 gpg-agent[45635] ssh sign request failed: Cannot allocate memory <gcrypt>
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh handler 0x700009aed000 for fd 50 terminated
2017-05-23 12:15:50 gpg-agent[45635] ssh handler 0x700009bf3000 for fd 56 terminated
2017-05-23 12:15:50 gpg-agent[45635] failed to acquire the pinentry lock: Timeout
2017-05-23 12:15:50 gpg-agent[45635] failed to unprotect the secret key: Timeout
2017-05-23 12:15:50 gpg-agent[45635] failed to read the secret key
2017-05-23 12:15:50 gpg-agent[45635] ssh sign request failed: Timeout <GPG Agent>
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for request_identities (11) ready
2017-05-23 12:15:50 gpg-agent[45635] ssh handler 0x700009cf9000 for fd 58 terminated
2017-05-23 12:15:50 gpg-agent[45635] ssh request handler for sign_request (13) started
2017-05-23 12:15:50 gpg-agent[45635] starting a new PIN Entry

landro added a comment.May 23 2017, 12:21 PM
In T3027#97654, @justus wrote:

Hi @landro, thanks for the stack trace. Could you please try to resolve this frame

4   libgcrypt.20.dylib            	0x000000010d8b14d2 openpgp_s2k + 594

to a source code location? I believe it can be done this way:

$ atos -o /usr/local/opt/libgcrypt/lib/libgcrypt.20.dylib -arch x86_64 -l 0x10d896000 0x000000010d8b14d2

I tried to reproduce this issue locally but failed.

Here it is. @justus

$ atos -o /usr/local/opt/libgcrypt/lib/libgcrypt.20.dylib -arch x86_64 -l 0x10d896000 0x000000010d8b14d2
openpgp_s2k (in libgcrypt.20.dylib) + 594

• gniibe added a comment.May 23 2017, 12:31 PM

@landro Thanks a lot. I think that we see some failures in the log, and there might be another bug in the failure path.

justus added a comment.May 23 2017, 12:41 PM

"landro (Stefan Magnus Landrø)" <noreply@dev.gnupg.org> writes:

In https://dev.gnupg.org/T3027#97654, @justus wrote:
> Hi @landro, thanks for the stack trace.  Could you please try to resolve this frame
>
>   4   libgcrypt.20.dylib            	0x000000010d8b14d2 openpgp_s2k + 594

Here it is. @justus

$ atos -o /usr/local/opt/libgcrypt/lib/libgcrypt.20.dylib -arch x86_64 -l 0x10d896000 0x000000010d8b14d2
openpgp_s2k (in libgcrypt.20.dylib) + 594

Hm, it did not give us the location in the source unfortunately, only
the offset from the top of the function, which the original stack trace
already contains. Maybe the library does not contain debug information.
Depending on how you installed that software, there may be a way to
install the debug symbols too. That would make bug reports much more
helpful. Thanks anyway, maybe the log will help us trace the problem.

landro added a comment.May 23 2017, 3:19 PM

Hm, it did not give us the location in the source unfortunately, only
the offset from the top of the function, which the original stack trace
already contains. Maybe the library does not contain debug information.
Depending on how you installed that software, there may be a way to
install the debug symbols too. That would make bug reports much more
helpful. Thanks anyway, maybe the log will help us trace the problem.

Too bad. I installed both libgcrypt and gnupg using homebrew, and apparently there is no way to make homebrew include debug info. I guess I could build from source and include debug info - where can I find instructions on doing that?

justus added a comment.May 23 2017, 3:32 PM

"landro (Stefan Magnus Landrø)" <noreply@dev.gnupg.org> writes:

Too bad. I installed both libgcrypt and gnupg using homebrew, and apparently there is no way to make homebrew include debug info. I guess I could build from source and include debug info - where can I find instructions on doing that?

Don't bother for the moment (it is complex, not difficult, but complex),
we'll see what we can read from the log, and maybe try to reproduce it
on our macOS box.

landro added a comment.May 23 2017, 3:46 PM

Ok. To reproduce, I believe the key is to establish lots of connections (in my rig around 20) to (possibly different) ssh server(s) (possibly by going through a bastion) within a short timeframe.

justus added a comment.May 23 2017, 4:00 PM

So I noticed your log contains lot's of "starting a new PIN Entry", I assume you are using some kind of password manager integration, so that you don't need to enter it each time (sorry, I'm not familiar with how pinentry works on macOS).

I too noticed the pinentry popping up several times in my tests, which is odd by itself, and may point to a (the?) problem, because the passphrase should be cached.

landro added a comment.May 24 2017, 12:52 PM

So I'm using pinentry-mac in my gpg-agent.conf:

➜  .gnupg cat gpg-agent.conf
enable-ssh-support
pinentry-program /usr/local/bin/pinentry-mac
log-file /tmp/gpg-agent.log
debug 160

I installed pinentry-mac using homebrew:

➜  0.9.4 brew list pinentry-mac
/usr/local/Cellar/pinentry-mac/0.9.4/bin/pinentry-mac
/usr/local/Cellar/pinentry-mac/0.9.4/pinentry-mac.app/Contents/ (8 files)

The code for pinentry-mac can be found at: https://github.com/GPGTools/pinentry-mac/tree/v0.9.4

Pinentry popping up several times in the logs - but not on the screen! (pinentry-mac is a gui thing) - is indeed odd - since the passphrase is cached.

I can try to reproduce bug using the text based pinentry-program, but I guess the results will be the same. Let me know if you need that.

landro added a comment.May 24 2017, 12:55 PM

Just noticed one more thing - I'm not trying to use a smartcard at this time (I plan on moving to yubikeys in future though) - why is "new connection to SCdaemon established" all over the logs?

justus added a comment.May 24 2017, 1:44 PM

"landro (Stefan Magnus Landrø)" <noreply@dev.gnupg.org> writes:

Just noticed one more thing - I'm **not** trying to use a smartcard at this time (I plan on moving to yubikeys in future though) - why is "new connection to SCdaemon established" all over the logs?

We have been working on integrating smart card support more with gpg,
for example, gpg should prefer keys on the smartcard if one is currently
plugged in. That's probably why it is connecting to scdaemon. Is that
plausible @gniibe?

• gniibe added a comment.May 24 2017, 1:57 PM

For smartcard, yes. The feature for ssh with smartcard has been available more than ten years. I recently apply the approach to gpg frontend.

This bug has two things. The crash: this should be fixed soon. Perhaps, the double free would be in the failure path. Requests rate bigger than processing rate. This will be best if it will be connection error. I mean, by throttling.

landro added a comment.May 24 2017, 3:13 PM

What do you mean by connection error, @gniibe? I hope the user is not impacted by what you are suggesting.

• gniibe added a comment.May 25 2017, 12:06 AM

(Since I was writing by phone, the sentence was terse. Sorry. This time, by PC.)

(1) We will fix the crash issue, because this is a real bug.
(2) It is true that the processing time of the authentication is slow by gpg-agent (if we compare the original ssh-agent implementation), because it includes the processing time of decrypting the private key, and it is intentionally slow in GnuPG to avoid brute force attack against encrypted private key.
(3) The problem is: What if when many requests come in than the maximum processing rate of gpg-agent?

Current implementation has no control of throttling about accepting connections from clients. So, the answer to (3) is: memory allocation error eventually; Consider the scenario: a request comes in. try to serve the request. while processing, another request comes in. try to serve... and gpg-agent keeps accepting requests, until it dies.

Throttling means that: Don't accept new connection beyond maximum serving limits. The intention is to protect the server (gpg-agent, in this case). This means that clients have to wait until the server (gpg-agent) finishes other requests. This can regulate the accepting requests rate and keeps it lower than maximum processing rate. New client have to wait the connection to gpg-agent until it resumes accepting new request. Thus, clients wait.

Then, new question is: Even so, what if generating many new clients' requests, many, and many?

It results connection error, namely, connection time out for some of clients. It is not possible to server beyond the maximum.

• gniibe added a comment.May 25 2017, 2:47 AM

@landro , Do you have any key which might require passphrase update for its expiration?
I mean, do you have an gpg-agent option of "max_passphrase_days" set (default is not set).

I am suspecting recursive lock acquire of entry_lock variable in agent/call-pinentry.c.
The call chain in question is:

agent_askpin -> callback (e.g. try_unprotect_cb in findkey.c) -> agent_get_confirmation

If it is not related to your problem, this is indeed a bug.

landro added a comment.May 25 2017, 7:47 AM

@gniibe , I'm not setting the max-passphrase-option. Currently, my gpg-agent.conf looks like this:

➜  .gnupg cat gpg-agent.conf
enable-ssh-support
pinentry-program /usr/local/bin/pinentry-mac
log-file /tmp/gpg-agent.log
debug 160
• gniibe added a comment.Jun 1 2017, 5:02 AM

I fixed a bug in nPth: rPTH4fae99976c31: Fix busy_wait_for.
During this debug, I also found a bug and fixed in libassuan: rA62f3123d3877: Use gpgrt_free to release memory allocated by gpgrt_asprintf.
Also, I fixed two related bug in GnuPG:
rGc03e0eb01dc4: agent: Fix error from do_encryption.
rG996544626ea4: agent: Fix memory leaks.

Well, this issue contributes many bug fixes :-), but I still can't identify the cause of this particular issue.

• gniibe mentioned this in D431: secmem fix.Jun 1 2017, 2:13 PM
• gniibe added a comment.Jun 1 2017, 2:16 PM

I managed to replicate this issue by preparing artificial nPth on x86 GNU/Linux.

I build nPth (before the fix) by:

ac_cv_func_pthread_mutex_timedlock=false ../npth/configure

And I upload the fix for libgcrypt: D431: secmem fix

• werner added a subscriber: • werner.Jun 1 2017, 2:47 PM

So, should we do a new libgcrypt release RSN?
There is another bug with solution also pending and it might not be too late for Squeeze if we hurry.

• gniibe added a comment.Jun 2 2017, 12:36 AM

libgcrypt secmem fix is not that in hurry, I think. nPTh bug for macOS sounds more severe.

• gniibe added a commit: rCe0958debe1a7: secmem: Fix SEGV and stat calculation..Jun 2 2017, 3:39 AM
• werner added a commit: rC91456759b887: secmem: Fix SEGV and stat calculation..Jun 2 2017, 8:42 AM
• werner added a comment.Jun 2 2017, 10:52 AM

I released libgcrypt 1.7.7
and nPth 1.6

marcus changed the task status from Open to Testing.Jul 13 2017, 1:43 AM
marcus added a subscriber: marcus.

@landro Would you like to do one more round of testing?

landro added a comment.Jul 16 2017, 12:46 PM

@marcus sure, but I am currently away on vacation and won't be back until mid August. Also, I'd need some detailed build instructions (I'm on mac os) since I'm not very familiar with building C code - I brew installed gpg.

• gniibe added a comment.Jul 31 2017, 2:02 AM

GnuPG 2.1.22 in Homebrew is out: https://github.com/Homebrew/homebrew-core/commit/39a392ffd6ac20a36ea8a4aec5c4dc5febcfc1d6
Please check it out.

• gniibe closed this task as Resolved.Aug 31 2017, 10:26 AM

Given no feedback, I'm closing this issue.
If there is still problem, please reopen.

sundbp added a subscriber: sundbp.EditedDec 11 2017, 11:48 PM

I'm seeing something quite similar - same setup, osx and it only shows when using ansible. I'm on gnupg 2.2.3, also saw same using "GPG Suite 2017.2".

I don't get a crash, but I get "random" failures of ssh authentication via gpg-agent when issuing many ssh connections, the way ansible operates.

Happy to provide info if there's interesting trying to fix this.

sundbp reopened this task as Open.Dec 11 2017, 11:49 PM
• gniibe closed this task as Resolved.Dec 12 2017, 12:12 AM
• gniibe removed a project: In Progress.

Please open another report, not reusing similar. I don't think it's same bug.
Please note that GnuPG's ssh is not fast enough (intentionally), its rate is usually ten connections per second.