ssl, pubkey: Code and test adjustments

2 files changed, 184 insertions, 173 deletions

diff --git a/lib/ssl/test/ssl_crl_SUITE.erl b/lib/ssl/test/ssl_crl_SUITE.erl
index 7cf09aa419..da0349904c 100644
--- a/lib/ssl/test/ssl_crl_SUITE.erl
+++ b/lib/ssl/test/ssl_crl_SUITE.erl
@@ -61,96 +61,95 @@ v1_crl_tests() ->
 idp_crl_tests() ->
     [crl_verify_valid, crl_verify_revoked].
 
+%%%================================================================
+%%% Suite init/end
+
 init_per_suite(Config0) ->
-    ct:log("wtf~n"),
-    io:format("Config ~p~n", [Config0]),
     Dog = ct:timetrap(?LONG_TIMEOUT *2),
     case os:find_executable("openssl") of
 	false ->
 	    {skip, "Openssl not found"};
 	_ ->
-	    inets:start(),
-	    catch crypto:stop(),
-	    try crypto:start() of
-		ok ->
-		    ssl:start(),
-		    [{watchdog, Dog} | Config0]
-		catch _:_  ->
-		    {skip, "Crypto did not start"}
+	    TLSVersion = ?config(tls_version, Config0),
+	    OpenSSL_version = (catch os:cmd("openssl version")),
+	    ct:log("TLS version: ~p~nOpenSSL version: ~p~n~n~p:module_info(): ~p~n~nssh:module_info(): ~p~n",
+		   [TLSVersion, OpenSSL_version, ?MODULE, ?MODULE:module_info(), ssh:module_info()]),
+	    case ssl_test_lib:enough_openssl_crl_support(OpenSSL_version) of
+		false ->
+		    {skip, io_lib:format("Bad openssl version: ~p",[OpenSSL_version])};
+		_ ->
+		    catch crypto:stop(),
+		    try crypto:start() of
+			ok ->
+			    ssl:start(),
+			    [{watchdog, Dog}, {openssl_version,OpenSSL_version} | Config0]
+		    catch _C:_E ->
+			    ct:log("crypto:start() caught ~p:~p",[_C,_E]),
+			    {skip, "Crypto did not start"}
+		    end
 	    end
     end.
 
 end_per_suite(_Config) ->
     ssl:stop(),
-    inets:stop(),
     application:stop(crypto).
 
-init_per_group(v1_crl, Config) ->
-    ssl:start(),
-    CertDir = filename:join(?config(priv_dir, Config), "v1_crl"),
-    Result =
-	(catch make_certs:all(?config(data_dir, Config),
-			      CertDir,
-			      [{v2_crls, false}])),
-    ct:log("Make certs  ~p~n", [Result]),
-    %% start a HTTP server to serve the CRLs
-    {ok, Httpd} = inets:start(httpd, [{port, 8000}, {server_name, "localhost"},
-				      {server_root, "/tmp"},
-				      {document_root, CertDir},
-				      {modules, [mod_get]}]),
-    [{make_cert_result, Result}, {cert_dir, CertDir}, {httpd, Httpd} | Config];
-init_per_group(idp_crl, Config) ->
-    ssl:start(),
-    CertDir = filename:join(?config(priv_dir, Config), "idp_crl"),
-    Result =
-	(catch make_certs:all(?config(data_dir, Config),
-			      CertDir,
-			      [{issuing_distribution_point, true}])),
-    ct:log("Make certs  ~p~n", [Result]),
-    %% start a HTTP server to serve the CRLs
-    {ok, Httpd} = inets:start(httpd, [{port, 8000}, {server_name, "localhost"},
-				      {server_root, "/tmp"},
-				      {document_root, CertDir},
-				      {modules, [mod_get]}]),
-    [{make_cert_result, Result}, {cert_dir, CertDir}, {httpd, Httpd} | Config];
-init_per_group(_GroupName, Config) ->
+%%%================================================================
+%%% Group init/end
+
+init_per_group(Group, Config) ->
+    ct:log("~p:~p~nlisteners to port 8000:~n~p~n)",[?MODULE,?LINE,os:cmd("netstat -tln|grep ':8000'")]),
     ssl:start(),
-    CertDir = ?config(priv_dir, Config),
-    Result =
-	(catch make_certs:all(?config(data_dir, Config),
-			      CertDir)),
-    ct:log("Make certs  ~p~n", [Result]),
+    inets:start(),
+    CertDir = filename:join(?config(priv_dir, Config), Group),
+    DataDir = ?config(data_dir, Config),
+    ServerRoot = make_dir_path([?config(priv_dir,Config), Group, tmp]),
+    Result =  make_certs:all(DataDir, CertDir, cert_opts(Group)),
+    ct:log("~p:~p~nmake_certs:all(~n DataDir=~p,~n CertDir=~p,~n ServerRoot=~p~n Opts=~p~n) returned ~p~n", [?MODULE,?LINE,DataDir, CertDir, ServerRoot, cert_opts(Group), Result]),
     %% start a HTTP server to serve the CRLs
-    {ok, Httpd} = inets:start(httpd, [{port, 8000}, {server_name, "localhost"},
-				      {server_root, "/tmp"},
+    {ok, Httpd} = inets:start(httpd, [{server_name, "localhost"}, {port, 8000},
+				      {server_root, ServerRoot},
 				      {document_root, CertDir},
-				      {modules, [mod_get]}]),
+				      {modules, [mod_get]}
+				     ]),
+    ct:log("~p:~p~nlisteners to port 8000:~n~p~n)",[?MODULE,?LINE,os:cmd("netstat -tln|grep ':8000'")]),
     [{make_cert_result, Result}, {cert_dir, CertDir}, {httpd, Httpd} | Config].
 
+cert_opts(v1_crl)  -> [{v2_crls, false}];
+cert_opts(idp_crl) -> [{issuing_distribution_point, true}];
+cert_opts(_) -> [].
+
+make_dir_path(PathComponents) ->
+    lists:foldl(fun(F,P0) -> file:make_dir(P=filename:join(P0,F)), P end,
+		"",
+		PathComponents).
+
+
 end_per_group(_GroupName, Config) ->
     case ?config(httpd, Config) of
 	undefined -> ok;
 	Pid -> 
+	    ct:log("Stop httpd ~p",[Pid]),
 	   ok = inets:stop(httpd, Pid)
+		,ct:log("Stopped",[])
     end,
+    inets:stop(),
+    ct:log("~p:~p~nlisteners to port 8000:~n~p~n)",[?MODULE,?LINE,os:cmd("netstat -tln|grep ':8000'")]),
     Config.
 
+%%%================================================================
+%%% Test cases
+
 crl_verify_valid() ->
     [{doc,"Verify a simple valid CRL chain"}].
 crl_verify_valid(Config) when is_list(Config) ->
     process_flag(trap_exit, true),
-    %ServerOpts = ?config(server_opts, Config),
-
-    ct:log("server opts ~p~n", [Config]),
-
     PrivDir = ?config(cert_dir, Config),
-
     ServerOpts = [{keyfile, filename:join([PrivDir, "server", "key.pem"])},
 		  {certfile, filename:join([PrivDir, "server", "cert.pem"])},
 		  {cacertfile, filename:join([PrivDir, "server", "cacerts.pem"])}],
 
     {ClientNode, ServerNode, Hostname} = ssl_test_lib:run_where(Config),
-    
     Data = "From openssl to erlang",
 
     Server = ssl_test_lib:start_server([{node, ServerNode}, {port, 0}, 
@@ -158,6 +157,7 @@ crl_verify_valid(Config) when is_list(Config) ->
 			   {mfa, {?MODULE, erlang_ssl_receive, [Data]}},
 			   %{mfa, {ssl_test_lib, no_result, []}},
 			   {options, ServerOpts}]),
+    ct:log("~p:~p~nreturn from ssl_test_lib:start_server:~n~p",[?MODULE,?LINE,Server]),
     Port = ssl_test_lib:inet_port(Server),
 
     CACerts = load_cert(filename:join([PrivDir, "erlangCA", "cacerts.pem"])),
@@ -167,6 +167,7 @@ crl_verify_valid(Config) when is_list(Config) ->
 		  {verify_fun, {fun validate_function/3, {CACerts, []}}}],
 
 
+    ct:log("~p:~p~ncalling ssl_test_lib:start_client",[?MODULE,?LINE]),
     Client = ssl_test_lib:start_client([{node, ClientNode}, {port, Port}, 
 					{host, Hostname},
 					{from, self()}, 
@@ -174,9 +175,10 @@ crl_verify_valid(Config) when is_list(Config) ->
 					       erlang_ssl_send, [Data]}},
 					%{mfa, {ssl_test_lib, no_result, []}},
 					{options, ClientOpts}]),
-    ssl_test_lib:check_result(Client, ok),
-    ssl_test_lib:check_result(Server, ok),
-  
+    ct:log("~p:~p~nreturn from ssl_test_lib:start_client:~n~p",[?MODULE,?LINE,Client]),
+
+    ssl_test_lib:check_result(Client, ok,  Server, ok),
+
     %% Clean close down!   Server needs to be closed first !!
     ssl_test_lib:close(Server),
     ssl_test_lib:close(Client),
@@ -186,15 +188,11 @@ crl_verify_revoked() ->
     [{doc,"Verify a simple valid CRL chain"}].
 crl_verify_revoked(Config) when is_list(Config) ->
     process_flag(trap_exit, true),
-    %ServerOpts = ?config(server_opts, Config),
-
-    ct:log("server opts ~p~n", [Config]),
-
     PrivDir = ?config(cert_dir, Config),
-
     ServerOpts = [{keyfile, filename:join([PrivDir, "revoked", "key.pem"])},
 		  {certfile, filename:join([PrivDir, "revoked", "cert.pem"])},
 		  {cacertfile, filename:join([PrivDir, "revoked", "cacerts.pem"])}],
+    ct:log("~p:~p~nserver opts ~p~n", [?MODULE,?LINE, ServerOpts]),
 
     {ClientNode, ServerNode, Hostname} = ssl_test_lib:run_where(Config),
 
@@ -206,12 +204,10 @@ crl_verify_revoked(Config) when is_list(Config) ->
     Port = ssl_test_lib:inet_port(Server),
 
     CACerts = load_cert(filename:join([PrivDir, "erlangCA", "cacerts.pem"])),
-
     ClientOpts = [{cacerts, CACerts},
 		  {verify, verify_peer},
 		  {verify_fun, {fun validate_function/3, {CACerts, []}}}],
 
-
     {connect_failed, _} = ssl_test_lib:start_client([{node, ClientNode}, {port, Port}, 
 					{host, Hostname},
 					{from, self()}, 
@@ -224,19 +220,22 @@ crl_verify_revoked(Config) when is_list(Config) ->
     ssl_test_lib:close(Server),
     process_flag(trap_exit, false).
 
+%%%================================================================
+%%% Lib
+
 erlang_ssl_receive(Socket, Data) ->
-    ct:log("Connection info: ~p~n",
-		       [ssl:connection_info(Socket)]),
+    ct:log("~p:~p~nConnection info: ~p~n",
+		       [?MODULE,?LINE, ssl:connection_info(Socket)]),
     receive
 	{ssl, Socket, Data} ->
-	    io:format("Received ~p~n",[Data]),
+	    ct:log("~p:~p~nReceived ~p~n",[?MODULE,?LINE, Data]),
 	    %% open_ssl server sometimes hangs waiting in blocking read
 	    ssl:send(Socket, "Got it"), 
 	    ok;
 	{ssl, Socket, Byte} when length(Byte) == 1 ->
 	    erlang_ssl_receive(Socket, tl(Data));
 	{Port, {data,Debug}} when is_port(Port) ->
-	    io:format("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    erlang_ssl_receive(Socket,Data);
 	Other ->
 	    ct:fail({unexpected_message, Other})
@@ -246,8 +245,8 @@ erlang_ssl_receive(Socket, Data) ->
 
 
 erlang_ssl_send(Socket, Data) ->
-    ct:log("Connection info: ~p~n",
-		       [ssl:connection_info(Socket)]),
+    ct:log("~p:~p~nConnection info: ~p~n",
+		       [?MODULE,?LINE, ssl:connection_info(Socket)]),
     ssl:send(Socket, Data),
     ok.
 
@@ -263,14 +262,14 @@ load_certs(CertDir) ->
     end.
 
 load_certs([], Acc) ->
-    io:format("Successfully loaded ~p CA certificates~n", [length(Acc)]),
+    ct:log("~p:~p~nSuccessfully loaded ~p CA certificates~n", [?MODULE,?LINE, length(Acc)]),
     Acc;
 load_certs([Cert|Certs], Acc) ->
     case filelib:is_dir(Cert) of
         true ->
             load_certs(Certs, Acc);
         _ ->
-            %io:format("Loading certificate ~p~n", [Cert]),
+            %ct:log("~p:~p~nLoading certificate ~p~n", [?MODULE,?LINE, Cert]),
             load_certs(Certs, load_cert(Cert) ++ Acc)
     end.
 
@@ -289,30 +288,30 @@ load_cert(Cert) ->
 %% @doc Validator function for SSL negotiation.
 %%
 validate_function(Cert, valid_peer, State) ->
-    io:format("validing peer ~p with ~p intermediate certs~n",
-                [get_common_name(Cert), 
+    ct:log("~p:~p~nvaliding peer ~p with ~p intermediate certs~n",
+                [?MODULE,?LINE, get_common_name(Cert), 
                  length(element(2, State))]),
     %% peer certificate validated, now check the CRL
     Res = (catch check_crl(Cert, State)),
-    io:format("CRL validate result for ~p: ~p~n",
-                [get_common_name(Cert), Res]),
+    ct:log("~p:~p~nCRL validate result for ~p: ~p~n",
+                [?MODULE,?LINE, get_common_name(Cert), Res]),
     {Res, State};
 validate_function(Cert, valid, {TrustedCAs, IntermediateCerts}=State) ->
     case public_key:pkix_is_self_signed(Cert) of
         true ->
-            io:format("root certificate~n"),
+            ct:log("~p:~p~nroot certificate~n",[?MODULE,?LINE]),
             %% this is a root cert, no CRL
             {valid, {TrustedCAs, [Cert|IntermediateCerts]}};
         false ->
             %% check is valid CA certificate, add to the list of
             %% intermediates
             Res = (catch check_crl(Cert, State)),
-            io:format("CRL intermediate CA validate result for ~p: ~p~n",
-                        [get_common_name(Cert), Res]),
+            ct:log("~p:~p~nCRL intermediate CA validate result for ~p: ~p~n",
+                        [?MODULE,?LINE, get_common_name(Cert), Res]),
             {Res, {TrustedCAs, [Cert|IntermediateCerts]}}
     end;
 validate_function(_Cert, _Event, State) ->
-    %io:format("ignoring event ~p~n", [_Event]),
+    %ct:log("~p:~p~nignoring event ~p~n", [?MODULE,?LINE, _Event]),
     {valid, State}.
 
 %% @doc Given a certificate, find CRL distribution points for the given
@@ -321,22 +320,27 @@ validate_function(_Cert, _Event, State) ->
 %%
 check_crl(Cert, State) ->
     %% pull the CRL distribution point(s) out of the certificate, if any
-    case pubkey_cert:select_extension(?'id-ce-cRLDistributionPoints',
-                                      pubkey_cert:extensions_list(Cert#'OTPCertificate'.tbsCertificate#'OTPTBSCertificate'.extensions)) of
+    ct:log("~p:~p~ncheck_crl(~n Cert=~p,~nState=~p~n)",[?MODULE,?LINE,Cert,State]),
+    case pubkey_cert:select_extension(
+	   ?'id-ce-cRLDistributionPoints',
+	   pubkey_cert:extensions_list(Cert#'OTPCertificate'.tbsCertificate#'OTPTBSCertificate'.extensions)) of
         undefined ->
-            io:format("no CRL distribution points for ~p~n",
-                         [get_common_name(Cert)]),
+            ct:log("~p:~p~nno CRL distribution points for ~p~n",
+                         [?MODULE,?LINE, get_common_name(Cert)]),
             %% fail; we can't validate if there's no CRL
             no_crl;
         CRLExtension ->
+	    ct:log("~p:~p~nCRLExtension=~p)",[?MODULE,?LINE,CRLExtension]),
             CRLDistPoints = CRLExtension#'Extension'.extnValue,
             DPointsAndCRLs = lists:foldl(fun(Point, Acc) -> 
                             %% try to read the CRL over http or from a
                             %% local file
                             case fetch_point(Point) of
                                 not_available ->
+				    ct:log("~p:~p~nfetch_point returned~n~p~n)",[?MODULE,?LINE,not_available]),
                                     Acc;
                                 Res ->
+				    ct:log("~p:~p~nfetch_point returned~n~p~n)",[?MODULE,?LINE,Res]),
                                     [{Point, Res} | Acc]
                             end 
                     end, [], CRLDistPoints),
@@ -354,6 +358,7 @@ issuer_function(_DP, CRL, _Issuer, {TrustedCAs, IntermediateCerts}) ->
     %% XXX the 'Issuer' we get passed here is the AuthorityKeyIdentifier,
     %% which we are not currently smart enough to understand
     %% Read the CA certs out of the file
+    ct:log("~p:~p~nissuer_function(~nCRL=~p,~nLast param=~p)",[?MODULE,?LINE,CRL, {TrustedCAs, IntermediateCerts}]),
     Certs = [public_key:pkix_decode_cert(DER, otp) || DER <- TrustedCAs],
     %% get the real issuer out of the CRL
     Issuer = public_key:pkix_normalize_name(
@@ -362,10 +367,11 @@ issuer_function(_DP, CRL, _Issuer, {TrustedCAs, IntermediateCerts}) ->
     %% assume certificates are ordered from root to tip
     case find_issuer(Issuer, IntermediateCerts ++ Certs) of
         undefined ->
-            io:format("unable to find certificate matching CRL issuer ~p~n", 
-                        [Issuer]),
+            ct:log("~p:~p~nunable to find certificate matching CRL issuer ~p~n", 
+                        [?MODULE,?LINE, Issuer]),
             error;
         IssuerCert ->
+	    ct:log("~p:~p~nIssuerCert=~p~n)",[?MODULE,?LINE,IssuerCert]),
             case build_chain({public_key:pkix_encode('OTPCertificate', 
                                                      IssuerCert, 
                                                      otp), 
@@ -395,7 +401,7 @@ build_chain({DER, Cert}, IntCerts, TrustedCerts, Acc) ->
         true ->
             case find_issuer(Issuer, TrustedCerts) of
                 undefined ->
-                    io:format("self-signed certificate is NOT trusted~n"),
+                    ct:log("~p:~p~nself-signed certificate is NOT trusted~n",[?MODULE,?LINE]),
                     undefined;
                 TrustedCert ->
                     %% return the cert from the trusted list, to prevent
@@ -423,11 +429,11 @@ build_chain({DER, Cert}, IntCerts, TrustedCerts, Acc) ->
             case Match of
                 undefined when IntCerts /= TrustedCerts ->
                     %% continue the chain by using the trusted CAs
-                    io:format("Ran out of intermediate certs, switching to trusted certs~n"),
+                    ct:log("~p:~p~nRan out of intermediate certs, switching to trusted certs~n",[?MODULE,?LINE]),
                     build_chain({DER, Cert}, TrustedCerts, TrustedCerts, Acc);
                 undefined ->
-                    io:format("Can't construct chain of trust beyond ~p~n",
-                                [get_common_name(Cert)]),
+                    ct:log("Can't construct chain of trust beyond ~p~n",
+                                [?MODULE,?LINE, get_common_name(Cert)]),
                     %% can't find the current cert's issuer
                     undefined;
                 Match ->
@@ -461,6 +467,7 @@ fetch_point(#'DistributionPoint'{distributionPoint={fullName, Names}}) ->
     Decoded = [{NameType, 
                 pubkey_cert_records:transform(Name, decode)} 
                || {NameType, Name} <- Names],
+    ct:log("~p:~p~ncall fetch(~nDecoded=~p~n)",[?MODULE,?LINE,Decoded]),
     fetch(Decoded).
 
 %% @doc Given a list of locations to retrieve a CRL from, attempt to
@@ -473,29 +480,35 @@ fetch_point(#'DistributionPoint'{distributionPoint={fullName, Names}}) ->
 fetch([]) ->
     not_available;
 fetch([{uniformResourceIdentifier, "http"++_=URL}|Rest]) ->
-    io:format("getting CRL from ~p~n", [URL]),
-    _ = inets:start(),
+    ct:log("~p:~p~ngetting CRL from ~p~n", [?MODULE,?LINE, URL]),
+    ct:log("~p:~p~nlisteners to port 8000:~n~p~n)",[?MODULE,?LINE,os:cmd("netstat -tln|grep ':8000'")]),
     case httpc:request(get, {URL, []}, [], [{body_format, binary}]) of
         {ok, {_Status, _Headers, Body}} ->
             case Body of
                 <<"-----BEGIN", _/binary>> ->
+		    ct:log("~p:~p~npublic_key:pem_decode,~nBody=~p~n)",[?MODULE,?LINE,Body]),
                     [{'CertificateList', 
                       DER, _}=CertList] = public_key:pem_decode(Body),
+		    ct:log("~p:~p~npublic_key:pem_entry_decode,~nCertList=~p~n)",[?MODULE,?LINE,CertList]),
                     {DER, public_key:pem_entry_decode(CertList)};
                 _ ->
+		    ct:log("~p:~p~npublic_key:pem_entry_decode,~nBody=~p~n)",[?MODULE,?LINE,{'CertificateList', Body, not_encrypted}]),
                     %% assume DER encoded
                     CertList = public_key:pem_entry_decode(
                             {'CertificateList', Body, not_encrypted}),
                     {Body, CertList}
             end;
         {error, _Reason} ->
-            io:format("failed to get CRL ~p~n", [_Reason]),
+            ct:log("~p:~p~nfailed to get CRL ~p~n", [?MODULE,?LINE, _Reason]),
+            fetch(Rest);
+	Other ->
+            ct:log("~p:~p~nreally failed to get CRL ~p~n", [?MODULE,?LINE, Other]),
             fetch(Rest)
     end;
 fetch([Loc|Rest]) ->
     %% unsupported CRL location
-    io:format("unable to fetch CRL from unsupported location ~p~n", 
-                [Loc]),
+    ct:log("~p:~p~nunable to fetch CRL from unsupported location ~p~n", 
+                [?MODULE,?LINE, Loc]),
     fetch(Rest).
 
 %% get the common name attribute out of an OTPCertificate record
diff --git a/lib/ssl/test/ssl_test_lib.erl b/lib/ssl/test/ssl_test_lib.erl
index 1ebccf13ea..7d8ece8d19 100644
--- a/lib/ssl/test/ssl_test_lib.erl
+++ b/lib/ssl/test/ssl_test_lib.erl
@@ -60,7 +60,7 @@ run_server(Opts) ->
     Options = proplists:get_value(options, Opts),
     Pid = proplists:get_value(from, Opts),
     Transport =  proplists:get_value(transport, Opts, ssl),
-    ct:log("ssl:listen(~p, ~p)~n", [Port, Options]),
+    ct:log("~p:~p~nssl:listen(~p, ~p)~n", [?MODULE,?LINE, Port, Options]),
     {ok, ListenSocket} = rpc:call(Node, Transport, listen, [Port, Options]),
     Pid ! {listen, up},
     send_selected_port(Pid, Port, ListenSocket),
@@ -78,13 +78,13 @@ do_run_server(ListenSocket, AcceptSocket, Opts) ->
     Pid = proplists:get_value(from, Opts),
     Transport = proplists:get_value(transport, Opts, ssl),
     {Module, Function, Args} = proplists:get_value(mfa, Opts),
-    ct:log("Server: apply(~p,~p,~p)~n",
-		       [Module, Function, [AcceptSocket | Args]]),
+    ct:log("~p:~p~nServer: apply(~p,~p,~p)~n",
+		       [?MODULE,?LINE, Module, Function, [AcceptSocket | Args]]),
     case rpc:call(Node, Module, Function, [AcceptSocket | Args]) of
 	no_result_msg ->
 	    ok;
 	Msg ->
-	    ct:log("Server Msg: ~p ~n", [Msg]),
+	    ct:log("~p:~p~nServer Msg: ~p ~n", [?MODULE,?LINE, Msg]),
 	    Pid ! {self(), Msg}
     end,
     receive
@@ -93,10 +93,10 @@ do_run_server(ListenSocket, AcceptSocket, Opts) ->
 	{listen, MFA} ->
 	    run_server(ListenSocket, [MFA | proplists:delete(mfa, Opts)]);
 	close ->
-	    ct:log("Server closing  ~p ~n", [self()]),
+	    ct:log("~p:~p~nServer closing  ~p ~n", [?MODULE,?LINE, self()]),
 	    Result = rpc:call(Node, Transport, close, [AcceptSocket], 500),
 	    Result1 = rpc:call(Node, Transport, close, [ListenSocket], 500),
-	    ct:log("Result ~p : ~p ~n", [Result, Result1]);
+	    ct:log("~p:~p~nResult ~p : ~p ~n", [?MODULE,?LINE, Result, Result1]);
 	{ssl_closed, _} ->
 	    ok
     end.
@@ -116,7 +116,7 @@ connect(#sslsocket{} = ListenSocket, Opts) ->
     end;
 connect(ListenSocket, Opts) ->
     Node = proplists:get_value(node, Opts),
-    ct:log("gen_tcp:accept(~p)~n", [ListenSocket]),
+    ct:log("~p:~p~ngen_tcp:accept(~p)~n", [?MODULE,?LINE, ListenSocket]),
     {ok, AcceptSocket} = rpc:call(Node, gen_tcp, accept, 
 				  [ListenSocket]),
     AcceptSocket.
@@ -124,15 +124,17 @@ connect(ListenSocket, Opts) ->
 connect(_, _, 0, AcceptSocket, _) ->
     AcceptSocket;
 connect(ListenSocket, Node, N, _, Timeout) ->
-    ct:log("ssl:transport_accept(~p)~n", [ListenSocket]),
+    ct:log("~p:~p~nssl:transport_accept(~p)~n", [?MODULE,?LINE, ListenSocket]),
     {ok, AcceptSocket} = rpc:call(Node, ssl, transport_accept, 
 				  [ListenSocket]),    
-    ct:log("ssl:ssl_accept(~p, ~p)~n", [AcceptSocket, Timeout]),
+    ct:log("~p:~p~nssl:ssl_accept(~p, ~p)~n", [?MODULE,?LINE, AcceptSocket, Timeout]),
 
     case rpc:call(Node, ssl, ssl_accept, [AcceptSocket, Timeout]) of
 	ok ->
+ct:log("~p:~p~nok from ssl:ssl_accept@~p",[?MODULE,?LINE, Node]),
 	    connect(ListenSocket, Node, N-1, AcceptSocket, Timeout);
 	Result ->
+ct:log("~p:~p~nssl:ssl_accept@~p ret ~p",[?MODULE,?LINE, Node,Result]),
 	    Result
     end.
 
@@ -148,11 +150,11 @@ remove_close_msg(ReconnectTimes) ->
 start_client(Args) ->
     Result = spawn_link(?MODULE, run_client_init, [lists:delete(return_socket, Args)]),
     receive 
-	{ connected, Socket } ->
-        case lists:member(return_socket, Args) of
-            true -> { Result, Socket };
-            false -> Result
-        end;
+	{connected, Socket} ->
+	    case lists:member(return_socket, Args) of
+		true -> {Result, Socket};
+		false -> Result
+	    end;
 	{connect_failed, Reason} ->
 	    {connect_failed, Reason}
     end.
@@ -168,27 +170,30 @@ run_client(Opts) ->
     Pid = proplists:get_value(from, Opts),
     Transport =  proplists:get_value(transport, Opts, ssl),
     Options = proplists:get_value(options, Opts),
-    ct:log("ssl:connect(~p, ~p, ~p)~n", [Host, Port, Options]),
+    ct:log("~p:~p~nssl:connect(~p, ~p, ~p)~n", [?MODULE,?LINE, Host, Port, Options]),
+ct:log("~p:~p~nnet_adm:ping(~p)=~p",[?MODULE,?LINE, Node,net_adm:ping(Node)]),
+%%ct:log("~p:~p~n~p:connect(~p, ~p, ~p)@~p~n", [?MODULE,?LINE, Transport, Host, Port, Options, Node]),
+ct:log("~p:~p~n~p:connect(~p, ~p, ...)@~p~n", [?MODULE,?LINE, Transport, Host, Port, Node]),
     case rpc:call(Node, Transport, connect, [Host, Port, Options]) of
 	{ok, Socket} ->
-	    Pid ! { connected, Socket },
-	    ct:log("Client: connected~n", []),
+	    Pid ! {connected, Socket},
+	    ct:log("~p:~p~nClient: connected~n", [?MODULE,?LINE]),
 	    %% In special cases we want to know the client port, it will
 	    %% be indicated by sending {port, 0} in options list!
 	    send_selected_port(Pid,  proplists:get_value(port, Options), Socket),
 	    {Module, Function, Args} = proplists:get_value(mfa, Opts),
-	    ct:log("Client: apply(~p,~p,~p)~n",
-			       [Module, Function, [Socket | Args]]),
+	    ct:log("~p:~p~nClient: apply(~p,~p,~p)~n",
+			       [?MODULE,?LINE, Module, Function, [Socket | Args]]),
 	    case rpc:call(Node, Module, Function, [Socket | Args]) of
 		no_result_msg ->
 		    ok;
 		Msg ->
-		    ct:log("Client Msg: ~p ~n", [Msg]),
+		    ct:log("~p:~p~nClient Msg: ~p ~n", [?MODULE,?LINE, Msg]),
 		    Pid ! {self(), Msg}
 	    end,
 	    receive
 		close ->
-		    ct:log("Client closing~n", []),
+		    ct:log("~p:~p~nClient closing~n", [?MODULE,?LINE]),
 		    rpc:call(Node, Transport, close, [Socket]);
 		{ssl_closed, Socket} ->
 		    ok;
@@ -198,52 +203,42 @@ run_client(Opts) ->
 	{error, econnrefused = Reason} ->
 	    case get(retries) of
 		N when N < 5 ->
+		    ct:log("~p:~p~neconnrefused retries=~p sleep ~p",[?MODULE,?LINE, N,?SLEEP]),
 		    put(retries, N+1),
 		    ct:sleep(?SLEEP),
 		    run_client(Opts);
 	       _ ->
-		    ct:log("Client faild several times: connection failed: ~p ~n", [Reason]),
+		    ct:log("~p:~p~nClient faild several times: connection failed: ~p ~n", [?MODULE,?LINE, Reason]),
 		    Pid ! {self(), {error, Reason}}
 	    end;
 	{error, Reason} ->
-	    ct:log("Client: connection failed: ~p ~n", [Reason]),
-%%% FIXME: Which one of the two following???
-	    Pid ! {self(), {error, Reason}},
-	    Pid ! {connect_failed, Reason}
+	    ct:log("~p:~p~nClient: connection failed: ~p ~n", [?MODULE,?LINE, Reason]),
+	    Pid ! {connect_failed, Reason};
+	{badrpc,BadRPC} ->
+            ct:log("~p:~p~nBad rpc: ~p",[?MODULE,?LINE, BadRPC]),
+            Pid ! {connect_failed, {badrpc,BadRPC}}
     end.
 
 close(Pid) ->
-    ct:log("Close ~p ~n", [Pid]),
+    ct:log("~p:~p~nClose ~p ~n", [?MODULE,?LINE, Pid]),
     Monitor = erlang:monitor(process, Pid),
     Pid ! close,
     receive
 	{'DOWN', Monitor, process, Pid, Reason} ->
 	    erlang:demonitor(Monitor),
-	    ct:log("Pid: ~p down due to:~p ~n", [Pid, Reason])
+	    ct:log("~p:~p~nPid: ~p down due to:~p ~n", [?MODULE,?LINE, Pid, Reason])
     end.
 
 check_result(Server, ServerMsg, Client, ClientMsg) -> 
     receive 
-	{Server, ServerMsg} -> 
-	    receive 
-		{Client, ClientMsg} ->
-		    ok;
-		Unexpected ->
-		    Reason = {{expected, {Client, ClientMsg}}, 
-			      {got, Unexpected}},
-		    ct:fail(Reason)
-	    end;
-	{Client, ClientMsg} -> 
-	    receive 
-		{Server, ServerMsg} ->
-		    ok;
-		Unexpected ->
-		    Reason = {{expected, {Server, ClientMsg}}, 
-			      {got, Unexpected}},
-		    ct:fail(Reason)
-	    end;
+	{Server, ServerMsg} ->
+	    check_result(Client, ClientMsg);
+
+	{Client, ClientMsg} ->
+	    check_result(Server, ServerMsg);
+
 	{Port, {data,Debug}} when is_port(Port) ->
-	    io:format("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    check_result(Server, ServerMsg, Client, ClientMsg);
 
 	Unexpected ->
@@ -257,7 +252,7 @@ check_result(Pid, Msg) ->
 	{Pid, Msg} -> 
 	    ok;
 	{Port, {data,Debug}} when is_port(Port) ->
-	    io:format("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    check_result(Pid,Msg);
 	Unexpected ->
 	    Reason = {{expected, {Pid, Msg}}, 
@@ -282,7 +277,7 @@ wait_for_result(Server, ServerMsg, Client, ClientMsg) ->
 		%%     Unexpected
 	    end;
 	{Port, {data,Debug}} when is_port(Port) ->
-	    io:format("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    wait_for_result(Server, ServerMsg, Client, ClientMsg)
 	%% Unexpected ->
 	%%     Unexpected
@@ -294,7 +289,7 @@ wait_for_result(Pid, Msg) ->
 	{Pid, Msg} -> 
 	    ok;
 	{Port, {data,Debug}} when is_port(Port) ->
-	    io:format("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    wait_for_result(Pid,Msg)
 	%% Unexpected ->
 	%%     Unexpected
@@ -519,33 +514,33 @@ run_upgrade_server(Opts) ->
     SslOptions = proplists:get_value(ssl_options, Opts),
     Pid = proplists:get_value(from, Opts),
 
-    ct:log("gen_tcp:listen(~p, ~p)~n", [Port, TcpOptions]),
+    ct:log("~p:~p~ngen_tcp:listen(~p, ~p)~n", [?MODULE,?LINE, Port, TcpOptions]),
     {ok, ListenSocket} = rpc:call(Node, gen_tcp, listen, [Port, TcpOptions]),
     Pid ! {listen, up},
     send_selected_port(Pid, Port, ListenSocket),
-    ct:log("gen_tcp:accept(~p)~n", [ListenSocket]),
+    ct:log("~p:~p~ngen_tcp:accept(~p)~n", [?MODULE,?LINE, ListenSocket]),
     {ok, AcceptSocket} = rpc:call(Node, gen_tcp, accept, [ListenSocket]),
 
     try
 	{ok, SslAcceptSocket} = case TimeOut of
 				    infinity ->
-					ct:log("ssl:ssl_accept(~p, ~p)~n",
-							   [AcceptSocket, SslOptions]),
+					ct:log("~p:~p~nssl:ssl_accept(~p, ~p)~n",
+							   [?MODULE,?LINE, AcceptSocket, SslOptions]),
 					rpc:call(Node, ssl, ssl_accept,
 						 [AcceptSocket, SslOptions]);
 				    _ ->
-					ct:log("ssl:ssl_accept(~p, ~p, ~p)~n",
-							   [AcceptSocket, SslOptions, TimeOut]),
+					ct:log("~p:~p~nssl:ssl_accept(~p, ~p, ~p)~n",
+							   [?MODULE,?LINE, AcceptSocket, SslOptions, TimeOut]),
 					rpc:call(Node, ssl, ssl_accept,
 						 [AcceptSocket, SslOptions, TimeOut])
 				end,
 	{Module, Function, Args} = proplists:get_value(mfa, Opts),
 	Msg = rpc:call(Node, Module, Function, [SslAcceptSocket | Args]),
-	ct:log("Upgrade Server Msg: ~p ~n", [Msg]),
+	ct:log("~p:~p~nUpgrade Server Msg: ~p ~n", [?MODULE,?LINE, Msg]),
 	Pid ! {self(), Msg},
 	receive
 	    close ->
-		ct:log("Upgrade Server closing~n", []),
+		ct:log("~p:~p~nUpgrade Server closing~n", [?MODULE,?LINE]),
 		rpc:call(Node, ssl, close, [SslAcceptSocket])
 	end
     catch error:{badmatch, Error} ->
@@ -563,24 +558,24 @@ run_upgrade_client(Opts) ->
     TcpOptions = proplists:get_value(tcp_options, Opts),
     SslOptions = proplists:get_value(ssl_options, Opts),
     
-    ct:log("gen_tcp:connect(~p, ~p, ~p)~n",
-		       [Host, Port, TcpOptions]),
+    ct:log("~p:~p~ngen_tcp:connect(~p, ~p, ~p)~n",
+		       [?MODULE,?LINE, Host, Port, TcpOptions]),
     {ok, Socket} = rpc:call(Node, gen_tcp, connect, [Host, Port, TcpOptions]),
 
     send_selected_port(Pid, Port, Socket),
 
-    ct:log("ssl:connect(~p, ~p)~n", [Socket, SslOptions]),
+    ct:log("~p:~p~nssl:connect(~p, ~p)~n", [?MODULE,?LINE, Socket, SslOptions]),
     {ok, SslSocket} = rpc:call(Node, ssl, connect, [Socket, SslOptions]),
 
     {Module, Function, Args} = proplists:get_value(mfa, Opts),
-    ct:log("apply(~p, ~p, ~p)~n",
-		       [Module, Function, [SslSocket | Args]]),
+    ct:log("~p:~p~napply(~p, ~p, ~p)~n",
+		       [?MODULE,?LINE, Module, Function, [SslSocket | Args]]),
     Msg = rpc:call(Node, Module, Function, [SslSocket | Args]),
-    ct:log("Upgrade Client Msg: ~p ~n", [Msg]),
+    ct:log("~p:~p~nUpgrade Client Msg: ~p ~n", [?MODULE,?LINE, Msg]),
     Pid ! {self(), Msg},
     receive 
 	close ->
-	    ct:log("Upgrade Client closing~n", []),
+	    ct:log("~p:~p~nUpgrade Client closing~n", [?MODULE,?LINE]),
 	    rpc:call(Node, ssl, close, [SslSocket])
     end.
 
@@ -599,21 +594,21 @@ run_upgrade_server_error(Opts) ->
     SslOptions = proplists:get_value(ssl_options, Opts),
     Pid = proplists:get_value(from, Opts),
 
-    ct:log("gen_tcp:listen(~p, ~p)~n", [Port, TcpOptions]),
+    ct:log("~p:~p~ngen_tcp:listen(~p, ~p)~n", [?MODULE,?LINE, Port, TcpOptions]),
     {ok, ListenSocket} = rpc:call(Node, gen_tcp, listen, [Port, TcpOptions]),
     Pid ! {listen, up},
     send_selected_port(Pid, Port, ListenSocket),
-    ct:log("gen_tcp:accept(~p)~n", [ListenSocket]),
+    ct:log("~p:~p~ngen_tcp:accept(~p)~n", [?MODULE,?LINE, ListenSocket]),
     {ok, AcceptSocket} = rpc:call(Node, gen_tcp, accept, [ListenSocket]),
     Error = case TimeOut of
 		infinity ->
-		    ct:log("ssl:ssl_accept(~p, ~p)~n",
-				       [AcceptSocket, SslOptions]),
+		    ct:log("~p:~p~nssl:ssl_accept(~p, ~p)~n",
+				       [?MODULE,?LINE, AcceptSocket, SslOptions]),
 		    rpc:call(Node, ssl, ssl_accept,
 			     [AcceptSocket, SslOptions]);
 		_ ->
-		    ct:log("ssl:ssl_accept(~p, ~p, ~p)~n",
-				       [AcceptSocket, SslOptions, TimeOut]),
+		    ct:log("~p:~p~nssl:ssl_accept(~p, ~p, ~p)~n",
+				       [?MODULE,?LINE, AcceptSocket, SslOptions, TimeOut]),
 		    rpc:call(Node, ssl, ssl_accept,
 			     [AcceptSocket, SslOptions, TimeOut])
 	    end,
@@ -632,26 +627,26 @@ run_server_error(Opts) ->
     Options = proplists:get_value(options, Opts),
     Pid = proplists:get_value(from, Opts),
     Transport =  proplists:get_value(transport, Opts, ssl),
-    ct:log("ssl:listen(~p, ~p)~n", [Port, Options]),
+    ct:log("~p:~p~nssl:listen(~p, ~p)~n", [?MODULE,?LINE, Port, Options]),
     case rpc:call(Node, Transport, listen, [Port, Options]) of
 	{ok, #sslsocket{} = ListenSocket} ->
 	    %% To make sure error_client will
 	    %% get {error, closed} and not {error, connection_refused}
 	    Pid ! {listen, up},
 	    send_selected_port(Pid, Port, ListenSocket),
-	    ct:log("ssl:transport_accept(~p)~n", [ListenSocket]),
+	    ct:log("~p:~p~nssl:transport_accept(~p)~n", [?MODULE,?LINE, ListenSocket]),
 	    case rpc:call(Node, Transport, transport_accept, [ListenSocket]) of
 		{error, _} = Error ->
 		    Pid ! {self(), Error};
 		{ok, AcceptSocket} ->
-		    ct:log("ssl:ssl_accept(~p)~n", [AcceptSocket]),
+		    ct:log("~p:~p~nssl:ssl_accept(~p)~n", [?MODULE,?LINE, AcceptSocket]),
 		    Error = rpc:call(Node, ssl, ssl_accept, [AcceptSocket]),
 		    Pid ! {self(), Error}
 	    end;
 	{ok, ListenSocket} ->
 	    Pid ! {listen, up},
 	    send_selected_port(Pid, Port, ListenSocket),
-	    ct:log("~p:accept(~p)~n", [Transport, ListenSocket]),
+	    ct:log("~p:~p~n~p:accept(~p)~n", [?MODULE,?LINE, Transport, ListenSocket]),
 	     case rpc:call(Node, Transport, accept, [ListenSocket]) of
 		{error, _} = Error ->
 		     Pid ! {self(), Error}
@@ -673,7 +668,7 @@ run_client_error(Opts) ->
     Pid = proplists:get_value(from, Opts),
     Transport = proplists:get_value(transport, Opts, ssl),
     Options = proplists:get_value(options, Opts),
-    ct:log("ssl:connect(~p, ~p, ~p)~n", [Host, Port, Options]),
+    ct:log("~p:~p~nssl:connect(~p, ~p, ~p)~n", [?MODULE,?LINE, Host, Port, Options]),
     Error = rpc:call(Node, Transport, connect, [Host, Port, Options]),
     Pid ! {self(), Error}.
 
@@ -896,7 +891,7 @@ der_to_pem(File, Entries) ->
 
 cipher_result(Socket, Result) ->
     Result = ssl:connection_info(Socket),
-    ct:log("Successfull connect: ~p~n", [Result]),
+    ct:log("~p:~p~nSuccessfull connect: ~p~n", [?MODULE,?LINE, Result]),
     %% Importante to send two packets here
     %% to properly test "cipher state" handling
     ssl:send(Socket, "Hello\n"),
@@ -1065,10 +1060,13 @@ check_sane_openssl_version(Version) ->
 	    true
     end.
 
+enough_openssl_crl_support("OpenSSL 0." ++ _) -> false;
+enough_openssl_crl_support(_) -> true.
+
 wait_for_openssl_server() ->
     receive
 	{Port, {data, Debug}} when is_port(Port) ->
-	    ct:log("openssl ~s~n",[Debug]),
+	    ct:log("~p:~p~nopenssl ~s~n",[?MODULE,?LINE, Debug]),
 	    %% openssl has started make sure
 	    %% it will be in accept. Parsing
 	    %% output is too error prone. (Even