Skip to content

Commit 2925bac

Browse files
comandeo-mongocomandeo-mongo
authored
RUBY-3456 Suppress no-op SDAM debug log lines (#3030)
1 parent 3dae92c commit 2925bac

6 files changed

Lines changed: 289 additions & 1 deletion

‎lib/mongo/monitoring/server_description_changed_log_subscriber.rb‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,8 @@ class ServerDescriptionChangedLogSubscriber < SDAMLogSubscriber
2323
private
2424

2525
def log_event(event)
26+
return if event.previous_description == event.new_description
27+
2628
log_debug(
2729
"Server description for #{event.address} changed from " +
2830
"'#{event.previous_description.server_type}' to '#{event.new_description.server_type}'#{awaited_indicator(event)}."

‎lib/mongo/monitoring/topology_changed_log_subscriber.rb‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,9 @@ class TopologyChangedLogSubscriber < SDAMLogSubscriber
2424

2525
def log_event(event)
2626
if event.previous_topology.class == event.new_topology.class
27+
return if event.previous_topology.server_descriptions ==
28+
event.new_topology.server_descriptions
29+
2730
log_debug(
2831
"There was a change in the members of the '#{event.new_topology.display_name}' " +
2932
'topology.'

‎lib/mongo/server/description.rb‎

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -185,14 +185,35 @@ class Description
185185
# @api private
186186
CONNECTION_ID = 'connectionId'
187187

188+
# Constant for reading the modern primary flag from config.
189+
#
190+
# @api private
191+
IS_WRITABLE_PRIMARY = 'isWritablePrimary'
192+
193+
# Constant for reading the helloOk capability flag from config.
194+
#
195+
# @api private
196+
HELLO_OK = 'helloOk'
197+
188198
# Fields to exclude when comparing two descriptions.
189199
#
200+
# The PRIMARY (legacy `ismaster`), IS_WRITABLE_PRIMARY (modern `hello`),
201+
# and HELLO_OK keys are excluded because the driver does a one-time
202+
# legacy-`isMaster` to modern-`hello` protocol switch on the initial
203+
# handshake (per the SDAM Server Monitoring spec). Two responses for the
204+
# same logical role differ only in which of these keys is populated.
205+
# The role itself is still differentiated by the SECONDARY flag and the
206+
# remaining replica-set metadata.
207+
#
190208
# @since 2.0.6
191209
EXCLUDE_FOR_COMPARISON = [ LOCAL_TIME,
192210
LAST_WRITE,
193211
OPERATION_TIME,
194212
Operation::CLUSTER_TIME,
195-
CONNECTION_ID, ].freeze
213+
CONNECTION_ID,
214+
PRIMARY,
215+
IS_WRITABLE_PRIMARY,
216+
HELLO_OK, ].freeze
196217

197218
# Instantiate the new server description from the result of the hello
198219
# command or fabricate a placeholder description for Unknown and
@@ -866,6 +887,7 @@ def service_id
866887
def ==(other)
867888
return false if self.class != other.class
868889
return false if unknown? || other.unknown?
890+
return false if server_type != other.server_type
869891

870892
(config.keys + other.config.keys).uniq.all? do |k|
871893
config[k] == other.config[k] || EXCLUDE_FOR_COMPARISON.include?(k)

‎spec/mongo/monitoring/server_description_changed_log_subscriber_spec.rb‎

Lines changed: 119 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,119 @@
1+
# frozen_string_literal: true
2+
3+
require 'lite_spec_helper'
4+
5+
describe Mongo::Monitoring::ServerDescriptionChangedLogSubscriber do
6+
let(:subscriber) { described_class.new }
7+
let(:address) { Mongo::Address.new('127.0.0.1:27017') }
8+
9+
let(:primary_config) do
10+
{
11+
'isWritablePrimary' => true,
12+
'secondary' => false,
13+
'setName' => 'rs0',
14+
'hosts' => [ '127.0.0.1:27017' ],
15+
'me' => '127.0.0.1:27017',
16+
'minWireVersion' => 0,
17+
'maxWireVersion' => 21,
18+
'ok' => 1,
19+
}
20+
end
21+
22+
let(:topology) { double('topology') }
23+
24+
before { Mongo::Logger.level = Logger::DEBUG }
25+
after { Mongo::Logger.level = Logger::INFO }
26+
27+
def make_event(prev_desc, new_desc, awaited: false)
28+
Mongo::Monitoring::Event::ServerDescriptionChanged.new(
29+
address, topology, prev_desc, new_desc, awaited: awaited
30+
)
31+
end
32+
33+
context 'when previous and new descriptions are equal' do
34+
let(:prev_desc) { Mongo::Server::Description.new(address, primary_config.dup) }
35+
let(:new_desc) { Mongo::Server::Description.new(address, primary_config.dup) }
36+
37+
it 'does not log' do
38+
expect(subscriber).not_to receive(:log_debug)
39+
subscriber.succeeded(make_event(prev_desc, new_desc))
40+
end
41+
42+
it 'does not log when only excluded heartbeat-noise fields differ' do
43+
old_config = primary_config.merge('localTime' => Time.at(0))
44+
new_config = primary_config.merge('localTime' => Time.at(1000))
45+
prev = Mongo::Server::Description.new(address, old_config)
46+
new_d = Mongo::Server::Description.new(address, new_config)
47+
48+
expect(subscriber).not_to receive(:log_debug)
49+
subscriber.succeeded(make_event(prev, new_d, awaited: true))
50+
end
51+
end
52+
53+
context 'when server_type transitions from unknown to primary' do
54+
let(:prev_desc) { Mongo::Server::Description.new(address, {}) }
55+
let(:new_desc) { Mongo::Server::Description.new(address, primary_config) }
56+
57+
it 'logs the change' do
58+
expect(subscriber).to receive(:log_debug).with(
59+
"Server description for #{address} changed from 'unknown' to 'primary'."
60+
)
61+
subscriber.succeeded(make_event(prev_desc, new_desc))
62+
end
63+
64+
it 'includes the [awaited] suffix when the event is awaited' do
65+
expect(subscriber).to receive(:log_debug).with(
66+
"Server description for #{address} changed from 'unknown' to 'primary' [awaited]."
67+
)
68+
subscriber.succeeded(make_event(prev_desc, new_desc, awaited: true))
69+
end
70+
end
71+
72+
context 'when server_type is identical but a non-excluded field differs' do
73+
let(:prev_desc) do
74+
Mongo::Server::Description.new(address, primary_config.merge('setVersion' => 1))
75+
end
76+
let(:new_desc) do
77+
Mongo::Server::Description.new(address, primary_config.merge('setVersion' => 2))
78+
end
79+
80+
it 'logs the change' do
81+
expect(subscriber).to receive(:log_debug)
82+
subscriber.succeeded(make_event(prev_desc, new_desc))
83+
end
84+
end
85+
86+
context 'when both descriptions are unknown' do
87+
let(:prev_desc) { Mongo::Server::Description.new(address, {}) }
88+
let(:new_desc) { Mongo::Server::Description.new(address, {}) }
89+
90+
it 'still logs (Description#== returns false when either side is unknown)' do
91+
expect(subscriber).to receive(:log_debug).with(
92+
"Server description for #{address} changed from 'unknown' to 'unknown'."
93+
)
94+
subscriber.succeeded(make_event(prev_desc, new_desc))
95+
end
96+
end
97+
98+
context 'when descriptions differ only by legacy hello vs modern hello reply shape' do
99+
let(:prev_desc) do
100+
Mongo::Server::Description.new(address, primary_config.merge(
101+
'ismaster' => true,
102+
'helloOk' => true,
103+
'isWritablePrimary' => nil
104+
))
105+
end
106+
let(:new_desc) do
107+
Mongo::Server::Description.new(address, primary_config.merge(
108+
'isWritablePrimary' => true,
109+
'ismaster' => nil,
110+
'helloOk' => nil
111+
))
112+
end
113+
114+
it 'does not log (one-time protocol switch is not interesting)' do
115+
expect(subscriber).not_to receive(:log_debug)
116+
subscriber.succeeded(make_event(prev_desc, new_desc, awaited: true))
117+
end
118+
end
119+
end

‎spec/mongo/monitoring/topology_changed_log_subscriber_spec.rb‎

Lines changed: 96 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,96 @@
1+
# frozen_string_literal: true
2+
3+
require 'lite_spec_helper'
4+
5+
describe Mongo::Monitoring::TopologyChangedLogSubscriber do
6+
let(:subscriber) { described_class.new }
7+
let(:address) { Mongo::Address.new('127.0.0.1:27017') }
8+
9+
let(:primary_config) do
10+
{
11+
'isWritablePrimary' => true,
12+
'secondary' => false,
13+
'setName' => 'rs0',
14+
'hosts' => [ '127.0.0.1:27017' ],
15+
'me' => '127.0.0.1:27017',
16+
'minWireVersion' => 0,
17+
'maxWireVersion' => 21,
18+
'ok' => 1,
19+
}
20+
end
21+
22+
let(:primary_desc) { Mongo::Server::Description.new(address, primary_config) }
23+
24+
before { Mongo::Logger.level = Logger::DEBUG }
25+
after { Mongo::Logger.level = Logger::INFO }
26+
27+
# Build a topology instance without invoking its initializer (which requires
28+
# a real Cluster). The subscriber only reads `class`, `display_name`, and
29+
# `server_descriptions` on the topology, so this is sufficient.
30+
def fabricate_topology(klass, server_descriptions)
31+
topology = klass.allocate
32+
topology.instance_variable_set(:@server_descriptions, server_descriptions)
33+
topology
34+
end
35+
36+
def make_event(prev_top, new_top)
37+
Mongo::Monitoring::Event::TopologyChanged.new(prev_top, new_top)
38+
end
39+
40+
context 'when topologies have the same class and equal server_descriptions' do
41+
let(:server_descriptions) { { address.to_s => primary_desc } }
42+
let(:prev_top) do
43+
fabricate_topology(Mongo::Cluster::Topology::ReplicaSetWithPrimary, server_descriptions)
44+
end
45+
let(:new_top) do
46+
fabricate_topology(Mongo::Cluster::Topology::ReplicaSetWithPrimary, server_descriptions)
47+
end
48+
49+
it 'does not log' do
50+
expect(subscriber).not_to receive(:log_debug)
51+
subscriber.succeeded(make_event(prev_top, new_top))
52+
end
53+
end
54+
55+
context 'when topologies have the same class but different server_descriptions' do
56+
let(:other_address) { Mongo::Address.new('127.0.0.1:27018') }
57+
let(:other_desc) { Mongo::Server::Description.new(other_address, primary_config) }
58+
59+
let(:prev_top) do
60+
fabricate_topology(
61+
Mongo::Cluster::Topology::ReplicaSetWithPrimary,
62+
{ address.to_s => primary_desc }
63+
)
64+
end
65+
let(:new_top) do
66+
fabricate_topology(
67+
Mongo::Cluster::Topology::ReplicaSetWithPrimary,
68+
{ address.to_s => primary_desc, other_address.to_s => other_desc }
69+
)
70+
end
71+
72+
it 'logs the members-changed message' do
73+
expect(subscriber).to receive(:log_debug).with(
74+
a_string_matching(/There was a change in the members of the '.*' topology\./)
75+
)
76+
subscriber.succeeded(make_event(prev_top, new_top))
77+
end
78+
end
79+
80+
context 'when topology class changes' do
81+
let(:server_descriptions) { { address.to_s => primary_desc } }
82+
let(:prev_top) do
83+
fabricate_topology(Mongo::Cluster::Topology::Unknown, server_descriptions)
84+
end
85+
let(:new_top) do
86+
fabricate_topology(Mongo::Cluster::Topology::ReplicaSetWithPrimary, server_descriptions)
87+
end
88+
89+
it 'logs the type-change message' do
90+
expect(subscriber).to receive(:log_debug).with(
91+
a_string_matching(/Topology type '.*' changed to type '.*'\./)
92+
)
93+
subscriber.succeeded(make_event(prev_top, new_top))
94+
end
95+
end
96+
end

‎spec/mongo/server/description_spec.rb‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -712,6 +712,52 @@
712712
end
713713
end
714714

715+
context 'when one description is from a legacy isMaster reply and the other from a modern hello reply' do
716+
let(:legacy) do
717+
described_class.new(address, replica.merge(
718+
'ismaster' => true,
719+
'helloOk' => true,
720+
'isWritablePrimary' => nil
721+
))
722+
end
723+
724+
let(:modern) do
725+
described_class.new(address, replica.merge(
726+
'isWritablePrimary' => true,
727+
'ismaster' => nil,
728+
'helloOk' => nil
729+
))
730+
end
731+
732+
it 'treats them as equal' do
733+
expect(legacy == modern).to be(true)
734+
end
735+
end
736+
737+
context 'when configs differ only in isWritablePrimary, causing server_type to flip' do
738+
let(:rs_other) do
739+
described_class.new(address, replica.merge(
740+
'ismaster' => nil,
741+
'isWritablePrimary' => false,
742+
'secondary' => false
743+
))
744+
end
745+
746+
let(:promoted) do
747+
described_class.new(address, replica.merge(
748+
'ismaster' => nil,
749+
'isWritablePrimary' => true,
750+
'secondary' => false
751+
))
752+
end
753+
754+
it 'returns false because the server_type changed' do
755+
expect(rs_other.server_type).to eq(:other)
756+
expect(promoted.server_type).to eq(:primary)
757+
expect(rs_other == promoted).to be false
758+
end
759+
end
760+
715761
context 'when one config is a subset of the other' do
716762
let(:one) do
717763
described_class.new(address, { primary_param => true,

0 commit comments

Comments
 (0)