Agent Logs
==========

Plugin measurements are collected every one minute and traverse through the following Dynatrace modules:

#. `Plugin Agent`_ - does the data serialization,
#. `OS Agent`_ - does the data aggregation, normalization and verification,
#. Server – does the data storage, visualization and generates alerts.

In this section we will learn, how to get detailed information from modules, that run on monitored host. For server side diagnostics please reference :doc:`error_ui`.

Plugin Agent
------------
Plugin Agent provides detailed plugin development log file: ‘pluginDevLoggerPluginEngineDefault.log’ located on agent machine in “/opt/dynatrace/oneagent/log/plugin” or Windows equivalent “C:\\Program Files (x86)\\dynatrace\\oneagent\\log\\plugin”. The file logs information about all plugins located in ‘plugin_development’ directory. The log delivers diagnostic information about plugin state, plugin configuration, plugin errors, measurements, and properties. Additionally the logger is injected into plugins allowing an author of a plugin to log plugin specific information.

Every log message contains timestamp, log level, thread name, function name, and actual message.

Some examples of messages useful in plugin development are shown below:

* setting configuration::

	2016-04-18 09:32:40,551 INFO 139635534845696(Thread-1) - [event_set_configuration] event_set_configuration, plugin: <PluginEngine, meta_name:myruxit.python.mysql1 id:0x7eff74bbb128> config: {'connection_port': '3306', 'connection_user': 'root', 'connection_password': '########'}

event_set_configuration message is shown whenever plugin's configuration is set (e.g. when plugin agent starts) or changed. It includes the details of configuration (e.g. server port in this example). However passwords are excluded from this log for security reasons (see connection_password field in this example). This log message can be used to check whether appropriate settings are passed to a developed plugin.

* information about running processes (Process snapshot)::

	2016-04-18 13:31:02,147 DEBUG 139635675899648(MainThread) - [_update_latest_snapshot] Latest process snapshot: ProcessSnapshot(host_id=3628148073171719828, entries=[ProcessSnapshotEntry(group_id=3943744791741340845, node_id=0, group_instance_id=18026693943928305163, process_type=9, group_name='MySQL', processes=[ProcessInfo(pid=679, process_name='mysqld_safe', properties={'CmdLine': '/usr/bin/mysqld_safe', 'WorkDir': '/'}), ProcessInfo(pid=1035, process_name='mysqld', properties={'PortBindings': '127.0.0.1_3306', 'CmdLine': '--basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --log-error=/var/log/mysql/error.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306', 'WorkDir': '/var/lib/mysql', 'ListeningPorts': '3306'})], properties={})], containers=[])

Latest process snapshot message is shown whenever Plugin Agent receives information about running processes from OS agent. To activate a plugin, a process entry with matching technology has to be present in process snapshot. This log message can be used to determine what prevents a developed plugin from running.

* information about plugin results (e.g. measurements)::

	2016-04-18 13:37:04,789 DEBUG 139635675899648(MainThread) - [_report_plugin_results] Plugin finished engine=<PluginEngine, meta_name:myruxit.python.mysql1 id:0x7eff74bbb128>, result=WrappedResults(measurements=PluginMeasurementList(timestamp=1460979424786, measurements=[PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:created_tmp_tables', dimensions=[], value=2.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:queries', dimensions=[], value=2.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:connection_errors_max_connections', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:slow_queries', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_update', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_insert', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_delete', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:innodb_data_reads', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_insert_select', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_update_multi', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_delete_multi', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:innodb_data_writes', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_select', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:com_replace_select', dimensions=[], value=0.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:threads_created', dimensions=[], value=3.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:threads_running', dimensions=[], value=1.0, aggregation=1), PluginMeasurement(monitoredEntityId=18026693943928305163, tsIdentifier='myruxit.python.mysql1.dev:innodb_buffer_pool_size', dimensions=[], value=134217728.0, aggregation=1)]))


