def test_match_only(self):
model = Drain()
res = model.add_log_message("aa aa aa")
print(res[0])
res = model.add_log_message("aa aa bb")
print(res[0])
res = model.add_log_message("aa aa cc")
print(res[0])
res = model.add_log_message("xx yy zz")
print(res[0])
c: LogCluster = model.match("aa aa tt")
self.assertEqual(1, c.cluster_id)
c: LogCluster = model.match("xx yy zz")
self.assertEqual(2, c.cluster_id)
c: LogCluster = model.match("xx yy rr")
self.assertIsNone(c)
c: LogCluster = model.match("nothing")
self.assertIsNone(c)
def test_max_clusters(self):
"""Verify model respects the max_clusters option.
Key difference between this and other tests is that with `max_clusters`
set to 1 model is capable of keeping track of a single cluster at a
time. Consequently, when log stream switched form the A format to the B
and back model doesn't recognize it and returnes a new template with no
slots.
"""
model = Drain(max_clusters=1)
entries = str.splitlines("""
A format 1
A format 2
B format 1
B format 2
A format 3
""")
expected = str.splitlines("""
A format 1
A format <*>
B format 1
B format <*>
A format 3
""")
actual = []
for entry in entries:
cluster, change_type = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(1, model.get_total_cluster_size())
def test_add_log_message(self):
model = Drain()
entries = str.splitlines("""
Dec 10 07:07:38 LabSZ sshd[24206]: input_userauth_request: invalid user test9 [preauth]
Dec 10 07:08:28 LabSZ sshd[24208]: input_userauth_request: invalid user webmaster [preauth]
Dec 10 09:12:32 LabSZ sshd[24490]: Failed password for invalid user ftpuser from 0.0.0.0 port 62891 ssh2
Dec 10 09:12:35 LabSZ sshd[24492]: Failed password for invalid user pi from 0.0.0.0 port 49289 ssh2
Dec 10 09:12:44 LabSZ sshd[24501]: Failed password for invalid user ftpuser from 0.0.0.0 port 60836 ssh2
Dec 10 07:28:03 LabSZ sshd[24245]: input_userauth_request: invalid user pgadmin [preauth]
""")
expected = str.splitlines("""
Dec 10 07:07:38 LabSZ sshd[24206]: input_userauth_request: invalid user test9 [preauth]
Dec 10 <*> LabSZ <*> input_userauth_request: invalid user <*> [preauth]
Dec 10 09:12:32 LabSZ sshd[24490]: Failed password for invalid user ftpuser from 0.0.0.0 port 62891 ssh2
Dec 10 <*> LabSZ <*> Failed password for invalid user <*> from 0.0.0.0 port <*> ssh2
Dec 10 <*> LabSZ <*> Failed password for invalid user <*> from 0.0.0.0 port <*> ssh2
Dec 10 <*> LabSZ <*> input_userauth_request: invalid user <*> [preauth]
""")
actual = []
for entry in entries:
cluster, change_type = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(8, model.get_total_cluster_size())
def test_depth_3(self):
"""When `depth` is set to 3 then there is no prefixing based on any of the tokens"""
model = Drain(
depth=3,
sim_th=0.3,
max_children=100,
)
entries = str.splitlines("""
X A B
X A C
Y A B
Y A C
""")
expected = str.splitlines("""
X A B
X A <*>
<*> A <*>
<*> A <*>
""")
actual = []
for entry in entries:
cluster, change_type = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(6, model.get_total_cluster_size())
def test_depth_4(self):
"""When `depth` is set to 4 then the first token is never wild-carded because it's part of the prefix tree"""
model = Drain(
depth=4,
sim_th=0.3,
max_children=100,
)
entries = str.splitlines("""
X A B
X A C
Y A B
Y A C
""")
expected = str.splitlines("""
X A B
X A <*>
Y A B
Y A <*>
""")
actual = []
for entry in entries:
cluster, change_type = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(6, model.get_total_cluster_size())
def test_add_shorter_than_depth_message(self):
model = Drain(depth=4)
res = model.add_log_message("word")
print(res[1])
print(res[0])
self.assertEqual(res[1], "cluster_created")
res = model.add_log_message("word")
print(res[1])
print(res[0])
self.assertEqual(res[1], "none")
res = model.add_log_message("otherword")
print(res[1])
print(res[0])
self.assertEqual(res[1], "cluster_created")
self.assertEqual(2, len(model.id_to_cluster))
def test_max_clusters_lru_multiple_leaf_nodes(self):
"""When all templates end up in different nodes and the max number of
clusters is reached, then clusters are removed according to the lru
policy.
"""
model = Drain(max_clusters=2, depth=4, param_str="*")
entries = [
"A A A",
"A A B",
"B A A",
"B A B",
"C A A",
"C A B",
"B A A",
"A A A",
]
expected = [
# lru: []
"A A A",
# lru: ["A A A"]
"A A *",
# lru: ["A A *"]
"B A A",
# lru: ["B A A", "A A *"]
"B A *",
# lru: ["B A *", "A A *"]
"C A A",
# lru: ["C A A", "B A *"]
"C A *",
# lru: ["C A *", "B A *"]
"B A *",
# Message "B A A" was normalized because the template "B A *" is
# still present in the cache.
# lru: ["B A *", "C A *"]
"A A A",
# Message "A A A" was not normalized because the template "C A A"
# pushed out the template "A A *" from the cache.
# lru: ["A A A", "C A *"]
]
actual = []
for entry in entries:
cluster, _ = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(4, model.get_total_cluster_size())
def test_max_clusters_lru(self):
"""When max number of clusters is reached, then clusters are removed
according to the lru policy.
"""
model = Drain(max_clusters=3, depth=3)
entries = [
"A A foramt 1",
"A A foramt 2",
"A B format 1",
"A B format 2",
"B format 1",
"B format 2",
"A A foramt 3",
"C foramt 1",
"A B format 3",
]
expected = [
"A A foramt 1", # LRU = ["A"]
"A A foramt <*>", # LRU = ["A"]
# Use "A A" prefix to make sure both "A" and "A A" clusters end up
# in the same leaf node. This is a setup for an interesting edge
# case.
"A B format 1", # LRU = ["AA", "A"]
"A B format <*>", # LRU = ["AA", "A"]
"B format 1", # LRU = ["B", "A A", "A"]
"B format <*>", # LRU = ["B", "A A", "A"]
"A A foramt <*>", # LRU = ["A", "B", "A A"]
"C foramt 1", # LRU = ["C", "A", "B"]
# Cluster "A A" should have been removed in the previous step, thus,
# it should be recognized as a new cluster with no slots.
"A B format 3", # LRU = ["A A', "C", "A"]
]
actual = []
for entry in entries:
cluster, _ = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(5, model.get_total_cluster_size())
def test_add_log_message_sim_75(self):
"""When `sim_th` is set to 75% then only certain log entries match.
In this test similarity threshold is set to 75% which makes the model
less aggressive in grouping entries into clusters. In particular, it
only finds clusters for "Failed password" entries.
"""
model = Drain(
depth=4,
sim_th=0.75,
max_children=100,
)
entries = str.splitlines(
"""
Dec 10 07:07:38 LabSZ sshd[24206]: input_userauth_request: invalid user test9 [preauth]
Dec 10 07:08:28 LabSZ sshd[24208]: input_userauth_request: invalid user webmaster [preauth]
Dec 10 09:12:32 LabSZ sshd[24490]: Failed password for invalid user ftpuser from 0.0.0.0 port 62891 ssh2
Dec 10 09:12:35 LabSZ sshd[24492]: Failed password for invalid user pi from 0.0.0.0 port 49289 ssh2
Dec 10 09:12:44 LabSZ sshd[24501]: Failed password for invalid user ftpuser from 0.0.0.0 port 60836 ssh2
Dec 10 07:28:03 LabSZ sshd[24245]: input_userauth_request: invalid user pgadmin [preauth]
"""
)
expected = str.splitlines(
"""
Dec 10 07:07:38 LabSZ sshd[24206]: input_userauth_request: invalid user test9 [preauth]
Dec 10 07:08:28 LabSZ sshd[24208]: input_userauth_request: invalid user webmaster [preauth]
Dec 10 09:12:32 LabSZ sshd[24490]: Failed password for invalid user ftpuser from 0.0.0.0 port 62891 ssh2
Dec 10 <*> LabSZ <*> Failed password for invalid user <*> from 0.0.0.0 port <*> ssh2
Dec 10 <*> LabSZ <*> Failed password for invalid user <*> from 0.0.0.0 port <*> ssh2
Dec 10 07:28:03 LabSZ sshd[24245]: input_userauth_request: invalid user pgadmin [preauth]
"""
)
actual = []
for entry in entries:
cluster, change_type = model.add_log_message(entry)
actual.append(cluster.get_template())
self.assertListEqual(list(map(str.strip, expected)), actual)
self.assertEqual(8, model.get_total_cluster_size())
class TemplateMiner:
def __init__(self,
persistence_handler: PersistenceHandler = None,
config: TemplateMinerConfig = None):
"""
Wrapper for Drain with persistence and masking support
:param persistence_handler: The type of persistence to use. When None, no persistence is applied.
:param config: Configuration object. When none, configuration is loaded from default .ini file (if exist)
"""
logger.info("Starting Drain3 template miner")
if config is None:
logger.info(f"Loading configuration from {config_filename}")
config = TemplateMinerConfig()
config.load(config_filename)
self.config = config
self.profiler: Profiler = NullProfiler()
if self.config.profiling_enabled:
self.profiler = SimpleProfiler()
self.persistence_handler = persistence_handler
param_str = self.config.mask_prefix + "*" + self.config.mask_suffix
self.drain = Drain(
sim_th=self.config.drain_sim_th,
depth=self.config.drain_depth,
max_children=self.config.drain_max_children,
max_clusters=self.config.drain_max_clusters,
extra_delimiters=self.config.drain_extra_delimiters,
profiler=self.profiler,
param_str=param_str,
parametrize_numeric_tokens=self.config.parametrize_numeric_tokens)
self.masker = LogMasker(self.config.masking_instructions,
self.config.mask_prefix,
self.config.mask_suffix)
self.parameter_extraction_cache = LRUCache(
self.config.parameter_extraction_cache_capacity)
self.last_save_time = time.time()
if persistence_handler is not None:
self.load_state()
def load_state(self):
logger.info("Checking for saved state")
state = self.persistence_handler.load_state()
if state is None:
logger.info("Saved state not found")
return
if self.config.snapshot_compress_state:
state = zlib.decompress(base64.b64decode(state))
loaded_drain: Drain = jsonpickle.loads(state, keys=True)
# json-pickle encoded keys as string by default, so we have to convert those back to int
# this is only relevant for backwards compatibility when loading a snapshot of drain <= v0.9.1
# which did not use json-pickle's keys=true
if len(loaded_drain.id_to_cluster) > 0 and isinstance(
next(iter(loaded_drain.id_to_cluster.keys())), str):
loaded_drain.id_to_cluster = {
int(k): v
for k, v in list(loaded_drain.id_to_cluster.items())
}
if self.config.drain_max_clusters:
cache = LRUCache(maxsize=self.config.drain_max_clusters)
cache.update(loaded_drain.id_to_cluster)
loaded_drain.id_to_cluster = cache
self.drain.id_to_cluster = loaded_drain.id_to_cluster
self.drain.clusters_counter = loaded_drain.clusters_counter
self.drain.root_node = loaded_drain.root_node
logger.info("Restored {0} clusters built from {1} messages".format(
len(loaded_drain.clusters), loaded_drain.get_total_cluster_size()))
def save_state(self, snapshot_reason):
state = jsonpickle.dumps(self.drain, keys=True).encode('utf-8')
if self.config.snapshot_compress_state:
state = base64.b64encode(zlib.compress(state))
logger.info(
f"Saving state of {len(self.drain.clusters)} clusters "
f"with {self.drain.get_total_cluster_size()} messages, {len(state)} bytes, "
f"reason: {snapshot_reason}")
self.persistence_handler.save_state(state)
def get_snapshot_reason(self, change_type, cluster_id):
if change_type != "none":
return "{} ({})".format(change_type, cluster_id)
diff_time_sec = time.time() - self.last_save_time
if diff_time_sec >= self.config.snapshot_interval_minutes * 60:
return "periodic"
return None
def add_log_message(self, log_message: str) -> dict:
self.profiler.start_section("total")
self.profiler.start_section("mask")
masked_content = self.masker.mask(log_message)
self.profiler.end_section()
self.profiler.start_section("drain")
cluster, change_type = self.drain.add_log_message(masked_content)
self.profiler.end_section("drain")
result = {
"change_type": change_type,
"cluster_id": cluster.cluster_id,
"cluster_size": cluster.size,
"template_mined": cluster.get_template(),
"cluster_count": len(self.drain.clusters)
}
if self.persistence_handler is not None:
self.profiler.start_section("save_state")
snapshot_reason = self.get_snapshot_reason(change_type,
cluster.cluster_id)
if snapshot_reason:
self.save_state(snapshot_reason)
self.last_save_time = time.time()
self.profiler.end_section()
self.profiler.end_section("total")
self.profiler.report(self.config.profiling_report_sec)
return result
def match(self,
log_message: str,
full_search_strategy="never") -> LogCluster:
"""
Mask log message and match against an already existing cluster.
Match shall be perfect (sim_th=1.0).
New cluster will not be created as a result of this call, nor any cluster modifications.
:param log_message: log message to match
:param full_search_strategy: when to perform full cluster search.
(1) "never" is the fastest, will always perform a tree search [O(log(n)] but might produce
false negatives (wrong mismatches) on some edge cases;
(2) "fallback" will perform a linear search [O(n)] among all clusters with the same token count, but only in
case tree search found no match.
It should not have false negatives, however tree-search may find a non-optimal match with
more wildcard parameters than necessary;
(3) "always" is the slowest. It will select the best match among all known clusters, by always evaluating
all clusters with the same token count, and selecting the cluster with perfect all token match and least
count of wildcard matches.
:return: Matched cluster or None if no match found.
"""
masked_content = self.masker.mask(log_message)
matched_cluster = self.drain.match(masked_content,
full_search_strategy)
return matched_cluster
def get_parameter_list(self, log_template: str,
log_message: str) -> List[str]:
"""
Extract parameters from a log message according to a provided template that was generated
by calling `add_log_message()`.
This function is deprecated. Please use extract_parameters instead.
:param log_template: log template corresponding to the log message
:param log_message: log message to extract parameters from
:return: An ordered list of parameter values present in the log message.
"""
extracted_parameters = self.extract_parameters(log_template,
log_message,
exact_matching=False)
if not extracted_parameters:
return []
return [parameter.value for parameter in extracted_parameters]
def extract_parameters(
self,
log_template: str,
log_message: str,
exact_matching: bool = True) -> Optional[List[ExtractedParameter]]:
"""
Extract parameters from a log message according to a provided template that was generated
by calling `add_log_message()`.
For most accurate results, it is recommended that
- Each `MaskingInstruction` has a unique `mask_with` value,
- No `MaskingInstruction` has a `mask_with` value of `*`,
- The regex-patterns of `MaskingInstruction` do not use unnamed back-references;
instead use back-references to named groups e.g. `(?P=some-name)`.
:param log_template: log template corresponding to the log message
:param log_message: log message to extract parameters from
:param exact_matching: whether to apply the correct masking-patterns to match parameters, or try to approximate;
disabling exact_matching may be faster but may lead to situations in which parameters
are wrongly identified.
:return: A ordered list of ExtractedParameter for the log message
or None if log_message does not correspond to log_template.
"""
for delimiter in self.config.drain_extra_delimiters:
log_message = re.sub(delimiter, " ", log_message)
template_regex, param_group_name_to_mask_name = self._get_template_parameter_extraction_regex(
log_template, exact_matching)
# Parameters are represented by specific named groups inside template_regex.
parameter_match = re.match(template_regex, log_message)
# log template does not match template
if not parameter_match:
return None
# create list of extracted parameters
extracted_parameters = []
for group_name, parameter in parameter_match.groupdict().items():
if group_name in param_group_name_to_mask_name:
mask_name = param_group_name_to_mask_name[group_name]
extracted_parameter = ExtractedParameter(parameter, mask_name)
extracted_parameters.append(extracted_parameter)
return extracted_parameters
@cachedmethod(lambda self: self.parameter_extraction_cache)
def _get_template_parameter_extraction_regex(self, log_template: str,
exact_matching: bool):
param_group_name_to_mask_name = dict()
param_name_counter = [0]
def get_next_param_name():
param_group_name = "p_" + str(param_name_counter[0])
param_name_counter[0] += 1
return param_group_name
# Create a named group with the respective patterns for the given mask-name.
def create_capture_regex(_mask_name):
allowed_patterns = []
if exact_matching:
# get all possible regex patterns from masking instructions that match this mask name
masking_instructions = self.masker.instructions_by_mask_name(
_mask_name)
for mi in masking_instructions:
# MaskingInstruction may already contain named groups.
# We replace group names in those named groups, to avoid conflicts due to duplicate names.
if hasattr(mi, 'regex'):
mi_groups = mi.regex.groupindex.keys()
pattern = mi.pattern
else:
# non regex masking instructions - support only non-exact matching
mi_groups = []
pattern = ".+?"
for group_name in mi_groups:
param_group_name = get_next_param_name()
def replace_captured_param_name(param_pattern):
_search_str = param_pattern.format(group_name)
_replace_str = param_pattern.format(
param_group_name)
return pattern.replace(_search_str, _replace_str)
pattern = replace_captured_param_name("(?P={}")
pattern = replace_captured_param_name("(?P<{}>")
# support unnamed back-references in masks (simple cases only)
pattern = re.sub(r"\\(?!0)\d{1,2}", r"(?:.+?)", pattern)
allowed_patterns.append(pattern)
if not exact_matching or _mask_name == "*":
allowed_patterns.append(r".+?")
# Give each capture group a unique name to avoid conflicts.
param_group_name = get_next_param_name()
param_group_name_to_mask_name[param_group_name] = _mask_name
joined_patterns = "|".join(allowed_patterns)
capture_regex = "(?P<{}>{})".format(param_group_name,
joined_patterns)
return capture_regex
# For every mask in the template, replace it with a named group of all
# possible masking-patterns it could represent (in order).
mask_names = set(self.masker.mask_names)
# the Drain catch-all mask
mask_names.add("*")
escaped_prefix = re.escape(self.masker.mask_prefix)
escaped_suffix = re.escape(self.masker.mask_suffix)
template_regex = re.escape(log_template)
# replace each mask name with a proper regex that captures it
for mask_name in mask_names:
search_str = escaped_prefix + re.escape(mask_name) + escaped_suffix
while True:
rep_str = create_capture_regex(mask_name)
# Replace one-by-one to get a new param group name for each replacement.
template_regex_new = template_regex.replace(
search_str, rep_str, 1)
# Break when all replaces for this mask are done.
if template_regex_new == template_regex:
break
template_regex = template_regex_new
# match also messages with multiple spaces or other whitespace chars between tokens
template_regex = re.sub(r"\\ ", r"\\s+", template_regex)
template_regex = "^" + template_regex + "$"
return template_regex, param_group_name_to_mask_name
class TemplateMiner:
def __init__(self,
persistence_handler: PersistenceHandler = None,
config: TemplateMinerConfig = None):
"""
Wrapper for Drain with persistence and masking support
:param persistence_handler: The type of persistence to use. When None, no persistence is applied.
:param config: Configuration object. When none, configuration is loaded from default .ini file (if exist)
"""
logger.info("Starting Drain3 template miner")
if config is None:
logger.info(f"Loading configuration from {config_filename}")
config = TemplateMinerConfig()
config.load(config_filename)
self.config = config
self.profiler: Profiler = NullProfiler()
if self.config.profiling_enabled:
self.profiler = SimpleProfiler()
self.persistence_handler = persistence_handler
self.drain = Drain(sim_th=self.config.drain_sim_th,
depth=self.config.drain_depth,
max_children=self.config.drain_max_children,
max_clusters=self.config.drain_max_clusters,
extra_delimiters=self.config.drain_extra_delimiters,
profiler=self.profiler)
self.masker = LogMasker(self.config.masking_instructions)
self.last_save_time = time.time()
if persistence_handler is not None:
self.load_state()
def load_state(self):
logger.info("Checking for saved state")
state = self.persistence_handler.load_state()
if state is None:
logger.info("Saved state not found")
return
if self.config.snapshot_compress_state:
state = zlib.decompress(base64.b64decode(state))
drain: Drain = jsonpickle.loads(state)
# json-pickle encode keys as string by default, so we have to convert those back to int
keys = drain.id_to_cluster.keys()
for key in keys:
drain.id_to_cluster[int(key)] = drain.id_to_cluster.pop(key)
drain.profiler = self.profiler
self.drain = drain
logger.info("Restored {0} clusters with {1} messages".format(
len(drain.clusters), drain.get_total_cluster_size()))
def save_state(self, snapshot_reason):
state = jsonpickle.dumps(self.drain).encode('utf-8')
if self.config.snapshot_compress_state:
state = base64.b64encode(zlib.compress(state))
logger.info(
f"Saving state of {len(self.drain.clusters)} clusters "
f"with {self.drain.get_total_cluster_size()} messages, {len(state)} bytes, "
f"reason: {snapshot_reason}")
self.persistence_handler.save_state(state)
def get_snapshot_reason(self, change_type, cluster_id):
if change_type != "none":
return "{} ({})".format(change_type, cluster_id)
diff_time_sec = time.time() - self.last_save_time
if diff_time_sec >= self.config.snapshot_interval_minutes * 60:
return "periodic"
return None
def add_log_message(self, log_message: str):
self.profiler.start_section("total")
self.profiler.start_section("mask")
masked_content = self.masker.mask(log_message)
self.profiler.end_section()
self.profiler.start_section("drain")
cluster, change_type = self.drain.add_log_message(masked_content)
self.profiler.end_section("drain")
result = {
"change_type": change_type,
"cluster_id": cluster.cluster_id,
"cluster_size": cluster.size,
"template_mined": cluster.get_template(),
"cluster_count": len(self.drain.clusters)
}
if self.persistence_handler is not None:
self.profiler.start_section("save_state")
snapshot_reason = self.get_snapshot_reason(change_type,
cluster.cluster_id)
if snapshot_reason:
self.save_state(snapshot_reason)
self.last_save_time = time.time()
self.profiler.end_section()
self.profiler.end_section("total")
self.profiler.report(self.config.profiling_report_sec)
return result
class TemplateMiner:
def __init__(self, persistence_handler: PersistenceHandler = None):
logger.info("Starting Drain3 template miner")
self.config = configparser.ConfigParser()
self.config.read(config_filename)
self.profiler: Profiler = NullProfiler()
self.profiling_report_sec = self.config.getint('PROFILING',
'report_sec',
fallback=60)
if self.config.getboolean('PROFILING', 'enabled', fallback=False):
self.profiler = SimpleProfiler()
self.persistence_handler = persistence_handler
self.snapshot_interval_seconds = self.config.getint(
'SNAPSHOT', 'snapshot_interval_minutes', fallback=5) * 60
self.compress_state = self.config.getboolean('SNAPSHOT',
'compress_state',
fallback=True)
extra_delimiters = self.config.get('DRAIN',
'extra_delimiters',
fallback="[]")
extra_delimiters = ast.literal_eval(extra_delimiters)
self.drain = Drain(sim_th=self.config.getfloat('DRAIN',
'sim_th',
fallback=0.4),
depth=self.config.getint('DRAIN',
'depth',
fallback=4),
max_children=self.config.getint('DRAIN',
'max_children',
fallback=100),
max_clusters=self.config.getint('DRAIN',
'max_clusters',
fallback=None),
extra_delimiters=extra_delimiters,
profiler=self.profiler)
self.masker = LogMasker(self.config)
self.last_save_time = time.time()
if persistence_handler is not None:
self.load_state()
def load_state(self):
logger.info("Checking for saved state")
state = self.persistence_handler.load_state()
if state is None:
logger.info("Saved state not found")
return
if self.compress_state:
state = zlib.decompress(base64.b64decode(state))
drain: Drain = jsonpickle.loads(state)
# After loading, the keys of "parser.root_node.key_to_child" are string instead of int,
# so we have to cast them to int
keys = []
for i in drain.root_node.key_to_child_node.keys():
keys.append(i)
for key in keys:
drain.root_node.key_to_child_node[int(
key)] = drain.root_node.key_to_child_node.pop(key)
drain.profiler = self.profiler
self.drain = drain
logger.info("Restored {0} clusters with {1} messages".format(
len(drain.clusters), drain.get_total_cluster_size()))
def save_state(self, snapshot_reason):
state = jsonpickle.dumps(self.drain).encode('utf-8')
if self.compress_state:
state = base64.b64encode(zlib.compress(state))
logger.info(
f"Saving state of {len(self.drain.clusters)} clusters "
f"with {self.drain.get_total_cluster_size()} messages, {len(state)} bytes, "
f"reason: {snapshot_reason}")
self.persistence_handler.save_state(state)
def get_snapshot_reason(self, change_type, cluster_id):
if change_type != "none":
return "{} ({})".format(change_type, cluster_id)
diff_time_sec = time.time() - self.last_save_time
if diff_time_sec >= self.snapshot_interval_seconds:
return "periodic"
return None
def add_log_message(self, log_message: str):
self.profiler.start_section("total")
self.profiler.start_section("mask")
masked_content = self.masker.mask(log_message)
self.profiler.end_section()
self.profiler.start_section("drain")
cluster, change_type = self.drain.add_log_message(masked_content)
self.profiler.end_section("drain")
result = {
"change_type": change_type,
"cluster_id": cluster.cluster_id,
"cluster_size": cluster.size,
"template_mined": cluster.get_template(),
"cluster_count": len(self.drain.clusters)
}
if self.persistence_handler is not None:
self.profiler.start_section("save_state")
snapshot_reason = self.get_snapshot_reason(change_type,
cluster.cluster_id)
if snapshot_reason:
self.save_state(snapshot_reason)
self.last_save_time = time.time()
self.profiler.end_section()
self.profiler.end_section("total")
self.profiler.report(self.profiling_report_sec)
return result
class TemplateMiner:
def __init__(self,
persistence_handler: PersistenceHandler = None,
config: TemplateMinerConfig = None):
"""
Wrapper for Drain with persistence and masking support
:param persistence_handler: The type of persistence to use. When None, no persistence is applied.
:param config: Configuration object. When none, configuration is loaded from default .ini file (if exist)
"""
logger.info("Starting Drain3 template miner")
if config is None:
logger.info(f"Loading configuration from {config_filename}")
config = TemplateMinerConfig()
config.load(config_filename)
self.config = config
self.profiler: Profiler = NullProfiler()
if self.config.profiling_enabled:
self.profiler = SimpleProfiler()
self.persistence_handler = persistence_handler
param_str = self.config.mask_prefix + "*" + self.config.mask_suffix
self.drain = Drain(
sim_th=self.config.drain_sim_th,
depth=self.config.drain_depth,
max_children=self.config.drain_max_children,
max_clusters=self.config.drain_max_clusters,
extra_delimiters=self.config.drain_extra_delimiters,
profiler=self.profiler,
param_str=param_str
)
self.masker = LogMasker(self.config.masking_instructions, self.config.mask_prefix, self.config.mask_suffix)
self.last_save_time = time.time()
if persistence_handler is not None:
self.load_state()
def load_state(self):
logger.info("Checking for saved state")
state = self.persistence_handler.load_state()
if state is None:
logger.info("Saved state not found")
return
if self.config.snapshot_compress_state:
state = zlib.decompress(base64.b64decode(state))
drain: Drain = jsonpickle.loads(state, keys=True)
# json-pickle encoded keys as string by default, so we have to convert those back to int
# this is only relevant for backwards compatibility when loading a snapshot of drain <= v0.9.1
# which did not use json-pickle's keys=true
if len(drain.id_to_cluster) > 0 and isinstance(next(iter(drain.id_to_cluster.keys())), str):
drain.id_to_cluster = {int(k): v for k, v in list(drain.id_to_cluster.items())}
if self.config.drain_max_clusters:
cache = LRUCache(maxsize=self.config.drain_max_clusters)
cache.update(drain.id_to_cluster)
drain.id_to_cluster = cache
drain.profiler = self.profiler
self.drain = drain
logger.info("Restored {0} clusters with {1} messages".format(
len(drain.clusters), drain.get_total_cluster_size()))
def save_state(self, snapshot_reason):
state = jsonpickle.dumps(self.drain, keys=True).encode('utf-8')
if self.config.snapshot_compress_state:
state = base64.b64encode(zlib.compress(state))
# logger.info(f"Saving state of {len(self.drain.clusters)} clusters "
# f"with {self.drain.get_total_cluster_size()} messages, {len(state)} bytes, "
# f"reason: {snapshot_reason}")
self.persistence_handler.save_state(state)
def get_snapshot_reason(self, change_type, cluster_id):
if change_type != "none":
return "{} ({})".format(change_type, cluster_id)
diff_time_sec = time.time() - self.last_save_time
if diff_time_sec >= self.config.snapshot_interval_minutes * 60:
return "periodic"
return None
def add_log_message(self, log_message: str) -> dict:
self.profiler.start_section("total")
self.profiler.start_section("mask")
masked_content = self.masker.mask(log_message)
self.profiler.end_section()
self.profiler.start_section("drain")
cluster, change_type = self.drain.add_log_message(masked_content)
self.profiler.end_section("drain")
result = {
"change_type": change_type,
"cluster_id": cluster.cluster_id,
"cluster_size": cluster.size,
"template_mined": cluster.get_template(),
"cluster_count": len(self.drain.clusters)
}
if self.persistence_handler is not None:
self.profiler.start_section("save_state")
snapshot_reason = self.get_snapshot_reason(change_type, cluster.cluster_id)
if snapshot_reason:
self.save_state(snapshot_reason)
self.last_save_time = time.time()
self.profiler.end_section()
self.profiler.end_section("total")
self.profiler.report(self.config.profiling_report_sec)
return result
def match(self, log_message: str) -> LogCluster:
"""
Match against an already existing cluster. Match shall be perfect (sim_th=1.0).
New cluster will not be created as a result of this call, nor any cluster modifications.
:param log_message: log message to match
:return: Matched cluster or None of no match found.
"""
masked_content = self.masker.mask(log_message)
matched_cluster = self.drain.match(masked_content)
return matched_cluster
def get_parameter_list(self, log_template: str, content: str):
escaped_prefix = re.escape(self.config.mask_prefix)
escaped_suffix = re.escape(self.config.mask_suffix)
template_regex = re.sub(escaped_prefix + r".+?" + escaped_suffix, self.drain.param_str, log_template)
if self.drain.param_str not in template_regex:
return []
template_regex = re.escape(template_regex)
template_regex = re.sub(r'\\ +', r'\\s+', template_regex)
template_regex = "^" + template_regex.replace(escaped_prefix + r"\*" + escaped_suffix, "(.*?)") + "$"
for delimiter in self.config.drain_extra_delimiters:
content = re.sub(delimiter, ' ', content)
parameter_list = re.findall(template_regex, content)
parameter_list = parameter_list[0] if parameter_list else ()
parameter_list = list(parameter_list) if isinstance(parameter_list, tuple) else [parameter_list]
def is_mask(p: str):
return p.startswith(self.config.mask_prefix) and p.endswith(self.config.mask_suffix)
parameter_list = [p for p in list(parameter_list) if not is_mask(p)]
return parameter_list
def test_one_token_message(self):
model = Drain()
cluster, change_type = model.add_log_message("oneTokenMessage")
self.assertEqual("cluster_created", change_type, "1st check")
cluster, change_type = model.add_log_message("oneTokenMessage")
self.assertEqual("none", change_type, "2nd check")
class TemplateMiner:
def __init__(self, persistence_handler: PersistenceHandler):
logger.info("Starting Drain3 template miner")
self.compress_state = config.get('DEFAULT', 'compress_state', fallback=True)
self.persistence_handler = persistence_handler
self.snapshot_interval_seconds = int(config.get('DEFAULT', 'snapshot_interval_minutes', fallback=5)) * 60
self.drain = Drain(sim_th=float(config.get('DEFAULT', 'sim_th', fallback=0.4)))
self.masker = LogMasker()
self.last_save_time = time.time()
if persistence_handler is not None:
self.load_state()
def load_state(self):
logger.info("Checking for saved state")
state = self.persistence_handler.load_state()
if state is None:
logger.info("Saved state not found")
return
if self.compress_state:
state = zlib.decompress(base64.b64decode(state))
drain: Drain = jsonpickle.loads(state)
# After loading, the keys of "parser.root_node.key_to_child" are string instead of int,
# so we have to cast them to int
keys = []
for i in drain.root_node.key_to_child_node.keys():
keys.append(i)
for key in keys:
drain.root_node.key_to_child_node[int(key)] = drain.root_node.key_to_child_node.pop(key)
self.drain = drain
logger.info("Restored {0} clusters with {1} messages".format(
len(drain.clusters), drain.get_total_cluster_size()))
def save_state(self, snapshot_reason):
state = jsonpickle.dumps(self.drain).encode('utf-8')
if self.compress_state:
state = base64.b64encode(zlib.compress(state))
logger.info(f"Saving state of {len(self.drain.clusters)} clusters "
f"with {self.drain.get_total_cluster_size()} messages, {len(state)} bytes, "
f"reason: {snapshot_reason}")
self.persistence_handler.save_state(state)
def get_snapshot_reason(self, change_type):
if change_type != "none":
return change_type
diff_time_sec = time.time() - self.last_save_time
if diff_time_sec >= self.snapshot_interval_seconds:
return "periodic"
return None
def add_log_message(self, log_message: str):
masked_content = self.masker.mask(log_message)
cluster, change_type = self.drain.add_log_message(masked_content)
result = {
"change_type": change_type,
"cluster_id": cluster.cluster_id,
"cluster_size": cluster.size,
"template_mined": cluster.get_template(),
"cluster_count": len(self.drain.clusters)
}
if self.persistence_handler is not None:
snapshot_reason = self.get_snapshot_reason(change_type)
if snapshot_reason:
self.save_state(snapshot_reason)
self.last_save_time = time.time()
return result