Skip to content

structured JSON logging - #2968

Draft
darkexplosiveqwx wants to merge 26 commits into
pi-hole:developmentfrom
darkexplosiveqwx:log-structured
Draft

structured JSON logging#2968
darkexplosiveqwx wants to merge 26 commits into
pi-hole:developmentfrom
darkexplosiveqwx:log-structured

Conversation

@darkexplosiveqwx

Copy link
Copy Markdown
Contributor

Thank you for your contribution to the Pi-hole Community!

Please read the comments below to help us consider your Pull Request.

We are all volunteers and completing the process outlined will help us review your commits quicker.

Please make sure you

  1. Base your code and PRs against the repositories developmental branch.
  2. Sign Off all commits as we enforce the DCO for all contributions
  3. Sign all your commits as they must have verified signatures
  4. File a pull request for any change that requires changes to our documentation at our documentation repo

What does this PR aim to accomplish?:

Builds upon #2958 and #2960
Discussed in #2897

Todo: possibly upstream the don't redirect stdout patch to dnsmasq

How does this PR accomplish the above?:

Link documentation PRs if any are needed to support this PR:


By submitting this pull request, I confirm the following:

  1. I have read and understood the contributors guide, as well as this entire template. I understand which branch to base my commits and Pull Requests against.
  2. I have commented my proposed changes within the code and I have tested my changes.
  3. I am willing to help maintain this change if there are issues with it later.
  4. It is compatible with the EUPL 1.2 license
  5. I have squashed any insignificant commits. (git rebase)
  6. I have checked that another pull request for this purpose does not exist.
  7. I have considered, and confirmed that this submission will be valuable to others.
  8. I accept that this submission may not be used, and the pull request closed at the will of the maintainer.
  9. I give this submission freely, and claim no ownership to its content.

  • I have read the above and my PR is ready for review. Check this box to confirm

@github-actions

Copy link
Copy Markdown

This pull request has conflicts, please resolve those before we can evaluate the pull request.

@github-actions

Copy link
Copy Markdown

Conflicts have been resolved.

Comment thread src/log.c Fixed
Comment thread src/log.c Dismissed
@github-actions

Copy link
Copy Markdown

This pull request has conflicts, please resolve those before we can evaluate the pull request.

@DL6ER

DL6ER commented Aug 16, 2026

Copy link
Copy Markdown
Member

Following up on the allocation point from #2897, with more detail on why it matters here.

my_syslog() runs inside dnsmasq's request handling, once or twice per query, and #2960 drops log-async, so the write is already synchronous on the DNS thread. This is the absolute hot path - anything we add lands on query latency. Today it allocates nothing: snprintf() into a stack buffer and a write(), no cJSON in sight. log_to_json() adds an object, two cJSON_strdup()s per field, and cJSON_PrintUnformatted() with its growing buffer, so roughly fifteen malloc/free pairs per line from a thread already contending for the allocator.

The schema is six fixed keys, so please emit it directly into a stack buffer. Only message needs escaping, the other five are ours. escape_string() and escape_data() are not reusable - they emit C-style \xNN and allocate - but this is enough:

// Escape into a caller-supplied buffer so the log path needs no allocation.
// Never splits an escape, so a short buffer truncates to valid JSON.
static size_t json_escape(char *out, const size_t outlen, const char *in)
{
	static const char hex[] = "0123456789abcdef";
	size_t o = 0;

	for(const unsigned char *p = (const unsigned char *)in; *p != '\0'; p++)
	{
		// Widest form is \u00XX, and every escape starts with a backslash
		char esc[6] = { '\\' };
		size_t len = 2;

		switch(*p)
		{
			case '"':  esc[1] = '"';  break;
			case '\\': esc[1] = '\\'; break;
			case '\b': esc[1] = 'b';  break;
			case '\f': esc[1] = 'f';  break;
			case '\n': esc[1] = 'n';  break;
			case '\r': esc[1] = 'r';  break;
			case '\t': esc[1] = 't';  break;

			default:
				// Printable and UTF-8 bytes pass through
				if(*p >= 0x20)
				{
					esc[0] = (char)*p;
					len = 1;
					break;
				}

				// Other control characters have no short form
				esc[1] = 'u';
				esc[2] = '0';
				esc[3] = '0';
				esc[4] = hex[*p >> 4];
				esc[5] = hex[*p & 0x0f];
				len = 6;
				break;
		}

		// Stop on the last character that fits, keeping room for the NUL
		if(o + len >= outlen)
			break;

		memcpy(out + o, esc, len);
		o += len;
	}

	out[o] = '\0';
	return o;
}

