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 #147 (comment).

[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.