Table of contents
Open Table of contents
Article body
This article is an extension of Shipping Tomcat access_logs from EC2 to ELK with Filebeat and AWS CloudWatch Logs. Why extend it? In the previous article, after Filebeat pulled the logs, they still had to be sent to Logstash for processing. But Logstash’s drawback is that it’s too resource-hungry — nowhere near as lightweight as Filebeat. For this reason, I started trying to use Filebeat to send Tomcat’s access_log directly into Elasticsearch, with a structure that complies with the ECS specification.
Using the dissect processor to destructure the access_log
processors:
- dissect:
tokenizer: '%{client.ip} - - [%{access_timestamp}] %{response_time|integer} %{session_id} "%{http.request.method} %{url_original} %{http.version}" %{http.response.status_code|integer} %{http.response.bytes} "%{http.request.referrer}" "%{user_agent.original}"'
field: "message"
target_prefix: ""
ignore_failure: false
- drop_event:
when:
contains:
# drop PCI scanner http request event
user_agent.original: "AlertLogic"
- if:
contains:
url_original: "?"
then:
- dissect:
tokenizer: "%{path}?%{query}"
field: "url_original"
target_prefix: "url"
else:
- copy_fields:
fields:
- from: url_original
to: url.path
fail_on_error: false
ignore_missing: true
- timestamp:
field: "access_timestamp"
layouts:
- "2006-01-02T15:04:05Z"
- "2006-01-02T15:04:05.999Z"
- "2006-01-02T15:04:05.999-07:00"
test:
- "2019-06-22T16:33:51Z"
- "2019-11-18T04:59:51.123Z"
- "2020-08-03T07:10:20.123456+02:00"
- drop_fields:
fields:
[
"agent",
"log",
"cloud",
"event",
"message",
"log.file.path",
"access_timestamp",
"input",
"url_original",
"awscloudwatch",
"host",
]
ignore_missing: true
- add_tags:
when:
network:
client.ip: [private, loopback]
tags: ["private internets"]
- add_tags:
tags: ["aws_access_log"]
- replace:
when:
contains:
http.response.bytes: "-"
fields:
- field: "http.response.bytes"
pattern: "-"
replacement: "0"
ignore_missing: true
- convert:
fields:
- { from: "http.response.bytes", type: "integer" }
ignore_missing: false
fail_on_error: falseA brief explanation of the configuration above:
- Most fields are named according to the ECS specification, because Filebeat already has all the ECS fields built in by default. There’s no need to work around Logstash’s behavior — where dots cannot be recognized and fields can only be named with underscores. In Filebeat, dots are the default, and a dot is automatically parsed as a nested structure
- Use Condition to process different fields. For ip-type fields, Filebeat automatically parses them into the IP type; use the network condition to tag intranet or local IPs
- When the http.response.bytes field is -, replace it with the string 0, and then convert it to the integer type
Changing the output to Elasticsearch
output.elasticsearch:
hosts: ["elasticsearch:9200"]
username: elastic
password: ${ELASTIC_PASSWORD}Setting the logs as a Data Stream and enabling Index Lifecycle Management (ILM)
Why use a Data Stream?
A data stream lets you store append-only time series data across multiple indices while giving you a single named resource for requests. Data streams are well-suited for logs, events, metrics, and other continuously generated data
From the Data Stream section of the official Elasticsearch documentation For log-type data, the official recommendation is to use a Data Stream
Why use ILM?
Our Elasticsearch storage space is limited, so it’s impossible to keep log data in ES forever. By default we only keep 7 days of log data. To do this, we need ES to automatically clean up expired log data after 7 days. You could write code — start a scheduled task that calls the Elasticsearch API to clean up expired logs. But since ES already provides this tool, I think we can just use it directly instead of programming it ourselves
Configuring ILM for the log data
Official Filebeat documentation on configuring ILM
setup.template.settings:
index.number_of_shards: 1
index.number_of_replicas: 0
setup.ilm.overwrite: true
setup.ilm.policy_file: /usr/share/filebeat/filebeat-lifecycle-policy.jsonThe lifecycle policy JSON file: when the index reaches 5gb or 2 days of age, a rollover is performed. After rollover, the index is deleted once it exceeds 7 days
{
"policy": {
"phases": {
"hot": {
"min_age": "0ms",
"actions": {
"rollover": {
"max_primary_shard_size": "5gb",
"max_age": "2d"
}
}
},
"warm": {
"min_age": "2d",
"actions": {
"readonly": {},
"set_priority": {
"priority": 50
}
}
},
"delete": {
"min_age": "7d",
"actions": {
"delete": {
"delete_searchable_snapshot": true
}
}
}
}
}
}Understanding the lifecycle
-
After data is written to an index, it enters the hot phase
The min_age defaults to 0ms, so new indices enter the hot phase immediately
The above is quoted from the ILM section of the official documentation
-
When max_age or other trigger conditions are met, another index starts being created; this action is called rollover. This action happens in the hot phase, and after rollover the index is still in the hot phase.
The index will roll over once any max_* condition is satisfied and all min_* conditions are satisfied. Note, however, that empty indices are not rolled over by default
When a rollover is triggered, a new index is created
The above is quoted from the ILM section of the official documentation
-
Timing starts after rollover; when the warm phase is configured as 2 days, it means the index enters the warm phase once more than 2 days have passed after the rollover action
-
The warm phase is configured with readonly; after rollover, this index becomes read-only. Before rollover is triggered, it can still be updated
To use the readonly action in the hot phase, the rollover action must be present. If no rollover action is configured, ILM will reject the policy
-
When the delete phase is configured as 7 days, it means the index enters the delete phase once more than 7 days have passed after rollover
-
In summary, after rolling over, the index stays in the hot phase for 2 days; after entering the warm phase, once the warm phase actions have finished executing, it stays in the warm phase for 5 days, and then enters the delete phase and is deleted.
How is min_age calculated in the lifecycle?
The
min_agevalue is relative to the rollover time, not the index creation time.
The above is quoted from the ILM section of the official documentation
The minimum age defaults to zero, which causes ILM to move indices to the next phase as soon as all actions in the current phase complete
How to determine whether an index should move to the next phase?
ILM moves indices through the lifecycle according to their age. To control the timing of these transitions, you set a minimum age for each phase.For an index to move to the next phase, all actions in the current phase must be complete and the index must be older than the minimum age of the next phase
The above is quoted from the ILM section of the official documentation
The Rollover mentioned above is also a kind of action, and can only be configured in the hot phase
How to ensure expired indices are deleted normally?
Q: Why set index.number_of_shards and index.number_of_replicas? A: Because when Elasticsearch cleans up expired indices, the index’s status must be healthy — that is, green. Our ELK is a single-node setup; since it’s only used for querying logs, we think a single node is enough, which is why number_of_replicas is set to 0 here. If the index were yellow, it would remain in ES forever, because it couldn’t be cleaned up.
This explanation can be found in the official documentation
However, because Elasticsearch can only perform certain clean up tasks on a green cluster, there might be unexpected side effects
The index template used here is Filebeat’s default one. If you only have one type of log, the default is sufficient.
For those who want to learn more about ILM, please head over to the Elasticsearch Data Management section and the Concepts > Index lifecycle part under it
Performance Tuning
After the configuration above, you can pull logs from AWS CloudWatch Logs and send them to Elasticsearch.
But during actual testing, I found that the delay between the logs retrieved in ES and the original logs was quite large — basically over 2 minutes — which was unacceptable. So I started tuning
First, I found an article on the Elasticsearch Blog, How to Tune Elastic Beats Performance. The approach in this article helped me a lot.
Configuring Filebeat’s internal queue size
After reading this article, I also referred to Filebeat’s official documentation on the internal queue. In short, Filebeat gets events from the input, but it doesn’t send each event to the output immediately upon receiving it; it waits for a batch of events and then sends them to the output for processing. If the batch size isn’t reached within a period of time, it waits a certain amount of time before sending.
The default for events is 4096, which I think is too small. I also noticed a sentence mentioned in the official documentation
If the queue is full, no new events can be inserted into the memory queue. Only after the signal from the output will the queue free up space for more events to be accepted
If the queue is full, subsequent data can’t get in.
Why do I think the default queue size is set too small for our log volume?
Because we have dozens of servers, and in the input section I configured it to pull logs from AWS once every 10 seconds. By estimating the average number of requests per server and testing repeatedly, I think 12288 is reasonable and sufficient. That is to say, pulling once every 10 seconds yields a data volume of roughly 12288 each time — not too much, and manageable in most cases. This way, each time I pull logs, they can basically all fit into the memory queue, and then be processed immediately without blocking subsequent events from entering the queue
# Reference https://www.elastic.co/guide/en/beats/filebeat/current/configuring-internal-queue.html
# queue.mem.events = number of servers * average requests per second per server * scan_frequency(10s). I think 12288 is more reasonable now
# queue.mem.events = output.worker * output.bulk_max_size
# queue.mem.flush.min_events = output.bulk_max_size
queue.mem:
events: 12288
flush.min_events: 4096
flush.timeout: 1sHow to verify that queue.mem is reasonable and correct?
With the configuration above in place, how can we be sure that the Filebeat side really achieves basically no latency? I first changed the output section to write to a file, and kept observing the file contents and the time Filebeat pulled the logs. Through continuous testing and adjustment, I finally confirmed that with the configuration above, Filebeat pulls logs every 10 seconds and can write the content to the file very quickly. With the default 4096 configuration, however, there was a relatively long delay when writing to the file. Also, during debugging I modified the following registry.flush configuration
# Reduce the frequency of Filebeat refreshing files to improve performance
filebeat.registry.flush: 30sThe reason is
Filtering out a huge number of logs can cause many registry updates, slowing down processing. Setting registry.flush to a value >0s reduces write operations, helping Filebeat process more events
The default refresh is 1 second, which I think is too frequent. So, to avoid the registry file refreshing too fast and affecting Filebeat’s speed, I changed it to 30s
At this point, after verification and debugging, the Filebeat part is finally ensured not to have very large latency
Configuring worker and bulk_max_size in the output section
After finishing the Filebeat-side adjustments, I changed the output section back to Elasticsearch and continued testing, and found there was still relatively large latency. This means it’s time to tune the Elasticsearch part of the output The main principle is
$$ queue.mem.events = workers \times bulk_max_size \tag{1} $$
Make min_events equal to bulk_max_size; this conclusion comes from the official blog mentioned above. According to the official blog’s suggestion, the formula should be as follows
$$ queue.mem.events = 2 \times workers \times batch size \tag{2} \ queue.mem.flush.min_events = batch size $$
But in actual practice, I got lower latency using formula 1; this may have something to do with the specific hardware and memory size.
Also enable compression
So the final configuration of the output section is
output.elasticsearch:
hosts: ["elasticsearch:9200"]
username: elastic
password: ${ELASTIC_PASSWORD}
worker: 3
bulk_max_size: 4096
compression_level: 3Test Results
After the configuration above was complete, I tested again, and also reduced the log-pull interval from 10 seconds to 5 seconds. This time the log latency was between 5s and 15 seconds. This is acceptable. Why do I say it’s acceptable? Because suppose it’s now 4:30:30; the logs Filebeat pulls are from the past 5 seconds, so when you see the 4:30:30 logs in ES, the time is around 4:30:35. So I think it’s acceptable — squeezing out another 1-2 seconds in the end doesn’t mean much.
Final Result
After starting Filebeat, ES, and Kibana with docker compose, you can see logs being written into the ES Data Stream with acceptable latency.
You can see it in Kibana under Index Management > Data Stream. Clicking the index number after it jumps to the corresponding backing index.
When an index exceeds 7 days, it is automatically deleted. When deleting, ES doesn’t delete exactly at the 7-day mark; it may take a few more minutes, because ES deleting an index also requires some operations and time.
Note: If ES encounters an exception when deleting expired indices — such as an out-of-memory error — you can try reducing the index size, configured in the ILM JSON file above. I haven’t strictly verified this suggestion; it’s just that this situation occurred once during my testing, and after I reduced the index size, the error never appeared again, and I never adjusted the parameter back. Those with time can verify it.
Limitations of This Approach
- AWS CloudWatch Logs has limits on requests. If you install multiple Filebeats to pull logs from the CloudWatch Logs of the same account, you may hit the limit if you’re not careful. See Filebeat’s explanation of api_sleep
- Cost: pulling data from CloudWatch Logs to another environment incurs charges
Unresolved Issues
During practice, I found that when Filebeat pulls logs from AWS CloudWatch Logs, a small amount of data is lost — not on every pull, and the amount lost varies. After multiple rounds of troubleshooting, I found no pattern. Losing a small amount of data is currently acceptable for us, so I left it at that. This issue may be related to this issue
Summary
Getting something up and running is only the most elementary part; how to use something well and properly support the scenarios currently needed is what matters most.
If you run into a problem during debugging and have no clue where to start, be sure to look at the server logs — for example, Filebeat’s logs or ES’s logs. Whatever you do, don’t just Google your own requirement, such as why Filebeat latency is very high, because the same requirement faces different scenarios, and the answers given are completely different and may not apply to you.
Most of the key configurations have already been given, so I won’t provide the source code here, since the configurations above are all in filebeat.yml.