Skip to content

Commit

Permalink
Change device logs API (#27)
Browse files Browse the repository at this point in the history
* Change device logs API
* Ensure unicode encoding
* Cleanup tests
* upgrade eresu
* Add test suite for log encoding
* Add function for manual log tests
  • Loading branch information
maehjam authored May 3, 2024
1 parent c002e7d commit f9f40f7
Show file tree
Hide file tree
Showing 13 changed files with 326 additions and 19 deletions.
7 changes: 6 additions & 1 deletion rebar.config
Original file line number Diff line number Diff line change
Expand Up @@ -56,8 +56,13 @@
]}
]},
{test, [
{overrides,
[{add, eresu, [
{erl_opts, [{d,'TEST'}]}]
}]
},
{deps, [
grisp_emulation,
{grisp_emulation, "0.2.0"},
{grisp_manager, {git, "[email protected]:stritzinger/grisp_manager", {branch, "main"}}}
]},
{ct_opts, [{sys_config, "./config/test.config"}]},
Expand Down
17 changes: 17 additions & 0 deletions src/grisp_connect.erl
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,8 @@

-module(grisp_connect).

-include_lib("kernel/include/logger.hrl").

%--- Exports -------------------------------------------------------------------

% API functions
Expand All @@ -13,6 +15,8 @@
-export([ping/0]).
-export([link_device/0]).
-export([link_device/1]).
-export([log/2]).
-export([test_log_encoding/0]).

%--- API Functions -------------------------------------------------------------

Expand Down Expand Up @@ -47,3 +51,16 @@ link_device() ->
{ok, binary()} | {error, invalid_token}.
link_device(Token) ->
grisp_connect_client:request(post, device_linking_token, #{token => Token}).

% @doc Log from inside grisp_connect for testing.
log(Level, Args) -> apply(logger, Level, Args).

% @doc For manually testing the log encoding.
% Alternative to shell commands. The shell double encodes unicode strings.
test_log_encoding() ->
String = "@#$%^&*()_ +{}|:\"<>?-[];'./,\\`~!\néäüßóçøáîùêñÄÖÜÉÁÍÓÚàèìòùÂÊÎÔÛ",
Binary = <<"@#$%^&*()_ +{}|:\"<>?-[];'./,\\`~!\néäüßóçøáîùêñÄÖÜÉÁÍÓÚàèìòùÂÊÎÔÛ"/utf8>>,
?LOG_NOTICE("List:\n" ++ String),
?LOG_NOTICE(<<"Binary: \n", Binary/binary>>),
?LOG_NOTICE("List:~n~tp~nBinary:~n~tp~n", [String, Binary]),
?LOG_NOTICE(#{list => String, binary => Binary}).
39 changes: 38 additions & 1 deletion src/grisp_connect_log_server.erl
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ handle_info(send_logs, #state{active = false, timer = undefined} = State) ->

send_logs_chunk({Events, Dropped}) ->
LogUpdate = #{
events => [[Seq, E] || {Seq, E} <- Events],
events => [[Seq, jsonify(E)] || {Seq, E} <- Events],
dropped => Dropped
},
case grisp_connect_client:request(post, logs, LogUpdate) of
Expand All @@ -71,3 +71,40 @@ send_logs_chunk({Events, Dropped}) ->
E ->
?LOG_ERROR(#{event => send_logs, data => E})
end.

jsonify(Event) ->
jsonify_meta(jsonify_msg(binary_to_term(base64:decode(Event)))).

jsonify_msg(#{msg := {string, String}} = Event) ->
maps:put(msg, unicode:characters_to_binary(String), Event);
jsonify_msg(#{msg := {report, Report}} = Event) ->
case jsx:is_term(Report) of
true ->
maps:put(msg, Report, Event);
false ->
String = unicode:characters_to_binary(
io_lib:format("[JSON incompatible term]~n~tp", [Report])
),
maps:put(msg, String, Event)
end;
jsonify_msg(#{msg := {FormatString, Term}} = Event) ->
%FIXME: scan format and ensure unicode encoding
String = unicode:characters_to_binary(io_lib:format(FormatString, Term)),
maps:put(msg, String, Event).

jsonify_meta(#{meta := Meta} = Event) ->
MFA = case maps:is_key(mfa, Meta) of
true ->
{M, F, A} = maps:get(mfa, Meta),
[M, F, A];
false ->
null
end,
File = case maps:is_key(file, Meta) of
true -> unicode:characters_to_binary(maps:get(file, Meta));
false -> null
end,
Default = #{mfa => MFA, file => File},
Optional = maps:without(maps:keys(Default), Meta),
FilterFun = fun(Key, Value) -> jsx:is_term(#{Key => Value}) end,
maps:put(meta, maps:merge(maps:filter(FilterFun, Optional), Default), Event).
File renamed without changes.
File renamed without changes.
File renamed without changes.
File renamed without changes.
File renamed without changes.
File renamed without changes.
28 changes: 12 additions & 16 deletions test/grisp_connect_api_SUITE.erl
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,10 @@

-compile([export_all, nowarn_export_all]).

-import(grisp_connect_test_client, [wait_connection/0]).
-import(grisp_connect_test_client, [serial_number/0]).
-import(grisp_connect_test_client, [cert_dir/0]).

%--- API -----------------------------------------------------------------------

all() ->
Expand All @@ -18,7 +22,7 @@ all() ->

init_per_suite(Config) ->
PrivDir = ?config(priv_dir, Config),
CertDir = filename:join(?config(data_dir, Config), "certs"),
CertDir = cert_dir(),

PolicyFile = filename:join(PrivDir, "policies.term"),
?assertEqual(ok, file:write_file(PolicyFile, <<>>)),
Expand All @@ -30,31 +34,33 @@ init_per_suite(Config) ->
end_per_suite(Config) ->
grisp_connect_manager:cleanup_apps(?config(apps, Config)).

init_per_testcase(_, Config) ->
init_per_testcase(TestCase, Config) ->
{ok, _} = application:ensure_all_started(grisp_emulation),
application:set_env(grisp_connect, test_cert_dir, ?config(cert_dir, Config)),
{ok, _} = application:ensure_all_started(grisp_connect),
case TestCase of
auto_connect_test -> ok;
_ -> ok = wait_connection()
end,
Config.

end_per_testcase(_, Config) ->
ok = application:stop(grisp_connect),
mnesia:activity(transaction, fun() ->
mnesia:delete({grisp_device, <<"0000">>})
mnesia:delete({grisp_device, serial_number()})
end),
flush(),
Config.

%--- Tests ---------------------------------------------------------------------

auto_connect_test(_) ->
?assertMatch(ok, wait_connection(20)).
?assertMatch(ok, wait_connection()).

ping_test(_) ->
?assertMatch(ok, wait_connection(20)),
?assertMatch({ok, <<"pang">>}, grisp_connect:ping()).

link_device_test(_) ->
?assertMatch(ok, wait_connection(20)),
?assertMatch({error, token_undefined}, grisp_connect:link_device()),
application:set_env(grisp_connect, device_linking_token, <<"token">>),
?assertMatch({error, invalid_token}, grisp_connect:link_device()),
Expand All @@ -65,16 +71,6 @@ link_device_test(_) ->

%--- Internal ------------------------------------------------------------------

wait_connection(0) ->
{error, timeout};
wait_connection(N) ->
case grisp_connect:is_connected() of
true -> ok;
false ->
ct:sleep(100),
wait_connection(N - 1)
end.

flush() ->
receive Any -> ct:pal("Flushed: ~p", [Any]), flush()
after 0 -> ok
Expand Down
220 changes: 220 additions & 0 deletions test/grisp_connect_log_SUITE.erl
Original file line number Diff line number Diff line change
@@ -0,0 +1,220 @@
-module(grisp_connect_log_SUITE).

-behaviour(ct_suite).
-include_lib("common_test/include/ct.hrl").
-include_lib("stdlib/include/assert.hrl").

-compile([export_all, nowarn_export_all]).

-import(grisp_connect_test_client, [cert_dir/0]).
-import(grisp_connect_test_client, [serial_number/0]).
-import(grisp_connect_test_client, [wait_connection/0]).

%--- API -----------------------------------------------------------------------

all() ->
[
F
||
{F, 1} <- ?MODULE:module_info(exports),
lists:suffix("_test", atom_to_list(F))
].

init_per_suite(Config) ->
PrivDir = ?config(priv_dir, Config),
CertDir = cert_dir(),

PolicyFile = filename:join(PrivDir, "policies.term"),
?assertEqual(ok, file:write_file(PolicyFile, <<>>)),
application:set_env(seabac, policy_file, PolicyFile),

Config2 = grisp_connect_manager:start(CertDir, Config),
grisp_connect_manager:link_device(),
[{cert_dir, CertDir} | Config2].

end_per_suite(Config) ->
grisp_connect_manager:cleanup_apps(?config(apps, Config)).

init_per_testcase(log_level_test, Config) ->
#{level := Level} = logger:get_primary_config(),
logger:set_primary_config(level, debug),
init_per_testcase(other, [{default_level, Level} | Config]);
init_per_testcase(_, Config) ->
{ok, _} = application:ensure_all_started(grisp_emulation),
application:set_env(grisp_connect, test_cert_dir, ?config(cert_dir, Config)),
{ok, _} = application:ensure_all_started(grisp_connect),
ok = wait_connection(),
ct:sleep(1000),
send_logs(),
ct:sleep(1000),
Config.

end_per_testcase(log_level_test, Config) ->
logger:set_primary_config(level, ?config(default_level, Config)),
end_per_testcase(other, Config);
end_per_testcase(_, Config) ->
Config.

%--- Tests ---------------------------------------------------------------------

string_logs_test(_) ->
LastSeq = last_seq(),
S1 = "@#$%^&*()_ +{}|:\"<>?-[];'./,\\`~!\néäüßóçøáîùêñÄÖÜÉÁÍÓÚàèìòùÂÊÎÔÛ€",
S2 = <<"@#$%^&*()_ +{}|:\"<>?-[];'./,\\`~!\néäüßóçøáîùêñÄÖÜÉÁÍÓÚàèìòùÂÊÎÔÛ€"/utf8>>,
Strings = [S1, S2],
Texts = [<<S2/binary, "\n">>, <<S2/binary, "\n">>],
Seqs = [LastSeq + 1, LastSeq + 2],
Fun = fun({Seq, String, Text}) ->
grisp_connect:log(error, [String]),
send_logs(),
ct:sleep(100),
check_log(Seq, error, Text)
end,
lists:map(Fun, lists:zip3(Seqs, Strings, Texts)).

formatted_logs_test(_) ->
ArgsList = [["~c, ~tc", [, $€]],
["~p, ~tp", ['tést', 'tést']],
["~p, ~tp", [<<"tést">>, <<"tést"/utf8>>]],
["~s, ~ts", ["tést", "tést"]],
["~s, ~ts", [<<"tést">>, <<"tést"/utf8>>]]],
LastSeq = last_seq(),
Texts = [<<"ä, €\n"/utf8>>,
<<"tést, tést\n"/utf8>>,
<<"<<\"tést\">>, <<\"tést\"/utf8>>\n"/utf8>>,
<<"tést, tést\n"/utf8>>,
<<"tést, tést\n"/utf8>>],
Seqs = lists:seq(LastSeq + 1, LastSeq + length(ArgsList)),
Fun = fun({Seq, Args, Text}) ->
grisp_connect:log(error, Args),
send_logs(),
ct:sleep(100),
check_log(Seq, error, Text)
end,
lists:map(Fun, lists:zip3(Seqs, ArgsList, Texts)).

structured_logs_test(_) ->
Events = [#{event => <<"tést"/utf8>>},
#{event => "tést"},
#{event => 'tést'},
#{event => ['tést1', <<"tést2"/utf8>>]},
#{event => #{'tèst1' => true}},
#{event => #{<<"errör"/utf8>> => false}},
#{event => 1234},
#{event => 0.1},
#{event => {'äh', 'bäh'}}],
LastSeq = last_seq(),
Texts = [<<" event: <<\"tést\"/utf8>>\n"/utf8>>,
<<" event: tést\n"/utf8>>,
<<" event: <<\"tést\"/utf8>>\n"/utf8>>,
<<" event: [<<\"tést1\"/utf8>>,<<\"tést2\"/utf8>>]\n"/utf8>>,
<<" event: #{tèst1 => true}\n"/utf8>>,
<<" event: #{<<\"errör\"/utf8>> => false}\n"/utf8>>,
<<" event: 1234\n"/utf8>>,
<<" event: 0.1\n"/utf8>>,
<<"[JSON incompatible term]\n#{event => {äh,bäh}}\n"/utf8>>],
Seqs = lists:seq(LastSeq + 1, LastSeq + length(Events)),
Fun = fun({Seq, Event, Text}) ->
grisp_connect:log(error, [Event]),
send_logs(),
ct:sleep(100),
check_log(Seq, error, Text)
end,
lists:map(Fun, lists:zip3(Seqs, Events, Texts)).

log_level_test(_) ->
Levels = [emergency,
alert,
critical,
error,
warning,
notice,
info,
debug],
LastSeq = last_seq(),
Seqs = lists:seq(LastSeq + 1, LastSeq + length(Levels)),
Fun = fun({Seq, Level}) ->
grisp_connect:log(Level, ["level test"]),
send_logs(),
ct:sleep(100),
check_log(Seq, Level, <<"level test\n"/utf8>>)
end,
lists:map(Fun, lists:zip(Seqs, Levels)),

% Check that logs outside of configured level are not send to the server
% One needs to be able to control the traffic
logger:set_primary_config(level, notice),
grisp_connect:log(info, ["level test"]),
send_logs(),
ct:sleep(100),
Logs = grisp_manager_device_logs:fetch(serial_number(), last_seq()),
?assertEqual([], Logs).

meta_data_test(_) ->
Meta = #{custom1 => <<"binäry"/utf8>>,
custom2 => ['é1', <<"é2"/utf8>>],
custom3 => 'åtom',
custom4 => #{'kèy' => 'välüe'},
custom5 => #{boolean => true},
custom6 => 6,
custom7 => 7.0},
LoggerConfig = #{legacy_header => true,
single_line => false,
template => [[logger_formatter, header], "\n",
custom1, "\n",
custom2, "\n",
custom3, "\n",
custom4, "\n",
custom5, "\n",
custom6, "\n",
custom7, "\n",
msg, "\n"]},
application:set_env(grisp_manager, device_log_config, LoggerConfig),
Text = iolist_to_binary(
[<<"<<\"binäry\"/utf8>>\n"/utf8>>,
<<"\[<<\"é1\"/utf8>>,<<\"é2\"/utf8>>\]\n"/utf8>>,
<<"<<\"åtom\"/utf8>>\n"/utf8>>,
<<"#{kèy => <<\"välüe\"/utf8>>}\n"/utf8>>,
<<"#{boolean => true}\n"/utf8>>,
<<"6\n"/utf8>>,
<<"7.0\n"/utf8>>,
<<"Test meta\n"/utf8>>]),
LastSeq = last_seq(),
Seq = LastSeq + 1,
grisp_connect:log(error, ["Test meta", Meta]),
send_logs(),
ct:sleep(100),
check_log(Seq, error, Text).

%--- Internal ------------------------------------------------------------------

send_logs() ->
LogServer = whereis(grisp_connect_log_server),
LogServer ! send_logs.

last_seq() ->
{Seq, _} = case grisp_manager_device_logs:fetch(serial_number(), -1) of
[] -> {0, []};
List -> lists:last(List)
end,
Seq.

check_log(Seq, Level, Text) ->
Logs = grisp_manager_device_logs:fetch(serial_number(), Seq - 1),
?assertMatch([{Seq, _}], Logs, ["Text: ", Text]),
[{_, Log}] = Logs,
Split = binary:split(Log, <<"\n">>, [trim_all]),
?assertMatch([_, Text], Split, ["Text: ", Text]),
Header = log_header(Level),
?assertMatch([Header, _],
binary:split(Log, <<"= ">>),
["Header: ", Header]).

log_header(emergency) -> <<"=EMERGENCY REPORT===">>;
log_header(alert) -> <<"=ALERT REPORT===">>;
log_header(critical) -> <<"=CRITICAL REPORT===">>;
log_header(error) -> <<"=ERROR REPORT===">>;
log_header(warning) -> <<"=WARNING REPORT===">>;
log_header(notice) -> <<"=NOTICE REPORT===">>;
log_header(info) -> <<"=INFO REPORT===">>;
log_header(debug) -> <<"=DEBUG REPORT===">>.
Loading

0 comments on commit f9f40f7

Please sign in to comment.