gpg-agent and putty/ssh agent bug

[Marko Božiković]

Hi all,

I think I've found a bug with gpg-agent acting as a putty pageant.

System details
==============
Windows 7 x64 Ultimate
UAC disabled
logged in as a member of Administrators

GnuPG details
=============
a primary 4096 bit RSA key, with SC capabilities
3 2048 bit RSA keys - one for each: S, E, A
A key's keygrip added to the sshcontrol file, with TTL set to 0 and no
additional flags

options file
------------
cipher-algo AES256
digest-algo SHA512
s2k-cipher-algo AES256
s2k-digest-algo SHA512

no-comments
no-emit-version


gpg-agent.conf file
-------------------
enable-putty-support
debug-level expert


gpg-agent command line
----------------------
gpg-agent.exe --homedir F:\Users\bozho\.gnupg --use-standard-socket --daemon



Steps to reproduce
------------------
1. Start gpg-agent (either directly, or using gpg-connect-agent, makes no
difference). No other instance of gpg-agent is running.

2. Start putty, enter server IP address. When asked for the login, enter it
and press ENTER. After a bit, a default pinetry dialog pops up. Enter key
password and click OK. After some time, putty shows an error dialog with the
message: "Server unexpectedly closed network connection."

3. Close putty, start it again. Enter the server IP address again and connect.
Enter the login when asked. The pientry dialog pops up *again*. Enter key
password and click OK. Putty connects normally.

4. Every subsequent putty connection attempt works as expected (no pinentry,
connects to the server fine)

5. Restarting gpg-agent reproduces steps 1-4 every time.


Using ssh-pageant as an ssh-agent "bridge" exhibits a similar behaviour:

1. Set an environment variable SSH_AUTH_SOCK to "/tmp/.ssh-pageant-bozho"

2. Start gpg-agent as before

3. start ssh-pagenat: ssh-pageant.exe -r -a /tmp/.ssh-pageant-bozho

4. Try to connect to the server using Cygwin's ssh

5. Pinentry dialog pops up, enter password.

6. After a while, ssh reports an error and exits:
Error reading response length from authentication socket.
Permission denied (publickey).

7. ssh-pageant has crashed.

8. Restart ssh-pagenat.

9. Run ssh again, enter the password in the pinentry dialog, ssh connects fine.


Additional notes
----------------
I have attached gpg-agent's debug log (gpg-agent.log)

I have also used Spy++ to log WM_COPYDATA messages from gpg-agent
(gpg-agent-messages.log)

The first four lines (2 WM_COPYDATA messages) are from the unsuccessful
attempt (notice that fProcessed is False in the second message)

The last four lines are from the second, successful attempt.

Additionally, all four messages seem to have the same message parameters:
wParam: 00000000
lParam: 028CFE84
   dwData: 804E50BA
   cbData: 23
   lpData: 0039E7C0


I hope this helps in locating the bug :)


