diff --git a/config/mcp_config.yaml.example b/config/mcp_config.yaml.example index 45acb8c4a3..435777fcb6 100644 --- a/config/mcp_config.yaml.example +++ b/config/mcp_config.yaml.example @@ -28,5 +28,6 @@ rate_limit: # Logging (optional - defaults shown) logging: enabled: false - level: INFO # DEBUG, INFO, WARN, ERROR, FATAL - log_file: msfmcp.log + level: INFO # DEBUG, INFO, WARN, ERROR + log_file: ~/.msf4/logs/msfmcp.log + sanitize: true diff --git a/config/mcp_config_jsonrpc.yaml.example b/config/mcp_config_jsonrpc.yaml.example index c663a777a5..12ca832304 100644 --- a/config/mcp_config_jsonrpc.yaml.example +++ b/config/mcp_config_jsonrpc.yaml.example @@ -27,5 +27,6 @@ rate_limit: # Logging (optional - defaults shown) logging: enabled: false - level: INFO # DEBUG, INFO, WARN, ERROR, FATAL - log_file: msfmcp.log + level: INFO # DEBUG, INFO, WARN, ERROR + log_file: ~/.msf4/logs/msfmcp.log + sanitize: true diff --git a/lib/msf/core/mcp.rb b/lib/msf/core/mcp.rb index 273a1b01ec..b7cca12f59 100644 --- a/lib/msf/core/mcp.rb +++ b/lib/msf/core/mcp.rb @@ -1,25 +1,40 @@ # frozen_string_literal: true -require 'rex/logging' -require 'rex/socket' -require 'rex/logging/log_sink' -require 'rex/logging/sinks/stream' -require 'rex/logging/sinks/flatfile' -require 'rex/logging/sinks/stderr' - -# Make Rex::Logging constants (LOG_ERROR, LOG_INFO, etc.) and the Kernel-level -# logging stubs (ilog, elog, dlog, wlog) available without a full `require 'rex'`. -include Rex::Logging - # Main entry point for MSF MCP Server module Msf module MCP VERSION = '0.1.0' - LOG_SOURCE = 'mcp' end end -# Error classes (load first) +# Load the base configuration (for default paths, etc.) +require 'msf/base/config' + +# Load the base Rex libraries +require 'rex/socket' +require 'rex/logging' +require 'rex/logging/log_sink' + +module Msf + module MCP + # Log source identifier for all MCP log messages. + LOG_SOURCE = 'mcp' + + # Log level aliases — semantic names for Rex::Logging level constants. + LOG_DEBUG = Rex::Logging::LEV_3 + LOG_INFO = Rex::Logging::LEV_2 + LOG_WARN = Rex::Logging::LEV_1 + LOG_ERROR = Rex::Logging::LEV_0 + end +end + +# Load the MCP-specific logging components +require_relative 'mcp/logging/sinks/json_stream' +require_relative 'mcp/logging/sinks/json_flatfile' +require_relative 'mcp/logging/sinks/sanitizing' +require_relative 'mcp/middleware/request_logger' + +# Error classes require_relative 'mcp/errors' # Configuration Layer @@ -37,9 +52,6 @@ require_relative 'mcp/metasploit/jsonrpc_client' require_relative 'mcp/metasploit/client' require_relative 'mcp/metasploit/response_transformer' -# Logging Layer — sanitizing sink only; the Logger wrapper has been removed -require_relative 'mcp/logging/sinks/sanitizing' - # MCP SDK require 'mcp' @@ -57,3 +69,7 @@ require_relative 'mcp/server' # Application Layer require_relative 'mcp/application' + +# Make logging stubs (ilog, elog, dlog, wlog) +include Rex::Logging + diff --git a/lib/msf/core/mcp/application.rb b/lib/msf/core/mcp/application.rb index e131536c9f..8d1ba4efe5 100644 --- a/lib/msf/core/mcp/application.rb +++ b/lib/msf/core/mcp/application.rb @@ -47,8 +47,6 @@ module Msf::MCP start_mcp_server rescue Msf::MCP::Config::ValidationError, Msf::MCP::Config::ConfigurationError => e handle_configuration_error(e) - rescue Errno::ENOENT => e - handle_file_not_found_error(e) rescue Msf::MCP::Metasploit::ConnectionError => e handle_connection_error(e) rescue Msf::MCP::Metasploit::APIError => e @@ -71,7 +69,10 @@ module Msf::MCP # @param signal [String] Signal name (e.g., 'INT', 'TERM') # @return [void] def shutdown(signal = 'INT') - ilog("Shutting down (SIG#{signal})", LOG_SOURCE, Rex::Logging::LEV_0) + ilog({ + message: 'Shutting down', + context: { signal: "SIG#{signal}" } + }, LOG_SOURCE, LOG_INFO) @mcp_server&.shutdown @rpc_manager&.stop_rpc_server @output.puts "\nShutdown complete" @@ -90,7 +91,7 @@ module Msf::MCP @options[:config_path] = File.expand_path(path) end - opts.on('--enable-logging', 'Enable file logging with sanitization') do + opts.on('--enable-logging', 'Enable file logging') do @options[:enable_logging_cli] = true end @@ -130,7 +131,7 @@ module Msf::MCP # Register a Rex log source when logging is enabled. # - # Selects a Flatfile sink pointed at the configured log path and wraps it + # Selects a JsonFlatfile sink pointed at the configured log path and wraps it # with the sanitizing middleware unless sanitization has been explicitly # disabled in the config. # @@ -140,13 +141,20 @@ module Msf::MCP def initialize_logger return unless @options[:enable_logging_cli] || @config.dig(:logging, :enabled) - log_file = @options[:log_file_cli] || @config.dig(:logging, :log_file) || 'msfmcp.log' - log_level = (@config.dig(:logging, :level) || 'INFO').upcase - sanitize = @config.dig(:logging, :sanitize) != false - - threshold = log_level == 'DEBUG' ? Rex::Logging::LEV_1 : Rex::Logging::LEV_0 - inner = Rex::Logging::Sinks::Flatfile.new(log_file) - sink = sanitize ? Msf::MCP::Logging::Sinks::Sanitizing.new(inner) : inner + log_file = @options[:log_file_cli] || @config.dig(:logging, :log_file) + level = @config.dig(:logging, :level) + threshold = case @config.dig(:logging, :level).upcase + when 'DEBUG' + Rex::Logging::LEV_3 + when 'INFO' + Rex::Logging::LEV_2 + when 'WARN' + Rex::Logging::LEV_1 + when 'ERROR' + Rex::Logging::LEV_0 + end + inner = Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file) + sink = @config.dig(:logging, :sanitize) ? Msf::MCP::Logging::Sinks::Sanitizing.new(inner) : inner deregister_log_source(LOG_SOURCE) if log_source_registered?(LOG_SOURCE) register_log_source(LOG_SOURCE, sink, threshold) @@ -280,44 +288,44 @@ module Msf::MCP # Error handlers def handle_configuration_error(error) - elog("Configuration validation failed", LOG_SOURCE, Rex::Logging::LEV_0, error: error) @output.puts "Configuration validation failed: #{error.message}" exit 1 end - def handle_file_not_found_error(error) - elog("Configuration file not found", LOG_SOURCE, Rex::Logging::LEV_0, error: error) - @output.puts "Configuration file not found: #{@options[:config_path]}" - @output.puts "Create a configuration file or specify a valid path with --config" - exit 1 - end - def handle_connection_error(error) - elog("Connection error to #{@config[:msf_api][:host]}:#{@config[:msf_api][:port]}", LOG_SOURCE, Rex::Logging::LEV_0, error: error) + elog({ + message: 'Connection error', + context: { host: @config[:msf_api][:host], port: @config[:msf_api][:port] }, + exception: error + }, LOG_SOURCE, LOG_ERROR) @output.puts "Connection error to Metasploit RPC at #{@config[:msf_api][:host]}:#{@config[:msf_api][:port]} - #{error.message}" exit 1 end def handle_api_error(error) - elog("Metasploit API error", LOG_SOURCE, Rex::Logging::LEV_0, error: error) + elog({ message: 'Metasploit API error', exception: error }, LOG_SOURCE, LOG_ERROR) @output.puts "Metasploit API error: #{error.message}" exit 1 end def handle_authentication_error(error) - elog("Authentication error (username: #{@config[:msf_api][:user]})", LOG_SOURCE, Rex::Logging::LEV_0, error: error) + elog({ + message: 'Authentication error', + context: { username: @config[:msf_api][:user].to_s }, + exception: error + }, LOG_SOURCE, LOG_ERROR) @output.puts "Authentication error (username: #{@config[:msf_api][:user]}): #{error.message}" exit 1 end def handle_rpc_startup_error(error) - elog("RPC startup error", LOG_SOURCE, Rex::Logging::LEV_0, error: error) + elog({ message: 'RPC startup error', exception: error }, LOG_SOURCE, LOG_ERROR) @output.puts "RPC startup error: #{error.message}" exit 1 end def handle_fatal_error(error) - elog("Fatal error during startup", LOG_SOURCE, Rex::Logging::LEV_0, error: error) + elog({ message: 'Fatal error during startup', exception: error }, LOG_SOURCE, LOG_ERROR) @output.puts "Fatal error: #{error.message}" @output.puts error.backtrace.first(5).join("\n") if error.backtrace exit 1 diff --git a/lib/msf/core/mcp/config/loader.rb b/lib/msf/core/mcp/config/loader.rb index 912b3448f0..75f9cf39e3 100644 --- a/lib/msf/core/mcp/config/loader.rb +++ b/lib/msf/core/mcp/config/loader.rb @@ -48,51 +48,40 @@ module Msf::MCP # # @param config [Hash] Configuration hash to modify in place def self.apply_defaults(config) - # Ensure nested hashes exist config[:msf_api] ||= {} config[:mcp] ||= {} + config[:rate_limit] ||= {} + config[:logging] ||= {} - # Default MSF API type and host config[:msf_api][:type] ||= 'messagepack' config[:msf_api][:host] ||= 'localhost' - - # Default port is 8081 for JSON-RPC or 55553 for MessagePack (and anything else) config[:msf_api][:port] ||= (config[:msf_api][:type] == 'json-rpc') ? 8081 : 55553 - # Use SSL by default - config[:msf_api][:ssl] = true if !config[:msf_api].key?(:ssl) + config[:msf_api][:ssl] = config[:msf_api].fetch(:ssl, true) + config[:msf_api][:auto_start_rpc] = config[:msf_api].fetch(:auto_start_rpc, true) - # Auto-start RPC by default - config[:msf_api][:auto_start_rpc] = true unless config[:msf_api].key?(:auto_start_rpc) - - # Default endpoint based on API type config[:msf_api][:endpoint] ||= case config[:msf_api][:type] - when 'json-rpc' - Msf::MCP::Metasploit::JsonRpcClient::DEFAULT_ENDPOINT - else - Msf::MCP::Metasploit::MessagePackClient::DEFAULT_ENDPOINT - end + when 'json-rpc' + Msf::MCP::Metasploit::JsonRpcClient::DEFAULT_ENDPOINT + else + Msf::MCP::Metasploit::MessagePackClient::DEFAULT_ENDPOINT + end - # Default transport config[:mcp][:transport] ||= 'stdio' - # Default MCP server network settings (for HTTP transport) if config[:mcp][:transport] == 'http' config[:mcp][:host] ||= 'localhost' config[:mcp][:port] ||= 3000 end - # Default rate limit - config[:rate_limit] ||= {} - config[:rate_limit][:enabled] = true unless config[:rate_limit].key?(:enabled) + config[:rate_limit][:enabled] = config[:rate_limit].fetch(:enabled, true) config[:rate_limit][:requests_per_minute] ||= 60 config[:rate_limit][:burst_size] ||= 10 - # Default logging - config[:logging] ||= {} - config[:logging][:enabled] = false unless config[:logging].key?(:enabled) + config[:logging][:enabled] = config[:logging].fetch(:enabled, false) config[:logging][:level] ||= 'INFO' - config[:logging][:log_file] ||= 'msfmcp.log' + config[:logging][:log_file] ||= File.join(Msf::Config.log_directory, 'msfmcp.log') + config[:logging][:sanitize] = config[:logging].fetch(:sanitize, true) end # Apply environment variable overrides diff --git a/lib/msf/core/mcp/config/validator.rb b/lib/msf/core/mcp/config/validator.rb index a37d76f279..176c71ce4e 100644 --- a/lib/msf/core/mcp/config/validator.rb +++ b/lib/msf/core/mcp/config/validator.rb @@ -175,7 +175,7 @@ module Msf::MCP end end - VALID_LOG_LEVELS = %w[DEBUG INFO WARN ERROR FATAL].freeze + VALID_LOG_LEVELS = %w[DEBUG INFO WARN ERROR].freeze # Validate logging section fields def validate_logging(config, errors) @@ -192,6 +192,10 @@ module Msf::MCP if logging.key?(:log_file) && logging[:log_file].to_s.strip.empty? errors[:'logging.log_file'] = "must be a non-empty string" end + + if logging.key?(:sanitize) && ![true, false].include?(logging[:sanitize]) + errors[:'logging.sanitize'] = "must be boolean (true or false)" + end end end end diff --git a/lib/msf/core/mcp/logging/sinks/json_flatfile.rb b/lib/msf/core/mcp/logging/sinks/json_flatfile.rb new file mode 100644 index 0000000000..9581d6f69e --- /dev/null +++ b/lib/msf/core/mcp/logging/sinks/json_flatfile.rb @@ -0,0 +1,24 @@ +# -*- coding: binary -*- +module Msf::MCP + module Logging + module Sinks + ### + # + # This class implements the LogSink interface and backs it against a + # JSON file on disk. + # + ### + class JsonFlatfile < Msf::MCP::Logging::Sinks::JsonStream + + # + # Creates a JSON flatfile log sink instance that will be configured to log to + # the supplied file path. + # + def initialize(file) + super(File.new(file, 'a')) + end + + end + end + end +end diff --git a/lib/msf/core/mcp/logging/sinks/json_stream.rb b/lib/msf/core/mcp/logging/sinks/json_stream.rb new file mode 100644 index 0000000000..b884cd287a --- /dev/null +++ b/lib/msf/core/mcp/logging/sinks/json_stream.rb @@ -0,0 +1,123 @@ +# frozen_string_literal: true + +module Msf::MCP + module Logging + module Sinks + # A Rex LogSink that formats log messages as JSON and writes them to + # an IO stream (e.g. $stdout, a File, a StringIO). + # + # @example Writing JSON logs to $stderr + # sink = Msf::MCP::Logging::Sinks::JsonStream.new($stderr) + # register_log_source('mcp', sink, Rex::Logging::LEV_0) + # + # @example Backed by a file via JsonFlatfile + # sink = Msf::MCP::Logging::Sinks::JsonFlatfile.new('msfmcp.log') + # register_log_source('mcp', sink, Rex::Logging::LEV_0) + class JsonStream + include Rex::Logging::LogSink + + def initialize(stream) + @stream = stream + end + + def log(sev, src, level, msg) + log_entry = { + timestamp: get_current_timestamp, + severity: sev.to_s.upcase, + level: level.to_s, + source: src.to_s, + message: msg.to_s + } + + if msg.is_a?(Hash) + log_entry[:message] = msg[:message] if msg[:message] && !msg[:message].empty? + if msg[:context] && !msg[:context].empty? + log_entry[:context] = if debug_log_level? + msg[:context] + else + summarize_context(msg[:context]) + end + end + if msg[:exception] + log_entry[:exception] = if msg[:exception].is_a?(Exception) + ex_msg = { class: msg[:exception].class.name, message: msg[:exception].message } + if get_log_level(LOG_SOURCE) >= BACKTRACE_LOG_LEVEL + ex_msg[:backtrace] = msg[:exception].backtrace&.first(5) || [] + end + ex_msg + else + msg[:exception] + end + end + end + + stream.write(log_entry.to_json + "\n") + stream.flush + end + + def cleanup + stream.close + end + + protected + + attr_accessor :stream + + private + + # Keys whose values can be large (full API responses, tool results, etc.) + # and should be truncated at non-DEBUG log levels. + HEAVY_KEYS = %i[result body error].freeze + + # Maximum character length for truncated values. + TRUNCATE_MAX_LENGTH = 1000 + + # Whether the current log level for the MCP source is at least DEBUG + # (LEV_3 / BACKTRACE_LOG_LEVEL), which enables full context output + # and exception backtraces. + # + # @return [Boolean] + def debug_log_level? + get_log_level(LOG_SOURCE) >= BACKTRACE_LOG_LEVEL + end + + # Return a reduced copy of +ctx+ suitable for non-DEBUG log entries. + # + # Heavy keys (:result, :body, :error) are truncated. The :response sub-hash is also + # truncated. All other keys (scalars like :method, :elapsed_ms, :session_id) pass + # through unchanged. + # + # @param ctx [Hash] The original context hash + # @return [Hash] A summarized copy + def summarize_context(ctx) + return ctx unless ctx.is_a?(Hash) + + ctx.each_with_object({}) do |(k, v), acc| + if HEAVY_KEYS.include?(k) + acc[k] = truncate_value(v) + elsif k == :response && v.is_a?(Hash) + acc[k] = v.each_with_object({}) do |(k_sub, v_sub), acc_sub| + acc_sub[k_sub] = HEAVY_KEYS.include?(k_sub) ? truncate_value(v_sub) : v_sub + end + else + acc[k] = v + end + end + end + + # Truncate a value to a human-readable summary string. + # + # @param val [Object] The value to truncate + # @param max_length [Integer] Maximum character length before truncation + # @return [Object] The original value if short enough, otherwise a truncated string + def truncate_value(val, max_length: TRUNCATE_MAX_LENGTH) + str = val.is_a?(String) ? val : val.to_json + return val if str.length <= max_length + + "#{str[0...max_length]}... (truncated, #{str.length} bytes)" + end + + end + end + end +end diff --git a/lib/msf/core/mcp/logging/sinks/sanitizing.rb b/lib/msf/core/mcp/logging/sinks/sanitizing.rb index 8a42dc37c8..666ce5f802 100644 --- a/lib/msf/core/mcp/logging/sinks/sanitizing.rb +++ b/lib/msf/core/mcp/logging/sinks/sanitizing.rb @@ -5,13 +5,13 @@ require 'rex/logging/log_sink' module Msf::MCP module Logging module Sinks - # A Rex LogSink decorator that redacts credentials, tokens, and API keys - # from log messages before delegating to a wrapped sink. + # A Rex LogSink decorator that redacts sensitive information from log + # messages before delegating to a wrapped sink. # - # @example Wrapping a flatfile sink - # inner = Rex::Logging::Sinks::Flatfile.new('msfmcp.log') + # @example Wrapping a JsonFlatfile sink + # inner = Msf::MCP::Logging::Sinks::JsonFlatfile.new('msfmcp.log') # sink = Msf::MCP::Logging::Sinks::Sanitizing.new(inner) - # register_log_source('msfmcp', sink, 0) + # register_log_source('mcp', sink, Rex::Logging::LEV_0) class Sanitizing include Rex::Logging::LogSink @@ -28,6 +28,8 @@ module Msf::MCP bearer: /bearer\s+[a-zA-Z0-9_\-\.]+/i }.freeze + SENSITIVE_KEYS = /\A(password|token|secret|api_key|api_secret|credential|auth_token|bearer|access_token|private_key)\z/i + # @param sink [Rex::Logging::LogSink] The underlying sink to write to def initialize(sink) @sink = sink @@ -43,15 +45,55 @@ module Msf::MCP private - def sanitize(msg) - return msg unless msg.is_a?(String) + # Sanitize data for logging by redacting sensitive information. + # + # @param data [Object] Data to sanitize (Hash, Array, String, or other) + # @return [Object] Sanitized copy of data + def sanitize(data) + case data + when Hash + data.each_with_object({}) do |(k, v), result| + result[k] = if k.to_s.match?(SENSITIVE_KEYS) + v.is_a?(Hash) || v.is_a?(Array) ? sanitize(v) : REDACTED + elsif k.to_sym == :exception && v.is_a?(Exception) + ex_msg = { class: v.class.name, message: sanitize(v.message) } + if get_log_level(LOG_SOURCE) >= BACKTRACE_LOG_LEVEL + bt = v.backtrace&.first(5) || [] + bt = bt.map{|x| x.sub(/^.*lib\//, 'lib/') } # Dont expose the install path + ex_msg[:backtrace] = sanitize(bt) + end + ex_msg + else + sanitize(v) + end + end + when Array + data.map { |item| sanitize(item) } + when String + sanitize_string(data) + else + data + end + end - sanitized = msg.dup + # Sanitize a string by redacting sensitive patterns + # + # @param str [String] String to sanitize + # @return [String] Sanitized string + def sanitize_string(str) + return str unless str.is_a?(String) + + sanitized = str.dup + + # Redact sensitive patterns - match entire pattern and replace value part SENSITIVE_PATTERNS.each do |name, pattern| sanitized = sanitized.gsub(pattern) do |match| + # For header-style tokens (token abc123, bearer abc123), replace the value + # # TODO: check this if name == :token_header || name == :bearer parts = match.split(/\s+/, 2) "#{parts[0]} #{REDACTED}" + # For key-value style (token: abc123, password=abc123), replace after separator elsif match =~ /(.*[:=])\s*[\"']?/ "#{Regexp.last_match[1]} #{REDACTED}" else @@ -59,8 +101,10 @@ module Msf::MCP end end end + sanitized end + end end end diff --git a/lib/msf/core/mcp/metasploit/jsonrpc_client.rb b/lib/msf/core/mcp/metasploit/jsonrpc_client.rb index f7328ce357..ac626859d9 100644 --- a/lib/msf/core/mcp/metasploit/jsonrpc_client.rb +++ b/lib/msf/core/mcp/metasploit/jsonrpc_client.rb @@ -52,13 +52,13 @@ module Msf::MCP @request_id += 1 - # Build JSON-RPC 2.0 request + # Build JSON-RPC 2.0 request as a hash request_body = { jsonrpc: '2.0', method: method, params: args, id: @request_id - }.to_json + } # Send HTTP request response = send_request(request_body) @@ -138,7 +138,7 @@ module Msf::MCP private # Send HTTP POST request with JSON-RPC payload - # @param request_body [String] JSON-RPC request + # @param request_body [Hash] JSON-RPC request body as a hash # @return [Hash] Parsed response # @raise [ConnectionError] If connection fails # @raise [AuthenticationError] If token is invalid @@ -154,9 +154,12 @@ module Msf::MCP request = Net::HTTP::Post.new(@endpoint) request['Content-Type'] = 'application/json' request['Authorization'] = "Bearer #{@token}" - request.body = request_body + request.body = request_body.to_json - dlog("JSON-RPC request method=#{request.method} endpoint=#{@endpoint}", LOG_SOURCE, Rex::Logging::LEV_1) + dlog({ + message: 'JSON-RPC request', + context: { method: request.method, endpoint: @endpoint, body: request_body } + }, LOG_SOURCE, LOG_DEBUG) # Send request and parse response begin @@ -175,7 +178,10 @@ module Msf::MCP raise ConnectionError, "HTTP #{response.code}: #{response.message}" end - dlog("JSON-RPC response status=#{response.code}", LOG_SOURCE, Rex::Logging::LEV_1) + dlog({ + message: 'JSON-RPC response', + context: { status: response.code, body: parsed } + }, LOG_SOURCE, LOG_DEBUG) parsed rescue Errno::ECONNREFUSED, Errno::EHOSTUNREACH => e diff --git a/lib/msf/core/mcp/metasploit/messagepack_client.rb b/lib/msf/core/mcp/metasploit/messagepack_client.rb index c416552ce1..ef96c99b1f 100644 --- a/lib/msf/core/mcp/metasploit/messagepack_client.rb +++ b/lib/msf/core/mcp/metasploit/messagepack_client.rb @@ -24,7 +24,7 @@ module Msf::MCP @user = nil @password = nil @retry_count = 0 - @max_retries = 1 + @max_retries = 2 @ssl = ssl end @@ -63,29 +63,49 @@ module Msf::MCP def call_api(method, args = []) raise ArgumentError, "args must be an Array, got #{args.class}" unless args.is_a?(Array) - raise AuthenticationError, 'Not authenticated' unless @token + begin + raise AuthenticationError, 'Not authenticated' unless @token - # Build request array: [method, token, *args] - request_array = [method, @token, *args] + # Build request array: [method, token, *args] + request_array = [method, @token, *args] - # Send HTTP request - response = send_request(request_array) - @retry_count = 0 # Reset retry count on success - response + # Send HTTP request + send_request(request_array) + + rescue AuthenticationError => e + # It is not possible to reauthenticate if we don't have credentials stored + raise unless @user && @password + # If reauthentication succeeded but the token is still invalid, we should not retry indefinitely + raise unless @retry_count < @max_retries - rescue AuthenticationError => e - # TODO: Log authentication error if needed - if @user && @password && @retry_count < @max_retries @retry_count += 1 @token = nil - # Re-authenticate - authenticate(@user, @password) + begin + wlog({ message: "#{method}': #{e.message}. Attempting to re-authenticate (#{@retry_count}/#{@max_retries})" }, + LOG_SOURCE, LOG_WARN) + authenticate(@user, @password) + rescue AuthenticationError => auth_e + wlog({ message: "Re-authentication failed: #{auth_e.message}" }, + LOG_SOURCE, LOG_WARN) + if @retry_count < @max_retries + @retry_count += 1 + @token = nil + retry + end + raise AuthenticationError, "Unable to authenticate after #{@retry_count} attempts: #{auth_e.message}" + end # Retry the original request with new token retry end - raise AuthenticationError, "Unable to authenticate after #{@retry_count} attempts: #{e.message}" + + rescue Msf::MCP::Error => e + elog({ message: 'MessagePack API call error', context: { error: e.message } }, + LOG_SOURCE, LOG_ERROR) + raise + ensure + @retry_count = 0 end # Search for Metasploit modules @@ -178,7 +198,10 @@ module Msf::MCP request['Content-Type'] = 'binary/message-pack' request.body = request_body - dlog("MessagePack request method=#{request.method} endpoint=#{@endpoint} body=#{sanitize_request_array(request_array).inspect}", LOG_SOURCE, Rex::Logging::LEV_1) + dlog({ + message: 'MessagePack request', + context: { method: request.method, endpoint: @endpoint, body: sanitize_request_array(request_array) } + }, LOG_SOURCE, LOG_DEBUG) # Send request and parse response begin @@ -199,7 +222,10 @@ module Msf::MCP raise ConnectionError, "HTTP #{response.code}: #{response.message}" end - dlog("MessagePack response status=#{response.code}", LOG_SOURCE, Rex::Logging::LEV_1) + dlog({ + message: 'MessagePack response', + context: { status: response.code, body: parsed } + }, LOG_SOURCE, LOG_DEBUG) parsed rescue Errno::ECONNREFUSED, Errno::EHOSTUNREACH => e diff --git a/lib/msf/core/mcp/metasploit/response_transformer.rb b/lib/msf/core/mcp/metasploit/response_transformer.rb index a6ceeefd56..4a6999aadb 100644 --- a/lib/msf/core/mcp/metasploit/response_transformer.rb +++ b/lib/msf/core/mcp/metasploit/response_transformer.rb @@ -38,8 +38,7 @@ module Msf::MCP disclosure_date: info['disclosuredate'], description: info['description'], license: info['license'], - # TODO: sanitize the filepath to remove local paths - filepath: info['filepath'], + filepath: info['filepath']&.sub(/^.*modules\//, 'modules/'), # Dont expose the install path architectures: info['arch'], platforms: info['platform'], authors: info['authors'], diff --git a/lib/msf/core/mcp/middleware/request_logger.rb b/lib/msf/core/mcp/middleware/request_logger.rb new file mode 100644 index 0000000000..d2154d3bcb --- /dev/null +++ b/lib/msf/core/mcp/middleware/request_logger.rb @@ -0,0 +1,187 @@ +# frozen_string_literal: true + +module Msf::MCP + module Middleware + ## + # Rack middleware that logs MCP HTTP request/response details via Rex logging. + # + # Focuses on the HTTP transport layer: request method, status code, session ID, + # content type, and round-trip timing. For POST requests it also extracts + # JSON-RPC fields (method, id, params) and response result/error to provide + # DEBUG-level visibility into the exchange. + # + # MCP-level business details (tool names, tool durations, and structured + # results) are handled by the SDK's +around_request+ callback configured + # in Server, avoiding duplication. + # + # @example Usage in a Rack::Builder + # Rack::Builder.new do + # use Msf::MCP::Middleware::RequestLogger + # run transport + # end + # + class RequestLogger + + ## + # @param app [#call] The next Rack application in the middleware stack + # + def initialize(app) + @app = app + end + + ## + # Process the request, delegating to the next Rack app and logging + # transport-level details after the response is produced. + # + # @param env [Hash] The Rack environment + # @return [Array] The Rack response triplet [status, headers, body] + # + def call(env) + request = Rack::Request.new(env) + started_at = Process.clock_gettime(Process::CLOCK_MONOTONIC) + + response = @app.call(env) + + elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started_at + log_exchange(request, response, elapsed) + + response + end + + private + + ## + # Log a single request/response entry at the HTTP transport level. + # + # Dispatches to {#log_post_exchange} for POST requests (which extracts + # JSON-RPC fields). GET, DELETE, and other methods are logged directly + # with status and timing information. + # + # @param request [Rack::Request] The incoming HTTP request + # @param response [Array] The Rack response [status, headers, body] + # @param elapsed [Float] Wall-clock seconds for the round-trip + # + def log_exchange(request, response, elapsed) + status, headers, _body = response + session_id = request.env['HTTP_MCP_SESSION_ID'] || headers&.fetch('Mcp-Session-Id', nil) + elapsed_ms = (elapsed * 1000).round(2) + + context = { elapsed_ms: elapsed_ms } + context[:session_id] = session_id if session_id + + case request.request_method + when 'POST' + log_post_exchange(request, response, context) + when 'GET' + context[:response] = build_response_context(response) + ilog({ message: "SSE stream opened (#{elapsed_ms}ms)", context: context }, LOG_SOURCE, LOG_INFO) + when 'DELETE' + context[:response] = build_response_context(response) + ilog({ message: "Session deleted (#{elapsed_ms}ms)", context: context }, LOG_SOURCE, LOG_INFO) + else + context[:response] = build_response_context(response) + dlog({ message: "HTTP #{request.request_method} #{status} (#{elapsed_ms}ms)", context: context }, LOG_SOURCE, LOG_DEBUG) + end + end + + ## + # Log a POST exchange with JSON-RPC params and response result/error + # nested under :request and :response keys. + # + # For streaming responses (Proc body), the result is not available here — + # it is logged by the +around_request+ callback in Server instead. + # + # Distinguishes between: + # - Notifications (no id): logged at DEBUG since the SDK instrumentation + # does not fire for these + # - Requests with HTTP errors: logged at ERROR with the error details + # - Normal requests: logged at DEBUG with params and result + # (the +around_request+ callback provides the INFO-level business log) + # + # @param request [Rack::Request] The incoming HTTP request + # @param response [Array] The Rack response [status, headers, body] + # @param context [Hash] Pre-built context hash with session_id and elapsed_ms + # + def log_post_exchange(request, response, context) + context[:request] = {} + jsonrpc = extract_jsonrpc_fields(request) + if jsonrpc + context[:request][:method] = jsonrpc[:method] if jsonrpc[:method] + context[:request][:id] = jsonrpc[:id] if jsonrpc[:id] + context[:request][:params] = jsonrpc[:params] if jsonrpc[:params] + end + + context[:response] = build_response_context(response) + response_body = extract_response_body(response) + if response_body + context[:response][:result] = response_body[:result] if response_body[:result] + context[:response][:error] = response_body[:error] if response_body[:error] + end + + method_name = context[:request][:method] || 'unknown' + if context[:request][:id].nil? && context[:request][:method] + # Notification — no instrumentation fires for these + dlog({ message: "Notification: #{method_name} #{context[:response][:status]} (#{context[:elapsed_ms]}ms)", context: context }, LOG_SOURCE, LOG_DEBUG) + elsif context[:response][:status] >= 400 + elog({ message: "HTTP #{context[:response][:status]}: #{method_name} (#{context[:elapsed_ms]}ms)", context: context }, LOG_SOURCE, LOG_ERROR) + else + dlog({ message: "HTTP #{context[:response][:status]}: #{method_name} id=#{context[:request][:id]} (#{context[:elapsed_ms]}ms)", context: context }, LOG_SOURCE, LOG_DEBUG) + end + end + + ## + # Build the response portion of the log context from the Rack response. + # + # @param response [Array] The Rack response [status, headers, body] + # @return [Hash] Response context with :status and :content_type + # + def build_response_context(response) + status, headers, _body = response + res = { status: status } + res[:content_type] = headers['Content-Type'] if headers&.key?('Content-Type') + res + end + + ## + # Extract JSON-RPC method, id, and params from the request body. + # + # Rewinds before and after reading so downstream handlers can still + # consume the body. + # + # @param request [Rack::Request] The incoming HTTP request + # @return [Hash, nil] Parsed fields (:method, :id, :params), or nil on + # parse failure + # + def extract_jsonrpc_fields(request) + request.body.rewind + body = request.body.read + request.body.rewind + parsed = JSON.parse(body) + { method: parsed['method'], id: parsed['id'], params: parsed['params'] } + rescue JSON::ParserError + nil + end + + ## + # Extract result or error from the response body. + # + # Only parses Array bodies (direct JSON responses). SSE stream responses + # (Proc bodies) are not parseable here — their results are logged by the + # +around_request+ callback in Server. + # + # @param response [Array] The Rack response [status, headers, body] + # @return [Hash, nil] Parsed fields (:result, :error), or nil if the body + # is empty, non-Array, or unparseable + # + def extract_response_body(response) + _status, _headers, body = response + return nil unless body.is_a?(Array) && !body.empty? + + parsed = JSON.parse(body.first) + { result: parsed['result'], error: parsed['error'] } + rescue JSON::ParserError + nil + end + end + end +end diff --git a/lib/msf/core/mcp/rpc_manager.rb b/lib/msf/core/mcp/rpc_manager.rb index f856508697..ee37460412 100644 --- a/lib/msf/core/mcp/rpc_manager.rb +++ b/lib/msf/core/mcp/rpc_manager.rb @@ -39,12 +39,15 @@ module Msf::MCP host = @config[:msf_api][:host] port = @config[:msf_api][:port] - socket = TCPSocket.new(host, port) + socket = Rex::Socket::Tcp.create( + 'PeerHost' => host, + 'PeerPort' => port + ) socket.close - dlog("RPC server is available at #{Rex::Socket.to_authority(host, port)}", LOG_SOURCE, Rex::Logging::LEV_0) + dlog({ message: "RPC server is available at #{Rex::Socket.to_authority(host, port)}" }, + LOG_SOURCE, LOG_DEBUG) true - rescue Errno::ECONNREFUSED, Errno::EHOSTUNREACH, Errno::ENETUNREACH, - Errno::ETIMEDOUT, SocketError + rescue Rex::ConnectionError false end @@ -78,7 +81,8 @@ module Msf::MCP end @output.puts 'Starting Metasploit RPC server...' - ilog('Starting Metasploit RPC server', LOG_SOURCE, Rex::Logging::LEV_0) + ilog({ message: 'Starting Metasploit RPC server' }, + LOG_SOURCE, LOG_INFO) unless File.executable?(MSFRPCD_PATH) raise Msf::MCP::Metasploit::RpcStartupError, @@ -133,7 +137,8 @@ module Msf::MCP return unless @rpc_managed @output.puts 'Stopping managed RPC server...' - ilog("Stopping managed RPC server (PID: #{@rpc_pid})", LOG_SOURCE, Rex::Logging::LEV_0) + ilog({ message: "Stopping managed RPC server (PID: #{@rpc_pid})" }, + LOG_SOURCE, LOG_INFO) begin Process.kill('TERM', @rpc_pid) @@ -150,33 +155,39 @@ module Msf::MCP # Ensure an RPC server is available, auto-starting if needed. # - # When no credentials are provided and auto-start is enabled, random - # credentials are generated and written back into the config hash so the - # application can use them to authenticate. + # When the RPC server is already listening, verifies that credentials + # (or a token for JSON-RPC) are available for the caller to authenticate. + # + # When the server is not available, auto-start is attempted only for + # MessagePack on localhost with auto_start_rpc enabled. Random + # credentials are generated when none are provided. # # @return [void] - # @raise [Msf::MCP::Metasploit::RpcStartupError] If the RPC server is already - # running but no credentials were provided + # @raise [Msf::MCP::Metasploit::RpcStartupError] If the server cannot be + # reached and auto-start is not possible, or if the server is running + # but no credentials/token were provided def ensure_rpc_available if rpc_available? - unless credentials_provided? - raise Msf::MCP::Metasploit::RpcStartupError, - 'RPC server is already running but no credentials were provided. ' \ - 'Use --user and --password options to authenticate with the existing server.' - end - @output.puts 'Metasploit RPC server is already running' + validate_credentials_for_existing_server! return end + if @config[:msf_api][:type] == 'json-rpc' + raise Msf::MCP::Metasploit::RpcStartupError, + 'RPC server is not running and auto-start is not supported for JSON-RPC API type.' + end + + unless localhost? + message = "RPC server is not available at #{@config[:msf_api][:host]}:#{@config[:msf_api][:port]}." + message << ' Cannot auto-start RPC on remote hosts. Please start the RPC server manually.' if auto_start_enabled? + raise Msf::MCP::Metasploit::RpcStartupError, message + end + unless auto_start_enabled? - if localhost? - @output.puts 'RPC server is not running and auto-start is disabled' - else - @output.puts "Cannot auto-start RPC on remote host #{@config[:msf_api][:host]}. " \ - 'Please start the RPC server manually.' - end - return + raise Msf::MCP::Metasploit::RpcStartupError, + "RPC server is not running on #{@config[:msf_api][:host]}:#{@config[:msf_api][:port]} " \ + 'and auto-start is disabled.' end generate_random_credentials unless credentials_provided? @@ -219,6 +230,36 @@ module Msf::MCP !user.to_s.strip.empty? && !password.to_s.strip.empty? end + # Whether the BEARER token is present in the configuration. + # + # @return [Boolean] + def token_provided? + token = @config[:msf_api][:token] + !token.to_s.strip.empty? + end + + # Verify that the caller has credentials to authenticate with an + # already-running RPC server. For MessagePack this means user+password; + # for JSON-RPC this means a bearer token. + # + # @raise [Msf::MCP::Metasploit::RpcStartupError] If required credentials + # are missing + def validate_credentials_for_existing_server! + if @config[:msf_api][:type] == 'json-rpc' + return if token_provided? + + raise Msf::MCP::Metasploit::RpcStartupError, + 'RPC server is already running but no token was provided. ' \ + 'Use --token option or MSF_API_TOKEN environment variable.' + else + return if credentials_provided? + + raise Msf::MCP::Metasploit::RpcStartupError, + 'RPC server is already running but no credentials were provided. ' \ + 'Use --user and --password options or MSF_API_USER and MSF_API_PASSWORD environment variables.' + end + end + # Generate random credentials and write them into the config hash. # # @return [void] @@ -226,7 +267,8 @@ module Msf::MCP @config[:msf_api][:user] = SecureRandom.hex(8) @config[:msf_api][:password] = SecureRandom.hex(16) @output.puts 'Generated random credentials for auto-started RPC server' - ilog('Generated random credentials for auto-started RPC server', LOG_SOURCE, Rex::Logging::LEV_0) + ilog({ message: 'Generated random credentials for auto-started RPC server' }, + LOG_SOURCE, LOG_INFO) end # Check if the managed child process is still alive. diff --git a/lib/msf/core/mcp/server.rb b/lib/msf/core/mcp/server.rb index 5e433b835d..6d80a413fc 100644 --- a/lib/msf/core/mcp/server.rb +++ b/lib/msf/core/mcp/server.rb @@ -30,9 +30,9 @@ module Msf::MCP rate_limiter: rate_limiter } - # Create MCP configuration with instrumentation callbacks + # Create MCP configuration with request lifecycle callbacks mcp_config = ::MCP::Configuration.new - mcp_config.instrumentation_callback = create_instrumentation_callback + mcp_config.around_request = create_around_request mcp_config.exception_reporter = create_exception_reporter # Initialize MCP server with all tools @@ -92,7 +92,6 @@ module Msf::MCP # def start_stdio transport = ::MCP::Server::Transports::StdioTransport.new(@mcp_server) - @mcp_server.transport = transport transport.open @mcp_server end @@ -100,6 +99,10 @@ module Msf::MCP ## # Start HTTP transport (for web/network usage) # + # The transport implements the Rack app interface (#call), so it is mounted + # directly. MCP-aware request/response logging is handled by the + # Middleware::RequestLogger middleware. + # # @param host [String] Host address to bind to # @param port [Integer] Port to listen on # @@ -110,21 +113,12 @@ module Msf::MCP require 'rack/handler/puma' transport = ::MCP::Server::Transports::StreamableHTTPTransport.new(@mcp_server) - @mcp_server.transport = transport - # Create the Rack application following official MCP example - app = proc do |env| - request = Rack::Request.new(env) - log_http_request(request) - response = transport.handle_request(request) - log_http_response(request, response) - response - end - - # Build the Rack application with middleware + # Build the Rack application with logging middleware. + # The transport itself is a Rack app (implements #call). rack_app = Rack::Builder.new do - use Rack::ShowExceptions - run app + use Msf::MCP::Middleware::RequestLogger + run transport end # Start Puma server using the handler appropriate for the Rack version. @@ -146,80 +140,28 @@ module Msf::MCP end ## - # Log HTTP request details via Rex logging + # Create around_request callback for MCP SDK # - # @param request [Rack::Request] The HTTP request + # This callback wraps every JSON-RPC request handler, providing access to + # both the instrumentation data and the response result. It replaces the + # deprecated +instrumentation_callback+ which only fires after completion + # and does not expose the result. # - def log_http_request(request) - if request.post? - body = request.body.read - request.body.rewind - begin - parsed_body = JSON.parse(body) - ilog( - "HTTP Request: #{parsed_body['method']} (id: #{parsed_body['id']}) params=#{parsed_body['params'].inspect}", - LOG_SOURCE, Rex::Logging::LEV_0 - ) - rescue JSON::ParserError - wlog('Invalid JSON in HTTP request', LOG_SOURCE, Rex::Logging::LEV_0) - end - elsif request.get? - session_id = request.env['HTTP_MCP_SESSION_ID'] || - Rack::Utils.parse_query(request.env['QUERY_STRING'])['sessionId'] - ilog("SSE connection request session_id=#{session_id.inspect}", LOG_SOURCE, Rex::Logging::LEV_0) - end - end + # The +data+ hash is populated by the SDK with: + # - :method — the JSON-RPC method name (e.g. "tools/call", "tools/list") + # - :tool_name, :prompt_name, :resource_uri — specific handler identifiers + # - :tool_arguments — arguments passed to a tool call + # - :client — client info hash (name, version) + # - :error — error type symbol (e.g. :tool_not_found, :internal_error) + # - :duration — added in the ensure block after this callback returns + # + # @return [Proc] Callback that wraps request execution and logs via Rex + # + def create_around_request + ->(data, &request_handler) do + result = request_handler.call - ## - # Log HTTP response details via Rex logging - # - # @param request [Rack::Request] The HTTP request - # @param response [Array] The Rack response [status, headers, body] - # - def log_http_response(request, response) - status, headers, body = response - - if body.is_a?(Array) && !body.empty? && request.post? - begin - parsed_response = JSON.parse(body.first) - if parsed_response['error'] - elog( - "HTTP Response error: #{parsed_response['error']['message']} (code: #{parsed_response['error']['code']})", - LOG_SOURCE, Rex::Logging::LEV_0 - ) - elsif parsed_response['accepted'] - ilog('Response sent via SSE stream', LOG_SOURCE, Rex::Logging::LEV_0) - else - ilog( - "HTTP Response: success (id: #{parsed_response['id']}) session=#{headers['Mcp-Session-Id'].inspect}", - LOG_SOURCE, Rex::Logging::LEV_0 - ) - end - rescue JSON::ParserError - wlog('Invalid JSON in HTTP response', LOG_SOURCE, Rex::Logging::LEV_0) - end - elsif request.get? && status == 200 - ilog('SSE stream established', LOG_SOURCE, Rex::Logging::LEV_0) - end - end - - ## - # Create instrumentation callback for MCP SDK - # - # This callback receives information about: - # - Tool calls (with tool_name, duration) - # - Prompt calls (with prompt_name, duration) - # - Resource calls (with resource_uri, duration) - # - Errors (with error type, e.g., tool_not_found) - # - Any additional data from the MCP SDK - # - # @return [Proc] Callback that logs instrumentation data via Rex - # - def create_instrumentation_callback - ->(data) do - return unless data - - # Build message based on instrumentation type + # Build message based on the type of request message = if data[:error] "MCP Error: #{data[:error]}" elsif data[:tool_name] @@ -231,26 +173,30 @@ module Msf::MCP elsif data[:method] "Method call: #{data[:method]}" else - "MCP instrumentation" + "MCP request" end - # Add duration to message if available - message = message.dup - message << " (#{(data[:duration] * 1000).round(2)}ms)" if data[:duration] - message << " #{data.inspect}" unless data.empty? - - if data[:error] - elog(message, LOG_SOURCE, Rex::Logging::LEV_0) - else - ilog(message, LOG_SOURCE, Rex::Logging::LEV_0) + context = data.dup + if result + message = "#{message} (ERROR)" if result[:isError] + context[:result] = result end + + if data[:error] || result&.fetch(:isError, nil) + elog({ message: message, context: context }, LOG_SOURCE, LOG_ERROR) + else + ilog({ message: message, context: context }, LOG_SOURCE, LOG_INFO) + end + + result end end ## # Create exception reporter callback for MCP SDK # - # This callback is invoked for any exception during request processing. + # This callback is invoked for any server exception during request processing, + # which are not tool execution errors. # It receives: # - exception: The Ruby exception object # - context: Hash with :request (JSON string) or :notification (method name string) @@ -266,11 +212,15 @@ module Msf::MCP if context&.fetch(:request, nil) error_context[:type] = 'request' - if context[:request].is_a?(Hash) - error_context[:method] = context.dig(:request, :name) || 'unknown' - error_context[:arguments] = context.dig(:request, :arguments) || [] - else + request = nil + begin + request = JSON.parse(context[:request]) + rescue JSON::ParserError + # Not valid JSON, log raw data error_context[:raw_data] = context[:request].inspect + else + error_context[:method] = request['method'] if request['method'] + error_context[:params] = request['params'] if request['params'] end elsif context&.fetch(:notification, nil) error_context[:type] = 'notification' @@ -281,11 +231,11 @@ module Msf::MCP error_context[:raw_data] = context.inspect end - msg = "Error during #{error_context[:type]} processing" - msg << " (#{error_context[:method]})" if error_context[:method] && !error_context[:method].empty? - msg << " #{error_context.inspect}" - - elog(msg, LOG_SOURCE, Rex::Logging::LEV_0, error: exception) + elog({ + message: "Error during #{error_context[:type]} processing#{error_context[:method] ? " (#{error_context[:method]})" : ''}", + exception: exception, + context: error_context + }, LOG_SOURCE, LOG_ERROR) end end end diff --git a/lib/msf/core/mcp/tools/credential_info.rb b/lib/msf/core/mcp/tools/credential_info.rb index f08ec3156f..9d003bab7e 100644 --- a/lib/msf/core/mcp/tools/credential_info.rb +++ b/lib/msf/core/mcp/tools/credential_info.rb @@ -146,9 +146,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/host_info.rb b/lib/msf/core/mcp/tools/host_info.rb index a76b4184d5..cead5a9af0 100644 --- a/lib/msf/core/mcp/tools/host_info.rb +++ b/lib/msf/core/mcp/tools/host_info.rb @@ -164,9 +164,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/loot_info.rb b/lib/msf/core/mcp/tools/loot_info.rb index 3a63e00053..62a56e2905 100644 --- a/lib/msf/core/mcp/tools/loot_info.rb +++ b/lib/msf/core/mcp/tools/loot_info.rb @@ -148,9 +148,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/module_info.rb b/lib/msf/core/mcp/tools/module_info.rb index 1fb0460ecf..de2bcacf7b 100644 --- a/lib/msf/core/mcp/tools/module_info.rb +++ b/lib/msf/core/mcp/tools/module_info.rb @@ -134,9 +134,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/note_info.rb b/lib/msf/core/mcp/tools/note_info.rb index 19b7ddffd4..776288e6de 100644 --- a/lib/msf/core/mcp/tools/note_info.rb +++ b/lib/msf/core/mcp/tools/note_info.rb @@ -172,9 +172,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/search_modules.rb b/lib/msf/core/mcp/tools/search_modules.rb index 369be09d6e..2af666efbb 100644 --- a/lib/msf/core/mcp/tools/search_modules.rb +++ b/lib/msf/core/mcp/tools/search_modules.rb @@ -145,9 +145,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/service_info.rb b/lib/msf/core/mcp/tools/service_info.rb index 4d599e37f4..053e017de4 100644 --- a/lib/msf/core/mcp/tools/service_info.rb +++ b/lib/msf/core/mcp/tools/service_info.rb @@ -184,9 +184,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/lib/msf/core/mcp/tools/vulnerability_info.rb b/lib/msf/core/mcp/tools/vulnerability_info.rb index cbb9943367..8a54813936 100644 --- a/lib/msf/core/mcp/tools/vulnerability_info.rb +++ b/lib/msf/core/mcp/tools/vulnerability_info.rb @@ -176,9 +176,9 @@ module Msf::MCP ) rescue Msf::MCP::Security::RateLimitExceededError => e tool_error_response("Rate limit exceeded: #{e.message}") - rescue Metasploit::AuthenticationError => e + rescue Msf::MCP::Metasploit::AuthenticationError => e tool_error_response("Authentication failed: #{e.message}") - rescue Metasploit::APIError => e + rescue Msf::MCP::Metasploit::APIError => e tool_error_response("Metasploit API error: #{e.message}") rescue Msf::MCP::Security::ValidationError => e tool_error_response(e.message) diff --git a/spec/integration/msfmcpd/logging_pipeline_spec.rb b/spec/integration/msfmcpd/logging_pipeline_spec.rb new file mode 100644 index 0000000000..0d7bf1fe3f --- /dev/null +++ b/spec/integration/msfmcpd/logging_pipeline_spec.rb @@ -0,0 +1,143 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'stringio' +require 'tempfile' +require 'json' + +RSpec.describe 'Logging Pipeline Integration' do + let(:output) { StringIO.new } + let(:log_file) { Tempfile.new(['logging_integration', '.log']).tap(&:close).path } + let(:log_src) { Msf::MCP::LOG_SOURCE } + let(:lvl_info) { Msf::MCP::LOG_INFO } + let(:lvl_warn) { Msf::MCP::LOG_WARN } + let(:lvl_error) { Msf::MCP::LOG_ERROR } + + after do + deregister_log_source(log_src) if log_source_registered?(log_src) + File.delete(log_file) if File.exist?(log_file) + end + + describe 'initialize_logger with sanitize enabled' do + it 'produces JSON log entries with sensitive data redacted' do + app = Msf::MCP::Application.new([], output: output) + app.send(:parse_arguments) + app.instance_variable_set(:@config, { + logging: { + enabled: true, + level: 'INFO', + log_file: log_file, + sanitize: true + } + }) + app.send(:initialize_logger) + + ilog({ message: 'Connection established', context: { password: 's3cret', host: 'localhost' } }, log_src, lvl_info) + + content = File.read(log_file) + expect(content).not_to be_empty + + entry = JSON.parse(content.strip.split("\n").last) + + expect(entry['timestamp']).not_to be_nil + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('Connection established') + + expect(entry['context']['password']).to eq('[REDACTED]') + expect(entry['context']['host']).to eq('localhost') + + expect(content).not_to include('s3cret') + end + end + + describe 'initialize_logger with sanitize disabled' do + it 'produces JSON log entries without redaction' do + app = Msf::MCP::Application.new([], output: output) + app.send(:parse_arguments) + app.instance_variable_set(:@config, { + logging: { + enabled: true, + level: 'INFO', + log_file: log_file, + sanitize: false + } + }) + app.send(:initialize_logger) + + ilog({ message: 'Connection established', context: { password: 's3cret', host: 'localhost' } }, log_src, lvl_info) + + content = File.read(log_file) + entry = JSON.parse(content.strip.split("\n").last) + + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('Connection established') + + expect(entry['context']['password']).to eq('s3cret') + expect(entry['context']['host']).to eq('localhost') + end + end + + describe 'log level filtering' do + it 'filters messages below the configured threshold' do + app = Msf::MCP::Application.new([], output: output) + app.send(:parse_arguments) + app.instance_variable_set(:@config, { + logging: { + enabled: true, + level: 'WARN', + log_file: log_file, + sanitize: false + } + }) + app.send(:initialize_logger) + + # INFO (LEV_2) should be filtered at WARN (LEV_1) threshold + ilog({ message: 'This should be filtered' }, log_src, lvl_info) + # WARN (LEV_1) should pass + wlog({ message: 'This should appear' }, log_src, lvl_warn) + # ERROR (LEV_0) should pass + elog({ message: 'This error should appear' }, log_src, lvl_error) + + content = File.read(log_file) + lines = content.strip.split("\n").reject(&:empty?) + + expect(lines.length).to eq(2) + + entries = lines.map { |l| JSON.parse(l) } + expect(entries.map { |e| e['severity'] }).to contain_exactly('WARN', 'ERROR') + expect(content).not_to include('This should be filtered') + end + end + + describe 'exception logging through the pipeline' do + it 'formats exceptions as structured JSON with sanitized messages' do + app = Msf::MCP::Application.new([], output: output) + app.send(:parse_arguments) + app.instance_variable_set(:@config, { + logging: { + enabled: true, + level: 'ERROR', + log_file: log_file, + sanitize: true + } + }) + app.send(:initialize_logger) + + error = StandardError.new('Failed with password=hunter2') + error.set_backtrace(['lib/msf/core/mcp/server.rb:42:in `start`']) + + elog({ message: 'Startup failed', exception: error }, log_src, lvl_error) + + content = File.read(log_file) + entry = JSON.parse(content.strip.split("\n").last) + + expect(entry['severity']).to eq('ERROR') + expect(entry['message']).to include('Startup failed') + expect(entry['exception']).to be_a(Hash) + expect(entry['exception']['class']).to eq('StandardError') + + expect(entry['exception']['message']).to include('[REDACTED]') + expect(entry['exception']['message']).not_to include('hunter2') + end + end +end diff --git a/spec/integration/msfmcpd/messagepack_reauth_flow_spec.rb b/spec/integration/msfmcpd/messagepack_reauth_flow_spec.rb new file mode 100644 index 0000000000..75d9b52abb --- /dev/null +++ b/spec/integration/msfmcpd/messagepack_reauth_flow_spec.rb @@ -0,0 +1,157 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'webmock/rspec' + +RSpec.describe 'MessagePack Re-Authentication Flow Integration' do + before(:all) do + WebMock.disable_net_connect!(allow_localhost: false) + end + + after(:all) do + WebMock.allow_net_connect! + end + + let(:host) { 'localhost' } + let(:port) { 55553 } + let(:endpoint) { '/api/' } + let(:api_url) { "https://#{host}:#{port}#{endpoint}" } + let(:user) { 'test_user' } + let(:password) { 'test_password' } + + describe 'Automatic Re-Authentication on Token Expiry' do + it 're-authenticates and retries when API call returns 401' do + call_count = 0 + + # Stub all POST requests and dispatch based on body content + stub_request(:post, api_url).to_return do |request| + body = MessagePack.unpack(request.body) + call_count += 1 + + case call_count + when 1 + # Initial authentication succeeds + expect(body[0]).to eq('auth.login') + { + status: 200, + body: { 'result' => 'success', 'token' => 'initial_token' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + when 2 + # First API call returns 401 (token expired) + expect(body[0]).to eq('module.search') + expect(body[1]).to eq('initial_token') + { + status: 401, + body: { 'error_message' => 'Token expired' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + when 3 + # Re-authentication succeeds with new token + expect(body[0]).to eq('auth.login') + { + status: 200, + body: { 'result' => 'success', 'token' => 'refreshed_token' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + when 4 + # Retry with new token succeeds + expect(body[0]).to eq('module.search') + expect(body[1]).to eq('refreshed_token') + { + status: 200, + body: [{ 'fullname' => 'exploit/test', 'type' => 'exploit', 'name' => 'test' }].to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + else + raise "Unexpected request ##{call_count}: #{body.inspect}" + end + end + + client = Msf::MCP::Metasploit::MessagePackClient.new( + host: host, + port: port, + endpoint: endpoint + ) + client.authenticate(user, password) + + # This call should trigger: 401 → re-auth → retry → success + result = client.search_modules('smb') + + expect(result).to be_an(Array) + expect(result.first['fullname']).to eq('exploit/test') + expect(client.instance_variable_get(:@token)).to eq('refreshed_token') + expect(call_count).to eq(4) + end + + it 'gives up after max retries when re-auth succeeds but API keeps failing' do + call_count = 0 + + stub_request(:post, api_url).to_return do |request| + body = MessagePack.unpack(request.body) + call_count += 1 + + if body[0] == 'auth.login' + { + status: 200, + body: { 'result' => 'success', 'token' => "token_#{call_count}" }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + else + # API calls always return 401 + { + status: 401, + body: { 'error_message' => 'Token invalid' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + } + end + end + + client = Msf::MCP::Metasploit::MessagePackClient.new( + host: host, + port: port, + endpoint: endpoint + ) + client.authenticate(user, password) + + # Should exhaust retries (max_retries=2) and re-raise + expect { + client.search_modules('smb') + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError) + end + + it 'propagates re-auth failure through the tool layer as an error response' do + stub_request(:post, api_url) + .with(body: ['auth.login', user, password].to_msgpack) + .to_return( + status: 200, + body: { 'result' => 'success', 'token' => 'test_token' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + ) + + # All subsequent requests return 401 + stub_request(:post, api_url) + .with { |req| MessagePack.unpack(req.body)[0] != 'auth.login' } + .to_return( + status: 401, + body: { 'error_message' => 'Token invalid' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + ) + + client = Msf::MCP::Metasploit::MessagePackClient.new( + host: host, + port: port, + endpoint: endpoint + ) + client.authenticate(user, password) + + limiter = Msf::MCP::Security::RateLimiter.new(requests_per_minute: 60) + server_context = { msf_client: client, rate_limiter: limiter } + + result = Msf::MCP::Tools::SearchModules.call(query: 'smb', server_context: server_context) + + expect(result.error?).to be true + expect(result.content.first[:text]).to include('Authentication failed') + end + end +end diff --git a/spec/integration/msfmcpd/rpc_availability_spec.rb b/spec/integration/msfmcpd/rpc_availability_spec.rb new file mode 100644 index 0000000000..2f57768b60 --- /dev/null +++ b/spec/integration/msfmcpd/rpc_availability_spec.rb @@ -0,0 +1,165 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'stringio' +require 'tempfile' + +RSpec.describe 'RPC Availability Integration' do + let(:output) { StringIO.new } + let(:file_fixtures_path) { File.join(Msf::Config.install_root, 'spec', 'file_fixtures') } + let(:valid_messagepack_path) { File.join(file_fixtures_path, 'config_files', 'msfmcpd', 'valid_messagepack.yaml') } + + describe 'Application run with RPC already available but no credentials' do + it 'exits with RPC startup error when MessagePack credentials are missing' do + # Config with no credentials — validator allows this because auto-start + # could generate them, but RPC is already running so generation won't happen + config = { + msf_api: { + type: 'messagepack', + host: 'localhost', + port: 55553, + auto_start_rpc: true + } + } + + config_file = Tempfile.new(['no_creds', '.yaml']) + config_file.write(YAML.dump(JSON.parse(config.to_json))) + config_file.flush + + app = Msf::MCP::Application.new(['--config', config_file.path], output: output) + + # Stub RPC as already available + allow_any_instance_of(Msf::MCP::RpcManager).to receive(:rpc_available?).and_return(true) + allow(Signal).to receive(:trap) + + expect { app.run }.to raise_error(SystemExit) do |e| + expect(e.status).to eq(1) + end + + expect(output.string).to include('RPC startup error') + expect(output.string).to include('no credentials') + + config_file.close + config_file.unlink + end + + it 'exits with RPC startup error when JSON-RPC token is missing' do + config = { + msf_api: { + type: 'json-rpc', + host: 'localhost', + port: 8081 + } + } + + config_file = Tempfile.new(['no_token', '.yaml']) + config_file.write(YAML.dump(JSON.parse(config.to_json))) + config_file.flush + + app = Msf::MCP::Application.new(['--config', config_file.path], output: output) + + # Stub RPC as already available + allow_any_instance_of(Msf::MCP::RpcManager).to receive(:rpc_available?).and_return(true) + allow(Signal).to receive(:trap) + + expect { app.run }.to raise_error(SystemExit) do |e| + expect(e.status).to eq(1) + end + + # The validator catches missing token before RpcManager runs + expect(output.string).to match(/token|Configuration validation failed/i) + + config_file.close + config_file.unlink + end + + it 'proceeds when RPC is available and credentials are provided' do + app = Msf::MCP::Application.new(['--config', valid_messagepack_path], output: output) + + # Stub RPC as already available + allow_any_instance_of(Msf::MCP::RpcManager).to receive(:rpc_available?).and_return(true) + + # Stub the rest of the startup sequence + mock_client = instance_double(Msf::MCP::Metasploit::Client) + allow(Msf::MCP::Metasploit::Client).to receive(:new).and_return(mock_client) + allow(mock_client).to receive(:authenticate) + mock_server = instance_double(Msf::MCP::Server) + allow(Msf::MCP::Server).to receive(:new).and_return(mock_server) + allow(mock_server).to receive(:start) + allow(Signal).to receive(:trap) + + expect { app.run }.not_to raise_error + + expect(output.string).to include('already running') + expect(output.string).to include('Authentication successful') + end + end + + describe 'Application run with RPC not available' do + it 'exits with RPC startup error when auto-start is disabled' do + config = { + msf_api: { + type: 'messagepack', + host: 'localhost', + port: 55553, + user: 'msf', + password: 'pass', + auto_start_rpc: false + } + } + + config_file = Tempfile.new(['no_autostart', '.yaml']) + config_file.write(YAML.dump(JSON.parse(config.to_json))) + config_file.flush + + app = Msf::MCP::Application.new(['--config', config_file.path], output: output) + + # Stub RPC as not available + allow_any_instance_of(Msf::MCP::RpcManager).to receive(:rpc_available?).and_return(false) + allow(Signal).to receive(:trap) + + expect { app.run }.to raise_error(SystemExit) do |e| + expect(e.status).to eq(1) + end + + expect(output.string).to include('RPC startup error') + expect(output.string).to include('auto-start is disabled') + + config_file.close + config_file.unlink + end + + it 'exits with RPC startup error on remote host' do + config = { + msf_api: { + type: 'messagepack', + host: '192.0.2.1', + port: 55553, + user: 'msf', + password: 'pass', + auto_start_rpc: true + } + } + + config_file = Tempfile.new(['remote_host', '.yaml']) + config_file.write(YAML.dump(JSON.parse(config.to_json))) + config_file.flush + + app = Msf::MCP::Application.new(['--config', config_file.path], output: output) + + # Stub RPC as not available + allow_any_instance_of(Msf::MCP::RpcManager).to receive(:rpc_available?).and_return(false) + allow(Signal).to receive(:trap) + + expect { app.run }.to raise_error(SystemExit) do |e| + expect(e.status).to eq(1) + end + + expect(output.string).to include('RPC startup error') + expect(output.string).to include('192.0.2.1') + + config_file.close + config_file.unlink + end + end +end diff --git a/spec/integration/msfmcpd/tool_execution_module_info_spec.rb b/spec/integration/msfmcpd/tool_execution_module_info_spec.rb new file mode 100644 index 0000000000..28061127b8 --- /dev/null +++ b/spec/integration/msfmcpd/tool_execution_module_info_spec.rb @@ -0,0 +1,128 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'webmock/rspec' + +RSpec.describe 'Tool Execution End-to-End - Module Info' do + before(:all) do + WebMock.disable_net_connect!(allow_localhost: false) + end + + after(:all) do + WebMock.allow_net_connect! + end + + let(:host) { 'localhost' } + let(:port) { 55553 } + let(:endpoint) { '/api/' } + let(:api_url) { "https://#{host}:#{port}#{endpoint}" } + let(:user) { 'test_user' } + let(:password) { 'test_password' } + + let(:limiter) { Msf::MCP::Security::RateLimiter.new(requests_per_minute: 60, burst_size: 10) } + let(:client) do + c = Msf::MCP::Metasploit::MessagePackClient.new(host: host, port: port, endpoint: endpoint) + c.authenticate(user, password) + c + end + let(:server_context) { { msf_client: client, rate_limiter: limiter } } + + before do + stub_request(:post, api_url) + .with(body: ['auth.login', user, password].to_msgpack) + .to_return( + status: 200, + body: { 'result' => 'success', 'token' => 'test_token' }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + ) + end + + describe 'Module Info Integration with HTTP' do + it 'retrieves module info through complete HTTP request flow' do + info_stub = stub_request(:post, api_url) + .with(body: ['module.info', 'test_token', 'exploit', 'windows/smb/ms17_010_eternalblue'].to_msgpack) + .to_return( + status: 200, + body: { + 'type' => 'exploit', + 'name' => 'MS17-010 EternalBlue', + 'fullname' => 'exploit/windows/smb/ms17_010_eternalblue', + 'rank' => 'excellent', + 'disclosuredate' => '2017-03-14', + 'description' => 'MS17-010 EternalBlue SMB Remote Windows Kernel Pool Corruption', + 'license' => 'MSF_LICENSE', + 'filepath' => '/opt/metasploit-framework/modules/exploits/windows/smb/ms17_010_eternalblue.rb', + 'arch' => ['x64', 'x86'], + 'platform' => ['windows'], + 'authors' => ['Author1', 'Author2'], + 'privileged' => true, + 'check' => true, + 'references' => [['CVE', '2017-0144'], ['URL', 'https://example.com']], + 'targets' => { 0 => 'Windows 7', 1 => 'Windows 8' }, + 'default_target' => 0, + 'options' => { 'RHOSTS' => { 'type' => 'address', 'required' => true } } + }.to_msgpack, + headers: { 'Content-Type' => 'binary/message-pack' } + ) + + result = Msf::MCP::Tools::ModuleInfo.call( + type: 'exploit', + name: 'windows/smb/ms17_010_eternalblue', + server_context: server_context + ) + + expect(info_stub).to have_been_requested.once + + expect(result).to be_a(MCP::Tool::Response) + expect(result.error?).to be false + + data = result.structured_content[:data] + expect(data[:fullname]).to eq('exploit/windows/smb/ms17_010_eternalblue') + expect(data[:rank]).to eq('excellent') + expect(data[:architectures]).to eq(['x64', 'x86']) + expect(data[:has_check_method]).to be true + + # Verify filepath is stripped of install path + expect(data[:filepath]).to eq('modules/exploits/windows/smb/ms17_010_eternalblue.rb') + expect(data[:filepath]).not_to include('/opt/metasploit-framework/') + + # Verify references are transformed + expect(data[:references]).to eq([ + { type: 'CVE', value: '2017-0144' }, + { type: 'URL', value: 'https://example.com' } + ]) + + # Verify metadata + expect(result.structured_content[:metadata][:query_time]).to be_a(Float) + end + + it 'handles module not found through HTTP' do + stub_request(:post, api_url) + .with(body: ['module.info', 'test_token', 'exploit', 'nonexistent/module'].to_msgpack) + .to_return( + status: 500, + body: { 'error_message' => 'Module not found' }.to_msgpack + ) + + result = Msf::MCP::Tools::ModuleInfo.call( + type: 'exploit', + name: 'nonexistent/module', + server_context: server_context + ) + + expect(result.error?).to be true + expect(result.content.first[:text]).to include('Metasploit API error') + end + + it 'validates module type before making HTTP request' do + result = Msf::MCP::Tools::ModuleInfo.call( + type: 'invalid_type', + name: 'windows/smb/ms17_010_eternalblue', + server_context: server_context + ) + + expect(result.error?).to be true + expect(result.content.first[:text]).to include('Module type') + end + end +end diff --git a/spec/lib/msf/core/mcp/application_spec.rb b/spec/lib/msf/core/mcp/application_spec.rb index a750fe9dfc..c5bfcc97bc 100644 --- a/spec/lib/msf/core/mcp/application_spec.rb +++ b/spec/lib/msf/core/mcp/application_spec.rb @@ -124,7 +124,9 @@ RSpec.describe Msf::MCP::Application do let(:log_file) { Tempfile.new('app_test_log').tap(&:close).path } after do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end File.delete(log_file) if File.exist?(log_file) end @@ -139,7 +141,7 @@ RSpec.describe Msf::MCP::Application do it 'registers the Rex source when --enable-logging is set' do app = described_class.new(['--enable-logging', '--log-file', log_file], output: output) app.send(:parse_arguments) - app.instance_variable_set(:@config, { logging: { enabled: false, level: 'INFO' } }) + app.instance_variable_set(:@config, { logging: { enabled: false, level: 'INFO', sanitize: false } }) app.send(:initialize_logger) expect(log_source_registered?(Msf::MCP::LOG_SOURCE)).to be true @@ -147,7 +149,7 @@ RSpec.describe Msf::MCP::Application do it 'registers the Rex source when logging.enabled is true in config' do app = described_class.new([], output: output) - app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file } }) + app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file, sanitize: false } }) app.send(:initialize_logger) expect(log_source_registered?(Msf::MCP::LOG_SOURCE)).to be true @@ -157,7 +159,7 @@ RSpec.describe Msf::MCP::Application do cli_log = Tempfile.new('cli_log').tap(&:close).path app = described_class.new(['--log-file', cli_log], output: output) app.send(:parse_arguments) - app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file } }) + app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file, sanitize: false } }) app.send(:initialize_logger) # Emit a message and confirm it went to the CLI path, not the config path @@ -168,6 +170,29 @@ RSpec.describe Msf::MCP::Application do deregister_log_source(Msf::MCP::LOG_SOURCE) File.delete(cli_log) if File.exist?(cli_log) end + + it 'wraps the sink with Sanitizing when sanitize is true' do + app = described_class.new([], output: output) + app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file, sanitize: true } }) + app.send(:initialize_logger) + + # Log a message containing a sensitive pattern and verify it is redacted + elog({ message: 'password= s3cret' }, Msf::MCP::LOG_SOURCE, Rex::Logging::LEV_0) + content = File.read(log_file) + expect(content).to include('[REDACTED]') + expect(content).not_to include('s3cret') + end + + it 'does not wrap with Sanitizing when sanitize is false' do + app = described_class.new([], output: output) + app.instance_variable_set(:@config, { logging: { enabled: true, level: 'INFO', log_file: log_file, sanitize: false } }) + app.send(:initialize_logger) + + # Log a message containing a sensitive pattern — should appear as-is + elog({ message: 'password= s3cret' }, Msf::MCP::LOG_SOURCE, Rex::Logging::LEV_0) + content = File.read(log_file) + expect(content).to include('s3cret') + end end describe '#install_signal_handlers' do @@ -426,6 +451,17 @@ RSpec.describe Msf::MCP::Application do expect(output.string).to include('Shutdown complete') end + it 'calls stop_rpc_server on rpc_manager when present' do + mock_rpc_manager = instance_double(Msf::MCP::RpcManager) + + app = described_class.new([], output: output) + app.instance_variable_set(:@rpc_manager, mock_rpc_manager) + + expect(mock_rpc_manager).to receive(:stop_rpc_server) + + app.shutdown('INT') + end + it 'handles nil mcp_server gracefully' do app = described_class.new([], output: output) app.instance_variable_set(:@mcp_server, nil) @@ -433,6 +469,14 @@ RSpec.describe Msf::MCP::Application do expect { app.shutdown('INT') }.not_to raise_error expect(output.string).to include('Shutdown complete') end + + it 'handles nil rpc_manager gracefully' do + app = described_class.new([], output: output) + app.instance_variable_set(:@rpc_manager, nil) + + expect { app.shutdown('INT') }.not_to raise_error + expect(output.string).to include('Shutdown complete') + end end describe '#ensure_rpc_server' do @@ -549,19 +593,23 @@ RSpec.describe Msf::MCP::Application do expect(output.string).to include('Configuration validation failed') end - end + it 'handles ConfigurationError the same way' do + app = described_class.new([], output: output) + error = Msf::MCP::Config::ConfigurationError.new('Configuration file not found: /missing.yml') - describe '#handle_file_not_found_error' do - it 'outputs error message with config path and exits' do - app = described_class.new(['--config', '/missing/config.yml'], output: output) - app.send(:parse_arguments) - error = Errno::ENOENT.new('No such file') - - expect { app.send(:handle_file_not_found_error, error) }.to raise_error(SystemExit) do |e| + expect { app.send(:handle_configuration_error, error) }.to raise_error(SystemExit) do |e| expect(e.status).to eq(1) end - expect(output.string).to include('Configuration file not found: /missing/config.yml') - expect(output.string).to include('Create a configuration file or specify a valid path') + expect(output.string).to include('Configuration file not found') + end + + it 'does not call elog (logger not available yet)' do + app = described_class.new([], output: output) + error = Msf::MCP::Config::ValidationError.new({}) + + # elog should not be called — logger is not initialized at this stage + expect(app).not_to receive(:elog) + expect { app.send(:handle_configuration_error, error) }.to raise_error(SystemExit) end end @@ -577,6 +625,15 @@ RSpec.describe Msf::MCP::Application do expect(output.string).to include('Connection error to Metasploit RPC at localhost:55553') expect(output.string).to include('Connection refused') end + + it 'logs the error via elog' do + app = described_class.new([], output: output) + app.instance_variable_set(:@config, valid_config) + error = Msf::MCP::Metasploit::ConnectionError.new('Connection refused') + + expect(app).to receive(:elog).with(hash_including(message: 'Connection error'), anything, anything) + expect { app.send(:handle_connection_error, error) }.to raise_error(SystemExit) + end end describe '#handle_api_error' do @@ -589,6 +646,14 @@ RSpec.describe Msf::MCP::Application do end expect(output.string).to include('Metasploit API error: Invalid method') end + + it 'logs the error via elog' do + app = described_class.new([], output: output) + error = Msf::MCP::Metasploit::APIError.new('Invalid method') + + expect(app).to receive(:elog).with(hash_including(message: 'Metasploit API error'), anything, anything) + expect { app.send(:handle_api_error, error) }.to raise_error(SystemExit) + end end describe '#handle_authentication_error' do @@ -602,6 +667,35 @@ RSpec.describe Msf::MCP::Application do end expect(output.string).to include('Authentication error (username: testuser): Login Failed') end + + it 'logs the error via elog' do + app = described_class.new([], output: output) + app.instance_variable_set(:@config, valid_config) + error = Msf::MCP::Metasploit::AuthenticationError.new('Login Failed') + + expect(app).to receive(:elog).with(hash_including(message: 'Authentication error'), anything, anything) + expect { app.send(:handle_authentication_error, error) }.to raise_error(SystemExit) + end + end + + describe '#handle_rpc_startup_error' do + it 'outputs RPC startup error message and exits' do + app = described_class.new([], output: output) + error = Msf::MCP::Metasploit::RpcStartupError.new('msfrpcd not found') + + expect { app.send(:handle_rpc_startup_error, error) }.to raise_error(SystemExit) do |e| + expect(e.status).to eq(1) + end + expect(output.string).to include('RPC startup error: msfrpcd not found') + end + + it 'logs the error via elog' do + app = described_class.new([], output: output) + error = Msf::MCP::Metasploit::RpcStartupError.new('msfrpcd not found') + + expect(app).to receive(:elog).with(hash_including(message: 'RPC startup error'), anything, anything) + expect { app.send(:handle_rpc_startup_error, error) }.to raise_error(SystemExit) + end end describe '#handle_fatal_error' do @@ -618,6 +712,14 @@ RSpec.describe Msf::MCP::Application do expect(output.string).to include('line5') expect(output.string).not_to include('line6') # Only first 5 lines end + + it 'logs the error via elog' do + app = described_class.new([], output: output) + error = StandardError.new('Unexpected error') + + expect(app).to receive(:elog).with(hash_including(message: 'Fatal error during startup'), anything, anything) + expect { app.send(:handle_fatal_error, error) }.to raise_error(SystemExit) + end end end diff --git a/spec/lib/msf/core/mcp/config/loader_spec.rb b/spec/lib/msf/core/mcp/config/loader_spec.rb index b1013a101e..8f78a03819 100644 --- a/spec/lib/msf/core/mcp/config/loader_spec.rb +++ b/spec/lib/msf/core/mcp/config/loader_spec.rb @@ -393,6 +393,7 @@ RSpec.describe Msf::MCP::Config::Loader do context 'logging defaults' do let(:config_hash) { {} } + let(:default_log_file) { File.join(Msf::Config.log_directory, 'msfmcp.log') } it 'sets default enabled to false' do config = described_class.load_from_hash(config_hash) @@ -404,9 +405,14 @@ RSpec.describe Msf::MCP::Config::Loader do expect(config[:logging][:level]).to eq('INFO') end - it 'sets default log_file to msfmcp.log' do + it 'sets default log_file to msfmcp.log in the default Msf log directory' do config = described_class.load_from_hash(config_hash) - expect(config[:logging][:log_file]).to eq('msfmcp.log') + expect(config[:logging][:log_file]).to eq(default_log_file) + end + + it 'sets default sanitize to true' do + config = described_class.load_from_hash(config_hash) + expect(config[:logging][:sanitize]).to be true end context 'when logging is explicitly enabled' do @@ -420,7 +426,26 @@ RSpec.describe Msf::MCP::Config::Loader do it 'still applies other defaults' do config = described_class.load_from_hash(config_hash) expect(config[:logging][:level]).to eq('INFO') - expect(config[:logging][:log_file]).to eq('msfmcp.log') + expect(config[:logging][:log_file]).to eq(default_log_file) + expect(config[:logging][:sanitize]).to be true + end + end + + context 'when sanitize is explicitly set to false' do + let(:config_hash) { { logging: { sanitize: false } } } + + it 'preserves explicit false value' do + config = described_class.load_from_hash(config_hash) + expect(config[:logging][:sanitize]).to be false + end + end + + context 'when sanitize is explicitly set to true' do + let(:config_hash) { { logging: { sanitize: true } } } + + it 'preserves explicit true value' do + config = described_class.load_from_hash(config_hash) + expect(config[:logging][:sanitize]).to be true end end @@ -432,6 +457,11 @@ RSpec.describe Msf::MCP::Config::Loader do expect(config[:logging][:enabled]).to be false end + it 'applies default for sanitize' do + config = described_class.load_from_hash(config_hash) + expect(config[:logging][:sanitize]).to be true + end + it 'preserves explicit values' do config = described_class.load_from_hash(config_hash) expect(config[:logging][:level]).to eq('DEBUG') diff --git a/spec/lib/msf/core/mcp/config/validator_spec.rb b/spec/lib/msf/core/mcp/config/validator_spec.rb index 2701274ea9..4621f8c977 100644 --- a/spec/lib/msf/core/mcp/config/validator_spec.rb +++ b/spec/lib/msf/core/mcp/config/validator_spec.rb @@ -889,7 +889,7 @@ RSpec.describe Msf::MCP::Config::Validator do end it 'accepts all valid log levels' do - %w[DEBUG INFO WARN ERROR FATAL].each do |level| + %w[DEBUG INFO WARN ERROR].each do |level| config = base_config.merge(logging: { level: level }) expect(described_class.validate!(config)).to be true end @@ -917,6 +917,30 @@ RSpec.describe Msf::MCP::Config::Validator do expect(error.errors[:'logging.log_file']).to eq('must be a non-empty string') end end + + it 'accepts sanitize set to true' do + config = base_config.merge(logging: { sanitize: true }) + expect(described_class.validate!(config)).to be true + end + + it 'accepts sanitize set to false' do + config = base_config.merge(logging: { sanitize: false }) + expect(described_class.validate!(config)).to be true + end + + it 'raises ValidationError for non-boolean logging.sanitize' do + config = base_config.merge(logging: { sanitize: 'yes' }) + expect { + described_class.validate!(config) + }.to raise_error(Msf::MCP::Config::ValidationError) do |error| + expect(error.errors[:'logging.sanitize']).to eq('must be boolean (true or false)') + end + end + + it 'does not validate sanitize when key is absent' do + config = base_config.merge(logging: { enabled: true, level: 'INFO' }) + expect(described_class.validate!(config)).to be true + end end end diff --git a/spec/lib/msf/core/mcp/logging/log_constants_spec.rb b/spec/lib/msf/core/mcp/logging/log_constants_spec.rb new file mode 100644 index 0000000000..a0e163cafa --- /dev/null +++ b/spec/lib/msf/core/mcp/logging/log_constants_spec.rb @@ -0,0 +1,72 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'tempfile' +require 'json' + +RSpec.describe 'Msf::MCP log constants' do + describe 'LOG_SOURCE' do + it 'is set to mcp' do + expect(Msf::MCP::LOG_SOURCE).to eq('mcp') + end + end + + describe 'LOG_LEVEL constants' do + it 'maps LOG_DEBUG to LEV_3' do + expect(Msf::MCP::LOG_DEBUG).to eq(Rex::Logging::LEV_3) + end + + it 'maps LOG_INFO to LEV_2' do + expect(Msf::MCP::LOG_INFO).to eq(Rex::Logging::LEV_2) + end + + it 'maps LOG_WARN to LEV_1' do + expect(Msf::MCP::LOG_WARN).to eq(Rex::Logging::LEV_1) + end + + it 'maps LOG_ERROR to LEV_0' do + expect(Msf::MCP::LOG_ERROR).to eq(Rex::Logging::LEV_0) + end + end + + describe 'explicit source and level usage' do + let(:log_file) { Tempfile.new(['log_constants_test', '.log']).tap(&:close).path } + let(:log_source) { Msf::MCP::LOG_SOURCE } + + before do + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), Rex::Logging::LEV_3) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + File.delete(log_file) if File.exist?(log_file) + end + + def last_log_entry + JSON.parse(File.read(log_file).strip.split("\n").last) + end + + it 'routes messages to the mcp source when passed explicitly' do + ilog('info message', log_source, Msf::MCP::LOG_INFO) + expect(last_log_entry['message']).to include('info message') + expect(last_log_entry['severity']).to eq('INFO') + end + + it 'does not affect the default core source' do + ilog('core message') + expect(File.read(log_file)).to be_empty + end + + it 'filters messages below the registered threshold' do + deregister_log_source(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), Rex::Logging::LEV_1) + + dlog('should be filtered', log_source, Msf::MCP::LOG_DEBUG) + expect(File.read(log_file)).to be_empty + + wlog('should appear', log_source, Msf::MCP::LOG_WARN) + expect(File.read(log_file)).not_to be_empty + end + end +end diff --git a/spec/lib/msf/core/mcp/logging/sinks/json_flatfile_spec.rb b/spec/lib/msf/core/mcp/logging/sinks/json_flatfile_spec.rb new file mode 100644 index 0000000000..62f9720af3 --- /dev/null +++ b/spec/lib/msf/core/mcp/logging/sinks/json_flatfile_spec.rb @@ -0,0 +1,134 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'tempfile' +require 'json' + +RSpec.describe Msf::MCP::Logging::Sinks::JsonFlatfile do + let(:log_path) { Tempfile.new(['json_flatfile_test', '.log']).tap(&:close).path } + let(:sink) { described_class.new(log_path) } + + after do + sink.cleanup rescue nil + File.delete(log_path) if File.exist?(log_path) + end + + describe '#initialize' do + it 'creates the log file' do + described_class.new(log_path) + expect(File.exist?(log_path)).to be true + end + + it 'opens the file in append mode' do + # Write some content first + File.write(log_path, "existing\n") + new_sink = described_class.new(log_path) + new_sink.log(:info, 'mcp', 0, 'appended') + new_sink.cleanup + + content = File.read(log_path) + expect(content).to start_with("existing\n") + expect(content).to include('appended') + end + + it 'inherits from JsonStream' do + expect(described_class.superclass).to eq(Msf::MCP::Logging::Sinks::JsonStream) + end + end + + describe '#log' do + it 'writes a JSON line to the file' do + sink.log(:info, 'mcp', 0, 'test message') + content = File.read(log_path) + expect(content).not_to be_empty + + entry = JSON.parse(content.strip) + expect(entry).to be_a(Hash) + end + + it 'includes timestamp, severity, level, source, and message' do + sink.log(:error, 'mcp', 2, 'something broke') + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['timestamp']).not_to be_nil + expect(entry['severity']).to eq('ERROR') + expect(entry['level']).to eq('2') + expect(entry['source']).to eq('mcp') + expect(entry['message']).to include('something broke') + end + + it 'writes one JSON object per line' do + sink.log(:info, 'mcp', 0, 'first') + sink.log(:info, 'mcp', 0, 'second') + + lines = File.read(log_path).strip.split("\n") + expect(lines.length).to eq(2) + expect(JSON.parse(lines[0])['message']).to include('first') + expect(JSON.parse(lines[1])['message']).to include('second') + end + + context 'with a Hash message' do + it 'extracts :message from the hash' do + sink.log(:info, 'mcp', 0, { message: 'structured log' }) + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['message']).to eq('structured log') + end + + it 'includes :context when present' do + sink.log(:info, 'mcp', 0, { message: 'with context', context: { tool: 'search' } }) + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['context']).to be_a(Hash) + expect(entry['context']['tool']).to eq('search') + end + + it 'omits :context when empty' do + sink.log(:info, 'mcp', 0, { message: 'no context', context: {} }) + entry = JSON.parse(File.read(log_path).strip) + + expect(entry).not_to have_key('context') + end + + it 'formats Exception in :exception as structured hash' do + error = StandardError.new('test error') + error.set_backtrace(['line1', 'line2']) + + sink.log(:error, 'mcp', 0, { message: 'error occurred', exception: error }) + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['exception']).to be_a(Hash) + expect(entry['exception']['class']).to eq('StandardError') + expect(entry['exception']['message']).to eq('test error') + end + + it 'passes non-Exception :exception values through as-is' do + sink.log(:error, 'mcp', 0, { message: 'error', exception: 'just a string' }) + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['exception']).to eq('just a string') + end + end + + context 'with a String message' do + it 'uses the string directly as message' do + sink.log(:info, 'mcp', 0, 'plain string') + entry = JSON.parse(File.read(log_path).strip) + + expect(entry['message']).to eq('plain string') + expect(entry).not_to have_key('context') + expect(entry).not_to have_key('exception') + end + end + end + + describe '#cleanup' do + it 'closes the underlying file' do + sink.log(:info, 'mcp', 0, 'before cleanup') + sink.cleanup + + # Writing after cleanup should raise (file is closed) + expect { sink.log(:info, 'mcp', 0, 'after cleanup') }.to raise_error(IOError) + end + end +end diff --git a/spec/lib/msf/core/mcp/logging/sinks/json_stream_spec.rb b/spec/lib/msf/core/mcp/logging/sinks/json_stream_spec.rb new file mode 100644 index 0000000000..547502bdf9 --- /dev/null +++ b/spec/lib/msf/core/mcp/logging/sinks/json_stream_spec.rb @@ -0,0 +1,246 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'stringio' +require 'json' + +RSpec.describe Msf::MCP::Logging::Sinks::JsonStream do + let(:stream) { StringIO.new } + let(:sink) { described_class.new(stream) } + let(:log_source) { Msf::MCP::LOG_SOURCE } + + # Helper: parse the last JSON line written to the stream + def last_entry + stream.rewind + lines = stream.read.strip.split("\n") + JSON.parse(lines.last) + end + + describe '#initialize' do + it 'accepts any IO-like stream' do + expect { described_class.new(StringIO.new) }.not_to raise_error + end + + it 'includes Rex::Logging::LogSink' do + expect(described_class.ancestors).to include(Rex::Logging::LogSink) + end + end + + describe '#log' do + it 'writes JSON to the stream' do + sink.log(:info, 'mcp', 0, 'test') + expect(last_entry).to be_a(Hash) + end + + it 'flushes after each write' do + expect(stream).to receive(:flush).once + sink.log(:info, 'mcp', 0, 'test') + end + + it 'appends a newline after each entry' do + sink.log(:info, 'mcp', 0, 'test') + stream.rewind + expect(stream.read).to end_with("\n") + end + + it 'includes a timestamp' do + sink.log(:info, 'mcp', 0, 'test') + expect(last_entry['timestamp']).not_to be_nil + end + + it 'uppercases the severity' do + sink.log(:error, 'mcp', 0, 'test') + expect(last_entry['severity']).to eq('ERROR') + end + + it 'converts level to string' do + sink.log(:info, 'mcp', 2, 'test') + expect(last_entry['level']).to eq('2') + end + + it 'converts source to string' do + sink.log(:info, :mcp, 0, 'test') + expect(last_entry['source']).to eq('mcp') + end + + context 'with a String message' do + it 'uses the string as message' do + sink.log(:info, 'mcp', 0, 'plain text') + expect(last_entry['message']).to eq('plain text') + end + + it 'does not include context or exception keys' do + sink.log(:info, 'mcp', 0, 'plain text') + expect(last_entry).not_to have_key('context') + expect(last_entry).not_to have_key('exception') + end + end + + context 'with a Hash message' do + it 'extracts :message from the hash' do + sink.log(:info, 'mcp', 0, { message: 'structured' }) + expect(last_entry['message']).to eq('structured') + end + + it 'falls back to hash.to_s when :message is nil' do + sink.log(:info, 'mcp', 0, { context: { a: 1 } }) + # message is the Hash#to_s representation since :message key is absent + expect(last_entry['message']).to include('context') + end + + it 'does not overwrite message when :message is empty string' do + sink.log(:info, 'mcp', 0, { message: '', context: { a: 1 } }) + # Empty :message is skipped, so message stays as hash.to_s + expect(last_entry['message']).to include('context') + end + + it 'includes :context when present and non-empty' do + sink.log(:info, 'mcp', 0, { message: 'test', context: { tool: 'search' } }) + expect(last_entry['context']).to eq({ 'tool' => 'search' }) + end + + it 'omits :context when nil' do + sink.log(:info, 'mcp', 0, { message: 'test', context: nil }) + expect(last_entry).not_to have_key('context') + end + + it 'omits :context when empty hash' do + sink.log(:info, 'mcp', 0, { message: 'test', context: {} }) + expect(last_entry).not_to have_key('context') + end + end + + context 'with an Exception in :exception' do + let(:error) do + StandardError.new('boom').tap do |e| + e.set_backtrace(%w[line1 line2 line3 line4 line5 line6]) + end + end + + it 'formats the exception as a structured hash' do + sink.log(:error, 'mcp', 0, { message: 'fail', exception: error }) + ex = last_entry['exception'] + + expect(ex['class']).to eq('StandardError') + expect(ex['message']).to eq('boom') + end + + it 'includes backtrace at DEBUG log level' do + # Register at LEV_3 (DEBUG) to enable backtrace + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_3) + + sink.log(:error, 'mcp', 0, { message: 'fail', exception: error }) + ex = last_entry['exception'] + + expect(ex['backtrace']).to be_an(Array) + expect(ex['backtrace'].length).to eq(5) # first(5) + expect(ex['backtrace']).not_to include('line6') + + deregister_log_source(log_source) + end + + it 'omits backtrace below DEBUG log level' do + # Register at LEV_0 — below BACKTRACE_LOG_LEVEL (3) + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_0) + + sink.log(:error, 'mcp', 0, { message: 'fail', exception: error }) + ex = last_entry['exception'] + + expect(ex).not_to have_key('backtrace') + + deregister_log_source(log_source) + end + + it 'handles exception with nil backtrace' do + no_bt = RuntimeError.new('no trace') + # backtrace is nil by default when not raised + + sink.log(:error, 'mcp', 0, { message: 'fail', exception: no_bt }) + ex = last_entry['exception'] + + expect(ex['class']).to eq('RuntimeError') + expect(ex['message']).to eq('no trace') + end + + it 'passes non-Exception :exception values through' do + sink.log(:error, 'mcp', 0, { message: 'fail', exception: 'string error' }) + expect(last_entry['exception']).to eq('string error') + end + end + + context 'context summarization at non-DEBUG level' do + before do + # Register at LEV_0 so debug_log_level? returns false + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_0) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + end + + it 'truncates heavy keys (:result, :body, :error)' do + long_value = 'x' * 2000 + sink.log(:info, 'mcp', 0, { message: 'test', context: { result: long_value } }) + ctx = last_entry['context'] + + expect(ctx['result']).to include('truncated') + expect(ctx['result'].length).to be < 2000 + end + + it 'passes through non-heavy scalar keys unchanged' do + sink.log(:info, 'mcp', 0, { message: 'test', context: { method: 'tools/call', elapsed_ms: 42 } }) + ctx = last_entry['context'] + + expect(ctx['method']).to eq('tools/call') + expect(ctx['elapsed_ms']).to eq(42) + end + + it 'truncates heavy keys inside :response sub-hash' do + long_result = 'y' * 2000 + context = { response: { status: 200, result: long_result } } + sink.log(:info, 'mcp', 0, { message: 'test', context: context }) + resp = last_entry['context']['response'] + + expect(resp['status']).to eq(200) + expect(resp['result']).to include('truncated') + end + + it 'does not truncate short values' do + sink.log(:info, 'mcp', 0, { message: 'test', context: { result: 'short' } }) + ctx = last_entry['context'] + + expect(ctx['result']).to eq('short') + end + end + + context 'context at DEBUG level' do + before do + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_3) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + end + + it 'passes context through without summarization' do + long_value = 'x' * 2000 + sink.log(:info, 'mcp', 0, { message: 'test', context: { result: long_value } }) + ctx = last_entry['context'] + + expect(ctx['result']).to eq(long_value) + expect(ctx['result']).not_to include('truncated') + end + end + end + + describe '#cleanup' do + it 'closes the stream' do + sink.cleanup + expect(stream).to be_closed + end + end +end diff --git a/spec/lib/msf/core/mcp/logging/sinks/sanitizing_spec.rb b/spec/lib/msf/core/mcp/logging/sinks/sanitizing_spec.rb index 8084d4c2af..5b560a81b5 100644 --- a/spec/lib/msf/core/mcp/logging/sinks/sanitizing_spec.rb +++ b/spec/lib/msf/core/mcp/logging/sinks/sanitizing_spec.rb @@ -2,55 +2,38 @@ require 'msf/core/mcp' require 'stringio' +require 'json' RSpec.describe Msf::MCP::Logging::Sinks::Sanitizing do - # Use a StringIO-backed Stream as the inner sink so we can inspect output - # without touching the filesystem. - let(:buffer) { StringIO.new } - let(:inner_sink) { Rex::Logging::Sinks::Stream.new(buffer) } - let(:sink) { described_class.new(inner_sink) } + let(:stream) { StringIO.new } + let(:inner_sink) { Msf::MCP::Logging::Sinks::JsonStream.new(stream) } + let(:sink) { described_class.new(inner_sink) } + let(:log_source) { Msf::MCP::LOG_SOURCE } - def logged_output - buffer.string + # Helper: parse the last JSON log entry from the stream + def last_log_entry + stream.rewind + lines = stream.read.strip.split("\n") + JSON.parse(lines.last) end describe '#log' do + it 'delegates to the inner sink' do + sink.log(:info, 'mcp', 0, 'hello') + expect(last_log_entry['message']).to include('hello') + end + + it 'passes severity, source, and level through' do + sink.log(:error, 'mcp', 2, 'test') + entry = last_log_entry + expect(entry['severity']).to eq('ERROR') + expect(entry['source']).to eq('mcp') + expect(entry['level']).to eq('2') + end + it 'passes through innocuous messages unchanged' do - sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, 'connected to host') - expect(logged_output).to include('connected to host') - end - - it 'delegates severity, source, and level to the inner sink' do - sink.log(Rex::Logging::LOG_WARN, 'msfmcp', 0, 'watch out') - expect(logged_output).to match(/\[w\(0\)\].*msfmcp.*watch out/) - end - - it 'redacts password key-value pairs' do - sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, 'password: hunter2') - expect(logged_output).to include('[REDACTED]') - expect(logged_output).not_to include('hunter2') - end - - it 'redacts token key-value pairs' do - sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, 'token=abc123xyz') - expect(logged_output).to include('[REDACTED]') - expect(logged_output).not_to include('abc123xyz') - end - - it 'redacts bearer tokens' do - sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, 'Authorization: Bearer eyJhbGci.payload.sig') - expect(logged_output).to include('[REDACTED]') - expect(logged_output).not_to include('eyJhbGci.payload.sig') - end - - it 'redacts API keys' do - sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, 'api_key=sk_live_1234567890abcdef') - expect(logged_output).to include('[REDACTED]') - expect(logged_output).not_to include('sk_live_1234567890abcdef') - end - - it 'passes through non-string messages without error' do - expect { sink.log(Rex::Logging::LOG_INFO, 'msfmcp', 0, nil) }.not_to raise_error + sink.log(:info, 'mcp', 0, 'connected to host') + expect(last_log_entry['message']).to include('connected to host') end end @@ -60,4 +43,271 @@ RSpec.describe Msf::MCP::Logging::Sinks::Sanitizing do sink.cleanup end end + + describe 'string sanitization' do + it 'redacts password key-value pairs' do + sink.log(:info, 'mcp', 0, 'password: hunter2') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('hunter2') + end + + it 'redacts password with equals sign' do + sink.log(:info, 'mcp', 0, 'password=s3cret') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('s3cret') + end + + it 'redacts token key-value pairs' do + sink.log(:info, 'mcp', 0, 'token=abc123xyz') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('abc123xyz') + end + + it 'redacts bearer tokens' do + sink.log(:info, 'mcp', 0, 'bearer eyJhbGci.payload.sig') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('eyJhbGci.payload.sig') + end + + it 'redacts token header style' do + sink.log(:info, 'mcp', 0, 'token abc123def') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('abc123def') + end + + it 'redacts API keys' do + sink.log(:info, 'mcp', 0, 'api_key=sk_live_1234567890') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('sk_live_1234567890') + end + + it 'redacts secret keys' do + sink.log(:info, 'mcp', 0, 'secret_key: my_secret_value') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('my_secret_value') + end + + it 'redacts credential values' do + sink.log(:info, 'mcp', 0, 'credential=admin_cred') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('admin_cred') + end + + it 'redacts auth values' do + sink.log(:info, 'mcp', 0, 'auth: some_auth_value') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('some_auth_value') + end + + it 'is case-insensitive' do + sink.log(:info, 'mcp', 0, 'PASSWORD: upper_case_secret') + msg = last_log_entry['message'] + expect(msg).to include('[REDACTED]') + expect(msg).not_to include('upper_case_secret') + end + + it 'does not redact non-sensitive strings' do + sink.log(:info, 'mcp', 0, 'Module loaded: exploit/windows/smb/ms17_010') + expect(last_log_entry['message']).to eq('Module loaded: exploit/windows/smb/ms17_010') + end + end + + describe 'hash sanitization' do + it 'redacts scalar values under sensitive keys' do + msg = { message: 'test', context: { password: 'secret123', host: 'localhost' } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + expect(ctx['password']).to eq('[REDACTED]') + expect(ctx['host']).to eq('localhost') + end + + it 'redacts all SENSITIVE_KEYS patterns' do + %w[password token secret api_key api_secret credential auth_token bearer access_token private_key].each do |key| + stream.truncate(0) + stream.rewind + msg = { message: 'test', context: { key.to_sym => 'sensitive_value' } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + expect(ctx[key]).to eq('[REDACTED]'), "Expected #{key} to be redacted" + end + end + + it 'recurses into Hash values under sensitive keys' do + msg = { message: 'test', context: { token: { password: 'deep_secret', safe: 'visible' } } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + # Hash under sensitive key is recursed, not replaced with REDACTED + expect(ctx['token']).to be_a(Hash) + expect(ctx['token']['password']).to eq('[REDACTED]') + expect(ctx['token']['safe']).to eq('visible') + end + + it 'recurses into Array values under sensitive keys' do + msg = { message: 'test', context: { token: ['value1', 'password: secret'] } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + expect(ctx['token']).to be_an(Array) + # String elements in the array get pattern-based sanitization + expect(ctx['token'][1]).to include('[REDACTED]') + expect(ctx['token'][1]).not_to include('secret') + end + + it 'recurses into non-sensitive hash values' do + msg = { message: 'test', context: { data: { password: 'nested_secret' } } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + expect(ctx['data']['password']).to eq('[REDACTED]') + end + + it 'passes through non-string/hash/array types' do + msg = { message: 'test', context: { count: 42, enabled: true, value: nil } } + sink.log(:info, 'mcp', 0, msg) + ctx = last_log_entry['context'] + + expect(ctx['count']).to eq(42) + expect(ctx['enabled']).to be true + expect(ctx['value']).to be_nil + end + + it 'sanitizes strings in arrays' do + msg = { message: 'test', context: { items: ['safe', 'password=secret', 'also safe'] } } + sink.log(:info, 'mcp', 0, msg) + items = last_log_entry['context']['items'] + + expect(items[0]).to eq('safe') + expect(items[1]).to include('[REDACTED]') + expect(items[1]).not_to include('secret') + expect(items[2]).to eq('also safe') + end + end + + describe 'exception handling' do + let(:error) do + StandardError.new('password=s3cret in message').tap do |e| + e.set_backtrace([ + '/opt/metasploit-framework/lib/msf/core/mcp/server.rb:42:in `start`', + '/opt/metasploit-framework/lib/msf/core/mcp/application.rb:100:in `run`', + '/home/user/lib/custom/code.rb:10:in `call`', + 'line4', 'line5', 'line6' + ]) + end + end + + it 'formats Exception as structured hash' do + msg = { message: 'error occurred', exception: error } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex['class']).to eq('StandardError') + expect(ex['message']).to be_a(String) + end + + it 'sanitizes the exception message' do + msg = { message: 'error occurred', exception: error } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex['message']).to include('[REDACTED]') + expect(ex['message']).not_to include('s3cret') + end + + context 'at DEBUG log level' do + before do + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_3) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + end + + it 'includes backtrace' do + msg = { message: 'error', exception: error } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex['backtrace']).to be_an(Array) + end + + it 'limits backtrace to 5 frames' do + msg = { message: 'error', exception: error } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex['backtrace'].length).to eq(5) + end + + it 'strips install path prefix from backtrace frames' do + msg = { message: 'error', exception: error } + sink.log(:error, 'mcp', 0, msg) + bt = last_log_entry['exception']['backtrace'] + + expect(bt[0]).to start_with('lib/msf/') + expect(bt[0]).not_to include('/opt/metasploit-framework/') + end + + it 'sanitizes backtrace strings containing sensitive patterns' do + error_with_sensitive_bt = StandardError.new('fail').tap do |e| + e.set_backtrace(['lib/msf/core/mcp/server.rb:42:in `token=abc123`']) + end + msg = { message: 'error', exception: error_with_sensitive_bt } + sink.log(:error, 'mcp', 0, msg) + bt = last_log_entry['exception']['backtrace'] + + expect(bt[0]).to include('[REDACTED]') + expect(bt[0]).not_to include('abc123') + end + end + + context 'below DEBUG log level' do + before do + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new('/dev/null'), Rex::Logging::LEV_0) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + end + + it 'omits backtrace' do + msg = { message: 'error', exception: error } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex).not_to have_key('backtrace') + end + end + + it 'handles exception with nil backtrace' do + no_bt = RuntimeError.new('no trace') + msg = { message: 'error', exception: no_bt } + sink.log(:error, 'mcp', 0, msg) + ex = last_log_entry['exception'] + + expect(ex['class']).to eq('RuntimeError') + expect(ex['message']).to eq('no trace') + end + + it 'passes non-Exception :exception values through after sanitization' do + msg = { message: 'error', exception: 'password=oops' } + sink.log(:error, 'mcp', 0, msg) + + expect(last_log_entry['exception']).to include('[REDACTED]') + expect(last_log_entry['exception']).not_to include('oops') + end + end end diff --git a/spec/lib/msf/core/mcp/metasploit/jsonrpc_client_spec.rb b/spec/lib/msf/core/mcp/metasploit/jsonrpc_client_spec.rb index d8cfa6bffa..13bf351587 100644 --- a/spec/lib/msf/core/mcp/metasploit/jsonrpc_client_spec.rb +++ b/spec/lib/msf/core/mcp/metasploit/jsonrpc_client_spec.rb @@ -55,12 +55,12 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do it 'enables SSL on Net::HTTP client' do expect(http_mock).to receive(:use_ssl=).with(true) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end it 'sets verify_mode to VERIFY_NONE' do expect(http_mock).to receive(:verify_mode=).with(OpenSSL::SSL::VERIFY_NONE) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end end @@ -69,12 +69,12 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do it 'disables SSL on Net::HTTP client' do expect(http_mock).to receive(:use_ssl=).with(false) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end it 'does not set verify_mode' do expect(http_mock).not_to receive(:verify_mode=) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end end @@ -84,7 +84,7 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do it 'configures HTTPS connection' do expect(http_mock).to receive(:use_ssl=).with(true) expect(http_mock).to receive(:verify_mode=).with(OpenSSL::SSL::VERIFY_NONE) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end end @@ -94,7 +94,7 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do it 'uses SSL by default' do expect(http_mock).to receive(:use_ssl=).with(true) expect(http_mock).to receive(:verify_mode=).with(OpenSSL::SSL::VERIFY_NONE) - client.send(:send_request, '{}') + client.send(:send_request, { jsonrpc: '2.0', method: 'test', id: 1 }) end end end @@ -110,11 +110,10 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do it 'sends JSON-RPC 2.0 request with correct structure' do expect(client).to receive(:send_request) do |body| - parsed = JSON.parse(body) - expect(parsed['jsonrpc']).to eq('2.0') - expect(parsed['method']).to eq('module.search') - expect(parsed['params']).to eq(['smb']) - expect(parsed['id']).to eq(1) + expect(body[:jsonrpc]).to eq('2.0') + expect(body[:method]).to eq('module.search') + expect(body[:params]).to eq(['smb']) + expect(body[:id]).to eq(1) { 'result' => {} } end @@ -196,6 +195,17 @@ RSpec.describe Msf::MCP::Metasploit::JsonRpcClient do ) expect { client.call_api('module.search', ['smb']) }.not_to raise_error end + + it 'calls dlog for request and response' do + allow(http_mock).to receive(:request).and_return( + instance_double(Net::HTTPResponse, code: '200', body: '{"result": {}}') + ) + + expect(client).to receive(:dlog).with(hash_including(message: 'JSON-RPC request'), anything, anything).ordered + expect(client).to receive(:dlog).with(hash_including(message: 'JSON-RPC response'), anything, anything).ordered + + client.call_api('module.search', ['smb']) + end end describe 'API wrapper methods' do diff --git a/spec/lib/msf/core/mcp/metasploit/messagepack_client_spec.rb b/spec/lib/msf/core/mcp/metasploit/messagepack_client_spec.rb index a6a3d745bc..7f5fec2073 100644 --- a/spec/lib/msf/core/mcp/metasploit/messagepack_client_spec.rb +++ b/spec/lib/msf/core/mcp/metasploit/messagepack_client_spec.rb @@ -97,17 +97,23 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do expect(token).to eq('abc123') end - it 'raises AuthenticationError on failure' do - # send_request raises AuthenticationError for HTTP 401 - allow(client).to receive(:send_request).and_raise(Msf::MCP::Metasploit::AuthenticationError, 'Login Failed') + it 'raises AuthenticationError when response contains error key' do + allow(client).to receive(:send_request).and_return({ 'error' => 'Invalid credentials' }) expect { - client.authenticate('testuser', 'testpass') - }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Login Failed') + client.authenticate('testuser', 'badpass') + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Invalid credentials') end it 'raises AuthenticationError with default message when result is not success' do - # send_request raises AuthenticationError for HTTP 401 + allow(client).to receive(:send_request).and_return({ 'result' => 'failure' }) + + expect { + client.authenticate('testuser', 'testpass') + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Authentication failed') + end + + it 'raises AuthenticationError when send_request raises' do allow(client).to receive(:send_request).and_raise(Msf::MCP::Metasploit::AuthenticationError, 'Login Failed') expect { @@ -145,16 +151,15 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do }.to raise_error(ArgumentError, /args must be an Array/) end - it 'raises AuthenticationError if no token present' do + it 'raises AuthenticationError if no token present and no credentials stored' do client.instance_variable_set(:@token, nil) expect { client.call_api('module.search', ['smb']) - }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, "Unable to authenticate after 0 attempts: Not authenticated") + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Not authenticated') end it 'raises APIError when response contains error' do - # send_request raises APIError for HTTP 500 allow(client).to receive(:send_request).and_raise(Msf::MCP::Metasploit::APIError, 'Method not found') expect { @@ -162,13 +167,13 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do }.to raise_error(Msf::MCP::Metasploit::APIError, 'Method not found') end - it 'raises APIError with error value when error is not a string' do - # send_request raises APIError for HTTP 500 - allow(client).to receive(:send_request).and_raise(Msf::MCP::Metasploit::APIError, 'true') + it 'logs via elog before re-raising Msf::MCP::Error subclasses' do + allow(client).to receive(:send_request).and_raise(Msf::MCP::Metasploit::APIError, 'Method not found') + expect(client).to receive(:elog).with(hash_including(message: 'MessagePack API call error'), anything, anything) expect { client.call_api('module.search', ['smb']) - }.to raise_error(Msf::MCP::Metasploit::APIError, 'true') + }.to raise_error(Msf::MCP::Metasploit::APIError) end end @@ -237,6 +242,18 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do ) expect { client_no_ssl.authenticate('user', 'pass') }.not_to raise_error end + + it 'calls dlog for request and response' do + client_no_ssl = described_class.new(host: host, port: port, ssl: false) + allow(http_mock).to receive(:request).and_return( + instance_double(Net::HTTPResponse, code: '200', body: { 'result' => 'success', 'token' => 'abc' }.to_msgpack) + ) + + expect(client_no_ssl).to receive(:dlog).with(hash_including(message: 'MessagePack request'), anything, anything).ordered + expect(client_no_ssl).to receive(:dlog).with(hash_including(message: 'MessagePack response'), anything, anything).ordered + + client_no_ssl.authenticate('user', 'pass') + end end describe 'automatic re-authentication' do @@ -275,7 +292,7 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do expect(client.instance_variable_get(:@token)).to eq('refreshed_token') end - it 'does not retry more than once' do + it 'stops retrying after max_retries when API calls keep failing' do retry_attempt = 0 allow(client).to receive(:send_request) do |request_array| @@ -289,13 +306,13 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do end end - # Should fail after one retry attempt + # After exhausting retries (max_retries=2), re-raises the last error expect { client.search_modules('smb') - }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, /Unable to authenticate/) + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Invalid token') - # Should have tried: initial call + re-auth + retry = 2 API calls (not counting auth) - expect(retry_attempt).to eq(2) + # initial call + 2 retries = 3 API attempts + expect(retry_attempt).to eq(3) end it 'does not auto-reauth if credentials not stored' do @@ -307,7 +324,39 @@ RSpec.describe Msf::MCP::Metasploit::MessagePackClient do expect { new_client.search_modules('smb') - }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, /Unable to authenticate/) + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, 'Invalid token') + end + + it 'logs wlog when attempting re-authentication' do + call_count = 0 + allow(client).to receive(:send_request) do |request_array| + call_count += 1 + case call_count + when 1 + raise Msf::MCP::Metasploit::AuthenticationError, 'Invalid token' + when 2 + { 'result' => 'success', 'token' => 'new_token' } + when 3 + { 'modules' => [] } + end + end + + expect(client).to receive(:wlog).with(hash_including(message: /Attempting to re-authenticate/), anything, anything) + client.search_modules('smb') + end + + it 'raises with descriptive message when re-authentication itself fails' do + allow(client).to receive(:send_request) do |request_array| + if request_array[0] == 'auth.login' + raise Msf::MCP::Metasploit::AuthenticationError, 'Bad credentials' + else + raise Msf::MCP::Metasploit::AuthenticationError, 'Invalid token' + end + end + + expect { + client.search_modules('smb') + }.to raise_error(Msf::MCP::Metasploit::AuthenticationError, /Unable to authenticate after 2 attempts: Bad credentials/) end it 'resets retry count after successful re-authentication' do diff --git a/spec/lib/msf/core/mcp/metasploit/response_transformer_spec.rb b/spec/lib/msf/core/mcp/metasploit/response_transformer_spec.rb index c0455c210e..79b2ebf70b 100644 --- a/spec/lib/msf/core/mcp/metasploit/response_transformer_spec.rb +++ b/spec/lib/msf/core/mcp/metasploit/response_transformer_spec.rb @@ -64,7 +64,7 @@ RSpec.describe Msf::MCP::Metasploit::ResponseTransformer do 'disclosuredate' => '2017-03-14', 'description' => 'Test description', 'license' => 'MSF_LICENSE', - 'filepath' => '/path/to/module', + 'filepath' => '/opt/metasploit-framework/modules/exploits/windows/smb/ms17_010.rb', 'arch' => ['x64', 'x86'], 'platform' => ['windows'], 'authors' => ['Author 1', 'Author 2'], @@ -92,7 +92,7 @@ RSpec.describe Msf::MCP::Metasploit::ResponseTransformer do disclosure_date: '2017-03-14', description: 'Test description', license: 'MSF_LICENSE', - filepath: '/path/to/module', + filepath: 'modules/exploits/windows/smb/ms17_010.rb', architectures: ['x64', 'x86'], platforms: ['windows'], authors: ['Author 1', 'Author 2'], @@ -129,12 +129,34 @@ RSpec.describe Msf::MCP::Metasploit::ResponseTransformer do end it 'compacts nil values' do - minimal_info = { 'name' => 'test' } + minimal_info = { 'name' => 'test', 'filepath' => 'modules/exploits/test.rb' } result = described_class.transform_module_info(minimal_info) - expect(result).to eq({ name: 'test' }) + expect(result[:name]).to eq('test') + expect(result[:filepath]).to eq('modules/exploits/test.rb') expect(result).not_to have_key(:description) end + + it 'strips the install path prefix from filepath' do + info = { 'name' => 'test', 'filepath' => '/home/user/.msf4/modules/post/linux/gather/enum_configs.rb' } + result = described_class.transform_module_info(info) + + expect(result[:filepath]).to eq('modules/post/linux/gather/enum_configs.rb') + end + + it 'handles nil filepath via safe navigation' do + info = { 'name' => 'test', 'filepath' => nil } + result = described_class.transform_module_info(info) + + expect(result).not_to have_key(:filepath) + end + + it 'passes through filepath that already starts with modules/' do + info = { 'name' => 'test', 'filepath' => 'modules/exploits/test.rb' } + result = described_class.transform_module_info(info) + + expect(result[:filepath]).to eq('modules/exploits/test.rb') + end end describe '.transform_hosts' do diff --git a/spec/lib/msf/core/mcp/middleware/request_logger_spec.rb b/spec/lib/msf/core/mcp/middleware/request_logger_spec.rb new file mode 100644 index 0000000000..55ad8544fd --- /dev/null +++ b/spec/lib/msf/core/mcp/middleware/request_logger_spec.rb @@ -0,0 +1,305 @@ +# frozen_string_literal: true + +require 'msf/core/mcp' +require 'tempfile' +require 'json' +require 'rack' + +RSpec.describe Msf::MCP::Middleware::RequestLogger do + let(:log_file) { Tempfile.new(['request_logger_test', '.log']).tap(&:close).path } + let(:log_source) { Msf::MCP::LOG_SOURCE } + + # A simple Rack app that returns a configurable response + let(:response_status) { 200 } + let(:response_headers) { { 'Content-Type' => 'application/json' } } + let(:response_body) { ['{"jsonrpc":"2.0","id":1,"result":{}}'] } + let(:inner_app) { ->(_env) { [response_status, response_headers, response_body] } } + let(:middleware) { described_class.new(inner_app) } + + before do + deregister_log_source(log_source) if log_source_registered?(log_source) + register_log_source(log_source, Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), Rex::Logging::LEV_3) + end + + after do + deregister_log_source(log_source) if log_source_registered?(log_source) + File.delete(log_file) if File.exist?(log_file) + end + + # Helper: parse the last JSON log entry + def last_log_entry + JSON.parse(File.read(log_file).strip.split("\n").last) + end + + # Helper: build a minimal Rack env for a given HTTP method + def rack_env_for(method, body: nil, headers: {}) + env = Rack::MockRequest.env_for('http://localhost:3000/mcp', method: method) + if body + io = StringIO.new(body) + env['rack.input'] = io + end + headers.each do |key, value| + rack_key = "HTTP_#{key.upcase.tr('-', '_')}" + env[rack_key] = value + end + env + end + + describe '#call' do + it 'delegates to the inner app and returns its response' do + env = rack_env_for('POST', body: '{"jsonrpc":"2.0","method":"ping","id":1}') + status, headers, body = middleware.call(env) + + expect(status).to eq(200) + expect(headers).to eq(response_headers) + expect(body).to eq(response_body) + end + + it 'logs after the inner app responds' do + env = rack_env_for('POST', body: '{"jsonrpc":"2.0","method":"ping","id":1}') + middleware.call(env) + + expect(File.read(log_file)).not_to be_empty + end + end + + describe 'POST requests' do + context 'with a normal JSON-RPC request' do + it 'logs at DEBUG level with method and id' do + body = '{"jsonrpc":"2.0","method":"tools/call","id":42,"params":{"name":"test"}}' + env = rack_env_for('POST', body: body) + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('DEBUG') + expect(entry['message']).to include('tools/call') + expect(entry['message']).to include('id=42') + end + + it 'includes elapsed time in the message' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + + expect(last_log_entry['message']).to match(/\d+(\.\d+)?ms/) + end + + it 'includes request fields in context' do + body = '{"jsonrpc":"2.0","method":"tools/call","id":1,"params":{"name":"test"}}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['request']['method']).to eq('tools/call') + expect(ctx['request']['id']).to eq(1) + end + + it 'includes response status in context' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']['status']).to eq(200) + end + + it 'includes response result in context' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']['result']).to eq({}) + end + end + + context 'with a notification (no id)' do + it 'logs at DEBUG level as a notification' do + body = '{"jsonrpc":"2.0","method":"notifications/initialized"}' + env = rack_env_for('POST', body: body) + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('DEBUG') + expect(entry['message']).to include('Notification') + expect(entry['message']).to include('notifications/initialized') + end + end + + context 'with an HTTP error response' do + let(:response_status) { 400 } + let(:response_body) { ['{"jsonrpc":"2.0","error":{"code":-32601,"message":"Method not found"}}'] } + + it 'logs at ERROR level' do + body = '{"jsonrpc":"2.0","method":"invalid","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('ERROR') + expect(entry['message']).to include('400') + expect(entry['message']).to include('invalid') + end + + it 'includes error details in response context' do + body = '{"jsonrpc":"2.0","method":"invalid","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']['error']).to be_a(Hash) + expect(ctx['response']['error']['message']).to eq('Method not found') + end + end + + context 'with invalid JSON in request body' do + it 'logs with unknown method name' do + env = rack_env_for('POST', body: 'not valid json{{{') + middleware.call(env) + + expect(last_log_entry['message']).to include('unknown') + end + end + + context 'with empty response body' do + let(:response_body) { [] } + + it 'does not include result or error in response context' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']).not_to have_key('result') + expect(ctx['response']).not_to have_key('error') + end + end + + context 'with non-Array response body (SSE stream)' do + let(:response_body) { proc { |_| } } + + it 'does not include result or error in response context' do + body = '{"jsonrpc":"2.0","method":"tools/call","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']).not_to have_key('result') + expect(ctx['response']).not_to have_key('error') + end + end + + context 'with invalid JSON in response body' do + let(:response_body) { ['not json{{{'] } + + it 'does not include result or error in response context' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + ctx = last_log_entry['context'] + + expect(ctx['response']).not_to have_key('result') + expect(ctx['response']).not_to have_key('error') + end + end + end + + describe 'GET requests' do + it 'logs SSE stream opened at INFO level' do + env = rack_env_for('GET') + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('SSE stream opened') + end + + it 'includes elapsed time' do + env = rack_env_for('GET') + middleware.call(env) + + expect(last_log_entry['message']).to match(/\d+(\.\d+)?ms/) + end + + it 'includes session_id from header when present' do + env = rack_env_for('GET', headers: { 'Mcp-Session-Id' => 'sess-abc' }) + middleware.call(env) + + expect(last_log_entry['context']['session_id']).to eq('sess-abc') + end + + it 'includes response status in context' do + env = rack_env_for('GET') + middleware.call(env) + + expect(last_log_entry['context']['response']['status']).to eq(200) + end + end + + describe 'DELETE requests' do + it 'logs session deleted at INFO level' do + env = rack_env_for('DELETE') + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('Session deleted') + end + end + + describe 'other HTTP methods' do + it 'logs at DEBUG level with method name and status' do + env = rack_env_for('OPTIONS') + middleware.call(env) + entry = last_log_entry + + expect(entry['severity']).to eq('DEBUG') + expect(entry['message']).to include('OPTIONS') + expect(entry['message']).to include('200') + end + end + + describe 'session ID extraction' do + it 'extracts session_id from request header' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body, headers: { 'Mcp-Session-Id' => 'req-sess' }) + middleware.call(env) + + expect(last_log_entry['context']['session_id']).to eq('req-sess') + end + + it 'falls back to session_id from response header' do + response_headers['Mcp-Session-Id'] = 'resp-sess' + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + + expect(last_log_entry['context']['session_id']).to eq('resp-sess') + end + + it 'omits session_id when not present' do + body = '{"jsonrpc":"2.0","method":"ping","id":1}' + env = rack_env_for('POST', body: body) + middleware.call(env) + + expect(last_log_entry['context']).not_to have_key('session_id') + end + end + + describe 'content type in response context' do + it 'includes Content-Type when present' do + env = rack_env_for('GET') + middleware.call(env) + + expect(last_log_entry['context']['response']['content_type']).to eq('application/json') + end + + it 'omits Content-Type when not present' do + response_headers.delete('Content-Type') + env = rack_env_for('GET') + middleware.call(env) + + expect(last_log_entry['context']['response']).not_to have_key('content_type') + end + end +end diff --git a/spec/lib/msf/core/mcp/rpc_manager_spec.rb b/spec/lib/msf/core/mcp/rpc_manager_spec.rb index c7b132c8ed..4f3393402d 100644 --- a/spec/lib/msf/core/mcp/rpc_manager_spec.rb +++ b/spec/lib/msf/core/mcp/rpc_manager_spec.rb @@ -43,16 +43,22 @@ RSpec.describe Msf::MCP::RpcManager do context 'when RPC server is listening' do it 'returns true' do - tcp_socket = instance_double(TCPSocket) - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_return(tcp_socket) + tcp_socket = instance_double('Rex::Socket::Tcp') + allow(Rex::Socket::Tcp).to receive(:create).with( + 'PeerHost' => 'localhost', + 'PeerPort' => 55553 + ).and_return(tcp_socket) allow(tcp_socket).to receive(:close) expect(manager.rpc_available?).to be true end it 'closes the probe connection' do - tcp_socket = instance_double(TCPSocket) - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_return(tcp_socket) + tcp_socket = instance_double('Rex::Socket::Tcp') + allow(Rex::Socket::Tcp).to receive(:create).with( + 'PeerHost' => 'localhost', + 'PeerPort' => 55553 + ).and_return(tcp_socket) expect(tcp_socket).to receive(:close) manager.rpc_available? @@ -61,31 +67,31 @@ RSpec.describe Msf::MCP::RpcManager do context 'when RPC server is not listening' do it 'returns false on connection refused' do - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_raise(Errno::ECONNREFUSED) + allow(Rex::Socket::Tcp).to receive(:create).and_raise(Rex::ConnectionError) expect(manager.rpc_available?).to be false end it 'returns false on host unreachable' do - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_raise(Errno::EHOSTUNREACH) + allow(Rex::Socket::Tcp).to receive(:create).and_raise(Rex::ConnectionError) expect(manager.rpc_available?).to be false end it 'returns false on network unreachable' do - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_raise(Errno::ENETUNREACH) + allow(Rex::Socket::Tcp).to receive(:create).and_raise(Rex::ConnectionError) expect(manager.rpc_available?).to be false end it 'returns false on socket error' do - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_raise(SocketError, 'getaddrinfo: nodename nor servname provided') + allow(Rex::Socket::Tcp).to receive(:create).and_raise(Rex::ConnectionError) expect(manager.rpc_available?).to be false end it 'returns false on timeout' do - allow(TCPSocket).to receive(:new).with('localhost', 55553).and_raise(Errno::ETIMEDOUT) + allow(Rex::Socket::Tcp).to receive(:create).and_raise(Rex::ConnectionError) expect(manager.rpc_available?).to be false end @@ -100,7 +106,10 @@ RSpec.describe Msf::MCP::RpcManager do let(:manager) { described_class.new(config: custom_config, output: output) } it 'probes the configured host and port' do - expect(TCPSocket).to receive(:new).with('192.0.2.1', 9999).and_raise(Errno::ECONNREFUSED) + expect(Rex::Socket::Tcp).to receive(:create).with( + 'PeerHost' => '192.0.2.1', + 'PeerPort' => 9999 + ).and_raise(Rex::ConnectionError) manager.rpc_available? end @@ -534,12 +543,20 @@ RSpec.describe Msf::MCP::RpcManager do let(:manager) { described_class.new(config: default_config, output: output) } before do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) - register_log_source(Msf::MCP::LOG_SOURCE, Rex::Logging::Sinks::Flatfile.new(log_file), Rex::Logging::LEV_1) + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end + register_log_source( + Msf::MCP::LOG_SOURCE, + Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), + Rex::Logging::LEV_3 + ) end after do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end File.delete(log_file) if File.exist?(log_file) end @@ -571,8 +588,8 @@ RSpec.describe Msf::MCP::RpcManager do context 'when RPC availability check succeeds' do it 'logs at DEBUG level' do - tcp_socket = instance_double(TCPSocket) - allow(TCPSocket).to receive(:new).and_return(tcp_socket) + tcp_socket = instance_double('Rex::Socket::Tcp') + allow(Rex::Socket::Tcp).to receive(:create).and_return(tcp_socket) allow(tcp_socket).to receive(:close) manager.rpc_available? @@ -624,7 +641,10 @@ RSpec.describe Msf::MCP::RpcManager do it 'uses the configured port for availability checks' do manager = described_class.new(config: custom_port_config, output: output) - expect(TCPSocket).to receive(:new).with('localhost', 44444).and_raise(Errno::ECONNREFUSED) + expect(Rex::Socket::Tcp).to receive(:create).with( + 'PeerHost' => 'localhost', + 'PeerPort' => 44444 + ).and_raise(Rex::ConnectionError) manager.rpc_available? end end @@ -693,6 +713,51 @@ RSpec.describe Msf::MCP::RpcManager do end end + describe '#token_provided?' do + context 'when token is present' do + it 'returns true' do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(token: 'valid_token') + manager = described_class.new(config: config, output: output) + expect(manager.send(:token_provided?)).to be true + end + end + + context 'when token is nil' do + it 'returns false' do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(token: nil) + manager = described_class.new(config: config, output: output) + expect(manager.send(:token_provided?)).to be false + end + end + + context 'when token is empty string' do + it 'returns false' do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(token: '') + manager = described_class.new(config: config, output: output) + expect(manager.send(:token_provided?)).to be false + end + end + + context 'when token is whitespace only' do + it 'returns false' do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(token: ' ') + manager = described_class.new(config: config, output: output) + expect(manager.send(:token_provided?)).to be false + end + end + + context 'when token key is absent' do + it 'returns false' do + manager = described_class.new(config: default_config, output: output) + expect(manager.send(:token_provided?)).to be false + end + end + end + describe '#generate_random_credentials' do let(:config) do c = default_config.dup @@ -728,8 +793,14 @@ RSpec.describe Msf::MCP::RpcManager do it 'logs the event via Rex' do log_file = Tempfile.new('creds_log').tap(&:close).path - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) - register_log_source(Msf::MCP::LOG_SOURCE, Rex::Logging::Sinks::Flatfile.new(log_file), Rex::Logging::LEV_0) + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end + register_log_source( + Msf::MCP::LOG_SOURCE, + Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), + Rex::Logging::LEV_3 + ) manager.send(:generate_random_credentials) @@ -798,6 +869,61 @@ RSpec.describe Msf::MCP::RpcManager do end end + context 'when RPC is already available with JSON-RPC type and token provided' do + let(:jsonrpc_config) do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(type: 'json-rpc', token: 'valid_token') + config + end + let(:manager) { described_class.new(config: jsonrpc_config, output: output) } + + before do + allow(manager).to receive(:rpc_available?).and_return(true) + end + + it 'does not raise' do + expect { manager.ensure_rpc_available }.not_to raise_error + end + end + + context 'when RPC is already available with JSON-RPC type but no token' do + let(:jsonrpc_no_token_config) do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(type: 'json-rpc', token: nil) + config + end + let(:manager) { described_class.new(config: jsonrpc_no_token_config, output: output) } + + before do + allow(manager).to receive(:rpc_available?).and_return(true) + end + + it 'raises RpcStartupError about missing token' do + expect { manager.ensure_rpc_available }.to raise_error( + Msf::MCP::Metasploit::RpcStartupError, /already running.*no token/i + ) + end + end + + context 'when RPC is not available with JSON-RPC type' do + let(:jsonrpc_config) do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(type: 'json-rpc', token: 'valid_token') + config + end + let(:manager) { described_class.new(config: jsonrpc_config, output: output) } + + before do + allow(manager).to receive(:rpc_available?).and_return(false) + end + + it 'raises RpcStartupError about auto-start not supported' do + expect { manager.ensure_rpc_available }.to raise_error( + Msf::MCP::Metasploit::RpcStartupError, /auto-start is not supported for JSON-RPC/i + ) + end + end + context 'when RPC is not available and auto-start is enabled' do before do allow(manager).to receive(:rpc_available?).and_return(false, true) @@ -862,19 +988,26 @@ RSpec.describe Msf::MCP::RpcManager do end context 'when RPC is not available and auto-start is disabled' do + let(:disabled_config) do + config = default_config.dup + config[:msf_api] = config[:msf_api].merge(auto_start_rpc: false) + config + end + let(:manager) { described_class.new(config: disabled_config, output: output) } + before do allow(manager).to receive(:rpc_available?).and_return(false) - allow(manager).to receive(:auto_start_enabled?).and_return(false) end it 'does not start an RPC server' do expect(manager).not_to receive(:start_rpc_server) - manager.ensure_rpc_available + expect { manager.ensure_rpc_available }.to raise_error(Msf::MCP::Metasploit::RpcStartupError) end - it 'outputs a warning about the unavailable RPC server' do - manager.ensure_rpc_available - expect(output.string).to include('not running') + it 'raises RpcStartupError about the unavailable RPC server' do + expect { manager.ensure_rpc_available }.to raise_error( + Msf::MCP::Metasploit::RpcStartupError, /not running.*auto-start is disabled/i + ) end end @@ -892,12 +1025,13 @@ RSpec.describe Msf::MCP::RpcManager do it 'does not attempt to start the RPC server' do expect(manager).not_to receive(:start_rpc_server) - manager.ensure_rpc_available + expect { manager.ensure_rpc_available }.to raise_error(Msf::MCP::Metasploit::RpcStartupError) end - it 'outputs a message about the remote host' do - manager.ensure_rpc_available - expect(output.string).to match(/remote|cannot auto-start/i) + it 'raises RpcStartupError about the remote host' do + expect { manager.ensure_rpc_available }.to raise_error( + Msf::MCP::Metasploit::RpcStartupError, /not available.*192\.0\.2\.1/ + ) end end end diff --git a/spec/lib/msf/core/mcp/server_spec.rb b/spec/lib/msf/core/mcp/server_spec.rb index 1cd8444a56..7a61d866d7 100644 --- a/spec/lib/msf/core/mcp/server_spec.rb +++ b/spec/lib/msf/core/mcp/server_spec.rb @@ -128,6 +128,21 @@ RSpec.describe Msf::MCP::Server do rate_limiter: rate_limiter ) end + + it 'passes a configuration object with around_request and exception_reporter' do + expect(::MCP::Server).to receive(:new) do |args| + config = args[:configuration] + expect(config).to be_a(::MCP::Configuration) + expect(config.around_request).to be_a(Proc) + expect(config.exception_reporter).to be_a(Proc) + mock_mcp_server + end + + described_class.new( + msf_client: mock_msf_client, + rate_limiter: rate_limiter + ) + end end describe '#start' do @@ -146,14 +161,6 @@ RSpec.describe Msf::MCP::Server do server.start(transport: :stdio) end - it 'sets transport on mcp_server' do - allow(::MCP::Server::Transports::StdioTransport).to receive(:new).and_return(mock_transport) - - expect(mock_mcp_server).to receive(:transport=).with(mock_transport) - - server.start(transport: :stdio) - end - it 'opens the transport' do allow(::MCP::Server::Transports::StdioTransport).to receive(:new).and_return(mock_transport) @@ -196,12 +203,6 @@ RSpec.describe Msf::MCP::Server do server.start(transport: :http, port: 3000) end - it 'sets transport on mcp_server' do - expect(mock_mcp_server).to receive(:transport=).with(mock_http_transport) - - server.start(transport: :http, port: 3000) - end - it 'starts Puma server via Rack handler' do expect(puma_handler).to receive(:run).with( anything, # Rack app @@ -337,103 +338,116 @@ RSpec.describe Msf::MCP::Server do # Instrumentation and logging tests describe 'instrumentation and logging' do require 'tempfile' + require 'json' let(:log_file) { Tempfile.new(['test_log', '.log']).tap(&:close).path } - # Wire a Rex flatfile sink for the duration of each example. before do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) - register_log_source(Msf::MCP::LOG_SOURCE, Rex::Logging::Sinks::Flatfile.new(log_file), Rex::Logging::LEV_0) - + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end + register_log_source( + Msf::MCP::LOG_SOURCE, + Msf::MCP::Logging::Sinks::JsonFlatfile.new(log_file), + Rex::Logging::LEV_3 + ) + # Mock the transport to prevent the server to actually start listening transport = instance_double(MCP::Server::Transports::StdioTransport) allow(::MCP::Server::Transports::StdioTransport).to receive(:new).and_return(transport) allow(transport).to receive(:open) end after do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) + if log_source_registered?(Msf::MCP::LOG_SOURCE) + deregister_log_source(Msf::MCP::LOG_SOURCE) + end File.delete(log_file) if File.exist?(log_file) end + # Helper: parse the last JSON log entry from the file + def last_log_entry + JSON.parse(File.read(log_file).strip.split("\n").last) + end + let(:server) { described_class.new(msf_client: mock_msf_client, rate_limiter: rate_limiter) } let(:mcp_server) { server.start } - describe 'instrumentation_callback' do + describe 'around_request' do it 'is always configured as a Proc' do - expect(mcp_server.configuration.instrumentation_callback).to be_a(Proc) + expect(mcp_server.configuration.around_request).to be_a(Proc) end - it 'is a no-op when called with nil' do - expect { mcp_server.configuration.instrumentation_callback.call(nil) }.not_to raise_error + it 'calls the request handler and returns its result' do + result = mcp_server.configuration.around_request.call({ tool_name: 'test' }) { { isError: false } } + expect(result).to eq({ isError: false }) end - it 'logs errors with [e] severity code' do - mcp_server.configuration.instrumentation_callback.call( - method: 'tools/call', tool_name: 'test_tool', error: 'tool_not_found', duration: 0.123 - ) - content = File.read(log_file) - expect(content).to match(/\[e\(\d\)\]/) - expect(content).to include('MCP Error: tool_not_found') - expect(content).to include('test_tool') + it 'logs error tool calls with error severity' do + mcp_server.configuration.around_request.call( + { method: 'tools/call', tool_name: 'test_tool', error: 'tool_not_found' } + ) { nil } + entry = last_log_entry + + expect(entry['severity']).to eq('ERROR') + expect(entry['message']).to include('MCP Error: tool_not_found') end - it 'logs successful tool calls with [i] severity code' do - mcp_server.configuration.instrumentation_callback.call( - method: 'tools/call', tool_name: 'search_modules', duration: 0.456 - ) - content = File.read(log_file) - expect(content).to match(/\[i\(\d\)\]/) - expect(content).to include('Tool call: search_modules') - expect(content).to include('456') + it 'logs successful tool calls with info severity' do + mcp_server.configuration.around_request.call( + { method: 'tools/call', tool_name: 'search_modules' } + ) { { isError: false } } + entry = last_log_entry + + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('Tool call: search_modules') end - it 'includes duration in milliseconds' do - mcp_server.configuration.instrumentation_callback.call( - method: 'tools/call', tool_name: 'test_tool', duration: 1.23456 - ) - expect(File.read(log_file)).to include('1234.56ms') + it 'logs isError results with error severity' do + mcp_server.configuration.around_request.call( + { method: 'tools/call', tool_name: 'test_tool' } + ) { { isError: true } } + entry = last_log_entry + + expect(entry['severity']).to eq('ERROR') + expect(entry['message']).to include('(ERROR)') + end + + it 'logs via ilog when result is nil and no error' do + mcp_server.configuration.around_request.call( + { method: 'tools/call', tool_name: 'test_tool' } + ) { nil } + entry = last_log_entry + + expect(entry['severity']).to eq('INFO') + expect(entry['message']).to include('Tool call: test_tool') end it 'logs prompt calls' do - mcp_server.configuration.instrumentation_callback.call( - method: 'prompts/get', prompt_name: 'exploit_suggestion', duration: 0.123 - ) - content = File.read(log_file) - expect(content).to include('Prompt call: exploit_suggestion') - expect(content).to include('123.0ms') + mcp_server.configuration.around_request.call( + { method: 'prompts/get', prompt_name: 'exploit_suggestion' } + ) { {} } + + expect(last_log_entry['message']).to include('Prompt call: exploit_suggestion') end it 'logs resource calls' do - mcp_server.configuration.instrumentation_callback.call( - method: 'resources/read', resource_uri: 'msf://exploits/windows', duration: 0.089 - ) - expect(File.read(log_file)).to include('Resource call: msf://exploits/windows') + mcp_server.configuration.around_request.call( + { method: 'resources/read', resource_uri: 'msf://exploits/windows' } + ) { {} } + + expect(last_log_entry['message']).to include('Resource call: msf://exploits/windows') end it 'logs generic method calls' do - mcp_server.configuration.instrumentation_callback.call(method: 'ping', duration: 0.001) - expect(File.read(log_file)).to include('Method call: ping') + mcp_server.configuration.around_request.call({ method: 'ping' }) { {} } + + expect(last_log_entry['message']).to include('Method call: ping') end it 'logs fallback message when no specific key is present' do - mcp_server.configuration.instrumentation_callback.call(some_unknown_key: 'value') - expect(File.read(log_file)).to include('MCP instrumentation') - end + mcp_server.configuration.around_request.call({}) { {} } - it 'omits duration text when not present' do - mcp_server.configuration.instrumentation_callback.call(tool_name: 'msf_host_info') - content = File.read(log_file) - expect(content).to include('Tool call: msf_host_info') - expect(content).not_to match(/\d+(\.\d+)?ms/) - end - - it 'includes extra data keys in the log line' do - mcp_server.configuration.instrumentation_callback.call( - tool_name: 'msf_search_modules', custom_key: 'custom_value', another_key: 42 - ) - content = File.read(log_file) - expect(content).to include('custom_value') - expect(content).to include('42') + expect(last_log_entry['message']).to include('MCP request') end end @@ -446,26 +460,24 @@ RSpec.describe Msf::MCP::Server do expect { mcp_server.configuration.exception_reporter.call(nil, nil) }.not_to raise_error end - it 'logs exceptions with [e] severity' do + it 'logs exceptions with error severity' do mcp_server.configuration.exception_reporter.call( StandardError.new('Something went wrong'), - { request: { name: 'msf_search_modules', arguments: { 'name' => 'test_tool' } } } + { request: '{"method":"tools/call","params":{"name":"msf_search_modules"}}' } ) - content = File.read(log_file) - expect(content).to match(/\[e\(\d\)\]/) - expect(content).to include('Error during request processing') - expect(content).to include('msf_search_modules') - expect(content).to include('Something went wrong') + entry = last_log_entry + + expect(entry['severity']).to eq('ERROR') + expect(entry['message']).to include('Error during request processing') end - it 'includes exception class and message in the log line' do + it 'extracts JSON-RPC method name from request context' do mcp_server.configuration.exception_reporter.call( - ArgumentError.new('Invalid argument provided'), - { request: { name: 'msf_search_modules', arguments: {} } } + StandardError.new('fail'), + { request: '{"method":"tools/call","params":{"name":"test"}}' } ) - content = File.read(log_file) - expect(content).to include('ArgumentError') - expect(content).to include('Invalid argument provided') + + expect(last_log_entry['message']).to include('(tools/call)') end it 'logs notification context' do @@ -473,155 +485,24 @@ RSpec.describe Msf::MCP::Server do RuntimeError.new('Notification failed'), { notification: 'notifications/initialized' } ) - content = File.read(log_file) - expect(content).to include('Error during notification processing') - expect(content).to include('notifications/initialized') - expect(content).to include('Notification failed') + entry = last_log_entry + + expect(entry['message']).to include('Error during notification processing') + expect(entry['message']).to include('notifications/initialized') end it 'logs unknown context type' do mcp_server.configuration.exception_reporter.call(StandardError.new('Unknown error'), {}) - content = File.read(log_file) - expect(content).to include('Error during unknown processing') - expect(content).to include('Unknown error') + + expect(last_log_entry['message']).to include('Error during unknown processing') end - it 'handles a non-Hash request value' do + it 'handles a non-JSON request value' do mcp_server.configuration.exception_reporter.call( - StandardError.new('Parse error'), { request: 'not valid Hash' } - ) - content = File.read(log_file) - expect(content).to include('Error during request processing') - expect(content).to include('not valid Hash') - end - end - end - - describe 'HTTP request/response logging' do - require 'tempfile' - require 'json' - require 'rack' - - let(:log_file) { Tempfile.new(['test_log', '.log']).tap(&:close).path } - let(:server) do - allow(::MCP::Server).to receive(:new).and_return(mock_mcp_server) - described_class.new(msf_client: mock_msf_client, rate_limiter: rate_limiter) - end - - before do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) - register_log_source(Msf::MCP::LOG_SOURCE, Rex::Logging::Sinks::Flatfile.new(log_file), Rex::Logging::LEV_0) - end - - after do - deregister_log_source(Msf::MCP::LOG_SOURCE) if log_source_registered?(Msf::MCP::LOG_SOURCE) - File.delete(log_file) if File.exist?(log_file) - end - - describe '#log_http_request' do - it 'logs POST method, id, and params' do - body = StringIO.new({ 'method' => 'tools/call', 'id' => 42, 'params' => { 'name' => 'test' } }.to_json) - request = instance_double(Rack::Request, post?: true, get?: false, body: body) - - server.send(:log_http_request, request) - - content = File.read(log_file) - expect(content).to match(/\[i\(\d\)\]/) - expect(content).to include('HTTP Request: tools/call (id: 42)') - expect(content).to include('"name"=>"test"') - end - - it 'logs a warning for invalid JSON in POST body' do - body = StringIO.new('not valid json{{{') - request = instance_double(Rack::Request, post?: true, get?: false, body: body) - - server.send(:log_http_request, request) - - expect(File.read(log_file)).to match(/\[w\(\d\)\].*Invalid JSON in HTTP request/) - end - - it 'logs GET SSE connection with session_id from header' do - request = instance_double(Rack::Request, - post?: false, get?: true, - env: { 'HTTP_MCP_SESSION_ID' => 'abc-123', 'QUERY_STRING' => '' } + StandardError.new('Parse error'), { request: 'not valid json' } ) - server.send(:log_http_request, request) - - content = File.read(log_file) - expect(content).to include('SSE connection request') - expect(content).to include('abc-123') - end - - it 'logs GET SSE connection with session_id from query string' do - request = instance_double(Rack::Request, - post?: false, get?: true, - env: { 'QUERY_STRING' => 'sessionId=xyz-789' } - ) - - server.send(:log_http_request, request) - - expect(File.read(log_file)).to include('xyz-789') - end - - it 'does not log non-POST/GET requests' do - request = instance_double(Rack::Request, post?: false, get?: false) - server.send(:log_http_request, request) - expect(File.read(log_file)).to be_empty - end - end - - describe '#log_http_response' do - it 'logs POST response errors with [e] severity' do - request = instance_double(Rack::Request, post?: true, get?: false) - response_body = { 'error' => { 'message' => 'Method not found', 'code' => -32601 } }.to_json - - server.send(:log_http_response, request, [400, {}, [response_body]]) - - content = File.read(log_file) - expect(content).to match(/\[e\(\d\)\]/) - expect(content).to include('HTTP Response error: Method not found') - expect(content).to include('-32601') - end - - it 'logs SSE accepted response' do - request = instance_double(Rack::Request, post?: true, get?: false) - server.send(:log_http_response, request, [202, {}, [{ 'accepted' => true }.to_json]]) - expect(File.read(log_file)).to include('Response sent via SSE stream') - end - - it 'logs successful POST response with id and session' do - request = instance_double(Rack::Request, post?: true, get?: false) - server.send(:log_http_response, request, - [200, { 'Mcp-Session-Id' => 'sess-456' }, [{ 'id' => 42, 'result' => {} }.to_json]]) - - content = File.read(log_file) - expect(content).to include('HTTP Response: success (id: 42)') - expect(content).to include('sess-456') - end - - it 'logs a warning for invalid JSON in POST response' do - request = instance_double(Rack::Request, post?: true, get?: false) - server.send(:log_http_response, request, [200, {}, ['not json{{']]) - expect(File.read(log_file)).to match(/\[w\(\d\)\].*Invalid JSON in HTTP response/) - end - - it 'logs SSE stream established for 200 GET' do - request = instance_double(Rack::Request, post?: false, get?: true) - server.send(:log_http_response, request, [200, {}, []]) - expect(File.read(log_file)).to include('SSE stream established') - end - - it 'does not log anything for empty POST body' do - request = instance_double(Rack::Request, post?: true, get?: false) - server.send(:log_http_response, request, [200, {}, []]) - expect(File.read(log_file)).to be_empty - end - - it 'does not log anything for non-array body' do - request = instance_double(Rack::Request, post?: true, get?: false) - server.send(:log_http_response, request, [200, {}, 'string body']) - expect(File.read(log_file)).to be_empty + expect(last_log_entry['message']).to include('Error during request processing') end end end