If you have ever used web interfaces to view logs, you have probably noticed how often these interfaces tend to be bulky and (often) not very convenient or responsive. Some you can get used to, some are downright terrible, but it seems to me that the root of all the problems lies in our approach to log viewing: we try to create a web interface where the command line interface (CLI) works better. Personally, I am very comfortable working with tail, grep, awk, and the like, so for me, the ideal interface for working with logs would be something akin to tail and grep, but usable for reading logs coming from multiple servers. In other words, reading them from ClickHouse, of course!
*in the personal opinion of a Habr user
Meet logscli
I didn't come up with a name for my interface, and to be honest, it mostly exists as a prototype, but if you want to check out the source code right away, welcome: (350 lines of carefully selected code in Go).
Capabilities
I aimed to create an interface that feels familiar to those used to tail/grep, which includes support for the following features:
- Viewing all logs without filtering.
- Retaining lines that contain a fixed substring (flag
-Fatgrep). - Retaining lines that match a regular expression (flag
-Eatgrep). - By default, viewing is in reverse chronological order, since typically, the most recent logs are of most interest.
- Showing context around each line (parameters
-A,-Band-Catgrep, printing N lines before, after, and around each matching line respectively). - Viewing incoming logs in real-time, with filtering and without (essentially
tail -f | grep). - The interface should be compatible with
less,head,tailand others — by default, results should be returned without restrictions on their quantity; lines are printed in a streaming fashion until the user is no longer interested in receiving them; the signalSIGPIPEshould silently interrupt the log streaming, just astail,grepand other UNIX utilities do.
Implementation
I will assume that you already know how to deliver logs to ClickHouse in some way. If you don’t, I recommend trying and , as well as .
First, we need to determine the database schema. Since logs are usually desired to be sorted by time, it makes sense to store them that way. If there are many log categories that are similar, we can use the category of logs as the first column of the primary key—this will allow us to have one table instead of multiple, which will be a significant advantage when inserting into ClickHouse (it is recommended to insert data no more than once every ~1 second on servers with hard drives). for the entire server).
That is, we need approximately the following table schema:
CREATE TABLE logs(
category LowCardinality(String), -- log category (optional)
time DateTime, -- event time
millis UInt16, -- milliseconds (it can be microseconds, etc.): recommended to store if there are many events to easily distinguish between them
..., -- your own fields, such as server name, logging level, etc.
message String -- message text
) ENGINE=MergeTree()
ORDER BY (category, time, millis)Unfortunately, I couldn’t immediately find any open sources with realistic logs that could be downloaded, so instead I used the following as an example: . Their structure is certainly not quite the same as text logs, but for illustration purposes, this is not critical.
instructions for uploading Amazon reviews into ClickHouse
Let's create a table:
CREATE TABLE amazon(
review_date Date,
time DateTime DEFAULT toDateTime(toUInt32(review_date) * 86400 + rand() % 86400),
millis UInt16 DEFAULT rand() % 1000,
marketplace LowCardinality(String),
customer_id Int64,
review_id String,
product_id LowCardinality(String),
product_parent Int64,
product_title String,
product_category LowCardinality(String),
star_rating UInt8,
helpful_votes UInt32,
total_votes UInt32,
vine FixedString(1),
verified_purchase FixedString(1),
review_headline String,
review_body String
)
ENGINE=MergeTree()
ORDER BY (time, millis)
SETTINGS index_granularity=8192The Amazon dataset only contains the review date, but not the exact time, so we will fill in this data randomly.
You don’t need to download all of the tsv files; limiting to the first ~10-20 will give you a sufficiently large dataset that won’t fit into 16 GB of RAM. To upload the TSV files, I used the following command:
for i in *.tsv; do
echo $i;
tail -n +2 $i | pv |
clickhouse-client --input_format_allow_errors_ratio 0.5 --query='INSERT INTO amazon(marketplace,customer_id,review_id,product_id,product_parent,product_title,product_category,star_rating,helpful_votes,total_votes,vine,verified_purchase,review_headline,review_body,review_date) FORMAT TabSeparated'
doneOn a standard Persistent Disk (which is HDD) in Google Cloud with a size of 1000 GB (I chose this size mainly for a bit higher speed, though perhaps the required size of SSD would have come out cheaper), the upload speed was about ~75 MB/sec on 4 cores.
- I must clarify that I work at Google, but I used a personal account and this article has no relation to my work at the company.
I will produce all illustrations with this dataset as it is all I had on hand.
Data scanning progress display
Since in ClickHouse we will use a full scan on the logs table, and this operation can take a significant amount of time and may not return any results quickly if few matches are found, it is preferable to be able to show the progress of the query execution before receiving the first rows with results. For this purpose, the HTTP interface has a parameter that allows returning progress in HTTP headers: send_progress_in_http_headers=1. Unfortunately, the standard Go library does not read headers as they are received, but the HTTP 1.0 interface (do not confuse with 1.1!) is supported by ClickHouse, so you can open a raw TCP connection to ClickHouse, send GET /?query=... HTTP/1.0nn and receive headers and the body of the response without any escaping or encryption, so in this case, we don't even need to use the standard library.
Streaming logs from ClickHouse
ClickHouse has had optimizations for queries with ORDER BY for quite some time now (since 2019?) so a query like
SELECT time, millis, message
FROM logs
WHERE message LIKE '%something%'
ORDER BY time DESC, millis DESCwill start returning rows immediately that have the substring "something" in the message, without waiting for the scanning to finish.
It would also be very convenient if ClickHouse could cancel the query itself when the connection is closed, but this is not the default behavior. Automatic query cancellation can be enabled with the option cancel_http_readonly_queries_on_client_close=1.
Proper handling of SIGPIPE in Go
When you run, say, a command some_cmd | head -n 10, how exactly does the command some_cmd stop its execution when head 10 lines have been read? The answer is simple: when head it completes, the pipe is closed, and the stdout of the some_cmd command starts pointing, conditionally, "to nowhere". When some_cmd it tries to write to a closed pipe, .
In Go, this happens by default as well, but the SIGPIPE signal handler also prints "signal: SIGPIPE" or a similar message in the end. To eliminate this message, we need to handle SIGPIPE ourselves, simply letting it exit quietly:
ch := make(chan os.Signal)
signal.Notify(ch, syscall.SIGPIPE)
go func() {
<-ch
os.Exit(0)
}()Show message context
Often, we want to see the context in which an error occurred (for instance, which request caused the panic, or what related issues were visible before the crash), and for this, grep the options -A, -B, and -C serve, showing the specified number of lines after, before, and around the message respectively.
Unfortunately, I haven't found a simple way to do the same in ClickHouse, so for displaying the context, an additional query is sent for each result row, approximately of the following form (the details depend on the sorting and whether the context is shown before or after):
SELECT time, millis, review_body FROM amazon
WHERE (time = 'EVENT_TIME' AND millis < EVENT_MILLISECONDS) OR (time < 'EVENT_TIME')
ORDER BY time DESC, millis DESC
LIMIT CONTEXT_LINES
SETTINGS max_threads=1Since the query is sent almost immediately after ClickHouse returns the corresponding row, it gets cached, and overall, the query executes fairly quickly, consuming a bit of CPU (usually the query takes around ~6 ms on my virtual machine).
Show new messages in real-time
To display incoming messages in (almost) real-time, simply execute the query every few seconds, remembering the last timestamp we encountered before.
Command examples
What do typical logscli commands look like in practice?
If you loaded the Amazon dataset I mentioned at the beginning of the article, you can run the following commands:
# Показать строки, где встречается слово walmart
$ logscli -F 'walmart' | less
# Показать самые свежие 10 строк, где встречается "terrible"
$ logscli -F terrible -limit 10
# То же самое без -limit:
$ logscli -F terrible | head -n 10
# Показать все строки, подходящие под /times [0-9]/, написанные для vine и у которых высокий рейтинг
$ logscli -E 'times [0-9]' -where="vine='Y' AND star_rating>4" | less
# Показать все строки со словом "panic" и 3 строки контекста вокруг
$ logscli -F 'panic' -C 3 | less
# Непрерывно показывать новые строки со словом "5-star"
$ logscli -F '5-star' -tailfLinks
The utility code (without documentation) is available on github at . I would be happy to hear your thoughts on my idea for a console interface for viewing logs based on ClickHouse.
Source: habr.com
