Navigation
This version of the documentation is archived and no longer supported.

Monitoring

On this page

The driver allows the application to be notified when certain events happen. These events are organized into the following categories:

  • Command monitoring
  • Topology lifecycle
  • Server lifecycle
  • Server heartbeats
  • Connection pools and connections

Topology and server events are part of Server Discovery and Monitoring (SDAM).

Command Monitoring

All user-initiated commands that are sent to the server publish events that can be subscribed to for fine grained information. The monitoring API publishes a guaranteed start event for each command, then either a succeeded or a failed event. A subscriber must implement 3 methods: started, succeeded, and failed, each which takes a single parameter for the event. The following is an example logging subscriber based on a logging subscriber used internally by the driver:

copy 
class CommandLogSubscriber
  include Mongo::Loggable

  def started(event)
    log_debug("#{prefix(event)} | STARTED | #{format_command(event.command)}")
  end

  def succeeded(event)
    log_debug("#{prefix(event)} | SUCCEEDED | #{event.duration}s")
  end

  def failed(event)
    log_debug("#{prefix(event)} | FAILED | #{event.message} | #{event.duration}s")
  end

  private

  def logger
    Mongo::Logger.logger
  end

  def format_command(args)
    begin
      args.inspect
    rescue Exception
      '<Unable to inspect arguments>'
    end
  end

  def format_message(message)
    format("COMMAND | %s".freeze, message)
  end

  def prefix(event)
    "#{event.address.to_s} | #{event.database_name}.#{event.command_name}"
  end
end

To register a custom subscriber, you can do so globally for all clients or on a per-client basis:

copy 
subscriber = CommandLogSubscriber.new

Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::COMMAND, subscriber)

client = Mongo::Client.new([ '127.0.0.1:27017' ], :database => 'test' )
client.subscribe( Mongo::Monitoring::COMMAND, subscriber )

Sample output:

copy 
D, [2018-09-23T13:47:31.258020 #4692] DEBUG -- : COMMAND | 127.0.0.1:27027 | test.hello | STARTED | {"hello"=>1, "$readPreference"=>{"mode"=>"primary"}, "lsid"=>{"id"=><BSON::Binary:0x47111693353080 type=uuid data=0x730341e880dc40a2...>}}
D, [2018-09-23T13:47:31.259145 #4692] DEBUG -- : COMMAND | 127.0.0.1:27027 | test.hello | SUCCEEDED | 0.000791175s

Server Discovery And Monitoring

The Ruby driver implements Server Discovery And Monitoring (SDAM) specification. and makes the following events available to the application:

  • Topology opening
  • Server opening
  • Server description changed
  • Topology changed
  • Server closed
  • Topology closed
  • Heartbeat events (covered below in a separate section)

For all events other than the heartbeat events, the succeeded method will be called on each event subscriber with the event as the sole argument. Available data for events varies, therefore to log the events a separate class is needed for each event type. A simple SDAM logging subscriber can look like the following:

copy 
class SDAMLogSubscriber
  include Mongo::Loggable

  def succeeded(event)
    log_debug(format_event(event))
  end

  private

  def logger
    Mongo::Logger.logger
  end

  def format_message(message)
    format("SDAM | %s".freeze, message)
  end
end

class TopologyOpeningLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    "Topology type '#{event.topology.display_name}' initializing."
  end
end

class ServerOpeningLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    "Server #{event.address} initializing."
  end
end

class ServerDescriptionChangedLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    "Server description for #{event.address} changed from " +
    "'#{event.previous_description.server_type}' to '#{event.new_description.server_type}'."
  end
end

class TopologyChangedLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    if event.previous_topology != event.new_topology
      "Topology type '#{event.previous_topology.display_name}' changed to " +
      "type '#{event.new_topology.display_name}'."
    else
      "There was a change in the members of the '#{event.new_topology.display_name}' " +
      "topology."
    end
  end
end

class ServerClosedLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    "Server #{event.address} connection closed."
  end
end

class TopologyClosedLogSubscriber < SDAMLogSubscriber
  private

  def format_event(event)
    "Topology type '#{event.topology.display_name}' closed."
  end
end

To subscribe to SDAM events globally:

copy 
topology_opening_subscriber = TopologyOpeningLogSubscriber.new
server_opening_subscriber = ServerOpeningLogSubscriber.new
server_description_changed_subscriber = ServerDescriptionChangedLogSubscriber.new
topology_changed_subscriber = TopologyChangedLogSubscriber.new
server_closed_subscriber = ServerClosedLogSubscriber.new
topology_closed_subscriber = TopologyClosedLogSubscriber.new

Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::TOPOLOGY_OPENING,
  topology_opening_subscriber)
Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::SERVER_OPENING,
  server_opening_subscriber)
Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::SERVER_DESCRIPTION_CHANGED,
  server_description_changed_subscriber)
Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::TOPOLOGY_CHANGED,
  topology_changed_subscriber)
Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::SERVER_CLOSED,
  server_closed_subscriber)
Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::TOPOLOGY_CLOSED,
  topology_closed_subscriber)

