SO 5.8 InDepth Message Delivery Tracing

What Is It?

Message delivery tracing (or msg_tracing for short) is a mechanism for showing details of the process of a message dispatching and consuming. This mechanism is disabled by default and must be enabled explicitly. When enabled the message delivery tracing shows every important step of message delivery.

Purpose

The main purpose of message delivery tracing is a debugging of an application written on top of SObjectizer-5.

There are many situations where a programmer can make a mistake during event’s subscriptions or message sending: there could not be a subscription for a message, or subscription can be made for a different state, or message can be sent to a different message box. As a result, the message will not be processed. But how to find a root of such error?

Message delivery tracing shows the main stages of the message delivery process. It makes possible to see is there an appropriate subscriber with an appropriate event handler.

Please note that message delivery tracing has a huge performance impact. Because of that message delivery tracing should be enabled for testing and debugging purposes only. Do not enable message delivery tracing in production.

Usage

Message delivery tracing is enabled by passing an instance of so_5::msg_tracing::tracer_t to environment_params during the start of SObjectizer Environment.

There are three functions those create ready to use tracer objects: so_5::msg_tracing::std_cout_tracer(), so_5::msg_tracing::std_cerr_tracer() and so_5::msg_tracing::std_clog_tracer(). They use std::cout, std::cerr and std::clog streams for logging traces.

The easiest way of enabling message delivery tracing is the usage of one of those functions. For example:

so_5::launch( []( so_5::environment_t & env ) {...},
    []( so_5::environment_params_t & params ) {
        params.message_delivery_tracer( so_5::msg_tracing::std_cout_tracer() );
    }
} );

Please note that message delivery tracing can be enabled only at the start of SObjectizer Environment and can't be disabled during the work of the Environment. However, if message delivery tracing is enabled it can be turned off or on.

Features

Message delivery tracing mechanism logs the following stages in the message dispatching process:

absence of subscribers for a message sent to a mbox;
rejection of a message for a particular subscriber (by a delivery filter);
pushing of a message to an event queue for a particular subscriber;
performing a reaction to an overlimit of message’s quantity for a particular subscriber;
searching of an event handler for a message for a particular subscriber;
change the state of an agent.

It is a basic set of information to find a trace of message instance route during delivering and handling. This set can be extended in the future versions of SObjectizer.

How To Read Tracing Data

This section contains a short overview of the data included in message delivery tracing.

Common Cases

An output of example chstate_msg_tracing is used for showing the most widespread cases.

Every trace line contains several tags with values and short stage description. Tags are enclosed in square braces. Stage description is represented in action_name.action_desc form.

The first line from output to review is:

[tid=3][mbox_id=4] deliver_message.push_to_queue
[msg_type=N17a_state_swither_t16greeting_messageE]
[envelope_ptr=0x836440]
[overlimit_deep=1][agent_ptr=0x8379f0]

This line tells about pushing a message to event queue inside deliver_message (short description is deliver_message.push_to_queue). This action takes place at the thread with ID 3 (tid=3). A message is sent to a message box with ID 4 (mbox_id=4). Message type is a_state_switcher_t::greeting_message (its mangled name is in tag msg_type).

Tag with envelope_ptr value shows a pointer to message object.

Tag overlimit_deep shows deep of overlimit actions recursion. Value 1 tells that there is no such recursion and this is the first attempt of message delivery.

Tag agent_ptr shows a pointer to the receiver of the message. The message will be pushed to the event queue of that agent.

The next line to review is:

[tid=2][agent_ptr=0x8379f0] demand_handler_on_message.find_handler
[mbox_id=4][msg_type=N17a_state_swither_t16greeting_messageE]
[envelope_ptr=0x836440]
[state=<DEFAULT>][evt_handler=0x837fe8]

This line tells about searching an event handler for a message.

The search is performed on a different thread (tid=2). It is because the search is performing on the context of the agent’s working thread.

A pointer to the agent is in tag agent_ptr. It is easy to see that this is the same agent as the agent-receiver from the previous trace line. It means that the message has been extracted from the event queue and passed to the receiver to be processed. The receiver has done a search for event handler and the result of that search is shown.

The tags mbox_id shows ID of mbox from which the message has been received.

