better logging and metrics, debian packaging

11 files changed, 272 insertions, 159 deletions

diff --git a/.dockerignore b/.dockerignore
new file mode 100644
index 0000000..492a5ba
--- /dev/null
+++ b/.dockerignore
@@ -0,0 +1,3 @@
+target/
+artifacts/
+.env
diff --git a/.gitignore b/.gitignore
index fedaa2b..3d50a57 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,2 +1,3 @@
 /target
+/artifacts
 .env
diff --git a/Cargo.lock b/Cargo.lock
index 3d4472b..5344f8f 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -14,6 +14,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "aho-corasick"
+version = "0.7.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1e37cfd5e7657ada45f742d6e99ca5788580b5c529dc78faf11ece6dc702656f"
+dependencies = [
+ "memchr",
+]
+
+[[package]]
 name = "async-trait"
 version = "0.1.56"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -34,6 +43,17 @@ dependencies = [
 ]
 
 [[package]]
+name = "atty"
+version = "0.2.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
+dependencies = [
+ "hermit-abi",
+ "libc",
+ "winapi",
+]
+
+[[package]]
 name = "autocfg"
 version = "1.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -91,20 +111,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
 [[package]]
-name = "chrono"
-version = "0.4.19"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73"
-dependencies = [
- "libc",
- "num-integer",
- "num-traits",
- "serde",
- "time",
- "winapi",
-]
-
-[[package]]
 name = "cpufeatures"
 version = "0.2.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -129,55 +135,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2d0165d2900ae6778e36e80bbc4da3b5eefccee9ba939761f9c2882a5d9af3ff"
 
 [[package]]
