postprocess: Index logs per process and per method (#1025)

* postprocess: Index logs per process and per method

* Look for Method in all logs

* Fix bug

* Update drakrun/analyzer/postprocessing/indexer.py
This commit is contained in:
Paweł Srokosz
2025-04-22 17:53:14 +02:00
committed by GitHub
parent 3a33bc244b
commit 242311f946
8 changed files with 381 additions and 314 deletions
@@ -0,0 +1,94 @@
import logging
import pathlib
from collections import defaultdict
from typing import List, Optional
import orjson
from .process_tree import ProcessTree
logger = logging.getLogger(__name__)
def index_log_file(
log_file: pathlib.Path,
process_tree: ProcessTree,
key: str = None,
):
index = defaultdict(lambda: {"blocks": [], "values": [], "mapping": []})
processes = {}
with log_file.open("r") as f:
while True:
data_start = f.tell()
entry_data = f.readline()
if not entry_data:
break
try:
entry = orjson.loads(entry_data)
pid = entry.get("PID")
event_id = entry.get("EventUID")
value = entry.get(key) if key is not None else None
if not pid or not event_id:
continue
event_id = int(event_id, 16)
if (pid not in processes) or (
processes[pid].evtid_to and processes[pid].evtid_to < event_id
):
process = process_tree.get_process_for_evtid(pid, event_id)
if not process:
raise RuntimeError(
f"No process found for event. Bug? (PID={pid} EventUID={event_id})"
)
processes[pid] = process
else:
process = processes[pid]
entry_seqid = process.seqid
index_entry = index[entry_seqid]
value_index = None
if key is not None:
try:
value_index = index_entry["values"].index(value)
except ValueError:
index_entry["values"].append(value)
value_index = len(index_entry["values"]) - 1
if (
index_entry["blocks"]
and data_start == index_entry["blocks"][-1][1]
and (
value_index is None or index_entry["mapping"][-1] == value_index
)
):
# If adjacent blocks belong to the same mapping
index_entry["blocks"][-1][1] = f.tell()
else:
index_entry["blocks"].append([data_start, f.tell()])
if key is not None:
index_entry["mapping"].append(value_index)
except Exception:
logger.exception("Failed to process entry")
return dict(index)
def scattered_read_file(
log_file: pathlib.Path,
offsets: List[List[int]],
skip: int = 0,
length: Optional[int] = None,
):
bytes_scanned = 0
bytes_read = 0
with log_file.open("rb") as f:
for offset_start, offset_end in offsets:
block_length = offset_end - offset_start
if skip < (bytes_scanned + block_length):
block_skip = max(0, skip - bytes_scanned)
f.seek(offset_start + block_skip)
block_read = block_length - block_skip
if length is not None:
block_read = min(length - bytes_read, block_read)
yield f.read(block_read)
bytes_read += block_read
bytes_scanned += block_length
@@ -6,7 +6,6 @@ from .generate_graphs import generate_graphs
from .generate_wireshark_key_file import generate_wireshark_key_file
from .index_logs import index_logs
from .plugin_base import PostprocessPlugin
from .process_apimon_log import process_apimon_log
from .split_drakmon_log import split_drakmon_log
POSTPROCESS_PLUGINS = [
@@ -16,9 +15,6 @@ POSTPROCESS_PLUGINS = [
PostprocessPlugin(
function=split_drakmon_log, requires=["drakmon.log"], generates=[]
),
PostprocessPlugin(
function=process_apimon_log, requires=["apimon.log"], generates=["apicalls"]
),
PostprocessPlugin(
function=generate_wireshark_key_file,
requires=["tlsmon.log"],
@@ -39,5 +35,7 @@ POSTPROCESS_PLUGINS = [
),
PostprocessPlugin(function=crop_dumps, requires=["dumps"], generates=["dumps.zip"]),
PostprocessPlugin(function=compress_ipt, requires=["ipt"], generates=["ipt.zip"]),
PostprocessPlugin(function=index_logs, requires=[], generates=["index"]),
PostprocessPlugin(
function=index_logs, requires=["procmon.log"], generates=["index"]
),
]
@@ -1,219 +1,17 @@
import json
import logging
import pathlib
from dataclasses import dataclass, field
from typing import Any, Dict, List, Optional, TextIO
import mslex
from ..process_tree import tree_from_log
logger = logging.getLogger(__name__)
@dataclass
class Process:
seqid: int
pid: int
ts_from: float
ts_to: Optional[float]
procname: str
args: List[str]
parent: Optional["Process"] = None
children: List["Process"] = field(default_factory=list)
def __str__(self) -> str:
return f"{pathlib.PureWindowsPath(self.procname).name}(pid={self.pid}, seq={self.seqid}) {self.args}"
class ProcessTree:
def __init__(self):
self.processes: List[Process] = []
def add_process(
self,
pid: int,
ts_from: float,
procname: str,
parent: Optional[Process],
args: Optional[List[str]] = None,
) -> Process:
"""
Add a new process to tree, assign sequential id and return Process object
"""
process = Process(
seqid=len(self.processes),
pid=pid,
ts_from=ts_from,
ts_to=None,
procname=procname,
parent=parent,
args=args or [],
)
existing_process = self.get_process(pid)
if existing_process is not None and existing_process.ts_to is None:
# Found another process with the same PID
# Let's assume it's no longer active, it may happen in parse_running_process_entry
existing_process.ts_to = ts_from
self.processes.append(process)
if parent:
parent.children.append(process)
return process
def get_process(self, pid: int) -> Optional[Process]:
"""
Get last seen active process with given PID.
"""
for process in reversed(self.processes):
if process.pid == pid:
return process
return None
def __str__(self):
def print_tree_rec(depth: int, root: Process) -> str:
res = "\t" * depth + str(root) + "\n"
res += "".join([print_tree_rec(depth + 1, c) for c in root.children])
return res
roots = [p for p in self.processes if p.parent is None]
subtrees = [print_tree_rec(0, r) for r in roots]
return "\n".join(subtrees)
def as_dict(self) -> List[Dict[str, Any]]:
def tree_as_dict(root) -> Dict[str, Any]:
subtrees = [tree_as_dict(c) for c in root.children]
return {
"seqid": root.seqid,
"pid": root.pid,
"procname": root.procname,
"args": root.args,
"ts_from": root.ts_from,
"ts_to": root.ts_to,
"children": subtrees,
}
roots = [p for p in self.processes if p.parent is None]
root_subtrees = [tree_as_dict(r) for r in roots]
return root_subtrees
def parse_running_process_entry(pstree: ProcessTree, entry: Dict[str, Any]) -> None:
# We assume here that running processes are enumerated in order of creation
# (created by appending new entries to the end of EPROCESS linked list)
parent = pstree.get_process(entry["PPID"])
pstree.add_process(
pid=entry["PID"], ts_from=0.0, procname=entry["RunningProcess"], parent=parent
)
def split_commandline(cmdline: str) -> [str]:
# Procmon plugin performs extra cmdline encoding.
cmdline = cmdline.encode().decode("unicode_escape")
try:
return mslex.split(cmdline, check=False, like_cmd=False)
except Exception:
# If we fail to parse cmdline, wrap it into list, so we don't
# lose any information.
logger.info("Failed to convert commandline to args")
return [cmdline]
def parse_nt_create_user_process_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
# NtCreateUserProcess method is used to create processes from Vista+.
if int(entry["Status"], 16) != 0:
# Ignore unsuccessful entries.
return
process_pid = entry["NewPid"]
process_ppid = entry["PID"]
parent = pstree.get_process(process_ppid)
if parent is None:
# Parent must be alive at the process creation time, but who knows what happened
logger.warning(
f"Parent process not found at the process creation time (PID: {process_pid}, PPID: {process_ppid})"
)
pstree.add_process(
pid=process_pid,
ts_from=float(entry["TimeStamp"]),
procname=entry["ImagePathName"],
parent=parent,
args=split_commandline(entry["CommandLine"]) if entry["CommandLine"] else [],
)
def parse_nt_create_process_ex_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
# NtCreateProcessEx method was used to create processes up to Windows XP.
if int(entry["Status"], 16) != 0:
# Ignore unsuccessful entries.
return
process_pid = entry["NewPid"]
process_ppid = entry["PID"]
parent = pstree.get_process(process_ppid)
if parent is None:
# Parent must be alive at the process creation time, but who knows what happened
logger.warning(
f"Parent process not found at the process creation time (PID: {process_pid}, PPID: {process_ppid})"
)
pstree.add_process(
pid=process_pid,
ts_from=float(entry["TimeStamp"]),
procname="Unnamed",
parent=parent,
)
def parse_mm_clean_process_address_space_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
pid = entry["ExitPid"]
p = pstree.get_process(pid)
if p is None:
logger.warning(f"Process not found ath the process exit time (PID: {pid})")
return
p.ts_to = float(entry["TimeStamp"])
def tree_from_log(file: TextIO) -> List[Dict[str, Any]]:
pstree = ProcessTree()
prev_line = None
for line in file:
try:
if line == prev_line:
# There is still some unfixed bug in drakvuf, that duplicates some entries.
# Just ignore the duplicate.
continue
prev_line = line
entry = json.loads(line)
if "RunningProcess" in entry:
# Process has been created before the analysis started.
parse_running_process_entry(pstree, entry)
elif "Method" in entry and entry["Method"] in ["NtCreateUserProcess"]:
# Process has been created after the analysis started.
parse_nt_create_user_process_entry(pstree, entry)
elif "Method" in entry and entry["Method"] == "NtCreateProcessEx":
# Process has been created after the analysis started.
parse_nt_create_process_ex_entry(pstree, entry)
elif "Method" in entry and entry["Method"] == "MmCleanProcessAddressSpace":
# Process has been terminated.
parse_mm_clean_process_address_space_entry(pstree, entry)
except json.JSONDecodeError as e:
logger.warning(f"Line cannot be parsed as JSON\n{e}")
continue
except Exception as e:
logger.warning(f"Failed to process {entry}")
raise e
return pstree.as_dict()
def build_process_tree(analysis_dir: pathlib.Path) -> None:
procmon_log_path = analysis_dir / "procmon.log"
process_tree_path = analysis_dir / "process_tree.json"
with procmon_log_path.open("r") as procmon_log:
process_tree = tree_from_log(procmon_log)
process_tree = tree_from_log(procmon_log).as_dict()
data = json.dumps(process_tree)
process_tree_path.write_text(data)
@@ -1,57 +1,31 @@
"""
Index generated log files
DRAKVUF logs are in ndJSON (newline delimited) format. Size of output from
each plugin varies from very small (< 1KB) to very large (>1GB).
In order to present the logs in web UI, we have to load them in chunks of
some reasonable size. Unfortunately, length of JSON records is also variable
so we build and index, to quickly look up where n-th line begins.
"""
import json
import pathlib
from typing import List, TypedDict
class LineMarker(TypedDict):
line: int
offset: int
def generate_file_index(file, chunk_size=1024 * 1024):
markers: List[LineMarker] = [LineMarker(line=0, offset=0)]
current_chunk_size = 0
file_offset = 0
index = 0
for index, line in enumerate(file, start=1):
# when we've reached the limit insert new marker
if current_chunk_size + len(line) >= chunk_size:
markers.append(LineMarker(line=index, offset=file_offset))
# and reset current size
current_chunk_size = 0
current_chunk_size += len(line)
file_offset += len(line)
return {
# Chunk markers
"markers": markers,
# Total number of lines in file
"num_lines": index,
# Chunk size used for indexing
"chunk_size": chunk_size,
}
from ..indexer import index_log_file
from ..process_tree import tree_from_log
def index_logs(analysis_dir: pathlib.Path) -> None:
index_dir = analysis_dir / "index"
index_dir.mkdir(exist_ok=True)
# TODO: I need ProcessTree object but right now
# I can't easily load it from process_tree.json
procmon_log_path = analysis_dir / "procmon.log"
with procmon_log_path.open("r") as procmon_log:
process_tree = tree_from_log(procmon_log)
for log_file_path in analysis_dir.glob("*.log"):
with log_file_path.open("rb") as log_file:
index = generate_file_index(log_file)
index_path = index_dir / f"{log_file_path.name}.json"
index_data = json.dumps(index)
index_path.write_text(index_data)
plugin_name = log_file_path.stem
if plugin_name == "drakrun":
continue
index = index_log_file(
log_file_path,
process_tree,
key="Method",
)
for seqid in index.keys():
index_path = index_dir / f"{plugin_name}.{seqid}.json"
index_path.write_text(json.dumps(index[seqid]))
@@ -1,38 +0,0 @@
import json
import logging
import pathlib
logger = logging.getLogger(__name__)
def process_apimon_log(analysis_dir: pathlib.Path) -> None:
apimon_log_path = analysis_dir / "apimon.log"
target_dir = analysis_dir / "apicall"
pid_files = {}
target_dir.mkdir()
with apimon_log_path.open("r") as apimon_log:
for line_no, line in enumerate(apimon_log):
# I don't expect any encoding problems as they
# should be resolved by split_drakmon_log
entry = json.loads(line)
if entry["Event"] != "api_called":
continue
if "PID" not in entry:
logger.warning(f"Missing PID in {apimon_log_path}:{line_no}")
continue
pid = entry["PID"]
filtered_entry = {
"pid": pid,
"timestamp": entry["TimeStamp"],
"method": entry["Method"],
"arguments": entry["Arguments"],
"returnvalue": entry["ReturnValue"],
}
if pid not in pid_files:
pid_files[pid] = (target_dir / f"{pid}.json").open("w")
pid_files[pid].write(json.dumps(filtered_entry) + "\n")
for pid_file in pid_files.values():
pid_file.close()
@@ -0,0 +1,236 @@
import json
import logging
import pathlib
from dataclasses import dataclass, field
from typing import Any, Dict, List, Optional, TextIO
import mslex
logger = logging.getLogger(__name__)
@dataclass
class Process:
seqid: int
pid: int
ts_from: float
ts_to: Optional[float]
evtid_from: Optional[int]
evtid_to: Optional[int]
procname: str
args: List[str]
parent: Optional["Process"] = None
children: List["Process"] = field(default_factory=list)
def __str__(self) -> str:
return f"{pathlib.PureWindowsPath(self.procname).name}(pid={self.pid}, seq={self.seqid}) {self.args}"
class ProcessTree:
def __init__(self):
self.processes: List[Process] = []
def add_process(
self,
pid: int,
evtid_from: Optional[int],
ts_from: float,
procname: str,
parent: Optional[Process],
args: Optional[List[str]] = None,
) -> Process:
"""
Add a new process to tree, assign sequential id and return Process object
"""
process = Process(
seqid=len(self.processes),
pid=pid,
ts_from=ts_from,
ts_to=None,
evtid_from=evtid_from,
evtid_to=None,
procname=procname,
parent=parent,
args=args or [],
)
existing_process = self.get_process(pid)
if existing_process is not None and existing_process.ts_to is None:
# Found another process with the same PID
# Let's assume it's no longer active, it may happen in parse_running_process_entry
existing_process.evtid_to = evtid_from - 1
existing_process.ts_to = ts_from
self.processes.append(process)
if parent:
parent.children.append(process)
return process
def get_process_for_evtid(self, pid: int, evtid: int) -> Optional[Process]:
for process in self.processes:
if process.pid == pid:
if evtid >= process.evtid_from and (
(not process.evtid_to) or evtid <= process.evtid_to
):
return process
return None
def get_process(self, pid: int) -> Optional[Process]:
"""
Get last seen active process with given PID.
"""
for process in reversed(self.processes):
if process.pid == pid:
return process
return None
def __str__(self):
def print_tree_rec(depth: int, root: Process) -> str:
res = "\t" * depth + str(root) + "\n"
res += "".join([print_tree_rec(depth + 1, c) for c in root.children])
return res
roots = [p for p in self.processes if p.parent is None]
subtrees = [print_tree_rec(0, r) for r in roots]
return "\n".join(subtrees)
def as_dict(self) -> List[Dict[str, Any]]:
def tree_as_dict(root) -> Dict[str, Any]:
subtrees = [tree_as_dict(c) for c in root.children]
return {
"seqid": root.seqid,
"pid": root.pid,
"procname": root.procname,
"args": root.args,
"ts_from": root.ts_from,
"ts_to": root.ts_to,
"evtid_from": root.evtid_from,
"evtid_to": root.evtid_to,
"children": subtrees,
}
roots = [p for p in self.processes if p.parent is None]
root_subtrees = [tree_as_dict(r) for r in roots]
return root_subtrees
def parse_running_process_entry(pstree: ProcessTree, entry: Dict[str, Any]) -> None:
# We assume here that running processes are enumerated in order of creation
# (created by appending new entries to the end of EPROCESS linked list)
parent = pstree.get_process(entry["PPID"])
pstree.add_process(
pid=entry["PID"],
ts_from=0.0,
evtid_from=0,
procname=entry["RunningProcess"],
parent=parent,
)
def split_commandline(cmdline: str) -> [str]:
# Procmon plugin performs extra cmdline encoding.
cmdline = cmdline.encode().decode("unicode_escape")
try:
return mslex.split(cmdline, check=False, like_cmd=False)
except Exception:
# If we fail to parse cmdline, wrap it into list, so we don't
# lose any information.
logger.info("Failed to convert commandline to args")
return [cmdline]
def parse_nt_create_user_process_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
# NtCreateUserProcess method is used to create processes from Vista+.
if int(entry["Status"], 16) != 0:
# Ignore unsuccessful entries.
return
process_pid = entry["NewPid"]
process_ppid = entry["PID"]
evtid = int(entry["EventUID"], 16)
parent = pstree.get_process(process_ppid)
if parent is None:
# Parent must be alive at the process creation time, but who knows what happened
logger.warning(
f"Parent process not found at the process creation time (PID: {process_pid}, PPID: {process_ppid})"
)
pstree.add_process(
pid=process_pid,
ts_from=float(entry["TimeStamp"]),
evtid_from=evtid,
procname=entry["ImagePathName"],
parent=parent,
args=split_commandline(entry["CommandLine"]) if entry["CommandLine"] else [],
)
def parse_nt_create_process_ex_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
# NtCreateProcessEx method was used to create processes up to Windows XP.
if int(entry["Status"], 16) != 0:
# Ignore unsuccessful entries.
return
process_pid = entry["NewPid"]
process_ppid = entry["PID"]
evtid = int(entry["EventUID"], 16)
parent = pstree.get_process(process_ppid)
if parent is None:
# Parent must be alive at the process creation time, but who knows what happened
logger.warning(
f"Parent process not found at the process creation time (PID: {process_pid}, PPID: {process_ppid})"
)
pstree.add_process(
pid=process_pid,
ts_from=float(entry["TimeStamp"]),
evtid_from=evtid,
procname="Unnamed",
parent=parent,
)
def parse_mm_clean_process_address_space_entry(
pstree: ProcessTree, entry: Dict[str, Any]
) -> None:
pid = entry["ExitPid"]
evtid = int(entry["EventUID"], 16)
p = pstree.get_process(pid)
if p is None:
logger.warning(f"Process not found ath the process exit time (PID: {pid})")
return
p.ts_to = float(entry["TimeStamp"])
p.evtid_to = evtid
def tree_from_log(file: TextIO) -> ProcessTree:
pstree = ProcessTree()
prev_line = None
for line in file:
try:
if line == prev_line:
# There is still some unfixed bug in drakvuf, that duplicates some entries.
# Just ignore the duplicate.
continue
prev_line = line
entry = json.loads(line)
if "RunningProcess" in entry:
# Process has been created before the analysis started.
parse_running_process_entry(pstree, entry)
elif "Method" in entry and entry["Method"] in ["NtCreateUserProcess"]:
# Process has been created after the analysis started.
parse_nt_create_user_process_entry(pstree, entry)
elif "Method" in entry and entry["Method"] == "NtCreateProcessEx":
# Process has been created after the analysis started.
parse_nt_create_process_ex_entry(pstree, entry)
elif "Method" in entry and entry["Method"] == "MmCleanProcessAddressSpace":
# Process has been terminated.
parse_mm_clean_process_address_space_entry(pstree, entry)
except json.JSONDecodeError as e:
logger.warning(f"Line cannot be parsed as JSON\n{e}")
continue
except Exception as e:
logger.warning(f"Failed to process {entry}")
raise e
return pstree
-4
View File
@@ -21,10 +21,6 @@ class AnalysisStorage:
def _check_path(self, path):
return check_path(path, self.analysis_dir)
def get_apicalls(self, pid):
"""Download API calls of this process"""
return self._check_path(self.analysis_dir / "apicall" / f"{pid}.json")
def get_processed(self, name):
"""Download post-process results"""
return self._check_path(self.analysis_dir / f"{name}.json")
+24 -15
View File
@@ -7,12 +7,14 @@ from tempfile import NamedTemporaryFile
from zipfile import ZIP_DEFLATED, ZipFile
import magic
from flask import Flask, jsonify, request, send_file, send_from_directory
from flask import Flask, Response, jsonify, request, send_file, send_from_directory
from orjson import orjson
from rq.exceptions import NoSuchJobError
from rq.job import Job
from drakrun.analyzer.analysis_options import AnalysisOptions
from drakrun.analyzer.file_metadata import FileMetadata
from drakrun.analyzer.postprocessing.indexer import scattered_read_file
from drakrun.analyzer.worker import enqueue_analysis, get_redis_connection
from drakrun.lib.config import load_config
from drakrun.lib.paths import ANALYSES_DIR
@@ -140,15 +142,6 @@ def processed(task_uid, which):
return send_file(path, mimetype="application/json")
@app.route("/processed/<task_uid>/apicall/<pid>")
def apicall(task_uid, pid):
analysis = get_analysis_data(task_uid)
path = analysis.get_apicalls(pid)
if not path.exists():
return dict(error="Data not found"), 404
return send_file(path, mimetype="application/json")
@app.route("/logs/<task_uid>/<log_type>")
def logs(task_uid, log_type):
analysis = get_analysis_data(task_uid)
@@ -158,13 +151,29 @@ def logs(task_uid, log_type):
return send_file(path, mimetype="text/plain")
@app.route("/logindex/<task_uid>/<log_type>")
def logindex(task_uid, log_type):
@app.route("/logs/<task_uid>/<log_type>/process/<seqid>")
def process_logs(task_uid, log_type, seqid):
analysis = get_analysis_data(task_uid)
path = analysis.get_log_index(log_type)
if not path.exists():
index_path = analysis.get_log_index(f"{log_type}.{seqid}.json")
if not index_path.exists():
return dict(error="Data not found"), 404
return send_file(path, mimetype="application/json")
index = orjson.loads(index_path.read_text())
blocks = index["blocks"]
filter_values = request.args.getlist("filter")
if filter_values:
filter_indices = [
index["values"].index(filter_value)
for filter_value in filter_values
if filter_value in index["values"]
]
blocks = [
block
for (block, mapping) in zip(index["blocks"], index["mapping"])
if mapping in filter_indices
]
log_path = analysis.get_log(log_type)
scattered_read = scattered_read_file(log_path, blocks)
return Response(b"".join(scattered_read), mimetype="text/plain")
@app.route("/pcap_dump/<task_uid>")