Valid UTF-8 survives as is. Also, printf("%s\n", out) bypasses the cached descriptor writer from #2960, so this path gets stdio buffering rather than the O_APPEND write - worth folding in.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
the embedded dnsmasq already does a fd cleanup on startup, so this is not strictly necessary, but still good practice

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
message

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
The fd == -1 fast path in write_log_line() sat before the
reopen_needed check, so SIGUSR2 could not revive a log whose initial
open failed: a missing /var/log/pihole or a transient EACCES disabled
that log for the lifetime of the process. Move the reopen before the
fd test and access both fields only under the lock (flush_dnsmasq_log()
reassigns the descriptor under the lock, so the unlocked fast path was
racy). Also drop the fd == -1 early return in FTL_write_dnsmasq_log()
which would have bypassed the reopen for pihole.log entirely.

Code Review:
**2. `write_log_line()` can never recover a log whose initial open failed.** The `if(log->fd == -1) return false;` fast path sits before the `reopen_needed` check, so `SIGUSR2` cannot revive it. A missing `/var/log/pihole` at first start, or a transient `EACCES`, disables that log for the lifetime of the process. Testing the reopen flag first fixes it.

**Smaller:** `log->fd` is read outside the lock as a fast path while `flush_dnsmasq_log()` reassigns it under the lock

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
strftime("%b %e %H:%M:%S") into a 16 byte buffer overflows in
non-English locales: init_locale() calls setlocale(LC_ALL, ""), so %b
is the localized month abbreviation (six bytes for ru_RU, more
elsewhere). When it does not fit, strftime() returns 0 and leaves the
buffer contents unspecified, so pihole.log gets garbage. Use dnsmasq's
own idiom instead: ctime(&now) + 4 truncated to 15 characters. ctime()
renders the weekday/month in the C locale regardless of the process
locale, so this cannot overflow and keeps the on-disk format
byte-identical to what we write today.

Code Review:
**3. The dnsmasq timestamp buffer is too small for non-English locales.** `char ts_buf[16]` fits `"Jan 1 12:00:00"` exactly in the C locale, but `init_locale()` calls `setlocale(LC_ALL, "")`, so `%b` is the localized abbreviation - six bytes for `ru_RU`, more elsewhere. When it does not fit, `strftime()` returns 0 and leaves the buffer contents *unspecified*, so `pihole.log` gets garbage. dnsmasq itself sidesteps this with `ctime(&time_now) + 4` and `%.15s`, which is locale-independent and keeps the on-disk format byte-identical to what we write today.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
open_log_fds() warned when webserver.log could not be opened but said
nothing for pihole.log. A failed open therefore silently disabled every
dnsmasq log line for the lifetime of the process. Add the matching
warning so the missing log is visible in FTL.log at startup.

Code Review:
**4. dnsmasq messages have no fallback left.** `my_syslog()` returns before dnsmasq's own syslog path and `FTL_write_dnsmasq_log()` returns silently when the descriptor is -1, so if `pihole.log` cannot be opened every dnsmasq message is lost. `_FTL_log()` and `_log_web()` both fall back, and `open_log_fds()` warns for `webserver.log` but says nothing for `pihole.log`.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
dnsmasq forks per TCP query while FTL threads are running. If a fork
happens while another thread holds dnsmasq_log.lock, the child inherits
it locked and the first my_syslog() there blocks forever, hanging that
query. Register pthread_atfork() handlers that take all three per-file
mutexes before fork() and release them in both parent and child, so a
fork can never observe a locked log mutex.

Code Review:
**5. The per-file mutex is not fork-safe.** dnsmasq forks per TCP query while our threads are running. If a fork happens while another thread holds `dnsmasq_log.lock`, the child inherits it locked and the first `my_syslog()` there blocks forever, hanging that query. Our SHM lock is process-shared and robust for exactly this reason. Since every write is `O_APPEND`, and a single `write()` to a regular file is atomic, the lock only guards the reopen - `pthread_atfork()` handlers or an atomic descriptor swap would be enough.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
open_log_fds(false) runs before FTL drops privileges, so a fresh install
now gets root-owned webserver.log and pihole.log; dnsmasq used to
create pihole.log after dropping to pihole, and webserver.log was
created on the first request. FTL_fork_and_bind_sockets() chowned only
files.log.ftl. Chown the webserver and dnsmasq log files alongside it
when actually dropping from root.

Code Review:
**6. New root-owned log files.** `open_log_fds(false)` runs before we drop privileges, so a fresh install now gets root-owned `webserver.log` and `pihole.log`; dnsmasq used to create `pihole.log` after dropping to `pihole`, and `webserver.log` was created on the first request. `FTL_fork_and_bind_sockets()` chowns only `files.log.ftl` and should cover the other two.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
my_syslog() bypasses dnsmasq's own logging path and FTL writes every
pihole.log line synchronously through a cached descriptor, so the
log-async queue is never populated. Emitting log-async in the generated
config is misleading dead configuration.

Code Review:
**7. `log-async` is now dead code in the generated config.** With `my_syslog()` bypassed, dnsmasq's async queue is never used, so query logging became a blocking `write()` in the DNS thread - which is the stall that queue exists to prevent. Either drop the `log-async` lines or say why the synchronous write is acceptable for us.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
The rest of the tree is ASCII; replace the em dashes introduced in the
recent log comments with plain hyphens.

Code Review:
**Smaller:** five of the new comments contain em dashes while the rest of the tree is ASCII

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
The clamp that protects the writes into the 2048 byte line buffer ran
after off had already been used as an offset into line and as the size
argument (sizeof(line) - off would underflow if the first snprintf()
ever truncated). Clamp off between the two formatting calls in
FTL_write_dnsmasq_log(), _FTL_log() and _log_web().

Code Review:
**Smaller:** `off` is used as an offset into `line` before it is clamped

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
The open failure warning is shown regardless of the hide_dnsmasq_warn
setting, but the message now notes whether dnsmasq warnings are hidden
by it, so the notice reflects the actual behaviour instead of always
claiming warnings are relayed to the FTL log.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
is_log_fd() was incorrectly stripped of __attribute__((pure)) in an
earlier review-fix pass.  The attribute is correct: pure means no side
effects and may depend on global state (unlike const which is a pure
function).  GCC only caches the result when it can prove the read
state hasn't changed, which it cannot for struct members accessed
through pointers that other threads may modify.  The compiler itself
warns suggest-attribute=pure when the attribute is missing, confirming
it belongs here.

Also fix the ctime_r() return type: use const char* to match the
fallback string literal and avoid -Wdiscarded-qualifiers.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
free(log->path) is called before path has been set on the first
invocation, triggering a spurious WARNING from the custom FTLfree()
wrapper.  Add a NULL check to avoid the noise.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
@github-actions

Copy link
Copy Markdown

Conflicts have been resolved.

log_to_json() runs on every log line when structured JSON logging is
active.  The cJSON path allocates an object, two cJSON_strdup()s per
field, and cJSON_PrintUnformatted() with its growing buffer - roughly
fifteen malloc/free pairs per line.

The schema is six fixed keys, so emit it directly into a stack buffer
with snprintf().  Only the message field needs JSON escaping; the other
five are controlled by the code.  A new json_escape() helper writes
into a caller-supplied buffer so the log path needs no allocation.
Valid UTF-8 passes through unchanged.

Also use write(STDOUT_FILENO, ...) instead of printf() to avoid stdio
buffering.

Code Review:
pi-hole#2968 (comment)

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
@DL6ER

DL6ER commented Aug 20, 2026

Copy link
Copy Markdown
Member

set_log_path(), ctime_r(), the syslog fallback for dnsmasq lines, the reopen warning after a flush and the off < 0 clamps all look right now.

Three things left.

log_to_json() is unchanged: still an object, six cJSON_AddStringToObject() and cJSON_PrintUnformatted() per line, then printf(). That is the allocation churn on the DNS hot path from my earlier comment, and the printf() also bypasses the cached descriptor writer this branch introduces.

