[Issue 10561] New: multiple logging.c minor issues

https://bugs.openldap.org/show_bug.cgi?id=10561

Issue ID: 10561 Summary: multiple logging.c minor issues Product: OpenLDAP Version: 2.6.13 Hardware: All OS: All Status: UNCONFIRMED Keywords: needs_review Severity: normal Priority: --- Component: slapd Assignee: bugs@openldap.org Reporter: dontbugme.relocate646@slmail.me Target Milestone: ---

Created attachment 1185 --> https://bugs.openldap.org/attachment.cgi?id=1185&action=edit servers/slapd/logging.c surprising behaviors

# OpenLDAP `slapd` log-file engine — observed bugs and pitfalls

This document lists defects and surprising behaviors identified by reading `servers/slapd/logging.c` (the `logfile`, `logfile-format`, `logfile-only` and `logfile-rotate` implementation) in this tree. All line references point to that file.

Scope: these concern the **internal** log file that `slapd` writes itself when `logfile <path>` is configured. They are independent of `rsyslogd`/`syslog-ng`.

---

## Bug 1 — `loglevel`/`olcLogLevel` messages are *not* written to the logfile unless `logfile-only on`

### What happens

`slapd` maintains two separate diagnostic streams:

* the **debug stream** (`slap_debug`), fed by the `-d` command-line flag, and * the **syslog stream** (`ldap_syslog`), fed by `loglevel`/`olcLogLevel` (and `-s`).

The internal log file is written **only** from the debug stream. The actual write is done in `slap_debug_print()`, which is the `LBER_OPT_LOG_PRINT_FN` callback fired for every `ber_log*` message whose level passes `slap_debug` (`logging.c:138` and `:222`). Messages that only pass `ldap_syslog` are emitted through `syslog()` and never reach the file.

`logfile-only` controls this:

* `logfile-only off` (default): `slap_debug_print()` also writes to stderr (`:135`), and syslog messages stay in syslog — **they never land in the file**. * `logfile-only on`: `slap_syslog_set()` ORs the syslog level into `slap_debug` and zeroes `ldap_syslog` (`:571-581`, `:807-819`, `:593-600`), so syslog messages now flow into the file — **but syslog itself is disabled**.

So there is **no configuration that writes *both* syslog and a complete log file**. Setting `logfile` + `loglevel stats` is the trap most operators fall into: stats go to syslog, and the file stays empty (unless you also used `-d` or `logfile-only on`).

### How to reproduce

`slapd.conf` (or `cn=config` equivalent):

``` logfile /tmp/slapd.log loglevel stats # (no -d flag, no logfile-only) ```

1. Start `slapd -f slapd.conf -h "ldap://:3899/"` (do **not** pass `-d`). 2. Bind / search a few times. 3. Inspect the file:

```sh cat /tmp/slapd.log # empty (or only the startup Versionstr line) journalctl -t slapd # shows "conn=N op=M ... RESULT" stats lines ```

4. Stop, add `logfile-only on`, restart, repeat. Now:

```sh cat /tmp/slapd.log # stats lines ARE present journalctl -t slapd # stats lines are GONE (syslog disabled) ```

### Severity

High for operators expecting `logfile` + `loglevel` to mirror syslog. The behavior is by design but undocumented as a limitation.

---

## Bug 2 — Stale PID in syslog-style log prefixes (`getpid()` captured before `fork()`)

### What happens

When `logfile-format` is one of the syslog-style values (`syslog-utc`/`syslog-localtime`/`rfc3339-utc`), the prefix string `"<host> <prog>[<pid>]: "` is built **once**, at config-parse time, inside the `CFG_LOGFILE_FORMAT` handler (`logging.c:852-856`):

```c splen = sprintf( syslog_prefix, "%s %s %s[%d]: ", ..., serverName, getpid() ); ```

`config_logging()` runs while `slapd` is still the original process. `slapd` then daemonizes (`slapd_daemon()` forks), so the child that actually does the logging has a **different PID** than the one baked into `syslog_prefix`. Every line in the file therefore shows the pre-fork parent PID, not the PID of the running daemon.

### How to reproduce

`slapd.conf`:

``` logfile /tmp/slapd.log logfile-format syslog-localtime loglevel stats ```

1. Start `slapd` in daemon mode (default): `slapd -f slapd.conf -h "ldap://:3899/"`. 2. Find the real daemon PID:

```sh pidof slapd cat /run/slapd/slapd.pid # or wherever pidfile points ```

3. Trigger a line (any search) and look at the prefix in the file:

```sh head -3 /tmp/slapd.log # e.g. Aug 05 10:40:12 host slapd[1234]: conn=1 ... ```

`1234` is the PID of the short-lived parent, not the daemon PID printed by `pidof slapd`.

### Severity

Medium. Cosmetic for single-instance setups, but misleading for log analysis / process correlation and for systems that run `slapd` under a supervisor that expects the logged PID to match the supervised process.

---

## Bug 3 — `logfile-format default` is identical to `logfile-format debug`

### What happens

The log-file header is only rebuilt when `logfile_format > LFMT_DEBUG` (`logging.c:185`). For `LFMT_DEFAULT` (value `0`) and `LFMT_DEBUG` (value `1`) the `iov[0]` debug prefix (`"%lx.<frac> <pthread> "`, built at `:130`) is used verbatim. So:

* `default` → raw `epoch.hex <threadptr> ` prefix, **no** date, **no** hostname, **no** PID; * `debug` → exactly the same.

