Package io.mats3.intercept.logging

Class MatsMetricsLoggingInterceptor

java.lang.Object
io.mats3.intercept.logging.MatsMetricsLoggingInterceptor
All Implemented Interfaces:
MatsInitiateInterceptor, MatsInterceptable.MatsLoggingInterceptor, MatsStageInterceptor
public class MatsMetricsLoggingInterceptor extends Object implements MatsInterceptable.MatsLoggingInterceptor, MatsInitiateInterceptor, MatsStageInterceptor
A logging interceptor that writes loglines to two SLF4J loggers, including multiple pieces of information on the MDC (initiatorId, endpointId and stageIds, and timings and sizes), so that it hopefully is easy to reason about and debug all Mats flows, and to be able to use the logging system (e.g. Kibana over ElasticSearch) to create statistics.

Two loggers are used, which are "io.mats3.log.init" and "io.mats3.log.stage". All loglines' message-part is prepended with "#MATSLOG#".

Log lines and their metadata

There are 5 different type of log lines emitted by this logging interceptor - but note that the "Per Message" log line can be combined with the "Initiate Complete" or "Stage Complete" loglines if the initiation or stage only produce a single message - read more at end.
  1. Initiate Complete
  2. Message Received (on Stage)
  3. Stage Complete
  4. Per Created/Sent message (both for initiations and stage produced messages)
  5. Metrics set from the user lambda during initiation and stages
Some MDC properties are set by the JMS implementation, and not by this interceptor. These are the ones that do not have a JavaDoc-link in the below listings.

Note that all loglines that are emitted by any code, user or system, which are within Mats init or processing, will have the follow properties set:

  • "mats.AppName": The app-name which the MatsFactory was created with
  • "mats.AppVersion": The app-version which the MatsFactory was created with
  • Either, or both, of "mats.Init" (set to 'true' on initiation enter, and cleared on exit) and "mats.Stage" (set fixed to 'true' for all Mats Stage processors). If initiation within a stage, both are set.
  • "mats.CallNo": The "Call Number", which starts at 0 for the initiation, and then 1 for first stage processing. (It refers to the "calls", i.e. passed messages.)
  • For Stage processors: "mats.StageId": Set fixed to the stageId for all Mats Stage processors.
  • For Stage processors: "mats.StageIndex": Set fixed to the stage index for all Mats Stage processors - '0' for the initial Stage, '1' for stage1 etc.

MDC Properties for Initiate Complete:

Notice: Initiate Complete is rather similar to Stage Complete.
  • "mats.InitiateCompleted": Present on a single logline per completed initiation - can be used to count initiations. The value is same as "mats.exec.Total.ms", see Metrics below. Assuming each initiation produces one message, and hence one flow, this count should be identical to the count of MDC_MATS_FLOW_COMPLETED. However, an initiation can produce multiple messages (or zero), as described in MDC_MATS_COMPLETE_QUANTITY_OUT, thus if you sum the quantity value of lines that have this property set, the result should actually be identical to flows completed.
  • "mats.InitOrStageId": The initiatorId ("fromId") from the first (typically sole) message in an initiation. It should be common that all messages in a single initiation have the same initiatorId. If there are no sent messages, the value for an initiation will be "_no_outgoing_messages_". This property is also set on the sent messages. For an initiation, this will be identical to "mats.init.Id", see below.
  • "traceId": (Flow prop) Set for an initiation from when it is set in the user code performing the initiation (reset to whatever it was upon exit of initiation lambda)
  • "mats.init.App": (Flow prop) For an initiation, this is the current app, so identical to "mats.AppName".
  • "mats.init.Id": (Flow prop) For an initiation, this will be identical to "mats.InitOrStageId", see above.
  • "mats.Interactive": (Flow prop) This will be the value of the interactive flag of the first (typically sole) message of an initiation. It should be common that all messages in a single initiation have the same value. If there are no sent messages, the value for an initiation will be false.
Metrics for the execution of the initiation (very similar to the metrics for a stage processing): User metrics: Furthermore, any metrics (measurements and timings) set from within an initiation or stage will be available as separate log lines, the metric being set on the MDC. The MDC-key for timings will be "mats.exec.ops.time."+{metricId}+".ms" and for measurements "mats.exec.ops.measure."+{metricId} + '.' + {baseUnit}. If labels/tags are set on a metric, the MDC-key will be {metric MDC-key} + ".tag." + {labelKey}. The name of the constructed metric MDC-key is made available as value of the MDC-key "mats.exec.ops.key", this so that the metrics keys employed can be found more easily by searching for this static key (Elastic have no easy way to find key names in an index using the query language itself). The description of the metric is available under the MDC-key "mats.exec.ops.description".

MDC Properties for Message Received:

  • "mats.MessageReceived": Present on a single logline per received message - can be used to count received messages. This count should be identical to the count of MDC_MATS_STAGE_COMPLETED. The value is the same as "mats.in.TotalPreprocDeserial.ms", see Metrics below.
  • "mats.StageId": Always set on the Processor threads for a stage, so any logline output inside a Mats stage will have this set.
  • "traceId": The Mats flow's traceId, set from the initiation.
  • "mats.in.MsgSysId": The messageId the messaging system assigned the message when it was produced on the sender side (e.g JMSMessageID for the JMS implementation)
  • "mats.in.MatsMsgId": The messageId the Mats system assigned the message when it was produced on the sender side. Note that it consists of the Mats flow id + an individual part per message in the flow.
  • "mats.in.MessageType": The MessageType of the incoming message, for example "SEND", "REQUEST" or "REPLY".
  • "mats.in.from.App": Which app this incoming message is from.
  • "mats.in.from.Id": Which initiatorId, endpointId or stageId this message is from.
  • NOTICE: NOT using "mats.in.to.app", as that is "this" App, and thus identical to "mats.AppName".
  • NOTICE: NOT using "mats.in.to.id", as that is "this" StageId, and thus identical to "mats.StageId".
"Flow properties", i.e. common for all received and sent messages in a Mats flow (initiated, received on stage and sent from stage):
  • "mats.init.App": Which App initiated this Mats flow.
  • "mats.init.Id": The initiatorId of this MatsFlow; matsInitiate.from(initiatorId).
  • "mats.Audit": Whether this Mats flow should be audited.
  • "mats.Interactive": Whether this Mats flow should be treated as "interactive", meaning that a human is actively waiting for its execution.
  • "mats.Persistent": Whether the messaging system should use persistent (as opposed to non-persistent) message passing, i.e. store to disk to survive a crash.
Metrics for message reception (note how these compare to the production of a message, on the "Per Message" loglines):
  • "mats.in.SinceSent.ms": Time taken from message was sent to it was received. This metric gives the queue time, plus any other latency wrt. sending and committing on the sending side and the transfer and reception on the receiving side.This metric is susceptible to time skews between nodes.
  • "mats.in.PrecedEpStage.ms": Time taken from the sending of a message from the Stage immediately preceding this Stage on the same Endpoint, to the reception of a message on this Stage, i.e. the time between stages of an Endpoint (but also between an Initiation REQUEST and the replyTo-reception on the Terminator). This timing includes queue times and processing times of requested endpoints happening in between the send and the receive, as well as any other latencies. For example, it is the time between when EndpointA.Stage2 performs a REQUEST to AnotherEndpointB, till the REPLY from that endpoint is received on EndpointA.Stage3 (There might be dozens of message passing and processings in between those two stages of the same endpoint, as AnotherEndpointB might itself have a dozen stages, each performing some requests to yet other endpoints). This metric is susceptible to time skews between nodes.
  • "mats.in.TotalPreprocDeserial.ms": Total time taken to preprocess and deserialize the incoming message. The same value is present on "mats.MessageReceived", see above.
  • "mats.in.MsgSysDeconstruct.ms": Part of total time taken to pick out the Mats pieces from the incoming message system message.
  • "mats.in.EnvelopeWire.bytes": How big the incoming Mats envelope ("MatsTrace") was in the incoming message system message, i.e. "on the wire".
  • "mats.in.EnvelopeDecompress.ms": Part of total time taken to decompress the Mats envelope (will be 0 if it was sent plain, and > 0 if it was compressed).
  • "mats.in.EnvelopeSerial.bytes": How big the incoming Mats envelope ("MatsTrace") is in its serialized form, after decompression.
  • "mats.in.EnvelopeDeserial.ms": Part of total time taken to deserialize the incoming serialized Mats envelope.
  • "mats.in.DataAndStateDeserial.ms": Part of total time taken to deserialize the data and state objects (DTO and STO) from the Mats envelope.
  • "mats.in.TotalWire.bytes": Best approximation of the total message system wire size (envelope + sideloads + any meta info set on the message). The overhead of the message system itself will probably not be included.
  • "mats.in.StateSerial.bytes": The serialized size of the incoming state object (STO). If there is no incoming state, 0 is returned - this is normal for initial stage of an endpoint, unless an initiation sets initialState. If the serializer employs Strings, the returned value is String.length(), which might not exactly be the number of bytes depending on the String contents.
  • "mats.in.DataSerial.bytes": The serialized size of the incoming data object (DTO). Note that null might not return 0 bytes, depending on how the serializer works. If the serializer employs Strings, the returned value is String.length(), which might not exactly be the number of bytes depending on the String contents.

MDC Properties for Stage Complete:

Notice: Stage Complete is rather similar to Initiate Complete.
  • "mats.StageCompleted": Present on a single logline per completed stage - can be used to count stage processings. This count should be identical to the count of MDC_MATS_MESSAGE_RECEIVED. The value is same as "mats.exec.Total.ms", see Metrics below.
  • "mats.StageId": Always set on the Processor threads for a stage, so any logline output inside a Mats stage will have this set.
  • "mats.ProcessResult": the ProcessResult enum
  • "mats.InitOrStageId": The StageId for the completed stage, thus identical to "mats.StageId". The rationale for having this one more time is so that you can search for it across initiation complete and stage complete, using a common key, as they are rather similar processes. Note that it is also set on message sending.
  • "traceId": (Flow prop) The Mats flow's traceId, set from the initiation.
  • "mats.init.App": (Flow prop) The application that initiated this Mats Flow.
  • "mats.init.Id": (Flow prop) The initiatorId for this Mats Flow, i.e. the value of matsInitiate.from(initiatorId).
  • "mats.Interactive": (Flow prop) The value of the interactive flag for this Mats Flow.
Metrics for the processing of the stage (very similar to the metrics for an initiation execution, but includes metrics for the reception of a message): User metrics: Furthermore, any metrics (measurements and timings) set from an initiation or stage will be available as separate log lines - same as for initiations.

Extra Properties for Endpoint Complete:

When any Stage of an Endpoint (typically the last) either REPLYs, or stops the flow (neither sending a REQUEST, NEXT nor GOTO), the endpoint is completed.
  • "mats.EndpointCompleted": Present on the same single logline as Stage Completed if this also is the endpoint completion. Notice that the span from an initiation REQUEST to the replyTo-reception on a Terminator is also counted as a EndpointCompleted. The value is the time taken from entry on the initial stage of an endpoint, to stage completed on the final stage (or from Initiation REQUEST to replyTo-reception on the Terminator). This metric is susceptible to time skews between nodes.

Extra Properties for Flow Complete:

When a Stage doesn't send any REPLY, REQUEST, NEXT or GOTO, it stops the flow. This is the normal situation for a Terminator, but technically a flow may stop anywhere if the stage doesn't send a flow message.
  • "mats.FlowCompleted": Present on the same single logline as Stage Completed if this also is flow completion. can be used to count mats flows. This count has a very tight relationship with MDC_MATS_INITIATE_COMPLETED, read above. The value is the time taken from the flow was initiated at a MatsInitiator, or from within a flow, to it ends. This metric is susceptible to time skews between nodes.

MDC Properties for Per created Message (both initiations and stage produced messages):

  • "mats.MessageSent": Present on single logline per sent message - can be used to count sent messages. The value is the same as "mats.out.Total.ms", see below.
  • "mats.DispatchType": The DispatchType enum; INIT, STAGE, STAGE_INIT
  • "mats.out.MatsMsgId": The messageId the Mats system gave the message. Note that it consists of the Mats flow id + an individual part per message in the flow.
  • "mats.out.MsgSysId": The messageId that the messaging system gave the message - for the JMS Implementation, it is the JMSMessageId.
  • NOTICE: NOT using "mats.out.from.app", as that is 'this' App, and thus identical to: "mats.AppName".
  • NOTICE: NOT using "mats.out.from.Id", as that is identical to "mats.InitOrStageId".
  • "mats.InitOrStageId": "this" StageId or InitiatorId: Who created this message.
  • "mats.out.to.Id": target EndpointId/StageId
  • NOTICE: NOT using "mats.out.to.app", since we do not know which app will consume it.
