Bug 373374

Summary: Test failures with gnupg-2.1.16
Product: [Unmaintained] trojita Reporter: Jan Kundrát <jkt>
Component: CryptographyAssignee: Trojita default assignee <trojita-bugs>
Status: RESOLVED UPSTREAM    
Severity: normal CC: projects.rg
Priority: NOR    
Version: git   
Target Milestone: ---   
Platform: Other   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:

Description Jan Kundrát 2016-12-07 00:24:14 UTC 
Continuing from https://bugzilla.redhat.com/show_bug.cgi?id=1401716 . It seems that signature verification of our internal supposed-to-be-valid signature doesn't conclude for some reason. Debug patch:

diff --git a/tests/Cryptography/test_Cryptography_PGP.cpp b/tests/Cryptography/test_Cryptography_PGP.cpp
index 2d33a4d..bd9628c 100644
--- a/tests/Cryptography/test_Cryptography_PGP.cpp
+++ b/tests/Cryptography/test_Cryptography_PGP.cpp
@@ -110,6 +110,8 @@ void CryptographyPGPTest::testDecryption()
     }
     // allow for event processing, so that the model can retrieve the results
     QCoreApplication::processEvents();
+    // ensure that we're done now
+    QVERIFY(!data.data(Imap::Mailbox::RolePartCryptoNotFinishedYet).toBool());
 
     if (!qcaErrorSpy.isEmpty() && successful) {
         qDebug() << "Unexpected failure in crypto";


jkt@kolibrik ~/work/prog/_trojita-build/qt5 $ ninja && ctest -R test_Cryptography_PGP -VV
[53/53] Linking CXX executable test_Cryptography_PGP
UpdateCTestConfiguration  from :/home/jkt/work/prog/_trojita-build/qt5/DartConfiguration.tcl
UpdateCTestConfiguration  from :/home/jkt/work/prog/_trojita-build/qt5/DartConfiguration.tcl
Test project /home/jkt/work/prog/_trojita-build/qt5
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 24
    Start 24: test_Cryptography_PGP

24: Test command: /home/jkt/work/prog/_trojita-build/qt5/test_Cryptography_PGP
24: Environment variables: 
24:  UBSAN_OPTIONS=suppressions=/home/jkt/work/prog/trojita/tests/ubsan.supp
24: Test timeout computed to be: 9.99988e+06
24: ********* Start testing of CryptographyPGPTest *********
24: Config: Using QtTest library 5.7.1, Qt 5.7.1 (x86_64-little_endian-lp64 shared (dynamic) release build; by GCC 4.9.3)
24: PASS   : CryptographyPGPTest::initTestCase()
24: FAIL!  : CryptographyPGPTest::testDecryption(valid) '!data.data(Imap::Mailbox::RolePartCryptoNotFinishedYet).toBool()' returned FALSE. ()
24:    Loc: [/home/jkt/work/prog/trojita/tests/Cryptography/test_Cryptography_PGP.cpp(114)]
24: QDEBUG : CryptographyPGPTest::testDecryption(valid) We have 1 orphaned crypto tasks
24: PASS   : CryptographyPGPTest::testDecryption(invalid)
24: FAIL!  : CryptographyPGPTest::testDecryption(expiredKey) '!data.data(Imap::Mailbox::RolePartCryptoNotFinishedYet).toBool()' returned FALSE. ()
24:    Loc: [/home/jkt/work/prog/trojita/tests/Cryptography/test_Cryptography_PGP.cpp(114)]
24: QDEBUG : CryptographyPGPTest::testDecryption(expiredKey) We have 1 orphaned crypto tasks
24: PASS   : CryptographyPGPTest::testDecryption(unknownKey)
24: PASS   : CryptographyPGPTest::testDecryptWithoutEnvelope()
24: PASS   : CryptographyPGPTest::testVerification(valid-me)
24: PASS   : CryptographyPGPTest::testVerification(my-signature-different-identity)
24: PASS   : CryptographyPGPTest::testVerification(my-signature-different-data)
24: PASS   : CryptographyPGPTest::testVerification(invalid-implicit-content-type)
24: PASS   : CryptographyPGPTest::testMalformed(signed-missing-protocol-micalg)
24: PASS   : CryptographyPGPTest::testMalformed(signed-ml-stripped-gpg-signature)
24: PASS   : CryptographyPGPTest::testOffline(signed)
24: PASS   : CryptographyPGPTest::testOffline(encrypted)
24: PASS   : CryptographyPGPTest::cleanupTestCase()
24: Totals: 13 passed, 2 failed, 0 skipped, 0 blacklisted, 21125ms
24: ********* Finished testing of CryptographyPGPTest *********
1/1 Test #24: test_Cryptography_PGP ............***Failed   21.14 sec

0% tests passed, 1 tests failed out of 1

Total Test time (real) =  21.14 sec

The following tests FAILED:
         24 - test_Cryptography_PGP (Failed)
Errors while running CTest
Comment 1 Jan Kundrát 2016-12-07 00:39:32 UTC 
OK, it seems that for those tests where validation should actually succeed,  GnuPG::Context::decryptAndVerify never returns. Here's what remains running in the system after these failures (two test rows actually happen):

jkt@kolibrik ~/work/prog/_trojita-build/qt5 $ ps -ef | grep gnupg
jkt      11066  3509  0 01:37 pts/5    00:00:00 grep --colour=auto gnupg
jkt@kolibrik ~/work/prog/_trojita-build/qt5 $ ps -ef | grep gpg
jkt       8492     1  0 01:15 ?        00:00:00 gpg-agent --homedir /home/jkt/work/prog/_trojita-build/qt5/keys --use-standard-socket --daemon
jkt      11017     1  0 01:37 pts/5    00:00:00 gpg2 --enable-special-filenames --batch --no-sk-comments --status-fd 7 --no-tty --charset utf8 --enable-progress-filter --exit-on-status-write-error --display :0 --decrypt --output - -- -&10
jkt      11023     1  0 01:37 pts/5    00:00:00 gpg2 --enable-special-filenames --batch --no-sk-comments --status-fd 9 --no-tty --charset utf8 --enable-progress-filter --exit-on-status-write-error --display :0 --decrypt --output - -- -&12
jkt      11074  3509  0 01:37 pts/5    00:00:00 grep --colour=auto gpg
jkt@kolibrik ~/work/prog/_trojita-build/qt5 $ lsof -p 8492
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
      Output information may be incomplete.
COMMAND    PID USER   FD      TYPE             DEVICE SIZE/OFF      NODE NAME
gpg-agent 8492  jkt  cwd       DIR              254,0      248        96 /
gpg-agent 8492  jkt  rtd       DIR              254,0      248        96 /
gpg-agent 8492  jkt  txt       REG              254,0   414360 274454906 /usr/bin/gpg-agent
gpg-agent 8492  jkt  mem       REG              254,0  1738328 410388282 /lib64/libc-2.22.so
gpg-agent 8492  jkt  mem       REG              254,0   105272 410395864 /lib64/libpthread-2.22.so
gpg-agent 8492  jkt  mem       REG              254,0    18248 269514259 /usr/lib64/libnpth.so.0.0.5
gpg-agent 8492  jkt  mem       REG              254,0    88112    931164 /usr/lib64/libassuan.so.0.7.3
gpg-agent 8492  jkt  mem       REG              254,0    92128 134752584 /usr/lib64/libgpg-error.so.0.19.1
gpg-agent 8492  jkt  mem       REG              254,0  1166304 268688873 /usr/lib64/libgcrypt.so.20.1.3
gpg-agent 8492  jkt  mem       REG              254,0   148816 410388248 /lib64/ld-2.22.so
gpg-agent 8492  jkt  mem       REG              254,0  1745248 268688934 /usr/lib64/locale/locale-archive
gpg-agent 8492  jkt    0r      CHR                1,3      0t0      2051 /dev/null
gpg-agent 8492  jkt    1w      CHR                1,3      0t0      2051 /dev/null
gpg-agent 8492  jkt    2w      CHR                1,3      0t0      2051 /dev/null
gpg-agent 8492  jkt    3u     unix 0xffff88d6b3479800      0t0    429639 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent type=STREAM
gpg-agent 8492  jkt    4u     unix 0xffff88d6b3479c00      0t0    429640 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent.extra type=STREAM
gpg-agent 8492  jkt    5u     unix 0xffff88d6b3479400      0t0    429641 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent.browser type=STREAM
gpg-agent 8492  jkt    6u     unix 0xffff88d6b347a000      0t0    429642 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent.ssh type=STREAM
gpg-agent 8492  jkt    7r  a_inode               0,11        0      8449 inotify
gpg-agent 8492  jkt    8u     unix 0xffff88d503b3e000      0t0    429648 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent type=STREAM
gpg-agent 8492  jkt    9r      CHR                1,9      0t0      2056 /dev/urandom
gpg-agent 8492  jkt   10u     unix 0xffff88d9a0edf400      0t0    427933 /home/jkt/work/prog/_trojita-build/qt5/keys/S.gpg-agent type=STREAM
jkt@kolibrik ~/work/prog/_trojita-build/qt5 $ lsof -p 11017
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
      Output information may be incomplete.
COMMAND   PID USER   FD   TYPE             DEVICE SIZE/OFF      NODE NAME
gpg2    11017  jkt  cwd    DIR              254,0    20480 174033037 /home/jkt/work/prog/_trojita-build/qt5
gpg2    11017  jkt  rtd    DIR              254,0      248        96 /
gpg2    11017  jkt  txt    REG              254,0   991856 274761284 /usr/bin/gpg2
gpg2    11017  jkt  mem    REG              254,0   244416 402758332 /lib64/libtinfo.so.6.0
gpg2    11017  jkt  mem    REG              254,0  1738328 410388282 /lib64/libc-2.22.so
gpg2    11017  jkt  mem    REG              254,0    88112    931164 /usr/lib64/libassuan.so.0.7.3
gpg2    11017  jkt  mem    REG              254,0   330624 135078460 /lib64/libreadline.so.6.3
gpg2    11017  jkt  mem    REG              254,0    92128 134752584 /usr/lib64/libgpg-error.so.0.19.1
gpg2    11017  jkt  mem    REG              254,0  1166304 268688873 /usr/lib64/libgcrypt.so.20.1.3
gpg2    11017  jkt  mem    REG              254,0    70520 402976937 /lib64/libbz2.so.1.0.6
gpg2    11017  jkt  mem    REG              254,0    96256 269070520 /lib64/libz.so.1.2.8
gpg2    11017  jkt  mem    REG              254,0   148816 410388248 /lib64/ld-2.22.so
gpg2    11017  jkt  mem    REG              254,0  1745248 268688934 /usr/lib64/locale/locale-archive
gpg2    11017  jkt    0u   CHR                1,3      0t0      2051 /dev/null
gpg2    11017  jkt    1w  FIFO               0,10      0t0    441011 pipe
gpg2    11017  jkt    2u   CHR                1,3      0t0      2051 /dev/null
gpg2    11017  jkt    3r   REG              254,0     3492 274761272 /home/jkt/work/prog/_trojita-build/qt5/keys/pubring.kbx
gpg2    11017  jkt    4u  unix 0xffff88d88f8ef800      0t0    442481 type=STREAM
gpg2    11017  jkt    7w  FIFO               0,10      0t0    441010 pipe
Comment 2 Jan Kundrát 2016-12-07 01:29:46 UTC 
I'm having lots of fun so far.

I did some debugging and it seems to me that my gpg-agent started deadlocking:

(gdb) t a a bt

Thread 3 (Thread 0x7fcaaffff700 (LWP 23673)):
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007fcab5369f65 in __GI___pthread_mutex_lock (mutex=0x7fcab5ecbd08 <pool_lock+8>) at ../nptl/pthread_mutex_lock.c:81
#2  0x0000000000000080 in ?? ()
#3  0x00007fcaa8003aa0 in ?? ()
#4  0x00007fcab60e6a20 in ?? ()
#5  0x00007fcaafffeaf0 in ?? ()
#6  0x00007fcab5c87b7a in _gcry_mpi_randomize (w=0x80, nbits=<optimized out>, level=<optimized out>)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/mpi/mpiutil.c:655
#7  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7fcab4fb3700 (LWP 23657)):
#0  0x00007fcab536fb8b in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, futex_word=0x7fcab5782080 <sceptre_buffer>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  do_futex_wait (sem=sem@entry=0x7fcab5782080 <sceptre_buffer>, abstime=0x0) at sem_waitcommon.c:111
#2  0x00007fcab536fc5c in __new_sem_wait_slow (sem=0x7fcab5782080 <sceptre_buffer>, abstime=0x0) at sem_waitcommon.c:181
#3  0x00007fcab536fd0e in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
#4  0x00007fcab557fdc1 in leave_npth () at /var/tmp/portage/dev-libs/npth-1.2/work/npth-1.2/src/npth.c:134
#5  0x00007fcab558061c in npth_usleep (usec=<optimized out>) at /var/tmp/portage/dev-libs/npth-1.2/work/npth-1.2/src/npth.c:497
#6  0x00007fcab5c7e302 in _gcry_rndlinux_gather_random (add=0x7fcab5c794e0 <add_randomness>, origin=RANDOM_ORIGIN_SLOWPOLL, length=90, level=<optimized out>)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/rndlinux.c:205
#7  0x00007fcab5c79092 in read_random_source (origin=origin@entry=RANDOM_ORIGIN_SLOWPOLL, length=length@entry=120, level=level@entry=1)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random-csprng.c:1275
#8  0x00007fcab5c7a184 in random_poll () at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random-csprng.c:1101
#9  read_pool (level=0, length=<optimized out>, buffer=0x7fcab5ecc6a4 <nonce_buffer+20> "")
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random-csprng.c:995
#10 _gcry_rngcsprng_randomize (buffer=<optimized out>, length=<optimized out>, level=GCRY_WEAK_RANDOM)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random-csprng.c:538
#11 0x00007fcab5c78efb in _gcry_randomize (level=GCRY_WEAK_RANDOM, length=8, buffer=0x7fcab5ecc6a4 <nonce_buffer+20>)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random.c:341
#12 _gcry_create_nonce (buffer=buffer@entry=0x7fcab60e6228, length=length@entry=128)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/random/random.c:466
#13 0x00007fcab5c87b7a in _gcry_mpi_randomize (w=w@entry=0x7fcab0003ab0, nbits=nbits@entry=1024, level=level@entry=GCRY_WEAK_RANDOM)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/mpi/mpiutil.c:655
#14 0x00007fcab5c49e2d in secret_blinded (output=0x7fcab0003a90, input=0x7fcab0001d70, sk=0x7fcab4fb2b90, nbits=1024)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/cipher/rsa.c:1067
#15 0x00007fcab5c4a6d5 in rsa_decrypt (r_plain=0x7fcab4fb2d08, s_data=<optimized out>, keyparms=0x7fcab0003880)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/cipher/rsa.c:1365
#16 0x00007fcab5bd451f in _gcry_pk_decrypt (r_plain=r_plain@entry=0x7fcab4fb2d08, s_data=s_data@entry=0x7fcab00030f0, s_skey=s_skey@entry=0x7fcab00031a0)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/cipher/pubkey.c:377
#17 0x00007fcab5bbe0d6 in gcry_pk_decrypt (result=result@entry=0x7fcab4fb2d08, data=0x7fcab00030f0, skey=0x7fcab00031a0)
    at /var/tmp/portage/dev-libs/libgcrypt-1.7.3/work/libgcrypt-1.7.3/src/visibility.c:985
#18 0x000055e5d82880e9 in agent_pkdecrypt (ctrl=ctrl@entry=0x55e5d89c7d60, desc_text=<optimized out>, ciphertext=0x7fcab0001ed0 "(7:enc-val(3:rsa(1:a129:", 
    ciphertextlen=156, outbuf=outbuf@entry=0x7fcab4fb2d90, r_padding=r_padding@entry=0x7fcab4fb2d7c) at pkdecrypt.c:109