Thank you,
-- 
Marko
-------------- next part --------------
2015-06-28 23:07:04 gpg-agent[7576] listening on socket 'F:\Users\bozho\.gnupg\S.gpg-agent'
2015-06-28 23:07:04 gpg-agent[7576] listening on socket 'F:\Users\bozho\.gnupg\S.gpg-agent.ssh'
2015-06-28 23:07:04 gpg-agent[7576] gpg-agent (GnuPG) 2.1.5 started
2015-06-28 23:07:04 gpg-agent[7576] putty message loop thread started
2015-06-28 23:07:15 gpg-agent[7576] DBG: ssh map file 'PageantRequest00002418'
2015-06-28 23:07:15 gpg-agent[7576] DBG: ssh map handle 0x00000140
2015-06-28 23:07:15 gpg-agent[7576] DBG:           my sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:07:15 gpg-agent[7576] DBG: ssh map file sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:07:15 gpg-agent[7576] DBG: ssh IPC buffer at 0x025c0000
2015-06-28 23:07:15 gpg-agent[7576] ssh request handler for request_identities (11) started
2015-06-28 23:07:15 gpg-agent[7576] no running SCdaemon - starting it
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- OK GNU Privacy Guard's Smartcard server ready
2015-06-28 23:07:15 gpg-agent[7576] DBG: first connection to SCdaemon established
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C -> GETINFO socket_name
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- D F:\Users\bozho\.gnupg\S.scdaemon
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- OK
2015-06-28 23:07:15 gpg-agent[7576] DBG: additional connections at 'F:\Users\bozho\.gnupg\S.scdaemon'
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C -> OPTION event-signal=110
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- OK
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C -> GETATTR $AUTHKEYID
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- ERR 100663404 Card error <SCD>
2015-06-28 23:07:15 gpg-agent[7576] no authentication key for ssh on card: Card error
2015-06-28 23:07:15 gpg-agent[7576] ssh request handler for request_identities (11) ready
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C -> RESTART
2015-06-28 23:07:15 gpg-agent[7576] DBG: chan_0000016C <- OK
2015-06-28 23:07:26 gpg-agent[7576] DBG: ssh map file 'PageantRequest00002418'
2015-06-28 23:07:26 gpg-agent[7576] DBG: ssh map handle 0x00000140
2015-06-28 23:07:26 gpg-agent[7576] DBG:           my sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:07:26 gpg-agent[7576] DBG: ssh map file sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:07:26 gpg-agent[7576] DBG: ssh IPC buffer at 0x025c0000
2015-06-28 23:07:26 gpg-agent[7576] ssh request handler for sign_request (13) started
2015-06-28 23:07:26 gpg-agent[7576] DBG: agent_get_cache '3F8FFAB15E8B51DF57F1274CEDEE8E8FF3D77E5A' (mode 4) ...
2015-06-28 23:07:26 gpg-agent[7576] DBG: ... miss
2015-06-28 23:07:26 gpg-agent[7576] starting a new PIN Entry
2015-06-28 23:07:26 gpg-agent[7576] DBG: connection to PIN entry established
2015-06-28 23:12:29 gpg-agent[7576] DBG: ssh map file 'PageantRequest00001eac'
2015-06-28 23:12:29 gpg-agent[7576] DBG: ssh map handle 0x00000188
2015-06-28 23:12:29 gpg-agent[7576] DBG:           my sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:12:29 gpg-agent[7576] DBG: ssh map file sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:12:29 gpg-agent[7576] DBG: ssh IPC buffer at 0x025d0000
2015-06-28 23:12:29 gpg-agent[7576] ssh request handler for request_identities (11) started
2015-06-28 23:12:29 gpg-agent[7576] new connection to SCdaemon established (reusing)
2015-06-28 23:12:29 gpg-agent[7576] DBG: chan_0000016C -> GETATTR $AUTHKEYID
2015-06-28 23:12:29 gpg-agent[7576] DBG: chan_0000016C <- ERR 100663404 Card error <SCD>
2015-06-28 23:12:29 gpg-agent[7576] no authentication key for ssh on card: Card error
2015-06-28 23:12:29 gpg-agent[7576] ssh request handler for request_identities (11) ready
2015-06-28 23:12:29 gpg-agent[7576] DBG: chan_0000016C -> RESTART
2015-06-28 23:12:29 gpg-agent[7576] DBG: chan_0000016C <- OK
2015-06-28 23:12:40 gpg-agent[7576] DBG: ssh map file 'PageantRequest00001eac'
2015-06-28 23:12:40 gpg-agent[7576] DBG: ssh map handle 0x00000188
2015-06-28 23:12:40 gpg-agent[7576] DBG:           my sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:12:40 gpg-agent[7576] DBG: ssh map file sid: 'S-1-5-21-1972494145-3003797530-3302421020-1000'
2015-06-28 23:12:40 gpg-agent[7576] DBG: ssh IPC buffer at 0x025d0000
2015-06-28 23:12:40 gpg-agent[7576] ssh request handler for sign_request (13) started
2015-06-28 23:12:40 gpg-agent[7576] DBG: agent_get_cache '3F8FFAB15E8B51DF57F1274CEDEE8E8FF3D77E5A' (mode 4) ...
2015-06-28 23:12:40 gpg-agent[7576] DBG: ... miss
2015-06-28 23:12:48 gpg-agent[7576] DBG: agent_put_cache '3F8FFAB15E8B51DF57F1274CEDEE8E8FF3D77E5A' (mode 4) requested ttl=0
2015-06-28 23:12:48 gpg-agent[7576] ssh request handler for sign_request (13) ready
-------------- next part --------------

<000001> 004D0794 S WM_COPYDATA hwndFrom:(null) pcds:028CFE84
<000002> 004D0794 R WM_COPYDATA fProcessed:True
<000003> 004D0794 S WM_COPYDATA hwndFrom:(null) pcds:028CFE84
<000004> 004D0794 R WM_COPYDATA fProcessed:False
<000005> 004D0794 S WM_COPYDATA hwndFrom:(null) pcds:028CFE84
<000006> 004D0794 R WM_COPYDATA fProcessed:True
<000007> 004D0794 S WM_COPYDATA hwndFrom:(null) pcds:028CFE84
<000008> 004D0794 R WM_COPYDATA fProcessed:True