Tag envelope_ptr has the same meaning as described above.

Tag state shows the name of the current state of the agent. The value "" means that the agent is in the default state.

Tag evt_handler shows a pointer to the event handler for the messages. In this case, that pointer is not null. That means that the event handler is found and the message will be processed.

The next line to review is:

[tid=3][mbox_id=4] deliver_message.push_to_queue
[msg_type=N17a_state_swither_t19change_state_signalE]
[signal]
[overlimit_deep=1][agent_ptr=0x8379f0]

This is a trace of deliver_message operation at the stage of pushing the message to an event queue of an agent-receiver. All tags have been described above but there is no envelope_ptr tag, but there is a [signal] tag. It is because a_state_switcher_t::change_state_signal is a signal. Signals are delivered without actual message objects. Because of that, there is no envelope.

The next line to review is about searching the event handler for change_state_signal:

[tid=2][agent_ptr=0x8379f0] demand_handler_on_message.find_handler
[mbox_id=4][msg_type=N17a_state_swither_t19change_state_signalE]
[signal]
[state=<DEFAULT>][evt_handler=0x837fa8]

It is easy to see that the agent is in the default state and that the event handler for the signal is found.

The next line to review is again about dispatching an instance of greeting_message to an agent-receiver:

[tid=3][mbox_id=4] deliver_message.push_to_queue
[msg_type=N17a_state_swither_t16greeting_messageE]
[envelope_ptr=0x836440]
[overlimit_deep=1][agent_ptr=0x8379f0]

All tags are already described above. But it is necessary to note that pointers to the envelope are the same as in the very first delivery attempt. It is because greeting_message is a periodic message. For periodic messages, the same message envelope is delivered again and again.

The next line shows the case when event handler for a message is not found:

[tid=2][agent_ptr=0x8379f0] demand_handler_on_message.find_handler 
[mbox_id=4][msg_type=N17a_state_swither_t16greeting_messageE]
[envelope_ptr=0x836440]
[state=state_1][evt_handler=NONE]

Tag state has value "state_1". It is the name of the current state of the agent. And tag evt_handler has value "NONE". That value means that there is no event handler for greeting_message in the state "state_1". Because of that, the message will be ignored.

More Special Cases

This section briefly explains rare traces which can be seen in complex message delivery scenarios.

Absence of Subscribers

In the case when there is no subscribers for a message the trace could look like:

[tid=6][mbox_id=4] deliver_message.no_subscribers
[msg_type=6finish]
[signal]
[overlimit_deep=1]

Rejection of a Message

This line shows the case when a message is rejected by the subscriber:

[tid=3][mbox_id=4] deliver_message.message_rejected
[msg_type=N8a_test_t9dummy_msgE]
[envelope_ptr=0x5b80e0]
[overlimit_deep=1][agent_ptr=0x5b72d0]

Message rejection occurs if a message is blocked by a delivery filter defined by the subscriber.

Overlimit Reactions

There are several examples of traces for cases of overlimit reactions.

This is overlimit reaction of type 'abort the application':

[tid=3][mbox_id=4] deliver_message.overlimit.abort
[msg_type=N8a_test_t9dummy_msgE]
[envelope_ptr=0x7c9730]
[overlimit_deep=1][agent_ptr=0x7c98f0]

This trace is done just before aborting the application.

This is overlimit reaction of type 'drop the message':

[tid=3][mbox_id=4] deliver_message.overlimit.drop
[msg_type=N8a_test_t9dummy_msgE]
[envelope_ptr=0x48a470]
[overlimit_deep=1][agent_ptr=0x489f60]

This is overlimit reaction of type 'redirect the message':

[tid=3][mbox_id=5] deliver_message.overlimit.redirect
[msg_type=5hello][signal]
[overlimit_deep=1][agent_ptr=0x5a6af0] ==> [mbox_id=4]

A signal of type 'hello' is redirected from mbox with ID 5 to mbox with ID 4 (destination mbox is shown in tag mbox_id after separator '==>'). The next line in trace shows the result of that redirection: an attempt to deliver that signal via mbox with ID 4 to different subscriber:

[tid=3][mbox_id=4] deliver_message.push_to_queue 
[msg_type=5hello][signal]
[overlimit_deep=2][agent_ptr=0x5a69a0]

Please note value 2 in overlimit_deep tag. This value means that this is the next recursion level in overlimit processing for that signal.

This is overlimit reaction of type 'transform the message':

[tid=3][mbox_id=5] deliver_message.overlimit.transform 
[msg_type=5hello][envelope_ptr=0x817e50]
[overlimit_deep=1][agent_ptr=0x818500] ==>
[mbox_id=4][msg_type=3bye][envelope_ptr=0x8165f0]

This line shows a transformation of a message of type 'hello' from mbox with ID 5 to a message of type 'bye' which is redirected to mbox with ID 4 (information about the new message is in tags after separator '==>'). As result of that transformation there is the next line about dispatching the new message:

[tid=3][mbox_id=4] deliver_message.push_to_queue 
[msg_type=3bye]
[envelope_ptr=0x8165f0]
[overlimit_deep=2][agent_ptr=0x816ac0]

Again a value of overlimit_deep tag shows that this is the next recursion level in overlimit processing of message delivery.

Changing Agent's State

Since v.5.5.15 message delivery tracing also traces changes of agent's state. For example:

[tid=6948][agent_ptr=0x1fdf00ae5d0] state.leaving [state=<DEFAULT>]
[tid=6948][agent_ptr=0x1fdf00ae5d0] state.entering [state=dialog.wait_activity]
[tid=6948][agent_ptr=0x1fdf00ae5d0] state.leaving [state=dialog.wait_activity]
[tid=6948][agent_ptr=0x1fdf00ae5d0] state.entering [state=dialog.number_selection]

Every state change leads to two lines in the trace. The first one tells about leaving the old state. The second one tells about entering into a new state. Two lines required because there could be on_exit/on_enter handlers which can send some messages. Two lines simplify the analysis of such cases.

Writing Own Tracer

A user can write its own implementation of so_5::msg_tracing::tracer_t interface: it is not a hard task because tracer_t contains just one virtual method. For example it is easy to write something like this:

class demo_file_tracer : public so_5::msg_tracing::tracer_t
{
private :
    std::ofstream m_to;
    std::mutex m_lock; // To protect in the case of traces from different threads
    
    std::string make_timestamp() { /* some timestamp-related stuff */ }
    
public :
    demo_file_tracer( const char * file_name ) : m_to{ file_name } {}
    
    void trace( const std::string & msg ) noexcept override
    {
        std::lock_guard< std::mutex > lock{ m_lock };
        m_to << make_timestamp() << ": " << msg << std::endl;
    }
};

This tracer can be set as message delivery tracer during the preparation to the start of SObjectizer Environment:

so_5::launch( []( so_5::environment_t & env ) { ... },
    []( so_5::environment_params_t & params ) {
        params.message_delivery_tracer(
            std::make_unique< demo_file_tracer >( "msg_tracing.log" ) );
    } );

Delivery Tracing Filter

Message Delivery Tracing is very useful for debugging small SObjectizer-based applications. But it is hard to use this mechanism in a large application with a big amount of agents and/or messages: too much information is going to trace and it's hard to analyze it.

To solve this problem there is delivery tracing filter which allows or disables particular trace messages. A user can define its own filter and reduce the number of messages in the trace.

A Role of Delivery Tracing Filter

Inside SObjectizer msg_tracing-filters are handled that way:

A presence of msg_tracing-filter is checked before a new trace message will be formed and passed to the tracer object.
If a msg_tracing-filter is present then it is called for the new trace message. If msg_tracing-filter returns false then trace message will be ignored.

It means that if a user doesn't set msg_tracing-filter then the msg_tracing mechanism will work the usual way: all trace messages are going to tracer object.

But if msg_tracing-filter is present then it is called and its return value is used: if the filter returns true then analyzed trace message is going to tracer object. If filter returns false then analyzed trace message will be ignored and will not be passed to the tracer object.

Possibility to Change Filters After Start of SObjectizer's Environment

Message delivery tracing mechanism can be turned on only before the start of SObjectizer's Environment and can't be turned off when SObjectizer's Environment is running. It's also impossible to change tracer object after the start of SObjectizer's Environment.

But msg_tracing-filter can be changed at any time (while SObjectizer's Environment works). It allows to turn a stream of trace message on or off. For example, we can launch SObjectizer's Environment with disable-all filter which will block all trace messages:

so_5::launch([](so_5::environment_t & env) {...},
   [](so_5::environment_params_t & params) {
      params.message_delivery_tracer(
         so_5::msg_tracing::std_cout_tracer());
      params.message_delivery_tracer_filter(
         so_5::msg_tracing::make_disable_all_filter());
   });

And then we can change this filter to new one (for example to enable-all filter):

void some_agent::on_some_event() {
   // Trace messages can be enabled at this point.
   so_environment().change_message_delivery_tracer_filter(
      so_5::msg_tracing::make_enable_all_filter());
   ...
}

Ready to Use Individual Trace Filter

Since v.5.8.3 there is a individual trace filter that can be used out of the box. It allows to trace delivery of a single message or signal that is sent a special way.

The first thing that a user has to do is to turn message delivery tracing on and set special individual trace filter:

so_5::launch([](so_5::environment_t & env) {...},
   [](so_5::environment_params_t & params) {
      params.message_delivery_tracer(
         so_5::msg_tracing::std_cout_tracer());
      params.message_delivery_tracer_filter(
         so_5::msg_tracing::make_individual_trace_filter());
   });

Then a message/signal to be traced has to be sent this way:

so_5::send< MsgToTrace >( so_5::msg_tracing::individual_trace(dest), ... /* Args for MsgToTrace */);

Actions related to this instance of MsgToTrace will be traced.

The key point is the usage of so_5::msg_tracing::individual_trace function. It makes a special destination that is recognized by the trace filter.

Please note that so_5::msg_tracing::individual_trace can be used for delayed and periodic messages too:

so_5::send_delayed< MsgToTrace >( so_5::msg_tracing::individual_trace(dest), 150ms, ... /* Args for MsgToTrace */);

How to Create Own Filter

There are two ways for the creation of own msg_tracing-filter.

The first one is the hardest. A filter must implement the so_5::msg_tracing::filter_t interface. Because of that an user can derive its own class from filter_t and override filter method. For example:

class my_filter : public so_5::msg_tracing::filter_t {
public:
   ...
   bool filter(
      const so_5::msg_tracing::trace_data_t & td) noexcept override {
      ...
   }
};

An instance of that class must be created dynamically and set as msg_tracing-filter. Form example:

so_5::launch([](so_5::environment_t & env) {...},
   [](so_5::environment_params_t & params) {
      params.message_delivery_tracer(
         so_5::msg_tracing::std_cout_tracer());
      params.message_delivery_tracer_filter(new my_filter{...});
   });

The second way is much easier. A lambda-function can be used as a filter. This function must have a prototype similar to prototype of filter_t::filter() method. For example:

so_5::launch([](so_5::environment_t & env) {...},
   [](so_5::environment_params_t & params) {
      params.message_delivery_tracer(
         so_5::msg_tracing::std_cout_tracer());
      params.message_delivery_tracer_filter(
         so_5::msg_tracing::make_filter(
            [](so_5::msg_tracing::trace_data_t & td) noexcept {
               ...
            }));
   });

Examples of Own Filters

SObjectizer-5.8 contains two examples: selective_msg_tracing and nohandler_msg_tracing which show the usage of msg_tracing-filters.

A Few Words About trace_data_t

There is so_5::msg_tracing::trace_data_t type. This is an interface for accessing the data related to trace message. But note two very important things:

There are different trace messages with different data inside. For example, for some messages we have a pointer to target agent, but we don't have this pointer for other messages. Because of that, all methods of trace_data_t return optional. This optional has value only if the required data is available for the current trace message. Otherwise, it will be an empty optional. Please note also that all pointers and references returned by trace_data_t are valid only inside filter_t::filter() method. Do not store and use them outside -- they can and will be invalidated after return from filter_t::filter() method.
The current version of trace_data_t provides access only for a part of available data. We decided that this part will be a good starting point for msg_tracing-filter functionality. But this part can be extended in some future version of SObjectizer. So if you want to access some data via trace_data_t but have no ability to do that just let us know about this.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly