fixeria has submitted this change. ( https://gerrit.osmocom.org/c/erlang/osmo-s1gw/+/37216?usp=email ) Change subject: logging: use ?LOG macros instead of calling logger:level() ...................................................................... logging: use ?LOG macros instead of calling logger:level() The difference between using these macros and the exported functions is that macros add location (originator) information to the metadata, and perform lazy evaluation by wrapping the logger call in a case statement, so it is only evaluated if the log level of the event passes the primary log level check. https://www.erlang.org/doc/apps/kernel/logger_chapter.html#logger-api Change-Id: I3b6e4296f736f9c87d2706ef5fb75146fd9f1239 --- M src/s1ap_proxy.erl M src/sctp_client.erl M src/sctp_proxy.erl M src/sctp_server.erl 4 files changed, 63 insertions(+), 41 deletions(-) Approvals: laforge: Looks good to me, approved Jenkins Builder: Verified pespin: Looks good to me, but someone else must approve diff --git a/src/s1ap_proxy.erl b/src/s1ap_proxy.erl index d50d765..6c143e8 100644 --- a/src/s1ap_proxy.erl +++ b/src/s1ap_proxy.erl @@ -38,6 +38,8 @@ encode_pdu/1, decode_pdu/1]). +-include_lib("kernel/include/logger.hrl"). + -include("S1AP-PDU-Descriptions.hrl"). -include("S1AP-PDU-Contents.hrl"). -include("S1AP-Containers.hrl"). @@ -52,10 +54,10 @@ handle_pdu(Data) when is_binary(Data) -> case decode_pdu(Data) of {ok, Pdu} -> - logger:info("S1AP PDU: ~p", [Pdu]), + ?LOG_INFO("S1AP PDU: ~p", [Pdu]), handle_pdu(Data, Pdu); {error, {asn1, Error}} -> - logger:error("S1AP PDU decoding failed: ~p", [Error]), + ?LOG_ERROR("S1AP PDU decoding failed: ~p", [Error]), Data end. @@ -86,7 +88,7 @@ {ok, NewData} -> NewData; {error, {asn1, Error}} -> - logger:error("S1AP PDU encoding failed: ~p", [Error]), + ?LOG_ERROR("S1AP PDU encoding failed: ~p", [Error]), Data end. @@ -95,7 +97,7 @@ handle_pdu(Data, {Outcome = initiatingMessage, #'InitiatingMessage'{procedureCode = ?'id-E-RABSetup', value = Content} = Pdu}) -> - logger:debug("Patching E-RAB SETUP REQUEST"), + ?LOG_DEBUG("Patching E-RAB SETUP REQUEST"), IEs = handle_ies(Content#'E-RABSetupRequest'.protocolIEs, ?'id-E-RABToBeSetupListBearerSUReq'), NewContent = Content#'E-RABSetupRequest'{protocolIEs = IEs}, @@ -105,7 +107,7 @@ handle_pdu(Data, {Outcome = successfulOutcome, #'SuccessfulOutcome'{procedureCode = ?'id-E-RABSetup', value = Content} = Pdu}) -> - logger:debug("Patching E-RAB SETUP RESPONSE"), + ?LOG_DEBUG("Patching E-RAB SETUP RESPONSE"), IEs = handle_ies(Content#'E-RABSetupResponse'.protocolIEs, ?'id-E-RABSetupListBearerSURes'), NewContent = Content#'E-RABSetupResponse'{protocolIEs = IEs}, @@ -117,7 +119,7 @@ handle_pdu(Data, {Outcome = initiatingMessage, #'InitiatingMessage'{procedureCode = ?'id-E-RABModificationIndication', value = Content} = Pdu}) -> - logger:debug("Patching E-RAB MODIFICATION INDICATION"), + ?LOG_DEBUG("Patching E-RAB MODIFICATION INDICATION"), IEs = Content#'E-RABModificationIndication'.protocolIEs, %% E-RAB to be Modified List IEs1 = handle_ies(IEs, ?'id-E-RABToBeModifiedListBearerModInd'), @@ -130,7 +132,7 @@ handle_pdu(Data, {Outcome = initiatingMessage, #'InitiatingMessage'{procedureCode = ?'id-InitialContextSetup', value = Content} = Pdu}) -> - logger:debug("Patching INITIAL CONTEXT SETUP REQUEST"), + ?LOG_DEBUG("Patching INITIAL CONTEXT SETUP REQUEST"), IEs = handle_ies(Content#'InitialContextSetupRequest'.protocolIEs, ?'id-E-RABToBeSetupListCtxtSUReq'), NewContent = Content#'InitialContextSetupRequest'{protocolIEs = IEs}, @@ -140,7 +142,7 @@ handle_pdu(Data, {Outcome = successfulOutcome, #'SuccessfulOutcome'{procedureCode = ?'id-InitialContextSetup', value = Content} = Pdu}) -> - logger:debug("Patching INITIAL CONTEXT SETUP RESPONSE"), + ?LOG_DEBUG("Patching INITIAL CONTEXT SETUP RESPONSE"), IEs = handle_ies(Content#'InitialContextSetupResponse'.protocolIEs, ?'id-E-RABSetupListCtxtSURes'), NewContent = Content#'InitialContextSetupResponse'{protocolIEs = IEs}, @@ -234,7 +236,7 @@ %% Catch-all variant, which should not be called normally handle_ie(#'ProtocolIE-Field'{value = Content} = IE) -> - logger:error("[BUG] Unhandled S1AP IE: ~p", [IE]), + ?LOG_ERROR("[BUG] Unhandled S1AP IE: ~p", [IE]), Content. diff --git a/src/sctp_client.erl b/src/sctp_client.erl index 320d4da..06ee31d 100644 --- a/src/sctp_client.erl +++ b/src/sctp_client.erl @@ -40,6 +40,7 @@ send_data/2, disconnect/1]). +-include_lib("kernel/include/logger.hrl"). -include_lib("kernel/include/inet.hrl"). -include_lib("kernel/include/inet_sctp.hrl"). diff --git a/src/sctp_proxy.erl b/src/sctp_proxy.erl index 29cc425..7f389aa 100644 --- a/src/sctp_proxy.erl +++ b/src/sctp_proxy.erl @@ -45,6 +45,7 @@ send_data/2, shutdown/1]). +-include_lib("kernel/include/logger.hrl"). -include_lib("kernel/include/inet.hrl"). -include_lib("kernel/include/inet_sctp.hrl"). @@ -83,7 +84,7 @@ %% CONNECTING state connecting(enter, OldState, #{mme_addr := MmeAddr, mmr_port := MmePort} = S) -> - logger:info("State change: ~p -> ~p", [OldState, ?FUNCTION_NAME]), + ?LOG_INFO("State change: ~p -> ~p", [OldState, ?FUNCTION_NAME]), %% Initiate connection establishment with the MME {ok, Sock} = sctp_client:connect(MmeAddr, MmePort), {keep_state, S#{sock => Sock}, @@ -104,29 +105,29 @@ assoc_id = Aid}}}, S) -> case ConnState of comm_up -> - logger:notice("MME connection (id=~p, ~p:~p) established", - [Aid, MmeAddr, MmePort]), + ?LOG_NOTICE("MME connection (id=~p, ~p:~p) established", + [Aid, MmeAddr, MmePort]), {next_state, connected, S#{mme_aid => Aid}}; _ -> - logger:notice("MME connection establishment failed: ~p", [ConnState]), + ?LOG_NOTICE("MME connection establishment failed: ~p", [ConnState]), {stop, {shutdown, conn_est_fail}} end; %% Catch-all for other kinds of SCTP events connecting(info, {sctp, _Socket, MmeAddr, MmePort, {AncData, Data}}, S) -> - logger:debug("Unhandled SCTP event (~p:~p): ~p, ~p", - [MmeAddr, MmePort, AncData, Data]), + ?LOG_DEBUG("Unhandled SCTP event (~p:~p): ~p, ~p", + [MmeAddr, MmePort, AncData, Data]), {keep_state, S}; connecting(Event, EventData, S) -> - logger:error("Unexpected event ~p: ~p", [Event, EventData]), + ?LOG_ERROR("Unexpected event ~p: ~p", [Event, EventData]), {keep_state, S}. %% CONNECTED state connected(enter, OldState, S) -> - logger:info("State change: ~p -> ~p", [OldState, ?FUNCTION_NAME]), + ?LOG_INFO("State change: ~p -> ~p", [OldState, ?FUNCTION_NAME]), %% Send pending eNB -> MME messages (if any) ok = sctp_send_pending(S), {keep_state, maps:remove(tx_queue, S)}; @@ -142,32 +143,32 @@ assoc_id = Aid}}}, S) -> case ConnState of comm_up -> - logger:notice("MME connection (id=~p, ~p:~p) is already established?!?", - [Aid, MmeAddr, MmePort]), + ?LOG_NOTICE("MME connection (id=~p, ~p:~p) is already established?!?", + [Aid, MmeAddr, MmePort]), {keep_state, S}; _ -> - logger:notice("MME connection state: ~p", [ConnState]), + ?LOG_NOTICE("MME connection state: ~p", [ConnState]), {stop, {shutdown, conn_fail}} end; %% Handle an #sctp_sndrcvinfo event (MME -> eNB data) connected(info, {sctp, _Socket, MmeAddr, MmePort, {[#sctp_sndrcvinfo{assoc_id = Aid}], Data}}, S) -> - logger:debug("MME connection (id=~p, ~p:~p) -> eNB: ~p", - [Aid, MmeAddr, MmePort, Data]), + ?LOG_DEBUG("MME connection (id=~p, ~p:~p) -> eNB: ~p", + [Aid, MmeAddr, MmePort, Data]), sctp_server:send_data(maps:get(enb_aid, S), handle_pdu(Data)), {keep_state, S}; %% Catch-all for other kinds of SCTP events connected(info, {sctp, _Socket, MmeAddr, MmePort, {AncData, Data}}, S) -> - logger:debug("Unhandled SCTP event (~p:~p): ~p, ~p", - [MmeAddr, MmePort, AncData, Data]), + ?LOG_DEBUG("Unhandled SCTP event (~p:~p): ~p, ~p", + [MmeAddr, MmePort, AncData, Data]), {keep_state, S}; %% Catch-all handler for this state connected(Event, EventData, S) -> - logger:error("Unexpected event ~p: ~p", [Event, EventData]), + ?LOG_ERROR("Unexpected event ~p: ~p", [Event, EventData]), {keep_state, S}. @@ -177,7 +178,7 @@ terminate(Reason, State, S) -> - logger:notice("Terminating in state ~p, reason ~p", [State, Reason]), + ?LOG_NOTICE("Terminating in state ~p, reason ~p", [State, Reason]), case S of #{sock := Sock, mme_aid := Aid} -> sctp_client:disconnect({Sock, Aid}), @@ -199,7 +200,7 @@ NewData -> NewData catch Exception:Reason -> - logger:error("An exception occurred: ~p, ~p", [Exception, Reason]), + ?LOG_ERROR("An exception occurred: ~p, ~p", [Exception, Reason]), Data %% proxy as-is end. diff --git a/src/sctp_server.erl b/src/sctp_server.erl index 806c559..5c73fc2 100644 --- a/src/sctp_server.erl +++ b/src/sctp_server.erl @@ -44,6 +44,7 @@ send_data/2, shutdown/0]). +-include_lib("kernel/include/logger.hrl"). -include_lib("kernel/include/inet.hrl"). -include_lib("kernel/include/inet_sctp.hrl"). @@ -85,7 +86,7 @@ {type, seqpacket}, {reuseaddr, true}, {active, true}]), - logger:info("SCTP server listening on ~w:~w", [BindAddr, BindPort]), + ?LOG_INFO("SCTP server listening on ~w:~w", [BindAddr, BindPort]), ok = gen_sctp:listen(Sock, true), {ok, #server_state{sock = Sock, clients = dict:new(), @@ -119,7 +120,7 @@ %% Handle termination events of the child processes handle_info({'EXIT', Pid, Reason}, #server_state{sock = Sock, clients = Clients} = State) -> - logger:debug("Child process ~p terminated with reason ~p", [Pid, Reason]), + ?LOG_DEBUG("Child process ~p terminated with reason ~p", [Pid, Reason]), case client_find(State, Pid) of {ok, {Aid, _Client}} -> %% gracefully close the eNB connection @@ -137,7 +138,7 @@ terminate(Reason, State) -> - logger:notice("Terminating, reason ~p", [Reason]), + ?LOG_NOTICE("Terminating, reason ~p", [Reason]), close_conns(State), gen_sctp:close(State#server_state.sock), ok. @@ -152,18 +153,18 @@ assoc_id = Aid}}) -> case ConnState of comm_up -> - logger:notice("eNB connection (id=~p, ~p:~p) established", [Aid, FromAddr, FromPort]), + ?LOG_NOTICE("eNB connection (id=~p, ~p:~p) established", [Aid, FromAddr, FromPort]), Clients = client_add(State#server_state.clients, Aid, FromAddr, FromPort, State#server_state.mme_addr_port); shutdown_comp -> - logger:notice("eNB connection (id=~p, ~p:~p) closed", [Aid, FromAddr, FromPort]), + ?LOG_NOTICE("eNB connection (id=~p, ~p:~p) closed", [Aid, FromAddr, FromPort]), Clients = client_del(State#server_state.clients, Aid); comm_lost -> - logger:notice("eNB connection (id=~p, ~p:~p) lost", [Aid, FromAddr, FromPort]), + ?LOG_NOTICE("eNB connection (id=~p, ~p:~p) lost", [Aid, FromAddr, FromPort]), Clients = client_del(State#server_state.clients, Aid); _ -> - logger:notice("eNB connection (id=~p, ~p:~p) state ~p", - [Aid, FromAddr, FromPort, ConnState]), + ?LOG_NOTICE("eNB connection (id=~p, ~p:~p) state ~p", + [Aid, FromAddr, FromPort, ConnState]), Clients = State#server_state.clients end, State#server_state{clients = Clients}; @@ -171,20 +172,20 @@ %% Handle an #sctp_sndrcvinfo event (incoming data) sctp_recv(State, {FromAddr, FromPort, [#sctp_sndrcvinfo{assoc_id = Aid}], Data}) -> - logger:debug("eNB connection (id=~p, ~p:~p) -> MME: ~p", [Aid, FromAddr, FromPort, Data]), + ?LOG_DEBUG("eNB connection (id=~p, ~p:~p) -> MME: ~p", [Aid, FromAddr, FromPort, Data]), case dict:find(Aid, State#server_state.clients) of {ok, #client_state{pid = Pid}} -> sctp_proxy:send_data(Pid, Data); error -> - logger:error("eNB connection (id=~p, ~p:~p) is not known to us?!?", - [Aid, FromAddr, FromPort]) + ?LOG_ERROR("eNB connection (id=~p, ~p:~p) is not known to us?!?", + [Aid, FromAddr, FromPort]) end, State; %% Catch-all for other kinds of SCTP events sctp_recv(State, {FromAddr, FromPort, AncData, Data}) -> - logger:debug("Unhandled SCTP event (~p:~p): ~p, ~p", - [FromAddr, FromPort, AncData, Data]), + ?LOG_DEBUG("Unhandled SCTP event (~p:~p): ~p, ~p", + [FromAddr, FromPort, AncData, Data]), State. @@ -228,7 +229,7 @@ close_conns(Sock, [{Aid, Client} | Clients]) -> {FromAddr, FromPort} = Client#client_state.addr_port, - logger:notice("Terminating eNB connection (id=~p, ~p:~p)", [Aid, FromAddr, FromPort]), + ?LOG_NOTICE("Terminating eNB connection (id=~p, ~p:~p)", [Aid, FromAddr, FromPort]), %% request to terminate an MME connection sctp_proxy:shutdown(Client#client_state.pid), %% gracefully close an eNB connection -- To view, visit https://gerrit.osmocom.org/c/erlang/osmo-s1gw/+/37216?usp=email To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: erlang/osmo-s1gw Gerrit-Branch: master Gerrit-Change-Id: I3b6e4296f736f9c87d2706ef5fb75146fd9f1239 Gerrit-Change-Number: 37216 Gerrit-PatchSet: 2 Gerrit-Owner: fixeria <vyanitskiy(a)sysmocom.de> Gerrit-Reviewer: Jenkins Builder Gerrit-Reviewer: fixeria <vyanitskiy(a)sysmocom.de> Gerrit-Reviewer: laforge <laforge(a)osmocom.org> Gerrit-Reviewer: pespin <pespin(a)sysmocom.de> Gerrit-MessageType: merged