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
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
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?
The proposed patches in https://bugzilla.redhat.com/show_bug.cgi?id=1401716 let the test pass again for Fedora Rawhide.
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
This appears to work as of Gentoo's gnupg-2.1.20-r1.