From 4790726e9a9e30a61398ba58ef754df2fa543492 Mon Sep 17 00:00:00 2001 From: Andreas Schultz Date: Wed, 15 Sep 2021 19:15:58 +0200 Subject: [PATCH] Add traces to pgw_s5s8_proxy, and separate cases for gtp_path:register_monitor Module pgw_s5s8_proxy has debug messages for all related traffic functions. --- src/gtp_path.erl | 65 ++++++++++++++++++++++++++++++++++++++---- src/pgw_s5s8_proxy.erl | 22 +++++++++++++- 2 files changed, 81 insertions(+), 6 deletions(-) diff --git a/src/gtp_path.erl b/src/gtp_path.erl index c0466462..0e397e1d 100644 --- a/src/gtp_path.erl +++ b/src/gtp_path.erl @@ -232,6 +232,7 @@ init([#socket{name = SocketName} = Socket, Version, RemoteIP, Args]) -> handle_event(enter, #state{peer = Old}, #state{peer = Peer}, Data) when Old /= Peer -> + ?LOG(debug, "enter state when Old ~p /= Peer ~p", [Old, Peer]), peer_state_change(Old, Peer, Data), OldState = peer_state(Old), NewState = peer_state(Peer), @@ -239,44 +240,55 @@ handle_event(enter, #state{peer = Old}, #state{peer = Peer}, Data) handle_event(enter, #state{echo = Old}, #state{peer = Peer, echo = Echo}, Data) when Old /= Echo -> + ?LOG(debug, "enter state when Old ~p /= Echo ~p, new peer: ~p", [Old, Echo, Peer]), State = peer_state(Peer), {keep_state_and_data, enter_state_echo_action(State, Data)}; handle_event(enter, _OldState, _State, _Data) -> + ?LOG(debug, "enter state otherwise"), keep_state_and_data; handle_event({timeout, stop_echo}, stop_echo, State, Data) -> + ?LOG(debug, "timed out on stop_echo"), {next_state, State#state{echo = stopped}, Data, [{{timeout, echo}, cancel}]}; handle_event({timeout, echo}, start_echo, #state{echo = EchoT} = State0, Data) when EchoT =:= stopped; EchoT =:= idle -> + ?LOG(debug, "timed out on echo, msg start_echo when EchoT was stopped or idle"), State = send_echo_request(State0, Data), {next_state, State, Data}; handle_event({timeout, echo}, start_echo, _State, _Data) -> + ?LOG(debug, "timed out on echo, msg start_echo otherwise"), keep_state_and_data; handle_event({timeout, peer}, stop, _State, #{reg_key := RegKey}) -> + ?LOG(debug, "timed out on peer with msg stop"), gtp_path_reg:unregister(RegKey), {stop, normal}; handle_event({call, From}, all, _State, #{contexts := CtxS} = _Data) -> + ?LOG(debug, "requesting all contexts"), Reply = maps:keys(CtxS), {keep_state_and_data, [{reply, From, Reply}]}; handle_event({call, From}, {MonOrBind, Pid}, #state{peer = #peer{state = down}}, _Data) when MonOrBind == monitor; MonOrBind == bind -> + ?LOG(debug, "requesting monitor or bind ~p when peer state id down", [Pid]), Path = self(), proc_lib:spawn(fun() -> gtp_context:path_restart(Pid, Path) end), {keep_state_and_data, [{reply, From, {ok, undefined}}]}; handle_event({call, From}, {monitor, Pid}, #state{recovery = RstCnt} = State, Data) -> + ?LOG(debug, "requesting monitor ~p when recovery is ~p", [Pid, RstCnt]), register_monitor(Pid, State, Data, [{reply, From, {ok, RstCnt}}]); handle_event({call, From}, {bind, Pid}, #state{recovery = RstCnt} = State, Data) -> + ?LOG(debug, "requesting bind ~p when peer recovery is ~p", [Pid, RstCnt]), register_bind(Pid, State, Data, [{reply, From, {ok, RstCnt}}]); handle_event({call, From}, {bind, Pid, RstCnt}, State, Data) -> + ?LOG(debug, "requesting bind ~p with restart counter ~p", [Pid, RstCnt]), case update_restart_counter(RstCnt, State, Data) of initial -> register_bind(Pid, State#state{recovery = RstCnt}, Data, [{reply, From, ok}]); @@ -288,6 +300,7 @@ handle_event({call, From}, {bind, Pid, RstCnt}, State, Data) -> end; handle_event({call, From}, {unbind, Pid}, State, Data) -> + ?LOG(debug, "requesting unbind ~p", [Pid]), unregister(Pid, State, Data, [{reply, From, ok}]); handle_event({call, From}, info, #state{peer = #peer{contexts = CtxCnt}} = State, @@ -295,6 +308,7 @@ handle_event({call, From}, info, #state{peer = #peer{contexts = CtxCnt}} = State version := Version, ip := IP} = Data) -> Reply = #{path => self(), socket => SocketName, tunnels => CtxCnt, version => Version, ip => IP, state => State, data => Data}, + ?LOG(debug, "requesting info: ~p", [Reply]), {keep_state_and_data, [{reply, From, Reply}]}; handle_event(cast, {handle_request, ReqKey, #gtp{type = echo_request} = Msg0}, @@ -316,30 +330,36 @@ handle_event(cast, {handle_request, ReqKey, #gtp{type = echo_request} = Msg0}, handle_event(cast, {handle_response, echo_request, ReqRef, _Msg}, #state{echo = SRef}, _) when ReqRef /= SRef -> + ?LOG(debug, "cast response to echo_request: ~p /= ~p", [ReqRef, SRef]), keep_state_and_data; handle_event(cast,{handle_response, echo_request, _, #gtp{} = Msg}, State, Data) -> + ?LOG(debug, "cast response to echo_request with GTP msg, otherwise"), handle_recovery_ie(Msg, State#state{echo = idle}, Data); handle_event(cast,{handle_response, echo_request, _, _Msg}, State, Data) -> + ?LOG(debug, "cast response to echo_request, otherwise"), path_restart(undefined, peer_state(down, State), Data, []); handle_event(cast, icmp_error, _, #{icmp_error_handling := ignore}) -> + ?LOG(debug, "icmp_error when ignoring icmp errors"), keep_state_and_data; handle_event(cast, icmp_error, State, Data) -> + ?LOG(debug, "icmp_error when *not* ignoring icmp errors"), path_restart(undefined, peer_state(down, State), Data, []); handle_event(info,{'DOWN', _MonitorRef, process, Pid, _Info}, State, Data) -> + ?LOG(debug, "received a down signal from ~p", [Pid]), unregister(Pid, State, Data, []); handle_event({timeout, 'echo'}, _, #state{echo = idle} = State0, Data) -> - ?LOG(debug, "handle_event timeout: ~p", [Data]), + ?LOG(debug, "handle_event timeout (when echo = idle): ~p", [Data]), State = send_echo_request(State0, Data), {next_state, State, Data}; handle_event({timeout, 'echo'}, _, _State, _Data) -> - ?LOG(debug, "handle_event timeout: ~p", [_Data]), + ?LOG(debug, "handle_event timeout (otherwise): ~p", [_Data]), keep_state_and_data; %% test support @@ -499,16 +519,42 @@ update_contexts(State0, #{socket := Socket, version := Version, ip := IP} = Data register_monitor(Pid, State, #{contexts := CtxS, monitors := Mons} = Data, Actions) when is_map_key(Pid, CtxS), is_map_key(Pid, Mons) -> - ?LOG(debug, "~s: monitor(~p)", [?MODULE, Pid]), + ?LOG(debug, "~s: monitor(~p), pid found in both context and monitors", [?MODULE, Pid]), {next_state, State, Data, Actions}; register_monitor(Pid, State, #{contexts := CtxS, monitors := Mons} = Data, Actions) when not is_map_key(Pid, CtxS), is_map_key(Pid, Mons) -> + ?LOG(debug, "~s: monitor(~p), pid found in monitors ONLY", [?MODULE, Pid]), {next_state, State, Data, Actions}; register_monitor(Pid, State, #{contexts := CtxS, monitors := Mons} = Data, Actions) when is_map_key(Pid, CtxS), not is_map_key(Pid, Mons) -> + ?LOG(debug, "~s: monitor(~p), pid found in contexts ONLY", [?MODULE, Pid]), {next_state, State, Data, Actions}; register_monitor(Pid, State, #{contexts := CtxS, monitors := Mons} = Data, Actions) when not is_map_key(Pid, CtxS), not is_map_key(Pid, Mons) -> + case logger:allow(debug, ?MODULE) of + true -> + IsInM = is_map_key(Pid, Mons), + IsInC = is_map_key(Pid, CtxS), + Cpids = maps:keys(CtxS), + Mpids = maps:keys(Mons), + IsAlive = fun (P) -> + case + process_info(P, status) of + undefined -> false; + _ -> true + end + end, + {CpidsAlive, CpidsDead} = lists:splitwith(IsAlive, Cpids), + {MpidsAlive, MpidsDead} = lists:splitwith(IsAlive, Mpids), + ?LOG(debug, "Register monitor contexts (alive/dead): ~p / ~p", [length(CpidsAlive), length(CpidsDead)]), + ?LOG(debug, "Register monitor monitors (alive/dead): ~p / ~p", [length(MpidsAlive), length(MpidsDead)]), + ?LOG(debug, "~s: monitor(~p), pid not found in any: ~p", [?MODULE, Pid, {IsInM, IsInC}]), + CurrentMs = element(2, erlang:process_info(Pid, monitored_by)), + MonitoredByMe = lists:member(self(), CurrentMs), + ?LOG(debug, "Is ~p already monitored by me? ~p : ~p", [Pid, MonitoredByMe, CurrentMs]); + _ -> + ok + end, MRef = erlang:monitor(process, Pid), {next_state, State, Data#{monitors => maps:put(Pid, MRef, Mons)}, Actions}. @@ -519,14 +565,23 @@ register_bind(Pid, MRef, State, #{contexts := CtxS} = Data, Actions) -> %% register_bind/4 register_bind(Pid, State, #{monitors := Mons} = Data, Actions) when is_map_key(Pid, Mons) -> - ?LOG(debug, "~s: register(~p)", [?MODULE, Pid]), + ?LOG(debug, "~s: monitor register(~p)", [?MODULE, Pid]), MRef = maps:get(Pid, Mons), register_bind(Pid, MRef, State, Data#{monitors => maps:remove(Pid, Mons)}, Actions); register_bind(Pid, State, #{contexts := CtxS} = Data, Actions) when is_map_key(Pid, CtxS) -> + ?LOG(debug, "~s: context register(~p)", [?MODULE, Pid]), {next_state, State, Data, Actions}; register_bind(Pid, State, Data, Actions) -> - ?LOG(debug, "~s: register(~p)", [?MODULE, Pid]), + ?LOG(debug, "~s: default register(~p)", [?MODULE, Pid]), + case logger:allow(debug, ?MODULE) of + true -> + CurrentMs = element(2, erlang:process_info(Pid, monitored_by)), + MonitoredByMe = lists:member(self(), CurrentMs), + ?LOG(debug, "Is ~p already monitored by me? ~p : ~p", [Pid, MonitoredByMe, CurrentMs]); + _ -> + ok + end, MRef = erlang:monitor(process, Pid), register_bind(Pid, MRef, State, Data, Actions). diff --git a/src/pgw_s5s8_proxy.erl b/src/pgw_s5s8_proxy.erl index 852026bf..842537e1 100644 --- a/src/pgw_s5s8_proxy.erl +++ b/src/pgw_s5s8_proxy.erl @@ -221,11 +221,13 @@ handle_request(ReqKey, Request, true, _State, %% handle_request(ReqKey, #gtp{type = create_session_request} = Request, true, _State, #{right_tunnel := RightTunnel}) -> + ?LOG(debug, "create session request for right tunnel ~p", [RightTunnel]), ergw_proxy_lib:forward_request(RightTunnel, ReqKey, Request), keep_state_and_data; handle_request(ReqKey, #gtp{type = change_notification_request} = Request, true, _State, #{left_tunnel := LeftTunnel, right_tunnel := RightTunnel}) when ?IS_REQUEST_TUNNEL_OPTIONAL_TEI(ReqKey, Request, LeftTunnel) -> + ?LOG(debug, "change notification request when ?IS_REQUEST_TUNNEL_OPTIONAL_TEI(ReqKey, Request, LeftTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), ergw_proxy_lib:forward_request(RightTunnel, ReqKey, Request), keep_state_and_data; @@ -242,7 +244,7 @@ handle_request(ReqKey, bearer := #{left := LeftBearer0} = Bearer0, 'Session' := Session} = Data) when State == run; State == connecting -> - + ?LOG(debug, "create session request when State == run; State == connecting for left tunnel ~p", [LeftTunnel0]), Context = pgw_s5s8:update_context_from_gtp_req(Request, Context0), {LeftTunnel1, LeftBearer1} = @@ -321,6 +323,7 @@ handle_request(ReqKey, %% 30 second timeout to have enough room for resents Action = [{state_timeout, 30 * 1000, ReqKey}], + ?LOG(debug, "finished create session request for left tunnel"), {next_state, connecting, DataNew, Action}; handle_request(ReqKey, @@ -330,6 +333,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnelOld, right_tunnel := RightTunnelOld, bearer := #{left := LeftBearerOld, right := RightBearer} = Bearer} = Data) when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnelOld) -> + ?LOG(debug, "modify bearer request when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnelOld) for right tunnel ~p and left tunnel ~p", [RightTunnelOld, LeftTunnelOld]), {LeftTunnel0, LeftBearer} = case pgw_s5s8:update_tunnel_from_gtp_req( Request, LeftTunnelOld#tunnel{version = v2}, LeftBearerOld) of @@ -356,6 +360,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnel, right_tunnel := RightTunnel, bearer := #{right := RightBearer}} = Data0) when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) -> + ?LOG(debug, "modify bearer command when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), Data1 = bind_forward_path(sgw2pgw, Request, Data0), @@ -374,6 +379,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnel, right_tunnel := RightTunnel, bearer := #{right := RightBearer}} = Data) when ?IS_REQUEST_TUNNEL_OPTIONAL_TEI(ReqKey, Request, LeftTunnel) -> + ?LOG(debug, "change notification request when ?IS_REQUEST_TUNNEL_OPTIONAL_TEI(ReqKey, Request, LeftTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), DataNew = bind_forward_path(sgw2pgw, Request, Data), @@ -393,6 +399,7 @@ handle_request(ReqKey, when (Type == suspend_notification orelse Type == resume_notification) andalso ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) -> + ?LOG(debug, "suspend or resume notification when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), DataNew = bind_forward_path(sgw2pgw, Request, Data), @@ -410,6 +417,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnel, right_tunnel := RightTunnel, bearer := #{left := LeftBearer}} = Data0) when ?IS_REQUEST_TUNNEL(ReqKey, Request, RightTunnel) -> + ?LOG(debug, "update bearer request when ?IS_REQUEST_TUNNEL(ReqKey, Request, RightTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), Data = bind_forward_path(pgw2sgw, Request, Data0), @@ -427,6 +435,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnel, right_tunnel := RightTunnel, bearer := #{right := RightBearer}} = Data0) when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) -> + ?LOG(debug, "delete session request when ?IS_REQUEST_TUNNEL(ReqKey, Request, LeftTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), forward_request(sgw2pgw, ReqKey, Request, RightTunnel, RightBearer, ProxyContext, Data0, Data0), @@ -445,6 +454,7 @@ handle_request(ReqKey, left_tunnel := LeftTunnel, right_tunnel := RightTunnel, bearer := #{left := LeftBearer}} = Data0) when ?IS_REQUEST_TUNNEL(ReqKey, Request, RightTunnel) -> + ?LOG(debug, "delete bearer request when ?IS_REQUEST_TUNNEL(ReqKey, Request, RightTunnel) for right tunnel ~p and left tunnel ~p", [RightTunnel, LeftTunnel]), forward_request(pgw2sgw, ReqKey, Request, LeftTunnel, LeftBearer, Context, Data0, Data0), @@ -454,21 +464,26 @@ handle_request(ReqKey, {keep_state, Data}; handle_request(_ReqKey, _Request, _Resent, connecting, _Data) -> + ?LOG(debug, "any other connecting request"), {keep_state_and_data, [postpone]}; handle_request(ReqKey, _Request, _Resent, _State, _Data) -> + ?LOG(debug, "default case for requests"), gtp_context:request_finished(ReqKey), keep_state_and_data. handle_response(ReqInfo, #gtp{version = v1} = Msg, Request, State, Data) -> + ?LOG(debug, "v1 Response"), ?GTP_v1_Interface:handle_response(ReqInfo, Msg, Request, State, Data); handle_response(_, _Response, _Request, shutdown, _Data) -> + ?LOG(debug, "shutdown Response ~p", [_Response]), keep_state_and_data; handle_response(#proxy_request{direction = sgw2pgw}, timeout, #gtp{type = create_session_request}, State, _) when State == connected; State == connecting -> + ?LOG(debug, "timedout create session request"), keep_state_and_data; handle_response(#proxy_request{direction = sgw2pgw} = ProxyRequest, @@ -646,16 +661,19 @@ handle_response(#proxy_request{request = ReqKey} = _ReqInfo, handle_response(_, _, #gtp{type = Type}, shutdown, _) when Type =:= delete_bearer_request; Type =:= delete_session_request -> + ?LOG(debug, "shutdown delete bearer or session Response"), keep_state_and_data; handle_response({Direction, From}, timeout, #gtp{type = Type}, shutdown_initiated, Data) when Type =:= delete_bearer_request; Type =:= delete_session_request -> + ?LOG(debug, "shutdown initiated (timeout) delete bearer or session Response ~p"), session_teardown_response({error, timeout}, Direction, From, Data); handle_response({Direction, From}, #gtp{type = Type}, _, shutdown_initiated, Data) when Type =:= delete_bearer_response; Type =:= delete_session_response -> + ?LOG(debug, "shutdown initiated (timeout 2?) delete bearer or session"), session_teardown_response(ok, Direction, From, Data). terminate(_Reason, _State, _Data) -> @@ -815,10 +833,12 @@ session_teardown_response(Answer, Direction, From, #{shutdown := Shutdown0} = Da bind_forward_path(sgw2pgw, Request, #{left_tunnel := LeftTunnel, right_tunnel := RightTunnel} = Data) -> + ?LOG(debug, "bind forward path, sgw2pgw"), Data#{left_tunnel => gtp_path:bind(Request, LeftTunnel), right_tunnel => gtp_path:bind(RightTunnel)}; bind_forward_path(pgw2sgw, Request, #{left_tunnel := LeftTunnel, right_tunnel := RightTunnel} = Data) -> + ?LOG(debug, "bind forward path, pgw2sgw"), Data#{left_tunnel => gtp_path:bind(LeftTunnel), right_tunnel => gtp_path:bind(Request, RightTunnel)}.