Skip to content

Commit

Permalink
Add traces to pgw_s5s8_proxy, and separate cases for gtp_path:registe…
Browse files Browse the repository at this point in the history 
…r_monitor

Module pgw_s5s8_proxy has debug messages for all related traffic functions.
  • Loading branch information
@RoadRunnr @javiermtorres
RoadRunnr authored and javiermtorres committed Sep 16, 2021
1 parent 036d477 commit 4790726
Show file tree
Hide file tree
Showing 2 changed files with 81 additions and 6 deletions.
65 changes: 60 additions & 5 deletions src/gtp_path.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -232,51 +232,63 @@ 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),
{keep_state_and_data, enter_peer_state_action(OldState, NewState, 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}]);
Expand All @@ -288,13 +300,15 @@ 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,
#{socket := #socket{name = SocketName},
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},
Expand All @@ -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
Expand Down Expand Up @@ -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}.

Expand All @@ -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).

Expand Down
22 changes: 21 additions & 1 deletion src/pgw_s5s8_proxy.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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} =
Expand Down Expand Up @@ -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,
Expand All @@ -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
Expand All @@ -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),

Expand All @@ -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),

Expand All @@ -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),

Expand All @@ -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),

Expand All @@ -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),

Expand All @@ -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),

Expand All @@ -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,
Expand Down Expand Up @@ -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) ->
Expand Down Expand Up @@ -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)}.

Expand Down

0 comments on commit 4790726

Please sign in to comment.