Redesign the logging capability using Rex::Logging and Rake middleware

- remove the original Logger
- use Rex::Logging with helper methods (dlog, ilog, etc.)
- add `sanitize` configuration option
- create Sanitizing, JsonFlatfile and JsonStream sinks for JSON logging format
- minor updates in apply_default (Loader)
- update the re-authentication logic (fix a specific usecase)
- add a Rack middleware that logs MCP HTTP request/response
- use Rex::Socket::Tcp instead of TcpSocket
- update the ensure_rpc_available for better validation
- use around_request instead of the deprecated SDK instrumentation for logging
- update and add specs
This commit is contained in:
Christophe De La Fuente
2026-04-30 11:10:09 +02:00
parent 20065b3f3d
commit 6f3884e832
40 changed files with 2869 additions and 597 deletions
@@ -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
@@ -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
@@ -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
@@ -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
+116 -14
View File
@@ -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
+33 -3
View File
@@ -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')
+25 -1
View File
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
+161 -27
View File
@@ -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
+107 -226
View File
@@ -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