You are not logged in.

Pages: 1

#1 2016-12-16 02:39:16

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

[Solved] gpg2 delay on first invocation.

I've noticed a significant delay when using gpg2 in conjunction with mutt recently. After typing in my password it hangs for more than ten seconds before it starts downloading the email headers. I haven't changed any settings for gpg - is anyone else experiencing this problem?

I call it from my .muttrc with the following line:

source "gpg2 -dq $HOME/.my-pwds.gpg |"

~S

Last edited by Steinberg2010 (2017-01-06 01:58:28)

Offline

#2 2016-12-16 04:05:38

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Yes, a couple of us have experienced this over the last several weeks.

I have been attempting to isolate the issue. It would be helpful to know the various versions of software you are running: gnupg, pinentry, keychain/envoy/etc (if applicable).

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#3 2016-12-16 05:53:52

mpan
Member
Registered: 2012-08-01
Posts: 1,334
Website

Re: [Solved] gpg2 delay on first invocation.

I had a similar problem around october, but GnuPG was always hanging for some time when invoking pinentry. Stracing provided no hints, there was no increased load — it seemed like gpg-agent was just doing nothing, blocked on something. An update of GnuPG and the kernel arrived at approximately same time for me, and after this the issue disappeared, so I have assumed that it was a reported and already fixed bug.

I may be a bit off with the date, could be the end of september. Looking at my pacman logs, I found that:

[2016-08-25 00:12] [ALPM] upgraded gnupg (2.1.14-1 -> 2.1.15-1)
[2016-08-25 00:13] [ALPM] upgraded linux (4.7-1 -> 4.7.1-1)

Since I’m certain that the disappearance of the problem coincided with update of both gnupg and linux, this may be some hint when searching for the offender.

Three other candidates in my logs are:

[2016-07-18 17:01] [ALPM] upgraded gnupg (2.1.13-1 -> 2.1.14-1)
[2016-07-18 17:01] [ALPM] upgraded linux (4.6.3-1 -> 4.6.4-1)
…
[2016-11-19 02:35] [ALPM] upgraded gnupg (2.1.15-1 -> 2.1.15-2)
[2016-11-19 02:36] [ALPM] upgraded linux (4.8.6-1 -> 4.8.8-2)
…
[2016-11-25 22:19] [ALPM] upgraded linux (4.8.8-2 -> 4.8.10-1)
[2016-11-28 13:39] [ALPM] upgraded gnupg (2.1.15-2 -> 2.1.16-1)

But the first one seems too early, the later two — to late.

Hope that helps somehow.

---edit

One more note: the bug was reproducible with the GTK2 pinentry. I was testing with the Curses and TTY version too, but — unfortunately — I don’t remember the result anymore; but the GTK2 backend was certainly exhibiting the issue.

Last edited by mpan (2016-12-16 06:00:58)

Sometimes I seem a bit harsh — don’t get offended too easily!

Offline

#4 2016-12-16 06:23:09

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Yeah, pinentry-* makes no difference.

I have [testing] enabled and have experienced it for several iterations of the vanilla kernel and my own (currently 4.9.0). Similarly, downgrading gnupg or pinentry seems to have no impact. I have swapped out my config with working boxes, changed shells, removed keychain, tried using gpg-agent, started it from .zprofile and as a systemd --user service. All to no avail. As mpan notes, stracing provides no difference between a working and a hanging setup.

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#5 2016-12-16 12:40:41

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

jasonwryan wrote:

Yes, a couple of us have experienced this over the last several weeks.

I have been attempting to isolate the issue. It would be helpful to know the various versions of software you are running: gnupg, pinentry, keychain/envoy/etc (if applicable).

gpg: 2.1.6
pinentry: 1.0.0
kernel: 4.8.13-1

I update fairly regularly so I'm guessing these are probably the latest releases in the repos.
Also I use the pinentry-curses client. I found GTK to be a little jarring when working from a terminal.

Sorry to hear that it's taken up so much time/energy!

~S

Offline

#6 2016-12-16 12:58:17

ayekat
Member
Registered: 2011-01-17
Posts: 1,611

Re: [Solved] gpg2 delay on first invocation.

I'm running the LTS kernel, and I've also noticed this delay during the last couple of weeks - so either it's unrelated to the kernel... or it's a kernel-update that's been backported (presumably some security upgrade).

gnupg-2.1.6-2
pinentry-1.0.0-1
linux-lts-4.4.38-1
haveged-1.9.1-2

--edit--
From a strace, it seems to wait for entropy. This is what I get after entering my passphrase:

Passphrase: 
"S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34
read(6, "S PROGRESS need_entropy X 30 120"..., 1002) = 33
read(6, "S PROGRESS need_entropy X 120 12"..., 1002) = 34

It outputs roughly ten lines per seconds, so in the end I'm waiting quite some seconds. I'm wondering why GnuPG would require entropy to decrypt something. Is this a security mechanism to keep sensible data from popping up at insecure locations in the RAM?

--edit2--

Add haveged version.

Last edited by ayekat (2016-12-22 08:41:09)

pkgs │ hacks │ cfg │ blag

Offline

#7 2016-12-17 14:57:51

ratcheer
Member
Registered: 2011-10-09
Posts: 912

Re: [Solved] gpg2 delay on first invocation.

I run haveged for entropy. I have heard that the next major kernel (4.9) will have much improved entropy gathering facitity.

Tim

Offline

#8 2016-12-17 22:46:17

mpan
Member
Registered: 2012-08-01
Posts: 1,334
Website

Re: [Solved] gpg2 delay on first invocation.

In my case strace was telling nothing about entropy.

Currently, with the following versions, I experience no problems:

linux 4.8.13-1
gnupg 2.1.16-2
pinentry 1.0.0-1

