Failed test 'Client non-SSL connection'

[djzhh]

Just reporting, hoping this is the right place...

The test above fails with

t/connectSSL-timeout.t ............ ok

Failed test 'Client non-SSL connection'

at t/core.t line 77.

got: 'This server is SSL only'

expected: 'This server is SSL only'

t/core.t .......................... Failed 1/48 subtests

To me it seems not to be an error. Or is it?

Best regards Dirk

% perl -V Summary of my perl5 (revision 5 version 38 subversion 2) configuration:

Platform: osname=linux osvers=3.10.0-1160.102.1.el7.x86_64 archname=x86_64-linux uname='linux it-r2dev-pa.desy.de 3.10.0-1160.102.1.el7.x86_64 #1 smp tue oct 17 15:42:21 utc 2023 x86_64 x86_64 x86_64 gnulinux ' config_args='-des -Dcc=gcc -Dprefix=/home/XXX -Dccflags=-L/home/XXX/lib -I/home/XXX/include -L/home/XXX/lib64 -std=gnu99 -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_FORTIFY_SOURCE=2 -Dcppflags=-L/home/XXX/lib -I/home/XXX/include -L/home/XXX/lib64 -std=gnu99 -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -Dldflags=-L/home/XXX/lib64 -L/home/XXX/lib -fstack-protector-strong -Dlibpth=/home/XXX/lib64 /home/XXX/lib /usr/lib /usr/lib64 -Dcccdlflags=-I/home/XXX/include -fPIC -Dlddlflags=-shared -O2 -L/home/XXX/lib64 -L/home/XXX/lib -fstack-protector-strong' hint=recommended useposix=true d_sigaction=define useithreads=undef usemultiplicity=undef use64bitint=define use64bitall=define uselongdouble=undef usemymalloc=n default_inc_excludes_dot=define Compiler: cc='gcc' ccflags ='-L/home/XXX/lib -I/home/XXX/include -L/home/XXX/lib64 -std=gnu99 -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_FORTIFY_SOURCE=2 -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64' optimize='-O2' cppflags='-L/home/XXX/lib -I/home/XXX/include -L/home/XXX/lib64 -std=gnu99 -fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong' ccversion='' gccversion='4.8.5 20150623 (Red Hat 4.8.5-44)' gccosandvers='' intsize=4 longsize=8 ptrsize=8 doublesize=8 byteorder=12345678 doublekind=3 d_longlong=define longlongsize=8 d_longdbl=define longdblsize=16 longdblkind=3 ivtype='long' ivsize=8 nvtype='double' nvsize=8 Off_t='off_t' lseeksize=8 alignbytes=8 prototype=define Linker and Libraries: ld='gcc' ldflags ='-L/home/XXX/lib64 -L/home/XXX/lib -fstack-protector-strong -L/usr/local/lib' libpth=/home/XXX/lib64 /r2/XXX/lib /usr/local/lib /usr/lib /usr/lib64 /usr/local/lib64 libs=-lpthread -lgdbm -ldb -ldl -lm -lcrypt -lutil -lc -lgdbm_compat perllibs=-lpthread -ldl -lm -lcrypt -lutil -lc libc=libc-2.17.so so=so useshrplib=false libperl=libperl.a gnulibc_version='2.17' Dynamic Linking: dlsrc=dl_dlopen.xs dlext=so d_dlsymun=undef ccdlflags='-Wl,-E' cccdlflags='-fPIC' lddlflags='-shared -O2 -L/home/XXX/lib64 -L/home/XXX/lib -L/usr/local/lib -fstack-protector-strong'

Characteristics of this binary (from libperl): Compile-time options: HAS_LONG_DOUBLE HAS_STRTOLD HAS_TIMES PERLIO_LAYERS PERL_COPY_ON_WRITE PERL_DONT_CREATE_GVSV PERL_HASH_FUNC_SIPHASH13 PERL_HASH_USE_SBOX32 PERL_MALLOC_WRAP PERL_OP_PARENT PERL_PRESERVE_IVUV PERL_USE_SAFE_PUTENV USE_64_BIT_ALL USE_64_BIT_INT USE_LARGE_FILES USE_LOCALE USE_LOCALE_COLLATE USE_LOCALE_CTYPE USE_LOCALE_NUMERIC USE_LOCALE_TIME USE_PERLIO USE_PERL_ATOF Built under linux Compiled at Dec 6 2023 08:23:45 @INC: /home/XXX/lib/perl5/site_perl/5.38.2/x86_64-linux /home/XXX/lib/perl5/site_perl/5.38.2 /home/XXX/lib/perl5/5.38.2/x86_64-linux /home/XXX/lib/perl5/5.38.2

