Use structed json logging#2036
Conversation
|
Having structured logging sounds very interesting. |
|
Personally I don't like mixing JSON and plain text output on the same file. Maybe we need a FTL option to choose between JSON and plain text logs, so users can choose the output format for all log files. |
|
My previous comment was a suggestion to add an option to FTL, so users could choose between plain text or JSON log formats.
|
Me neither, this is not the goal of this PR. I'd also like to change the FTL output, but before I start working on this I wanted to get some feedback on the whole idea. Having a flag or option in the toml sounds like a good idea and also include |
This is json, but not as structured as I think it could be. The timestamp is duplicated, there is no distinction between each 'service' (only 'stream') and no severity level. My main reason to bring this up is that the current logging is flooded with the ntp info, but there is no easy way to filter this for errors. |
OK. In this case, I don't think we should change this on the docker repository. The best approach to achieve this goal would be to change how FTL prints the log messages, including an option to generate logs using JSON output. |
|
We need both. Otherwise the log of our docker commands incl. crond would still be plain bash output |
|
I have hacked together a quick prototype of JSON logging in FTL. $ sudo -u pihole pihole-FTL -f --log-json
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"########## FTL started on frodo-blue! ##########"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"FTL branch: log-json"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"FTL version: v6.6.2-210-gc92e52c8-dirty"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"FTL commit: c92e52c8-dirty"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"FTL date: 2026-05-15 20:36:39 +0200"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"FTL user: pihole"}
{"timestamp":"2026-05-20T22:52:37.240+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"Compiled for x86_64 (compiled locally) using gcc (GCC) 16.1.1 20260515 (Red Hat 16.1.1-2)"}
{"timestamp":"2026-05-20T22:52:37.241+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"Reading default TOML config file"}
{"timestamp":"2026-05-20T22:52:37.242+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"dns.revServer does not exist - nothing to migrate"}
{"timestamp":"2026-05-20T22:52:37.242+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"dns.domain does not exist - nothing to migrate"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Calling nlgetmsg(type = 26)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Calling parse_nl_msg (len = 116)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Parsing Netlink message (type 24, len 116/116, flags 0x2, sqe 0)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Parsing IPv6 route: table 255 is ff00:: via direct"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Returning next nl_msg_type: 0<unknown>, remaining len: 0/0"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Calling nlgetmsg(type = 26)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Calling parse_nl_msg (len = 20)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"Returning next nl_msg_type: 3 (NLMSG_DONE), remaining len: 20/20"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_NETLINK","service":"pihole-FTL","component":"FTL","message":"netlink done: Success (0)"}
{"timestamp":"2026-05-20T22:52:37.247+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"Testing /etc/pihole/dnsmasq.conf.temp"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"Files /etc/pihole/dnsmasq.conf.temp and /etc/pihole/dnsmasq.conf are identical (skipped the first 24 lines)"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"dnsmasq.conf unchanged"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"Opening /etc/pihole/custom.list.tmp for writing"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"Files /etc/pihole/custom.list.tmp and /etc/pihole/hosts/custom.list are identical (skipped the first 24 lines)"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"DEBUG_CONFIG","service":"pihole-FTL","component":"FTL","message":"custom.list unchanged"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"Parsed config file /etc/pihole/pihole.toml successfully"}
{"timestamp":"2026-05-20T22:52:37.252+02:00","log_level":"WARNING","service":"pihole-FTL","component":"FTL","message":"Unable to read PID from file: No such file or directory"}
{"timestamp":"2026-05-20T22:52:37.253+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"PID file does not exist or not readable"}
{"timestamp":"2026-05-20T22:52:37.253+02:00","log_level":"INFO","service":"pihole-FTL","component":"FTL","message":"No other running FTL process found."}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"* CAP_MKNOD (27) = --- *"}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"* CAP_LEASE (28) = --- *"}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"* CAP_AUDIT_WRITE (29) = --- *"}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"* CAP_AUDIT_CONTROL (30) = --- *"}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"* CAP_SETFCAP (31) = --- *"}
{"timestamp":"2026-05-20T22:52:37.266+02:00","log_level":"DEBUG_CAPS","service":"pihole-FTL","component":"FTL","message":"***************************************"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"INFO","service":"pihole-FTL","component":"webserver","message":"Initializing HTTP server on ports \"+8086\""}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[document_root] -> [/usr/share/pihole/www] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[error_pages] -> [/usr/share/pihole/www/admin/] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[listening_ports] -> [+8086] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[decode_url] -> [yes] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[enable_directory_listing] -> [no] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[num_threads] -> [50] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[authentication_domain] -> [pi.hole] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[additional_header] -> [X-DNS-Prefetch-Control: off\r\nContent-Security-Policy: default-src 'none'; connect-src 'self'; font-src 'self'; frame-ancestors 'none'; img-src 'self'; manifest-src 'self'; script-src 'self'; style-src 'self' 'unsafe-inline'; for"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[index_files] -> [index.html,index.htm,index.lp] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[enable_keep_alive] -> [yes] (src/webserver/civetweb/civetweb.c:21420)"}
{"timestamp":"2026-05-20T22:52:37.324+02:00","log_level":"DEBUG","service":"pihole-FTL","component":"webserver","message":"[keep_alive_timeout_ms] -> [5000] (src/webserver/civetweb/civetweb.c:21420)"}Escaping is done automatically, as I made use of the already embedded cJSON. This includes currently only the FTL and webserver logs, the dnsmasq log isn't exposed that nicely and I didn't go that deeply just yet. Should I open a draft PR on the FTL repo where we can discuss further details and look at my bad code? |
|
This is great! Thanks for contributing. Yes, please open a draft PR at FTL repo.
This can be changes, I just took the short form as an example. |
Yes. The current log shows the ID string as |
|
I have submitted pi-hole/FTL#2897
done.
I just noted that it currently mismatches and we need a single format later on, but thats a minor issue. Some problems regarding this: |
As far as I now The issue here is that FTL only prints the messages to the file (nothing is sent to |
Yes, what I meant is that the stdout/stderr of pihole-FTL isn't captured, but that FTL.log is tailed instead to show FTL's logs. |
|
This pull request has conflicts, please resolve those before we can evaluate the pull request. |
Signed-off-by: yubiuser <github@yubiuser.dev>
|
Conflicts have been resolved. |
Signed-off-by: yubiuser <github@yubiuser.dev>
Signed-off-by: yubiuser <github@yubiuser.dev>
|
For FTL's JSON logs we need to read its stdout directly, as I opted not to change FTL.log to JSON. A quick idea of mine: diff --git a/src/Dockerfile b/src/Dockerfile
index 3797d90..b8b0a86 100644
--- a/src/Dockerfile
+++ b/src/Dockerfile
@@ -18,7 +18,7 @@ ARG PIHOLE_UID=1000
ARG PIHOLE_GID=1000
ENV DNSMASQ_USER=pihole
-ENV FTL_CMD=no-daemon
+ENV FTL_CMD="no-daemon --log-json"
RUN apk add --no-cache \
bash \
diff --git a/src/start.sh b/src/start.sh
index 46e698b..b47d03b 100644
--- a/src/start.sh
+++ b/src/start.sh
@@ -66,11 +66,10 @@ start() {
__log "INFO" "pihole-docker" "Starting pihole-FTL as user ${DNSMASQ_USER}"
- capsh --user="${DNSMASQ_USER}" --keep=1 -- -c "/usr/bin/pihole-FTL $FTL_CMD >/dev/null" &
+ capsh --user="${DNSMASQ_USER}" --keep=1 -- -c "/usr/bin/pihole-FTL $FTL_CMD" &
# Notes on above:
# - DNSMASQ_USER default of pihole is in Dockerfile & can be overwritten by runtime container env
- # - /var/log/pihole/pihole*.log has FTL's output that no-daemon would normally print in FG too
- # prevent duplicating it in docker logs by sending to dev null
+ # - "--log-json" already writes full structured JSON, we can capture it directly
# We need the PID of the capsh process so that we can wait for it to finish
CAPSH_PID=$!
@@ -92,13 +91,6 @@ start() {
}')
__log "INFO" "pihole-docker" "$versionJson"
- if [ "${TAIL_FTL_LOG:-1}" -eq 1 ]; then
- # Start tailing the FTL log file from the EOF position we recorded on container start�����������������������������������������������������������������������������������������������������- tail -F -c +$((startFrom + 1)) -- "${FTLlogFile}" &
- else
- __log "INFO" "pihole-docker" "FTL log output is disabled. Remove the Environment variable TAIL_FTL_LOG, or set it to 1 to enable FTL log output."
- fi��������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������������-
# Wait for the capsh process (which spawned FTL) to finish
wait $CAPSH_PID
FTL_EXIT_CODE=$?This however would remove the support for I am not that familiar with docker development (only run a few containers), so I don’t even know whether this approach work. |
|
Oh, look at that I compiled FTL in the dev container locally and copied the binary into |
I think it would be OK to remove this option. I'm not sure how many users disabled the option - and why would I don't want any log output of the container's main service? |
Signed-off-by: yubiuser <github@yubiuser.dev>
|
Will there be an option to turn structured logging off or will this completely replace the current more human readable output? I understand the reason for that change, but I prefer the current state for my personal usage. |
|
I agree with casperklein. I don't think JSON output will be the best format for every use case. |
|
I'm not against this as a concept, but it should be opt-in via an env var (which also sets the FTL logging mode to be JSON too, if that's the direction), and not the default. JSON is great for consumption by machine, but it's not so easy for a human to quickly parse |
|
Even with a var like
Especially for machine consumption, we should go with ISO 8601, or more specifically RFC 3339, ("YYYY-MM-DDTHH:MM:SS.mmm"+"Z"/"±hh:mm") the question that remains is if we want to normalize the timestamp to UTC (and use "Z") or if we want to keep the information of the local timezone (and use "±hh:mm"). |
|
Note: Currently, We can use a variable ( |
State of the art logging for docker is structured json logging. This allows aggregation, analysis and filtering. Currently, we use plain shell output that is optimized for human consumption. This PR changes the output to structured
jsonwhich can be easily parsed and consumed by other tools.This kind of output allows separation of the logging of the processes running on the container simultaneously:
start.sh,FTL,crond,...This is a draft. Before I go on and parse the FTL output (or maybe adjust this in FTL repo), I'd like to know the opinion of the other team members. Example output