How to automatically generate a new metric and a new log stream in Service Mesh

One of the advantage of deploying a microservice-based application in an Istio service mesh is to allow one to externally control service monitoring, tracing, request (version) routing, resiliency testing, security and policy enforcement, etc., in a consistent way across those services, for the application as a whole. In this blog we will focus on the in-depth telemetry side of the house and see how can we configure mixer to collect a uniform set of metrics across all services.

At the end of this blog our goal will be to have a new metric and a new log stream enabled for calls to services within our mesh. We are going to use the Bookinfo application as an example.

Minimum Requirements:

This blog post is tested on these versions of the following environments:

• Red Hat OpenShift version 3.11
• Service Mesh version 0.6

Deployment:

The following are the steps to setup this environment :

• On a freshly installed OpenShift 3.11, use this link to enable Service Mesh.
• Once Service Mesh is installed use this link to deploy Bookinfo application.
• Create a new YAML file to hold configuration for the new metric and log stream that Istio will generate and collect automatically.

Save the following as new_telemetry.yaml

# Configuration for metric instances

apiVersion: "config.istio.io/v1alpha2"

kind: metric

metadata:

  name: doublerequestcount

  namespace: istio-system

spec:

  value: "2" # count each request twice

  dimensions:

    reporter: conditional((context.reporter.kind | "inbound") == "outbound", "client", "server")

    source: source.workload.name | "unknown"

    destination: destination.workload.name | "unknown"

    message: '"twice the fun!"'

  monitored_resource_type: '"UNSPECIFIED"'

---

# Configuration for a Prometheus handler

apiVersion: "config.istio.io/v1alpha2"

kind: prometheus

metadata:

  name: doublehandler

  namespace: istio-system

spec:

  metrics:

  - name: double_request_count # Prometheus metric name

    instance_name: doublerequestcount.metric.istio-system # Mixer instance name (fully-qualified)

    kind: COUNTER

    label_names:

    - reporter

    - source

    - destination

    - message

---

# Rule to send metric instances to a Prometheus handler

apiVersion: "config.istio.io/v1alpha2"

kind: rule

metadata:

  name: doubleprom

  namespace: istio-system

spec:

  actions:

  - handler: doublehandler.prometheus

    instances:

    - doublerequestcount.metric

---

# Configuration for logentry instances

apiVersion: "config.istio.io/v1alpha2"

kind: logentry

metadata:

  name: newlog

  namespace: istio-system

spec:

  severity: '"warning"'

  timestamp: request.time

  variables:

    source: source.labels["app"] | source.workload.name | "unknown"

    user: source.user | "unknown"

    destination: destination.labels["app"] | destination.workload.name | "unknown"

    responseCode: response.code | 0

    responseSize: response.size | 0

    latency: response.duration | "0ms"

  monitored_resource_type: '"UNSPECIFIED"'

---

# Configuration for a stdio handler

apiVersion: "config.istio.io/v1alpha2"

kind: stdio

metadata:

  name: newhandler

  namespace: istio-system

spec:

 severity_levels:

   warning: 1 # Params.Level.WARNING

 outputAsJson: true

---

# Rule to send logentry instances to a stdio handler

apiVersion: "config.istio.io/v1alpha2"

kind: rule

metadata:

  name: newlogstdio

  namespace: istio-system

spec:

  match: "true" # match for all requests

  actions:

   - handler: newhandler.stdio

     instances:

     - newlog.logentry

---

• Push the new configuration.

$ oc apply -f new_telemetry.yaml

Created configuration metric/istio-system/doublerequestcount at revision 1973035

Created configuration prometheus/istio-system/doublehandler at revision 1973036

Created configuration rule/istio-system/doubleprom at revision 1973037

Created configuration logentry/istio-system/newlog at revision 1973038

Created configuration stdio/istio-system/newhandler at revision 1973039

Created configuration rule/istio-system/newlogstdio at revision 1973041_**

• Send traffic to the sample application.

export GATEWAY_URL=$(oc get route -n istio-system istio-ingressgateway -o jsonpath='{.spec.host}')

curl -o /dev/null -s -w "%{http_code}\n" http://$GATEWAY_URL/productpage

• Open prometheus GUI and execute query for new metrics "istio_double_request_count".The provided link opens the Prometheus UI and executes a query for values of the “istio_double_request_count” metric

$ export PROMETHEUS_URL=$(oc get route -n istio-system prometheus -o jsonpath='{.spec.host}')

• Last, verify that the logs stream has been created and is being populated for requests. In a Kubernetes environment, search through the logs for the istio-telemetry pod as follows:

[root@bastion ~]# kubectl -n istio-system logs $(kubectl -n istio-system get pods -l istio-mixer-type=telemetry -o jsonpath='{.items[0].metadata.name}') -c mixer | grep \"instance\":\"newlog.logentry.istio-system\"