Subscribing to SDAM events for a single client is a little more involved since the events may be published during the client’s construction:

copy 
topology_opening_subscriber = TopologyOpeningLogSubscriber.new
server_opening_subscriber = ServerOpeningLogSubscriber.new
server_description_changed_subscriber = ServerDescriptionChangedLogSubscriber.new
topology_changed_subscriber = TopologyChangedLogSubscriber.new
server_closed_subscriber = ServerClosedLogSubscriber.new
topology_closed_subscriber = TopologyClosedLogSubscriber.new

sdam_proc = Proc.new do |client|
  client.subscribe(Mongo::Monitoring::TOPOLOGY_OPENING,
    topology_opening_subscriber)
  client.subscribe(Mongo::Monitoring::SERVER_OPENING,
    server_opening_subscriber)
  client.subscribe(Mongo::Monitoring::SERVER_DESCRIPTION_CHANGED,
    server_description_changed_subscriber)
  client.subscribe(Mongo::Monitoring::TOPOLOGY_CHANGED,
    topology_changed_subscriber)
  client.subscribe(Mongo::Monitoring::SERVER_CLOSED,
    server_closed_subscriber)
  client.subscribe(Mongo::Monitoring::TOPOLOGY_CLOSED,
    topology_closed_subscriber)
end

client = Mongo::Client.new(['127.0.0.1:27017'], database: 'test',
  sdam_proc: sdam_proc)

Sample output:

copy 
D, [2018-10-09T13:58:03.489461 #22079] DEBUG -- : SDAM | Topology type 'Unknown' initializing.
D, [2018-10-09T13:58:03.489699 #22079] DEBUG -- : SDAM | Server 127.0.0.1:27100 initializing.
D, [2018-10-09T13:58:03.491384 #22079] DEBUG -- : SDAM | Server description for 127.0.0.1:27100 changed from 'unknown' to 'unknown'.
D, [2018-10-09T13:58:03.491642 #22079] DEBUG -- : SDAM | Server localhost:27100 initializing.
D, [2018-10-09T13:58:03.493199 #22079] DEBUG -- : SDAM | Server description for localhost:27100 changed from 'unknown' to 'primary'.
D, [2018-10-09T13:58:03.493473 #22079] DEBUG -- : SDAM | Server localhost:27101 initializing.
D, [2018-10-09T13:58:03.494874 #22079] DEBUG -- : SDAM | Server description for localhost:27101 changed from 'unknown' to 'secondary'.
D, [2018-10-09T13:58:03.495139 #22079] DEBUG -- : SDAM | Server localhost:27102 initializing.
D, [2018-10-09T13:58:03.496504 #22079] DEBUG -- : SDAM | Server description for localhost:27102 changed from 'unknown' to 'secondary'.
D, [2018-10-09T13:58:03.496777 #22079] DEBUG -- : SDAM | Topology type 'Unknown' changed to type 'ReplicaSetNoPrimary'.
D, [2018-10-09T13:58:03.497306 #22079] DEBUG -- : SDAM | Server 127.0.0.1:27100 connection closed.
D, [2018-10-09T13:58:03.497606 #22079] DEBUG -- : SDAM | Topology type 'ReplicaSetNoPrimary' changed to type 'ReplicaSetWithPrimary'.

# client.close

D, [2018-10-09T13:58:05.342057 #22079] DEBUG -- : SDAM | Server localhost:27100 connection closed.
D, [2018-10-09T13:58:05.342299 #22079] DEBUG -- : SDAM | Server localhost:27101 connection closed.
D, [2018-10-09T13:58:05.342565 #22079] DEBUG -- : SDAM | Server localhost:27102 connection closed.
D, [2018-10-09T13:58:05.342693 #22079] DEBUG -- : SDAM | Topology type 'ReplicaSetWithPrimary' closed.

Note

:sdam_proc client option applies only to the client during whose construction it is given. When certain client options are changed via the Client#with call, a new cluster may be created by the driver with a default set of event subscribers. If this happens, the provided :sdam_proc is not called and the application may miss events.

Server Heartbeats

The application can be notified of each server heartbeat by subscribing to SERVER_HEARTBEAT topic. A server heartbeat listener must implement three methods: started, succeeded and failed. Each heartbeat invokes the started method on the listener, and then either succeeded or failed method depending on the outcome of the heartbeat.

All heartbeat events contain the address of the server that the heartbeat was sent to. Succeeded and failed events contain the round trip time for the hello or legacy hello command. Failed event also contains the exception instance that was raised during hello or legacy hello command execution. Please review the API documentation for ServerHeartbeatStarted, ServerHeartbeatSucceeded and ServerHeartbeatFailed for event attribute details.

The following is an example logging heartbeat event subscriber:

copy 
class HeartbeatLogSubscriber
  include Mongo::Loggable

  def started(event)
    log_debug("#{event.address} | STARTED")
  end

  def succeeded(event)
    log_debug("#{event.address} | SUCCEEDED | #{event.duration}s")
  end

  def failed(event)
    log_debug("#{event.address} | FAILED | #{event.error.class}: #{event.error.message} | #{event.duration}s")
  end

  private

  def logger
    Mongo::Logger.logger
  end

  def format_message(message)
    format("HEARTBEAT | %s".freeze, message)
  end
end

Similarly to command events, the application can subscribe to heartbeat events globally or for a specific client:

copy 
subscriber = HeartbeatLogSubscriber.new

Mongo::Monitoring::Global.subscribe(Mongo::Monitoring::SERVER_HEARTBEAT, subscriber)

client = Mongo::Client.new([ '127.0.0.1:27017' ], :database => 'test' )
client.subscribe( Mongo::Monitoring::SERVER_HEARTBEAT, subscriber )

Sample output:

copy 
D, [2018-09-23T13:44:10.707018 #1739] DEBUG -- : HEARTBEAT | 127.0.0.1:27027 | STARTED
D, [2018-09-23T13:44:10.707778 #1739] DEBUG -- : HEARTBEAT | 127.0.0.1:27027 | SUCCEEDED | 0.000772381s

Heartbeat Event Intervals

When connected to MongoDB 4.2 and earlier servers, Ruby driver by default issues heartbeats every :heartbeat_frequency (Ruby client option) seconds, and heartbeats are non-overlapping (the succeeded event for a heartbeat is guaranteed to be published before the started event for the next heartbeat is published). When connected to MongoDB 4.4 and later servers, the driver uses multiple monitoring threads and a more complex heartbeat protocol designed to detect changes in server state quicker; as a result, heartbeat event intervals can be more irregular and heartbeat events can overlap. Specifically, an awaited heartbeat can start or finish while a non-awaited heartbeat is in progress, and vice versa. Use the ServerHeartbeatStarted#awaited?, ServerHeartbeatSucceeded#awaited? and ServerHeartbeatFailed#awaited? methods to distinguish between non-awaited and awaited heartbeats.

When a client is attempting to perform an operation and it does not have a suitable server, the deployment is scanned more frequently - each server can be polled up to every 500 milliseconds. It is also possible for the application to request a manual scan of a particular server; the driver enforces the 500 millisecond minimum interval between scans.

Connection Pool And Connection Monitoring

Each client maintains a connection pool for each server in the deployment that it is aware of, and publishes events for both connection pools and individual connections. To subscribe to these events, define a subscriber class implementing the method pubished which takes a single parameter for the event that is being published. Note that future versions of the driver may introduce additional events published through this mechanism.

The following events are currently implemented by the driver, following the CMAP specification:

  • PoolCreated
  • PoolCleared
  • PoolClosed
  • ConnectionCreated
  • ConnectionReady
  • ConnectionClosed
  • ConnectionCheckOutStarted
  • ConnectionCheckOutFailed
  • ConnectionCheckOutSucceeded
  • ConnectionCheckedIn

The driver provides a logging subscriber which may be used to log all connection pool and connection-related events. This subscriber is not enabled by default because it will create log entries for each operation performed by the application. To enable this subscriber globally or per client:

copy 
Mongo::Monitoring::Global.subscribe(
  Mongo::Monitoring::CONNECTION_POOL,
  Mongo::Monitoring::CmapLogSubscriber.new)

client = Mongo::Client.new([ '127.0.0.1:27017' ], :database => 'test' )
subscriber = Mongo::Monitoring::CmapLogSubscriber.new
client.subscribe( Mongo::Monitoring::CONNECTION_POOL, subscriber )

Sample output:

copy 
D, [2019-05-06T17:23:21.595412 #8576] DEBUG -- : MONGODB | EVENT: #<PoolCreated address=127.0.0.1:27741 options={...}>
D, [2019-05-06T17:23:21.595584 #8576] DEBUG -- : MONGODB | EVENT: #<PoolCleared address=127.0.0.1:27741>
D, [2019-05-06T17:23:21.603549 #8576] DEBUG -- : MONGODB | EVENT: #<PoolCreated address=localhost:27741 options={...}>
D, [2019-05-06T17:23:21.603616 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionCheckOutStarted address=localhost:27741>
D, [2019-05-06T17:23:21.603684 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionCreated address=localhost:27741 connection_id=1>
D, [2019-05-06T17:23:21.604079 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionCheckedOut address=localhost:27741 connection_id=1>
D, [2019-05-06T17:23:21.605759 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionReady address=localhost:27741 connection_id=1>
D, [2019-05-06T17:23:21.605784 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionCheckedIn address=localhost:27741 connection_id=1>
D, [2019-05-06T17:23:21.605817 #8576] DEBUG -- : MONGODB | EVENT: #<PoolCleared address=localhost:27741>
D, [2019-05-06T17:23:21.605852 #8576] DEBUG -- : MONGODB | EVENT: #<ConnectionClosed address=localhost:27741 connection_id=1 reason=stale>

Disabling Monitoring

To turn off monitoring, set the client monitoring option to false:

copy 
client = Mongo::Client.new([ '127.0.0.1:27017' ], :database => 'test', :monitoring => false )

© MongoDB, Inc 2008-present. MongoDB, Mongo, and the leaf logo are registered trademarks of MongoDB, Inc.