I agree, these are problems we should address, they might be the symptoms of a
race somewhere. I bet they are in GnuPG though.

This is a GnuPG problem:

teythoon@europa ~/repos/g10/gpgme/obj/tests (git)-[master] % rm $GNUPGHOME/tofu.db && ( gpg2 --verify --with-
colons --status-fd=1 /tmp/testmsg )2>/dev/null | grep TOFU_STATS
[GNUPG:] TOFU_STATS 1 0 0 auto
[GNUPG:] TOFU_STATS_LONG Verified 0 messages signed by "Alfa Test (demo key) <alfa@example.net>".
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 1 0 0 none
teythoon@europa ~/repos/g10/gpgme/obj/tests (git)-[master] % rm $GNUPGHOME/tofu.db && ( gpg2 --verify --with-
colons --status-fd=1 /tmp/testmsg && gpg2 --verify --with-colons --status-fd=1 /tmp/testmsg && sleep 1 && gpg2 -
-verify --with-colons --status-fd=1 /tmp/testmsg )2>/dev/null | grep TOFU_STATS
[GNUPG:] TOFU_STATS 1 0 0 auto
[GNUPG:] TOFU_STATS_LONG Verified 0 messages signed by "Alfa Test (demo key) <alfa@example.net>".
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 2 1 0 auto 1 1
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alfa Test (demo key) <alfa@example.net>"%0Ain the past
1~second.
[GNUPG:] TOFU_STATS 2 1 0 auto 1 1
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alpha Test (demo key) <alpha@example.net>"%0Ain the past
1~second.
[GNUPG:] TOFU_STATS 2 1 0 auto 1 1
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alice (demo key)"%0Ain the past 1~second.

Ok, I pushed a fix related to this problem 45bb9a2a, this had the amusing effect of
reversing the behavior:

% rm -f $GNUPGHOME/tofu.db ; ( g10/gpg --verify --status-fd=1 /tmp/testmsg
)2>/dev/null | grep TOFU_STATS
[GNUPG:] TOFU_STATS 1 0 0 none
[GNUPG:] TOFU_STATS 2 1 0 auto 0 0
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alpha Test (demo key)
<alpha@example.net>"%0Ain the past 0~seconds.
[GNUPG:] TOFU_STATS 2 1 0 auto 0 0
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alice (demo key)"%0Ain the
past 0~seconds.

The difference stems from tofu_register setting already_verified to 0 for the first
uid, and to 1 for the second. In the former case, show_statistics is asked to ignore
the current message.

I guess the intention was to handle the very first message differently, but now we
are handling the first *uid* upon receiving the first message differently instead.
I'm not sure how to proceed, hence reassigning to Neal.

I believe that this bug has been fixed. Both Andre's and Justus' test cases now
emit the same information for all user ids (see below).

If you agree that this issue is resolved, please change the status appropriately.

us@grit:~/neal/work/gpg/build/gpgme/tests/gpg$ rm -f $GNUPGHOME/tofu.db && ( gpg
--verify --with-colons --status-fd=1 /tmp/testmsg )2>/dev/null
[GNUPG:] NEWSIG
[GNUPG:] KEY_CONSIDERED A0FF4590BB6122EDEF6E3C542D727CC768697734 0
[GNUPG:] SIG_ID QfzOUKyR2prNsVx/GI/4A5q2AxU 2002-03-03 1015172412
[GNUPG:] KEY_CONSIDERED A0FF4590BB6122EDEF6E3C542D727CC768697734 0
[GNUPG:] GOODSIG 2D727CC768697734 Alfa Test (demo key) <alfa@example.net>
[GNUPG:] VALIDSIG A0FF4590BB6122EDEF6E3C542D727CC768697734 2002-03-03 1015172412
0 4 0 17 2 00 A0FF4590BB6122EDEF6E3C542D727CC768697734
[GNUPG:] KEY_CONSIDERED A0FF4590BB6122EDEF6E3C542D727CC768697734 0
[GNUPG:] TOFU_USER A0FF4590BB6122EDEF6E3C542D727CC768697734 alfa@example.net
[GNUPG:] TOFU_STATS 2 1 0 auto 1472727595 1472727595
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alfa Test (demo key)
<alfa@example.net>"%0Ain the past 0~seconds.
[GNUPG:] TOFU_USER A0FF4590BB6122EDEF6E3C542D727CC768697734 alpha@example.net
[GNUPG:] TOFU_STATS 2 1 0 auto 1472727595 1472727595
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alpha Test (demo key)
<alpha@example.net>"%0Ain the past 0~seconds.
[GNUPG:] TOFU_USER A0FF4590BB6122EDEF6E3C542D727CC768697734 alice%20(demo%20key)
[GNUPG:] TOFU_STATS 2 1 0 auto 1472727595 1472727595
[GNUPG:] TOFU_STATS_LONG Verified 1 message signed by "Alice (demo key)"%0Ain
the past 0~seconds.
[GNUPG:] TRUST_MARGINAL 0 tofu

us@grit:~/neal/work/gpg/build/gpgme/tests/gpg$ ../../../gpgme/tests/run-verify
/tmp/testmsg
Original file name: [none]
Signature 0

status ....: Success
summary ...:
fingerprint: A0FF4590BB6122EDEF6E3C542D727CC768697734
created ...: 1015172412
expires ...: 0
validity ..: marginal
val.reason : Success
pubkey algo: 17 (DSA)
digest algo: 2 (SHA1)
pka address: [none]
pka trust .: n/a
other flags:
primary fpr: A0FF4590BB6122EDEF6E3C542D727CC768697734
tofu addr .: alfa@example.net
  validity : 2 (little history)
  policy ..: 1 (auto)
  sigcount : 1
  firstseen: 1970-01-01 00:01:46
  lastseen : 1970-01-01 00:01:46
  desc ....: Verified 1 message signed by "Alfa Test (demo key)

<alfa@example.net>"

             in the past 1 minute, 46 seconds.
tofu addr .: alpha@example.net
  validity : 2 (little history)
  policy ..: 1 (auto)
  sigcount : 1
  firstseen: 1970-01-01 00:01:46
  lastseen : 1970-01-01 00:01:46
  desc ....: Verified 1 message signed by "Alpha Test (demo key)

<alpha@example.net>"

             in the past 1 minute, 46 seconds.
tofu addr .: [none]
  validity : 2 (little history)
  policy ..: 1 (auto)
  sigcount : 1
  firstseen: 1970-01-01 00:01:46
  lastseen : 1970-01-01 00:01:46
  desc ....: Verified 1 message signed by "Alice (demo key)"
             in the past 1 minute, 46 seconds.

Thanks, this works now as expected.

While enabling the checks for signcount in gpgme/lang/qt/tests/t-tofuinfo.cpp
I've noticed though that if I sign and verify the same plaintext twice
immediately after another the signcount is not incremented correctly.

In line 266 of that test. The call to signAndVerify leads to an Assert if you
remove the " World" part of the "Hello World" message.

Alternatively adding a QTest::qWait(1000); before that line also results in a
success.

You can trigger this also by modifing the strings in line 233ff to contain the
same message.

Not really important imo as this is a constructed problem. The main issue here
is resolved for me.

OpenPGP has a timestamp granularity of one second and thus you can't distinguish
non-RSA signature from each other if they are donewithin the same second.

Waiting a second is an old trick which is even employed somewhere inside gpg.