Key creation problem with 2.1.16

[Carola Grunwald]

Hi Daniel,

on Tue, 06 Dec 2016 11:51:58 -0500, you wrote:

>Hi Carola--
>
>On Tue 2016-12-06 07:41:20 -0500, Carola Grunwald wrote:
>> I'v attached my application's complete log of the 'gpg.exe' program call
>> including the command line string ('Application' + ' ' + 'ExeStr') with
>> the 'Environment' parameter(s) set.
>
>ok, but it felt a bit like "burying the lede" in your attachments --
>it's a lot easier to understand what's going on if you describe it
>clearly at the top of your message.
>
>that may be one of the reasons it took nearly a week for anyone to
>respond to your message.
>
>now let's see if we can solve this!
>
>> It's not necessarily a problem with the GenKey code but may rather point
>> to an unreliable gpg - agent IPC, which, as gpg starts a new agent
>> instance minutes after processing begins to fail, would also explain the
>> many orphaned gpg-agent.exe entries in my Task Manager's Processes list.
>
>it would be great to see some logs for the gpg-agent processes -- if
>they're dying or becoming zombiefied, what were they doing when that
>happened?

I think that's what my 2nd example below is about.

>
>if the IPC is flakey, where is it failing?
>
>the main difference between your two logs seems to be that the agent in
>the failed case is actually asking gpg for a passphrase, whereas it
>*wasn't* asking gpg for a passphrase in the successful case.
>
>what would cause the agent to behave differently like that, given that
>it had already done INQUIRE NEWPASSWD ?  do you think the agent died and
>a new agent started up, which hadn't cached the previous password?


In fact I experience at least two different kinds of failure. Both are
sporadic, not systematic errors. As I tried to provide a similar
starting situation for each of these command calls I'm surprised at the
varying outcome.



There's the key creation failure, which I decided to show first, as I
thought it might be easier to follow.

Windows 7 in a VirtualBox VM. I start with an empty pub keyring and an
empty 'private-keys-v1.d' folder, no pgp-agent.exe process running. With
a fifty-fifty chance the --gen-key command unpredictably fails producing
always exactly the same log which I added to my earlier mail, returning
code 2. Key creation usually succeeds, as a valid .key and .rev file are
written to disk, but the fingerprint ('[GNUPG:] KEY_CREATED ...') isn't
returned. With this problem the agent stays alive. Follow-up commands
are processed correctly.



And there's a probably different problem with a likely broken IPC, where
I get 259/$103 in return for the current and all following commands
until another agent instance appears in the Task Manager after about 2
minutes.