#19 0x000055e5d8278412 in cmd_pkdecrypt (ctx=0x7fcab00008f0, line=<optimized out>) at command.c:849
#20 0x00007fcab578c60d in dispatch_command (ctx=0x7fcab00008f0, line=<optimized out>, linelen=<optimized out>) at assuan-handler.c:675
#21 0x00007fcab578ca7f in process_request (ctx=0x7fcab00008f0) at assuan-handler.c:871
#22 assuan_process (ctx=0x7fcab00008f0) at assuan-handler.c:894
#23 0x000055e5d827b31b in start_command_handler (ctrl=0x55e5d89c7d60, listen_fd=<optimized out>, fd=<optimized out>) at command.c:3304
#24 0x000055e5d82730b9 in do_start_connection_thread (ctrl=0x55e5d89c7d60) at gpg-agent.c:2601
#25 0x00007fcab557febf in thread_start (startup_arg=<optimized out>) at /var/tmp/portage/dev-libs/npth-1.2/work/npth-1.2/src/npth.c:265
#26 0x00007fcab536764c in start_thread (arg=0x7fcab4fb3700) at pthread_create.c:334
#27 0x00007fcab50a9b5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 1 (Thread 0x7fcab60bf700 (LWP 23656)):
#0  0x00007fcab536fb8b in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, futex_word=0x7fcab5782080 <sceptre_buffer>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  do_futex_wait (sem=sem@entry=0x7fcab5782080 <sceptre_buffer>, abstime=0x0) at sem_waitcommon.c:111
#2  0x00007fcab536fc5c in __new_sem_wait_slow (sem=0x7fcab5782080 <sceptre_buffer>, abstime=0x0) at sem_waitcommon.c:181
#3  0x00007fcab536fd0e in __new_sem_wait (sem=<optimized out>) at sem_wait.c:29
#4  0x00007fcab557fdc1 in leave_npth () at /var/tmp/portage/dev-libs/npth-1.2/work/npth-1.2/src/npth.c:134
#5  0x00007fcab5580934 in npth_pselect (nfd=<optimized out>, rfds=0x7ffcf969a020, wfds=0x0, efds=0x0, timeout=0x7ffcf9699e40, sigmask=0x7fcab5782180 <sigev_unblock>)
    at /var/tmp/portage/dev-libs/npth-1.2/work/npth-1.2/src/npth.c:630
