Current section
Files
Jump to
Current section
Files
clickhouse_ex_logger
README.md
README.md
# ClickhouseExLogger
Ship Elixir [`Logger`](https://hexdocs.pm/logger/Logger.html) events into
ClickHouse, through [Ash](https://hexdocs.pm/ash) and
[AshClickhouse](https://hexdocs.pm/ash_clickhouse), so they land in a table you
can `SELECT` against instead of a file you have to grep.
Logging stays non-blocking: `Logger.info/1` formats a row and hands it to a
buffer process. Batches are written with one insert each. If ClickHouse is slow
or down, the oldest buffered rows are discarded and counted — your application
never blocks and never runs out of memory.
## Installation
```elixir
def deps do
[{:clickhouse_ex_logger, "~> 0.1.0"}]
end
```
## Setup
Three steps. There is no application code to write: the library starts its own
pipeline when your application starts.
**1. Configure the connection.**
```elixir
# config/runtime.exs
config :clickhouse_ex_logger, ClickhouseExLogger.Repo,
url: System.get_env("CLICKHOUSE_URL", "http://localhost:8123"),
username: System.get_env("CLICKHOUSE_USER", "default"),
password: System.get_env("CLICKHOUSE_PASSWORD", ""),
database: "my_app"
```
That key is required, and a missing one is an error rather than a default:
```
** (AshClickhouse.Error.ConfigurationError) ClickhouseExLogger.Repo is not configured.
```
Without the check it would fall back to `http://localhost:8123` and quietly
write your logs somewhere you did not choose — or report every flush as failed,
which looks like a ClickHouse outage rather than a configuration mistake.
`username:` and `password:` authenticate the connection, as written — no URL
surgery in your `runtime.exs`. Against a password-protected server that is the
only change you need:
```sh
export CLICKHOUSE_URL=http://clickhouse.internal:8123
export CLICKHOUSE_USER=writer
export CLICKHOUSE_PASSWORD=... # the password is percent-encoded for you
```
<details>
<summary>Upgrading from a version that ignored these keys</summary>
Before this, `:username` and `:password` were accepted and then discarded: the
data layer forwards only `:url`, and the client beneath it has no credential
option. A password-protected server answered every request with
`Code: 194 ... Authentication failed`, reported and counted as lost — the same
as an outage. If you worked around it by building the credentialed URL yourself
in `config/runtime.exs`, delete that: the library does it now.
If you would rather keep the old behaviour — a server that ignores
authentication, say — put the credentials in the URL instead. A URL that already
carries them is used verbatim, and `:username`/`:password` are then ignored:
```elixir
config :clickhouse_ex_logger, ClickhouseExLogger.Repo,
url: "http://writer:s3cret@clickhouse.internal:8123",
database: "my_app"
```
</details>
**2. Create the schema.** Run this from your application *before* you start it, so
the first flush has somewhere to go.
```sh
mix clickhouse_ex_logger.migrate
```
It creates the database if it is missing and the `logs` table if it is not, and
is safe to re-run. To see what it would do without changing anything:
```sh
mix clickhouse_ex_logger.migrate --dry-run
```
In a release — where there is no Mix and no `mix` on the machine — call the same
operation instead:
```sh
bin/my_app eval "ClickhouseExLogger.Utils.migrate()"
bin/my_app eval "ClickhouseExLogger.Utils.migrate(dry_run: true)"
```
Both do exactly the same thing: same migrations, same files shipped in
`priv/repo/migrations`, same connection configuration. Run either *before* the
new version starts logging.
> **Upgrading an existing deployment? Run this again.** A later version of this
> library writes a `node` column that tables created by an earlier version do not
> have, and ClickHouse rejects the whole batch — `No such column node in table`.
> Nothing raises in your application; the rows are simply counted as `lost`. So
> run this command as part of the deploy, *before* the new version starts
> logging. The command is the same one you already run; you just have to run it
> again — `mix clickhouse_ex_logger.migrate` from a checkout, or
> `bin/my_app eval "ClickhouseExLogger.Utils.migrate()"` from a release.
> Use this task, not `mix ash_clickhouse.migrate`. That task finds AshClickhouse
> resources by listing the modules of the *current* project, so it never sees
> `ClickhouseExLogger.LogEntry` — that resource belongs to this dependency.
**3. Start logging.**
That is the whole setup. Starting your application starts the ClickHouse
connection and attaches the handler; there is nothing to add to your supervision
tree and nothing to call.
If you want proof rather than an absence of surprise, ask the library:
```elixir
ClickhouseExLogger.status()
#=> %{
#=> handler_attached?: true,
#=> buffer_active?: true,
#=> last_start: {:attached, "ClickhouseExLogger: attached the `:logger` handler; …"},
#=> stats: %{accepted: 0, delivered: 0, discarded: 0, lost: 0, failed: 0, buffered: 0},
#=> boot_capture: %{active?: false, held: 0, dropped: 0}
#=> }
```
That is "my rows are on their way to ClickHouse", answered without reading a log,
querying the table, or waiting on anything. See
[When no rows arrive](#when-no-rows-arrive) for the same call on the paths that
fail.
The library reads one thing at startup that is worth knowing about. It checks
whether the `logs` table exists before it attaches:
- **Table is there** — the handler attaches. This is the normal case.
- **Server does not answer** — the handler attaches anyway, and delivery failures
are reported and counted like any other. A ClickHouse that is briefly down at
boot does not turn your logging off.
- **Table is missing** — the handler does *not* attach, and you get one error
naming `mix clickhouse_ex_logger.migrate`. This is the "you forgot step 2" case,
and you get a sentence rather than a `lost` count that looks like an outage.
Create the table and restart.
Read the check itself: it is one `SELECT count()` against `system.tables`. Nothing
is created or altered at boot, ever — see
[`ClickhouseExLogger.Migration`](https://hexdocs.pm/clickhouse_ex_logger/ClickhouseExLogger.Migration.html).
### Events logged while the application starts are held, not lost
Attaching the handler takes a moment — the check above has to answer first — and
your own `Application.start/2` logs inside exactly that window. Those events are
captured from the moment this library's application starts and written with the
first batch the handler ships, in the order they were logged. Nothing is written
before the check answers, so a missing table still produces the one readable
message above rather than a failed write.
The hold is bounded by your `:max_buffer_size`: past it the oldest held row is
dropped to admit the newest, exactly as the buffer does, and the drop is reported
once, naming how many rows were dropped and the bound. A dropped row is not added
to the buffer's counters — it was never accepted — so the counters still reconcile
exactly.
Two limits are worth knowing. Events logged *before* this library's application
starts — by its dependencies, or by the VM's earliest boot — still reach only the
console: a dependency has no hook earlier than its own start. And your console
output is unchanged throughout: the hold adds a destination, it does not remove
one.
While rows are being held, `ClickhouseExLogger.status/0` says so:
`boot_capture.active?` is `true` and `held` is how many rows are waiting, so you
can tell "captured, waiting to be shipped" from "shipping now" without reading a
log.
### You do not need to configure `:logger`
There is no `:logger` configuration for this library, and none is missing if you
have not written any. What a host reaches for in its place is
`config :logger, :default_handler, config: [file: …]` — which configures Erlang's
**default** handler, the one that prints to your console, and nothing else. It
decides where *that* handler writes: standard output, or a rotating file. This
library's handler is registered separately, alongside it, and is unaffected either
way.
So if rows are not arriving, do not look for a `:logger` key to set. What that
config does affect is where this library's *own* reports go — and a report you
cannot see is indistinguishable from a library that works. Read
[When no rows arrive](#when-no-rows-arrive) instead.
The reverse is also worth knowing: adding the block above does not switch anything
on. It moves your console output into a file, which is why it sometimes looks like
the thing that made logging work when in fact it made a message about logging
visible somewhere you happened to be reading.
## Dashboard
Dashboard with basic search/filter & analysis in this [repo](https://github.com/ohhi-vn/logger_dashboard).
### Upgrading from 0.2.x
0.3.0 starts the pipeline itself. **If your application supervises
`ClickhouseExLogger.Repo`, add this to your configuration before you upgrade:**
```elixir
config :clickhouse_ex_logger, auto_start: false
```
Without it your application will not boot:
```
** (EXIT from #PID<0.123.0>) shutdown: failed to start child: ClickHouse.Interface.HTTP
** (EXIT) an exception was raised:
** (ArgumentError) errors were found at the given arguments:
* 1st argument: table name already exists
```
A ClickHouse client keeps a globally named ETS table per connection, so a second
connection under the same name cannot be started — the client raises from inside
the new process, and your supervisor takes the failure. This library starts the
connection; your supervision tree would be starting the same one.
With `auto_start: false` your existing code works unchanged: keep
`ClickhouseExLogger.Repo` in your children and your
`ClickhouseExLogger.Handler.install/2` call exactly as they are. Nothing else
about 0.2.x's setup changed. If you had no application code, delete nothing —
just upgrade.
## Configuration
All keys are optional except the connection block above.
### The connection
Set once, under `config :clickhouse_ex_logger, ClickhouseExLogger.Repo`. The
supported keys are those of `AshClickhouse.Repo`: `:url`, `:username`,
`:password`, `:database`, `:pool_size`, and `:ipv4_only`.
| Key | Meaning |
| --- | --- |
| `:url` | ClickHouse HTTP endpoint, e.g. `"http://localhost:8123"`. |
| `:username` | Authenticates as this user. A value other than `"default"` is sent even with no password. |
| `:password` | Sent as the password. Percent-encoded into the URL, so `@` and `:` need no escaping. |
| `:database` | Database holding the `logs` table. |
A URL that already carries credentials — `http://user:pass@host:8123` — is used
as-is and the two keys above are ignored. Omitting `:username` alongside a
`:password` authenticates as `default`. Leaving both at their defaults sends no
credentials at all, which is what a password-less local ClickHouse wants.
### `:auto_start`
| Key | Default | Meaning |
| --- | --- | --- |
| `:auto_start` | `true` | Whether the library starts the pipeline itself. See [Upgrading from 0.2.x](#upgrading-from-02x). |
### `:handler`
The options the automatically-started handler uses. Same options, same
validation, same defaults as the table below:
```elixir
config :clickhouse_ex_logger, handler: [level: :info, batch_size: 500]
```
| Key | Default | Meaning |
| --- | --- | --- |
| `:level` | `:all` | Minimum level to ship. `:logger` filters on this. |
| `:batch_size` | `500` | Buffered rows that trigger a write. |
| `:flush_interval_ms` | `1_000` | How often to write a partial batch. |
| `:max_buffer_size` | `10_000` | Hard cap on buffered rows. |
| `:include_node` | `true` | Record the node name on each row. See [below](#node-tells-you-which-machine). |
`:batch_size` is a **trigger, not a cap**: a write always takes everything
buffered, so a slow write lets rows accumulate rather than leaving a remainder
behind.
A value that is not a positive integer fails the start with an error naming the
option, rather than failing later during delivery. A non-boolean `:include_node`
fails the same way.
`:include_node` is a *handler* option rather than a batching one, so it does not
appear in `Buffer.options()`.
## Starting it yourself
`Handler.install/2` and `Handler.uninstall/1` are still there, and still what the
automatic start calls. Reach for them when you set `:auto_start` to `false` and
want the same behaviour from your own code:
```elixir
def start(_type, _args) do
children = [
ClickhouseExLogger.Repo,
MyAppWeb
# ...
]
with {:ok, pid} <- Supervisor.start_link(children, strategy: :one_for_one, name: MyApp.Supervisor) do
:ok = ClickhouseExLogger.Handler.install(:clickhouse_ex_logger, batch_size: 500)
{:ok, pid}
end
end
```
`Handler.install/2` registers the `:logger` handler and starts the batching
buffer. `Handler.uninstall/1` removes the handler and flushes what is still
buffered, so call it from your shutdown path if you have one:
```elixir
ClickhouseExLogger.Handler.uninstall(:clickhouse_ex_logger)
```
`Handler.install/2` is idempotent where it matters: a running buffer is reused
rather than duplicated, and an already-registered handler id is not registered
twice. So calling it while the automatic start has already attached does not give
you two handlers or two writers.
### Declarative registration
You can also register through `:logger` directly:
```elixir
config :my_app, :logger,
handler: [
{:handler, :clickhouse_ex_logger, ClickhouseExLogger.Handler,
%{batch_size: 500, flush_interval_ms: 1_000, max_buffer_size: 10_000}}
]
```
then `Logger.add_handlers(:my_app)` from `Application.start/2`.
Prefer `Handler.install/2`. Declarative registration hands the config straight to
`:logger`, which neither validates it nor gives this library a hook to flush on
removal — so a typo in `:batch_size` shows up as a misbehaving buffer rather than
an error at boot, and removing the handler discards whatever was buffered.
## The `logs` table
| Column | ClickHouse type | Meaning |
| --- | --- | --- |
| `id` | `UUID` | Unique identifier for the row |
| `timestamp` | `DateTime64(6)` | When the event was logged (UTC) |
| `level` | `String` | Erlang severity, e.g. `"info"` |
| `message` | `String` | The rendered log message |
| `module` | `Nullable(String)` | Calling module |
| `file` | `Nullable(String)` | Calling file |
| `line` | `Nullable(Int64)` | Calling line |
| `function` | `Nullable(String)` | Calling function/arity |
| `metadata` | `Map(String, String)` | Log metadata, values stringified |
| `node` | `Nullable(String)` | Node that handled the event, or `NULL` |
### `node` tells you which machine
Every row records the node that handled it — `my_app@10.0.0.5`, the full name, so
two applications sharing a host stay distinguishable. That is what makes
`WHERE node = 'my_app@10.0.0.5'` answer "which instance threw this".
It is `NULL` in two cases, and both are deliberate:
- **The system is not distributed** — a local `iex -S mix`, or the test suite,
where the node is `:nonode@nohost`. There is no host to report, and a stored
`nonode@nohost` is indistinguishable from a real host at a glance.
- **The host disabled capture** with `:include_node: false`.
So distributed rows are filterable in one step:
```sql
SELECT node, count() FROM logs WHERE node IS NOT NULL GROUP BY node
```
Turning the option off writes `NULL`; it does not remove the column. The schema is
the same either way, so a query written against `node` keeps working and turning
capture back on needs no migration.
`ENGINE = MergeTree()`, `ORDER BY (timestamp)` — so time-range queries prune
parts. Read rows back with plain SQL, or with Ash:
```elixir
ClickhouseExLogger.LogEntry
|> Ash.Query.filter(level == :error)
|> Ash.Query.sort(timestamp: :desc)
|> Ash.Query.limit(20)
|> Ash.read!()
```
### Two things about `id`
It is an identifier, not a uniqueness constraint. ClickHouse deduplicates by
*sorting key*, not by primary key, so it will happily store two rows with the same
`id`. It exists so you can cross-reference a specific row.
### Metadata values are strings
The column is `Map(String, String)`, so `ClickhouseExLogger.Event` renders every
value as text. Binaries pass through; other scalars go through `to_string/1`;
compound terms are stored as `inspect/1` output behind a `"term:"` marker so they
can be told apart from a genuine string and read back:
```elixir
"term:[1, 2]"
|> String.replace_prefix("term:", "")
|> Code.eval_string()
#=> {1, 2}, [1, 2]
```
Erlang's own event keys (`:mfa`, `:file`, `:line`, `:time`, …) are lifted into
their own columns and deliberately left out of the metadata map.
## Observing the pipeline
```elixir
ClickhouseExLogger.Buffer.stats()
#=> %{
#=> accepted: 12_480, # rows taken from the handler
#=> delivered: 12_470, # rows ClickHouse confirmed
#=> discarded: 10, # rows dropped because the buffer was full
#=> lost: 0, # rows ClickHouse did not accept, after a failed write
#=> failed: 0, # flushes that failed
#=> buffered: 0, # rows waiting right now
#=> active?: true # the buffer is running and accepting
#=> }
```
Read these as follows:
- **`accepted == delivered + discarded + lost`**, exactly, once nothing is in
flight. Every row the handler accepted is accounted for. A `discarded` count
that climbs means logging outpaces ClickHouse; a `lost` count that climbs
means ClickHouse refused rows.
- **`discarded`** counts rows dropped oldest-first, so the buffer stays bounded.
- **`lost`** counts rows a failed write did not get accepted. One flush is
several inserts, and the ones before a failure are already committed, so this
is counted per row rather than per flush.
- **`failed` counts flushes, not rows.** One bad batch is one failure no matter
how many rows it held.
- **`active?: false`** means the buffer is not running — the handler will keep
accepting events and dropping them.
A failed write logs one error, marked so it does not become a row itself:
```
ClickhouseExLogger: dropped 500 buffered log row(s); the ClickHouse insert failed: …
```
Nothing is retried. A log pipeline that queues behind a database turns a
downstream outage into an upstream memory leak.
### When no rows arrive
Call one function rather than reading a log, comparing destinations, or guessing:
```elixir
ClickhouseExLogger.status()
#=> %{
#=> handler_attached?: true,
#=> buffer_active?: true,
#=> last_start: {:attached, "ClickhouseExLogger: attached the `:logger` handler; …"},
#=> stats: %{accepted: 12_480, delivered: 12_470, discarded: 10, lost: 0,
#=> failed: 0, buffered: 0, active?: true},
#=> boot_capture: %{active?: false, held: 0, dropped: 0}
#=> }
```
Three of the fields answer "what is true now" and one answers "what did the start
decide", and that split is what makes the causes below separable — they would
otherwise look identical, because none of them accepts a row.
| What you see | Cause | What to do |
| --- | --- | --- |
| `handler_attached?: false` | The start declined to attach. `last_start`'s reason says why. | Read the reason. If it names the table, run [`mix clickhouse_ex_logger.migrate`](#setup). If it names an option, that option is invalid. |
| `handler_attached?: true`, `stats.accepted: 0` | Nothing is logging. The pipeline is fine and waiting. | Check your host's log level — events below `:level` never reach the handler. |
| `handler_attached?: true`, `accepted` climbing, `delivered` flat, `failed` climbing | ClickHouse is refusing the rows. | `stats.last_start`/the reported error names the reason. A missing column means the table predates a version — re-run the migration. |
| `handler_attached?: true`, `discarded` climbing | Logging outruns ClickHouse and the buffer is full. | Raise `:max_buffer_size`, or make ClickHouse faster. |
| `buffer_active?: false` | The buffer is not running, so every row is dropped silently. | The application may not have started it — check `:auto_start` and your supervision tree. |
| `boot_capture.active?: true` | Start-up has not finished deciding yet and rows are being held, not shipped. | Wait for start-up to finish; `held` is how many rows are waiting. |
| `last_start: :pending` | Nothing decided yet, or you set `:auto_start: false` and installed the handler yourself. | Wait for start-up to finish, or look at your own install call's result. |
`status/0` never contacts ClickHouse, so it works when ClickHouse is the thing
that is broken — which is the moment you call it. The two cases a `:logger`
configuration would have hidden are now unreachable by design: a start that did
not attach writes its reason to the standard error stream as well as through the
logger, so it is visible whether or not your `config :logger, :default_handler`
sends console output to a file.
For the counters themselves, read `stats/0` the way it is documented above:
`accepted == delivered + discarded + lost` once nothing is in flight, so a gap you
cannot explain is a row that was counted.
## Development
The suite starts its own ClickHouse, in a container, so you need a container
engine and nothing else:
```sh
podman machine start # or start Docker Desktop
mix test
```
`test/test_helper.exs` provisions the container, waits for it, creates the
schema, and points the suite at it. There is nothing to start by hand.
If no engine is reachable, `mix test` fails and says so. It does not skip the
ClickHouse-backed tests: a suite that quietly excludes the tests proving the
pipeline survives a stalled database is worse than one that tells you it cannot
run. The four modules that need no database still pass without an engine
(`mix test test/clickhouse_ex_logger/event_test.exs` and friends).
The container is reused between runs, so only the first one pays ClickHouse's
startup. To remove it:
```sh
podman rm -f $(podman ps -q --filter ancestor=clickhouse/clickhouse-server:26.9)
```
Set `CONTAINER_ENGINE_HOST` if your engine's socket is somewhere
`testcontainer_ex` does not look — with `podman machine` this is already handled,
but the socket path moves between machines and macOS releases. `CONTAINER_ENGINE`
forces a specific engine.
### Releasing
Releasing is a deliberate, manual act. `mix hex.publish` is irreversible in
practice: the name is taken on hex.pm, and anyone who published can be seen doing
so. Authenticate once with `mix hex.user auth`.
Run these in order. Each one catches something the next would otherwise ship.
```sh
mix test --cover # 204 tests; lib/ is gated at 90% line coverage
mix docs # must build with no warnings — Hex rebuilds this on publish
mix hex.build # writes clickhouse_ex_logger-<version>.tar
```
Then read the file list `mix hex.build` prints, and confirm the two shipped
migrations are in it:
```
priv/repo/migrations/20260101000000_create_logs.exs
priv/repo/migrations/20261001000000_add_node_to_logs.exs
```
This is the step that matters most. `mix clickhouse_ex_logger.migrate` resolves its
migrations through `:code.priv_dir/1`, so a release whose manifest omits `priv`
installs cleanly, compiles cleanly, and then raises `{:error, :bad_name}` the first
time a host runs the migration — the one step every host must run before it can log
anything. `test/mix_project_test.exs` asserts the manifest covers what `lib/`
resolves, so `mix test` already fails if that regresses.
Push the tag before publishing, not after. The published documentation points its
per-module source links at `v<version>`, so the tag has to exist when Hex builds
the docs:
```sh
git tag -a v0.1.0 -m "v0.1.0"
git push origin main --tags
mix hex.publish
```
To publish documentation for a version already on hex.pm without republishing the
package, use `mix hex.publish docs`. A release can be withdrawn for one hour after
publication with `mix hex.publish --revert VERSION`.
## A note on `ash_clickhouse`
The library writes through the data layer's batched insert,
`Ash.bulk_create/4`. Doing that needs two upstream fixes: the data layer must not
leak Ash's internal bulk options into the client option list, and it must encode
`DateTime64` in the form ClickHouse's JSON insert accepts (a fractional-second
number, not an integer tick count, which the JSON reader treats as seconds and
overflows). Both are present in `ash_clickhouse` 0.7.5. The data layer's own
failure logging is also at `:debug` there, so the library — not the dependency —
is what reports a failed flush.
`ClickhouseExLogger.Insert` still chunks a flush and calls `Ash.bulk_create/4`
once per 1000-row chunk, rather than once for the whole flush. That is an
accounting requirement, not a workaround: the data layer does not advertise
`:bulk_create_with_partial_success`, so a single call cannot report how many rows
an earlier chunk committed, and `ClickhouseExLogger.Buffer` credits `delivered`
from exactly that count. See `ClickhouseExLogger.Insert`.
## License
Apache-2.0. See [LICENSE](LICENSE).