Page MenuHome GnuPG
Create Task
Maniphest T4069

GpgSM, Dirmngr communication on Windows sometimes very slow
Closed, ResolvedPublic
Actions

Description

Sometimes when verifying S/MIME Mails a user (where I gave remote support) had the problem that it was very slow ~7 seconds. It appeared to be random. Sometimes it was fast as usual (~1s) even for the same mail but sometimes it was very slow.

From the GPGSM log I can see that dirmngr was very slow to respond. Taking 2 seconds for stuff like GETINFO Version. I don't really have an explanation why the dirmngr was busy. After activating logging and restarting the dirmngr the problem went away :-/

2018-07-11 10:33:46 gpgsm[4084] DBG:      serial: 008933CD7D
2018-07-11 10:33:46 gpgsm[4084] DBG:   notBefore: 2015-01-06 07:29:37
2018-07-11 10:33:46 gpgsm[4084] DBG:    notAfter: 2021-01-06 23:59:59
2018-07-11 10:33:46 gpgsm[4084] DBG:      issuer: CN=PCA-1-Verwaltung-14,O=PKI-1-Verwaltung,C=DE
2018-07-11 10:33:46 gpgsm[4084] DBG:     subject: CN=CA IVBB Deutsche Telekom AG 15,OU=Bund,O=PKI-1-Verwaltung,C=DE
2018-07-11 10:33:46 gpgsm[4084] DBG:   hash algo: 1.2.840.113549.1.1.11
2018-07-11 10:33:46 gpgsm[4084] DBG:   SHA1 Fingerprint: CD:DC:E1:F4:99:D4:32:1A:88:51:5B:31:63:08:F7:DB:9A:0D:81:3B
2018-07-11 10:33:46 gpgsm[4084] DBG: END Certificate
2018-07-11 10:33:46 gpgsm[4084] DBG: signature value: 28 37 3A 73 69 67 2D 76 61 6C 28 33 3A 72 73 61 28 31 3A 73 32 35 36 3A 9A FE 36 03 FC 67 2C DE EB 19 72 6E 34 B2 76 BC DF 25 C0 8A 9E 51 EF BB 9F 80 11 06 D2 47 68 B5 0C 86 19 CF BE A6 7D 43 BD 8A 82 C4 69 ED 64 14 B8 8B BF 47 CF C8 20 3F F1 54 57 CB 11 A6 91 4D AF EE E0 F3 78 BC 5E 42 F4 5D 9D 3B 13 AD B3 52 CD B0 B3 8D 96 03 AF 3A 19 B3 79 6C B1 79 AE 18 BC A3 C5 1B FE D9 37 0A A2 B3 18 0F 27 43 D5 D5 2E 7B 66 86 19 0D 4F EF B6 4C 1C 76 14 A3 41 8F E4 0A 9C D8 F9 34 FB 8D 06 B4 EA B0 76 90 61 B3 02 45 C1 8E DD 0F 6D 09 8C D3 2B A8 ED 2A 95 65 B5 BF 23 C1 AE 72 D2 EE E8 08 70 74 08 01 0E E4 AB C9 FA DE 2F 9E E0 44 EB 09 78 12 C7 D8 0C 5D 81 EB B0 AC 11 44 E9 90 DB B5 8C 2D 09 0B B2 B9 95 BF 2E E6 EC 5C 77 76 5D 02 51 18 DC A3 D8 DB CA 35 2F 23 F9 98 5F B8 AB CD 88 A0 82 96 5E 2F F2 C8 9A E9 0E 45 C8 AB A7 4A 23 54 81 AA B5 FC 29 29 28 34 3A 68 61 73 68 36 3A 73 68 61 32 35 36 29 29
2018-07-11 10:33:46 gpgsm[4084] DBG: encoded hash: 00 01 FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF 00 30 31 30 0D 06 09 60 86 48 01 65 03 04 02 01 05 00 04 20 4D F2 83 35 5B 9A C5 2C 02 9A A2 9B 40 59 FB 4C D0 0C 42 CC 1D B8 23 B0 A8 4E 19 F9 03 B5 DD 5D
2018-07-11 10:33:46 gpgsm[4084] DBG: gcry_pk_verify: Erfolg
2018-07-11 10:33:46 gpgsm[4084] DBG: chan_0x0000010c <- # Home: C:\Users\user\AppData\Roaming\gnupg
2018-07-11 10:33:47 gpgsm[4084] DBG: chan_0x0000010c <- # Config: C:\Users\user\AppData\Roaming\gnupg\dirmngr.conf
2018-07-11 10:33:47 gpgsm[4084] DBG: chan_0x0000010c <- OK Dirmngr 2.2.8 at your service
2018-07-11 10:33:47 gpgsm[4084] DBG: connection to the dirmngr established
2018-07-11 10:33:47 gpgsm[4084] DBG: chan_0x0000010c -> GETINFO version
2018-07-11 10:33:49 gpgsm[4084] DBG: chan_0x0000010c <- D 2.2.8
2018-07-11 10:33:49 gpgsm[4084] DBG: chan_0x0000010c <- OK
2018-07-11 10:33:49 gpgsm[4084] DBG: chan_0x0000010c -> OPTION audit-events=1
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c <- OK
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c -> LDAPSERVER x500.bund.de:0:::
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c <- OK
2018-07-11 10:33:51 gpgsm[4084] asking dirmngr about 7B:3F:A6:07:A2:45:99:0A:A8:01:5E:5F:86:46:89:5D:21:6E:EA:4B
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c -> ISVALID F9263E101470F70206718F7A0B84213A8534F450.5610881A4C95
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c <- INQUIRE ISTRUSTED D64FBEAE2CD1616FD701C77F7A204F60F77E08A4
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x000000fc -> ISTRUSTED D64FBEAE2CD1616FD701C77F7A204F60F77E08A4
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x000000fc <- OK
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c -> D 1
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c -> END
2018-07-11 10:33:51 gpgsm[4084] DBG: chan_0x0000010c <- OK
2018-07-11 10:33:51 gpgsm[4084] response of dirmngr: okay

Details

Version
2.2.8

Related Objects
Search...

Event Timeline

• aheinecke created this task.Jul 11 2018, 11:31 AM
• werner added a subscriber: • werner.Jul 11 2018, 8:27 PM

I have logging to a socket always enabled. That may explain why I don't see that error on Unix.

• werner added a comment.Jul 12 2018, 9:36 AM

it is not due to windows but due to the use of NTBTLS. I have the same problem here... and found it: We call es_fflush to let ntbtls flush its internal buffers but libgpg-error's estream module does no propagate this explicit flush to the cookie functions of ntbtls. Thus ntbtls gets stuck most of the time. I am not sure when this regression happened but it is pretty obvious.

Fix is in libgpg-error.

• werner added a comment.Jul 12 2018, 9:37 AM

Commit rEbd5bcd2dd19ef0b1c3d33a3a388b537ba08a4eb6

• aheinecke closed this task as Resolved.Jul 18 2018, 8:33 AM
• aheinecke claimed this task.

I got feedback from the user that had the problem. It's fixed with 2.2.9 which contains your commit afaik.

Thanks!

• aheinecke added a subtask: T4029: Gpg4win 3.1.3.Jul 18 2018, 8:34 AM
• aheinecke closed subtask T4029: Gpg4win 3.1.3 as Resolved.Sep 4 2018, 9:24 AM