HG-272: use scoped woody logs (#3)

.gitignore

@@ -6,6 +6,7 @@ log
 erl_crash.dump
 .tags*
 *.sublime-workspace
+.edts
 .DS_Store
 Dockerfile
 docker-compose.yml

config/sys.config

@@ -1,6 +1,6 @@
 [
     {sequences, [
-        {automaton_service_url, "http://machinegun:8022/v1/automaton"},
+        {automaton_service_url, <<"http://machinegun:8022/v1/automaton">>},
         {ip, "::"},
         {port, 8022},
         {net_opts, [
@@ -17,5 +17,8 @@
                 {formatter, lager_logstash_formatter}
             ]}
         ]}
+    ]},
+    {scoper, [
+        {storage, scoper_storage_lager}
     ]}
 ].

rebar.config

@@ -29,11 +29,12 @@
 %% Common project dependencies.
 {deps, [
 
-    {woody      , {git, "git@github.com:rbkmoney/woody_erlang.git", {branch, master}}},
+    {woody      , {git, "git@github.com:rbkmoney/woody_erlang.git", {branch, "master"}}},
     {seq_proto  , {git, "git@github.com:rbkmoney/sequences-proto.git", {branch, master}}},
     {mg_proto   , {git, "git@github.com:rbkmoney/machinegun_proto.git", {branch, master}}},
     {lager      , "3.2.1"},
-    {lager_logstash_formatter, {git, "git@github.com:rbkmoney/lager_logstash_formatter.git", {branch, master}}}
+    {lager_logstash_formatter, {git, "git@github.com:rbkmoney/lager_logstash_formatter.git", {branch, master}}},
+    {scoper     , {git, "git@github.com:rbkmoney/scoper.git", {branch, "master"}}}
 
 ]}.
 

rebar.lock

@@ -23,6 +23,10 @@
  {<<"mimerl">>,{pkg,<<"mimerl">>,<<"1.0.2">>},2},
  {<<"ranch">>,{pkg,<<"ranch">>,<<"1.4.0">>},2},
  {<<"rfc3339">>,{pkg,<<"rfc3339">>,<<"0.9.0">>},1},
+ {<<"scoper">>,
+  {git,"git@github.com:rbkmoney/scoper.git",
+       {ref,"30d206bf791def4a0c3b50834606baabfbd1ed71"}},
+  0},
  {<<"seq_proto">>,
   {git,"git@github.com:rbkmoney/sequences-proto.git",
        {ref,"a00415f6aa4a799b9c25149034246cd6792f4742"}},
@@ -38,7 +42,7 @@
   1},
  {<<"woody">>,
   {git,"git@github.com:rbkmoney/woody_erlang.git",
-       {ref,"2d00bda10454534e230d452b7338debafaf0a869"}},
+       {ref,"ad1e91050c36d8de15f1c7d8dd8a2c682d2d158c"}},
   0}]}.
 [
 {pkg_hash,[

src/seq_handler.erl

@@ -11,10 +11,23 @@
 -spec handle_function(woody:func(), woody:args(), woody_context:ctx(), woody:options()) ->
     {ok, woody:result()}.
 
-handle_function('GetCurrent', [SequenceId], Context, _Opts) ->
+handle_function(Func, Args, Context, Opts) ->
+    scoper:scope(sequences,
+        fun() -> handle_function_(Func, Args, Context, Opts) end
+    ).
+
+-spec handle_function_(woody:func(), woody:args(), woody_context:ctx(), woody:options()) ->
+    {ok, woody:result()}.
+handle_function_('GetCurrent', [SequenceId], Context, _Opts) ->
+    scoper:add_meta(#{
+        id => SequenceId
+    }),
     Value = seq_machine:get_current(SequenceId, Context),
     {ok, Value};
 
-handle_function('GetNext', [SequenceId], Context, _Opts) ->
+handle_function_('GetNext', [SequenceId], Context, _Opts) ->
+    scoper:add_meta(#{
+        id => SequenceId
+    }),
     Value = seq_machine:get_next(SequenceId, Context),
-    {ok, Value}.
+    {ok, Value}.

src/seq_machine.erl

@@ -27,18 +27,23 @@
 
 get_next(Id, Context) ->
     {ok, AuxState} = call_automaton_with_lazy_start('Call', Id, [?NIL], Context),
-    get_sequence_value(AuxState).
+    log_result(get_sequence_value(AuxState), "Sequence stepped").
 
 -spec get_current(id(), context()) ->
     integer().
 
 get_current(Id, Context) ->
     {ok, #'Machine'{aux_state = AuxState}} = call_automaton_with_lazy_start('GetMachine', Id, Context),
-    get_sequence_value(AuxState).
+    log_result(get_sequence_value(AuxState), "Sequence fetched").
 
 get_sequence_value(AuxState) ->
     unmarshal(AuxState).
 
+log_result(Value, Message) ->
+    ok = scoper:add_meta(#{value => Value}),
+    _ = lager:info(Message),
+    Value.
+
 %%
 
 ensure_started(Id, Context) ->
@@ -56,7 +61,10 @@ call_automaton(Function, Id, Args, Context) ->
 call_automaton(Function, Args, Context) ->
     Request = {{mg_proto_state_processing_thrift, 'Automaton'}, Function, Args},
     {ok, URL} = application:get_env(sequences, automaton_service_url),
-    Opts = #{url => URL, event_handler => {woody_event_handler_default, undefined}},
+    Opts = #{
+        url           => URL,
+        event_handler => scoper_woody_event_handler
+    },
     woody_client:call(Request, Opts, Context).
 
 call_automaton_with_lazy_start(Function, Id, Context) ->
@@ -85,13 +93,34 @@ construct_descriptor(Ref) ->
 -spec handle_function(func(), woody:args(), context(), woody:options()) ->
     {ok, term()}.
 
-handle_function('ProcessSignal', [#'SignalArgs'{signal = {init, _}}], _Context, _Opts) ->
+handle_function(Func, Args, Context, Opts) ->
+    scoper:scope(machine,
+        fun() -> handle_function_(Func, Args, Context, Opts) end
+    ).
+
+-spec handle_function_(func(), woody:args(), context(), woody:options()) ->
+    {ok, term()}.
+
+handle_function_('ProcessSignal', [Args], _Context, _Opts) ->
+    #'SignalArgs'{signal = {init, _}, machine = #'Machine'{id = ID}} = Args,
+    scoper:add_meta(#{
+        namespace => sequences,
+        id => ID,
+        activity => signal,
+        signal => init
+    }),
     {ok, #'SignalResult'{
         change = construct_change(init()),
         action = #'ComplexAction'{}
     }};
 
-handle_function('ProcessCall', [#'CallArgs'{machine = #'Machine'{aux_state = CurrentAuxState}}], _Context, _Opts) ->
+handle_function_('ProcessCall', [Args], _Context, _Opts) ->
+    #'CallArgs'{machine = #'Machine'{id = ID, aux_state = CurrentAuxState}} = Args,
+    scoper:add_meta(#{
+        namespace => sequences,
+        id => ID,
+        activity => call
+    }),
     NextAuxState = process_call(CurrentAuxState),
     {ok, #'CallResult'{
         change = construct_change(NextAuxState),
@@ -118,4 +147,4 @@ marshal(Int) when is_integer(Int) ->
     {arr, [{i, 1}, {i, Int}]}.
 
 unmarshal({arr, [{i, 1},  {i, Int}]}) ->
-    Int.
+    Int.

src/sequences.app.src

@@ -8,9 +8,10 @@
         lager,
         lager_logstash_formatter,
         woody,
+        scoper,
         seq_proto,
         mg_proto
     ]},
     {mod, {sequences, []}},
     {env, []}
-]}.
+]}.

src/sequences.erl

@@ -39,7 +39,7 @@ init([]) ->
             ip            => Ip,
             port          => genlib_app:env(?MODULE, port, 8022),
             net_opts      => genlib_app:env(?MODULE, net_opts, []),
-            event_handler => woody_event_handler_default,
+            event_handler => scoper_woody_event_handler,
             handlers      => [
                 get_handler_spec(sequences),
                 get_handler_spec(state_processor)
@@ -73,4 +73,4 @@ start(_StartType, _StartArgs) ->
 -spec stop(any()) ->
     ok.
 stop(_State) ->
-    ok.
+    ok.

test/seq_client.erl

@@ -25,11 +25,11 @@ call(Function, Args, Client) ->
     Call = {{seq_proto_sequences_thrift, 'Sequences'}, Function, Args},
     Opts = #{
         url => <<"http://sequences:8022/v1/sequences">>,
-        event_handler => {woody_event_handler_default, undefined}
+        event_handler => scoper_woody_event_handler
     },
     case woody_client:call(Call, Opts, Client) of
         {ok, Response} ->
             Response;
         {exception, Exception} ->
             throw(Exception)
-    end.
+    end.

test/sequences_tests_SUITE.erl

@@ -33,10 +33,12 @@ init_per_suite(C) ->
         {error_logger_hwm, 600},
         {suppress_application_start_stop, true},
         {handlers, [
-            {lager_common_test_backend, warning}
+            {lager_common_test_backend, [warning, {lager_logstash_formatter, []}]}
         ]}
+    ]) ++ genlib_app:start_application_with(scoper, [
+        {storage, scoper_storage_lager}
     ]) ++ genlib_app:start_application_with(sequences, [
-        {automaton_service_url, "http://machinegun:8022/v1/automaton"}
+        {automaton_service_url, <<"http://machinegun:8022/v1/automaton">>}
     ]),
     [{suite_apps, Apps} | C].
 
@@ -76,4 +78,4 @@ get_next(C) ->
 %%
 
 get_sequence_id() ->
-    integer_to_binary(erlang:system_time(micro_seconds)).
+    integer_to_binary(erlang:system_time(micro_seconds)).