Skip to content

breaking: utilize a cached file descriptor for logging & own dnsmasq.log - #2960

Open
darkexplosiveqwx wants to merge 21 commits into
pi-hole:developmentfrom
darkexplosiveqwx:log-dnsmasq
Open

breaking: utilize a cached file descriptor for logging & own dnsmasq.log#2960
darkexplosiveqwx wants to merge 21 commits into
pi-hole:developmentfrom
darkexplosiveqwx:log-dnsmasq

Conversation

@darkexplosiveqwx

@darkexplosiveqwx darkexplosiveqwx commented Jul 16, 2026

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
Discussed in #2897

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

@darkexplosiveqwx darkexplosiveqwx changed the title WIP utilize a cached file descriptor for logging & own dnsmasq.log utilize a cached file descriptor for logging & own dnsmasq.log Jul 23, 2026
@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.

@github-actions

Copy link
Copy Markdown

Conflicts have been resolved.

@DL6ER

DL6ER commented Aug 3, 2026

Copy link
Copy Markdown
Member

Had a look at this one while reviewing #2958, even though it is still a draft. The shape of the cached-fd rework is fine, but a few things would bite in production.

1. FTL.log and webserver.log stop being written after the first rotation. Our shipped advanced/Templates/logrotate rotates both with create 640 pihole pihole and no postrotate, with the comment "FTL.log and webserver.log are opened and closed for each line, therefore no postrotate is needed". With a cached descriptor we keep writing into the renamed FTL.log.1 - which logrotate then compresses while we still hold it open - and the freshly created file stays empty until FTL restarts. This needs a companion pi-hole PR adding kill -USR2 to both stanzas, and the two have to land together. pihole.log already has that postrotate, and create 640 matches the new S_IRUSR|S_IWUSR|S_IRGRP mode, so that part lines up.

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.

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.

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.

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.

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.

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.

Smaller: removing validate_filepath_dash silently retires files.log.dnsmasq = "-", which is a user-visible value and belongs on the breaking-change list; five of the new comments contain em dashes while the rest of the tree is ASCII; log->fd is read outside the lock as a fast path while flush_dnsmasq_log() reassigns it under the lock; and off is used as an offset into line before it is clamped.

@darkexplosiveqwx

Copy link
Copy Markdown
Contributor Author
  1. FTL.log and webserver.log stop being written after the first rotation. Our shipped advanced/Templates/logrotate rotates both with create 640 pihole pihole and no postrotate, with the comment "FTL.log and webserver.log are opened and closed for each line, therefore no postrotate is needed". With a cached descriptor we keep writing into the renamed FTL.log.1 - which logrotate then compresses while we still hold it open - and the freshly created file stays empty until FTL restarts. This needs a companion pi-hole PR adding kill -USR2 to both stanzas, and the two have to land together. pihole.log already has that postrotate, and create 640 matches the new S_IRUSR|S_IWUSR|S_IRGRP mode, so that part lines up.

Will take a look regarding the code later, but a Core PR already exists. It did get linked, but after that gotten mostly buried.
Here is an explicit mention again: pi-hole/pi-hole#6672

@github-actions

github-actions Bot commented Aug 5, 2026

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

1. struct log_fd.path outlives the string it points at. The path is cached once in open_log_fds() as a pointer straight into config.files.log.*.v.s and dereferenced much later, in the reopen inside write_log_line() and in flush_dnsmasq_log(). files.log.ftl becomes CONF_STRING_ALLOCATED whenever it comes from ENV, TOML or the legacy reader, and it carries FLAG_FTL_LOG, not FLAG_RESTART_FTL. free_config() only spares it while terminating:

case CONF_STRING_ALLOCATED:
    if(terminating && conf_item->f & FLAG_FTL_LOG)
        continue;
    free(conf_item->v.s);

and the config replacement path calls it with terminating == false. So changing files.log.ftl at runtime frees the string, and the next SIGUSR2 reopens a freed pointer. Even setting that aside, we would keep writing to the old file, whereas today _FTL_log() reopens the config value per line and picks the change up at once. Re-reading the config value at reopen time, or strdup()ing into struct log_fd and swapping on change, both solve it.

2. ctime() is not thread-safe. It returns a pointer to a static buffer shared with localtime() and asctime(). dnsmasq can use that idiom because it is single-threaded; FTL_write_dnsmasq_log() runs on the DNS thread while the webserver, database and NTP threads format their own timestamps, so concurrent callers tear the string. ctime() can also return NULL, and + 4 on that is undefined. ctime_r() with a 26-byte buffer gives the same output and the same locale independence.

3. dnsmasq messages still have no fallback. The new open-time warning is good, but it is a one-time notice: FTL_write_dnsmasq_log() discards write_log_line()'s return value, so with no descriptor every dnsmasq line is dropped for the life of the process. _FTL_log() falls back to vsyslog() and _log_web() to _FTL_log() for priority <= LOG_WARNING; dnsmasq lines deserve at least the same for warnings and errors.

4. The early-startup window is still uncovered. Moving open_log_fds(false) to just after readFTLconf() covers dnsmasq's runtime, but write_dnsmasq_config(), and with it test_dnsmasq_config(), is called from inside readFTLconf() (config.c:1913, 1943, 1976). Anything emitted there hits a descriptor that is still -1 and, per point 3, disappears. That is exactly what log-facility used to catch. Either open pihole.log before the first write_dnsmasq_config(), or give the writer a fallback.

5. flush_dnsmasq_log() does not check its reopen. If that open() fails, pihole.log is dead until the next SIGUSR2 with nothing in any log explaining why. An ftruncate() under the lock would also be simpler than the fopen("w") plus close plus reopen dance.

Smaller: validate_filepath_dash is still removed outright, which retires files.log.dnsmasq = "-" and belongs on the breaking-change list; the off clamps in all three writers only guard the upper bound, while snprintf() returns a negative value on an encoding error; is_log_fd() keeps __attribute__((pure)) although the descriptors it reads are reassigned on reopen from another thread; and the atfork comment should state the invariant it relies on, namely that we never fork from inside a log write. Leaving dnsmasq's now-dead write path in place after the early return is the right call for future merges.

Please rebase onto development. #2958 was squash-merged, so this branch still carries its original commits and that is what conflicts; a tree diff also shows it reverting newer work such as the FTL_parse_pseudoheaders() signature. pi-hole/pi-hole#6672 needs to land in the same release as this.

@github-actions

Copy link
Copy Markdown

Conflicts have been resolved.

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>
Comment thread src/log.c Dismissed
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>
@darkexplosiveqwx
darkexplosiveqwx marked this pull request as ready for review August 19, 2026 16:54
@darkexplosiveqwx
darkexplosiveqwx requested a review from a team as a code owner August 19, 2026 16:54
The fallback string lacked the weekday that ctime_r() always emits, so
the + 4 offset skipped past it and produced a truncated timestamp.

Signed-off-by: darkexplosiveqwx <101737077+darkexplosiveqwx@users.noreply.github.com>
@darkexplosiveqwx darkexplosiveqwx changed the title utilize a cached file descriptor for logging & own dnsmasq.log breaking: utilize a cached file descriptor for logging & own dnsmasq.log Aug 20, 2026
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