"Flow properties", i.e. common for all received and sent messages in a Mats flow (initiated, received on stage and sent from stage):
  • "mats.init.App": Which App initiated this Mats flow.
  • "mats.init.Id": The initiatorId of this MatsFlow; matsInitiate.from(initiatorId).
  • "mats.Audit": Whether this Mats flow should be audited.
  • "mats.Interactive": Whether this Mats flow should be treated as "interactive", meaning that a human is actively waiting for its execution.
  • "mats.Persistent": Whether the messaging system should use persistent (as opposed to non-persistent) message passing, i.e. store to disk to survive a crash.
Metrics for message production (note how these compare to the reception of a message, on the "Message Received" loglines):
  • "mats.out.Total.ms": Total time taken to produce the message, all of the Mats envelope ("MatsTrace"), serializing, compressing and producing the message system message (sum of the below parts). The same value is present on "mats.MessageSent", see above.
  • "mats.out.EnvelopeProduce.ms": Part of the total time taken to produce the Mats envelope ("MatsTrace"), including serialization of all constituents: DTO, STO and any Trace Properties.
  • "mats.out.EnvelopeSerial.ms": Part of the total time taken to serialize the Mats envelope.
  • "mats.out.EnvelopeSerial.bytes": Size of the serialized Mats envelope.
  • "mats.out.EnvelopeCompress.ms": Part of the total time taken to compress the serialized Mats envelope
  • "mats.out.EnvelopeWire.bytes": Size of the compressed serialized Mats envelope.
  • "mats.out.MsgSys.ms": Part of the total time taken to produce and send the message system message.
  • "mats.out.TotalWire.bytes": Best approximation of the total message system wire size (envelope + sideloads + any meta info set on the message). The overhead of the message system itself will probably not be included.
  • "mats.out.DataSerial.bytes": The serialized size of the outgoing data object (DTO). Note that null might not return 0 bytes, depending on how the serializer works. If the serializer employs Strings, the returned value is String.length(), which might not exactly be the number of bytes depending on the String contents.
  • NOTICE: NOT using "mats.out.StateSerial.bytes", as it felt confusing what any outgoing state relates to: It is not the target/receiving stage, as specified in MDC_MATS_OUT_TO_ID. The outgoing state (if any) is a part of the stack, and relates to the next stage of the current endpoint. However, this metric is available on the incoming side, via MDC_MATS_IN_SIZE_STATE_SERIAL.
Note: Both Initiation and Stage completed can produce messages. For the very common case where this is just a single message (a single initiated message starting a Mats flow, or a REQUEST or REPLY message from a Stage (in a flow)), the "Per message" log line is combined with the Initiation or Stage Complete log line - on the message part, the two lines are separated by a "/n", while each of the properties that come with the respective log line either are common - i.e. they have the same name, and would have the same value - or they are differently named, so that the combination does not imply any "overwrite" of a property name. If you search for a property that only occurs on "Per message" log lines (you e.g. want to count, or select, all outgoing message), you will get hits for log lines that are in the "combined" form (e.g. initiation producing a single message), and for log lines for individual messages (i.e. where an initiation produced two messages, which results in three log lines: 1 for the initiation, and 2 for the messages).

Note: This logging interceptor honors the Trace Property MatsInterceptable.MatsLoggingInterceptor.SUPPRESS_LOGGING_TRACE_PROPERTY_KEY and the Endpoint Attribute MatsInterceptable.MatsLoggingInterceptor.SUPPRESS_LOGGING_ENDPOINT_ALLOWS_ATTRIBUTE_KEY. Number of suppressed log outputs per matsFactoryName/initAppName/initiatorId/stageId will be logged every 30 minutes (stageId = "INIT" for initiations), on the LOG_STAGE_NAME logger. The first logging for each combo after logging the number of suppressions will also be logged in full.

Note: This interceptor (SLF4J Logger with Metrics on MDC) has special support in JmsMatsFactory: If present on the classpath, it is automatically installed using the install(MatsInterceptable) install method. This interceptor implements the special marker-interface MatsInterceptable.MatsLoggingInterceptor of which there can only be one instance installed in a JmsMatsFactory - implying that if you want a different type of logging, you may implement a custom variant (either subclassing this, on your own risk, or start from scratch), and simply install it, leading to this instance being removed (or just not have this variant on the classpath).