I’ve tried to drain /dev/random for a test and still noticed no delays.

However, if entropy pool is the problem, a question arises: what operation are we referring to? I’ve assume we’re talking about using a key (signing, verifying, …), but messages about entropy suggest that it’s something different.

Sometimes I seem a bit harsh — don’t get offended too easily!

Offline

#9 2016-12-22 08:31:37

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

I don't think it is entropy. With the same packages as mpan on two different machines, one works without issue, the other hangs. On the hanging machine I installed haveged, and it made no difference. I straced it, and see no lines about entropy, either with or without haveged.

Stumped. I have asked in #gnupg, and will update if that leads anywhere.

#edit: out of desperation, I completely removed ~/.gnupg and imported my key to see if starting from scratch made any difference. None. The IRC query proved fruitless as well... sad

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#10 2016-12-23 07:47:54

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Downgrading gnupg to 2.1.15-2 is the last working version. Comparing straces reveals no immediate candidate.

# edit: I was wrong (again). I ran it in debug mode and got the same entropy messages that ayekat reported (with haveged running).

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#11 2016-12-24 03:52:44

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Ugh, this is bullshit.

┌─[Centurion ~: «SSH»]
└─╼ cat /proc/sys/kernel/random/entropy_avail
3783

Keyring is unlocked immediately.

┌─[Shiv ~]
└─╼ cat /proc/sys/kernel/random/entropy_avail 
4094

(With rngd running and watermark set to 4096) still hangs for ~15 seconds.

So debug message indicates that there is insufficient entropy, but the pool is clearly sufficient on other machines...

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#12 2016-12-24 15:54:05

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

This is beyond my level of expertise.

[nicolas@archtp:~]→ cat /proc/sys/kernel/random/entropy_avail
3891

This is what I get.

~S

Offline

#13 2016-12-27 07:43:48

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

The dev (Werner) seems unconcerned: https://bugs.debian.org/cgi-bin/bugrepo … bug=847552

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#14 2016-12-27 13:21:02

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

The weird thing is that the original poster of that thread explicitly has no problem with the curses client. I exclusively use the curses client with mutt and I get the same problem.

~S

Offline

#15 2016-12-29 00:24:53

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Bug report: https://bugs.gnupg.org/gnupg/issue2897

...and rather droll assessment by Ted Ts'o: http://public-inbox.org/git/20161228160 … 6983a1af29

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#16 2016-12-30 17:58:16

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

This patch works around the issue until libgcrypt 1.8 is released:

--- a/agent/gpg-agent.c	2016-12-30 21:32:19.539737442 +1300
+++ b/agent/gpg-agent.c	2016-12-30 21:33:39.757081588 +1300
@@ -1763,7 +1763,7 @@
    * more entropy.  This way other threads have chance to run.  */
 #if GCRYPT_VERSION_NUMBER < 0x010800 /* 1.8.0 */
   if (what && !strcmp (what, "need_entropy"))
-    npth_usleep (100000); /* 100ms */
+    npth_usleep (1000); /* 1ms */
 #endif
 }

Thanks to stribika on U&L

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#17 2016-12-31 19:35:41

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

Thanks - I'll give this a go and see what happens!

~S

Offline

#18 2017-01-06 01:02:52

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

Steinberg2010 wrote:

Thanks - I'll give this a go and see what happens!

~S

Okay the rabbit hole opens further:

This is my first time using ABS so I'm a little green at this...

I copied the files from 

/var/abs/core/gnupg/

to 

~/abs/gnupg/

I enter the directory and run 

makepkg -o

I get the following output:

==> Validating source files with sha1sums...
    gnupg-2.1.17.tar.bz2 ... Passed
    gnupg-2.1.17.tar.bz2.sig ... Skipped
    libdns.patch ... Passed
==> Verifying source file signatures with gpg...
    gnupg-2.1.17.tar.bz2 ... FAILED (unknown public key 2071B08A33BD3F06)
==> ERROR: One or more PGP signatures could not be verified!
[nicolas@archtp:~/abs/gnupg]→

Not sure what I did wrong? I haven't modified anything yet...

~S

Offline

#19 2017-01-06 01:24:40

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Update your keyring: `pacman -Sy archlinux-keyring && pacman -Syyu`.

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#20 2017-01-06 01:27:01

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

jasonwryan wrote:

Update your keyring: `pacman -Sy archlinux-keyring && pacman -Syyu`.

Did that yesterday. Do you think it is related to this? https://bbs.archlinux.org/viewtopic.php … 6#p1188316

Offline

#21 2017-01-06 01:32:17

Scimmia
Fellow
Registered: 2012-09-01
Posts: 12,093

Re: [Solved] gpg2 delay on first invocation.

https://wiki.archlinux.org/index.php/Ma … e_checking

Online

#22 2017-01-06 01:41:09

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

Thanks all - particularly to JWR above for providing the solution and introducing me to the ABS wormhole.

Marking this solved...

Scimmia wrote:

Thanks!

~S

Last edited by Steinberg2010 (2017-01-06 01:57:59)

Offline

#23 2017-01-24 06:55:35

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 30,424
Website

Re: [Solved] gpg2 delay on first invocation.

Fixed upstream \o/
https://git.gnupg.org/cgi-bin/gitweb.cg … 0a05ac90d4

Arch + dwm   •   Mercurial repos  •   Surfraw

Registered Linux User #482438

Offline

#24 2017-01-24 13:13:28

Steinberg2010
Member
Registered: 2016-01-28
Posts: 73

Re: [Solved] gpg2 delay on first invocation.

Great - thanks once again for all your help with this.

All best

~S

Offline

Pages: 1

Board footer

Powered by FluxBB