{"thread":{"id":"44779","subject":"[RFH] gpg --import entropy while running tests","startedAt":"2016-12-28T07:29:56Z","lastAt":"2016-12-28T17:21:32Z","messageCount":4,"participants":["Jeff King","Theodore Ts'o"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"308438","messageId":"20161228072303.4wbhkwf37fvgpi7h@sigill.intra.peff.net","threadId":"44779","inReplyTo":null,"subject":"[RFH] gpg --import entropy while running tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-12-28T07:23:03Z","receivedAt":"2016-12-28T07:29:56Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"I noticed a few of our test scripts taking a long time to run, even\nthough they used to be quick. Here's one:\n\n  $ time ./t7612-merge-verify-signatures.sh \n  ok 1 - create signed commits\n  ok 2 - merge unsigned commit with verification\n  ok 3 - merge commit with bad signature with verification\n  ok 4 - merge commit with untrusted signature with verification\n  ok 5 - merge signed commit with verification\n  ok 6 - merge commit with bad signature without verification\n  # passed all 6 test(s)\n  1..6\n\n  real    0m12.285s\n  user    0m0.048s\n  sys     0m0.044s\n\n\nThat's a lot of time not using any CPU. What's going on? Running with\n\"sh -x\" shows that we spend most of the time in this line from\nlib-gpg.sh:\n\n  gpg --homedir \"${GNUPGHOME}\" 2>/dev/null --import \\\n\t  \"$TEST_DIRECTORY\"/lib-gpg/keyring.gpg\n\nAnd running gpg with \"--debug-level guru\" shows that we are blocking\nwhile waiting for entropy. Has anybody else seen this? I feel like I\nnoticed it starting a few weeks ago, and indeed dropping back to gpg\n2.0.26 (from 2.1.17) makes the problem go away.\n\nIs it a bug in gpg (oddly, the kernel reports lots of entropy available,\nand generating the signatures themselves is quite fast)? Or is the new\nversion doing something special in the import process that we need to\nwork around or disable?\n\nThe reason we use --import at all is to handle differences in the .gnupg\nformat between versions 1 and 2. So the nuclear option would be to just\ncarry pre-made .gnupg directories for _both_ versions in our test suite,\nand pick the appropriate one based on the output of \"gpg --version\".\nThat feels like a hack, but it gives us a lot of control.\n\nI'd love it if we could figure out a way of making --import reliably\nfast, though.\n\n-Peff\n"},{"id":"308441","messageId":"20161228080230.wygcmdmwvifcthvl@sigill.intra.peff.net","threadId":"44779","inReplyTo":"20161228072303.4wbhkwf37fvgpi7h@sigill.intra.peff.net","subject":"Re: [RFH] gpg --import entropy while running tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-12-28T08:02:30Z","receivedAt":"2016-12-28T08:02:40Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Dec 28, 2016 at 02:23:03AM -0500, Jeff King wrote:\n\n> That's a lot of time not using any CPU. What's going on? Running with\n> \"sh -x\" shows that we spend most of the time in this line from\n> lib-gpg.sh:\n> \n>   gpg --homedir \"${GNUPGHOME}\" 2>/dev/null --import \\\n> \t  \"$TEST_DIRECTORY\"/lib-gpg/keyring.gpg\n> \n> And running gpg with \"--debug-level guru\" shows that we are blocking\n> while waiting for entropy. Has anybody else seen this? I feel like I\n> noticed it starting a few weeks ago, and indeed dropping back to gpg\n> 2.0.26 (from 2.1.17) makes the problem go away.\n> \n> Is it a bug in gpg (oddly, the kernel reports lots of entropy available,\n> and generating the signatures themselves is quite fast)? Or is the new\n> version doing something special in the import process that we need to\n> work around or disable?\n\nAnswering my own question (somewhat): this is bisectable in the gnupg\nrepository, and it turns out to be caused by their 4473db1ef (agent:\nKludge to mitigate blocking calls in Libgcrypt., 2016-11-11), which\nintroduces a 100ms sleep (yuck) that is presumably triggering way more\nthan it needs to. More details at:\n\n  https://git.gnupg.org/cgi-bin/gitweb.cgi?p=gnupg.git;a=commit;h=4473db1ef24031ff4e26c9a9de95dbe898ed2b97\n\nSo this does seem like a gpg bug.\n\n-Peff\n"},{"id":"308443","messageId":"20161228083930.5li6cb6yplusc26m@sigill.intra.peff.net","threadId":"44779","inReplyTo":"20161228080230.wygcmdmwvifcthvl@sigill.intra.peff.net","subject":"Re: [RFH] gpg --import entropy while running tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-12-28T08:39:30Z","receivedAt":"2016-12-28T08:39:38Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Dec 28, 2016 at 03:02:30AM -0500, Jeff King wrote:\n\n> > Is it a bug in gpg (oddly, the kernel reports lots of entropy available,\n> > and generating the signatures themselves is quite fast)? Or is the new\n> > version doing something special in the import process that we need to\n> > work around or disable?\n> \n> Answering my own question (somewhat): this is bisectable in the gnupg\n> repository, and it turns out to be caused by their 4473db1ef (agent:\n> Kludge to mitigate blocking calls in Libgcrypt., 2016-11-11), which\n> introduces a 100ms sleep (yuck) that is presumably triggering way more\n> than it needs to. More details at:\n> \n>   https://git.gnupg.org/cgi-bin/gitweb.cgi?p=gnupg.git;a=commit;h=4473db1ef24031ff4e26c9a9de95dbe898ed2b97\n> \n> So this does seem like a gpg bug.\n\nI've submitted a bug report to gpg:\n\n  https://bugs.gnupg.org/gnupg/issue2897\n\nso we'll see what they say.\n\n-Peff\n"},{"id":"308452","messageId":"20161228160520.dsybuqljzkzsik2d@thunk.org","threadId":"44779","inReplyTo":"20161228083930.5li6cb6yplusc26m@sigill.intra.peff.net","subject":"Re: [RFH] gpg --import entropy while running tests","fromName":"Theodore Ts'o","fromEmail":"tytso@mit.edu","sentAt":"2016-12-28T16:05:21Z","receivedAt":"2016-12-28T17:21:32Z","isPatch":false,"sender":{"key":"tytso@mit.edu","avatar":"https://avatars.githubusercontent.com/u/51416?v=4"},"body":"On Wed, Dec 28, 2016 at 03:39:30AM -0500, Jeff King wrote:\n> >   https://git.gnupg.org/cgi-bin/gitweb.cgi?p=gnupg.git;a=commit;h=4473db1ef24031ff4e26c9a9de95dbe898ed2b97\n> > \n> > So this does seem like a gpg bug.\n> \n> I've submitted a bug report to gpg:\n> \n>   https://bugs.gnupg.org/gnupg/issue2897\n> \n> so we'll see what they say.\n\nYeah, they are definitely doing something very.... hard to explain.\n\nPid 8348 is the gpg-agent process which the main gpg program (pid\n8344) connected to.  It starts trying to get randomness in response to\na KEYWRAP command:\n\n8348  10:58:57.882909 access(\"/dev/random\", R_OK) = 0\n8348  10:58:57.883205 access(\"/dev/urandom\", R_OK) = 0\n8348  10:58:57.883472 open(\"/dev/urandom\", O_RDONLY) = 9\n8348  10:58:57.883729 fcntl(9, F_GETFD) = 0\n8348  10:58:57.883914 fcntl(9, F_SETFD, FD_CLOEXEC) = 0\n\nIt opens /dev/urandom, but then never uses fd 9 ever again.  Instead,\nit uses getrandom, but in a pretty silly fashion, with lots of sleeps\nin between, and not between each progress report, either:\n\n8348  10:58:57.884129 write(8, \"S PROGRESS need_entropy X 30 120\", 32 <unfinished ...>\n8344  10:58:57.884338 <... read resumed> \"S PROGRESS need_entropy X 30 120\", 1002) = 32\n8348  10:58:57.884424 <... write resumed> ) = 32\n8344  10:58:57.884488 read(5,  <unfinished ...>\n8348  10:58:57.884550 write(8, \"\\n\", 1 <unfinished ...>\n8344  10:58:57.884715 <... read resumed> \"\\n\", 970) = 1\n8348  10:58:57.884800 <... write resumed> ) = 1\n8344  10:58:57.884883 read(5,  <unfinished ...>\n8348  10:58:57.884951 nanosleep({0, 100000000}, NULL) = 0\n8348  10:58:57.985363 select(10, [9], NULL, NULL, {0, 100000}) = 1 (in [9], left {0, 99994})\n8348  10:58:57.985593 getrandom(\"&\\275\\354^\\256\\320\\3w\\21:R]`eJ\\t\\t\\350\\245\\202>\\255\\237\\324\\324\\340\\24^c\\323\\210\\376\"..., 90, 0) = 90\n8348  10:58:57.985751 write(8, \"S PROGRESS need_entropy X 120 12\"..., 33) = 33\n8344  10:58:57.985885 <... read resumed> \"S PROGRESS need_entropy X 120 12\"..., 1002) = 33\n8348  10:58:57.985934 write(8, \"\\n\", 1 <unfinished ...>\n8344  10:58:57.985982 read(5,  <unfinished ...>\n8348  10:58:57.986015 <... write resumed> ) = 1\n8344  10:58:57.986048 <... read resumed> \"\\n\", 969) = 1\n8348  10:58:57.986090 nanosleep({0, 100000000},  <unfinished ...>\n8344  10:58:57.986142 read(5,  <unfinished ...>\n8348  10:58:58.086253 <... nanosleep resumed> NULL) = 0\n8348  10:58:58.086370 write(8, \"S PROGRESS need_entropy X 30 120\", 32) = 32\n8344  10:58:58.086502 <... read resumed> \"S PROGRESS need_entropy X 30 120\", 1002) = 32\n8348  10:58:58.086541 write(8, \"\\n\", 1 <unfinished ...>\n8344  10:58:58.086579 read(5,  <unfinished ...>\n8348  10:58:58.086604 <... write resumed> ) = 1\n8344  10:58:58.086630 <... read resumed> \"\\n\", 970) = 1\n8348  10:58:58.086661 nanosleep({0, 100000000},  <unfinished ...>\n8344  10:58:58.086703 read(5,  <unfinished ...>\n8348  10:58:58.186815 <... nanosleep resumed> NULL) = 0\n8348  10:58:58.186894 select(10, [9], NULL, NULL, {0, 100000}) = 1 (in [9], left {0, 99995})\n8348  10:58:58.187038 getrandom(\"\\365\\221\\374m\\360\\235\\27\\330\\264\\223\\365\\363<6\\302\\324F\\5\\354Q|,\\366\\253\\337u\\226\\265\\345\\250CA\"..., 90, 0) = 90\n\nThe worst part of this is that the commit description claims this is a\nworkaround for libgcrypt using /dev/random, but it's not using\n/dev/random --- it's using getrandom, and it pointlessly opened\n/dev/urandom first (having never opened /dev/random).\n\nThis looks like a classic case of Lotus Notes / Websphere disease ---\nto many d*mned layers of abstraction....\n\n\t\t\t\t\t\t- Ted\n"}]}