# Logging

Level, format, the rotating file that never replaces standard error, and the two lines worth alerting on.

Source: https://docs.jmrp.io/ghchronicle/configuration/logging/

ghchronicle logs to standard error, and the `log` block sets the level, the format and an optional rotating file.

```yaml
log:
  level: info # debug, info, warn, error
  format: text # text or json
  file: /var/log/ghchronicle/ghchronicle.log
  max_bytes: 67108864
  keep: 5
```

## The keys

| Key         | Default    | Meaning                                       |
| ----------- | ---------- | --------------------------------------------- |
| `level`     | `info`     | `debug`, `info`, `warn` or `error`; anything else behaves as `info` |
| `format`    | `text`     | `text` for a human, `json` for a shipper; anything else is `text` |
| `file`      | none       | A rotating file **as well as** standard error |
| `max_bytes` | `67108864` | Rotate at 64 MiB. Anything not positive falls back to the default |
| `keep`      | `5`        | How many rotated files to keep. Anything not positive falls back to the default |

## Both, never instead

A configured `file` does not replace standard error, it is written in addition
to it. Under systemd the journal is where anyone looks first, and a log file
that silently took the journal's place would be a trap: `journalctl -u
ghchronicle` would go quiet and the obvious conclusion would be that the
service had stopped.

Rotation is by size with numbered suffixes, so retention is a count rather than
a date and two rotations in the same second cannot collide. The size counter is
read from the file at start-up, so a restart does not reset it and let the file
grow without bound.

## What the log says on a good day

Taken from the author's service on 2026-09-27, a start and the lines of its
sweeps:

```text
level=INFO msg="ghchronicle running" tick=15m0s tick_from="shortest cadence"
level=INFO msg="cache file read" file=/var/lib/ghchronicle/state-cache.bin written=2026-09-27T15:27:41+02:00 answers=1170 runs=672 refusals=100 page_sizes=54 age=1s
level=INFO msg="repositories discovered" count=37 archived_aside=17
level=INFO msg="slow families due together take turns" starting=planning waiting=settings,traffic
level=INFO msg=written sink=influxdb family=repo points=934 unchanged=1955
level=INFO msg="nothing moved since the window, repositories left unread" family=commits repos=34
level=INFO msg=written sink=influxdb family=commits points=17 unchanged=0
level=INFO msg="rate budget" bucket=core remaining=4477 limit=5000
level=INFO msg="points already written and not sent again" sink=influxdb skipped=54511
level=INFO msg="sweep finished"
```

The first two come once, when the process starts: the tick the loop wakes at,
and what [the cache beside the state
file](https://docs.jmrp.io/ghchronicle/configuration/#the-cache-beside-it) gave back. The list of
repositories is rebuilt once an hour, and `archived_aside` counts the archived
ones [set aside](https://docs.jmrp.io/ghchronicle/configuration/targets/#why-forks-and-archived-are-off-by-default),
which still get their two rows. In `written`, `points` is what reached the
store and `unchanged` what the write ledger left out because the store already
holds it; see [what the written line
counts](https://docs.jmrp.io/ghchronicle/sinks/#what-the-written-line-counts). A family of six
hours or more that is due behind another one is named under `waiting`, see
[the slow families take
turns](https://docs.jmrp.io/ghchronicle/configuration/cadences/#the-slow-families-take-turns), and
`commits`, `issues` and `issueevents` say how many repositories they left
unread because nothing moved in them, see [asking first what
moved](https://docs.jmrp.io/ghchronicle/api/cost/#asking-first-what-moved).

A family that is not due yet simply does not appear. That is normal, and it is
the first thing to check when a measurement seems to be missing: with a
twelve-hour cadence, half a day of logs can legitimately never mention
`stats`.

## The two lines worth an alert

**`rate limit reserve reached`** means a family was skipped to protect the
budget.

```text
level=WARN msg="rate limit reserve reached, family skipped" family=artifacts
```

Once is fine. Every sweep means the cadences are too fast for the number of
repositories.

**`family failed everywhere, not marking it as run`** means every repository
failed for one family.

```text
level=WARN msg="family failed everywhere, not marking it as run" family=security
```

The family is deliberately not marked as done, so it is retried at the next
cadence rather than being treated as complete. That is the line that separates
"a feature is off on one repository" from "the token lost a scope".

## Debugging

```yaml
log:
  level: debug
```

Debug adds these lines, and no more:

- `loaded the written-points ledger`, with how many points it came back with,
  when the service starts;
- `no cache file yet, the first pass of each family pays in full`, at the
  first start with a state file;
- `not every store keeps a write ledger`, when the runs the cache file
  remembers are listed again because a store keeps no ledger or the run ends
  with its sweep;
- `no targets.user, account-wide families skipped`;
- `sink dropped old entries`, with how many a sink left out for being older
  than its horizon, the only way to see that a push was trimmed rather than
  rejected;
- `card-only sweep, the state file is left as it was`;
- `cache file saved`, with how many answers and runs it holds and how long it
  took;
- `migration not needed` and `migration applied before`, at every start, for
  each change a store never needed or has had applied already;
- `migration noted: nothing is changed` and `migration frozen`, at every start
  after the first, which says each at `INFO`;
- `set-aside copy forgotten`, when a copy a migration set aside falls due and
  the state file stops naming it: `the store purges it itself` for one
  InfluxDB 3 purges on its own schedule, and `the store keeps it for good, and
  -migrate asks the store for it` for one it keeps for good.

There is no per-request log: the client in `internal/ghapi` carries no logger,
so which endpoint was called and which answer came back 304 are not visible at
any level. That includes its one retry: a REST request answered 500, 502, 503
or 504 is asked again two seconds later, silently, and so is a job log's
download from storage, so a `collector failed` naming one of those four has
already failed twice.

> **JSON for a shipper, text for a person**
>
> `format: json` emits one object per line, which is what Promtail, Vector or
> Filebeat want. It is the same information; only the encoding changes.
> Combining `format: json` with a `file` is the arrangement for a host that
> already ships logs somewhere.

## Not to be confused with the job log collector

`log` is the tool's own diary. `every.families.joblogs` is a _collector_: it fetches the
last forty lines of every failed GitHub Actions job and turns them into points.
They are unrelated settings, and the second one belongs in a log store rather
than in a metrics database. See [Loki](https://docs.jmrp.io/ghchronicle/sinks/loki/).