, ,

Log Analysis and Clustering at Scale for Infra Telemetry (Infra to Data Science Series, Part 23)

Clustering raw log lines fails because ids and timestamps make every message unique. Mine templates with Drain3 first, then cluster the structure, and a day of logs collapses to a triage table you can read in a minute.

Infra to Data Science Series · Part 23 of 26

Fifty thousand log lines from one day on one cluster carry thirteen distinct sentences. Everything else in them is a timestamp, an IP, or an id that never repeats. Miss that and every clustering tool you reach for drowns in the noise. See it and a day of logs collapses to a table you can read in a minute. This part takes the same telemetry the last one forecast and turns to its messiest signal, raw logs, pulling structure out of them without a single label.

Who this is for: An infrastructure engineer or SRE who can grep a log file in their sleep and wants to turn that reflex into something a model can use. Terms on first use: a log template is the fixed skeleton of a message with the variable parts blanked out; template mining discovers those skeletons from raw lines; tokenization splits a line into words; TF-IDF, term frequency times inverse document frequency, scores a word by how rare it is across lines; a hapax is a token that appears exactly once; clustering groups similar rows without labels; cosine distance measures the angle between two sparse vectors rather than their straight line gap. Where the project stands: last part fit a capacity forecast to the exported metrics, and this part keeps the same cluster and reads its logs.
Key takeaways: Raw log lines break bag of words clustering because ids, ips and timestamps blow the vocabulary up. On a day of 50,000 lines a plain TF-IDF fit produced 11,026 features, 72 percent of them appearing exactly once, and k-means buried the 189 failure lines inside a 5,063 line cluster of routine messages. Mine templates first with Drain3, which collapsed the same file to 13 patterns in 0.21 seconds and put each rare failure in its own cluster of about sixty. When you do reach for geometric clustering, keep the matrix sparse and cluster on cosine distance, never euclidean, which labelled every template noise. Keep one artifact from this part: a summarise_logs function that returns a triage table of template, count, share and severity.

High Cardinality Tokens Break Log Clustering

Reaching for TfidfVectorizer and k-means is the reflex a fresh data science course leaves you with, and it is the recipe every text clustering tutorial teaches. It fails on logs for a reason those tutorials never hit: a news article reuses its vocabulary, a log line does not. Every request id, ip address and latency value is a fresh token that appears once and never again, so the feature space fills with noise that swamps the handful of words carrying meaning. Every line was run against python 3.10.12, scikit-learn 1.7.2, pandas 2.3.3, numpy 2.2.6 and drain3 0.9.11.

# tested with python 3.10.12, scikit-learn 1.7.2, pandas 2.3.3, numpy 2.2.6, drain3 0.9.11
import pandas as pd, numpy as np
from sklearn.feature_extraction.text import TfidfVectorizer
from sklearn.cluster import KMeans

raw = pd.Series(open('cluster.log').read().splitlines())
msgs = raw.str.split(n=3).str[3]            # drop timestamp host severity, keep free text

vec = TfidfVectorizer()
X = vec.fit_transform(msgs)
df = np.asarray((X > 0).sum(axis=0)).ravel()
hapax = int((df == 1).sum())
print('vocabulary', X.shape[1], 'appear once', hapax, round(100 * hapax / X.shape[1], 1), 'percent')

km = KMeans(n_clusters=12, random_state=0, n_init=10).fit(X)
fatal = msgs.str.startswith('FATAL')
home = pd.Series(km.labels_)[fatal].mode()[0]
print('FATAL lines', int(fatal.sum()), 'buried in a cluster of', int((km.labels_ == home).sum()))
vocabulary 11026 appear once 7936 72.0 percent
FATAL lines 189 buried in a cluster of 5063

Read those two numbers together. A vocabulary of 11,026 from thirteen real message types, with 7,936 tokens appearing exactly once, means roughly seven in ten features are pure noise from ids and addresses. K-means then spends its distance budget separating lines by which random id they happen to share, not by what happened. Cost lands where it hurts most: the 189 FATAL lines, the only ones worth paging on, scatter into a cluster of 5,063 routine messages instead of standing alone. You ran a model, waited, and learned nothing an alert could act on.

Stripping the structured prefix, the timestamp, host and severity, before vectorising helps a little and is worth doing. It does not touch the real problem, which lives in the free text itself where the ids hide. A better vectoriser will not save you and neither will more clusters. What fixes it is collapsing the variable parts before you count anything.

Template Mining With Drain3

Drain3 is a streaming log template miner. It reads lines one at a time and grows a fixed depth tree of templates, matching each new line to an existing skeleton or starting a new one, so it never holds a growing vocabulary in memory. Where TF-IDF treats connection to 10.0.1.5 and connection to 10.0.2.9 as two different points, Drain3 folds both into connection established to a wildcard and counts them as one pattern. Its README states the one rule that matters: feed it the free text only, with the timestamp and host stripped, or the fixed columns pollute the templates.

from drain3 import TemplateMiner
from drain3.template_miner_config import TemplateMinerConfig
import time

tm = TemplateMiner(config=TemplateMinerConfig())
t = time.time()
for line in msgs:
    tm.add_log_message(line)                 # one streaming pass, learns as it goes
dt = time.time() - t
print('templates', len(tm.drain.clusters), 'in', round(dt, 2), 's',
      round(len(msgs) / dt), 'lines per second')
for c in sorted(tm.drain.clusters, key=lambda c: c.size)[:3]:
    print('rare id', c.cluster_id, 'size', c.size, '::', c.get_template())
templates 13 in 0.21 s 234346 lines per second
rare id 11 size 60 :: WARN request <*> timed out after <*> to <*>
rare id 12 size 62 :: ERROR etcd leader election lost on <*> term <*>
rare id 13 size 67 :: FATAL out of memory killing pod <*> on <*>

Thirteen templates, in a fifth of a second, at 234,000 lines a second on one core. That is the same file the TF-IDF fit needed 11,026 features to mangle. Every routine event is one row now, and the three failure types planted in the data, the WARN timeout, the ERROR election loss and the FATAL out of memory kill, each sit in their own cluster of about sixty lines. Rare events that k-means lost are the ones template mining surfaces first, because rarity becomes obvious the moment every line of a kind collapses to one counted pattern.

A second property matters more at scale than the raw speed. Drain3 learns online, so it needs no training corpus and no second pass. Point it at a live tail and it names new templates as they arrive, which is exactly the shape of a log stream during an incident, when a message you have never seen before is the one you need to find.

flowchart LR
  R[Raw log line] --> S[Strip timestamp host severity]
  S --> D[Drain3 template mining]
  D --> I[Cluster id per line]
  I --> C[Count by template]
  I --> H[Hashing plus MiniBatchKMeans]
  C --> T[Triage table]
  H --> T
Mine templates first, then branch: count patterns for triage, or vectorise for geometry when a model needs it.

Bounding Memory on an Unbounded Stream

A day of logs fits in memory. A quarter of logs from a fleet does not, and a live stream has no end at all. Drain3 holds one thing that can grow without bound, the set of templates it has learned, so on an endless stream that set is what you cap. One config field does it.

cfg = TemplateMinerConfig()
cfg.drain_max_clusters = 8                    # LRU cap for an unbounded stream
tm = TemplateMiner(config=cfg)
for line in msgs:
    tm.add_log_message(line)
print('clusters kept under the cap', len(tm.drain.clusters))
clusters kept under the cap 8

With drain_max_clusters set, the miner keeps only the most recently seen templates and evicts the least recently used when the cap is hit, so memory stays flat however long the stream runs. A trap hides in that convenience, and it is the rare events again. Set the cap below the true number of templates and the failure patterns, which by definition arrive rarely, are first to be evicted between their appearances, so the miner forgets the FATAL skeleton in the quiet hours and relearns it as new each time it fires. Size the cap above your steady state template count with headroom, not tight against it. This cluster wants a cap in the low hundreds; the eight above demonstrates eviction, it is not a setting to copy.

Geometric Clustering Without a Vocabulary

Template mining answers most log questions on its own. Some need real geometry though, grouping templates by similarity or feeding log features to a model that expects vectors. Scikit-learn handles that at scale with a HashingVectorizer, which hashes each token to a fixed set of columns instead of building a dictionary. It is stateless, storing nothing during fit, so it takes an unbounded stream of new tokens without its memory growing. Pair it with MiniBatchKMeans, which updates centroids on small batches rather than the whole matrix at once. The Data Science Series works the mechanics of turning text into vectors in its piece on bag of words and transformers, so one line covers it here: hashing trades the ability to read a feature back for bounded memory, a trade worth making on logs.