% openssl version OpenSSL 3.2.0 23 Nov 2023 (Library: OpenSSL 3.2.0 23 Nov 2023)

[pmgdeb]

On a more detailed output, I get:

[   21s] #   Failed test 'Client non-SSL connection'
[   21s] #   at t/core.t line 77.
[   21s] #          got: '�This server is SSL only'
[   21s] #     expected: 'This server is SSL only'
[   21s] t/core.t .......................... 
[   21s] Failed 1/48 subtests

And the code around it:

    70  unless (fork) {
    71      close $server;
    72      my $client = IO::Socket::INET->new(
    73      PeerAddr => $saddr,
    74      LocalAddr => $localip,
    75      );
    76      print $client "Test\n";
    77      is( <$client>, "This server is SSL only", "Client non-SSL connection");
    78      close $client;
    79  ...

[h-vn]

Good catch with the detailed output. I patched t/core.t as follows to add debugging and make it stop sooner:

--- a/t/core.t
+++ b/t/core.t
@@ -11,6 +11,7 @@ use Errno qw( EWOULDBLOCK EAGAIN );

 do './testlib.pl' || do './t/testlib.pl' || die "no testlib";

+$IO::Socket::SSL::DEBUG = 3;
 use Test::More;
 Test::More->builder->use_numbers(0);
 Test::More->builder->no_ending(1);
@@ -212,6 +213,7 @@ unless (fork) {
 my $client = $server->accept;

 ok( $error_trapped, "Server non-SSL Client Check");
+exit(0);

 if ($client && $client->opened) {
     fail("client stayed alive");

I then ran it with Net::SSLeay from its master branch that's compiled against OpenSSL 3.2.0. To capture unprintable characters, I piped it through cat -vet:

% PERL5LIB=../../../p5-net-ssleay/blib/lib/:../../../p5-net-ssleay/blib/arch perl -I lib t/core.t 2>&1 |cat -vet
1..48$
DEBUG: lib/IO/Socket/SSL.pm:3020: new ctx 140152358291968$
ok - Server Initialization$
ok - Server Fileno Check$
DEBUG: lib/IO/Socket/SSL.pm:982: no socket yet$
DEBUG: lib/IO/Socket/SSL.pm:984: accept created normal socket IO::Socket::SSL=GLOB(0x7f77c4809ed8)$
DEBUG: lib/IO/Socket/SSL.pm:1012: starting sslifying$
DEBUG: lib/IO/Socket/SSL.pm:1062: Net::SSLeay::accept -> -1$
DEBUG: lib/IO/Socket/SSL.pm:1065: SSL accept attempt failed$
SSL error:  12016: 1 - error:0A000139:SSL routines::record layer failure$
$
DEBUG: lib/IO/Socket/SSL.pm:1065: local error: SSL accept attempt failed error:0A0000C6:SSL routines::packet length too long$
ok - Server non-SSL Client Check$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140152358291968 open=140152358291968$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140152358291968$
not ok - Client non-SSL connection$
#   Failed test 'Client non-SSL connection'$
#   at t/core.t line 78.$
#          got: '^U^C^C^@^B^B^VThis server is SSL only'$
#     expected: 'This server is SSL only'$
DEBUG: lib/IO/Socket/SSL.pm:3020: new ctx 140152375075328$
DEBUG: lib/IO/Socket/SSL.pm:705: socket not yet connected$
DEBUG: ...evel/IO/Socket.pm:49: local error: IO::Socket::IP configuration failed$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140152375075328 open=140152375075328 140152358291968$
DEBUG: lib/IO/Socket/SSL.pm:3073: free ctx 140152375075328 callback$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140152375075328$
not ok #client failure$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140152358291968 open=140152358291968$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140152358291968$

The mystery characters ^U^C^C^@^B^B^V are hex bytes 15 0303 0002 02 16 which is a TLS fatal alert 22 'Record overflow'. A look with wireshark over loopback interface shows that the alert is sent by the server and then followed by the expected string 'This server is SSL only'.

I guess OpenSSL behaviour has changed in 3.2.0 to send an alert which is not what the test is expecting.

With OpenSSL 3.1.4 the output is as follows. Debug output is different and Wireshark shows that there's no alert sent by the server this time:

% PERL5LIB=../../../p5-net-ssleay/blib/lib/:../../../p5-net-ssleay/blib/arch perl -I lib t/core.t 2>&1 |cat -vet
1..48$
DEBUG: lib/IO/Socket/SSL.pm:3020: new ctx 140455851006464$
ok - Server Initialization$
ok - Server Fileno Check$
DEBUG: lib/IO/Socket/SSL.pm:982: no socket yet$
DEBUG: lib/IO/Socket/SSL.pm:984: accept created normal socket IO::Socket::SSL=GLOB(0x7fbe6d7272b8)$
DEBUG: lib/IO/Socket/SSL.pm:1012: starting sslifying$
DEBUG: lib/IO/Socket/SSL.pm:1062: Net::SSLeay::accept -> -1$
DEBUG: lib/IO/Socket/SSL.pm:1065: SSL accept attempt failed$
$
DEBUG: lib/IO/Socket/SSL.pm:1065: local error: SSL accept attempt failed error:0A00010B:SSL routines::wrong version number$
ok - Server non-SSL Client Check$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140455851006464 open=140455851006464$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140455851006464$
ok - Client non-SSL connection$
DEBUG: lib/IO/Socket/SSL.pm:3020: new ctx 140455874515968$
DEBUG: lib/IO/Socket/SSL.pm:705: socket not yet connected$
DEBUG: ...evel/IO/Socket.pm:49: local error: IO::Socket::IP configuration failed$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140455874515968 open=140455851006464 140455874515968$
DEBUG: lib/IO/Socket/SSL.pm:3073: free ctx 140455874515968 callback$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140455874515968$
not ok #client failure$
DEBUG: lib/IO/Socket/SSL.pm:3069: free ctx 140455851006464 open=140455851006464$
DEBUG: lib/IO/Socket/SSL.pm:3080: OK free ctx 140455851006464$

[pmgdeb]

Could this be related to the certificate version field set to 3? See this and this.

[noxxi]

Could this be related to the certificate version field set to 3? See this and this.

I very much doubt it. These are about the version field in X.509 certificates, which is unrelated to the TLS version (which is what the error is complaining about)

[noxxi]

This should hopefully fixed in 7c0798d, where I changed the "is" (exact match) to "like" (pattern match, and thus accepting "noise" at the beginning). I have no OpenSSL 3.2 currently for testing to verify it though.

[pmgdeb]

Yes, that commit makes the testsuite to pass. Thanks!

[karenetheridge]

I ran into this today also, when installing perl 5.39.7:

#   Failed test 'Client non-SSL connection'
#   at t/core.t line 77.
#          got: '^U^C^C^@^B^B^VThis server is SSL only'
#     expected: 'This server is SSL only'

[sdondley]

Just got this error. Running on mac. Looks like this has not been pused out to cpan yet. Looks like it's safe to do a force install, though.

[noxxi]

Now released as 2.085

[kraptor]

(...) and thus accepting "noise" at the beginning (...)

I don't think that patching the test like that is correct. I mean: if there is "noise" there, is because there is an under/over-read somewhere else, and then makes the test unreliable.

[noxxi]

(...) and thus accepting "noise" at the beginning (...)

I don't think that patching the test like that is correct. I mean: if there is "noise" there, is because there is an under/over-read somewhere else, and then makes the test unreliable.

It is not an under/over-read somewhere else. This "noise" is a behavior change with OpenSSL 3.2 which sends some alert - see https://github.com/noxxi/p5-io-socket-ssl/issues/147#issuecomment-1856691630.

[kraptor]

I've read that comment. By that very same comment you point to:

(...) which is a TLS fatal alert 22 'Record overflow'.

This indicates that somewhere else, there is a over/under-read. This should be fixed at some other place deeper than just ignoring it in the test itself, IMHO.

[noxxi]

This indicates that somewhere else, there is a over/under-read.

Again, this is not the case.

This part of the test is checking the function of SSL_error_trap which gets for example triggered if the SSL handshake fails, for example because a non-SSL client connects to a SSL server. This is tested by sending some plain text data to the SSL server, i.e. not a SSL handshake. The old behavior before OpenSSL 3.2 was to just trigger this error imediately. With OpenSSL 3.2 the internals of OpenSSL now send a TLS alert back which complains about this malformed TLS record from the client (which isn't a TLS record at all) - and this is what one is seeing here.

It is pretty common to get seemingly nonsensical errors like this when OpenSSL assumes that it gets TLS records even though this wasn't TLS in the first place. Some times it will also complain about wrong TLS version.