{"level":"warn","time":"2019-02-08T04:43:31.976519Z",**"instance":"newlog.logentry.istio-system"**,"destination":"policy","latency":"1.057101ms","responseCode":200,"responseSize":69,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:43:31.977266Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"808.716277ms","responseCode":200,"responseSize":5719,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:43:32.982593Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.32436ms","responseCode":200,"responseSize":5,"source":"policy","user":"cluster.local/ns/istio-system/sa/istio-mixer-service-account"}

{"level":"warn","time":"2019-02-08T04:43:33.787423Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.232455ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:43:35.605272Z",**"instance":"newlog.logentry.istio-system"**,"destination":"policy","latency":"994.038µs","responseCode":200,"responseSize":69,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:43:35.606203Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"35.180224ms","responseCode":200,"responseSize":5723,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:43:36.609317Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.362936ms","responseCode":200,"responseSize":5,"source":"policy","user":"cluster.local/ns/istio-system/sa/istio-mixer-service-account"}

{"level":"warn","time":"2019-02-08T04:43:36.642417Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.335828ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:43:37.493269Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"666.29414ms","responseCode":200,"responseSize":4415,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:43:39.160717Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.349926ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:46:08.796142Z",**"instance":"newlog.logentry.istio-system"**,"destination":"policy","latency":"922.414µs","responseCode":200,"responseSize":69,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:46:08.796827Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"42.429966ms","responseCode":200,"responseSize":5723,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:46:09.800069Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.38434ms","responseCode":200,"responseSize":5,"source":"policy","user":"cluster.local/ns/istio-system/sa/istio-mixer-service-account"}

{"level":"warn","time":"2019-02-08T04:46:09.840609Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.180847ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:46:10.255021Z",**"instance":"newlog.logentry.istio-system"**,"destination":"policy","latency":"973.534µs","responseCode":200,"responseSize":69,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:46:10.255948Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"30.521598ms","responseCode":200,"responseSize":5723,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:46:11.007806Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"15.861859ms","responseCode":200,"responseSize":4415,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:46:11.258938Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.287295ms","responseCode":200,"responseSize":5,"source":"policy","user":"cluster.local/ns/istio-system/sa/istio-mixer-service-account"}

{"level":"warn","time":"2019-02-08T04:46:11.288125Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.313989ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:46:12.024992Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.24976ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:47:43.511784Z",**"instance":"newlog.logentry.istio-system"**,"destination":"policy","latency":"1.029831ms","responseCode":200,"responseSize":69,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

{"level":"warn","time":"2019-02-08T04:47:43.512627Z",**"instance":"newlog.logentry.istio-system"**,"destination":"productpage","latency":"33.401581ms","responseCode":200,"responseSize":5719,"source":"istio-ingressgateway","user":"unknown"}

{"level":"warn","time":"2019-02-08T04:47:44.516879Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.257777ms","responseCode":200,"responseSize":5,"source":"policy","user":"cluster.local/ns/istio-system/sa/istio-mixer-service-account"}

{"level":"warn","time":"2019-02-08T04:47:44.546781Z",**"instance":"newlog.logentry.istio-system"**,"destination":"telemetry","latency":"1.048312ms","responseCode":200,"responseSize":5,"source":"unknown","user":"cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account"}

[root@bastion ~]#

Understanding the metrics configurations:

Now lets dig into new_telemetry.yaml. Overall, in this yaml we are instructing Mixer to automatically generate and report a new metric and a new log stream for all traffic within the mesh. Mixer, here, is the control plane component of Red Hat OpenShift Service Mesh which is responsible for enforcing access control and usage policies (such as authorization, rate limits, quotas, authentication, request tracing) and collecting telemetry data from the Envoy proxy and other services.

The added configuration via new_telemetry.yaml controlled three pieces of Mixer functionality:

1. Generation of instances (in this example, metric values and log entries) from Istio attributes
2. Creation of handlers (configured Mixer adapters) capable of processing generated instances
3. Dispatch of instances to handlers according to a set of rules

Now let's look at each of the components inside this new_telemetry.yaml file. There are three stanzas (or blocks) of configuration: instance configuration, handler configuration, and rule configuration. Below stanzas (or blocks) is the instance configuration.

kind: metric

metadata:

name: doublerequestcount

namespace: istio-system

spec:

value: "2" # count each request twice

It defines a schema for generated metric values (or instances) for a new metric named doublerequestcount. This instance configuration tells Mixer how to generate metric values for any given request, based on the attributes reported by Envoy (and generated by Mixer itself).

For each instance of doublerequestcount.metric, the configuration directs Mixer to supply a value of 2 for the instance. Because Istio generates an instance for each request, this means that this metric records a value equal to twice the total number of requests received.

dimensions:

reporter: conditional((context.reporter.kind | "inbound") == "outbound", "client", "server")

source: source.workload.name | "unknown"

destination: destination.workload.name | "unknown"

message: '"twice the fun!"'

monitored_resource_type: '"UNSPECIFIED"'

---

Dimensions as shown above provide a way to slice, aggregate, and analyze metric data according to different needs and directions of inquiry. For instance, it may be desirable to only consider requests for a certain destination service when troubleshooting application behavior.

So, the above configuration instructs Mixer to populate values for these dimensions based on attribute values and literal values. For example, for the source dimension, the new configuration requests that the value be taken from thesource.workload.name attribute. If that attribute value is not populated, the rule instructs Mixer to use a default value of "unknown." For the message dimension, a literal value of "twice the fun!" will be used for all instances.

Now, let's look at the handler configuration (second stanza). It defines a handler named doublehandler. The handler spec configures how the Prometheus adapter code translates received metric instances into Prometheus-formatted values that can be processed by a Prometheus backend. This configuration specified a new Prometheus metric named double_request_count. The Prometheus adapter prepends to be the istio_ namespace to all metric names, therefore this metric will show up in Prometheus as istio_double_request_count.

The metric has three labels matching the dimensions configured for doublerequestcount.metric instances.

For kind: prometheus handlers, Mixer instances are matched to Prometheus metrics via the instance_name parameter. The instance_name values must be the fully-qualified name for Mixer instances (example:doublerequestcount.metric.istio-system).

# Configuration for a Prometheus handler

apiVersion: "config.istio.io/v1alpha2"

kind: prometheus

metadata:

name: doublehandler

namespace: istio-system

spec:

metrics:

- name: double_request_count # Prometheus metric name

instance_name: doublerequestcount.metric.istio-system # Mixer instance name (fully-qualified)

kind: COUNTER

label_names:

- reporter

- source

- destination

- message

---

The rule stanza below defines a new rule named doubleprom. The rule directs Mixer to send all doublerequestcount.metric instances to the doublehandler.prometheus handler. Because there is no match clause in the rule, and because the rule is in the configured default configuration namespace (istio-system), the rule is executed for all requests in the mesh.

# Rule to send metric instances to a Prometheus handler

apiVersion: "config.istio.io/v1alpha2"

kind: rule

metadata:

name: doubleprom

namespace: istio-system

spec:

actions:

- handler: doublehandler.prometheus

instances:

- doublerequestcount.metric

---

Understanding the logs configurations:

The logs configuration below directs Mixer to send log entries to stdout. It uses three stanzas (or blocks) of configuration: instance configuration, handler configuration, and rule configuration.

Let’s first talk about instance configuration.

---

# Configuration for logentry instances

apiVersion: "config.istio.io/v1alpha2"

kind: logentry

metadata:

name: newlog

namespace: istio-system

spec:

severity: '"warning"'

timestamp: request.time

variables:

source: source.labels["app"] | source.workload.name | "unknown"

user: source.user | "unknown"

destination: destination.labels["app"] | destination.workload.name | "unknown"

responseCode: response.code | 0

responseSize: response.size | 0

latency: response.duration | "0ms"

monitored_resource_type: '"UNSPECIFIED"'

---

The kind: logentry stanza of configuration defines a schema for generated log entries (or instances) named newlog. This instance configuration tells Mixer how to generate log entries for requests based on the attributes reported by Envoy.

The severity parameter is used to indicate the log level for any generated logentry. In this example, a literal value of "warning" is used. This value will be mapped to supported logging levels by a logentry handler.

The timestamp parameter provides time information for all log entries. In this example, the time is provided by the attribute value of request.time, as provided by Envoy.

The variables parameter allows operators to configure what values should be included in each logentry. A set of expressions controls the mapping from Istio attributes and literal values into the values that constitute a logentry. In this example, each logentry instance has a field named latency populated with the value from the attribute response.duration. If there is no known value for response.duration, the latency field will be set to a duration of 0ms.

# Configuration for a stdio handler

apiVersion: "config.istio.io/v1alpha2"

kind: stdio

metadata:

name: newhandler

namespace: istio-system

spec:

severity_levels:

warning: 1 # Params.Level.WARNING

outputAsJson: true

---

The kind: stdio stanza of configuration defines a handler named newhandler. The handler spec configures how the stdio adapter code processes received logentry instances. The severity_levels parameter controls how logentryvalues for the severity field are mapped to supported logging levels. Here, the value of "warning" is mapped to the WARNING log level. The outputAsJson parameter directs the adapter to generate JSON-formatted log lines.

# Rule to send logentry instances to a stdio handler

apiVersion: "config.istio.io/v1alpha2"

kind: rule

metadata:

name: newlogstdio

namespace: istio-system

spec:

match: "true" # match for all requests

actions:

- handler: newhandler.stdio

instances:

- newlog.logentry

---

The kind: rule stanza of configuration defines a new rule named newlogstdio. The rule directs Mixer to send all newlog.logentry instances to the newhandler.stdio handler. Because the match parameter is set to true, the rule is executed for all requests in the mesh.

A match: true expression in the rule specification is not required to configure a rule to be executed for all requests. Omitting the entire match parameter from the spec is equivalent to setting match: true. It is included here to illustrate how to use match expressions to control rule execution.

With OpenShift, your cloud, your way

By standardizing on OpenShift, you can focus on the in-depth telemetry side of the house and see how can we configure mixer to collect a uniform set of metrics across all services.

With the help of simple configuration yaml file one can have a new metric and a new log stream enabled for calls to services within mesh.