Skip to main content
Version: 2.5

Troubleshooting Event Bindings in Kibana

Every run of an event binding is written to the application log as one record. This page describes what the record contains, how to find a particular execution in Kibana, and how to get from a failed request to the matching log lines.

Prerequisites

Records reach Kibana only on deployments where the application logs are shipped there. The queries on this page assume the standard ELK integration (tsm.elk.enabled together with tsm.elk.logstash.url), see Observability and Tracing. When the logs are collected differently, for example from stdout as JSON (tsm.logger.stdoutJson=true), the logger is in the field logger instead of logger_name, and the .keyword sub-fields depend on the index mapping of the log collector. Adjust the field names in the queries accordingly. Viewing logs in Kibana requires access to Kibana itself; the platform only hands out links.

What is logged​

The platform writes one record per binding execution through the logger tsm.automation.execution. To see all of them, filter on that logger:

logger_name : "tsm.automation.execution"

The record is written when the outcome is known:

StatusLevelWhen
SUCCEEDEDINFOThe script finished and the transaction was committed.
FAILEDERRORThe script threw an error. Written immediately and carries the error class and the first line of the message.
ROLLED_BACKWARNThe script finished, but the surrounding transaction was rolled back afterwards (or its outcome could not be determined).

Two consequences follow from this:

  • A successful execution is held back until its transaction completes, so a synchronous binding that ran correctly is still reported as ROLLED_BACK when a later step of the same request fails. When one request shows a FAILED record, other bindings that ran earlier in the same transaction can appear as ROLLED_BACK.
  • Bindings that a changedFields filter rejected never run the script. They are logged with status SKIPPED_CHANGED_FIELDS at DEBUG level only (INFO when the binding has logSkipped enabled), so they are normally not in Kibana.

The full stack trace of a failure is in the FAILED record. The response returned to the caller carries identifiers only (see below); a stack trace is added to it only for users with the authority !Api.Stacktrace.

Fields of the record​

FieldMeaning
tsm.automation.execution.idexecutionId — one run of one binding. A new value for every binding and every event. The primary troubleshooting key.
tsm.automation.event.ideventId — one entity event (for example one update of a ticket). Synchronous bindings of one event pass share the value.
traceIdtraceId — the HTTP request that caused the event. It is the value of the X-Trace-Id response header.
tsm.automation.binding.idId of the binding row in the register Scripts.Bindings.EntityEvents.
tsm.automation.binding.codeCode of the binding row.
spel.scriptCode of the executed script.
tsm.owner.typeEntity type the binding is registered for, for example Ticket.
tsm.owner.idId of the entity that raised the event. Missing when the id is not known.
tsm.automation.operationCREATE, UPDATE or DELETE.
tsm.automation.statusSUCCEEDED, FAILED or ROLLED_BACK.
tsm.automation.duration.msDuration of the script in milliseconds. The same value is in the numeric field tsm.duration.

The record never contains the entity data before or after the change, request or response bodies, or characteristic values.

executionId, eventId and traceId​

The three identifiers answer different questions:

  • executionId — "what exactly happened in this one binding". Use it when you already have an error and want its log record and stack trace.
  • eventId — "which bindings ran for this one event pass". Three synchronous bindings matching one entity change produce three executionIds and one eventId. It does not cover the whole change: asynchronous bindings of the same change get their own eventId, and so do some entity types whose private and public bindings are raised separately (for example Order). To follow one change completely, search by traceId.
  • traceId — "what else happened in this request". It also matches all ordinary application log lines of the request, in all microservices that took part (see X-Trace-Id). One request can raise several events, so one traceId can map to several eventIds. It is the key that connects all bindings of one change.

Asynchronous bindings (async=true) run on a background thread after the commit. The request identifiers are taken over from the originating request, so the record carries the same traceId as the request that made the change.

Finding an execution in Kibana​

Dashboard​

The Kibana dashboard tSM – Automation Executions is built over the tsm.automation.execution records. It shows the number of executions, failures and rollbacks, the duration, the bindings that fail most often or run slowest, and lists of the latest failures and rollbacks with a detail table of all executions.

Click a value in a table or chart (binding, status, entity, operation) to add it as a filter. To search by a specific identifier, type a KQL query into the query bar at the top of the dashboard, see below.

Importing the dashboard​

The dashboard is not created by the platform. It has to be imported into Kibana once per environment: in Kibana open Stack Management → Saved Objects → Import and upload the NDJSON file of the dashboard (provided by the platform team). The id of the imported dashboard must equal tsm.observability.kibana.automation-dashboard-id (default tsm-automation-executions), and it must be imported into the space configured in tsm.observability.kibana.space. Without it the observabilityUrl link leads to a dashboard that does not exist.

KQL queries​

Type these into the query bar of the dashboard or Discover. The dashboard already restricts itself to the tsm.automation.execution logger; in Discover add logger_name : "tsm.automation.execution" yourself (see the prerequisites for other log collectors).

GoalQuery
One execution (from an error)tsm.automation.execution.id : "<executionId>"
All bindings of one entity eventtsm.automation.event.id : "<eventId>"
Everything from one requesttraceId : "<traceId>"
One bindingtsm.automation.binding.code : "<bindingCode>" or tsm.automation.binding.id : "<bindingId>"
One entity (for example a ticket)tsm.owner.type : "Ticket" and tsm.owner.id : "<entityId>"
Failures and rollbackstsm.automation.status : ("FAILED" or "ROLLED_BACK")
Slow executionstsm.duration > 1000
One scriptspel.script : "<scriptCode>"

The dashboard panels themselves use the exact-match variants of the text fields (tsm.automation.status.keyword, tsm.owner.type.keyword and so on). The plain field names above work in the query bar as well.

Quote the values. Identifiers contain hyphens and Kibana would otherwise split them. Put parentheses around or when you combine it with and, otherwise and binds first and changes the result.

From a record to the rest of the request​

The execution record shows which binding failed and why. For everything that happened around it, copy its traceId and search for it without the logger filter:

traceId : "<traceId>"

This returns the ordinary log lines of the request, including the script's own @logger output.

From a failed request to its log record​

A failure of a synchronous binding is returned to the caller as the error AUTOMATION_EXECUTION_FAILED (HTTP 500). The response deliberately does not contain the script, the SpEL position or the internal error message. It carries identifiers only:

{
  "businessCode": "AUTOMATION_EXECUTION_FAILED",
  "traceId": "…",
  "details": {
    "executionId": "…",
    "eventId": "…",
    "bindingCode": "…",
    "observabilityUrl": "https://kibana.example.com/app/dashboards#/view/tsm-automation-executions?_g=…&_a=…" // optional, see below
  }
}

Take details.executionId and search for it as shown above, or use traceId to see the whole request.

Business errors are not automation failures

An error raised on purpose by the script, for example #businessException('CODE', 'message'), is the result of the binding. It is returned unchanged with its own status, business code and message, and it does not become AUTOMATION_EXECUTION_FAILED. The execution is still written to the log with status FAILED.

details.observabilityUrl is a ready-made link to the dashboard. It is available from the 2.4.x release that contains the Kibana link support (the exact version is filled in by the release notes); older 2.4 builds return only the ids. Opening it applies the query tsm.automation.execution.id : "<executionId>" and a time range. The link is present only when both conditions hold:

  1. Kibana is configured for the platform (see the table below).
  2. The signed-in user has the privilege Toolbar.Kibana. Without it the field is not in the response and the client keeps only the ids. On some environments the privilege Toolbar.Kibana does not exist yet and an administrator has to create it first. The parent privilege Toolbar covers it as well.
PropertyDefaultDescription
tsm.observability.kibana.enabledfalseSwitches link generation on. Both enabled and base-url are required.
tsm.observability.kibana.base-url(not set)Address of Kibana, for example https://kibana.example.com. A trailing slash is ignored.
tsm.observability.kibana.spacedefaultId of the Kibana space (not its display name). A space other than default is added to the path as /s/<space>.
tsm.observability.kibana.automation-dashboard-idtsm-automation-executionsId of the dashboard saved object.
tsm.observability.kibana.default-time-range24hTime range of the opened dashboard, counted back from now (now-24h). The value is used as it is and must be a Kibana date-math expression such as 30m or 7d.

The time range is counted from the moment the link is opened, not from the time of the error. A link to an older failure therefore opens an empty dashboard until the range is widened in Kibana.

The link only opens a dashboard. Kibana applies its own access control, and a user who can see the link but has no Kibana account still has to sign in there.

Limits​

  • Retention. Execution records are application logs. They live as long as the log retention of the environment allows and can be lost earlier, for example when the log shipping is down. They are a troubleshooting aid, not an audit trail.
  • Synchronous and asynchronous bindings. A synchronous binding runs in the transaction of the request, so its failure reaches the caller as AUTOMATION_EXECUTION_FAILED. An asynchronous binding runs after the commit on a background thread. Its failure is written to the log as a FAILED record, and the original request has already completed, so Kibana is the only place to learn about it.
  • Filtering by entity. tsm.owner.id is empty for events where the platform does not know the entity id. Fall back to the traceId search in that case.
  • Drilldowns. The dashboard is built without drilldowns (clickable links between panels). Filtering works by clicking a value to add a filter and by typing a KQL query.
  • changedFields and asynchronous bindings. The changed fields of an asynchronous event are not known, so a changedFields filter does not reject it and the script always runs.
  • Nested bindings. When a script changes another entity and a binding of that entity fails, both bindings are logged as FAILED. details.executionId in the response belongs to the outer binding, so the actual cause can be in another record with the same traceId.

See also​