OpenSSL 1.1.0 sometimes yields BIO_write: uninitialized

[triska]

When compiling with OpenSSL 1.1.0c, I sometimes get the message

BIO_write: uninitialized

when running the test cases.

This is very hard to reproduce, and occurs rather rarely, but I have seen it several times already.

Example, after $ swipl test_ssl.pl:

?- test_ssl.
% PL-Unit: ssl_options ......... done
% PL-Unit: ssl_server  ^C
Interrupted test ssl_server:server at .../test_ssl.pl:223
Action (h for help) ? abort
Client error:
ERROR: SSL(syscall) 1001: Unknown error 1001
ERROR: SSL(20071078) BIO_write: uninitialized
ERROR: ...swipl-devel/packages/ssl/test_ssl.pl:223:
        test server: failed

In this case, I have interrupted the hanging test case with ^C. Sometimes, this is not even necessary, and the error occurs without any interaction.

[JanWielemaker]

Try running under valgrind. That is pretty good at finding uninitialised memory access. Simply do

valgrind swipl arg ...

[triska]

I have constructed a program that lets you reproduce the issue within about 20 minutes, often sooner.

Please use test_server.pl with the contents shown below.

Then, use the following loop to repeatedly invoke the program and print the system date for each invocation:

$ while swipl -g run,halt test_server.pl; do date; done

Sample output:

Wed Nov 30 20:17:27 CET 2016
Wed Nov 30 20:17:28 CET 2016
...
Wed Nov 30 20:24:13 CET 2016
Wed Nov 30 20:24:13 CET 2016

After a few minutes, one of the invocations will hang, and you will consequently see no further output.

Then, when you interrupt with ^c and press a to abort, you get:

^CAction (h for help) ? abort
Client error:
ERROR: SSL(syscall) 1001: Unknown error 1001
ERROR: SSL(2006F078) BIO_read: uninitialized

At other times, you also get:

Client error:
ERROR: SSL(syscall) 1001: Unknown error 1001
ERROR: SSL(2006F079) BIO_read: unsupported method

At yet other times, you get:

Client error:
ERROR: SSL(20071078) BIO_write: uninitialized

---

test_server.pl:

:- use_module(library(ssl)).
:- use_module(library(socket)).

:- dynamic
	stop_server/0.

run :-
	make_server(SSL, Socket),
	thread_create(server_loop(SSL, Socket), Id, []),
	(   catch(client, E, true)
	->  (   var(E)
	    ->	thread_join(Id, Status),
		report_join_status(Status)
	    ;   format(user_error, 'Client error:~n', []),
		print_message(error, E),
		thread_join(Id, Status),
		report_join_status(Status),
		fail
	    )
	).

report_join_status(true).
report_join_status(false) :-
	print_message(error, goal_failed(server_loop(_))).
report_join_status(exception(Term)) :-
	print_message(error, Term).


make_server(SSL, Socket) :-
	ssl_context(server, SSL,
		    [ peer_cert(true),
		      cacert_file('tests/test_certs/rootCA/cacert.pem'),
		      certificate_file('tests/test_certs/server-cert.pem'),
		      key_file('tests/test_certs/server-key.pem'),
		      cert_verify_hook(get_cert_verify),
		      password('apenoot1')
		    ]),
	Port = 1111,
	tcp_socket(Socket),
	tcp_setopt(Socket, reuseaddr),
	tcp_bind(Socket, localhost:Port),
	tcp_listen(Socket, 5).

server_loop(SSL, Server) :-
	tcp_accept(Server, Socket, Peer),
	debug(connection, 'Connection from ~p', [Peer]),
	tcp_open_socket(Socket, Read, Write),
	ssl_negotiate(SSL, Read, Write, In, Out),
	catch(copy_client(In, Out), E,
	      assert(copy_error(E))),
	call_cleanup(close(In),	close(Out)),
	(   retract(stop_server)
	->  tcp_close_socket(Server)
	;   server_loop(SSL, Server)
	).


copy_client(In, Out) :-
	read_line_to_codes(In, Line),
	(   Line == end_of_file
	->  true
	;   debug(data, 'SERVER: Got ~s~n', [Line]),
	    debug(data, 'SERVER: writing ~s~n', [Line]),
	    format(Out, '~s~n', [Line]),
	    flush_output(Out),
	    (	atom_codes(bye, Line)
	    ->	assert(stop_server)
	    ;	true
	    ),
	    copy_client(In, Out)
	).


get_cert_verify(SSL,
		ProblemCertificate, AllCertificates, FirstCertificate,
		Error) :-
	debug(certificate,
	      'Accept from ~p, \c
	       ProblemCert: ~p, AllCerts: ~p, FirstCert: ~p, \c
	       Error: ~p',
	      [ SSL,
		ProblemCertificate, AllCertificates, FirstCertificate,
		Error
	      ]),
	(   Error == verified
	->  true
	;   domain_error(verified, Error)
	).


%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

client :-
	ssl_context(client, SSL,
		 [ host('localhost'),
		   cacert_file('tests/test_certs/rootCA/cacert.pem'),
		   certificate_file('tests/test_certs/client-cert.pem'),
		   key_file('tests/test_certs/client-key.pem'),
		   password('apenoot2')
		 ]),
	client_loop(SSL).

client_loop(SSL) :-
	Port = 1111,
	tcp_connect(localhost:Port, StreamPair, []),
	stream_pair(StreamPair, Read, Write),
	ssl_negotiate(SSL, Read, Write, In, Out),
        set_stream(In, timeout(1)),
	Message = 'Hello world',
	write_server(Message, In, Out),
	write_server(bye, In, Out),
	call_cleanup(close(In), close(Out)).

write_server(Message, In, Out) :-
	debug(data, 'CLIENT: writing: ~q~n', [Message]),
	write(Out, Message), nl(Out),
	flush_output(Out),
	catch(read_from_server(In, Message),
	      E,
	      debug(data, 'CLIENT: exception: ~q~n', [E])),
	(   var(E)
	->  true
	;   read_from_server(In, Message)
        ).

read_from_server(In, Message) :-
	debug(data, 'CLIENT: attempting to read reply from stream~n', []),
	read_line_to_codes(In, Line),
	(   Line == end_of_file
	->  true
	;   atom_codes(Reply, Line),
	    debug(data, 'CLIENT: Got ~q~n', [Reply]),
	    (	Reply == Message
	    ->	true
	    ;	format(user_error, 'CLIENT: ERROR: Sent ~q, Got ~q~n',
		       [Message, Reply])
	    )
	).