From 1b0d2b25da0e1464224ea92743a6540ad3c5407b Mon Sep 17 00:00:00 2001 From: Daniel Pezely Date: Fri, 5 Nov 2021 15:19:51 -0600 Subject: [PATCH 1/3] Add test demonstrating issue, from @michaeldjeffrey --- test/router_v8_SUITE.erl | 79 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 79 insertions(+) create mode 100644 test/router_v8_SUITE.erl diff --git a/test/router_v8_SUITE.erl b/test/router_v8_SUITE.erl new file mode 100644 index 000000000..f3a8883d5 --- /dev/null +++ b/test/router_v8_SUITE.erl @@ -0,0 +1,79 @@ +-module(router_v8_SUITE). + +-export([ + all/0, + init_per_testcase/2, + end_per_testcase/2 +]). + +-export([ + invalid_context_test/1 +]). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("eunit/include/eunit.hrl"). + +%%-------------------------------------------------------------------- +%% @public +%% @doc +%% Running tests for this suite +%% @end +%%-------------------------------------------------------------------- +all() -> + [invalid_context_test]. + +%%-------------------------------------------------------------------- +%% TEST CASE SETUP +%%-------------------------------------------------------------------- +init_per_testcase(TestCase, Config) -> + test_utils:init_per_testcase(TestCase, Config). + +%%-------------------------------------------------------------------- +%% TEST CASE TEARDOWN +%%-------------------------------------------------------------------- +end_per_testcase(TestCase, Config) -> + test_utils:end_per_testcase(TestCase, Config). + +%%-------------------------------------------------------------------- +%% TEST CASES +%%-------------------------------------------------------------------- + +invalid_context_test(_Config) -> + GoodFunction = + <<"function Decoder(bytes, port) {\n" + " var payload = {\"Testing\": \"42\"};\n" + " return payload;\n" + "}">>, + BadFunction = <<"function Decoder() { returrrrrrrn 0; }">>, + + {ok, _VMPid} = router_v8:start_link(#{}), + {ok, VM} = router_v8:get(), + {ok, Context1} = erlang_v8:create_context(VM), + {ok, Context2} = erlang_v8:create_context(VM), + + Payload = erlang:binary_to_list(base64:decode(<<"H4Av/xACRU4=">>)), + Port = 6, + Result = #{<<"Testing">> => <<"42">>}, + + %% Eval good function and ensure function works more than once + ?assertMatch({ok, undefined}, erlang_v8:eval(VM, Context1, GoodFunction)), + ?assertMatch({ok, Result}, erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port])), + ?assertMatch({ok, Result}, erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port])), + + %% Call undefined function + ?assertMatch( + {error, <<"ReferenceError: Decoder is not defined", _/binary>>}, + erlang_v8:call(VM, Context2, <<"Decoder">>, [Payload, Port]) + ), + + %% First Context still works + ?assertMatch({ok, Result}, erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port])), + + %% Eval bad function + ?assertMatch({error, crashed}, erlang_v8:eval(VM, Context2, BadFunction)), + + %% First Context no longer works + ?assertMatch({ok, Result}, erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port])), + + gen_server:stop(_VMPid), + ok. From a0f5fea1c61cb8917fbfbb8b78d0bb5f893e0d47 Mon Sep 17 00:00:00 2001 From: Daniel Pezely Date: Thu, 18 Nov 2021 09:51:27 -0700 Subject: [PATCH 2/3] handle ambiguous V8 errors and recover by restarting V8 VM --- rebar.lock | 4 --- src/decoders/router_decoder_custom_worker.erl | 21 +++++++++++- test/router_decoder_SUITE.erl | 32 ++++++++++++++++++- test/router_v8_SUITE.erl | 29 ++++++++++++++--- 4 files changed, 76 insertions(+), 10 deletions(-) diff --git a/rebar.lock b/rebar.lock index 6eae85f81..3ca5f3552 100644 --- a/rebar.lock +++ b/rebar.lock @@ -57,10 +57,6 @@ {git,"https://github.com/helium/erlang-stats.git", {ref,"6afc9a78682d367c9312c64e9f0a5bc5477f2cd8"}}, 1}, - {<<"erlang_v8">>, - {git,"https://github.com/Vagabond/erlang_v8.git", - {ref,"601145a18add79488ddc21e8eefa238ed36fec5a"}}, - 0}, {<<"exor_filter">>, {git,"https://github.com/mpope9/exor_filter", {ref,"8f875bc5abc838af9ddbf6e7d2af8cc735ad2810"}}, diff --git a/src/decoders/router_decoder_custom_worker.erl b/src/decoders/router_decoder_custom_worker.erl index 05dd91f3c..854e3afc5 100644 --- a/src/decoders/router_decoder_custom_worker.erl +++ b/src/decoders/router_decoder_custom_worker.erl @@ -105,13 +105,32 @@ handle_call( ) of {error, invalid_context} -> + %% Execution reaching here implies V8 vm restarted recently {Delay, Backoff1} = backoff:fail(Backoff0), + %% Refresh their Context and JS definition: _ = erlang:send_after(Delay, self(), ?INIT_CONTEXT), {reply, {error, invalid_context}, State1#state{ context = undefined, backoff = Backoff1 }}; - {error, _} = Error -> + {error, Reason0} = Error -> + %% Track repeat offenders of bad JS code via external monitoring + Reason1 = + case size(Reason0) of + N when N =< 10 -> Reason0; + _ -> binary:part(Reason0, 0, 10) + end, + lager:error( + "V8 call error=\"~p\" uuid=~p app_eui=~p dev_eui=~p", + [ + Reason1, + maps:get(uuid, UplinkDetails, unknown), + maps:get(app_eui, UplinkDetails, unknown), + maps:get(dev_eui, UplinkDetails, unknown) + ] + ), + %% Due to limited error granularity from V8 Port, restart after any error: + erlang_v8:restart_vm(VM), {reply, Error, State1}; {ok, _} = OK -> {reply, OK, State1} diff --git a/test/router_decoder_SUITE.erl b/test/router_decoder_SUITE.erl index d1a339fef..928a26a96 100644 --- a/test/router_decoder_SUITE.erl +++ b/test/router_decoder_SUITE.erl @@ -10,7 +10,8 @@ decode_test/1, template_test/1, timeout_test/1, - too_many_test/1 + too_many_test/1, + v8_recovery_test/1 ]). -include_lib("common_test/include/ct.hrl"). @@ -348,6 +349,35 @@ too_many_test(Config) -> ?assertEqual(1, ets:info(router_decoder_custom_sup_ets, size)), ok. +v8_recovery_test(Config) -> + %% Set console to decoder channel mode + Tab = proplists:get_value(ets, Config), + ets:insert(Tab, {channel_type, decoder}), + + test_utils:join_device(Config), + + %% Waiting for reply from router to hotspot + test_utils:wait_state_channel_message(1250), + + ValidDecoder = <<"function Decoder(a,b,c) { return 42; }">>, + Result = 42, + BogusDecoder = <<"function Decoder(a,b,c) { crash @ here! }">>, + Port = 6, + Payload = erlang:binary_to_list(base64:decode(<<"H4Av/xACRU4=">>)), + UplinkDetails = #{}, + + %% One context sends a valid function definiton and another sends + %% bogus javascript, causing the V8 VM to be restarted. The first + %% context should then recover. + + {ok, Pid} = router_decoder_custom_sup:add(ValidDecoder), + {ok, Result} = router_decoder_custom_worker:decode(Pid, Payload, Port, UplinkDetails), + + {error, _} = router_decoder_custom_sup:add(BogusDecoder), + + {ok, Result} = router_decoder_custom_worker:decode(Pid, Payload, Port, UplinkDetails), + ok. + %% ------------------------------------------------------------------ %% Helper functions %% ------------------------------------------------------------------ diff --git a/test/router_v8_SUITE.erl b/test/router_v8_SUITE.erl index f3a8883d5..54ad11a73 100644 --- a/test/router_v8_SUITE.erl +++ b/test/router_v8_SUITE.erl @@ -46,10 +46,15 @@ invalid_context_test(_Config) -> "}">>, BadFunction = <<"function Decoder() { returrrrrrrn 0; }">>, - {ok, _VMPid} = router_v8:start_link(#{}), + VMPid = + case router_v8:start_link(#{}) of + {ok, Pid} -> Pid; + {error, {already_started, Pid}} -> Pid + end, {ok, VM} = router_v8:get(), {ok, Context1} = erlang_v8:create_context(VM), {ok, Context2} = erlang_v8:create_context(VM), + ?assertNotMatch(Context1, Context2), Payload = erlang:binary_to_list(base64:decode(<<"H4Av/xACRU4=">>)), Port = 6, @@ -72,8 +77,24 @@ invalid_context_test(_Config) -> %% Eval bad function ?assertMatch({error, crashed}, erlang_v8:eval(VM, Context2, BadFunction)), - %% First Context no longer works - ?assertMatch({ok, Result}, erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port])), + %% Upon an error (other than invalid_source_size), v8 Port gets + %% killed and restarted + ?assertMatch(true, erlang:is_process_alive(VMPid)), + + %% Unintuitively, we get invalid context when attempting to reuse first Context: + ?assertMatch( + {error, invalid_context}, + erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port]) + ), + %% But that's because set of Context needs to be repopulated within V8's VM: + erlang_v8:restart_vm(VM), + + %% First Context no longer works-- not ideal behavior but what we + %% have at hand. Ideally, return value would still match `Result'. + ?assertMatch( + {error, invalid_context}, + erlang_v8:call(VM, Context1, <<"Decoder">>, [Payload, Port]) + ), - gen_server:stop(_VMPid), + gen_server:stop(VMPid), ok. From 98721b4e6e4169d383107aef38e6b600a89ceffa Mon Sep 17 00:00:00 2001 From: Daniel Pezely Date: Thu, 18 Nov 2021 17:47:59 -0700 Subject: [PATCH 3/3] Log device_id instead of UUIDv4 --- rebar.lock | 4 ++++ src/decoders/router_decoder_custom_worker.erl | 4 ++-- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/rebar.lock b/rebar.lock index 3ca5f3552..6eae85f81 100644 --- a/rebar.lock +++ b/rebar.lock @@ -57,6 +57,10 @@ {git,"https://github.com/helium/erlang-stats.git", {ref,"6afc9a78682d367c9312c64e9f0a5bc5477f2cd8"}}, 1}, + {<<"erlang_v8">>, + {git,"https://github.com/Vagabond/erlang_v8.git", + {ref,"601145a18add79488ddc21e8eefa238ed36fec5a"}}, + 0}, {<<"exor_filter">>, {git,"https://github.com/mpope9/exor_filter", {ref,"8f875bc5abc838af9ddbf6e7d2af8cc735ad2810"}}, diff --git a/src/decoders/router_decoder_custom_worker.erl b/src/decoders/router_decoder_custom_worker.erl index 854e3afc5..474dff4a1 100644 --- a/src/decoders/router_decoder_custom_worker.erl +++ b/src/decoders/router_decoder_custom_worker.erl @@ -121,10 +121,10 @@ handle_call( _ -> binary:part(Reason0, 0, 10) end, lager:error( - "V8 call error=\"~p\" uuid=~p app_eui=~p dev_eui=~p", + "V8 call error=\"~p\" device_id=~p app_eui=~p dev_eui=~p", [ Reason1, - maps:get(uuid, UplinkDetails, unknown), + maps:get(device_id, UplinkDetails, unknown), maps:get(app_eui, UplinkDetails, unknown), maps:get(dev_eui, UplinkDetails, unknown) ]