Page MenuHomePhabricator

Create an automation against the logs
Open, Needs TriagePublic

Description

Introduction

On the Abstract Wikipedia team, we have our chores, which is our own flavor of "engineering observability rounds". Basically, engineers monitor various sources (like Logstash, Grafana, etc.) to search for anomalies and collect data on the state of our systems. This is usually done once per day.

While the alerts are useful for many of those things, I am trying to automate some of the discovery part of that work (things we do not have alerts for because they are new, or situations that haven't happened before, so we do not have regular alerts to detect them).

 Problem statement

My initial take on this problem is to write a small script to check for some of the errors and warnings in our logs, using the Logstash API and, from there, see what we can do (and what we can't), such as aggregating errors and warnings and, if possible, reporting them somewhere.

Given the restrictions on the log machines, probably that script should be somewhere with access to those machines (I don't know where). What are your thoughts on this? Can you help me with a proper setup for this?

Event Timeline

At a high level the alerting system is coupled to prometheus metrics. For the purposes of generating metrics from log events we support what's called the promethues-es-exporter which executes queries against logs (opensearch) and transforms the results into metrics which can then be used to generate alerts.

Please see https://wikitech.wikimedia.org/wiki/Prometheus#Metrics_from_Logs_(prometheus-es-exporter) as a starting point, and please feel free to add me to any patches!

Hello @herron!

I believe we have used prometheus-es-exporter to alert on log levels before, here is an example. We then disabled this because they got too noisy and now only alert on rules defined here via Grafana.

We're envisioning an automated log digest that queries our logs periodically and posts a rolled-up summary to #aw-alerts — errors and warnings grouped by service, rather than per-event pings. I've started prototyping it in https://gitlab.wikimedia.org/repos/abstract-wiki/logs-reporter.

The output looks like:

Log Digest Report
==================================================
  Source  : ['data/sample_WF_logs.csv', 'data/sample_WL_logs.csv']
  Total   : 15 entries
  Errors  : 3
  Warnings: 12
==================================================

ERROR -- 3 unique message(s)
--------------------------------------------------
  * [function-orchestrator]
    Orchestration failed with unidentified error: Error: Function evaluation failed with status 429: {"status":429,"type":"internal_error","detail":"Rate limit exceeded by rateLimitMiddleware in Evaluator,\n\t\t\tpath: /, method: POST","method":"POST","uri":"/1/v1/evaluate/"}.

  * [function-orchestrator]
    Error while resolving ZID Z32274: Error: Status 503 from wikilambda_fetch (ZIDs <Z32272|Z32274>)
    at ReferenceResolver._fetchZIDs (/srv/service/src/fetchObject.js:423:11)
    at process.processTicksAndRejections (node:internal/process/task_queues:104:5)
...

WARN -- 12 unique message(s)
--------------------------------------------------
  * [mw-wikifunctions.eqiad]
    MediaWiki\Extension\WikiLambda\OrchestratorRequest::orchestrate evaluated response for WikiLambdaFunctionCall:#201fbb78a7dae417453b1a8ec41ef2c207f6cd9f6f590658459083ed3dcd6641 returned HTTP 501

  * [mw-wikifunctions.eqiad]
    MediaWiki\Extension\WikiLambda\OrchestratorRequest::orchestrate evaluated response for WikiLambdaFunctionCall:#88032ac6bf2bd03dd884963b06d1b8d803fefc12b47a1ccf1b30d7e8b47cd865 returned HTTP 504
...

Is this level of detail something that can be done using prometheus-es-exporter as well (and maybe that was your implication!)? Otherwise, how can we configure this to run on a schedule (cron, k8s job, something else), and how should it query the logs (Logstash/Elasticsearch/Kibana seems like the right source)?

I believe we have used prometheus-es-exporter to alert on log levels before, here is an example. We then disabled this because they got too noisy and now only alert on rules defined here via Grafana.

Interesting! Offhand it sounds like there may have been a threshold/query to tune there, if log alerts were firing per event as opposed to once per service-incident.

We're envisioning an automated log digest that queries our logs periodically and posts a rolled-up summary to #aw-alerts — errors and warnings grouped by service, rather than per-event pings. I've started prototyping it in https://gitlab.wikimedia.org/repos/abstract-wiki/logs-reporter.

The output looks like:

Log Digest Report
==================================================
  Source  : ['data/sample_WF_logs.csv', 'data/sample_WL_logs.csv']
  Total   : 15 entries
  Errors  : 3
  Warnings: 12
==================================================

ERROR -- 3 unique message(s)
--------------------------------------------------
  * [function-orchestrator]
    Orchestration failed with unidentified error: Error: Function evaluation failed with status 429: {"status":429,"type":"internal_error","detail":"Rate limit exceeded by rateLimitMiddleware in Evaluator,\n\t\t\tpath: /, method: POST","method":"POST","uri":"/1/v1/evaluate/"}.

  * [function-orchestrator]
    Error while resolving ZID Z32274: Error: Status 503 from wikilambda_fetch (ZIDs <Z32272|Z32274>)
    at ReferenceResolver._fetchZIDs (/srv/service/src/fetchObject.js:423:11)
    at process.processTicksAndRejections (node:internal/process/task_queues:104:5)
...

WARN -- 12 unique message(s)
--------------------------------------------------
  * [mw-wikifunctions.eqiad]
    MediaWiki\Extension\WikiLambda\OrchestratorRequest::orchestrate evaluated response for WikiLambdaFunctionCall:#201fbb78a7dae417453b1a8ec41ef2c207f6cd9f6f590658459083ed3dcd6641 returned HTTP 501

  * [mw-wikifunctions.eqiad]
    MediaWiki\Extension\WikiLambda\OrchestratorRequest::orchestrate evaluated response for WikiLambdaFunctionCall:#88032ac6bf2bd03dd884963b06d1b8d803fefc12b47a1ccf1b30d7e8b47cd865 returned HTTP 504
...

I would recommend visualizations in an opensearch dashboard to present the information above in real time (and historically via the time picker), with supporting alerts to direct people to the dashboard when actionable events occur. For instance, when the rate of logged (errors|warnings) is elevated for a given service. This way state can be understood as alerts fire and resolve, as opposed to a larger report that combines multiple issues (are the errors new? still happening? which ones? etc etc).

That'd be my recommendation, but I'll also unassign myself to make space for others to chime in as well thanks!

I was looking at logstash for warning patterns and spotted one from WikifunctionsClientStore (~9K warnings per 12h). Submitted a fix here: https://gerrit.wikimedia.org/r/c/mediawiki/extensions/WikiLambda/+/1293081

Thank you @herron
That makes sense, being able to see state over time is valuable. We have a normalized_message field in our index as well as message. I'm looking into building a Data Table visualization that aggregates on that field, grouped by service and severity level. Do you (or anyone reading this!) know if there's a way to have it send a periodic Slack summary of those aggregated messages, as a low-friction way to stay informed without active monitoring?

Do you (or anyone reading this!) know if there's a way to have it send a periodic Slack summary of those aggregated messages, as a low-friction way to stay informed without active monitoring?

Unfortunately no. The interface for log data is OpenSearch Dashboards (logstash). Our notifications infrastructure (with the interface to Slack) is based on and triggered by metric data which does not have access to Dashboard or Visualization data.

Alerts are particularly helpful when engineers are expected to respond promptly to correct issues when there is danger of breaching an objective or agreement (c.f. SLOs, SLAs). They are also simple by design and generally link to the Grafana and/or Logstash dashboard for engineers to review and make informed decisions when they fire.

We recommend keeping a human in the loop to view, evaluate, and correct the Dashboards regularly so they do not become out-of-date. Generally, when a team creates a dashboard to track an application's health and performance, SRE also ends up using these Dashboards when performing maintenance that affects the services in question. The chores process outlined in the description is a process used by most teams (including my own) and looks like a great way to both keep your team aware of the health of the services and keep the Dashboards fresh.