improve logging

Dockerfile

@@ -23,7 +23,7 @@ FROM $BUILD_FROM
 ENV LANG=C.UTF-8
 
 # Setup base
-RUN apk add --no-cache dnsmasq nginx-debug sqlite && mv /etc/nginx /etc/nginx-orig
+RUN apk add --no-cache dnsmasq nginx-debug sqlite socat && mv /etc/nginx /etc/nginx-orig
 
 # Copy data
 COPY rootfs /

Dockerfile.live

@@ -7,7 +7,7 @@ FROM golang:1.22-alpine
 ENV LANG=C.UTF-8
 
 # Setup base
-RUN apk add --no-cache dnsmasq nginx-debug sqlite && mv /etc/nginx /etc/nginx-orig
+RUN apk add --no-cache dnsmasq nginx-debug sqlite socat && mv /etc/nginx /etc/nginx-orig
 
 # Setup golang build tools
 RUN apk add --no-cache git make musl-dev go build-base

Makefile

@@ -33,38 +33,41 @@ build-backend:
 		golangci-lint run
 	cd dhcp-clients-webapp-backend && \
 		go test -v -cover ./...
-
 
+TEST_CONTAINER_NAME:=dnsmasq-dhcp-test
+DOCKER_RUN_OPTIONS:= \
+	-v $(shell pwd)/test-options.json:/data/options.json \
+	-v $(shell pwd)/test-leases.leases:/data/dnsmasq.leases \
+	-v $(shell pwd)/test-db.sqlite3:/data/trackerdb.sqlite3 \
+	-v $(shell pwd)/test-startcounter:/data/startcounter \
+	-v $(shell pwd)/dhcp-clients-webapp-backend:/app \
+	-v $(shell pwd)/dhcp-clients-webapp-backend/templates:/opt/web/templates/ \
+	-v $(shell pwd)/rootfs/opt/bin/dnsmasq-dhcp-script.sh:/opt/bin/dnsmasq-dhcp-script.sh \
+	-e LOCAL_TESTING=1 \
+	--cap-add NET_ADMIN \
+	--network host
+
+# when using the 'test-docker-image' target it's normal to see messages like
+#    "Something went wrong contacting the API"
+# at startup of the docker container... the reason is that the startup scripts
+# will try to reach to HomeAssistant Supervisor which is not running...
 test-docker-image: 
 	$(MAKE) FAST=1 build-docker-image
 	@echo "Starting container of image ${IMAGETAG}:localtest" 
 	docker run \
 		--rm \
-		-v $(shell pwd)/test-options.json:/data/options.json \
-		-v $(shell pwd)/test-leases.leases:/data/dnsmasq.leases \
-		-e LOCAL_TESTING=1 \
-		--cap-add NET_ADMIN \
-		--network host \
+		--name $(TEST_CONTAINER_NAME) \
+		${DOCKER_RUN_OPTIONS} \
 		${IMAGETAG}:localtest
 
-LIVE_CONTAINER_NAME:=dsnmasq-dhcp-test-live
 
 test-docker-image-live: 
 	docker build -f Dockerfile.live -t debug-image-live .
 	@echo "Starting container of image debug-image-live" 
 	docker run \
 		--rm \
-		--name $(LIVE_CONTAINER_NAME) \
-		-v $(shell pwd)/test-options.json:/data/options.json \
-		-v $(shell pwd)/test-leases.leases:/data/dnsmasq.leases \
-		-v $(shell pwd)/test-db.sqlite3:/data/trackerdb.sqlite3 \
-		-v $(shell pwd)/test-startcounter:/data/startcounter \
-		-v $(shell pwd)/dhcp-clients-webapp-backend:/app \
-		-v $(shell pwd)/dhcp-clients-webapp-backend/templates:/opt/web/templates/ \
-		-v $(shell pwd)/rootfs/opt/bin/dnsmasq-dhcp-script.sh:/opt/bin/dnsmasq-dhcp-script.sh \
-		-e LOCAL_TESTING=1 \
-		--cap-add NET_ADMIN \
-		--network host \
+		--name $(TEST_CONTAINER_NAME) \
+		${DOCKER_RUN_OPTIONS} \
 		debug-image-live
 
 