* information about duplicated plugin package name ::
	
	2017-01-17 10:13:34.774 UTC [e8b3c8b3] info    [native] 140410679965440(MainThread) - [_update_working_set] Plugins {'custom.python.demo_plugin_ui': PluginInfo(name='custom.python.demo_plugin_ui', reported_name='custom.python.demo_plugin_ui', version='1.1', directory='/opt/dynatrace/oneagent/plugin_deployment/custom.python.demo_plugin_ui'  package='demo_plugin_ui')} installation caused errors: [DuplicatedPackageNameException('custom.python.demo_plugin_ui has same package name like custom.python.copy.demo_plugin_ui. User cannot define 2 or more plugins with same package name.',)]
	
User cannot define 2 or more plugins with same package name.


Plugin finished engine message is shown every sampling interval (typically one minute). It includes all plugin results, especially values of reported metrics. It can be used to check whether Plugin Agent sends metrics to OS agent, or whether these metrics have expected values.

OS Agent
--------
OS Agent provides detailed plugin development log file: ‘pluginDevLoggerOsAgentDefault.log’ located on agent machine in “/opt/dynatrace/oneagent/log/plugin” or Windows equivalent “C:\\Program Files (x86)\\dynatrace\\oneagent\\log\\plugin”. The file logs information about all plugins located in ‘plugin_development’ directory. The log delivers diagnostic information allowing to check how plugin data is processed by OS agent and what does the list of running processes, known as process snapshot, look like.
The general format of a message was chosen to allow easy filtering, spotting changes in time domain or between various phases of processing. A typical message is a line of the following format consisting of local timestamp, type of message (each element in square brackets) and log level (in square brackets) followed by an actual message (a string)::

	Timestamp [key element 1][key element 2]...[key element n][log level] message
	
Generally we assume that an actual message is an object composed of properties separated by colons. Each property has a name and a value. Name is a string, might be in quotes if contains spaces or other controlling characters. Value might be

* a string, might be in quotes, escaped by backslash, 
* a number, 
* a set (elements in square brackets separated by commas), 
* another object enclosed in curly brackets.

The log provides the following message types:

* plugin_metrics – information about plugin measurements received from Plugin Agent split into processing phases:

	* after_receiving_from_plugin_agent - raw data received from Plugin Agent, log levels: 1-3
	* before_putting_into_aggregator – data after validation, log levels: 1-3
	
* plugin_timeseries – information about plugin measurements aggregated and normalized by OS Agent and about dropped data, split into categories: 

	* important_pgi_after_aggregator – presents the list of all important entities (PGIs) based on measurements, log levels: 1-3
	* before_filtering_unseen – presents plugin timeseries created as a result of aggregation and important PGI filtering phase, log levels: 1-3
	* filtering_unseen_removed_entities – presents the list of dropped entities (PGIs), log levels: 1
	* filtering_unseen_pgi_sent_in_osi – presents the list of important entities (PGIs) based on topology – should be the same as important_pgi_after_aggregator, log levels: 1
	* before_sending – presents timeseries just before sending to Dynatrace Cluster Node, log levels: 1-3
	
* process_snapshot – list of process group sent from OS Agent to Plugin Agent

	* before_sending, log levels: 1

To see data coming from Plugin Agent to OS Agent one should analyze messages plugin_metrics from after_receiving_from_plugin_agent phase. They are reported on 3 levels:

* Level 1 shows only statistics about all received measurements: all_metrics_count and and a number of measurements coming from plugins under development: selected_metrics_count - plugins under development, example::

	2016-03-15 22:39:53.145 [osagent][plugin_metrics][after_receiving_from_plugin_agent][1] { all_metrics_count=53; selected_metrics_count=2 }
* On level 2 we can see entities (plugins) with their IDs, application types, and names (where available)::

	2016-03-15 22:49:53.146 [osagent][plugin_metrics][after_receiving_from_plugin_agent][2] { only_entities=[  { key=entityid=fbf6d716f2c17fbf ; name="oneagent_sdk.demo_app_auth" ; type="Python" }  ] }