-name = "crossbeam"
-version = "0.8.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4ae5588f6b3c3cb05239e90bd110f257254aecd01e4635400391aeae07497845"
-dependencies = [
- "cfg-if",
- "crossbeam-channel",
- "crossbeam-deque",
- "crossbeam-epoch",
- "crossbeam-queue",
- "crossbeam-utils",
-]
-
-[[package]]
-name = "crossbeam-channel"
-version = "0.5.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4c02a4d71819009c192cf4872265391563fd6a84c81ff2c0f2a7026ca4c1d85c"
-dependencies = [
- "cfg-if",
- "crossbeam-utils",
-]
-
-[[package]]
-name = "crossbeam-deque"
-version = "0.8.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "6455c0ca19f0d2fbf751b908d5c55c1f5cbc65e03c4225427254b46890bdde1e"
-dependencies = [
- "cfg-if",
- "crossbeam-epoch",
- "crossbeam-utils",
-]
-
-[[package]]
-name = "crossbeam-epoch"
-version = "0.9.9"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "07db9d94cbd326813772c968ccd25999e5f8ae22f4f8d1b11effa37ef6ce281d"
-dependencies = [
- "autocfg",
- "cfg-if",
- "crossbeam-utils",
- "memoffset",
- "once_cell",
- "scopeguard",
-]
-
-[[package]]
 name = "crossbeam-queue"
 version = "0.3.5"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -246,10 +203,10 @@ dependencies = [
 
 [[package]]
 name = "dns-server"
-version = "0.1.0"
+version = "0.1.6"
 dependencies = [
  "dotenvy",
- "fast_log",
+ "env_logger",
  "futures-util",
  "hostname",
  "lazy_static",
@@ -293,28 +250,25 @@ dependencies = [
 ]
 
 [[package]]
-name = "event-listener"
-version = "2.5.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "77f3309417938f28bf8228fcff79a4a37103981e3e186d2ccd19c74b38f4eb71"
-
-[[package]]
-name = "fast_log"
-version = "1.5.17"
+name = "env_logger"
+version = "0.9.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4a24e9b899d3b7f68309b2630db0c242ff0cce633f58c5b814c34e009c1c7efb"
+checksum = "0b2cf0344971ee6c64c31be0d530793fba457d322dfec2810c453d0ef228f9c3"
 dependencies = [
- "chrono",
- "crossbeam",
- "crossbeam-channel",
- "crossbeam-utils",
+ "atty",
+ "humantime",
  "log",
- "once_cell",
- "serde",
- "serde_json",
+ "regex",
+ "termcolor",
 ]
 
 [[package]]
+name = "event-listener"
+version = "2.5.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77f3309417938f28bf8228fcff79a4a37103981e3e186d2ccd19c74b38f4eb71"
+
+[[package]]
 name = "form_urlencoded"
 version = "1.0.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -413,7 +367,7 @@ checksum = "4eb1a864a501629691edf6c15a593b7a51eebaa1e8468e9ddc623de7c9b58ec6"
 dependencies = [
  "cfg-if",
  "libc",
- "wasi 0.11.0+wasi-snapshot-preview1",
+ "wasi",
 ]
 
 [[package]]
@@ -488,6 +442,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
+[[package]]
 name = "idna"
 version = "0.2.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -524,6 +484,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "879d54834c8c76457ef4293a689b2a8c59b076067ad77b15efafbb05f92a592b"
 
 [[package]]
+name = "ipnetwork"
+version = "0.19.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1f84f1612606f3753f205a4e9a2efd6fe5b4c573a6269b2cc6c3003d44a0d127"
+
+[[package]]
 name = "itertools"
 version = "0.10.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -606,15 +572,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2dffe52ecf27772e601905b7522cb4ef790d2cc203488bbd0e2fe85fcb74566d"
 
 [[package]]
-name = "memoffset"
-version = "0.6.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "5aa361d4faea93603064a027415f07bd8e1d5c88c9fbf68bf56a285428fd79ce"
-dependencies = [
- "autocfg",
-]
-
-[[package]]
 name = "minimal-lexical"
 version = "0.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -628,7 +585,7 @@ checksum = "57ee1c23c7c63b0c9250c339ffdc69255f110b298b901b9f6c82547b7b87caaf"
 dependencies = [
  "libc",
  "log",
- "wasi 0.11.0+wasi-snapshot-preview1",
+ "wasi",
  "windows-sys",
 ]
 
@@ -643,16 +600,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "num-integer"
-version = "0.1.45"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "225d3389fb3509a24c93f5c29eb6bde2586b98d9f016636dff58d7c6f7569cd9"
-dependencies = [
- "autocfg",
- "num-traits",
-]
-
-[[package]]
 name = "num-traits"
 version = "0.2.15"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -824,6 +771,23 @@ dependencies = [
 ]
 
 [[package]]
+name = "regex"
+version = "1.5.6"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d83f127d94bdbcda4c8cc2e50f6f84f4b611f69c902699ca385a39c3a75f9ff1"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-syntax",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.26"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "49b3de9ec5dc0a3417da371aab17d729997c15010e7fd24ff707773a33bddb64"
+
+[[package]]
 name = "ring"
 version = "0.16.20"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -985,8 +949,7 @@ dependencies = [
 [[package]]
 name = "sqlx"
 version = "0.6.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1f82cbe94f41641d6c410ded25bbf5097c240cefdf8e3b06d04198d0a96af6a4"
+source = "git+https://github.com/launchbadge/sqlx#bd40cc9a2fc4946bfb86d4947f915b16a13ec4b4"
 dependencies = [
  "sqlx-core",
  "sqlx-macros",
@@ -995,8 +958,7 @@ dependencies = [
 [[package]]
 name = "sqlx-core"
 version = "0.6.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "6b69bf218860335ddda60d6ce85ee39f6cf6e5630e300e19757d1de15886a093"
+source = "git+https://github.com/launchbadge/sqlx#bd40cc9a2fc4946bfb86d4947f915b16a13ec4b4"
 dependencies = [
  "ahash",
  "atoi",
@@ -1018,6 +980,7 @@ dependencies = [
  "hkdf",
  "hmac",
  "indexmap",
+ "ipnetwork",
  "itoa",
  "libc",
  "log",
@@ -1047,8 +1010,7 @@ dependencies = [
 [[package]]
 name = "sqlx-macros"
 version = "0.6.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "f40c63177cf23d356b159b60acd27c54af7423f1736988502e36bae9a712118f"
+source = "git+https://github.com/launchbadge/sqlx#bd40cc9a2fc4946bfb86d4947f915b16a13ec4b4"
 dependencies = [
  "dotenv",
  "either",
@@ -1066,8 +1028,7 @@ dependencies = [
 [[package]]
 name = "sqlx-rt"
 version = "0.6.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "874e93a365a598dc3dadb197565952cb143ae4aa716f7bcc933a8d836f6bf89f"
+source = "git+https://github.com/launchbadge/sqlx#bd40cc9a2fc4946bfb86d4947f915b16a13ec4b4"
 dependencies = [
  "once_cell",
  "tokio",
@@ -1102,6 +1063,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "termcolor"
+version = "1.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bab24d30b911b2376f3a13cc2cd443142f0c81dda04c118693e35b3835757755"
+dependencies = [
+ "winapi-util",
+]
+
+[[package]]
 name = "thiserror"
 version = "1.0.31"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1122,17 +1092,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "time"
-version = "0.1.44"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "6db9e6914ab8b1ae1c260a4ae7a49b6c5611b40328a735b21862567685e73255"
-dependencies = [
- "libc",
- "wasi 0.10.0+wasi-snapshot-preview1",
- "winapi",
-]
-
-[[package]]
 name = "tinyvec"
 version = "1.6.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1290,12 +1249,6 @@ checksum = "49874b5167b65d7193b8aba1567f5c7d93d001cafc34600cee003eda787e483f"
 
 [[package]]
 name = "wasi"
-version = "0.10.0+wasi-snapshot-preview1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f"
-
-[[package]]
-name = "wasi"
 version = "0.11.0+wasi-snapshot-preview1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423"
@@ -1410,6 +1363,15 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
 
 [[package]]
+name = "winapi-util"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178"
+dependencies = [
+ "winapi",
+]
+
+[[package]]
 name = "winapi-x86_64-pc-windows-gnu"
 version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/Cargo.toml b/Cargo.toml
index c9f62f4..80894be 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -1,6 +1,6 @@
 [package]
 name = "dns-server"
-version = "0.1.0"
+version = "0.1.6"
 edition = "2021"
 license = "MIT"
 
@@ -8,11 +8,11 @@ license = "MIT"
 
 [dependencies]
 dotenvy = "0.15.1"
-fast_log = "1.5.17"
+env_logger = "0.9.0"
 futures-util = "0.3.21"
 hostname = "0.3.1"
 lazy_static = "1.4.0"
 log = "0.4.17"
-sqlx = { version = "0.6.0", features = ["postgres", "runtime-tokio-rustls"] }
+sqlx = { git = "https://github.com/launchbadge/sqlx", features = ["postgres", "runtime-tokio-rustls", "ipnetwork"] }
 tokio = { version = "1.19.2", features = ["full"] }
 trust-dns-proto = "0.21.2"
diff --git a/Dockerfile b/Dockerfile
new file mode 100644
index 0000000..5f998bc
--- /dev/null
+++ b/Dockerfile
@@ -0,0 +1,25 @@
+FROM rust:1.62-bullseye AS builder
+WORKDIR /src/
+RUN cargo init --bin
+COPY Cargo.toml Cargo.lock /src/
+RUN cargo build --release
+COPY ./ /src/
+RUN touch src/main.rs && cargo build --release
+
+
+FROM scratch AS bin
+COPY --from=builder /src/target/release/dns-server /dns-server
+
+
+FROM debian:buster AS deb-builder
+ARG VERSION
+WORKDIR /root/
+COPY pkg/ /root/pkg/
+COPY --from=bin /dns-server pkg/usr/bin/dns-server
+RUN sed -i "s/[{][{] VERSION [}][}]/$(pkg/usr/bin/dns-server --version)/g" ./pkg/DEBIAN/control
+RUN dpkg -b pkg dns-server_"$(pkg/usr/bin/dns-server --version)"_amd64.deb
+
+
+FROM scratch AS deb
+ARG VERSION
+COPY --from=deb-builder /root/dns-server_*_amd64.deb /
diff --git a/deploy.sh b/deploy.sh
new file mode 100755
index 0000000..191d66b
--- /dev/null
+++ b/deploy.sh
@@ -0,0 +1,11 @@
+#!/usr/bin/env bash
+
+cargo build --release
+
+for ns in ns{1..4}.fdns.dev; do
+        scp target/release/dns-server root@$ns:/tmp/coredns
+        ssh root@$ns << EOF
+                systemctl stop coredns && mv /tmp/coredns /usr/local/sbin/coredns && systemctl start coredns
+EOF
+
+done
diff --git a/docker-bake.hcl b/docker-bake.hcl
new file mode 100644
index 0000000..cfa0a10
--- /dev/null
+++ b/docker-bake.hcl
@@ -0,0 +1,22 @@
+variable "PKGVER" {
+    default = "0.1.0"
+}
+
+group "default" {
+    targets = ["deb"]
+}
+
+target "bin" {
+    dockerfile = "Dockerfile"
+    target = "bin"
+    output = ["artifacts"]
+}
+
+target "deb" {
+    dockerfile = "Dockerfile"
+    target = "deb"
+    output = ["artifacts"]
+    args = {
+        VERSION="${PKGVER}"
+    }
+}
diff --git a/pkg/DEBIAN/control b/pkg/DEBIAN/control
new file mode 100644
index 0000000..063a035
--- /dev/null
+++ b/pkg/DEBIAN/control
@@ -0,0 +1,9 @@
+Package: dns-server
+Version: {{ VERSION }}
+Architecture: amd64
+Essential: no
+Section: web
+Priority: optional
+Maintainer: Galen Guyer <galen@galenguyer.com>
+Installed-Size: 96
+Description: FDNS resolver
diff --git a/pkg/DEBIAN/postinst b/pkg/DEBIAN/postinst
new file mode 100755
index 0000000..23245e5
--- /dev/null
+++ b/pkg/DEBIAN/postinst
@@ -0,0 +1,8 @@
+#!/bin/sh
+
+if [ ! -f /etc/fdns.env ]; then
+	echo "DATABASE_URL=" >> /etc/fdns.env
+	echo "METRICS_URL=" >> etc/fdns.env
+fi
+
+systemctl is-active --quiet dns-server && systemctl restart dns-server || true
diff --git a/pkg/usr/lib/systemd/system/dns-server.service b/pkg/usr/lib/systemd/system/dns-server.service
new file mode 100644
index 0000000..c03f6ea
--- /dev/null
+++ b/pkg/usr/lib/systemd/system/dns-server.service
@@ -0,0 +1,14 @@
+[Unit]
+Description=FDNS resolver
+After=network.target
+After=systemd-user-sessions.service
+After=network-online.target
+
+[Service]
+Type=simple
+Restart=always
+EnvironmentFile=/etc/fdns.env
+ExecStart=/usr/bin/dns-server
+
+[Install]
+WantedBy=multi-user.target
diff --git a/src/main.rs b/src/main.rs
index 3bdf40d..68ba070 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -4,7 +4,7 @@ use sqlx::postgres::PgPoolOptions;
 use sqlx::FromRow;
 use sqlx::{Pool, Postgres};
 use std::env;
-use std::net::{Ipv4Addr, Ipv6Addr, SocketAddr};
+use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr};
 use std::str::FromStr;
 use std::sync::{Arc, Mutex};
 use std::time::Instant;
@@ -35,7 +35,7 @@ pub struct FdnsRecord {
     pub ttl: i32,
 }
 struct Metrics {
-    source_ip: String,
+    source_ip: IpAddr,
     qname: String,
     qtype: String,
     rcode: String,
@@ -44,13 +44,21 @@ struct Metrics {
 
 #[tokio::main]
 async fn main() {
+    if env::args().nth(1) == Some("--version".to_string()) {
+        println!(
+            "{}",
+            option_env!("CARGO_PKG_VERSION").unwrap_or_else(|| "unknown")
+        );
+        return;
+    }
+
     dotenvy::dotenv().ok();
-    fast_log::fast_log::init(
-        fast_log::Config::new()
-            .console()
-            .level(log::LevelFilter::Off),
-    )
-    .unwrap();
+    env_logger::init();
+    log::info!(
+        "Starting {} v{}",
+        option_env!("CARGO_PKG_NAME").unwrap_or_else(|| "dns-server"),
+        option_env!("CARGO_PKG_VERSION").unwrap_or_else(|| "unknown")
+    );
 
     let pg_pool = Arc::new(
         PgPoolOptions::new()
@@ -59,6 +67,8 @@ async fn main() {
             .await
             .unwrap(),
     );
+    log::info!("Connected to data postgres");
+
     let metrics_pool = Arc::new(
         PgPoolOptions::new()
             .max_connections(12)
@@ -66,10 +76,13 @@ async fn main() {
             .await
             .unwrap(),
     );
+    log::info!("Connected to metrics postgres");
 
-    let addr = String::from("127.0.0.1:5353")
+    let addr = env::var("BIND_ADDR")
+        .unwrap_or_else(|_| String::from("[::]:53"))
         .parse::<SocketAddr>()
         .expect("Unable to parse bind address");
+    log::info!("Binding to udp://{}", addr);
 
     let socket = UdpSocket::bind(&addr)
         .await
@@ -77,6 +90,7 @@ async fn main() {
     let (mut reciever, sender) =
         UdpStream::with_bound(socket, "127.0.0.254:9875".parse::<SocketAddr>().unwrap());
     let sender = Arc::new(Mutex::new(sender));
+    log::info!("Succesfully bound and listenining to udp://{}", addr);
 
     loop {
         let packet = reciever.next().await;
@@ -84,31 +98,40 @@ async fn main() {
             Some(packet) => packet,
             _ => continue,
         };
+        log::trace!("Recieved packet");
 
         match packet {
             Ok(raw_message) => {
                 let sender = Arc::clone(&sender);
                 let pg_pool = Arc::clone(&pg_pool);
                 let metrics_pool = Arc::clone(&metrics_pool);
+                log::trace!("Spawning new task");
                 tokio::spawn(async move {
                     let metrics = handle_message(raw_message, &pg_pool, sender).await;
+                    log::trace!("Packet handled, logging metrics");
                     if let Ok(metrics) = metrics {
+                        let hostname = match hostname::get() {
+                            Ok(hostname) => hostname.to_str().unwrap_or("unknown").to_owned(),
+                            Err(_) => String::from("unknown"),
+                        };
+                        if metrics.duration_us > 5 * 1000 {
+                            log::warn!("Query took over 5ms: {} {}", metrics.qname, metrics.qtype)
+                        }
                         if let Err(e) = sqlx::query(&INSERT_METRICS_SQL)
                             .bind(&metrics.source_ip)
                             .bind(&metrics.qname)
                             .bind(&metrics.qtype)
                             .bind(&metrics.rcode)
                             .bind(metrics.duration_us)
-                            .bind(match hostname::get() {
-                                Ok(hostname) => hostname.to_str().unwrap_or("unknown").to_owned(),
-                                Err(_) => String::from("unknown"),
-                            })
+                            .bind(hostname)
                             .execute(&*metrics_pool)
-                            .await {
-                                log::error!("{e}");
-                            }
+                            .await
+                        {
+                            log::error!("{e}");
+                        }
                     }
                 });
+                log::trace!("Task completed")
             }
             Err(e) => {
                 log::error!("{e}");
@@ -134,18 +157,24 @@ async fn handle_message(
             return Err(());
         }
     };
+    log::trace!("[{}] Parsed message", message.id());
+
+    message.set_response_code(ResponseCode::NoError);
 
     let query = message.queries().get(0).unwrap().to_owned();
 
-    let qname = query.name().to_string();
+    let qname = query.name().to_string().to_lowercase();
     let qtype = query.query_type().to_string();
+    log::trace!("[{}] Querying for {qname}", message.id());
 
     let records = sqlx::query_as::<_, FdnsRecord>(&GET_DOMAIN_SQL)
         .bind(&qname)
         .fetch_all(postgres)
         .await
         .unwrap();
+    log::trace!("[{}] Query for {qname} completed", message.id());
 
+    // TODO: CNAME resolution
     message.add_answers(
         records
             .iter()
@@ -160,40 +189,62 @@ async fn handle_message(
                         // TODO: Uhh log these errors just in case
                         RecordType::A => match r.content.parse::<Ipv4Addr>() {
                             Ok(addr) => Some(RData::A(addr)),
-                            Err(_) => None,
+                            Err(e) => {
+                                log::error!("Error parsing A record: {}", e);
+                                None
+                            }
                         },
                         RecordType::AAAA => match r.content.parse::<Ipv6Addr>() {
                             Ok(addr) => Some(RData::AAAA(addr)),
-                            Err(_) => None,
+                            Err(e) => {
+                                log::error!("Error parsing AAAA record: {}", e);
+                                None
+                            }
                         },
                         RecordType::CNAME => match r.content.parse::<Name>() {
                             Ok(name) => Some(RData::CNAME(name)),
-                            Err(_) => None,
+                            Err(e) => {
+                                log::error!("Error parsing CNAME record: {}", e);
+                                None
+                            }
                         },
+                        // TODO: randomize the order of these
                         RecordType::NS => match r.content.parse::<Name>() {
                             Ok(name) => Some(RData::NS(name)),
-                            Err(_) => None,
+                            Err(e) => {
+                                log::error!("Error parsing NS record: {}", e);
+                                None
+                            }
                         },
                         RecordType::SOA => match parse_soa(&r.content) {
                             Ok(soa) => Some(RData::SOA(soa)),
-                            Err(_) => None,
+                            Err(_) => {
+                                log::error!("Error parsing SOA record");
+                                None
+                            }
                         },
-                        _ => None,
+                        unknown => {
+                            log::warn!("Unknown record type {}", unknown.to_string());
+                            None
+                        }
                     })
                     .clone()
             })
             .filter(|r| r.data().is_some()),
     );
+    log::trace!("[{}] Answers set", message.id());
 
     if message.answers().is_empty() {
+        log::debug!("[{}] No answers, querying to see if we're authoritative", message.id());
         let zone_count: (i64,) = sqlx::query_as(&GET_ZONE_SQL)
             .bind(&qname)
             .fetch_one(postgres)
             .await
             .unwrap();
+        log::trace!("[{}] Query returned {} zones", message.id(), zone_count.0);
         if zone_count.0 == 0 {
             message.set_response_code(ResponseCode::Refused);
-        } else {
+        } else if records.is_empty() {
             message.set_response_code(ResponseCode::NXDomain);
             // TODO: Set additional SOA
         }
@@ -204,22 +255,29 @@ async fn handle_message(
     message.set_recursion_available(false);
 
     let response = SerialMessage::new(message.to_vec().unwrap(), src);
+    log::trace!("[{}] Locking output stream", message.id());
     let sender = (*sender).lock().unwrap();
     let mut sender = sender.with_remote_addr(src);
     match sender.send(response) {
         Ok(_) => {
-            log::debug!("{} success", message.id());
+            log::debug!("[{}] success", message.id());
         }
         Err(e) => {
-            log::error!("{e}");
+            log::error!("[{}] {e}", message.id());
         }
     };
+    log::trace!("[{}] Response sent", message.id());
 
     Ok(Metrics {
-        source_ip: src.ip().to_string(),
-        qname,
+        source_ip: src.ip(),
+        qname: query.name().to_string(),
         qtype,
-        rcode: message.response_code().to_string(),
+        rcode: match message.response_code() {
+            ResponseCode::NoError => String::from("NOERROR"),
+            ResponseCode::NXDomain => String::from("NXDOMAIN"),
+            ResponseCode::Refused => String::from("REFUSED"),
+            _ => String::from("UNKNOWN"),
+        },
         duration_us: start.elapsed().as_micros().try_into().unwrap(),
     })
 }