Page MenuHome GnuPG
Create Task
Maniphest T4978

On Windows 10, gpg-connect-agent needs 2 trials to launch gpg-agent
Closed, ResolvedPublic
Actions

Description

I try to launch the gpg-agent demon by

gpg-connect-agent --verbose /bye

Config file gpg-agent.conf contains enable-putty-support

I get this on my first attempt:

gpg-connect-agent: Kein aktiver gpg-agent - "C:\Program Files (x86)\GnuPG\bin\gpg-agent.exe" wird gestartet
gpg-connect-agent: Warte bis der agent bereit ist ... (5s)
gpg-connect-agent: Warte bis der agent bereit ist ... (4s)
gpg-connect-agent: Warte bis der agent bereit ist ... (3s)
gpg-connect-agent: Warte bis der agent bereit ist ... (2s)
gpg-connect-agent: Warte bis der agent bereit ist ... (1s)
gpg-connect-agent: can't connect to the agent: IPC "connect" Aufruf fehlgeschlagen
gpg-connect-agent: Fehler beim Senden der Standardoptionen: Agent läuft nicht

Result: gpg-agent.exe not running. If, however, I immedialtely repeat the the very same above command, I get this:

gpg-connect-agent: Kein aktiver gpg-agent - "C:\Program Files (x86)\GnuPG\bin\gpg-agent.exe" wird gestartet
gpg-connect-agent: Warte bis der agent bereit ist ... (5s)
gpg-connect-agent: Verbindung zum agent aufgebaut

Result: gpg-agent.exe is running and works afterwards as expected (SSH login with putty possible).

Shouldn't gpg-connect-agent launch the agent on first try?

This is on Windows 10-1909.
Same result for gpg (GnuPG) 2.2.19 and gpg (GnuPG) 2.2.20.

PROCESSOR_ARCHITECTURE=AMD64
PROCESSOR_IDENTIFIER=AMD64 Family 23 Model 113 Stepping 0, AuthenticAMD
PROCESSOR_LEVEL=23
PROCESSOR_REVISION=7100

KB4489899 is not installed. Therefore, bug T4427 does not apply.

Details

Version
GnuPG 2.2.19 and GnuPG 2.2.20

Related Objects

Event Timeline

BeginnersMind created this task.Jun 22 2020, 2:23 PM
• werner added a subscriber: • werner.Jun 22 2020, 3:18 PM

The 5 second timeout is to give the agent time to get ready and accept connections. I can't say with this infor why it takes longer at your site. Can you please try without putty support?

szszszsz-nitrokey added a subscriber: szszszsz-nitrokey.Jun 22 2020, 4:27 PM
BeginnersMind added a comment.Jun 22 2020, 5:07 PM
In T4978#135418, @werner wrote:

The 5 second timeout is to give the agent time to get ready and accept connections.

This always seemed already evident to me.

I can't say with this infor why it takes longer at your site.

This is the enigma. On second trial it always works quickly!

Can you please try without putty support?

I moved gpg-agent.conf which contains the option enable-putty-support out of c:\Users\MyName\AppData\Roaming\gnupg\
Then I rebooted 3 times and always executed gpg-connect-agent --verbose /bye afterwards. In one case, the agent came up on first attempt. In two cases, the agent started only the second time.

I saw earlier that in rare cases the agent is launched immediately. In the majority of cases, the agent won't come up at the first try. But the second try is always successful. So it looks as if the startup problem ist not caused by the putty support.

Are there any debug options which I could use?

• werner added a comment.Jun 22 2020, 10:19 PM

You may start the gpg-agent by hand:

gpg-agent -v --daemon  --log-file \temp\gpg-agent.log

This is what gpg-connect-agent does but it gives you a chance to see diagnostics from the agent.

gpgconf --kill gpg-agent

kills the current agent and you can checkout the log file.

BeginnersMind added a comment.Jun 23 2020, 5:18 PM

These are very nice commands which I had overlooked. My results:

# Open commandline window A, enter command:
> set LANG=en
> gpg-agent -v --daemon --log-file \temp\gpg-agent.log

2020-06-23 10:50:57 gpg-agent[14832] listening on socket 'C:\Users\Manfred\AppData\Roaming\gnupg\S.gpg-agent'
2020-06-23 10:50:57 gpg-agent[14832] listening on socket 'C:\Users\Manfred\AppData\Roaming\gnupg\S.gpg-agent.extra'
2020-06-23 10:50:57 gpg-agent[14832] listening on socket 'C:\Users\Manfred\AppData\Roaming\gnupg\S.gpg-agent.browser'
2020-06-23 10:50:57 gpg-agent[14832] listening on socket 'C:\Users\Manfred\AppData\Roaming\gnupg\S.gpg-agent.ssh'
2020-06-23 10:50:57 gpg-agent[14832] gpg-agent (GnuPG) 2.2.20 started
2020-06-23 10:50:57 gpg-agent[14832] putty message loop thread started

# Process gpg-agent.exe is running, Commandline window A blocked
# Now once a minute a handler is started and terminated:

2020-06-23 10:52:01 gpg-agent[14832] handler 0x4 for fd 648 started
2020-06-23 10:52:01 gpg-agent[14832] handler 0x4 for fd 648 terminated
2020-06-23 10:53:01 gpg-agent[14832] handler 0x4 for fd 752 started
2020-06-23 10:53:01 gpg-agent[14832] handler 0x4 for fd 752 terminated
# etc.

# Enter the Nitrokey, open putty and start SSH login:

2020-06-23 10:54:59 gpg-agent[14832] ssh request handler for request_identities (11) started
2020-06-23 10:54:59 gpg-agent[14832] no running SCdaemon - starting it
2020-06-23 10:54:59 gpg-agent[14832] DBG: first connection to SCdaemon established
2020-06-23 10:55:01 gpg-agent[14832] SIGUSR2 received - updating card event counter
2020-06-23 10:55:01 gpg-agent[14832] ssh request handler for request_identities (11) ready
2020-06-23 10:55:01 gpg-agent[14832] ssh request handler for sign_request (13) started
2020-06-23 10:55:01 gpg-agent[14832] new connection to SCdaemon established (reusing)
2020-06-23 10:55:01 gpg-agent[14832] DBG: detected card with S/N D1234567890123456789012345A12345
2020-06-23 10:55:01 gpg-agent[14832] starting a new PIN Entry
2020-06-23 10:55:02 gpg-agent[14832] handler 0x4 for fd 648 started
2020-06-23 10:55:02 gpg-agent[14832] handler 0x4 for fd 648 terminated
2020-06-23 10:55:11 gpg-agent[14832] ssh request handler for sign_request (13) ready

# SSH login successful

2020-06-23 10:56:02 gpg-agent[14832] handler 0x4 for fd 848 started
2020-06-23 10:56:02 gpg-agent[14832] handler 0x4 for fd 848 terminated
2020-06-23 10:57:02 gpg-agent[14832] handler 0x4 for fd 776 started
2020-06-23 10:57:02 gpg-agent[14832] handler 0x4 for fd 776 terminated

# Open putty once more and connect to another server

2020-06-23 10:57:26 gpg-agent[14832] ssh request handler for request_identities (11) started
2020-06-23 10:57:26 gpg-agent[14832] new connection to SCdaemon established (reusing)
2020-06-23 10:57:26 gpg-agent[14832] ssh request handler for request_identities (11) ready
2020-06-23 10:57:27 gpg-agent[14832] ssh request handler for sign_request (13) started
2020-06-23 10:57:27 gpg-agent[14832] new connection to SCdaemon established (reusing)
2020-06-23 10:57:27 gpg-agent[14832] DBG: detected card with S/N D1234567890123456789012345A12345
2020-06-23 10:57:29 gpg-agent[14832] ssh request handler for sign_request (13) ready

# 2nd SSH login successful

# Open another commandline window B and enter:
> gpgconf --kill gpg-agent

# gpg-agent.exe killed, commandline window A returns to prompt

This all looks very good. Then I rebooted several times. The gpg-agent did always start up immediately. I also performed several successful SSH logins.

Then I again tried the other start-up method. Guess what, I was no longer able to reproduce the initial hang. This is very enigmatic since before the initial hang was very stable, so stable that I wrote a script to investigate it.

There must have been something which disturbed the communication between gpg-connect-agent and gpg-agent. Perhaps something was patched away?

So I assume that it may not be possible to identify the cause of this effect.

BeginnersMind added a comment.Jun 23 2020, 5:28 PM

While the initial agent hang problem might be rare, it nevertheless does make sense to have a workaround for this in any case. Especially since it may not be possible to patch this effect away. The commands given by Werner provide this workaround nicely if gpg-connect-agent hangs.

I had already another scripting workaround which simply tried a second launch if the first one failed. This, however, has the drawback that one has to wait for the time out.

Here comes the workaround as a Python script. It solves the problem that the used direct agent launch method blocks a command line window: The created gpg-agent subprocess is detached from the window.

#========================================================================
# Tested under Windows 10 with Python 3.8.3 (June 23, 2020).
#========================================================================
import os, subprocess
#========================================================================
# This standard windows shell command gives returncode 0 if TASK runs:
# tasklist /fi "imagename eq TASK" 2>NUL | find /I /N "TASK">NUL
#========================================================================
def is_task_running(taskname: str, output=False) -> bool:
  command = 'tasklist /fi "imagename eq ' + taskname + \
            '" 2>NUL | find /I /N "' + taskname + '">NUL'
  it_runs = os.system(command) == 0
  if output:
    print('task', taskname, 'is running:', it_runs)
  return it_runs
  
#========================================================================  
# Begin main script
#========================================================================
if is_task_running('gpg-agent.exe'):
  print('gpg-agent already running, killing...')
  os.system('gpgconf --kill gpg-agent')
  is_task_running('gpg-agent.exe', True)
else:
  print('gpg-agent not running...')
  
#------------------------------------------------------------------------
# Create a subprocess with gpg-agent running and detach it.
# Version with logfile:
# ['gpg-agent.exe', '-v', '--daemon', '--log-file', '/temp/gpg-agent.log']
#------------------------------------------------------------------------
print('starting gpg-agent...')
subprocess.Popen(
  ['gpg-agent.exe', '--daemon'], \
  creationflags=subprocess.DETACHED_PROCESS | \
  subprocess.CREATE_NEW_PROCESS_GROUP | \
  subprocess.CREATE_BREAKAWAY_FROM_JOB)

if not is_task_running('gpg-agent.exe'):
  print('...failed')
  os.system('pause')
• aheinecke closed this task as Resolved.Aug 6 2020, 4:04 PM
• aheinecke claimed this task.
• aheinecke added a subscriber: • aheinecke.

Thanks for providing your workaround.

I guess this can be marked as resolved? Maybe not in the best way but it was still in "Needs Triage - Open" State.

BeginnersMind added a comment.Aug 6 2020, 6:07 PM

I don't mind if this is marked as resolved. As long as I use my script, the agent works flawlessly with my Nitrokey. The agent startup is very fast. The script also resolves the effect that the agent won't work after the system is waked from sleeping state.