Message delivery tracing is a mechanism for showing details of the process of 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 a message delivery.
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 different state, or message can be sent to different message box. As result a message will not be processed. But how to find a root of such error? Until v.5.5.9 there were no any help from SObjectizer in searching such mistakes.
Message delivery tracing shows main stages of message delivery process. It makes possible to see is there an appropriate subscriber with an appropriate event handler? Since v.5.5.9 you can get a trace of message deliveries during an application run and analyze those traces.
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.
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.
Message delivery tracing mechanism logs the following stages in the message dispatching process:
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.
This section contains a short overview of the data included in message delivery tracing.
An output of example chstate_msg_tracing is used for showing most widespead cases (that example is a part of SObjectizer distribution since v.5.5.9).
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][payload_ptr=0x836450] [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 thread with ID 3 (tid=3). A message is sent to 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 msg_ptr and payload_ptr values shows pointer to message object and pointer to actual payload inside that object.
This message is an instance of user-type message. It is delivered as an envelope of so_5::user_type_message_t type with an instance of greeting_message inside. Because of that there are two tags with pointers.
The first one is a pointer to message envelope (this tag is marked as envelope_ptr). The second one is a pointer to message payload, e.g. to greeting_message instance (this tag is marked as payload_ptr).
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][payload_ptr=0x836450] [state=<DEFAULT>][evt_handler=0x837fe8]
This line tells about searching an event handler for a message.
The search is performed on different thread (tid=2). It is because the search is performing on the context of agent’s working thread.
A pointer to 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 message has been extracted from event queue and passed to the receiver to be processed. The receiver has done 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.
Tags envelope_ptr and payload_ptr has the same meaning as described above.
Tag state shows the name of the current state of the agent. The value "<DEFAULT>" means that the agent is in the default state.
Tag evt_handler shows a pointer to event handler for the messages. In this case that pointer is not null. That means that 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 and payload_ptr tags, 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 and there is no any payload.
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 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][payload_ptr=0x836450] [overlimit_deep=1][agent_ptr=0x8379f0]
All tags are already described above. But it is necessary to note that pointers to the envelope and to the payload 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][payload_ptr=0x836450] [state=state_1][evt_handler=NONE]
Tag state has value "state_1". It is the name of the current state of 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.
This section breifly explains rare traces which can be seen in complex message delivery scenarios.
This line is an example of trace from delivery of service request:
[tid=7][mbox_id=4] deliver_service_request.push_to_queue [msg_type=6finish] [envelope_ptr=0x7db460][signal] [overlimit_deep=1][agent_ptr=0x7d82b0]
There is a slightly different description: deliver_service_request instead of deliver_message.
Service request is delivered as an envelope of some internal SObjectizer’s type. Actual message object (if any) is in that envelope as a payload. Because of that there is tag envelope_ptr. Tag signal is there because a signal is used as a service request. In the case of message as service request tag payload_ptr will be used in a trace.
In the case when there is no subscribers for a message or service request the trace could look like:
[tid=6][mbox_id=4] deliver_service_request.no_subscribers [msg_type=6finish] [envelope_ptr=0x1be3f90][signal] [overlimit_deep=1]
This line shows the case when a message is rejected by a subscriber:
[tid=3][mbox_id=4] deliver_message.message_rejected [msg_type=N8a_test_t9dummy_msgE] [envelope_ptr=0x5b80e0][payload_ptr=0x5b80ec] [overlimit_deep=1][agent_ptr=0x5b72d0]
Message rejection occurs if a message is blocked by a delivery filter defined by a subcriber.
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][payload_ptr=0x7c973c] [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][payload_ptr=0x48a47c] [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 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] [payload_ptr=0x817e5c][overlimit_deep=1][agent_ptr=0x818500] ⇒ [mbox_id=4][msg_type=3bye][envelope_ptr=0x8165f0][payload_ptr=0x816600]
This line shows a transformation of 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][payload_ptr=0x816600] [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 a message delivery.
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 trace. The first one tells about leaving old state. The second one tells about entering into new state. Two lines required because there could be on_exit/on_enter handlers which can send some messages. Two lines simplify the analyzis of such cases.
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 } {} virtual 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" ) ); } );
Wiki: Basics
Wiki: so-5.5 Basics
Wiki: so-5.5.9 Version Info