Skip to content

Commit

Permalink
Add script to extract metrics from unstructured logs (elastic#32096)
Browse files Browse the repository at this point in the history
* Add script to extract JSON metrics from log files.

* Add reference logs for metrics extraction.

* Add help text and example usage.

* Add a better example with jq.

* Explain how the sed command works.
  • Loading branch information
cmacknz authored Jun 27, 2022
1 parent e612933 commit 111cea0
Show file tree
Hide file tree
Showing 2 changed files with 57 additions and 0 deletions.
42 changes: 42 additions & 0 deletions script/metrics_from_log_file.sh
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
#!/bin/sh
set -e

usage="$(basename "$0") [-h] path_to_beat_log_file
Extracts monitoring metrics from beat log files that are not in structured JSON format.
For log files using structured JSON format, extract metrics with 'grep 'Non-zero' | jq'
where:
-h show this help text
Example:
# Extract all metrics, using jq to show changes in the active event count over time.
# The active event count is the number events in the pipeline, including the the queue.
$(basename "$0") ./sample_logs/log_with_metrics.log | jq \"{timestamp: .timestamp, active: .monitoring.metrics.libbeat.pipeline.events.active}\"
"

while getopts ':h' option; do
case "$option" in
h) echo "$usage"
exit 0;;
*) echo "Unknown option"
exit 1;;
esac
done
shift $((OPTIND - 1))

if [ $# -eq 0 ]; then
echo "No log file to parse."
exit 0
fi

# The command below uses a sed expression to convert the start of a log line like:
# 2022-06-15T14:20:46.928+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring":
# to a JSON line like:
# {"timestamp": "2022-06-15T14:20:46.928+0200", "data": {"monitoring":
# and then uses jq to restore the desired JSON structure of:
# {"timestamp": "2022-06-15T14:20:46.928+0200", "monitoring": {...}
cat "$@" | \
grep 'Non-zero' | \
sed -e 's/^\([0-9T:\.+\-]*\)[^{]*\(.*\)/{"timestamp": "\1", "data": \2}/' | \
jq '{"timestamp": .timestamp, "monitoring": .data.monitoring}'
15 changes: 15 additions & 0 deletions script/sample_logs/log_with_metrics.log
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
2022-06-15T14:20:46.928+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028453},"total":{"ticks":1859828,"value":1859828},"user":{"ticks":831375}},"handles":{"open":247},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774055849},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":13125808,"memory_total":48348409672,"rss":61067264},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":6,"events":{"active":0}}}}}}
2022-06-15T14:21:16.923+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028453},"total":{"ticks":1859843,"time":{"ms":15},"value":1859843},"user":{"ticks":831390,"time":{"ms":15}}},"handles":{"open":247},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774085833},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":13403936,"memory_total":48348687800,"rss":61067264},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":6,"events":{"active":1}}}}}}
2022-06-15T14:21:46.925+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028468,"time":{"ms":15}},"total":{"ticks":1859874,"time":{"ms":31},"value":1859874},"user":{"ticks":831406,"time":{"ms":16}}},"handles":{"open":247},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774115833},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":12373440,"memory_total":48349039968,"rss":61067264},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":6,"events":{"active":2}}}}}}
2022-06-15T14:22:14.059+0200 ERROR [logstash] logstash/async.go:280 Failed to publish events caused by:
2022-06-15T14:22:14.059+0200 INFO [publisher] pipeline/retry.go:219 retryer: send unwait signal to consumer
2022-06-15T14:22:14.059+0200 INFO [publisher] pipeline/retry.go:223 done
2022-06-15T14:22:15.697+0200 ERROR [publisher_pipeline_output] pipeline/output.go:180 failed to publish events: An existing connection was forcibly closed by the remote host.
2022-06-15T14:22:15.697+0200 INFO [publisher_pipeline_output] pipeline/output.go:143 Connecting to backoff
2022-06-15T14:22:15.697+0200 INFO [publisher] pipeline/retry.go:219 retryer: send unwait signal to consumer
2022-06-15T14:22:15.697+0200 INFO [publisher] pipeline/retry.go:223 done
2022-06-15T14:22:15.705+0200 INFO [publisher_pipeline_output] pipeline/output.go:151 Connection to backoff established
2022-06-15T14:22:16.938+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028500,"time":{"ms":32}},"total":{"ticks":1859953,"time":{"ms":79},"value":1859953},"user":{"ticks":831453,"time":{"ms":47}}},"handles":{"open":247},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774145843},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":15905312,"memory_total":48352571840,"rss":63008768},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":2,"active":0,"batches":3,"failed":1,"total":3},"read":{"bytes":2226},"write":{"bytes":2856,"errors":2}},"pipeline":{"clients":6,"events":{"active":0,"published":2,"retry":2,"total":2},"queue":{"acked":2}}}}}}
2022-06-15T14:22:46.933+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028500},"total":{"ticks":1859953,"value":1859953},"user":{"ticks":831453}},"handles":{"open":249},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774175839},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":16322376,"memory_total":48352988904,"rss":63008768},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":6,"events":{"active":100}}}}}}
2022-06-15T14:23:16.929+0200 INFO [monitoring] log/log.go:184 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":1028500},"total":{"ticks":1859968,"time":{"ms":15},"value":1859968},"user":{"ticks":831468,"time":{"ms":15}}},"handles":{"open":247},"info":{"ephemeral_id":"73523d91-7f49-4872-ba79-1cae844b217a","uptime":{"ms":1774205833},"version":"7.17.3"},"memstats":{"gc_next":24458848,"memory_alloc":16658848,"memory_total":48353325376,"rss":62996480},"runtime":{"goroutines":39}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":6,"events":{"active":0}}}}}}

0 comments on commit 111cea0

Please sign in to comment.