open_log_fds(false) still sits after readFTLconf() in main.c, and write_dnsmasq_config() runs inside it, so config-test output still meets a descriptor of -1. The new syslog fallback may well cover that window now - worth confirming rather than assuming.

Small one: the ctime_r() failure fallback is "Jan 1 00:00:00 ", but it is read as ctime_str + 4, which skips a weekday the fallback does not have and leaves " 1 00:00:00 ". It wants a full ctime-shaped string, e.g. "Thu Jan 1 00:00:00 1970".

validate_filepath_dash is still gone, so files.log.dnsmasq = "-" stays on the breaking-change list.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
@darkexplosiveqwx

Copy link
Copy Markdown
Contributor Author

log_to_json() is unchanged: still an object, six cJSON_AddStringToObject() and cJSON_PrintUnformatted() per line, then printf(). That is the allocation churn on the DNS hot path from my earlier comment, and the printf() also bypasses the cached descriptor writer this branch introduces.

This has already been addressed in f4b1477

open_log_fds(false) still sits after readFTLconf() in main.c, and write_dnsmasq_config() runs inside it, so config-test output still meets a descriptor of -1. The new syslog fallback may well cover that window now - worth confirming rather than assuming.

Part of #2960 and already addressed in 91c3ed2

Small one: the ctime_r() failure fallback is "Jan 1 00:00:00 ", but it is read as ctime_str + 4, which skips a weekday the fallback does not have and leaves " 1 00:00:00 ". It wants a full ctime-shaped string, e.g. "Thu Jan 1 00:00:00 1970".

Part of #2960 and now addressed in b8c1697 (I have not yet rebased this branch onto that commit)

validate_filepath_dash is still gone, so files.log.dnsmasq = "-" stays on the breaking-change list.

Do you think injecting log-facility=- if it is - and disabling out fallback paths would be better than making this a breaking change? (We cannot remove echo_stderr anyway, since it is needed for test_dnsmasq_config())

@DL6ER

DL6ER commented Aug 20, 2026

Copy link
Copy Markdown
Member

You are right on all three, and my point about open_log_fds() was simply wrong - 91c3ed2 adds the early call in readFTLconf() before write_dnsmasq_config(), which is exactly what I asked for. I checked the ordering in main.c, saw it unchanged and stopped there, without looking at config.c in the same commit. Sorry for the noise.

One thing on the new log_to_json(). escaped_msg and line are both 8192, but line also carries the timestamp, level, component, pid and about 90 bytes of framing, and msg arrives from a json_buffer[8192] where escaping can grow it up to sixfold. A long or escape-heavy message therefore overflows line, and snprintf() cuts it mid-string - no closing quote, no brace, no newline. That is the one outcome the escaper's careful truncation is meant to avoid, so line should be big enough for escaped_msg plus the framing, or truncation should be detected and a shorter valid record emitted instead.

On files.log.dnsmasq = "-": the retirement itself is fine, I only want it written down. v7 is a breaking release and the logging rework is already on the breaking-change list, so retiring one config value fits what is being announced anyway. Keeping it would mean carrying a second writer for a single setting, leaving the dnsmasq path reachable and in need of testing rather than letting it become dead code, and that is the more expensive option, so I would leave it retired.

Dropping validate_filepath_dash() was the right call as the branch stands - once FTL owns the file and stops emitting log-facility, the dash would reach open() and create a file called -. Just list it with the rest of the logging changes so nobody still using - meets it as a surprise. echo_stderr staying for test_dnsmasq_config() is unrelated and fine.

Code review:

One thing on the new log_to_json(). escaped_msg and line are both 8192,
but line also carries the timestamp, level, component, pid and about 90
bytes of framing, and msg arrives from a json_buffer[8192] where
escaping can grow it up to sixfold. A long or escape-heavy message
therefore overflows line, and snprintf() cuts it mid-string - no closing
quote, no brace, no newline. That is the one outcome the escaper's
careful truncation is meant to avoid, so line should be big enough for
escaped_msg plus the framing, or truncation should be detected and a
shorter valid record emitted instead.

pi-hole#2968 (comment)
Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
@github-actions

Copy link
Copy Markdown

This pull request has conflicts, please resolve those before we can evaluate the pull request.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants