Merge branch 'maint'

* maint:
  ssh: ssh_dbg updates
  ssh: Better reports in some test case failures
  ssh: Tests - timeout catches external ssh that does not disconnect

8 files changed, 67 insertions, 31 deletions

diff --git a/lib/ssh/src/ssh_dbg.erl b/lib/ssh/src/ssh_dbg.erl
index af9ad52d68..eb2c2848f3 100644
--- a/lib/ssh/src/ssh_dbg.erl
+++ b/lib/ssh/src/ssh_dbg.erl
@@ -146,7 +146,26 @@ msg_formater(msg, {trace_ts,_Pid,return_from,{ssh_message,encode,1},_Res,_TS}, D
 msg_formater(msg, {trace_ts,_Pid,call,{ssh_message,decode,_},_TS}, D) ->
     D;
 msg_formater(msg, {trace_ts,Pid,return_from,{ssh_message,decode,1},Msg,TS}, D) -> 
-    fmt("~n~s ~p RECV ~s~n", [ts(TS),Pid,wr_record(shrink_bin(Msg))], D);
+    Extra =
+        case Msg of
+            #ssh_msg_userauth_info_request{data = D0} ->
+                try ssh_message:decode_keyboard_interactive_prompts(D0, [])
+                of
+                    Acc ->
+                        io_lib:format("  -- decoded data:~n", []) ++
+                        element(1,
+                                lists:mapfoldl(
+                                  fun({Prompt,Echo}, N) ->
+                                          {io_lib:format("     prompt[~p]: \"~s\" (echo=~p)~n",[N,Prompt,Echo]), N+1}
+                                  end, 1, Acc))
+                catch
+                    _:_ ->
+                        ""
+                end;
+            _ ->
+                ""
+        end,
+    fmt("~n~s ~p RECV ~s~s~n", [ts(TS),Pid,wr_record(shrink_bin(Msg)),Extra], D);
 
 msg_formater(_auth, {trace_ts,Pid,return_from,{ssh_message,decode,1},#ssh_msg_userauth_failure{authentications=As},TS}, D) -> 
     fmt("~n~s ~p Client login FAILURE. Try ~s~n", [ts(TS),Pid,As], D);
@@ -232,21 +251,22 @@ msg_formater(_, {trace_ts,Pid,return_from, {ssh_transport,known_host_key,3}, Res
     end;
 
 msg_formater(_, {trace_ts,Pid,call,{ssh_auth,publickey_msg,[[SigAlg,#ssh{user=User}]]},TS}, D) ->
-     fmt("~n~s ~p Client will try to login user ~p with public key algorithm ~p~n", [ts(TS),Pid,User,SigAlg], D);
+     fmt("~n~s ~p Client will try to login user ~p with method: public key algorithm ~p~n", [ts(TS),Pid,User,SigAlg], D);
 msg_formater(_, {trace_ts,Pid,return_from,{ssh_auth,publickey_msg,1},{not_ok,#ssh{user=User}},TS}, D) ->
-     fmt("~s ~p User ~p can't login with that kind of public key~n", [ts(TS),Pid,User], D);
-msg_formater(_, {trace_ts,Pid,return_from,{ssh_auth,publickey_msg,1},{_,#ssh{user=User}},TS}, D) ->
-     fmt("~s ~p User ~p logged in~n", [ts(TS),Pid,User], D);
+     fmt("~s ~p User ~p can't use that kind of public key~n", [ts(TS),Pid,User], D);
+msg_formater(_, {trace_ts,_Pid,return_from,{ssh_auth,publickey_msg,1},_,_TS}, D) -> D;
 
 msg_formater(_, {trace_ts,Pid,call,{ssh_auth,password_msg,[[#ssh{user=User}]]},TS}, D) ->
-     fmt("~n~s ~p Client will try to login user ~p with password~n", [ts(TS),Pid,User], D);
+     fmt("~n~s ~p Client will try to login user ~p with method: password~n", [ts(TS),Pid,User], D);
 msg_formater(_, {trace_ts,Pid,return_from,{ssh_auth,password_msg,1},{not_ok,#ssh{user=User}},TS}, D) ->
-     fmt("~s ~p User ~p can't login with password~n", [ts(TS),Pid,User], D);
+     fmt("~s ~p User ~p can't use method password as login method~n", [ts(TS),Pid,User], D);
+msg_formater(_, {trace_ts,_Pid,return_from,{ssh_auth,password_msg,1},_Result,_TS}, D) -> D;
 
 msg_formater(_, {trace_ts,Pid,call,{ssh_auth,keyboard_interactive_msg,[[#ssh{user=User}]]},TS}, D) ->
-     fmt("~n~s ~p Client will try to login user ~p with password~n", [ts(TS),Pid,User], D);
+     fmt("~n~s ~p Client will try to login user ~p with method: keyboard-interactive~n", [ts(TS),Pid,User], D);
 msg_formater(_, {trace_ts,Pid,return_from,{ssh_auth,keyboard_interactive_msg,1},{not_ok,#ssh{user=User}},TS}, D) ->
-     fmt("~s ~p User ~p can't login with keyboard_interactive password~n", [ts(TS),Pid,User], D);
+     fmt("~s ~p User ~p can't use method keyboard-interactive as login method~n", [ts(TS),Pid,User], D);
+msg_formater(_, {trace_ts,_Pid,return_from,{ssh_auth,keyboard_interactive_msg,1},_Result,_TS}, D) -> D;
 
 msg_formater(msg, {trace_ts,Pid,send,{tcp,Sock,Bytes},Pid,TS}, D) ->
     fmt("~n~s ~p TCP SEND on ~p~n ~p~n", [ts(TS),Pid,Sock, shrink_bin(Bytes)], D);
diff --git a/lib/ssh/test/ssh_algorithms_SUITE.erl b/lib/ssh/test/ssh_algorithms_SUITE.erl
index 98964a2c8a..de6e448ebd 100644
--- a/lib/ssh/test/ssh_algorithms_SUITE.erl
+++ b/lib/ssh/test/ssh_algorithms_SUITE.erl
@@ -29,15 +29,13 @@
 %% Note: This directive should only be used in test suites.
 -compile(export_all).
 
--define(TIMEOUT, 35000).
-
 %%--------------------------------------------------------------------
 %% Common Test interface functions -----------------------------------
 %%--------------------------------------------------------------------
 
 suite() ->
     [{ct_hooks,[ts_install_cth]},
-     {timetrap,{seconds,40}}].
+     {timetrap,{seconds,round(1.5*?TIMEOUT/1000)}}].
 
 all() -> 
     %% [{group,kex},{group,cipher}... etc
@@ -90,7 +88,7 @@ init_per_suite(Config) ->
 		  " -- Max num algorithms: ~p~n"
 		 ,[os:getenv("HOME"),
 		   init:get_argument(home),
-		   os:cmd("ssh -V"),
+		   ssh_test_lib:installed_ssh_version("TIMEOUT"),
 		   ssh:default_algorithms(),
 		   crypto:info_lib(),
 		   ssh_test_lib:default_algorithms(sshc),
@@ -318,10 +316,10 @@ sshc_simple_exec_os_cmd(Config) ->
 		    ok;
 		false ->
 		    ct:log("Bad result: ~p~nExpected: ~p~nMangled result: ~p", [RawResult,Expect,Lines]),
-		    {fail, "Bad result"}
+		    {fail, "Bad result (see log in testcase)"}
 	    end
     after ?TIMEOUT ->
-	    ct:fail("Did not receive answer")
+	    ct:fail("Did not receive answer (timeout)")
     end.
 
 %%--------------------------------------------------------------------
diff --git a/lib/ssh/test/ssh_connection_SUITE.erl b/lib/ssh/test/ssh_connection_SUITE.erl
index 9bbd9da817..ba4518cfe6 100644
--- a/lib/ssh/test/ssh_connection_SUITE.erl
+++ b/lib/ssh/test/ssh_connection_SUITE.erl
@@ -91,7 +91,7 @@ end_per_suite(Config) ->
 init_per_group(openssh, Config) ->
     case ssh_test_lib:gen_tcp_connect("localhost", 22, []) of
 	{error,econnrefused} ->
-	    {skip,"No openssh deamon"};
+	    {skip,"No openssh deamon (econnrefused)"};
 	{ok, Socket} ->
 	    gen_tcp:close(Socket),
 	    ssh_test_lib:openssh_sanity_check(Config)
diff --git a/lib/ssh/test/ssh_sftp_SUITE.erl b/lib/ssh/test/ssh_sftp_SUITE.erl
index 7aa3d8a00a..c2f9c0eba8 100644
--- a/lib/ssh/test/ssh_sftp_SUITE.erl
+++ b/lib/ssh/test/ssh_sftp_SUITE.erl
@@ -181,8 +181,9 @@ init_per_group(openssh_server, Config) ->
 	    [{peer, {fmt_host(IPx),Portx}}, {group, openssh_server} | Config];
 	{error,"Key exchange failed"} ->
 	    {skip, "openssh server doesn't support the tested kex algorithm"};
-	_ ->
-	    {skip, "No openssh server"} 
+	Other ->
+            ct:log("No openssh server. Cause:~n~p~n",[Other]),
+	    {skip, "No openssh daemon (see log in testcase)"} 
     end;
 
 init_per_group(remote_tar, Config) ->
diff --git a/lib/ssh/test/ssh_sftpd_SUITE.erl b/lib/ssh/test/ssh_sftpd_SUITE.erl
index 763649a12f..5fc948fbed 100644
--- a/lib/ssh/test/ssh_sftpd_SUITE.erl
+++ b/lib/ssh/test/ssh_sftpd_SUITE.erl
@@ -34,7 +34,7 @@
 -define(PASSWD, "Sesame").
 -define(XFER_PACKET_SIZE, 32768).
 -define(XFER_WINDOW_SIZE, 4*?XFER_PACKET_SIZE).
--define(TIMEOUT, 10000).
+-define(SSH_TIMEOUT, 10000).
 -define(REG_ATTERS, <<0,0,0,0,1>>).
 -define(UNIX_EPOCH,  62167219200).
 
@@ -161,9 +161,9 @@ init_per_testcase(TestCase, Config) ->
 			       {silently_accept_hosts, true}]),
     {ok, Channel} =
 	ssh_connection:session_channel(Cm, ?XFER_WINDOW_SIZE,
-				       ?XFER_PACKET_SIZE, ?TIMEOUT),
+				       ?XFER_PACKET_SIZE, ?SSH_TIMEOUT),
     
-    success = ssh_connection:subsystem(Cm, Channel, "sftp", ?TIMEOUT),
+    success = ssh_connection:subsystem(Cm, Channel, "sftp", ?SSH_TIMEOUT),
 
     ProtocolVer = case atom_to_list(TestCase) of
 		      "ver3_" ++ _ ->
diff --git a/lib/ssh/test/ssh_test_lib.erl b/lib/ssh/test/ssh_test_lib.erl
index 83819b97a5..2d7bf75847 100644
--- a/lib/ssh/test/ssh_test_lib.erl
+++ b/lib/ssh/test/ssh_test_lib.erl
@@ -28,9 +28,7 @@
 -include_lib("public_key/include/public_key.hrl").
 -include_lib("common_test/include/ct.hrl").
 -include_lib("ssh/src/ssh_transport.hrl").
-
-
--define(TIMEOUT, 50000).
+-include("ssh_test_lib.hrl").
 
 %%%----------------------------------------------------------------
 connect(Port, Options) when is_integer(Port) ->
@@ -600,6 +598,7 @@ check_ssh_client_support2(P) ->
 	{P, {data, _A}} ->
 	    check_ssh_client_support2(P);
 	{P, {exit_status, E}} ->
+            ct:log("~p:~p exit_status:~n~p",[?MODULE,?LINE,E]),
 	    E
     after 5000 ->
 	    ct:log("Openssh command timed out ~n"),
@@ -651,14 +650,14 @@ default_algorithms(sshc, DaemonOptions) ->
 	{hostport,Srvr,{_Host,Port}} ->
 	    spawn(fun()-> os:cmd(lists:concat(["ssh -o \"StrictHostKeyChecking no\" -p ",Port," localhost"])) end)
     after ?TIMEOUT ->
-	    ct:fail("No server respons 1")
+	    ct:fail("No server respons (timeout) 1")
     end,
 
     receive
 	{result,Srvr,L} ->
 	    L
     after ?TIMEOUT ->
-	    ct:fail("No server respons 2")
+	    ct:fail("No server respons (timeout) 2")
     end.
 
 run_fake_ssh({ok,InitialState}) ->
@@ -772,12 +771,12 @@ ssh_type1() ->
 		not_found;
 	    Path ->
 		ct:log("~p:~p Found \"ssh\" at ~p",[?MODULE,?LINE,Path]),
-		case os:cmd("ssh -V") of
+                case installed_ssh_version(timeout) of
 		    Version = "OpenSSH" ++ _ ->
                         ct:log("~p:~p Found OpenSSH  ~p",[?MODULE,?LINE,Version]),
 			openSSH;
-		    Str -> 
-			ct:log("ssh client ~p is unknown",[Str]),
+                    Other ->
+			ct:log("ssh client ~p is unknown",[Other]),
 			unknown
 		end
 	end
@@ -787,6 +786,20 @@ ssh_type1() ->
 	    not_found
     end.
 
+installed_ssh_version(TimeoutReturn) ->
+    Parent = self(),
+    Pid = spawn(fun() ->
+                        Parent ! {open_ssh_version, os:cmd("ssh -V")}
+                end),
+    receive
+        {open_ssh_version, V} ->
+            V
+    after ?TIMEOUT ->
+            exit(Pid, kill),
+            TimeoutReturn
+    end.
+
+
 		   
 
 algo_intersection([], _) -> [];
diff --git a/lib/ssh/test/ssh_test_lib.hrl b/lib/ssh/test/ssh_test_lib.hrl
index 54c93b7e87..eaf856e6e8 100644
--- a/lib/ssh/test/ssh_test_lib.hrl
+++ b/lib/ssh/test/ssh_test_lib.hrl
@@ -1,4 +1,9 @@
 %%-------------------------------------------------------------------------
+%% Timeout time in ms
+%%-------------------------------------------------------------------------
+-define(TIMEOUT, 27000).
+
+%%-------------------------------------------------------------------------
 %% Check for usable crypt 
 %%-------------------------------------------------------------------------
 -define(CHECK_CRYPTO(Available),
diff --git a/lib/ssh/test/ssh_to_openssh_SUITE.erl b/lib/ssh/test/ssh_to_openssh_SUITE.erl
index 75d5b5e296..b20764ce47 100644
--- a/lib/ssh/test/ssh_to_openssh_SUITE.erl
+++ b/lib/ssh/test/ssh_to_openssh_SUITE.erl
@@ -27,7 +27,6 @@
 %% Note: This directive should only be used in test suites.
 -compile(export_all).
 
--define(TIMEOUT, 50000).
 -define(SSH_DEFAULT_PORT, 22).
 -define(REKEY_DATA_TMO, 65000).
 
@@ -69,7 +68,7 @@ init_per_suite(Config) ->
     ?CHECK_CRYPTO(
        case gen_tcp:connect("localhost", 22, []) of
 	   {error,econnrefused} ->
-	       {skip,"No openssh deamon"};
+	       {skip,"No openssh deamon (econnrefused)"};
 	   _ ->
 	       ssh_test_lib:openssh_sanity_check(Config)
        end