cleanup of 15-test_gendhparam.t and fix for #17480 #17689

arminfuerst · 2022-02-11T20:37:18Z

In the definition of the testdata-array in 15-test_gendhparam.t, there is a trailing comma. Even though this should be allowed in perl, I think this might cause the sporadic error described in #17480.

sokarax

arminfuerst · 2022-02-12T01:19:53Z

Something seems to be missing :)

bernd-edlinger · 2022-02-12T07:29:55Z

Hmm, I tried to reproduce the problem this way (using oldish perl, and with unpatched master):

$ while make test TESTS=test_gendhparam; do sleep 1; done
make depend && make _tests
make[1]: Entering directory `/home/ed/OPC/openssl'
make[1]: Leaving directory `/home/ed/OPC/openssl'
make[1]: Entering directory `/home/ed/OPC/openssl'
( SRCTOP=. \
	  BLDTOP=. \
	  PERL="/usr/bin/perl" \
	  FIPSKEY="f4556650ac31d35461610bac4ed81b1a181b2d8a43ea2854cbae22ca74560813" \
	  EXE_EXT= \
	  /usr/bin/perl ./test/run_tests.pl test_gendhparam )
00-prep_fipsmodule_cnf.t .. skipped: FIPS module config file only supported in a fips build
Files=1, Tests=0,  0 wallclock secs ( 0.01 usr  0.00 sys +  0.17 cusr  0.02 csys =  0.20 CPU)
Result: NOTESTS
15-test_gendhparam.t .. ok    
All tests successful.
Files=1, Tests=16,  4 wallclock secs ( 0.07 usr  0.03 sys +  2.88 cusr  0.26 csys =  3.24 CPU)
Result: PASS
make[1]: Leaving directory `/home/ed/OPC/openssl'
make depend && make _tests
make[1]: Entering directory `/home/ed/OPC/openssl'
make[1]: Leaving directory `/home/ed/OPC/openssl'
make[1]: Entering directory `/home/ed/OPC/openssl'
( SRCTOP=. \
	  BLDTOP=. \
	  PERL="/usr/bin/perl" \
	  FIPSKEY="f4556650ac31d35461610bac4ed81b1a181b2d8a43ea2854cbae22ca74560813" \
	  EXE_EXT= \
	  /usr/bin/perl ./test/run_tests.pl test_gendhparam )
00-prep_fipsmodule_cnf.t .. skipped: FIPS module config file only supported in a fips build
Files=1, Tests=0,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.17 cusr  0.01 csys =  0.19 CPU)
Result: NOTESTS
15-test_gendhparam.t .. ok    
All tests successful.
Files=1, Tests=16,  3 wallclock secs ( 0.09 usr  0.05 sys +  2.81 cusr  0.26 csys =  3.21 CPU)
Result: PASS
[...]
make[1]: Leaving directory `/home/ed/OPC/openssl'
make[1]: Leaving directory `/home/ed/OPC/openssl'
make depend && make _tests
make[1]: Entering directory `/home/ed/OPC/openssl'
make[1]: Leaving directory `/home/ed/OPC/openssl'
make[1]: Entering directory `/home/ed/OPC/openssl'
( SRCTOP=. \
	  BLDTOP=. \
	  PERL="/usr/bin/perl" \
	  FIPSKEY="f4556650ac31d35461610bac4ed81b1a181b2d8a43ea2854cbae22ca74560813" \
	  EXE_EXT= \
	  /usr/bin/perl ./test/run_tests.pl test_gendhparam )
00-prep_fipsmodule_cnf.t .. skipped: FIPS module config file only supported in a fips build
Files=1, Tests=0,  0 wallclock secs ( 0.01 usr  0.01 sys +  0.17 cusr  0.02 csys =  0.21 CPU)
Result: NOTESTS
15-test_gendhparam.t .. 5/? 
../../util/wrap.pl ../../apps/openssl genpkey -genparam -algorithm DHX -text -pkeyopt 'type:generator' -pkeyopt 'safeprime-generator:5' 2> /dev/null => 1
ok 16 - safe prime generator should fail for DHX
15-test_gendhparam.t .. All 16 subtests passed ---------------------------------