After a similar decryption command, which succeeds returning $0 I get:
| ================================================================================
| Started    : 2016-12-07 15:08:12.482
| Application: 'gpg\gpg.exe'
| Command    : '--pinentry-mode loopback --display-charset utf-8 --utf8-strings --no-mangle-dos-filenames --debug-level guru --debug-all --no-auto-key-locate --lock-once --no-encrypt-to --textmode --allow-weak-digest-algos --no-default-recipient --trust-model always --ignore-time-conflict --homedir "G:\mob\Mail\MyGnuPG\gpg" --no-default-keyring --keyring "G:\mob\Mail\MyGnuPG\key\nym.kbx" --keyring "G:\mob\Mail\MyGnuPG\key\srv.kbx" --no-emit-version --no-comments --status-fd 2'
| Parameters : '--decrypt --command-fd 0 --try-all-secrets --passphrase "ppppppppppppppppppppppppppppppppppppppppppp" --output "G:\mob\Mail\MyGnuPG\gpg\tmp\txt_clr.675" "G:\mob\Mail\MyGnuPG\gpg\tmp\txt_enc.675"'
| Environment: 'GNUPGHOME=G:\mob\Mail\MyGnuPG\gpg'
| Input      : 'y
| '
| ExeStr (659 bytes):
| '--pinentry-mode loopback --display-charset utf-8 --utf8-strings --no-mangle-dos-filenames --debug-level guru --debug-all --no-auto-key-locate --lock-once --no-encrypt-to --textmode --allow-weak-digest-algos --no-default-recipient --trust-model always --ignore-time-conflict --homedir "G:\mob\Mail\MyGnuPG\gpg" --no-default-keyring --keyring "G:\mob\Mail\MyGnuPG\key\nym.kbx" --keyring "G:\mob\Mail\MyGnuPG\key\srv.kbx" --no-emit-version --no-comments --status-fd 2 --decrypt --command-fd 0 --try-all-secrets --passphrase "ppppppppppppppppppppppppppppppppppppppppppp" --output "G:\mob\Mail\MyGnuPG\gpg\tmp\txt_clr.675" "G:\mob\Mail\MyGnuPG\gpg\tmp\txt_enc.675"'
| Timeout    : 30000
| ErrVal: 259 / $103
| Error: -------------------------------------------------------------------------
| gpg: Note: no default option file 'G:/mob/Mail/MyGnuPG/gpg/gpg.conf'
| gpg: enabled debug flags: packet mpi crypto filter iobuf memory cache memstat trust hashing cardio ipc clock lookup extprog
| gpg: DBG: [not enabled in the source] start
| gpg: DBG: fd_cache_open (G:\mob\Mail\MyGnuPG\gpg\tmp\txt_enc.675) not cached
| gpg: DBG: iobuf-1.0: open 'G:\mob\Mail\MyGnuPG\gpg\tmp\txt_enc.675' desc=file_filter(fd) fd=144
| gpg: DBG: iobuf-1.0: underflow: buffer size: 8192; still buffered: 0 => space for 8192 bytes
| gpg: DBG: iobuf-1.0: underflow: A->FILTER (8192 bytes)
| gpg: DBG: iobuf-1.0: A->FILTER() returned rc=0 (ok), read 8192 bytes
| gpg: DBG: armor-filter: control: 5
| gpg: DBG: iobuf-1.1: push 'armor_filter'
| gpg: DBG: armor-filter: control: 5
| gpg: DBG: iobuf chain: 1.1 'armor_filter' filter_eof=0 start=0 len=0
| gpg: DBG: iobuf chain: 1.0 'file_filter(fd)' filter_eof=0 start=0 len=8192
| gpg: DBG: armor-filter: control: 1
| gpg: DBG: iobuf-1.1: underflow: buffer size: 8192; still buffered: 0 => space for 8192 bytes
| gpg: DBG: iobuf-1.1: underflow: A->FILTER (8192 bytes)
| gpg: DBG: armor-filter: control: 3
| gpg: DBG: iobuf-1.0: underflow: buffer size: 8192; still buffered: 0 => space for 8192 bytes
| gpg: DBG: iobuf-1.0: underflow: A->FILTER (8192 bytes)
| gpg: DBG: iobuf-1.0: A->FILTER() returned rc=0 (ok), read 1410 bytes
| gpg: DBG: iobuf-1.1: A->FILTER() returned rc=0 (ok), read 6921 bytes
| gpg: DBG: parse_packet(iob=1): type=1 length=524 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/mainproc.c.1339)
| [GNUPG:] ENC_TO 4444444444444444 1 0
| gpg: DBG: [not enabled in the source] get_session_key enter
| gpg: DBG: [not enabled in the source] keydb_new
| gpg: DBG: [not enabled in the source] keydb_search enter
| gpg: DBG: keydb_search: 1 search descriptions:
| gpg: DBG: keydb_search   0: FIRST
| gpg: DBG: keydb_search: searching keybox (resource 0 of 2)
| gpg: DBG: keydb_search: searched keybox (resource 0 of 2) => Success
| gpg: DBG: [not enabled in the source] keydb_search leave (found)
| gpg: DBG: [not enabled in the source] keydb_get_keybock enter
| gpg: DBG: parse_packet(iob=2): type=6 length=418 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/keydb.c.1177)
| gpg: DBG: parse_packet(iob=2): type=13 length=40 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/keydb.c.1177)
| gpg: DBG: parse_packet(iob=2): type=2 length=90 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/keydb.c.1177)
| gpg: DBG: parse_packet(iob=2): type=14 length=525 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/keydb.c.1177)
| gpg: DBG: parse_packet(iob=2): type=2 length=73 (parse./home/wk/b-w32/speedo/PLAY-release/gnupg-w32-2.1.16/g10/keydb.c.1177)
| gpg: DBG: iobuf-2.0: underflow: buffer size: 1158; still buffered: 0 => space for 1158 bytes
| gpg: DBG: iobuf-2.0: close '?'
| 
| --------------------------------------------------------------------------------
| Finished   : 2016-12-07 15:08:42.872
| ================================================================================

Here command processing sometimes stops instead of continuing with (the
first two lines repeated) ...

| gpg: DBG: iobuf-2.0: underflow: buffer size: 1158; still buffered: 0 => space for 1158 bytes
| gpg: DBG: iobuf-2.0: close '?'
| gpg: DBG: [not enabled in the source] keydb_get_keyblock leave
| gpg: DBG: chan_0x0000009c <- OK Pleased to meet you
| gpg: DBG: connection to agent established
| gpg: DBG: chan_0x0000009c -> RESET
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: chan_0x0000009c -> GETINFO version
| gpg: DBG: chan_0x0000009c <- D 2.1.16
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: chan_0x0000009c -> OPTION allow-pinentry-notify
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: chan_0x0000009c -> OPTION agent-awareness=2.1.0
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: chan_0x0000009c -> OPTION pinentry-mode=loopback
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: get_keygrip for public key
| gpg: DBG: keygrip= 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11 11
| gpg: DBG: get_keygrip for public key
| gpg: DBG: keygrip= 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22 22
| gpg: DBG: chan_0x0000009c -> HAVEKEY 1111111111111111111111111111111111111111 2222222222222222222222222222222222222222
| gpg: DBG: chan_0x0000009c <- OK
| gpg: DBG: finish_lookup: checking key 33333333 (all)(req_usage=0)
| gpg: DBG: 	using key 33333333
| [GNUPG:] KEY_CONSIDERED 3333333333333333333333333333333333333333 0
...



I'd like to provide further information. So is there a chance to get an
even more verbose processing log. Please tell me what to do.

Kind regards

Caro