@@ -82,15 +85,13 @@ test-database-drop:
 
 # this target assumes that you launched 'test-docker-image-live' previously
 test-database-add-entry:
-	docker exec -ti $(LIVE_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh add "00:11:22:33:44:57" "192.168.1.250" "test-entry"
-	docker exec -ti $(LIVE_CONTAINER_NAME) cat /data/dnsmasq-dhcp-script.log
+	docker exec -ti $(TEST_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh add "00:11:22:33:44:57" "192.168.1.250" "test-entry"
 
 test-database-add-entry2:
-	docker exec -ti $(LIVE_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh add "00:11:22:33:44:58" "192.168.1.251" "test-entry2"
-	docker exec -ti $(LIVE_CONTAINER_NAME) cat /data/dnsmasq-dhcp-script.log
+	docker exec -ti $(TEST_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh add "00:11:22:33:44:58" "192.168.1.251" "test-entry2"
 
 # NOTE:
-#    docker exec -ti $(LIVE_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh del "00:11:22:33:44:57" "192.168.1.250" "test-entry"
+#    docker exec -ti $(TEST_CONTAINER_NAME) /opt/bin/dnsmasq-dhcp-script.sh del "00:11:22:33:44:57" "192.168.1.250" "test-entry"
 # won't work: there is no 'del' support... the only way to 
 test-database-del-entry:
 	sqlite3 test-db.sqlite3 "DELETE FROM dhcp_clients WHERE mac_addr = '00:11:22:33:44:57';"

dhcp-clients-webapp-backend/pkg/trackerdb/doc.go

@@ -8,14 +8,17 @@ For more info about the dnsmasq DHCP script please check
     where the "tracker DB" gets populated
 
 Q: Why do we need to have such "tracker DB" and we can't just rely on dnsmasq lease file/database?
-A: They solve two different issues: the dnsmasq lease file contains the _current_ list of DHCP clients.
+A: The trackerDB and dnsmasq leases solve two different issues:
+the dnsmasq lease file contains the _current_ list of DHCP clients.
 Such file/database is persisted to disk (/data is persistent) but if a DHCP client fails to renew its lease
 or does not contact dnsmasq server after a dnsmasq restart, then its entry gets deleted from dnsmasq.leases file.
 The tracker DB instead is built to maintain an history of _any_ DHCP client that ever connected to the
 dnsmasq server. Entries only get added to the tracker DB, never deleted. Each entry is added with a
 "last_seen" timestamp and also a "start counter index" which identifies which particular instance
 of dnsmasq received traffic from that DHCP client.
 
+Q: What do
+
 Q: What do we use tracker DB for?
 A: To implement the "Past DHCP clients" feature of the addon web UI.
 Such feature allows to list any DHCP client that was present in the past but that did not contact

rootfs/etc/services.d/log-helper/finish

@@ -0,0 +1,12 @@
+#!/usr/bin/env bashio
+# ==============================================================================
+# Take down the S6 supervision tree when service fails
+# s6-overlay docs: /~https://github.com/just-containers/s6-overlay
+# ==============================================================================
+
+if [[ "$1" -ne 0 ]] && [[ "$1" -ne 256 ]]; then
+  bashio::log.warning "Halt add-on"
+  exec /run/s6/basedir/bin/halt
+fi
+
+bashio::log.info "Service restart after closing"

rootfs/etc/services.d/log-helper/run

@@ -0,0 +1,12 @@
+#!/usr/bin/with-contenv bashio
+
+LOG_SOCKET=/tmp/dnsmasq-script-log-socket
+
+# This service implements just a very very basic
+# Unix socket -> stdout proxy server.
+# This is useful to get the messages logged by the
+# /opt/bin/dnsmasq-dhcp-script.sh 
+# to stdout
+
+bashio::log.info "Starting log-helper..."
+socat -u UNIX-LISTEN:${LOG_SOCKET},fork STDOUT

rootfs/opt/bin/dnsmasq-dhcp-script.sh

@@ -12,15 +12,27 @@ HOSTNAME="${4:-}"
 DB_PATH=/data/trackerdb.sqlite3
 ADDON_DHCP_SERVER_START_COUNTER="/data/startcounter"
 ADDON_DHCP_SERVER_START_EPOCH="/data/startepoch"
-LOGFILE="/data/dnsmasq-dhcp-script.log"
 START_TIME_THRESHOLD_SEC=3
 
+# About logging
+# Unfortunately logging from this script to stdout does not produce any output
+# (dnsmasq which launches this script seems to ignore its output).
+# Logging to a file implies also handling its rotation/cleanup...
+# so instead we log to a Unix socket and we have a basic 'socat' server 
+# that acts as log proxy; see the /etc/services.d/log-helper for more details.
+#LOGFILE="/data/dnsmasq-dhcp-script.log"
+LOG_SOCKET=/tmp/dnsmasq-script-log-socket
+
 log_info() {
-    echo "$(date): INFO: $*" >>$LOGFILE
+    #echo "$(date): INFO: $*" >>$LOGFILE
+    MSG="$(date): DNSMASQ-SCRIPT: INFO: $*"
+    echo "$MSG" | socat - UNIX-CONNECT:${LOG_SOCKET}
 }
 
 log_error() {
-    echo "$(date): ERR: $*" >>$LOGFILE
+    #echo "$(date): ERR: $*" >>$LOGFILE
+    MSG="$(date): DNSMASQ-SCRIPT: ERR: $*"
+    echo "$MSG" | socat - UNIX-CONNECT:${LOG_SOCKET}
 }
 
 # Reads the current start counter into global var DHCP_SERVER_START_COUNTER
@@ -31,7 +43,7 @@ read_start_counter() {
         DHCP_SERVER_START_COUNTER=0
     fi
 
-    log_info "The DHCP server start counter is ${DHCP_SERVER_START_COUNTER}"
+    log_info "Acquired DHCP server start counter: ${DHCP_SERVER_START_COUNTER}"
 }
 
 # Returns 1 if the dnsmasq just started or 0 if not
@@ -83,7 +95,7 @@ ON CONFLICT(mac_addr) DO UPDATE SET
 EOF
 
     if [[ $? -eq 0 ]]; then
-        log_info "Client with mac=$mac_addr, hostname=$hostname has been added/updated successfully."
+        log_info "Stored in trackerDB updated information for client mac=$mac_addr, hostname=$hostname"
     else
         log_error "Failed to add/update client. Expect inconsistencies."
     fi
@@ -116,7 +128,6 @@ elif [[ "$MODE" = "old" ]]; then
     if [[ $? -eq 1 ]]; then 
         log_info "Detected startup LEASE processing and ignoring it"
     else
-        log_info "Updating lease"
         read_start_counter
         last_seen=$(date -u +"%Y-%m-%dT%H:%M:%SZ")  # ISO 8601 UTC format
         add_or_update_dhcp_client "$DB_PATH" "$MAC_ADDRESS" "$HOSTNAME" "$last_seen" "$DHCP_SERVER_START_COUNTER"

test-leases.leases

@@ -1,12 +0,0 @@
-1727948636 f8:25:51:d9:1e:73 192.168.1.21 host-a 01:f8:25:51:d9:1e:73
-1727948544 08:a6:f7:4f:13:04 192.168.1.47 host-b 01:08:a6:f7:4f:13:04
-1727948521 40:ae:30:50:15:cb 192.168.1.41 host-c *
-1727948425 80:64:6f:dc:73:b8 192.168.1.44 host-d 01:80:64:6f:dc:73:b8
-1727948248 80:64:6f:c8:1f:3c 192.168.1.43 host-e 01:80:64:6f:c8:1f:3c
-1727947962 28:73:f6:88:b6:35 192.168.1.51 host-f *
-1727947954 50:8b:b9:30:0c:02 192.168.1.42 host-g *
-1727915892 4c:50:77:cf:3c:35 192.168.1.207 host-h 01:4c:50:77:cf:3c:35
-1727937507 80:be:af:c4:44:94 192.168.1.32 host-i 01:80:be:af:c4:44:94
-1727938824 ec:71:db:a1:ed:24 192.168.1.31 host-l 01:ec:71:db:a1:ed:24
-1727940354 6c:bf:b5:00:c9:ff 192.168.1.5 host-m *
-1727945736 80:be:af:c4:45:49 192.168.1.30 host-n 01:80:be:af:c4:45:49

test-startcounter

@@ -1 +1 @@
-0
+1