docs/reference/monitoring.txt
**********
Monitoring
**********
.. default-domain:: mongodb
.. contents:: On this page
:local:
:backlinks: none
:depth: 1
:class: singlecol
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:
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:
.. code-block:: ruby
class CommandLogSubscriber
include Mongo::Loggable
def started(event)
# The default inspection of a command which is a BSON document gets
# truncated in the middle. To get the full rendering of the command, the
# ``to_json`` method can be called on the document.
log_debug("#{prefix(event)} | STARTED | #{format_command(event.command.to_json)}")
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:
.. code-block:: ruby
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:
.. code-block:: none
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
.. _sdam:
Server Discovery And Monitoring
===============================
The Ruby driver implements `Server Discovery And Monitoring (SDAM) specification
<https://github.com/mongodb/specifications/tree/master/source/server-discovery-and-monitoring>`_.
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:
.. code-block:: ruby
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:
.. code-block:: ruby
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:
.. code-block:: ruby
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:
.. code-block:: none
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:
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:
.. code-block:: ruby
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:
.. code-block:: ruby
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:
.. code-block:: none
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 <https://github.com/mongodb/specifications/blob/master/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst>`_:
- 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:
.. code-block:: ruby
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:
.. code-block:: none
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``:
.. code-block:: ruby
client = Mongo::Client.new([ '127.0.0.1:27017' ], :database => 'test', :monitoring => false )
Excluded and Redacted Events
============================
The Ruby driver does not pubish, and occasionaly redacts, some events via the
command monitoring mechanism:
1. If the command belongs to a particular subset of redacted commands, or
contains keys that trigger payload redaction, an empty payload will be
provided for security reasons. The full payload can be accessed by setting
the ``MONGO_RUBY_DRIVER_UNREDACT_EVENTS`` environment variable to ``1``, ``true`` or ``yes``. The
following commands are redacted:
- ``authenticate``
- ``saslStart``
- ``saslContinue``
- ``getnonce``
- ``createUser``
- ``updateUser``
- ``copydbgetnonce``
- ``copydbsaslstart``
- ``copydb``
2. If the command is a handshake command, either ``ismaster`` or ``hello``, on
a non-monitoring connection, no event is published at all.
3. Commands sent over monitoring connections (such as ismaster and hello) do
not publish command monitoring events. Instead, every time a server is
checked a server heartbeat event is published. The server heartbeat events
do not include command or reply payloads.
4. If the command is a handshake command, and the ``speculativeAuthenticate``
options is ``true``, the command will be redacted, and an empty payload will
be provided.