better logging and HTTP/DNS

Author: Daniel-Nashed

Corefile

@@ -3,7 +3,7 @@ open-blocklist.internal {
    forward . 172.30.0.10:5353
 
     cache 10
-    log
+    # log
     errors
 }
 
@@ -14,14 +14,14 @@ open-blocklist-etcd.internal {
     }
 
     cache 10
-    log
+    # log
     errors
 }
 
 
 in-addr.arpa {
     forward . 172.30.0.10:5353
     cache 30
-    log
+    # log
     errors
 }

docker-compose.yml

@@ -31,7 +31,7 @@ services:
 
 
   open-blocklist:
-    image: ${OPEN_BLOCKLIST_IMAGE:-ghcr.io/nashcom/open-blocklist:latest}
+    image: ${OPENBL_IMAGE:-ghcr.io/nashcom/open-blocklist:latest}
     container_name: open-blocklist-main
     hostname: open-blocklist
 
@@ -43,8 +43,8 @@ services:
         ipv4_address: 172.30.0.10
 
     environment:
-      - OPENBL_ETCD_ENDPOINT=http://172.30.0.20:2379
-      - OPENBL_LOGLEVEL=DEBUG
+      OPENBL_ETCD_ENDPOINT: http://172.30.0.20:2379
+      OPENBL_LOGLEVEL: ${OPENBL_LOGLEVEL:-INFO}
 
     ports:
       - "${LOOKUP_HOST_PORT:-8080}:8080"

src/dns.go

@@ -6,6 +6,7 @@ package main
 import (
     "fmt"
     "strings"
+    "time"
     "github.com/miekg/dns"
 )
 
@@ -53,6 +54,9 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
     msg.SetReply(r)
     msg.Authoritative = true
 
+    start  := time.Now()
+    status := ""
+
     if len(r.Question) == 0 {
         msg.Rcode = dns.RcodeFormatError
         _ = w.WriteMsg(msg)
@@ -66,9 +70,6 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
     }
 
     q := r.Question[0]
-    queryType := dns.TypeToString[q.Qtype]
-
-    logMsg(LOG_DEBUG, "[DNS Requery]: Type=%s Name=%s", queryType, q.Name)
 
     switch q.Qtype {
 
@@ -78,7 +79,7 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
 
             msg.Rcode = dns.RcodeRefused
 
-            logMsg(LOG_VERBOSE, "[DNS Result/Refused]: Type=%s Name=%s", queryType, q.Name)
+            status = "Refused"
             stats.ReqDnsWrongZone.Add(1)
             break  // fall through to w.WriteMsg
         }
@@ -88,7 +89,7 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
             // Malformed label count — not a valid RBL query
             msg.Rcode = dns.RcodeFormatError
 
-            logMsg(LOG_VERBOSE, "[DNS Result/Malformed]: Type=%s Name=%s", queryType, q.Name)
+            status = "Malformed"
             stats.ReqDnsInvalidQuery.Add(1)
             break
         }
@@ -100,25 +101,23 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
             msg.Answer = append(msg.Answer, rr)
             msg.Rcode  = dns.RcodeSuccess
 
-            logMsg(LOG_VERBOSE, "[DNS Result/Found]: Type=%s Name=%s", queryType, q.Name)
+            status = "Found"
             stats.ReqDnsBlocked.Add(1)
 
         } else {
             // Known zone, not listed -> NXDOMAIN (RBL semantics)
             msg.Rcode = dns.RcodeNameError
 
-            logMsg(LOG_VERBOSE, "[DNS Result/NotFound]: Type=%s Name=%s", queryType, q.Name)
+            status = "NotFound"
             stats.ReqDnsNotListed.Add(1)
         }
 
     case dns.TypePTR:
 
-        logMsg(LOG_VERBOSE, "[DNS Query/PTR]: name=%s type=%s", q.Name, queryType)
-
         if !dns.IsSubDomain("in-addr.arpa.", q.Name) {
             msg.Rcode = dns.RcodeRefused
 
-            logMsg(LOG_VERBOSE, "[DNS Result/NO-IN-ARPA]: Type=%s Name=%s", queryType, q.Name)
+            status = "WrongZone"
             stats.ReqDnsWrongZone.Add(1)
             break
         }
@@ -127,7 +126,7 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
         if !ok {
             msg.Rcode = dns.RcodeFormatError
 
-            logMsg(LOG_VERBOSE, "[DNS Result/Invalid Query]: name=%s type=%s", q.Name, queryType)
+            status = "Invalid IP"
             stats.ReqDnsInvalidQuery.Add(1)
             break
         }
@@ -136,30 +135,31 @@ func handleDNSRequest(w dns.ResponseWriter, r *dns.Msg) {
         _ , blocked := ipTableLookup(ip)
 
         if blocked {
-            rr, _ := dns.NewRR(q.Name + " 10 IN PTR " + reverseHost + ".")
+            rr, _ := dns.NewRR(q.Name + " 10 IN PTR " + gReverseHost + ".")
             msg.Answer = append(msg.Answer, rr)
             msg.Rcode = dns.RcodeSuccess
 
-            logMsg(LOG_VERBOSE, "[DNS Result/Blocked]: name=%s type=%s", q.Name, queryType)
+            status = "Blocked"
             stats.ReqDnsBlocked.Add(1)
 
         } else {
             // Not listed -> NXDOMAIN (RBL semantics)
             msg.Rcode = dns.RcodeNameError
 
-            logMsg(LOG_VERBOSE, "[DNS Result/NotFound]: name=%s type=%s", q.Name, queryType)
+            status = "NotFound"
             stats.ReqDnsNotListed.Add(1)
         }
 
     default:
         msg.Rcode = dns.RcodeRefused
-
-        logMsg(LOG_VERBOSE, "[DNS Result/Unhandled]: name=%s type=%s", q.Name, queryType)
+        status = "Unhandled"
         stats.ReqDnsOtherQueryType.Add(1)
         break
     }
 
     _ = w.WriteMsg(msg)
+
+    logDnsReq(r, start, status)
 }
 
 // rblQueryToIP extracts and reverses the IP address encoded in an RBL query name.

src/helpers.go

@@ -299,14 +299,14 @@ func reverseKey(ip net.IP) string {
         p := ipv4Parts(ip)
 
         return fmt.Sprintf("%s/arpa/in-addr/%s/%s/%s/%s",
-            skyPrefix,
+            SKY_DNS_PREFIX,
             p[0], p[1], p[2], p[3])
     }
 
     p := ipv6Nibbles(ip)
 
     return fmt.Sprintf("%s/arpa/ip6/%s",
-        skyPrefix,
+        SKY_DNS_PREFIX,
         strings.Join(p, "/"))
 }
 

src/log.go

@@ -6,10 +6,13 @@ package main
 import (
     "log"
     "fmt"
+    "net/http"
     "os"
     "time"
+    "github.com/miekg/dns"
 )
 
+
 func showCfg(description, variableName, defaultValue, currentValue any) {
     logMsg(LOG_INFO, "%-34s  %-40s %-40v  %v", variableName, description, defaultValue, currentValue)
 }
@@ -42,16 +45,16 @@ func (l LogLevel) LowerCaseStr() string {
     }
 }
 
-func logLine(msg string) {
+func logLine(level LogLevel, msg string) {
 
     ts := time.Now().UTC().Format(time.RFC3339)
 
     if gLogJSON {
-        log.Printf(`{"ts":"%s","type":"%s","msg":%q}`, ts, "event", msg)
+        log.Printf(`{"ts":"%s","type":"event","level":"%s","msg":%q}`, ts, level.LowerCaseStr(), msg)
         return
     }
 
-    log.Println(ts + "   " + msg)
+    log.Println(ts + "   " + level.String() + ": " + msg)
 }
 
 func logSpace() {
@@ -60,7 +63,12 @@ func logSpace() {
         return
     }
 
-    logLine("")
+    if gLogLevel < LOG_INFO {
+        return
+    }
+
+    ts := time.Now().UTC().Format(time.RFC3339)
+    log.Println(ts)
 }
 
 func logMsg(level LogLevel, format string, args ...any) {
@@ -69,12 +77,12 @@ func logMsg(level LogLevel, format string, args ...any) {
         return
     }
 
-    logLine(fmt.Sprintf(format, args ...))
+    logLine(level, fmt.Sprintf(format, args ...))
 }
 
 func logFatal(format string, args ...any) {
 
-    logLine(fmt.Sprintf(format, args ...))
+    logLine(LOG_ERROR, fmt.Sprintf(format, args ...))
     os.Exit(1)
 }
 
@@ -86,4 +94,65 @@ func logListerner(info string, addr string) {
     } else {
         logMsg (LOG_INFO, "Listening  [%-10s]  on %s", info, addr)
     }
-}
+}
+
+func logHttpReq(r *http.Request, start time.Time, requestName string, status string) {
+
+    duration := time.Since(start)
+    ts := time.Now().UTC().Format(time.RFC3339)
+
+    if gLogJSON {
+        log.Printf(`{"ts":"%s","type":"http","request":%q,"method":%q,"uri":%q,"duration_seconds":%f,"status":%q}`,
+            ts,
+            requestName,
+            r.Method,
+            r.RequestURI,
+            duration.Seconds(),
+            status,
+        )
+        return
+    }
+
+    if gLogLevel < LOG_DEBUG {
+        return
+    }
+
+    logMsg(LOG_DEBUG, "[HTTP-REQ: %s] %s %s %v (%.6f seconds) -> %s",
+        requestName,
+        r.Method,
+        r.RequestURI,
+        duration,
+        duration.Seconds(),
+        status,
+    )
+}
+
+func logDnsReq(r *dns.Msg, start time.Time, status string) {
+
+    duration := time.Since(start)
+    ts := time.Now().UTC().Format(time.RFC3339)
+    q  := r.Question[0]
+
+    if gLogJSON {
+        log.Printf(`{"ts":"%s","type":"dns","request":%q,"qtype":%s,"duration_seconds":%f,"status":%s}`,
+            ts,
+            q.Name,
+            dns.TypeToString[q.Qtype],
+            duration.Seconds(),
+            status,
+        )
+        return
+    }
+
+    if gLogLevel < LOG_DEBUG {
+        return
+    }
+
+    logMsg(LOG_DEBUG, "[DNS Requery: %s] %s %v (%.6f seconds) -> %s",
+        dns.TypeToString[q.Qtype],
+        q.Name,
+        duration,
+        duration.Seconds(),
+        status,
+    )
+}