Test Summary Report
-------------------
15-test_gendhparam.t (Wstat: 0 Tests: 17 Failed: 1)
  Failed test:  16
  Parse errors: Tests out of sequence.  Found (1) but expected (2)
                Tests out of sequence.  Found (2) but expected (3)
                Tests out of sequence.  Found (3) but expected (4)
                Tests out of sequence.  Found (4) but expected (5)
                Tests out of sequence.  Found (5) but expected (6)
Displayed the first 5 of 17 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=1, Tests=17,  3 wallclock secs ( 0.07 usr  0.01 sys +  2.45 cusr  0.30 csys =  2.83 CPU)
Result: FAIL
make[1]: *** [run_tests] Error 1
make[1]: Leaving directory `/home/ed/OPC/openssl'
make: *** [tests] Fehler 2

The problem occurred after only 38 repetitions.
With this patch the same test survived over an hour.

bernd-edlinger · 2022-02-12T07:31:03Z

@levitte I really have no idea how this seems to fix the problem, do you have an idea?

arminfuerst · 2022-02-12T09:23:04Z

@levitte I really have no idea how this seems to fix the problem, do you have an idea?

@bernd-edlinger: My theory is, that foreach my $test (@testdata) runs an additional time with an empty element. Since you seem to be able to reproduce this with your loop, you could try - in the unpatched version - to report the details of the current element (e.g. algorithm and message). If the error occurs and in this run there are empty details, this would support my theory.

bernd-edlinger · 2022-02-12T13:24:38Z

I think that was just by luck it is not easy to reproduce,
when I look at the output of make test TESTS=test_gendhparam V=1
I see this:

15-test_gendhparam.t .. 
# The results of this test will end up in test-runs/test_gendhparam
1..16
.......+.+.....+.+...+.........+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++*
.....+..+.+.................+...........+................+...+.........+.+....+......+.....+.......................+.......+...................+......+....................+..+.......+.....+....+.......+..+..+..........+......+...+..+...+.....+........+...............+.+.............+.......+.+...+..................+.+.....................+.+........+.+.+..+............+.....................+...+....+....+...+..........+.......+......+.....+...................+....+....+........+..........+........+....+....+..+.+............+...+..................................+......+.....+..........+..................+...+..+..+.....................+......................+..+..+......+...+.........................+......+.............+.............+..............+.......+.............+.......+..+......+..........+.+.+..........+....+..+.....+.+..+.+................+........+.........+..+....+...........+.........................+..........+...................+.+...............+........+.............+..+....+....+......+...+.........+.....+.........+......+......................+......+..........+...+........+........+.......+................................+.+......................+.+....+...+.+.....+.....+...............+.+..+.+..+......+..+.........+............+........+............+.........+........+.........+......+.+..........+....+.....................+.+.........+...+....+..+..+..+......+.........................+..+..................+.......................+..+.+.+.+..+...+...........+.+...+.+....................+.........+.........+........+...........+.+............................+...+........................+......+...........+.......+.........................+..+..........+................+...+.+....+...........+..+.........+.....+......+..........+..........+..+.+....+.+.............................+.....+.......+...........+.................................+.+.+.......+.+..+.........+.....+.+.+........+..................+......+......+...+........+...+.+.+.........+..........+........+.+..........+.......+................+..+.......+.....+....+....+..+.....+.............+...................+.+........+.+.......+..............+..+..+....+..+.........+.+.....+...................+...+.............+..+.+..............+...........+.+....+.....+........+..........+........+.+........+...+......+.+........+.....+...+......+...........+.....+.+......+.............+.........+....+......+.+..+..............................+..+.......+..+..+.......................+......+.....+.+.......+....+.........+.........+..+..+........+.....+........+...............+.......+........+...............+.+............+.+..+...+.+....+.............+..+....+...+..................+.....+........................+........+.+...........+..+.+.+.............+...+.+....+...+.+..........+.........+..........+........+..+.+.....+.......+.............+...+.......................+.......+.........+......+.+..+.....+.+......+....+...+.+.+.+....................+......+..+.......+...............+.+.+.+..+...+.......+..............+....+..........+.....+.........+....+....+...................+.......+..................+......+.+................+......+....+..+........+..+....+......+...+..+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++*
../../util/wrap.pl ../../apps/openssl genpkey -genparam -algorithm DHX -text -pkeyopt 'type:fips186_4' -pkeyopt 'digest:SHA256' -pkeyopt 'gindex:1' => 0
-----------------
-----BEGIN X9.42 DH PARAMETERS-----
MIICUgKCAQEAyBzm4KgwiNQGSzmutQJcdTl5finLQ3NB4zZW8hcPURhQtnE6o0RR
SKrfPcuaHEBgTtcVRFLqsLrho/HpU80EPuiiwQduDILkhdQxbosnDzRVfJUpOudg
lgQ/FrIIa5A8RvZt3qzKQMQcYPxVMVOrpxUYaseQtqLb2HUzdpmZbEMNq1pGrngU
jz2jE6u5u5vm1gQZh3yPxfX2sKUGCDIg1C4nhitxU45+Z3kahNqfC7/6p9gRTAKe
GJOZjRpEJDwhb+zGRVR919Kn/7gyDQRMGOcPk8Yr1Kz09zq79zZY8zw1QZzUNlre
kIgcrSiTWi2qJyMhrzxaQbD/D9aFs78m6QKCAQEAmQyYspWbxoVBP6JJel1wwRXN
MUjKALrs9jhzC5qQE8gNjZne3zy5BBp8R1fp3foTeKSfO3d/4Z4/datU2ju2RV+J
BzBlwSShVUQnQVzvIuPoRbpJu1DOJs0d2OrCJY25ip9teT6/snqScvNJHeZ31/CO
nWO+r8Cqp5xf95zQLNDT7Dp9iIU0R5SjAQwMBvL2xQ4MyOYMo/d40Ijiv+mnd0pn
h4rraGC3ew2rw6jfWu5LG1ehBBgCIVKZ0EvarIgmsfvcRZQj/9bIImPEc3LTUNim
Hilc5wompT54cglN+yXYVuZsnGQyFGrHxxI/J8dz8idELnx901BJSzADg9l6+wId
ANenePUMB9oasiy0ppM4aNjciYCNYwhpcT8o/ZswJwMhADiCI5BzsDxvDYkyEMTp
0I8qeSd1CyNhG+se4r7hARqWAgIK/Q==
-----END X9.42 DH PARAMETERS-----

what if I had by chance a parameter generation where on line if the PEM output starts
with "ok+" or "ok/" ?
I can easily make that test fail by outputting something with "ok/" like this:

diff --git a/test/recipes/15-test_gendhparam.t b/test/recipes/15-test_gendhparam.t
index b95695b..be826b8 100644
--- a/test/recipes/15-test_gendhparam.t
+++ b/test/recipes/15-test_gendhparam.t
@@ -136,6 +136,7 @@ foreach my $test (@testdata) {
     my @testargs = @{ $test->{pkeyopts} };
     my @expected = @{ $test->{expect} };
     my @pkeyopts= ();
+print "ok/ALG=$alg MSG=$msg\n";
     foreach (@testargs) {
         push(@pkeyopts, '-pkeyopt');
         push(@pkeyopts, $_);

and no, there is no extra line ok/ALG= MSG= with my installation

arminfuerst · 2022-02-12T13:35:35Z

I would change it in a way it cannot interfere with the testing framework, for example:

open(DEBUGFILE,">>/tmp/15-test_gendhparam.txt");
my $iteration=0;
foreach my $test (@testdata) {
    my $alg = $test->{algorithm};
    my $msg = $test->{message};
    my @testargs = @{ $test->{pkeyopts} };
    my @expected = @{ $test->{expect} };
    my @pkeyopts= ();
    foreach (@testargs) {
        push(@pkeyopts, '-pkeyopt');
        push(@pkeyopts, $_);
    }
    $iteration++;
    print DEBUGFILE "$iteration: ALG=$alg MSG=$msg\n";
    my @lines;
    if ($expected[0] eq 'ERROR') {
        @lines = run(app(['openssl', 'genpkey', '-genparam',
                          '-algorithm', $alg, '-text', @pkeyopts],
                         stderr => undef),
                     capture => 1);
    } else {
        @lines = run(app(['openssl', 'genpkey', '-genparam',
                          '-algorithm', $alg, '-text', @pkeyopts]),
                     capture => 1);
    }
    ok(compareline(\@lines, \@expected), $msg);
}
close(DEBUGFILE);

You can run it without V=1 and find the results in /tmp/15-test_gendhparam.txt

bernd-edlinger · 2022-02-12T17:15:29Z

I think I spotted the root cause why the test fails around 1 of 1000 test runs:
#17692

bernd-edlinger · 2022-02-12T17:16:19Z

Nevertheless I like your cleanup too.

bernd-edlinger

LGTM although it is just a clean-up

…g with ok[^a-zA-Z0-9] as a testresult.

arminfuerst · 2022-02-13T17:03:26Z

I could prove:

lines from the output of openssl starting with ok[^a-zA-Z0-9] are misinterpreted as test results
if such lines are prefixed, they are not misinterpreted.
I added the prefix ": ", I assume any prefix will solve this, so if there are better suggestions, I have no objections to change the prefix.

Thanks to @bernd-edlinger for detecting this case.

PR was updated

mattcaswell

I prefer this approach to #17692

bernd-edlinger · 2022-02-15T11:05:38Z

Hmm, maybe switch to the prefix "# ", as it is used in other places?

arminfuerst · 2022-02-15T12:17:31Z

Hmm, maybe switch to the prefix "# ", as it is used in other places?

I totally agree about consistent usage. When I was choosing a prefix, I was looking and couldn't find a hint, which would make most sense. Do you have references where you found this one?

bernd-edlinger · 2022-02-15T14:26:46Z

I've searched in the test V=1 output for "---BEGIN" and found for instance this one:

15-test_gendh.t ....................
# The results of this test will end up in test-runs/test_gendh
1..9
# -----BEGIN PRIVATE KEY-----
# MIICJgIBADCCARcGCSqGSIb3DQEDATCCAQgCggEBAP//////////rfhUWKK7Spqv
# 3FYgJz088di5xYPOLTaVqeE2QRRkM/vMk53OJJs++X0v42NjDHXY9oGyAq7EYXrT
# 3x7V1f1lYSQz9R9fBm7QhWNlVT3tGvO1VxNef1fJNZhPDHDg5ot34qaJ2vPv6HId
# 8VihNq3nNTCsyk9IOnl6vAqxgrMk+2HRCKlLssjj+7lq2rdg1/RoHU9Co945TfSu
# Vu3nY3K7GQsHp8juCm1wngL84c334uzANATNKDQvYZFy/pzphYP/jk8SMu7ygYPD
# /jsbTG+tczu1/LwuwiAFxY7xg30Wg7LG80omwbLv+ohrQjhhKFyX//////////8C
# AQIEggEEAoIBABhAbhZgpeMs4oz8WA5g9kgrvb1P/ccFbtbOjQl8cvvycizixX8C
# xegYbChDaE4AUgp6Agxpw8CGF3IB9bwMLkFWZTWPMoa8FrjhHz12hK2NiSn5PKKA
# C4xc78vyq72lVNV+4VKjmK7yWtMEUgvI+N+78REtk4iNvBNyImmi8FN1lYlNqAg6
# atJLfgRQPwraZ67GJaJT9DPnTvkYW4TKwNik2VpJ5VMzLtUO1R75GdBa7hxqA/uD
# jHwsY61FIns3PwvOMzc9n9vzb2YRN66TF5ek3SCH545+OU880txWPDtEHfjYAyby
# 2XSUFVfgD30rPbU5BUqUC/6LycoSBQFDcw4=
# -----END PRIVATE KEY-----
# DH Private-Key: (2048 bit)
# private-key:

bernd-edlinger · 2022-02-15T14:29:11Z

oops..

arminfuerst · 2022-02-15T16:34:21Z

I would be fine changing it - ok for the reviewers? "Thumbs up" to this comment = yes, "Thumbs down" = no

openssl-machine · 2022-02-16T02:00:10Z

24 hours has passed since 'approval: done' was set, but as this PR has been updated in that time the label 'approval: ready to merge' is not being automatically set. Please review the updates and set the label manually.

t8m · 2022-02-16T07:18:05Z

@paulidale @mattcaswell still OK?

mattcaswell

Still ok.

arminfuerst · 2022-02-17T15:01:19Z

24 hours has passed since 'approval: done' was set, but as this PR has been updated in that time the label 'approval: ready to merge' is not being automatically set. Please review the updates and set the label manually.

Just to be sure: Do I have open tasks (setting labels or something else)?

Prefix output of generated dh parameters to avoid misinterpretation of lines beginning with ok[^a-zA-Z0-9] as a testresult. Also corrected indent and removed useless comma after last item. Fixes #17480 Reviewed-by: Matt Caswell <matt@openssl.org> Reviewed-by: Tomas Mraz <tomas@openssl.org> (Merged from #17689)

Prefix output of generated dh parameters to avoid misinterpretation of lines beginning with ok[^a-zA-Z0-9] as a testresult. Also corrected indent and removed useless comma after last item. Fixes #17480 Reviewed-by: Matt Caswell <matt@openssl.org> Reviewed-by: Tomas Mraz <tomas@openssl.org> (Merged from #17689) (cherry picked from commit b089d54)

t8m · 2022-02-17T15:08:49Z

Squashed the commits and reworded the commit message. Merged to master and 3.0 branches. Thank you for your contribution.

corrected indent and removed useless comma after last item

0f02a31

sokarax suggested changes Feb 12, 2022

View reviewed changes

bernd-edlinger added branch: master Merge to master branch branch: 3.0 Merge to openssl-3.0 branch approval: otc review pending This pull request needs review by an OTC member labels Feb 12, 2022

bernd-edlinger previously approved these changes Feb 12, 2022

View reviewed changes

arminfuerst mentioned this pull request Feb 12, 2022

Fix sporadic test failure in 15-test_gendhparam.t #17692

Closed

prefix output of openssl to avoid misinterpretation of lines beginnin…

7d4e58d

…g with ok[^a-zA-Z0-9] as a testresult.

arminfuerst changed the title ~~cleanup of 15-test_gendhparam.t~~ cleanup of 15-test_gendhparam.t and fix for #17480 Feb 13, 2022

mattcaswell approved these changes Feb 14, 2022

View reviewed changes

paulidale approved these changes Feb 15, 2022

View reviewed changes

paulidale added approval: done This pull request has the required number of approvals and removed approval: otc review pending This pull request needs review by an OTC member labels Feb 15, 2022

bernd-edlinger closed this Feb 15, 2022

t8m reopened this Feb 15, 2022

changed prefix

c50a8c9

t8m approved these changes Feb 16, 2022

View reviewed changes

mattcaswell approved these changes Feb 16, 2022

View reviewed changes

t8m closed this Feb 17, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cleanup of 15-test_gendhparam.t and fix for #17480 #17689

cleanup of 15-test_gendhparam.t and fix for #17480 #17689

arminfuerst commented Feb 11, 2022

sokarax left a comment

arminfuerst commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

arminfuerst commented Feb 12, 2022 •

edited

bernd-edlinger commented Feb 12, 2022

arminfuerst commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger left a comment

arminfuerst commented Feb 13, 2022

mattcaswell left a comment

bernd-edlinger commented Feb 15, 2022

arminfuerst commented Feb 15, 2022

bernd-edlinger commented Feb 15, 2022

bernd-edlinger commented Feb 15, 2022

arminfuerst commented Feb 15, 2022

openssl-machine commented Feb 16, 2022

t8m commented Feb 16, 2022

mattcaswell left a comment

arminfuerst commented Feb 17, 2022

t8m commented Feb 17, 2022

cleanup of 15-test_gendhparam.t and fix for #17480 #17689

cleanup of 15-test_gendhparam.t and fix for #17480 #17689

Conversation

arminfuerst commented Feb 11, 2022

sokarax left a comment

Choose a reason for hiding this comment

arminfuerst commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

arminfuerst commented Feb 12, 2022 • edited

bernd-edlinger commented Feb 12, 2022

arminfuerst commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger commented Feb 12, 2022

bernd-edlinger left a comment

Choose a reason for hiding this comment

arminfuerst commented Feb 13, 2022

mattcaswell left a comment

Choose a reason for hiding this comment

bernd-edlinger commented Feb 15, 2022

arminfuerst commented Feb 15, 2022

bernd-edlinger commented Feb 15, 2022

bernd-edlinger commented Feb 15, 2022

arminfuerst commented Feb 15, 2022

openssl-machine commented Feb 16, 2022

t8m commented Feb 16, 2022

mattcaswell left a comment

Choose a reason for hiding this comment

arminfuerst commented Feb 17, 2022

t8m commented Feb 17, 2022

arminfuerst commented Feb 12, 2022 •

edited