#6  0x000055e5d8274995 in handle_connections (listen_fd=<optimized out>, listen_fd_extra=<optimized out>, listen_fd_browser=<optimized out>, 
    listen_fd_ssh=<optimized out>) at gpg-agent.c:2848
#7  0x000055e5d8271415 in main (argc=0, argv=0x7ffcf969a440) at gpg-agent.c:1705


...so I noticed that I can update dev-libs/npth from 1.2 to 1.3, but the test was still failing (after making sure that I kill all GnuPG Leftovers in between attempts). I noticed that it doesn't appear to deadlock, though, so I increased the timeout for gpg-agent to do its job form 10s to 20s, went back to npth 1.2, and boom, it started working. However, it takes aaaaaaages (12s for that tets on my system).

If the gpg-agent remains running in between attempts, the subsequent runs succeed much faster.

Working hypothesis: maybe gpg-agent now needs some extra time for its first-time init?
Comment 3 Raphael Groner 2016-12-07 21:47:43 UTC 
The proposed patches in https://bugzilla.redhat.com/show_bug.cgi?id=1401716 let the test pass again for Fedora Rawhide.
Comment 4 Jan Kundrát 2016-12-21 11:30:05 UTC 
Git commit 60ad50c873679fb23f52eee6b4df6832889b1098 by Jan Kundrát.
Committed on 07/12/2016 at 12:05.
Pushed by gerrit into branch 'master'.

tests: GPG: Explicitly check that the crypto ops have finished

This is meant to improve the readability of the error messages during
eventual test failures.

Also unify the form of the check that we use among all of these tests.
Consistency is good.

Change-Id: I638607c0742a295cf29b61a1434d313e7618dc8a
Bug: https://bugzilla.redhat.com/show_bug.cgi?id=1401716

M  +4    -2    tests/Cryptography/test_Cryptography_PGP.cpp

https://commits.kde.org/trojita/60ad50c873679fb23f52eee6b4df6832889b1098
Comment 5 Jan Kundrát 2017-06-08 08:09:12 UTC 
This appears to work as of Gentoo's gnupg-2.1.20-r1.