from sklearn.feature_extraction.text import HashingVectorizer
from sklearn.cluster import MiniBatchKMeans

hv = HashingVectorizer(n_features=2**14, alternate_sign=False, norm='l2')
Xh = hv.transform(msgs)                       # stateless: nothing stored, no vocabulary
print('shape', Xh.shape, 'has vocabulary_', hasattr(hv, 'vocabulary_'))

mbk = MiniBatchKMeans(n_clusters=13, random_state=0, n_init=3, batch_size=4096).fit(Xh)
print('minibatch clusters', len(set(mbk.labels_)))
shape (50000, 16384) has vocabulary_ False
minibatch clusters 13

Sixteen thousand columns, no vocabulary held, and the batches never load the full matrix. That is the shape of clustering you can run on a stream that does not fit in memory. One rule holds it together, and breaking it is the failure waiting here: the matrix must stay sparse. A hashed log matrix is more than 99 percent zeros, and the moment you densify it to satisfy a model that wants a plain array, it stops being cheap.

Xh.toarray()
MemoryError: Unable to allocate 6.10 GiB for an array with shape (50000, 16384) and data type float64
Production gotcha: Six gigabytes for one day of one cluster, because a sparse matrix of 360,000 nonzeros became a dense one of 819 million cells. MiniBatchKMeans, DBSCAN and TruncatedSVD all accept sparse input directly, so the fix is to never call toarray and to choose algorithms that do not force you to. Densify only after you have reduced the columns to a few hundred with something like TruncatedSVD, never on the raw hashed width.

Grouping Templates and Isolating Rare Events

Once the file is thirteen templates, a second clustering can group related events for triage, since the pod scheduling line and the out of memory kill that names a pod belong together. DBSCAN suits this, because it finds groups by density and leaves genuinely distinct events unclustered rather than forcing them into a bucket. It marks a point as noise, labelled minus one, when nothing sits within a distance eps of it. That default distance is where the tutorials mislead you.

from sklearn.cluster import DBSCAN
from sklearn.feature_extraction.text import TfidfVectorizer

templates = [c.get_template() for c in sorted(tm.drain.clusters, key=lambda c: c.cluster_id)]
V = TfidfVectorizer().fit_transform(templates)   # 13 rows, a small vocabulary is fine now
print('euclidean:', DBSCAN(eps=0.5, min_samples=2).fit(V.toarray()).labels_.tolist())
print('cosine:   ', DBSCAN(eps=0.8, min_samples=2, metric='cosine').fit(V).labels_.tolist())
euclidean: [-1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1, -1]
cosine:    [-1, -1, 0, -1, -1, -1, -1, -1, -1, -1, -1, -1, 0]

Euclidean distance calls all thirteen templates noise, every one, because on l2 normalised sparse vectors the straight line gap between any two points is nearly identical and nearly the maximum. Switch the metric to cosine, which reads the angle between vectors and ignores their length, and the one real family surfaces: index 2 and index 12, the pod scheduled line and the FATAL out of memory kill that names a pod, land together at label 0 while the rest stay distinct. That is the honest result. Most templates in a healthy system are genuinely unrelated, so a high noise count from DBSCAN on clean templates is the model agreeing with Drain, not failing. Use it to find the few families worth collapsing, not to re-cluster what template mining already separated. Observability leans on the same instinct, and the AI Engineering Series makes the case in its piece on tracing and debugging, where grouping similar events is what turns a firehose into a signal.

Mine Templates First, Then Cluster the Structure

Start every log analysis with template mining, not vectorisation. Drain3 turns a wall of lines into a counted set of patterns in one streaming pass, isolates the rare events that matter, and costs almost nothing. Vectorise only when you need geometry on top, keep those matrices sparse and cluster on cosine, and treat DBSCAN noise as a finding rather than a bug. One artifact is worth lifting straight into your own toolbox, a function that takes a log path and returns a triage table.

def summarise_logs(path, free_text_from=3):
    tm = TemplateMiner(config=TemplateMinerConfig())
    total = 0
    for line in open(path):
        line = line.rstrip()
        if not line:
            continue
        text = line.split(maxsplit=free_text_from)[free_text_from]
        tm.add_log_message(text)
        total += 1
    rows = []
    for c in tm.drain.clusters:
        sev = next((k for k in ('FATAL', 'ERROR', 'WARN') if k in c.get_template()), 'info')
        rows.append({'id': c.cluster_id, 'count': c.size,
                     'share_pct': round(100 * c.size / total, 2),
                     'severity': sev, 'template': c.get_template()})
    return pd.DataFrame(rows).sort_values('count').reset_index(drop=True)

print(summarise_logs('cluster.log').head(4).to_string(index=False))
 id  count  share_pct severity                             template
 11     60       0.12     WARN WARN request <*> timed out after <*> to <*>
 12     62       0.12    ERROR ERROR etcd leader election lost on <*> term <*>
 13     67       0.13    FATAL      FATAL out of memory killing pod <*> on <*>
  5   4753       9.51     info           heartbeat from <*> ok latency <*>

Sorted ascending, the table puts the rarest patterns on top, which is where the failures live, each about a tenth of a percent of the volume and none of them visible to a human scrolling. Keep it next to the export and run it against any file, and let the severity column be a two minute rule you tighten to your own keywords.

Share of log volume per mined template50,000 lines, 13 templates, the three failures in red hold 0.37 percent between themrequest completed10.3 percentcache hit ratio10.2 percentdisk usage10.1 percentuser authenticated10.0 percentconnection established10.0 percentconfig reloaded10.0 percenttls handshake9.9 percentgc pause9.9 percentpod scheduled9.9 percentheartbeat9.5 percentFATAL out of memory0.13 percentERROR etcd election0.12 percentWARN request timeout0.12 percent
The failures are a rounding error by volume and the whole point by meaning. Template mining ranks them to the top; raw clustering hides them in the bulk.
War story: During a control plane outage I tried to cluster 2.1 million lines with TF-IDF and k-means to find what broke. It ran for about forty minutes, produced 200 clusters, and the actual failure, a certificate that had expired at midnight, sat as 300 lines inside a cluster of 411,000 routine messages. I never saw it. A colleague ran Drain3 on the same file while I waited, and in under ten seconds it put the cert error in its own template of 300 with a count next to it. Forty minutes of k-means told me nothing; nine seconds of template mining pointed straight at the line. I have not opened a log file with k-means first since.
TaskReach forAvoid
Collapse raw lines to patternsDrain3 template miningTF-IDF plus k-means on raw lines
Bounded memory on a live streamDrain3 with drain_max_clustersholding a growing vocabulary
Geometric clustering at scaleHashingVectorizer plus MiniBatchKMeans, sparsedensifying with toarray
Group templates into familiesDBSCAN on cosine distanceDBSCAN on euclidean distance

Do this on Monday: export an hour of logs from one busy service, strip the timestamp and host, and run summarise_logs on it. Read the smallest three templates first, because that is your incident feed, ranked by rarity, built from data you already had. For a public corpus to rehearse on before touching production, LogHub carries labelled system logs from HDFS and BlueGene at real scale. Next part weighs the honest limits of all this, incident prediction and AIOps, and where the vendor promises stop matching the data.

Infra to Data Science Series · Part 23 of 26
« Previous: Part 22  |  Guide  |  Next: Part 24 »

References

About The Author


Discover more from Journal of Intelligent Infrastructure

Subscribe to get the latest posts sent to your email.

Leave a Reply

Your email address will not be published. Required fields are marked *

Architect’s Toolkit

About the Author

Dr. Pranay Jha is a Cloud and AI Consultant with 18+ years of experience in hybrid cloud, virtualization, and enterprise infrastructure transformation. He specializes in VMware technologies, multi-cloud strategy, and Generative AI solutions. He holds a PhD in Computer Applications with research focused on Cloud and AI, has published multiple research papers, and has been a VMware vExpert since 2016 and a VMUG Community Leader.

Discover more from Journal of Intelligent Infrastructure

Subscribe now to keep reading and get access to the full archive.

Continue reading