Repository navigation
Architecture
DAD is a Rails application plus two long-running Ruby processes and one Rust collector. The web UI is the least important part: if the importer is down, you have a search engine over nothing.
┌──────────────────────────────────────────────┐
syslog/UDP:514 ───► │ syslog_collector (dad-syslog) │
│ writes Logs/LogStaging/syslog.<epoch> │
│ rotates it on a 60s boundary, but only │
│ when a packet arrives; renames to │
│ Logs/LogsToProcess at that point │
└──────────────────────────────────────────────┘
│
┌──────────────────▼───────────────────────────┐
│ import_syslog.rb (dad-importer) │
│ claims each file (.processing sidecar) │
│ EventIngestor.storeEvent → events + words │
│ moves the file to Logs/ProcessedLogs │
│ purges ProcessedLogs older than 7 days │
└──────────────────┬───────────────────────────┘
│ PostgreSQL
┌──────────────────▼───────────────────────────┐
│ Rails app (Passenger/Apache) │
│ search, alerts, dashboards, users/roles │
│ │
│ scheduler.rb (dad-scheduler) │
│ runs due Job rows through a fixed handler │
│ registry — no user-authored code is run │
│ (loop body in JobScheduler, so it is │
│ testable and one bad row cannot stop the │
│ rest) │
└──────────────────────────────────────────────┘
The two halves of that pipeline resolve their log paths differently, and nothing
checks that they agree. The collector hardcodes absolute paths —
DEFAULT_STAGING = "/var/DAD/Logs/LogStaging", DEFAULT_PROCESSING = "/var/DAD/Logs/LogsToProcess", in syslog_collector/src/runtime.rs. import_syslog.rb uses paths relative to its own
working directory: it Dir.chdirs into Logs/LogsToProcess and reaches
ProcessedLogs as ../ProcessedLogs. The diagram above is only accurate because
every systemd unit sets WorkingDirectory=/var/DAD. Run either process from
anywhere else and the collector keeps accepting UDP packets and writes into a tree
the importer never reads — silently, with no error on either side. The Docker image
uses WORKDIR /var/DAD for this reason; see Development.
Two consequences that read as bugs when you are watching a quiet system:
-
Rotation is traffic-driven.
ensure_openis called from the per-message path, so the rename intoLogsToProcesshappens on an inbound packet, not on a timer. With no traffic the staging file stays open and the importer has nothing to claim. This is why a single probe packet into a quiet system sits inLogStaginguntil a second packet arrives after the 60s boundary. -
A file left in
LogStagingis invisible until the collector restarts. The importer reads onlyLogsToProcess, so anything stranded inLogStagingis unreadable — until the next collector start, which moves it intoLogsToProcessbefore binding. That recovery is deliberate: it covers crashes, OOM kills, and power loss, which a shutdown handler cannot.
The Logs/ directory is the handoff: the collector writes it, the importer
consumes it, and nothing else should touch it. That constraint is load-bearing,
not stylistic — the collector's startup recovery moves every file it finds in
LogStaging into LogsToProcess, on the assumption it is the only writer there.
A second writer in that directory gets its in-progress file renamed away
mid-append. Windows events therefore arrive through separate directories,
Logs/Windows and Logs/WindowsStaging, and are enqueued into LogsToProcess
by a rename — whichever collection path produced them. See Windows Events.
| unit | runs | loop |
|---|---|---|
dad-syslog |
syslog_collector (Rust) |
rotates the staging file every 60s |
dad-importer |
import_syslog.rb |
one pass every 60s; purge every 12h |
dad-scheduler |
scheduler.rb |
due Job rows every 60s |
dad-windows |
import_windows_events.rb |
optional; tails OpenWEC output every 10s |
Windows hosts polled directly add no unit: poll_windows_events is a Job, so
the poller runs inside dad-scheduler, and it publishes to the same staging and
queue directories the OpenWEC forwarder uses. See Windows Events.
The first three run as www-data under systemd with Restart=always; dad-syslog
binds port 514 with CAP_NET_BIND_SERVICE rather than running as root, and is the
only unit with no EnvironmentFile — the collector has no business holding
database credentials. See systemd/README.md in the repo.
Every staging line begins with the address the collector saw the packet arrive
from, and that address is what EventIngestor files as the System. That is
right for a host sending syslog directly, and wrong for the Docker stack.
Under Docker, every container's syslog log driver sends from the bridge
gateway, so all of them arrive carrying the same address and collapse into a
single System row — while the container name, the only host identity the line
carries, sits in the application slot, because Docker's default frame omits the
RFC 3164 hostname slot:
172.18.0.1 Nov 13 15:14:49 dad-web[149784]: Started GET /users/logon
lib/syslog_source.rb resolves the application and host slots structurally
rather than positionally. The marker is the pid slot: an application is followed
by its pid and a colon, and stage_event's sanitizer replaces [ and ] with
spaces, leaving the : stranded between them. So by the time tokens exist, the
marker is the triple dad-web 149784 :. A hostname slot has no pid after it,
so whichever token owns the pid slot is the application, whichever frame shape
arrived.
Two things worth knowing before reading that line:
-
The pid is
dockerd's, not the container's, and it is the same number for every container on the host. It carries no per-process information and is never used as an identity. - The container name is filed in
systems.address, notsystems.name.addressis whatSystem.find_or_addkeys identity on;nameis an operator-assigned label.
The rename is gated on the source address being one of this container's own
default-route gateways and the importer actually running in a container.
Without the second gate, a systemd deployment would rename any syslog arriving
from the LAN router — routers do send syslog, and their address is their gateway.
A remote host's address is its own identity and is never rewritten.
DAD_SYSLOG_SELF_HOST=none disables the rewrite entirely.
The same rule fixes a mis-parse that has nothing to do with Docker. RFC 3164 as rsyslog forwards it by default does carry a hostname slot:
10.0.0.5 Jun 1 12:00:00 web01 sshd[4242]: Accepted publickey for bob
Reading positionally filed web01 as the Service — and the Service sanitizer
strips digits, so the row said web — and dropped sshd entirely.
The Windows forwarder is unaffected: it emits <host> <ISO-8601> <provider> …
with no pid slot, so it takes the positional fallback and keeps the host it
states. See Windows Events.
Ingest tokenises each line on whitespace. Every distinct token becomes a row in
words; events_words links (event_id, word_id) and carries its own
generated column so the join can be partitioned and pruned alongside events.
events.hunks holds the original, unmodified log line.
events_words carries exactly one index: the composite
(word_id, generated, event_id), which search reads as a covering index. It used
to carry a second, standalone index on generated, added in 2015. Nothing could
use it — search always restricts on word_id, and retention drops whole
partitions rather than deleting by timestamp — but every insert still had to
extend it. It cost 28 bytes per row (~2.8 GB at 100M rows) and 5.1% of insert
time, and removing it changed no search plan or timing. See
What Changed Since 2016.
Searching is a lookup of words by text followed by a scan of events_words —
see Search. There is no full-text index, no phrase matching, and no word
position data.
On PostgreSQL, events and events_words are range-partitioned by month
(events_pYYYYMM), which is what makes retention cheap: dropping a month is a
DROP TABLE on its partition rather than a DELETE that rewrites every index.
PostgreSQL is the engine in every environment — development, test and production.
SQLite was dropped as a development and test engine precisely because it has no
partitioning at all, so a SQLite run never exercised the shape production queries.
See Development.
Raw SQL is written with ? placeholders and routed through SqlPlaceholders.query,
which rewrites them to $1, $2, …. That translation layer is not multi-engine
support: it is the single seam where the placeholder form Rails documents becomes
the form PostgreSQL wants, and it is the seam through which the worst bug in the
project's history shipped. extract() is avoided in favour of
substr(cast(<ts> as text),1,13) for the dashboard's hourly buckets.
Ingest is at-least-once, not exactly-once. The importer claims each file by
renaming it to <name>.processing, and checkpoints a byte offset in a sidecar
only once that batch's rows are committed. A crash mid-file leaves the
.processing file; the next pass reclaims it and resumes at the offset, so
committed rows are never re-inserted and no line is lost. A crash with a batch
still in flight re-reads that batch, so up to one batch's events can be
duplicated — and in production a batch starts at 2000 lines and grows with
throughput.
The consequence: anything that counts events — dashboards, alert thresholds,
Statistic rates — is approximate across a crash boundary. This is a deliberate
trade-off, and test/import_syslog_crash_test.rb pins both halves.
A line that raises StandardError is logged at warn, counted as a Statistic
series, and skipped. One bad record no longer wedges the pipeline, which it used
to do permanently.
A flush writes its batch as multi-row INSERTs, chunked to whatever the database
allows in bind parameters per statement (65,535 on PostgreSQL),
with all chunks committed in one transaction. So a batch is still
all-or-nothing: a failure part-way through leaves no events_words row pointing
at an event that was never written.
The chunking is what makes batch size a free parameter. events_words is the
binding table — three columns, and roughly sixteen index rows per event — so a
2000-event batch needs on the order of 96,000 parameters, past both limits.
Before chunking, a production-sized batch failed the flush outright with
too many SQL variables. Batch size is now bounded by memory and by how much
duplication you will tolerate across a crash, not by the database.
A token already in the word cache (below) is stamped and indexed as the line is
parsed. A token that is not in the cache is not looked up at that moment — it
is held, together with the event id and generated value it came from, until the
batch is flushed. At flush the whole batch's unknown tokens are resolved at once:
one indexed lookup for the words that already exist, one bulk insert for the rest,
chunked so neither statement approaches the bind-parameter limits described above.
That batching is the single largest factor in ingest throughput. On 20,000 realistic syslog lines holding 46,450 distinct words, resolving each token as it was parsed issued 186,089 statements and 46,515 transactions; resolving them per batch issues 360 and 67. End to end:
| situation | before | after | |
|---|---|---|---|
words table empty (first run, backfill) |
23.15 s | 3.62 s | 6.4× |
words already populated (steady state) |
8.43 s | 3.57 s | 2.36× |
Use the second row when sizing a running collector and the first when sizing a backfill.
The events_words rows written are identical either way — 1,153,964 rows and
46,450 words for an 80,000-event corpus, before and after, with no orphaned rows
and no null word_ids — so this is not a change to what the index contains, only
to how quickly it gets built. Search plans and timings are unaffected.
One consequence worth knowing: a word seen for the first time reaches the words
table only when its batch is flushed. On a crash it is re-read along with the rest
of that batch, which is the same at-least-once boundary described above rather
than a new one.
EventIngestor caches token → word id in memory to keep ingest off the words
table entirely for words it has already seen. It is pruned by TTL, not by size:
once more than 100,000 words are cached, the next flush drops entries not used
within cache_lifetime seconds and nudges that lifetime up or down to keep the
cache near 100,000. The lifetime starts at 320 seconds. The prune_words job
calls the same routine by hand. See Jobs.
A word resolved during a flush is added to the cache, which is what makes the
steady-state case cheap: after the first batch that contains a token, no batch
issues any statement against words for it again while it stays cached.
Statistic rows are append-only samples written by the ingestion pipeline and
charted on the dashboard. type_id selects the series and the numbers are baked
into existing rows, so a series can be added but never renumbered:
-
0— lines processed per importer pass -
1— events/sec per flush -
2— log lines skipped as unprocessable, per importer pass