From 35eef6ae51e7a3dfad2d6783e1d204e40bf9ddc8 Mon Sep 17 00:00:00 2001 From: Naoto Ono Date: Mon, 27 Mar 2023 16:58:20 +0900 Subject: [PATCH] DAP: introduce Rdbg Inspector --- lib/debug/dap_custom/traceInspector.rb | 314 ++++++++++++++++++++++++ lib/debug/frame_info.rb | 9 + lib/debug/server_dap.rb | 12 + lib/debug/session.rb | 14 +- lib/debug/thread_client.rb | 6 +- test/protocol/rdbgTraceInspctor_test.rb | 218 ++++++++++++++++ test/support/protocol_test_case.rb | 64 +++++ 7 files changed, 629 insertions(+), 8 deletions(-) create mode 100644 lib/debug/dap_custom/traceInspector.rb create mode 100644 test/protocol/rdbgTraceInspctor_test.rb diff --git a/lib/debug/dap_custom/traceInspector.rb b/lib/debug/dap_custom/traceInspector.rb new file mode 100644 index 000000000..403df00c6 --- /dev/null +++ b/lib/debug/dap_custom/traceInspector.rb @@ -0,0 +1,314 @@ +module DEBUGGER__ + module DAP_TraceInspector + class MultiTracer < Tracer + def initialize ui, evts, trace_params, max_log_size: nil, **kw + @evts = evts + @log = [] + @trace_params = trace_params + if max_log_size + @max_log_size = max_log_size + else + @max_log_size = 50000 + end + @dropped_trace_cnt = 0 + super(ui, **kw) + @type = 'multi' + @name = 'TraceInspector' + end + + attr_accessor :dropped_trace_cnt + attr_reader :log + + def setup + @tracer = TracePoint.new(*@evts){|tp| + next if skip?(tp) + + case tp.event + when :call, :c_call, :b_call + if @trace_params + params = parameters_info tp + end + append(call_trace_log(tp, params: params)) + when :return, :c_return, :b_return + return_str = DEBUGGER__.safe_inspect(tp.return_value, short: true, max_length: 4096) + append(call_trace_log(tp, return_str: return_str)) + when :line + append(line_trace_log(tp)) + end + } + end + + def parameters_info tp + b = tp.binding + tp.parameters.map{|_type, name| + begin + { name: name, value: DEBUGGER__.safe_inspect(b.local_variable_get(name), short: true, max_length: 4096) } + rescue NameError, TypeError + nil + end + }.compact + end + + def call_identifier_str tp + if tp.defined_class + minfo(tp) + else + "block" + end + end + + def append log + if @log.size >= @max_log_size + @dropped_trace_cnt += 1 + @log.shift + end + @log << log + end + + def call_trace_log tp, return_str: nil, params: nil + log = { + depth: DEBUGGER__.frame_depth, + name: call_identifier_str(tp), + threadId: Thread.current.instance_variable_get(:@__thread_client_id), + location: { + path: tp.path, + line: tp.lineno + } + } + log[:returnValue] = return_str if return_str + log[:parameters] = params if params && params.size > 0 + log + end + + def line_trace_log tp + { + depth: DEBUGGER__.frame_depth, + threadId: Thread.current.instance_variable_get(:@__thread_client_id), + location: { + path: tp.path, + line: tp.lineno + } + } + end + + def skip? tp + super || !@evts.include?(tp.event) + end + + def skip_with_pattern?(tp) + super && !tp.method_id&.match?(@pattern) + end + end + + class Custom_Recorder < ThreadClient::Recorder + def initialize max_log_size: nil + if max_log_size + @max_log_size = max_log_size + else + @max_log_size = 50000 + end + @dropped_trace_cnt = 0 + super() + end + + attr_accessor :dropped_trace_cnt + + def append frames + if @log.size >= @max_log_size + @dropped_trace_cnt += 1 + @log.shift + end + @log << frames + end + end + + module Custom_UI_DAP + def custom_dap_request_rdbgTraceInspector(req) + @q_msg << req + end + end + + module Custom_Session + def process_trace_cmd req + cmd = req.dig('arguments', 'subCommand') + case cmd + when 'enable' + events = req.dig('arguments', 'events') + evts = [] + trace_params = false + filter = req.dig('arguments', 'filterRegExp') + max_log_size = req.dig('arguments', 'maxLogSize') + events.each{|evt| + case evt + when 'traceLine' + evts << :line + when 'traceCall' + evts << :call + evts << :b_call + when 'traceReturn' + evts << :return + evts << :b_return + when 'traceParams' + trace_params = true + when 'traceClanguageCall' + evts << :c_call + when 'traceClanguageReturn' + evts << :c_return + else + raise "unknown trace type #{evt}" + end + } + add_tracer MultiTracer.new @ui, evts, trace_params, max_log_size: max_log_size, pattern: filter + @ui.respond req, {} + when 'disable' + if t = find_multi_trace + t.disable + end + @ui.respond req, {} + when 'collect' + logs = [] + if t = find_multi_trace + logs = t.log + if t.dropped_trace_cnt > 0 + @ui.puts "Return #{logs.size} traces and #{t.dropped_trace_cnt} traces are dropped" + else + @ui.puts "Return #{logs.size} traces" + end + t.dropped_trace_cnt = 0 + end + @ui.respond req, logs: logs + else + raise "Unknown trace sub command #{cmd}" + end + return :retry + end + + def find_multi_trace + @tracers.values.each{|t| + if t.type == 'multi' + return t + end + } + return nil + end + + def process_record_cmd req + cmd = req.dig('arguments', 'subCommand') + case cmd + when 'enable' + @tc << [:dap, :rdbgTraceInspector, req] + when 'disable' + @tc << [:dap, :rdbgTraceInspector, req] + when 'step' + tid = req.dig('arguments', 'threadId') + count = req.dig('arguments', 'count') + if tc = find_waiting_tc(tid) + @ui.respond req, {} + tc << [:step, :in, count] + else + fail_response req + end + when 'stepBack' + tid = req.dig('arguments', 'threadId') + count = req.dig('arguments', 'count') + if tc = find_waiting_tc(tid) + @ui.respond req, {} + tc << [:step, :back, count] + else + fail_response req + end + when 'collect' + tid = req.dig('arguments', 'threadId') + if tc = find_waiting_tc(tid) + tc << [:dap, :rdbgTraceInspector, req] + else + fail_response req + end + else + raise "Unknown record sub command #{cmd}" + end + end + + def custom_dap_request_rdbgTraceInspector(req) + cmd = req.dig('arguments', 'command') + case cmd + when 'trace' + process_trace_cmd req + when 'record' + process_record_cmd req + else + raise "Unknown command #{cmd}" + end + end + + def custom_dap_request_event_rdbgTraceInspector(req, result) + cmd = req.dig('arguments', 'subCommand') + case cmd + when 'enable' + @ui.respond req, {} + when 'disable' + @ui.respond req, {} + when 'collect' + cnt = result.delete :dropped_trace_cnt + if cnt > 0 + @ui.puts "Return #{result[:logs].size} traces and #{cnt} traces are dropped" + else + @ui.puts "Return #{result[:logs].size} traces" + end + @ui.respond req, result + else + raise "Unknown command #{cmd}" + end + end + end + + module Custom_ThreadClient + def custom_dap_request_rdbgTraceInspector(req) + cmd = req.dig('arguments', 'subCommand') + case cmd + when 'enable' + size = req.dig('arguments', 'maxLogSize') + @recorder = Custom_Recorder.new max_log_size: size + @recorder.enable + event! :protocol_result, :rdbgTraceInspector, req + when 'disable' + if @recorder&.enabled? + @recorder.disable + end + @recorder = nil + event! :protocol_result, :rdbgTraceInspector, req + when 'collect' + logs = [] + log_index = nil + unless @recorder.nil? + log_index = @recorder.log_index + @recorder.log.each{|frames| + crt_frame = frames[0] + log = { + name: crt_frame.name, + location: { + path: crt_frame.location.path, + line: crt_frame.location.lineno, + }, + depth: crt_frame.frame_depth + } + if params = crt_frame.iseq_parameters_info + log[:parameters] = params + end + if return_str = crt_frame.return_str + log[:returnValue] = return_str + end + logs << log + } + end + event! :protocol_result, :rdbgTraceInspector, req, logs: logs, stoppedIndex: log_index, dropped_trace_cnt: @recorder.dropped_trace_cnt + @recorder.dropped_trace_cnt = 0 + else + raise "Unknown command #{cmd}" + end + end + end + + ::DEBUGGER__::SESSION.extend_feature session: Custom_Session, thread_client: Custom_ThreadClient, ui: Custom_UI_DAP + end +end diff --git a/lib/debug/frame_info.rb b/lib/debug/frame_info.rb index fa4135935..8eb041969 100644 --- a/lib/debug/frame_info.rb +++ b/lib/debug/frame_info.rb @@ -147,6 +147,15 @@ def local_variables end end + def iseq_parameters_info + case frame_type + when :block, :method + parameters_info + else + nil + end + end + def parameters_info vars = iseq.parameters_symbols vars.map{|var| diff --git a/lib/debug/server_dap.rb b/lib/debug/server_dap.rb index bae1e4dda..814931153 100644 --- a/lib/debug/server_dap.rb +++ b/lib/debug/server_dap.rb @@ -274,6 +274,14 @@ def recv_request retry end + def load_rdbgExtension req + if exts = req.dig('arguments', 'rdbgExtension') + exts.each{|ext| + require_relative "dap_custom/#{File.basename(ext)}" + } + end + end + def process while req = recv_request raise "not a request: #{req.inspect}" unless req['type'] == 'request' @@ -288,6 +296,8 @@ def process UI_DAP.local_fs_map_set req.dig('arguments', 'localfs') || req.dig('arguments', 'localfsMap') || true @nonstop = true + load_rdbgExtension req + when 'attach' send_response req UI_DAP.local_fs_map_set req.dig('arguments', 'localfs') || req.dig('arguments', 'localfsMap') @@ -298,6 +308,8 @@ def process @nonstop = false end + load_rdbgExtension req + when 'configurationDone' send_response req diff --git a/lib/debug/session.rb b/lib/debug/session.rb index 2595869f2..6007846d7 100644 --- a/lib/debug/session.rb +++ b/lib/debug/session.rb @@ -1993,6 +1993,13 @@ def before_fork need_lock = true def after_fork_parent @ui.after_fork_parent end + + # experimental API + def extend_feature session: nil, thread_client: nil, ui: nil + Session.include session if session + ThreadClient.include thread_client if thread_client + @ui.extend ui if ui + end end class ProcessGroup @@ -2147,13 +2154,6 @@ def flush end end - # experimental API - def extend_feature session: nil, thread_client: nil, ui: nil - Session.include session if session - ThreadClient.include thread_client if thread_client - @ui.extend ui if ui - end - # manual configuration methods def self.add_line_breakpoint file, line, **kw diff --git a/lib/debug/thread_client.rb b/lib/debug/thread_client.rb index cbecdf54d..05d2ca077 100644 --- a/lib/debug/thread_client.rb +++ b/lib/debug/thread_client.rb @@ -1300,10 +1300,14 @@ def initialize frame._callee = b.eval('__callee__') end } - @log << frames + append(frames) } end + def append frames + @log << frames + end + def enable unless @tp_recorder.enabled? @log.clear diff --git a/test/protocol/rdbgTraceInspctor_test.rb b/test/protocol/rdbgTraceInspctor_test.rb new file mode 100644 index 000000000..18a94b61f --- /dev/null +++ b/test/protocol/rdbgTraceInspctor_test.rb @@ -0,0 +1,218 @@ +# frozen_string_literal: true + +require_relative '../support/protocol_test_case' + +module DEBUGGER__ + class RdbgTraceInspectorTraceTest < ProtocolTestCase + PROGRAM = <<~RUBY + 1| def foo + 2| 'bar' + 3| end + 4| foo + 5| foo + RUBY + + def test_defaut_setting + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_trace_enable + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_trace_collect_result( + [ + { + returnValue: "\"bar\"", + name: 'Object#foo', + location: { + line: 3, + } + }, + { + name: 'Object#foo', + location: { + line: 1, + } + }, + { + location: { + line: 4, + } + }, + ] + ) + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + + def test_call_event + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_trace_enable(events: ['traceCall']) + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_trace_collect_result( + [ + { + name: 'Object#foo', + location: { + line: 1, + } + }, + ] + ) + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + + def test_return_event + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_trace_enable(events: ['traceReturn']) + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_trace_collect_result( + [ + { + returnValue: "\"bar\"", + name: 'Object#foo', + location: { + line: 3, + } + }, + ] + ) + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + + def test_line_event + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_trace_enable(events: ['traceLine']) + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_trace_collect_result( + [ + { + location: { + line: 4, + } + }, + ] + ) + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + + def test_restart_trace + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_trace_enable + req_rdbgTraceInspector_trace_disable + req_rdbgTraceInspector_trace_enable(events: ['traceLine']) + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_trace_collect_result( + [ + { + location: { + line: 4, + } + }, + ] + ) + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + end + + class RdbgTraceInspectorRecordTest < ProtocolTestCase + PROGRAM = <<~RUBY + 1| module Foo + 2| class Bar + 3| def self.a + 4| "hello" + 5| end + 6| end + 7| Bar.a + 8| bar = Bar.new + 9| end + RUBY + + def test_defaut_setting + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_record_enable + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_record_collect_result( + [ + { + name: "", + location: { + line: 2, + } + }, + { + name: "", + location: { + line: 3, + } + } + ] + ) + req_rdbgTraceInspector_record_step_back 4 + assert_line_num 2 + req_rdbgTraceInspector_record_step 1 + assert_line_num 3 + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + + def test_restart_trace + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments][:rdbgExtension] = ["traceInspector"] + run_protocol_scenario(PROGRAM, cdp: false) do + req_rdbgTraceInspector_record_enable + req_rdbgTraceInspector_record_disable + req_rdbgTraceInspector_record_enable + req_add_breakpoint 5 + req_continue + assert_rdbgTraceInspector_record_collect_result( + [ + { + name: "", + location: { + line: 2, + } + }, + { + name: "", + location: { + line: 3, + } + } + ] + ) + req_rdbgTraceInspector_record_step_back 4 + assert_line_num 2 + req_rdbgTraceInspector_record_step 1 + assert_line_num 3 + req_terminate_debuggee + end + ensure + DEBUGGER__::INITIALIZE_DAP_MSGS[1][:arguments].delete :rdbgExtension + end + end +end diff --git a/test/support/protocol_test_case.rb b/test/support/protocol_test_case.rb index b8741e3db..00a4b2d20 100644 --- a/test/support/protocol_test_case.rb +++ b/test/support/protocol_test_case.rb @@ -219,6 +219,22 @@ def gather_variables(frame_idx: 0, type: "locals") end end + def req_rdbgTraceInspector_trace_enable events: ['traceLine', 'traceCall', 'traceReturn', 'traceParams'] + send_custom_dap_request 'rdbgTraceInspector', command: 'trace', subCommand: 'enable', events: events + end + + def req_rdbgTraceInspector_trace_disable + send_custom_dap_request 'rdbgTraceInspector', command: 'trace', subCommand: 'disable' + end + + def req_rdbgTraceInspector_record_enable + send_custom_dap_request 'rdbgTraceInspector', command: 'record', subCommand: 'enable' + end + + def req_rdbgTraceInspector_record_disable + send_custom_dap_request 'rdbgTraceInspector', command: 'record', subCommand: 'disable' + end + def assert_locals_result expected, frame_idx: 0 case get_target_ui when 'vscode' @@ -301,8 +317,51 @@ def assert_watch_result expected, expression, frame_idx: 0 end end + def req_rdbgTraceInspector_record_step_back count + send_custom_dap_request 'rdbgTraceInspector', command: 'record', subCommand: 'stepBack', threadId: 1, count: count + end + + def req_rdbgTraceInspector_record_step count + send_custom_dap_request 'rdbgTraceInspector', command: 'record', subCommand: 'step', threadId: 1, count: count + end + + def assert_rdbgTraceInspector_record_collect_result expected + res = send_custom_dap_request 'rdbgTraceInspector', command: 'record', subCommand: 'collect', threadId: 1 + assert_collect_result(res, expected) do |exp, log| + check_hash_values(exp, log, :name) && + check_hash_values(exp[:location], log[:location], :line) + end + end + + def assert_rdbgTraceInspector_trace_collect_result expected + res = send_custom_dap_request 'rdbgTraceInspector', command: 'trace', subCommand: 'collect' + assert_collect_result(res, expected) do |exp, log| + check_hash_values(exp, log, :returnValue) && + check_hash_values(exp, log, :name) && + check_hash_values(exp[:location], log[:location], :line) + end + end + # Not API + def assert_collect_result res, expected + logs = res.dig(:body, :logs) + expected.each{|exp| + matched = logs.find {|log| + yield exp, log + } + if matched.nil? + msg = create_protocol_message "Expected to include\n`#{JSON.pretty_generate exp}`\nIn\n`#{JSON.pretty_generate logs}`\n" + flunk(msg) + end + } + end + + def check_hash_values hash_a, hash_b, key + hash_a.has_key?(key) == hash_b.has_key?(key) && + hash_a[key] == hash_b[key] + end + def attach_to_cdp_server_ body = get_request HOST, @remote_info.port, '/json' Timeout.timeout(TIMEOUT_SEC) do @@ -558,6 +617,11 @@ def send_dap_request command, **kw res end + def send_custom_dap_request command, **kw + send_request command, **kw + return find_crt_dap_response + end + def send_cdp_request command, **kw send_request command, **kw res = find_crt_cdp_response