The name `default` suggests a "normal" syslog-like line, but it is just the `-d`-style debugging prefix. The only formats that actually add a timestamp / host / PID header are `syslog-utc`, `syslog-localtime` and `rfc3339-utc`.

### How to reproduce

``` logfile /tmp/default.log logfile-format default loglevel stats # (separate run) logfile /tmp/debug.log logfile-format debug loglevel stats ```

Run `slapd`, trigger one operation in each, then `diff`:

```sh head -1 /tmp/default.log; head -1 /tmp/debug.log # byte-identical prefixes ```

### Severity

Low. Documentation/naming clarity issue; can surprise anyone expecting human-readable timestamps from the default format.

---

## Bug 4 — Rotation numbered-shift runs outside the mutex (lost backups under load)

### What happens

Rotation is split in two:

1. Under `logfile_mutex` (`:140-183`): the current file is renamed to `<path>.tmp` (`:147-148`) and a fresh file is reopened (`:166`). 2. **After** the mutex is released (`:227`), the numbered-shift loop runs (`:229-238`): it renames `<path>.tmp` → `<path>.NN` and shifts older `<path>.NN` → `<path>.N(N+1)`.

Because step 2 executes outside the lock, two (or more) threads that both tripped the size/age threshold can interleave:

``` T1: under lock -> rename current -> .tmp ; reopen ; unlock T2: under lock -> rename NEW current -> .tmp ; reopen ; unlock T1: outside lock-> rename .tmp -> .NN (this .tmp is actually T2's rotated file) T2: outside lock-> rename .tmp -> .NN (no .tmp exists anymore -> rename() fails, the backup T2 meant to keep is lost) ```

Consequences under heavy concurrent logging near the rotation threshold:

* a rotated backup can be silently overwritten / lost, and * `rename()` is called on a `.tmp` that no longer exists (returns `-1`, ignored).

The trigger-to-`.tmp` step is safe (under the lock) but the hand-off to the outside-lock shift is racy because the shared `.tmp` name is reused by every rotation event.

### How to reproduce (best-effort, not deterministic)

``` logfile /tmp/slapd.log logfile-format debug logfile-rotate 5 1 0 # 5 backups, 1 MB size limit, no age limit loglevel any # enable verbose categories ```

Drive a very high-volume debug stream so the file crosses 1 MB repeatedly in a short window (e.g. `loglevel sync stats packets` plus a busy replication session, or a tight loop of anonymous binds). Then list backups:

```sh ls -la /tmp/slapd.log* ```

Expected: `.01` … `.05` present and strictly ordered by age. Observed under load: gaps (e.g. `.01 .02 .04 .05` with `.03` missing) or a rotation where the oldest retained copy is newer than it should be, indicating a backup was clobbered by a racing rotation.

Note: because the race is timing-dependent, run the load several times; the failure is intermittent, which is itself the signature of a lock-ordering bug.

### Severity

Low-to-medium. Only matters with `logfile-rotate` enabled and very high log volume. Data-loss is of rotated *backups*, not of the live log.

---

## Bug 5 — Age-based rotation uses inode change time, not file create/modify time

### What happens

When a file is (re)opened, the rotation "birth" timestamp is taken from `st_ctime` (`logging.c:287`):

```c logfile_fcreated = st.st_ctime; /* not strictly true but close enough */ ```

The comment admits the approximation. `st_ctime` changes on *any* inode metadata change (chmod, chown, rename, truncate, `touch -c`), not just content creation. Age-based rotation (`logfile-rotate <max> <MB> <hours>`) therefore measures the interval since the last inode-changing event, which can be reset by an external tool (logrotate `copytruncate`, backup, permission change) and produce an unexpectedly early or late rotation.

### How to reproduce

``` logfile /tmp/slapd.log logfile-format debug logfile-rotate 3 0 1 # rotate every 1 hour (no size limit) loglevel stats ```

1. Start `slapd`; note the time. 2. Before the hour elapses, touch the inode metadata externally:

```sh touch /tmp/slapd.log # updates ctime (open with O_TRUNC not needed) ```

3. Watch rotation: it can fire based on the *touch* time rather than the daemon's own start/last-write time, because `logfile_fcreated` reflects `ctime`.

### Severity

Low. Edge-case affecting operators who let an external tool also touch the logfile.

---

## Summary table

| # | Bug | Config affected | Effect | Can lose data? | |---|-----|-----------------|--------|----------------| | 1 | `loglevel` not written to file unless `logfile-only on` | `logfile`+`loglevel` | file misses syslog-level messages | no (silent gap) | | 2 | Stale PID in syslog-style prefixes | `logfile-format syslog-*`/`rfc3339-*` | wrong `[pid]` in every line | no | | 3 | `default` == `debug` output | `logfile-format default` | no timestamp/host/pid header | no | | 4 | Rotation shift outside mutex | `logfile-rotate` under load | lost/overwritten backups | yes (backups only) | | 5 | Age rotation uses `ctime` | `logfile-rotate … <hours>` | wrong rotation timing | no |

---

## Workarounds

* To get `loglevel` content in the file, use `logfile-only on` **and** accept that native syslog logging is then disabled — or run `slapd -d <level>` instead of `loglevel`, or keep `rsyslogd` as the file writer. * For correct per-line PID/timestamps, prefer `logfile-format rfc3339-utc` (still has the stale-PID issue from Bug 2, but at least a real timestamp). * Avoid relying on `logfile-rotate` for audit-grade retention under very high log volume; use an external log rotator that copies and truncates, or pipe to `rsyslogd`.