* On level 3 we can also see metrics: type, id, name, aggregation type, timestamp and value::

	2016-03-15 22:49:53.146 [osagent][plugin_metrics][after_receiving_from_plugin_agent][3] { metrics=[  { key=metricType="custom.python.demo_plugin_auth.dev:counter" ; key=entityid=fbf6d716f2c17fbf ; name="oneagent_sdk.demo_app_auth" ; type="Python" ; senderid=-923034125 ; aggregation_type="aggregationType_average" ; value=1 ; timestamp_ms=1458078629553 },  { key=metricType="custom.python.demo_plugin_auth.dev:random" ; key=entityid=fbf6d716f2c17fbf ; name="oneagent_sdk.demo_app_auth" ; type="Python" ; senderid=-923034125 ; aggregation_type="aggregationType_average" ; value=215 ; timestamp_ms=1458078629553 }  ] }


The most interesting messages are plugin_timeseries in phase before_sending – presents plugin measurements after all normalization and filtering and just before being sent to the server.  They are reported on 3 log levels:

* Level 1 includes only information about a number of all_entities_count , i.e. working plugins delivering some measurements, and a number of selected_entities_count , i.e. plugins selected to monitor - plugins under development, example::

	2016-03-15 22:28:43.318 [osagent][plugin_timeseries][before_sending][1] { reported_timestamp_ms= 1458077280000 ; all_entities_count=3; selected_entities_count=1 }
* On level 2 we can see entities with their IDs, application types, and PGI names (where available)::

	2016-03-15 22:28:43.318 [osagent][plugin_timeseries][before_sending][2] { reported_timestamp_ms= 1458077280000 ; entities=[  { key=entityid=fbf6d716f2c17fbf ; name="oneagent_sdk.demo_app_auth" ; type="Python" }  ] }
* On level 3 we can also see all metrics sent in timeseries with their values::
	
	2016-03-15 22:28:43.318 [osagent][plugin_timeseries][before_sending][3] { reported_timestamp_ms= 1458077280000 ; entities=[  { key=entityid=fbf6d716f2c17fbf ; name="oneagent_sdk.demo_app_auth" ; type="Python" ; measures=[  { key=metricType="custom.python.demo_plugin_auth.dev:counter" ; count=1 ; min=1 ; max=1 ; sum=1 ; average=1 },  { key=metricType="custom.python.demo_plugin_auth.dev:random" ; count=1 ; min=872 ; max=872 ; sum=872 ; average=872 }  ] }  ] }

Some measurements may be dropped mainly because of communication problems or because monitored process group (PGI) is not considered as important. 
The list of not important PGIs may be taken by comparing the list of metrics before aggregation::

	grep before_putting_into_aggregator   pluginDevLoggerOsAgentDefault.log | grep "\[3\]"

with the list of metrics after aggregation::

	grep before_filtering_unseen   pluginDevLoggerOsAgentDefault.log | grep "\[3\]"

Other reason for dropping timeseries is that a PGI is not seen in topological data, the list of such entities can be taken from messages filtering_unseen_removed_entities.

The last message type is process_snapshot, which presents detailed information about processes running on monitored host. This information is sent from OS Agent to Plugin Agent and it’s used by Plugin Agent to activate certain plugin. To filter out the last process snapshot use the following bash command::

	cat pluginDevLoggerOsAgentDefault.log | grep process_snapshot | tail -1 | sed 's/{ groupid=/\n{groupid=/g'

result should be similar to this::

	{groupid=afd123e514ad04f5 ; groupname="oneagent_sdk.demo_app_auth" ; groupinstanceid=fbf6d716f2c17fbf ; processtype="PROCESS_TYPE_PYTHON" ; processes=[  { pid=14813 ; processname="python3.5" ; processagentinjected=0 ; properties=[  "WorkDir"="/usr/local/lib/python3.5/dist-packages/oneagent_sdk",  "CmdLine"="-m oneagent_sdk.demo_app_auth -p 8082",  "ListeningPorts"="8082",  "Bindings"="127.0.0.1,8082"] }] },


