aboutsummaryrefslogtreecommitdiffstats
path: root/lib/ssh/src/ssh_connection_handler.erl
diff options
context:
space:
mode:
authorHans Nilsson <[email protected]>2018-02-28 16:47:20 +0100
committerHans Nilsson <[email protected]>2018-03-29 11:58:28 +0200
commit3715deff44f38aa35873106cd1f116c74c65040a (patch)
tree858ee3c036609eab1f717c5fd42a9b606465026a /lib/ssh/src/ssh_connection_handler.erl
parent3352eaf189c55e60778fc76b94530fac0c314fba (diff)
downloadotp-3715deff44f38aa35873106cd1f116c74c65040a.tar.gz
otp-3715deff44f38aa35873106cd1f116c74c65040a.tar.bz2
otp-3715deff44f38aa35873106cd1f116c74c65040a.zip
ssh: Use the new ssh_dbg module
Diffstat (limited to 'lib/ssh/src/ssh_connection_handler.erl')
-rw-r--r--lib/ssh/src/ssh_connection_handler.erl614
1 files changed, 437 insertions, 177 deletions
diff --git a/lib/ssh/src/ssh_connection_handler.erl b/lib/ssh/src/ssh_connection_handler.erl
index 907ecef860..4261e5bf13 100644
--- a/lib/ssh/src/ssh_connection_handler.erl
+++ b/lib/ssh/src/ssh_connection_handler.erl
@@ -56,7 +56,7 @@
connection_info/2,
channel_info/3,
adjust_window/3, close/2,
- disconnect/1, disconnect/2,
+ disconnect/4,
get_print_info/1
]).
@@ -71,6 +71,18 @@
renegotiate/1, renegotiate_data/1, alg/1 % Export intended for test cases
]).
+-export([dbg_trace/3]).
+
+
+-define(send_disconnect(Code, DetailedText, StateName, State),
+ send_disconnect(Code, DetailedText, ?MODULE, ?LINE, StateName, State)).
+
+-define(send_disconnect(Code, Reason, DetailedText, StateName, State),
+ send_disconnect(Code, Reason, DetailedText, ?MODULE, ?LINE, StateName, State)).
+
+-define(call_disconnectfun_and_log_cond(LogMsg, DetailedText, StateName, D),
+ call_disconnectfun_and_log_cond(LogMsg, DetailedText, ?MODULE, ?LINE, StateName, D)).
+
%%====================================================================
%% Start / stop
%%====================================================================
@@ -149,17 +161,16 @@ start_connection(server = Role, Socket, Options, Timeout) ->
%%--------------------------------------------------------------------
%%% Some other module has decided to disconnect.
--spec disconnect(#ssh_msg_disconnect{}) -> no_return().
--spec disconnect(#ssh_msg_disconnect{}, iodata()) -> no_return().
+
+-spec disconnect(Code::integer(), Details::iodata(),
+ Module::atom(), Line::integer()) -> no_return().
%% . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
-disconnect(Msg = #ssh_msg_disconnect{}) ->
- throw({keep_state_and_data,
- [{next_event, internal, {disconnect, Msg, Msg#ssh_msg_disconnect.description}}]}).
-disconnect(Msg = #ssh_msg_disconnect{}, ExtraInfo) ->
- throw({keep_state_and_data,
- [{next_event, internal, {disconnect, Msg, {Msg#ssh_msg_disconnect.description,ExtraInfo}}}]}).
+% Preferable called with the macro ?DISCONNECT
+disconnect(Code, DetailedText, Module, Line) ->
+ throw({keep_state_and_data,
+ [{next_event, internal, {send_disconnect, Code, DetailedText, Module, Line}}]}).
%%--------------------------------------------------------------------
-spec open_channel(connection_ref(),
@@ -445,7 +456,7 @@ init_ssh_record(Role, Socket, Opts) ->
{ok,PeerAddr} = inet:peername(Socket),
init_ssh_record(Role, Socket, PeerAddr, Opts).
-init_ssh_record(Role, _Socket, PeerAddr, Opts) ->
+init_ssh_record(Role, Socket, PeerAddr, Opts) ->
AuthMethods = ?GET_OPT(auth_methods, Opts),
S0 = #ssh{role = Role,
key_cb = ?GET_OPT(key_cb, Opts),
@@ -456,6 +467,10 @@ init_ssh_record(Role, _Socket, PeerAddr, Opts) ->
},
{Vsn, Version} = ssh_transport:versions(Role, Opts),
+ LocalName = case inet:sockname(Socket) of
+ {ok,Local} -> Local;
+ _ -> undefined
+ end,
case Role of
client ->
PeerName = case ?GET_INTERNAL_OPT(host, Opts) of
@@ -474,7 +489,8 @@ init_ssh_record(Role, _Socket, PeerAddr, Opts) ->
false -> ssh_no_io
end,
userauth_quiet_mode = ?GET_OPT(quiet_mode, Opts),
- peer = {PeerName, PeerAddr}
+ peer = {PeerName, PeerAddr},
+ local = LocalName
},
S1#ssh{userauth_pubkeys = [K || K <- ?GET_OPT(pref_public_key_algs, Opts),
is_usable_user_pubkey(K, S1)
@@ -487,7 +503,8 @@ init_ssh_record(Role, _Socket, PeerAddr, Opts) ->
io_cb = ?GET_INTERNAL_OPT(io_cb, Opts, ssh_io),
userauth_methods = string:tokens(AuthMethods, ","),
kb_tries_left = 3,
- peer = {undefined, PeerAddr}
+ peer = {undefined, PeerAddr},
+ local = LocalName
}
end.
@@ -545,7 +562,7 @@ callback_mode() ->
handle_event_function.
-handle_event(_, _Event, {init_error,Error}, _) ->
+handle_event(_, _Event, {init_error,Error}=StateName, D) ->
case Error of
enotconn ->
%% Handles the abnormal sequence:
@@ -553,6 +570,9 @@ handle_event(_, _Event, {init_error,Error}, _) ->
%% <-SYNACK
%% ACK->
%% RST->
+ ?call_disconnectfun_and_log_cond("Protocol Error",
+ "TCP connenction to server was prematurely closed by the client",
+ StateName, D),
{stop, {shutdown,"TCP connenction to server was prematurely closed by the client"}};
OtherError ->
@@ -561,7 +581,7 @@ handle_event(_, _Event, {init_error,Error}, _) ->
%%% ######## {hello, client|server} ####
%% The very first event that is sent when the we are set as controlling process of Socket
-handle_event(_, socket_control, {hello,_}, D) ->
+handle_event(_, socket_control, {hello,_}=StateName, D) ->
VsnMsg = ssh_transport:hello_version_msg(string_version(D#data.ssh_params)),
send_bytes(VsnMsg, D),
case inet:getopts(Socket=D#data.socket, [recbuf]) of
@@ -576,10 +596,13 @@ handle_event(_, socket_control, {hello,_}, D) ->
{keep_state, D#data{inet_initial_recbuf_size=Size}};
Other ->
+ ?call_disconnectfun_and_log_cond("Option return",
+ io_lib:format("Unexpected getopts return:~n ~p",[Other]),
+ StateName, D),
{stop, {shutdown,{unexpected_getopts_return, Other}}}
end;
-handle_event(_, {info_line,_Line}, {hello,Role}, D) ->
+handle_event(_, {info_line,_Line}, {hello,Role}=StateName, D) ->
case Role of
client ->
%% The server may send info lines to the client before the version_exchange
@@ -590,28 +613,33 @@ handle_event(_, {info_line,_Line}, {hello,Role}, D) ->
%% But the client may NOT send them to the server. Openssh answers with cleartext,
%% and so do we
send_bytes("Protocol mismatch.", D),
+ ?call_disconnectfun_and_log_cond("Protocol mismatch.",
+ "Protocol mismatch in version exchange. Client sent info lines.",
+ StateName, D),
{stop, {shutdown,"Protocol mismatch in version exchange. Client sent info lines."}}
end;
-handle_event(_, {version_exchange,Version}, {hello,Role}, D) ->
+handle_event(_, {version_exchange,Version}, {hello,Role}, D0) ->
{NumVsn, StrVsn} = ssh_transport:handle_hello_version(Version),
- case handle_version(NumVsn, StrVsn, D#data.ssh_params) of
+ case handle_version(NumVsn, StrVsn, D0#data.ssh_params) of
{ok, Ssh1} ->
%% Since the hello part is finnished correctly, we set the
%% socket to the packet handling mode (including recbuf size):
- inet:setopts(D#data.socket, [{packet,0},
+ inet:setopts(D0#data.socket, [{packet,0},
{mode,binary},
{active, once},
- {recbuf, D#data.inet_initial_recbuf_size}]),
+ {recbuf, D0#data.inet_initial_recbuf_size}]),
{KeyInitMsg, SshPacket, Ssh} = ssh_transport:key_exchange_init_msg(Ssh1),
- send_bytes(SshPacket, D),
- {next_state, {kexinit,Role,init}, D#data{ssh_params = Ssh,
+ send_bytes(SshPacket, D0),
+ {next_state, {kexinit,Role,init}, D0#data{ssh_params = Ssh,
key_exchange_init_msg = KeyInitMsg}};
not_supported ->
- disconnect(
- #ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_VERSION_NOT_SUPPORTED,
- description = ["Protocol version ",StrVsn," not supported"]},
- {next_state, {hello,Role}, D})
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_VERSION_NOT_SUPPORTED,
+ io_lib:format("Offending version is ~p",[string:chomp(Version)]),
+ {hello,Role},
+ D0),
+ {stop, Shutdown, D}
end;
@@ -757,18 +785,20 @@ handle_event(internal, Msg, {ext_info,Role,_ReNegFlag}, D) when is_tuple(Msg) ->
%%% ######## {service_request, client|server} ####
-handle_event(_, Msg = #ssh_msg_service_request{name=ServiceName}, StateName = {service_request,server}, D) ->
+handle_event(_, Msg = #ssh_msg_service_request{name=ServiceName}, StateName = {service_request,server}, D0) ->
case ServiceName of
"ssh-userauth" ->
- Ssh0 = #ssh{session_id=SessionId} = D#data.ssh_params,
+ Ssh0 = #ssh{session_id=SessionId} = D0#data.ssh_params,
{ok, {Reply, Ssh}} = ssh_auth:handle_userauth_request(Msg, SessionId, Ssh0),
- send_bytes(Reply, D),
- {next_state, {userauth,server}, D#data{ssh_params = Ssh}};
+ send_bytes(Reply, D0),
+ {next_state, {userauth,server}, D0#data{ssh_params = Ssh}};
_ ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_SERVICE_NOT_AVAILABLE,
- description = "Unknown service"},
- StateName, D)
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_SERVICE_NOT_AVAILABLE,
+ io_lib:format("Unknown service: ~p",[ServiceName]),
+ StateName, D0),
+ {stop, Shutdown, D}
end;
handle_event(_, #ssh_msg_service_accept{name = "ssh-userauth"}, {service_request,client},
@@ -784,15 +814,15 @@ handle_event(_, #ssh_msg_service_accept{name = "ssh-userauth"}, {service_request
handle_event(_,
Msg = #ssh_msg_userauth_request{service = ServiceName, method = Method},
StateName = {userauth,server},
- D = #data{ssh_params=Ssh0}) ->
+ D0 = #data{ssh_params=Ssh0}) ->
case {ServiceName, Ssh0#ssh.service, Method} of
{"ssh-connection", "ssh-connection", "none"} ->
%% Probably the very first userauth_request but we deny unauthorized login
{not_authorized, _, {Reply,Ssh}} =
ssh_auth:handle_userauth_request(Msg, Ssh0#ssh.session_id, Ssh0),
- send_bytes(Reply, D),
- {keep_state, D#data{ssh_params = Ssh}};
+ send_bytes(Reply, D0),
+ {keep_state, D0#data{ssh_params = Ssh}};
{"ssh-connection", "ssh-connection", Method} ->
%% Userauth request with a method like "password" or so
@@ -801,20 +831,20 @@ handle_event(_,
%% Yepp! we support this method
case ssh_auth:handle_userauth_request(Msg, Ssh0#ssh.session_id, Ssh0) of
{authorized, User, {Reply, Ssh}} ->
- send_bytes(Reply, D),
- D#data.starter ! ssh_connected,
- connected_fun(User, Method, D),
+ send_bytes(Reply, D0),
+ D0#data.starter ! ssh_connected,
+ connected_fun(User, Method, D0),
{next_state, {connected,server},
- D#data{auth_user = User,
+ D0#data{auth_user = User,
ssh_params = Ssh#ssh{authenticated = true}}};
{not_authorized, {User, Reason}, {Reply, Ssh}} when Method == "keyboard-interactive" ->
- retry_fun(User, Reason, D),
- send_bytes(Reply, D),
- {next_state, {userauth_keyboard_interactive,server}, D#data{ssh_params = Ssh}};
+ retry_fun(User, Reason, D0),
+ send_bytes(Reply, D0),
+ {next_state, {userauth_keyboard_interactive,server}, D0#data{ssh_params = Ssh}};
{not_authorized, {User, Reason}, {Reply, Ssh}} ->
- retry_fun(User, Reason, D),
- send_bytes(Reply, D),
- {keep_state, D#data{ssh_params = Ssh}}
+ retry_fun(User, Reason, D0),
+ send_bytes(Reply, D0),
+ {keep_state, D0#data{ssh_params = Ssh}}
end;
false ->
%% No we do not support this method (=/= none)
@@ -828,9 +858,11 @@ handle_event(_,
%% {ServiceName, Expected, Method} when Expected =/= ServiceName -> Do what?
{ServiceName, _, _} when ServiceName =/= "ssh-connection" ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_SERVICE_NOT_AVAILABLE,
- description = "Unknown service"},
- StateName, D)
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_SERVICE_NOT_AVAILABLE,
+ io_lib:format("Unknown service: ~p",[ServiceName]),
+ StateName, D0),
+ {stop, Shutdown, D}
end;
%%---- userauth success to client
@@ -846,14 +878,14 @@ handle_event(_, #ssh_msg_userauth_success{}, {userauth,client}, D=#data{ssh_para
%%---- userauth failure response to client
handle_event(_, #ssh_msg_userauth_failure{}, {userauth,client}=StateName,
- D = #data{ssh_params = #ssh{userauth_methods = []}}) ->
- Msg = #ssh_msg_disconnect{code = ?SSH_DISCONNECT_NO_MORE_AUTH_METHODS_AVAILABLE,
- description = "Unable to connect using the available"
- " authentication methods"},
- disconnect(Msg, StateName, D);
-
+ #data{ssh_params = #ssh{userauth_methods = []}} = D0) ->
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_NO_MORE_AUTH_METHODS_AVAILABLE,
+ io_lib:format("User auth failed for: ~p",[D0#data.auth_user]),
+ StateName, D0),
+ {stop, Shutdown, D};
handle_event(_, #ssh_msg_userauth_failure{authentications = Methods}, StateName={userauth,client},
- D = #data{ssh_params = Ssh0}) ->
+ D0 = #data{ssh_params = Ssh0}) ->
%% The prefered authentication method failed try next method
Ssh1 = case Ssh0#ssh.userauth_methods of
none ->
@@ -864,15 +896,18 @@ handle_event(_, #ssh_msg_userauth_failure{authentications = Methods}, StateName=
Ssh0
end,
case ssh_auth:userauth_request_msg(Ssh1) of
- {disconnect, DisconnectMsg, {Msg, Ssh}} ->
- send_bytes(Msg, D),
- disconnect(DisconnectMsg, StateName, D#data{ssh_params = Ssh});
+ {send_disconnect, Code, Ssh} ->
+ {Shutdown, D} =
+ ?send_disconnect(Code,
+ io_lib:format("User auth failed for: ~p",[D0#data.auth_user]),
+ StateName, D0#data{ssh_params = Ssh}),
+ {stop, Shutdown, D};
{"keyboard-interactive", {Msg, Ssh}} ->
- send_bytes(Msg, D),
- {next_state, {userauth_keyboard_interactive,client}, D#data{ssh_params = Ssh}};
+ send_bytes(Msg, D0),
+ {next_state, {userauth_keyboard_interactive,client}, D0#data{ssh_params = Ssh}};
{_Method, {Msg, Ssh}} ->
- send_bytes(Msg, D),
- {keep_state, D#data{ssh_params = Ssh}}
+ send_bytes(Msg, D0),
+ {keep_state, D0#data{ssh_params = Ssh}}
end;
%%---- banner to client
@@ -966,7 +1001,7 @@ handle_event(_, #ssh_msg_disconnect{description=Desc} = Msg, StateName, D0) ->
{disconnect, _, RepliesCon} =
ssh_connection:handle_msg(Msg, D0#data.connection_state, role(StateName)),
{Actions,D} = send_replies(RepliesCon, D0),
- disconnect_fun(Desc, D),
+ disconnect_fun("Received disconnect: "++Desc, D),
{stop_and_reply, {shutdown,Desc}, Actions, D};
handle_event(_, #ssh_msg_ignore{}, _, _) ->
@@ -1288,29 +1323,32 @@ handle_event(info, {Proto, Sock, NewData}, StateName, D0 = #data{socket = Sock,
D0#data.ssh_params)
of
{packet_decrypted, DecryptedBytes, EncryptedDataRest, Ssh1} ->
- D = D0#data{ssh_params =
+ D1 = D0#data{ssh_params =
Ssh1#ssh{recv_sequence = ssh_transport:next_seqnum(Ssh1#ssh.recv_sequence)},
decrypted_data_buffer = <<>>,
undecrypted_packet_length = undefined,
encrypted_data_buffer = EncryptedDataRest},
try
- ssh_message:decode(set_kex_overload_prefix(DecryptedBytes,D))
+ ssh_message:decode(set_kex_overload_prefix(DecryptedBytes,D1))
of
Msg = #ssh_msg_kexinit{} ->
- {keep_state, D, [{next_event, internal, prepare_next_packet},
+ {keep_state, D1, [{next_event, internal, prepare_next_packet},
{next_event, internal, {Msg,DecryptedBytes}}
]};
Msg ->
- {keep_state, D, [{next_event, internal, prepare_next_packet},
+ {keep_state, D1, [{next_event, internal, prepare_next_packet},
{next_event, internal, Msg}
]}
catch
- _C:_E ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_ERROR,
- description = "Bad packet"},
- StateName, D)
+ C:E ->
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_ERROR,
+ io_lib:format("Bad packet: Decrypted, but can't decode~n~p:~p~n~p",
+ [C,E,erlang:get_stacktrace()]),
+ StateName, D1),
+ {stop, Shutdown, D}
end;
-
+
{get_more, DecryptedBytes, EncryptedDataRest, RemainingSshPacketLen, Ssh1} ->
%% Here we know that there are not enough bytes in
%% EncryptedDataRest to use. We must wait for more.
@@ -1321,19 +1359,26 @@ handle_event(info, {Proto, Sock, NewData}, StateName, D0 = #data{socket = Sock,
ssh_params = Ssh1}};
{bad_mac, Ssh1} ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_ERROR,
- description = "Bad packet"},
- StateName, D0#data{ssh_params=Ssh1});
-
- {error, {exceeds_max_size,_PacketLen}} ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_ERROR,
- description = "Bad packet"},
- StateName, D0)
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_ERROR,
+ "Bad packet: bad mac",
+ StateName, D0#data{ssh_params=Ssh1}),
+ {stop, Shutdown, D};
+
+ {error, {exceeds_max_size,PacketLen}} ->
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_ERROR,
+ io_lib:format("Bad packet: Size (~p bytes) exceeds max size",
+ [PacketLen]),
+ StateName, D0),
+ {stop, Shutdown, D}
catch
- _C:_E ->
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_ERROR,
- description = "Bad packet"},
- StateName, D0)
+ C:E ->
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_ERROR,
+ io_lib:format("Bad packet: Couldn't decrypt~n~p:~p~n~p",[C,E,erlang:get_stacktrace()]),
+ StateName, D0),
+ {stop, Shutdown, D}
end;
@@ -1349,15 +1394,13 @@ handle_event(internal, prepare_next_packet, _, D) ->
inet:setopts(D#data.socket, [{active, once}]),
keep_state_and_data;
-handle_event(info, {CloseTag,Socket}, StateName,
- D = #data{socket = Socket,
- transport_close_tag = CloseTag}) ->
- %% Simulate a disconnect from the peer
- handle_event(info,
- #ssh_msg_disconnect{code = ?SSH_DISCONNECT_BY_APPLICATION,
- description = "Connection closed"},
- StateName,
- D);
+handle_event(info, {CloseTag,Socket}, _StateName,
+ D0 = #data{socket = Socket,
+ transport_close_tag = CloseTag,
+ connection_state = C0}) ->
+ {Repls, D} = send_replies(ssh_connection:handle_stop(C0), D0),
+ disconnect_fun("Received a transport close", D),
+ {stop_and_reply, {shutdown,"Connection closed"}, Repls, D};
handle_event(info, {timeout, {_, From} = Request}, _,
#data{connection_state = #connection{requests = Requests} = C0} = D) ->
@@ -1423,25 +1466,26 @@ handle_event(info, UnexpectedMessage, StateName, D = #data{ssh_params = Ssh}) ->
keep_state_and_data
end;
-handle_event(internal, {disconnect,Msg,_Reason}, StateName, D) ->
- disconnect(Msg, StateName, D);
+handle_event(internal, {send_disconnect,Code,DetailedText,Module,Line}, StateName, D0) ->
+ {Shutdown, D} =
+ send_disconnect(Code, DetailedText, Module, Line, StateName, D0),
+ {stop, Shutdown, D};
handle_event(_Type, _Msg, {ext_info,Role,_ReNegFlag}, D) ->
%% If something else arrives, goto next state and handle the event in that one
{next_state, {connected,Role}, D, [postpone]};
-handle_event(Type, Ev, StateName, D) ->
- Descr =
+handle_event(Type, Ev, StateName, D0) ->
+ Details =
case catch atom_to_list(element(1,Ev)) of
"ssh_msg_" ++_ when Type==internal ->
-%% "Message in wrong state";
lists:flatten(io_lib:format("Message ~p in wrong state (~p)", [element(1,Ev), StateName]));
_ ->
- "Internal error"
+ io_lib:format("Unhandled event in state ~p:~n~p", [StateName,Ev])
end,
- disconnect(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_PROTOCOL_ERROR,
- description = Descr},
- StateName, D).
+ {Shutdown, D} =
+ ?send_disconnect(?SSH_DISCONNECT_PROTOCOL_ERROR, Details, StateName, D0),
+ {stop, Shutdown, D}.
%%--------------------------------------------------------------------
@@ -1452,39 +1496,49 @@ handle_event(Type, Ev, StateName, D) ->
%% . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
-terminate(normal, StateName, State) ->
- stop_subsystem(State),
- close_transport(State);
+terminate(normal, _StateName, D) ->
+ stop_subsystem(D),
+ close_transport(D);
+
+terminate({shutdown,"Connection closed"}, _StateName, D) ->
+ %% Normal: terminated by a sent by peer
+ stop_subsystem(D),
+ close_transport(D);
-terminate({shutdown,{init,Reason}}, StateName, State) ->
- error_logger:info_report(io_lib:format("Erlang ssh in connection handler init: ~p~n",[Reason])),
- stop_subsystem(State),
- close_transport(State);
+terminate({shutdown,{init,Reason}}, StateName, D) ->
+ %% Error in initiation. "This error should not occur".
+ log(error, D, io_lib:format("Shutdown in init (StateName=~p): ~p~n",[StateName,Reason])),
+ stop_subsystem(D),
+ close_transport(D);
-terminate(shutdown, StateName, State0) ->
+terminate({shutdown,_R}, _StateName, D) ->
+ %% Internal termination, usually already reported via ?send_disconnect resulting in a log entry
+ stop_subsystem(D),
+ close_transport(D);
+
+terminate(shutdown, _StateName, D0) ->
%% Terminated by supervisor
- State = send_msg(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_BY_APPLICATION,
- description = "Application shutdown"},
- State0),
- close_transport(State);
-
-terminate({shutdown,_R}, StateName, State) ->
- %% Internal termination
- stop_subsystem(State),
- close_transport(State);
-
-terminate(kill, StateName, State) ->
- stop_subsystem(State),
- close_transport(State);
-
-terminate(Reason, StateName, State0) ->
- %% Others, e.g undef, {badmatch,_}
- log_error(Reason),
- State = send_msg(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_BY_APPLICATION,
- description = "Internal error"},
- State0),
- stop_subsystem(State),
- close_transport(State).
+ %% Use send_msg directly instead of ?send_disconnect to avoid filling the log
+ D = send_msg(#ssh_msg_disconnect{code = ?SSH_DISCONNECT_BY_APPLICATION,
+ description = "Terminated (shutdown) by supervisor"},
+ D0),
+ stop_subsystem(D),
+ close_transport(D);
+
+terminate(kill, _StateName, D) ->
+ %% Got a kill signal
+ stop_subsystem(D),
+ close_transport(D);
+
+terminate(Reason, StateName, D0) ->
+ %% Others, e.g undef, {badmatch,_}, ...
+ log(error, D0, Reason),
+ {_ShutdownReason, D} = ?send_disconnect(?SSH_DISCONNECT_BY_APPLICATION,
+ "Internal error",
+ io_lib:format("Reason: ~p",[Reason]),
+ StateName, D0),
+ stop_subsystem(D),
+ close_transport(D).
%%--------------------------------------------------------------------
@@ -1493,36 +1547,41 @@ terminate(Reason, StateName, State0) ->
format_status(normal, [_, _StateName, D]) ->
[{data, [{"State", D}]}];
format_status(terminate, [_, _StateName, D]) ->
- DataPropList0 = fmt_stat_rec(record_info(fields, data), D,
- [decrypted_data_buffer,
- encrypted_data_buffer,
- key_exchange_init_msg,
- user_passwords,
- opts,
- inet_initial_recbuf_size]),
- SshPropList = fmt_stat_rec(record_info(fields, ssh), D#data.ssh_params,
- [c_keyinit,
- s_keyinit,
- send_mac_key,
- send_mac_size,
- recv_mac_key,
- recv_mac_size,
- encrypt_keys,
- encrypt_ctx,
- decrypt_keys,
- decrypt_ctx,
- compress_ctx,
- decompress_ctx,
- shared_secret,
- exchanged_hash,
- session_id,
- keyex_key,
- keyex_info,
- available_host_keys]),
- DataPropList = lists:keyreplace(ssh_params, 1, DataPropList0,
- {ssh_params,SshPropList}),
- [{data, [{"State", DataPropList}]}].
-
+ [{data, [{"State", state_data2proplist(D)}]}].
+
+
+state_data2proplist(D) ->
+ DataPropList0 =
+ fmt_stat_rec(record_info(fields, data), D,
+ [decrypted_data_buffer,
+ encrypted_data_buffer,
+ key_exchange_init_msg,
+ user_passwords,
+ opts,
+ inet_initial_recbuf_size]),
+ SshPropList =
+ fmt_stat_rec(record_info(fields, ssh), D#data.ssh_params,
+ [c_keyinit,
+ s_keyinit,
+ send_mac_key,
+ send_mac_size,
+ recv_mac_key,
+ recv_mac_size,
+ encrypt_keys,
+ encrypt_ctx,
+ decrypt_keys,
+ decrypt_ctx,
+ compress_ctx,
+ decompress_ctx,
+ shared_secret,
+ exchanged_hash,
+ session_id,
+ keyex_key,
+ keyex_info,
+ available_host_keys]),
+ lists:keyreplace(ssh_params, 1, DataPropList0,
+ {ssh_params,SshPropList}).
+
fmt_stat_rec(FieldNames, Rec, Exclude) ->
Values = tl(tuple_to_list(Rec)),
@@ -1847,11 +1906,49 @@ new_channel_id(#data{connection_state = #connection{channel_id_seed = Id} =
Connection#connection{channel_id_seed = Id + 1}}}.
%%%----------------------------------------------------------------
-%% %%% This server/client has decided to disconnect via the state machine:
-disconnect(Msg=#ssh_msg_disconnect{description=Description}, _StateName, State0) ->
- State = send_msg(Msg, State0),
- disconnect_fun(Description, State),
- {stop, {shutdown,Description}, State}.
+%%% This server/client has decided to disconnect via the state machine:
+%%% The unused arguments are for debugging.
+
+send_disconnect(Code, DetailedText, Module, Line, StateName, D) ->
+ send_disconnect(Code, default_text(Code), DetailedText, Module, Line, StateName, D).
+
+send_disconnect(Code, Reason, DetailedText, Module, Line, StateName, D0) ->
+ Msg = #ssh_msg_disconnect{code = Code,
+ description = Reason},
+ D = send_msg(Msg, D0),
+ LogMsg = io_lib:format("Disconnects with code = ~p [RFC4253 11.1]: ~s",[Code,Reason]),
+ call_disconnectfun_and_log_cond(LogMsg, DetailedText, Module, Line, StateName, D),
+ {{shutdown,Reason}, D}.
+
+call_disconnectfun_and_log_cond(LogMsg, DetailedText, Module, Line, StateName, D) ->
+ case disconnect_fun(LogMsg, D) of
+ void ->
+ log(info, D,
+ io_lib:format("~s~n"
+ "State = ~p~n"
+ "Module = ~p, Line = ~p.~n"
+ "Details:~n ~s~n",
+ [LogMsg, StateName, Module, Line, DetailedText]));
+ _ ->
+ ok
+ end.
+
+
+default_text(?SSH_DISCONNECT_HOST_NOT_ALLOWED_TO_CONNECT) -> "Host not allowed to connect";
+default_text(?SSH_DISCONNECT_PROTOCOL_ERROR) -> "Protocol error";
+default_text(?SSH_DISCONNECT_KEY_EXCHANGE_FAILED) -> "Key exchange failed";
+default_text(?SSH_DISCONNECT_RESERVED) -> "Reserved";
+default_text(?SSH_DISCONNECT_MAC_ERROR) -> "Mac error";
+default_text(?SSH_DISCONNECT_COMPRESSION_ERROR) -> "Compression error";
+default_text(?SSH_DISCONNECT_SERVICE_NOT_AVAILABLE) -> "Service not available";
+default_text(?SSH_DISCONNECT_PROTOCOL_VERSION_NOT_SUPPORTED) -> "Protocol version not supported";
+default_text(?SSH_DISCONNECT_HOST_KEY_NOT_VERIFIABLE) -> "Host key not verifiable";
+default_text(?SSH_DISCONNECT_CONNECTION_LOST) -> "Connection lost";
+default_text(?SSH_DISCONNECT_BY_APPLICATION) -> "By application";
+default_text(?SSH_DISCONNECT_TOO_MANY_CONNECTIONS) -> "Too many connections";
+default_text(?SSH_DISCONNECT_AUTH_CANCELLED_BY_USER) -> "Auth cancelled by user";
+default_text(?SSH_DISCONNECT_NO_MORE_AUTH_METHODS_AVAILABLE) -> "Unable to connect using the available authentication methods";
+default_text(?SSH_DISCONNECT_ILLEGAL_USER_NAME) -> "Illegal user name".
%%%----------------------------------------------------------------
counterpart_versions(NumVsn, StrVsn, #ssh{role = server} = Ssh) ->
@@ -1864,8 +1961,7 @@ conn_info(client_version, #data{ssh_params=S}) -> {S#ssh.c_vsn, S#ssh.c_version}
conn_info(server_version, #data{ssh_params=S}) -> {S#ssh.s_vsn, S#ssh.s_version};
conn_info(peer, #data{ssh_params=S}) -> S#ssh.peer;
conn_info(user, D) -> D#data.auth_user;
-conn_info(sockname, D) -> {ok, SockName} = inet:sockname(D#data.socket),
- SockName;
+conn_info(sockname, #data{ssh_params=S}) -> S#ssh.local;
%% dbg options ( = not documented):
conn_info(socket, D) -> D#data.socket;
conn_info(chan_ids, D) ->
@@ -1896,13 +1992,43 @@ fold_keys(Keys, Fun, Extra) ->
end, [], Keys).
%%%----------------------------------------------------------------
-log_error(Reason) ->
- Report = io_lib:format("Erlang ssh connection handler failed with reason:~n"
- " ~p~n"
- "Stacktrace:~n"
- " ~p~n",
- [Reason, erlang:get_stacktrace()]),
- error_logger:error_report(Report).
+log(Tag, D, Reason) ->
+ case atom_to_list(Tag) of % Dialyzer-technical reasons...
+ "error" -> do_log(error_msg, Reason, D);
+ "warning" -> do_log(warning_msg, Reason, D);
+ "info" -> do_log(info_msg, Reason, D)
+ end.
+
+do_log(F, Reason, #data{ssh_params = #ssh{role = Role} = S
+ }) ->
+ VSN =
+ case application:get_key(ssh,vsn) of
+ {ok,Vsn} -> Vsn;
+ undefined -> ""
+ end,
+ PeerVersion =
+ case Role of
+ server -> S#ssh.c_version;
+ client -> S#ssh.s_version
+ end,
+ CryptoInfo =
+ try
+ [{_,_,CI}] = crypto:info_lib(),
+ <<"(",CI/binary,")">>
+ catch
+ _:_ -> ""
+ end,
+ Other =
+ case Role of
+ server -> "Client";
+ client -> "Server"
+ end,
+ error_logger:F("Erlang SSH ~p ~s ~s.~n"
+ "~s: ~p~n"
+ "~s~n",
+ [Role, VSN, CryptoInfo,
+ Other, PeerVersion,
+ Reason]).
%%%----------------------------------------------------------------
not_connected_filter({connection_reply, _Data}) -> true;
@@ -1944,7 +2070,7 @@ get_repl(X, Acc) ->
%%%----------------------------------------------------------------
-define(CALL_FUN(Key,D), catch (?GET_OPT(Key, (D#data.ssh_params)#ssh.opts)) ).
-disconnect_fun({disconnect,Msg}, D) -> ?CALL_FUN(disconnectfun,D)(Msg);
+%%disconnect_fun({disconnect,Msg}, D) -> ?CALL_FUN(disconnectfun,D)(Msg);
disconnect_fun(Reason, D) -> ?CALL_FUN(disconnectfun,D)(Reason).
unexpected_fun(UnexpectedMessage, #data{ssh_params = #ssh{peer = {_,Peer} }} = D) ->
@@ -2099,3 +2225,137 @@ update_inet_buffers(Socket) ->
catch
_:_ -> ok
end.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+
+dbg_trace(points, _, _) -> [terminate, disconnect, connections, connection_events];
+
+dbg_trace(flags, connections, A) -> [c] ++ dbg_trace(flags, terminate, A);
+dbg_trace(on, connections, A) -> dbg:tp(?MODULE, init_connection_handler, 3, x),
+ dbg_trace(on, terminate, A);
+dbg_trace(off, connections, A) -> dbg:ctpg(?MODULE, init_connection_handler, 3),
+ dbg_trace(off, terminate, A);
+dbg_trace(format, connections, {call, {?MODULE,init_connection_handler, [Role, Sock, Opts]}}) ->
+ DefaultOpts = ssh_options:handle_options(Role,[]),
+ ExcludedKeys = [internal_options, user_options],
+ NonDefaultOpts =
+ maps:filter(fun(K,V) ->
+ case lists:member(K,ExcludedKeys) of
+ true ->
+ false;
+ false ->
+ V =/= (catch maps:get(K,DefaultOpts))
+ end
+ end,
+ Opts),
+ {ok, {IPp,Portp}} = inet:peername(Sock),
+ {ok, {IPs,Ports}} = inet:sockname(Sock),
+ [io_lib:format("Starting ~p connection:\n",[Role]),
+ io_lib:format("Socket = ~p, Peer = ~s:~p, Local = ~s:~p,~n"
+ "Non-default options:~n~p",
+ [Sock,inet:ntoa(IPp),Portp,inet:ntoa(IPs),Ports,
+ NonDefaultOpts])
+ ];
+dbg_trace(format, connections, F) ->
+ dbg_trace(format, terminate, F);
+
+dbg_trace(flags, connection_events, _) -> [c];
+dbg_trace(on, connection_events, _) -> dbg:tp(?MODULE, handle_event, 4, x);
+dbg_trace(off, connection_events, _) -> dbg:ctpg(?MODULE, handle_event, 4);
+dbg_trace(format, connection_events, {call, {?MODULE,handle_event, [EventType, EventContent, State, _Data]}}) ->
+ ["Connection event\n",
+ io_lib:format("EventType: ~p~nEventContent: ~p~nState: ~p~n", [EventType, EventContent, State])
+ ];
+dbg_trace(format, connection_events, {return_from, {?MODULE,handle_event,4}, Ret}) ->
+ ["Connection event result\n",
+ io_lib:format("~p~n", [event_handler_result(Ret)])
+ ];
+
+dbg_trace(flags, terminate, _) -> [c];
+dbg_trace(on, terminate, _) -> dbg:tp(?MODULE, terminate, 3, x);
+dbg_trace(off, terminate, _) -> dbg:ctpg(?MODULE, terminate, 3);
+dbg_trace(format, terminate, {call, {?MODULE,terminate, [Reason, StateName, D]}}) ->
+ ExtraInfo =
+ try
+ {conn_info(peer,D),
+ conn_info(user,D),
+ conn_info(sockname,D)}
+ of
+ {{_,{IPp,Portp}}, Usr, {IPs,Ports}} when is_tuple(IPp), is_tuple(IPs),
+ is_integer(Portp), is_integer(Ports) ->
+ io_lib:format("Peer=~s:~p, Local=~s:~p, User=~p",
+ [inet:ntoa(IPp),Portp,inet:ntoa(IPs),Ports,Usr]);
+ {Peer,Usr,Sockname} ->
+ io_lib:format("Peer=~p, Local=~p, User=~p",[Peer,Sockname,Usr])
+ catch
+ _:_ ->
+ ""
+ end,
+ if
+ Reason == normal ;
+ Reason == shutdown ;
+ element(1,Reason) == shutdown
+ ->
+ ["Connection Terminating:\n",
+ io_lib:format("Reason: ~p, StateName: ~p~n~s", [Reason, StateName, ExtraInfo])
+ ];
+
+ true ->
+ ["Connection Terminating:\n",
+ io_lib:format("Reason: ~p, StateName: ~p~n~s~nStateData = ~p",
+ [Reason, StateName, ExtraInfo, state_data2proplist(D)])
+ ]
+ end;
+
+dbg_trace(flags, disconnect, _) -> [c];
+dbg_trace(on, disconnect, _) -> dbg:tpl(?MODULE, send_disconnect, 7, x);
+dbg_trace(off, disconnect, _) -> dbg:ctpl(?MODULE, send_disconnect, 7);
+dbg_trace(format, disconnect, {call,{?MODULE,send_disconnect,
+ [Code, Reason, DetailedText, Module, Line, StateName, _D]}}) ->
+ ["Disconnecting:\n",
+ io_lib:format(" Module = ~p, Line = ~p, StateName = ~p,~n"
+ " Code = ~p, Reason = ~p,~n"
+ " DetailedText =~n"
+ " ~p",
+ [Module, Line, StateName, Code, Reason, lists:flatten(DetailedText)])
+ ].
+
+
+event_handler_result({next_state, NextState, _NewData}) ->
+ {next_state, NextState, "#data{}"};
+event_handler_result({next_state, NextState, _NewData, Actions}) ->
+ {next_state, NextState, "#data{}", Actions};
+event_handler_result(R) ->
+ state_callback_result(R).
+
+state_callback_result({keep_state, _NewData}) ->
+ {keep_state, "#data{}"};
+state_callback_result({keep_state, _NewData, Actions}) ->
+ {keep_state, "#data{}", Actions};
+state_callback_result(keep_state_and_data) ->
+ keep_state_and_data;
+state_callback_result({keep_state_and_data, Actions}) ->
+ {keep_state_and_data, Actions};
+state_callback_result({repeat_state, _NewData}) ->
+ {repeat_state, "#data{}"};
+state_callback_result({repeat_state, _NewData, Actions}) ->
+ {repeat_state, "#data{}", Actions};
+state_callback_result(repeat_state_and_data) ->
+ repeat_state_and_data;
+state_callback_result({repeat_state_and_data, Actions}) ->
+ {repeat_state_and_data, Actions};
+state_callback_result(stop) ->
+ stop;
+state_callback_result({stop, Reason}) ->
+ {stop, Reason};
+state_callback_result({stop, Reason, _NewData}) ->
+ {stop, Reason, "#data{}"};
+state_callback_result({stop_and_reply, Reason, Replies}) ->
+ {stop_and_reply, Reason, Replies};
+state_callback_result({stop_and_reply, Reason, Replies, _NewData}) ->
+ {stop_and_reply, Reason, Replies, "#data{}"};
+state_callback_result(R) ->
+ R.