demo: pflog step in the asciinema recording (pflogd: 2 records, DLT_PFLOG pcap); re-recorded cast

CHANGELOG.md

@@ -0,0 +1,88 @@
+# Changelog
+
+## v0.4.0 — 2026-11-11
+
+Lab-verified milestone release.  The full gate suite (9 gates) runs against
+Alpine VMs under libvirt on the kernel built from source.
+
+### Verified in the lab (each has a gate in `tests/vm/`)
+
+| Capability | Gate | What it proves |
+|---|---|---|
+| Engine loads, `/dev/pf`, real OpenBSD `pfctl` over the ioctl ABI | `01` | `insmod` + `pfctl -s info` + transit ping + state created |
+| `block` / `return` / `return-rst` | `02` | ICMP dropped, TCP refused |
+| `pfr` tables (inline `{ }`, `-T add/del/show`, `-T` block) | `03` | table load, block by table, delete, unblock |
+| Anchors and evaluation order | `04` | anchor child passes the request before the parent `block`, state created by the anchor rule, request dropped after the anchor is flushed |
+| `nat-to` (source NAT) | `05` | tcpdump proof of the rewritten source, reply de-NATed, state shows both tuples |
+| `rdr-to` (port redirect) | `06` | client talks to the firewall, server answers, **2 MB pulled through the redirect byte-identical**, firewall still responsive afterwards |
+| `divert-to` + `AF_DIVERT` + `pdivert` | `11` | drop with no listener (BSD `divs_noport` parity), packet delivered to userspace, rewritten and reinjected |
+| `pflog` + `pflogd` | `12` | logged packets read from `/dev/pflog` and written as a `DLT_PFLOG` pcap containing the real bytes |
+| Soak / unload discipline | `14` | traffic + states with no kernel warnings, clean `rmmod`, reload, no slab growth |
+
+### Added
+
+- `module/pfsrc/pfk_pflog.c` — `/dev/pflog` chardev backend (OpenBSD
+  `pflog_hdr` layout, 64-byte records, bounded queue, `poll`, stats ioctl).
+- `tools/pflogd` — reads `/dev/pflog`, writes `DLT_PFLOG` pcap (or a readable
+  one-line-per-record summary).
+- `tools/pdivert` — divert(4) relay with payload mutation + ICMP checksum fix.
+- `module/pfsrc/divert_sock.c` — `AF_DIVERT` socket family registered at
+  runtime (`PF_DIVERT = 32`, `IPPROTO_DIVERT = 254`), blocking `recvmsg`,
+  `poll`, BSD-compatible reinjection.
+- `scripts/demo-session.sh` + `scripts/demo-record.py` + `make demo` —
+  asciinema recording of the live lab (`out/demo-pf-linux.cast`).
+- `docs/{en,pt-BR}/`: README, install, build, guide, vm-lab, feature-matrix,
+  patches, caveats, demo.  `docs/porting-notes.md` records every deviation.
+- `patches/kernel/` + `scripts/apply-patches.sh` / `scripts/unpatch.sh` —
+  kernel-core patch mechanism, empty series by design (verified: the module
+  needs no core patch).
+
+### Fixed (all found by the VM gates, root causes documented)
+
+- `skb->mark` bookkeeping used multi-bit values, so the "in pass done" mark
+  also satisfied the "out pass done" test: transit traffic never reached the
+  **out** ruleset (NAT and egress rules silently ignored).
+- The out ruleset was never evaluated for forwarded packets: added the
+  `NF_INET_FORWARD` hook (OpenBSD evaluates it in `ip_forward()`).
+- `refcnt_rele()` had inverted polarity → live state keys freed → `Oops` in
+  the state RBT and `pfctl -s states` hangs.
+- `radix` `SALEN()` read the `sa_family` byte as a length (Linux sockaddrs
+  have no `sa_len`) → table entries dropped as duplicates.
+- BSD/Linux `LIST_HEAD` macro arity clash in `compat/sys/queue.h`.
+- Reverse NAT: a packet whose destination pf rewrote was delivered to the
+  firewall's own stack instead of being re-routed.
+- Checksums across translation: IP header checksum recomputed (OpenBSD's
+  `ip_output` does this, Linux does not); transport checksum recomputed in
+  software for plain skbs and handed back to the NIC (`CHECKSUM_PARTIAL`) for
+  GSO/TSO — the earlier software-only fix corrupted every segment after the
+  first and stalled bulk transfers.
+- `divert`: NULL dereference on an empty listener list (wedged the VM),
+  port byte order mismatch between `bind` and the queue, L3-only skbs injected
+  into an Ethernet device RX path, re-divert loop (solved with a skip mark).
+- `IOC_SIZEBITS` = 14 truncated the rule ioctl struct → `EINVAL` on load.
+- State iteration started at id 1 (kifs never attached), `stoeplitz_init()`
+  never called, purge timer re-arming itself at `rmmod`, `rtnl`×`NET` lock
+  order inversion in the interface notifier.
+
+### Known gaps
+
+`binat-to`, `route-to`/`dup-to`/`fail-to`, `af-to`, scrub end-to-end
+(normalization code is ported and compiles; the lab gate is not written),
+queues/ALTQ (`hfsc.c`/`fq_codel.c` staged, `pfq` qdisc not implemented),
+`pfsync`/CARP (out of scope).  See `docs/en/feature-matrix.md`.
+
+## v0.3.0 — 2026-11-11
+
+M2 data path: netisr-style workqueue, per-direction marks, state/table/anchor
+gates passing; divert design settled (in-module socket family, no core patch).
+
+## v0.2.0 — 2026-11-11
+
+M1: engine compiles into `pf.ko` (pf.c, pf_ioctl.c with the full ioctl ABI,
+pf_norm, pf_if, pf_lb, pf_table, pf_ruleset, pf_osfp, pf_syncookies, radix,
+md5/sha, ifq), `/dev/pf`, Linux-built OpenBSD `pfctl` talking to it.
+
+## v0.1.0 — 2026-11-11
+
+M0: repo, bilingual scaffold, kernel 7.3.4 build, libvirt Alpine lab with
+custom-kernel VMs (pf0/cli/srv/gw2), build/deploy/test scripts.

docs/en/pf-guide.md

@@ -60,34 +60,42 @@ treat them as load-and-pray until the matrix moves them.
 
 | Syntax | Until | What happens today |
 |---|---|---|
-| `nat-to`, `rdr-to`, `binat-to` | M3 | Rules load (engine code compiled) but translation is unwired/ungated — **do not rely on NAT**; outbound masquerade still comes from iptables/nft during the lab. |
+| `nat-to`, `rdr-to` (`binat-to` pending) | — | **Verified in the lab** (gates `05-nat`, `06-rdr`, the latter pulls 2 MB through a redirect and compares it byte for byte). `nat-to (egress)` expands the OpenBSD interface *group*; on a multi-NIC host prefer the explicit `nat-to (<iface>)` form. |
 | `scrub (…)`, `set reassemble` | M3 | `pf_norm.c` runs inside `pf_test` (compiled) — crafted-fragment behavior is untested; treat results as unvalidated. |
-| `divert-to`, `divert` tag | M4 (+ family per code comments) | Matching packets are **dropped** with a rate-limited kernel warning. Never ship this on a live host. |
+| `divert-to`, `divert` tag | — | **Verified in the lab** (gate `11-divert`): the packet is delivered to an `AF_DIVERT` socket (`PF_DIVERT=32`) served by `tools/pdivert`; with no listener it is dropped, exactly like BSD's `divs_noport`. |
 | `route-to`, `dup-to`, `fail-to`, `reply-to` | M4 | Not implemented as Linux routing glue yet; rules may load but the behavior is undefined — avoid. |
 | `queue` / `queue on` / `pfctl -s queue` | M5 | Parse and load. Queuing falls back to the priq-shaped compat `ifq` layer; **no bandwidth enforcement happens until the `pfq` qdisc lands**. |
-| `log`, `log all`, `block log`, `pflogd` | M4 | Nothing is logged (stub warns once at load: `pfk: … packet not logged`). |
+| `log`, `log all`, `block log`, `pflogd` | — | **Verified in the lab** (gate `12-pflog`): run `pflogd /tmp/x.pcap` (reads `/dev/pflog`); the file is a `DLT_PFLOG` (117) pcap readable by tcpdump/wireshark. |
 | `route-label …` | never (non-goal) | Rejected at the ioctl layer. |
 | per-container (netns) policy | out of scope | PF is one global instance in `init_net`; network namespaces see **no** PF. |
 
 ## Reading state correctly
 
-`pfctl -s states` currently has a listing/visibility anomaly being fixed in
+`pfctl -s states` shows the real table, including translations, in OpenBSD's
-the M2 gate work (transit flows can pass while no state is displayed). Until
+own format: a NAT/redirect state prints both tuples, e.g.
-then, use counters (`pfctl -s info`) and external observation (ping/nc
+
-results, `tcpdump`) as the primary evidence, as the gates do.
+```
+all icmp 10.0.2.1:59335 (10.0.1.10:4380) -> 10.0.2.20:8   0:0
+all tcp  10.0.2.20:80 (10.0.1.1:8080) <- 10.0.1.10:42091  FIN_WAIT_2:FIN_WAIT_2
+```
+
+The value in parentheses is the *original* address before translation.  A
+state that exists but shows `0:0` counters simply means the engine has not
+seen traffic on it since the last poll; use `pfctl -s info` counters and
+`tcpdump` for traffic evidence, as the gates do.
 
 ## Kernel log signals you should know
 
 ```
 pfk: PF-on-Linux engine loaded (OpenBSD 8.0 base)     ← insmod ok
 pfk: netfilter hooks registered (10, netisr wq data path)
-pfk: divert port N: no socket bound      # pdivert not listening on N
+pfk: divert port N: no socket bound      # pdivert/pflogd consumer not listening
-pfk: … packet not logged                              ← pflog stub
 ```
 
 Unloading stops the purge timers and drains the work queue first (an rmmod
-hang observed in the lab was fixed that way) — but the *soak* run
+hang observed in the lab was fixed that way).  The soak gate (`14-soak.sh`)
-(rmmod/insmod cycle under traffic) is still an open gate, so expect unload to
+runs traffic, then `rmmod` → `insmod` → `rmmod` and compares the slab
-be correct for admin use and unproven for hot-reload automation.
+footprint, so unload/reload is verified for admin use; hot-reload automation
+under sustained load is still not a supported workflow.
 
 Full list of behavioral divergences: [caveats.md](caveats.md).

docs/pt-BR/pf-guide.md

@@ -63,12 +63,12 @@ matriz mudar.
 
 | Sintaxe | Até | O que acontece hoje |
 |---|---|---|
-| `nat-to`, `rdr-to`, `binat-to` | M3 | As regras carregam (código do engine compilado), mas a tradução não está fiada/verificada — **não conte com NAT**; no laboratório o masquerade de saída ainda vem do iptables/nft. |
+| `nat-to`, `rdr-to` | — | **Verificado em lab** (gates `05-nat`, `06-rdr`; este último baixa 2 MB por um redirect e compara byte a byte). `nat-to (egress)` expande o *grupo* de interfaces do OpenBSD; num host multi-NIC prefira a forma explícita `nat-to (<iface>)`. `binat-to` ainda sem gate. |
 | `scrub (…)`, `set reassemble` | M3 | O `pf_norm.c` roda dentro do `pf_test` (compilado) — o comportamento com fragmentos forjados não foi testado; trate o resultado como não validado. |
-| `divert-to`, tag `divert` | M4 (+ família de sockets conforme comentário no código) | Os pacotes casados são **descartados** com um aviso de kernel rate-limited. Nunca coloque isso num host em produção. |
+| `divert-to`, tag `divert` | — | **Verificado em lab** (gate `11-divert`): o pacote é entregue a um socket `AF_DIVERT` (`PF_DIVERT=32`) atendido pelo `tools/pdivert`; sem listener é descartado, exatamente como o `divs_noport` do BSD. |
 | `route-to`, `dup-to`, `fail-to`, `reply-to` | M4 | Ainda não implementados como glue de roteamento Linux; as regras podem carregar, mas o comportamento é indefinido — evite. |
 | `queue` / `queue on` / `pfctl -s queue` | M5 | Faz parse e carrega. A fila cai no fallback priq da camada `ifq` de compat; **nenhuma limitação de banda acontece até o qdisc `pfq` chegar**. |
-| `log`, `log all`, `block log`, `pflogd` | M4 | Nada é logado (o stub avisa uma vez no load: `pfk: … packet not logged`). |
+| `log`, `log all`, `block log`, `pflogd` | — | **Verificado em lab** (gate `12-pflog`): rode `pflogd /tmp/x.pcap` (lê `/dev/pflog`); o arquivo é um pcap `DLT_PFLOG` (117) legível por tcpdump/wireshark. |
 | `route-label …` | nunca (não-objetivo) | Rejeitado na camada de ioctl. |
 | política por container (netns) | fora de escopo | O PF é uma instância global em `init_net`; network namespaces **não** enxergam o PF. |
 
@@ -85,8 +85,7 @@ primária, exatamente como os gates fazem.
 ```
 pfk: PF-on-Linux engine loaded (OpenBSD 8.0 base)     ← insmod ok
 pfk: netfilter hooks registered (10, netisr wq data path)
-pfk: divert port N: no socket bound      # pdivert não ouvido a porta N
+pfk: divert port N: no socket bound      # nenhum consumidor em pdivert/pflogd
-pfk: … packet not logged                              ← stub do pflog
 ```
 
 Descarregar o módulo primeiro para os timers de purge e drena a workqueue

out/demo-pf-linux.cast

@@ -1,65 +1,77 @@
-{"version": 2, "width": 80, "height": 24, "timestamp": 1794439963, "env": {"SHELL": null, "TERM": "dumb"}}
+{"version": 2, "width": 80, "height": 24, "timestamp": 1794445553, "env": {"SHELL": null, "TERM": "dumb"}}
-[1.256598, "o", "\u001b[1m===============================================================\u001b[0m\r\n\u001b[1m PF on Linux - the OpenBSD PF 8.0 engine inside the Linux kernel\u001b[0m\r\n\u001b[1m===============================================================\u001b[0m\r\n\r\nLab: 3 Alpine VMs under libvirt.\r\n  pftest-pf0 = firewall (kernel 7.3.4 built from source + pf.ko)\r\n  pftest-cli = client 10.0.1.10     pftest-srv = server 10.0.2.20\r\n\r\n\u001b[1m--- 1. our kernel, the OpenBSD engine as a module ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# uname -r\u001b[0m\r\n"]
+[1.622488, "o", "\u001b[1m===============================================================\u001b[0m\r\n"]
-[1.533174, "o", "7.3.4\r\n"]
+[1.623391, "o", "\u001b[1m PF on Linux - the OpenBSD PF 8.0 engine inside the Linux kernel\u001b[0m\r\n\u001b[1m===============================================================\u001b[0m\r\n\r\nLab: 3 Alpine VMs under libvirt.\r\n  pftest-pf0 = firewall (kernel 7.3.4 built from source + pf.ko)\r\n  pftest-cli = client 10.0.1.10     pftest-srv = server 10.0.2.20\r\n\r\n\u001b[1m--- 1. our kernel, the OpenBSD engine as a module ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# uname -r\u001b[0m\r\n"]
-[1.935704, "o", "\u001b[1;36mpftest-pf0# lsmod | grep '^pf ' || echo 'pf: not loaded yet'\u001b[0m\r\n"]
+[1.885894, "o", "7.3.4\r\n"]
-[2.205061, "o", "pf                    548864  0\r\n"]
+[2.289113, "o", "\u001b[1;36mpftest-pf0# lsmod | grep '^pf ' || echo 'pf: not loaded yet'\u001b[0m\r\n"]
-[2.607555, "o", "\u001b[1;36mpftest-pf0# insmod /opt/pf/pf.ko && dmesg | tail -3\u001b[0m\r\n"]
+[2.565982, "o", "pf                    552960  0\r\n"]
-[2.893207, "o", "insmod: ERROR: could not insert module /opt/pf/pf.ko: File exists\r\n"]
+[2.968407, "o", "\u001b[1;36mpftest-pf0# insmod /opt/pf/pf.ko && dmesg | tail -3\u001b[0m\r\n"]
-[3.296808, "o", "\r\n\u001b[1m--- 2. pfctl talks to the module over the OpenBSD ioctl ABI ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# /opt/pf/pfctl -s info | head -4\u001b[0m\r\n"]
+[3.226044, "o", "insmod: ERROR: could not insert module /opt/pf/pf.ko: File exists\r\n"]
-[3.569271, "o", "Status: Disabled for 0 days 00:00:09             Debug: err\r\n\r\nState Table                          Total             Rate\r\n  current entries                       32               \r\n"]
+[3.629164, "o", "\r\n"]
-[3.972723, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -e && /opt/pf/pfctl -s info | head -1\u001b[0m\r\n"]
+[3.629206, "o", "\u001b[1m--- 2. pfctl talks to the module over the OpenBSD ioctl ABI ---\u001b[0m\r\n"]
-[4.233194, "o", "Status: Enabled                                  Debug: err\r\npf enabled\r\n"]
+[3.629219, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -s info | head -4\u001b[0m\r\n"]
-[4.635445, "o", "\r\n"]
+[3.906215, "o", "Status: Disabled for 0 days 00:03:33             Debug: err\r\n\r\nState Table                          Total             Rate\r\n  current entries                        0               \r\n"]
-[4.635582, "o", "\u001b[1m--- 3. a real pf.conf: tables, stateful rules, an explicit drop ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# cat /tmp/demo-pf.conf\u001b[0m\r\n"]
+[4.310059, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -e && /opt/pf/pfctl -s info | head -1\u001b[0m\r\n"]
-[4.909045, "o", "# PF-on-Linux demo ruleset (pf.conf syntax, real OpenBSD pfctl)\r\nset block-policy return\r\ntable <trusted> { 10.0.1.0/24 }\r\n\r\n# transit traffic: stateful, table-driven\r\npass in quick on ingress proto icmp from <trusted> keep state\r\npass out quick on egress proto icmp keep state\r\n\r\n# deny a specific destination\r\nblock drop in quick proto icmp to 10.0.9.99\r\n\r\n# everything else\r\npass in quick\r\npass out quick\r\n"]
+[4.574117, "o", "Status: Enabled                                  Debug: err\r\npf enabled\r\n"]
-[5.311192, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'rules loaded'\u001b[0m\r\n"]
+[4.977439, "o", "\r\n\u001b[1m--- 3. a real pf.conf: tables, stateful rules, an explicit drop ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# cat /tmp/demo-pf.conf\u001b[0m\r\n"]
-[5.585074, "o", "rules loaded\r\n"]
+[5.245993, "o", "# PF-on-Linux demo ruleset (pf.conf syntax, real OpenBSD pfctl)\r\nset block-policy return\r\ntable <trusted> { 10.0.1.0/24 }\r\n\r\n# transit traffic: stateful, table-driven\r\npass in quick on ingress proto icmp from <trusted> keep state\r\npass out quick on egress proto icmp keep state\r\n\r\n# deny a specific destination\r\nblock drop in quick proto icmp to 10.0.9.99\r\n\r\n# everything else\r\npass in quick\r\npass out quick\r\n"]
-[5.987322, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -sr\u001b[0m\r\n"]
+[5.649022, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'rules loaded'\u001b[0m\r\n"]
-[6.253146, "o", "pass in quick on ingress proto icmp from <trusted> to any\r\npass out quick on egress proto icmp all\r\nblock drop in quick inet proto icmp from any to 10.0.9.99\r\npass in quick all flags S/SA\r\npass out quick all flags S/SA\r\n"]
+[5.926196, "o", "rules loaded\r\n"]
-[6.656054, "o", "\r\n\u001b[1m--- 4. transit traffic is allowed and stateful ---\u001b[0m\r\n"]
+[6.33004, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -sr\u001b[0m\r\n"]
-[6.65621, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
+[6.614075, "o", "pass in quick on ingress proto icmp from <trusted> to any\r\npass out quick on egress proto icmp all\r\nblock drop in quick inet proto icmp from any to 10.0.9.99\r\npass in quick all flags S/SA\r\npass out quick all flags S/SA\r\n"]
-[7.891731, "o", "--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.374/0.398/0.423 ms\r\n"]
+[7.017049, "o", "\r\n\u001b[1m--- 4. transit traffic is allowed and stateful ---\u001b[0m\r\n\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
-[8.295591, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -ss | grep -E 'icmp' | head -4\u001b[0m\r\n"]
+[8.256385, "o", "--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.343/0.381/0.419 ms\r\n"]
-[8.573677, "o", "all icmp 10.0.2.20:8 <- 10.0.1.10:4368       0:0\r\nall icmp 10.0.1.10:4368 -> 10.0.2.20:8       0:0\r\n"]
+[8.659624, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -ss | grep -E 'icmp' | head -4\u001b[0m\r\n"]
-[8.976904, "o", "\r\n\u001b[1m--- 5. tables are live objects ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# /opt/pf/pfctl -t trusted -T show\u001b[0m\r\n"]
+[8.94608, "o", "all icmp 10.0.2.20:8 <- 10.0.1.10:4987       0:0\r\nall icmp 10.0.1.10:4987 -> 10.0.2.20:8       0:0\r\n"]
-[9.257023, "o", "   10.0.1.0/24\r\n"]
+[9.348967, "o", "\r\n"]
-[9.65968, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -s Tables\u001b[0m\r\n"]
+[9.349022, "o", "\u001b[1m--- 5. tables are live objects ---\u001b[0m\r\n"]
-[9.92516, "o", "trusted\r\n"]
+[9.349263, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -t trusted -T show\u001b[0m\r\n"]
-[10.328262, "o", "\r\n\u001b[1m--- 6. the drop rule actually drops ---\u001b[0m\r\n"]
+[9.618085, "o", "   10.0.1.0/24\r\n"]
-[10.328317, "o", "\u001b[1;36mpftest-pf0# cat > /tmp/demo-block.conf <<EOF\r\nblock drop in quick proto icmp to 10.0.2.20\r\npass in quick\r\npass out quick\r\nEOF\u001b[0m\r\n"]
+[10.022258, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -s Tables\u001b[0m\r\n"]
-[11.007282, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-block.conf && echo 'block rules loaded'\u001b[0m\r\n"]
+[10.309891, "o", "trusted\r\n"]
-[11.293139, "o", "block rules loaded\r\n"]
+[10.712978, "o", "\r\n\u001b[1m--- 6. the drop rule actually drops ---\u001b[0m\r\n"]
-[11.696065, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
+[10.713088, "o", "\u001b[1;36mpftest-pf0# cat > /tmp/demo-block.conf <<EOF\r\nblock drop in quick proto icmp to 10.0.2.20\r\npass in quick\r\npass out quick\r\nEOF\u001b[0m\r\n"]
-[14.919615, "o", "\r\n--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 0 packets received, 100% packet loss\r\n"]
+[11.397835, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-block.conf && echo 'block rules loaded'\u001b[0m\r\n"]
-[15.32298, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -sr -vv | head -6\u001b[0m\r\n"]
+[11.650256, "o", "block rules loaded\r\n"]
-[15.593635, "o", "@0 block drop in quick inet proto icmp from any to 10.0.2.20\r\n  [ Evaluations: 3         Packets: 2         Bytes: 168         States: 0     ]\r\n  [ Inserted: uid 0 pid 2082 State Creations: 0     ]\r\n@1 pass in quick all flags S/SA\r\n  [ Evaluations: 1         Packets: 28        Bytes: 9296        States: 1     ]\r\n  [ Inserted: uid 0 pid 2082 State Creations: 1     ]\r\n"]
+[12.05359, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
-[15.996795, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'back to the stateful ruleset'\u001b[0m\r\n"]
+[15.280329, "o", "\r\n--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 0 packets received, 100% packet loss\r\n"]
-[16.265237, "o", "back to the stateful ruleset\r\n"]
+[15.683815, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -sr -vv | head -6\u001b[0m\r\n"]
-[16.668026, "o", "\r\n\u001b[1m--- 7. NAT: the source is translated on the way out, restored on the way back ---\u001b[0m\r\n"]
+[15.98217, "o", "@0 block drop in quick inet proto icmp from any to 10.0.2.20\r\n  [ Evaluations: 3         Packets: 2         Bytes: 168         States: 0     ]\r\n  [ Inserted: uid 0 pid 1877 State Creations: 0     ]\r\n@1 pass in quick all flags S/SA\r\n  [ Evaluations: 1         Packets: 28        Bytes: 9296        States: 1     ]\r\n  [ Inserted: uid 0 pid 1877 State Creations: 1     ]\r\n"]
-[16.668081, "o", "\u001b[1;36mpftest-pf0# cat > /tmp/demo-nat.conf <<EOF\r\npass out quick on egress from 10.0.1.0/24 to any nat-to (eth2)\r\npass in quick on ingress proto icmp keep state\r\npass out quick on egress proto icmp keep state\r\nEOF\u001b[0m\r\n"]
+[16.384573, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'back to the stateful ruleset'\u001b[0m\r\n"]
-[17.337271, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-nat.conf && echo 'nat rules loaded'\u001b[0m\r\n"]
+[16.670067, "o", "back to the stateful ruleset\r\n"]
-[17.6014, "o", "nat rules loaded\r\n"]
+[17.0729, "o", "\r\n\u001b[1m--- 7. NAT: the source is translated on the way out, restored on the way back ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# cat > /tmp/demo-nat.conf <<EOF\r\npass out quick on egress from 10.0.1.0/24 to any nat-to (eth2)\r\npass in quick on ingress proto icmp keep state\r\npass out quick on egress proto icmp keep state\r\nEOF\u001b[0m\r\n"]
-[18.004721, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
+[17.740601, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-nat.conf && echo 'nat rules loaded'\u001b[0m\r\n"]
-[19.243777, "o", "--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.347/0.381/0.415 ms\r\n"]
+[18.018113, "o", "nat rules loaded\r\n"]
-[19.647199, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -ss | grep -E 'icmp' | head -4\u001b[0m\r\n"]
+[18.42114, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -3\u001b[0m\r\n"]
-[19.917121, "o", "all icmp 10.0.2.20:8 <- 10.0.1.10:4380       0:0\r\nall icmp 10.0.2.1:59335 (10.0.1.10:4380) -> 10.0.2.20:8       0:0\r\n"]
+[19.636475, "o", "--- 10.0.2.20 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.325/0.362/0.400 ms\r\n"]
-[20.320866, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'back to the stateful ruleset'\u001b[0m\r\n"]
+[20.038543, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -ss | grep -E 'icmp' | head -4\u001b[0m\r\n"]
-[20.597072, "o", "back to the stateful ruleset\r\n"]
+[20.310123, "o", "all icmp 10.0.2.20:8 <- 10.0.1.10:4999       0:0\r\nall icmp 10.0.2.1:7697 (10.0.1.10:4999) -> 10.0.2.20:8       0:0\r\n"]
-[20.999951, "o", "\r\n\u001b[1m--- 8. divert-to: the packet goes to userspace and comes back ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# cat /tmp/demo-divert.conf\u001b[0m\r\n"]
+[20.712246, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'back to the stateful ruleset'\u001b[0m\r\n"]
-[21.277077, "o", "pass in quick proto icmp from 10.0.1.10 to 10.0.1.1 divert-to \"10.0.1.1\" port 10000 keep state\r\npass out quick\r\n"]
+[20.990114, "o", "back to the stateful ruleset\r\n"]
-[21.680804, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-divert.conf && echo 'divert rule loaded'\u001b[0m\r\n"]
+[21.392794, "o", "\r\n"]
-[21.949469, "o", "divert rule loaded\r\n"]
+[21.393027, "o", "\u001b[1m--- 8. pflog: logged packets reach userspace (/dev/pflog) ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# cat > /tmp/demo-log.conf <<EOF\r\npass in quick log proto icmp from 10.0.1.10 keep state\r\npass out quick\r\nEOF\u001b[0m\r\n"]
-[22.352874, "o", "\u001b[1;36mpftest-pf0# chmod +x /tmp/pdivert; (setsid /tmp/pdivert -p 10000 -f >/tmp/pdivert.log 2>&1 </dev/null &); sleep 1; pgrep pdivert\u001b[0m\r\n"]
+[22.057041, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-log.conf && echo 'log rule loaded'\u001b[0m\r\n"]
-[23.577515, "o", "2131\r\n"]
+[22.329918, "o", "log rule loaded\r\n"]
-[23.98128, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.1.1 | tail -3\u001b[0m\r\n"]
+[22.732644, "o", "\u001b[1;36mpftest-pf0# chmod +x /tmp/pflogd; rm -f /tmp/pflog.pcap; (setsid /tmp/pflogd -c 2 /tmp/pflog.pcap >/tmp/pflogd.log 2>&1 </dev/null &); sleep 1; echo 'pflogd collecting 2 records'\u001b[0m\r\n"]
-[25.227043, "o", "--- 10.0.1.1 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.220/0.240/0.260 ms\r\n"]
+[23.981016, "o", "pflogd collecting 2 records\r\n"]
-[25.62951, "o", "\u001b[1;36mpftest-pf0# head -3 /tmp/pdivert.log\u001b[0m\r\n"]
+[24.384736, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.2.20 | tail -2\u001b[0m\r\n"]
-[25.881153, "o", "pdivert: listening on divert port 10000\r\npdivert: got 84 bytes 10.0.1.10 -> 10.0.1.1\r\npdivert: got 84 bytes 10.0.1.10 -> 10.0.1.1\r\n"]
+[25.612472, "o", "2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.356/0.429/0.502 ms\r\n"]
-[26.284339, "o", "  (pdivert flipped the last payload byte and fixed the ICMP checksum)\r\n\r\n"]
+[28.017578, "o", "\u001b[1;36mpftest-pf0# cat /tmp/pflogd.log; ls -l /tmp/pflog.pcap; echo 'pcap header (magic d4c3b2a1, linktype 0x75=DLT_PFLOG):'; od -An -tx1 -N24 /tmp/pflog.pcap\u001b[0m\r\n"]
-[26.284374, "o", "\u001b[1m--- 9. shutdown ---\u001b[0m\r\n"]
+[28.277996, "o", "pflogd: 2 records\r\n-rw-------    1 root     root           352 Nov 12 01:06 /tmp/pflog.pcap\r\npcap header (magic d4c3b2a1, linktype 0x75=DLT_PFLOG):\r\n d4 c3 b2 a1 02 00 04 00 00 00 00 00 00 00 00 00\r\n ff ff 00 00 75 00 00 00\r\n"]
-[26.284384, "o", "\u001b[1;36mpftest-pf0# pkill pdivert; /opt/pf/pfctl -f /dev/null; /opt/pf/pfctl -d; echo 'pf disabled'\u001b[0m\r\n"]
+[28.681267, "o", "\u001b[1;36mpftest-pf0# pkill pflogd 2>/dev/null; /opt/pf/pfctl -f /tmp/demo-pf.conf >/dev/null\u001b[0m\r\n"]
-[26.545211, "o", "pf disabled\r\npf disabled\r\n"]
+[29.352889, "o", "\r\n\u001b[1m--- 9. divert-to: the packet goes to userspace and comes back ---\u001b[0m\r\n"]
-[26.948742, "o", "\u001b[1;36mpftest-pf0# lsmod | grep '^pf '\u001b[0m\r\n"]
+[29.35314, "o", "\u001b[1;36mpftest-pf0# cat /tmp/demo-divert.conf\u001b[0m\r\n"]
-[27.213013, "o", "pf                    548864  0\r\n"]
+[29.625878, "o", "pass in quick proto icmp from 10.0.1.10 to 10.0.1.1 divert-to \"10.0.1.1\" port 10000 keep state\r\npass out quick\r\n"]
-[27.615658, "o", "\r\n\u001b[1mdemo over - port, gates and docs:\u001b[0m\r\n"]
+[30.028664, "o", "\u001b[1;36mpftest-pf0# /opt/pf/pfctl -f /tmp/demo-divert.conf && echo 'divert rule loaded'\u001b[0m\r\n"]
-[27.615733, "o", "\u001b[1m  https://git.labexposed.com/lgcosta/pf-linux-port\u001b[0m\r\n\r\n"]
+[30.317998, "o", "divert rule loaded\r\n"]
+[30.719927, "o", "\u001b[1;36mpftest-pf0# chmod +x /tmp/pdivert; (setsid /tmp/pdivert -p 10000 -f >/tmp/pdivert.log 2>&1 </dev/null &); sleep 1; pgrep pdivert\u001b[0m\r\n"]
+[31.941535, "o", "1956\r\n"]
+[32.344, "o", "\u001b[1;36mpftest-cli# ping -c2 -W2 10.0.1.1 | tail -3\u001b[0m\r\n"]
+[33.584192, "o", "--- 10.0.1.1 ping statistics ---\r\n2 packets transmitted, 2 packets received, 0% packet loss\r\nround-trip min/avg/max = 0.228/0.242/0.257 ms\r\n"]
+[33.987279, "o", "\u001b[1;36mpftest-pf0# head -3 /tmp/pdivert.log\u001b[0m\r\n"]
+[34.261872, "o", "pdivert: listening on divert port 10000\r\npdivert: got 84 bytes 10.0.1.10 -> 10.0.1.1\r\npdivert: got 84 bytes 10.0.1.10 -> 10.0.1.1\r\n"]
+[34.664226, "o", "  (pdivert flipped the last payload byte and fixed the ICMP checksum)\r\n\r\n"]
+[34.664382, "o", "\u001b[1m--- 10. shutdown ---\u001b[0m\r\n\u001b[1;36mpftest-pf0# pkill pdivert; /opt/pf/pfctl -f /dev/null; /opt/pf/pfctl -d; echo 'pf disabled'\u001b[0m\r\n"]
+[34.938113, "o", "pf disabled\r\npf disabled\r\n"]
+[35.340577, "o", "\u001b[1;36mpftest-pf0# lsmod | grep '^pf '\u001b[0m\r\n"]
+[35.617928, "o", "pf                    552960  0\r\n"]
+[36.021187, "o", "\r\n\u001b[1mdemo over - port, gates and docs:\u001b[0m\r\n\u001b[1m  https://git.labexposed.com/lgcosta/pf-linux-port\u001b[0m\r\n\r\n"]

scripts/demo-session.sh

@@ -76,7 +76,7 @@ EGRESS_IF=$(onvm "$PF0_MGMT" "ip route get $SRV_IP | grep -o 'dev [a-z0-9]*' | c
 [ -n "$EGRESS_IF" ] || EGRESS_IF=eth2
 
 scp -q -o ProxyJump=root@192.168.1.242 -i "$KEY" "$CONF" "$DIV" \
-    tools/out/pdivert "root@$PF0_MGMT:/tmp/" 2>/dev/null
+    tools/out/pdivert tools/out/pflogd "root@$PF0_MGMT:/tmp/" 2>/dev/null
 
 bold "==============================================================="
 bold " PF on Linux - the OpenBSD PF 8.0 engine inside the Linux kernel"
@@ -138,7 +138,20 @@ p0 "/opt/pf/pfctl -ss | grep -E 'icmp' | head -4"
 p0 "/opt/pf/pfctl -f /tmp/demo-pf.conf && echo 'back to the stateful ruleset'"
 echo
 
-bold "--- 8. divert-to: the packet goes to userspace and comes back ---"
+bold "--- 8. pflog: logged packets reach userspace (/dev/pflog) ---"
+p0 "cat > /tmp/demo-log.conf <<EOF
+pass in quick log proto icmp from $CLI_IP keep state
+pass out quick
+EOF"
+p0 "/opt/pf/pfctl -f /tmp/demo-log.conf && echo 'log rule loaded'"
+p0 "chmod +x /tmp/pflogd; rm -f /tmp/pflog.pcap; (setsid /tmp/pflogd -c 2 /tmp/pflog.pcap >/tmp/pflogd.log 2>&1 </dev/null &); sleep 1; echo 'pflogd collecting 2 records'"
+vmc "ping -c2 -W2 $SRV_IP | tail -2"
+sleep 2
+p0 "cat /tmp/pflogd.log; ls -l /tmp/pflog.pcap; echo 'pcap header (magic d4c3b2a1, linktype 0x75=DLT_PFLOG):'; od -An -tx1 -N24 /tmp/pflog.pcap"
+p0 "pkill pflogd 2>/dev/null; /opt/pf/pfctl -f /tmp/demo-pf.conf >/dev/null"
+echo
+
+bold "--- 9. divert-to: the packet goes to userspace and comes back ---"
 p0 "cat /tmp/demo-divert.conf"
 p0 "/opt/pf/pfctl -f /tmp/demo-divert.conf && echo 'divert rule loaded'"
 p0 "chmod +x /tmp/pdivert; (setsid /tmp/pdivert -p 10000 -f >/tmp/pdivert.log 2>&1 </dev/null &); sleep 1; pgrep pdivert"
@@ -147,7 +160,7 @@ p0 "head -3 /tmp/pdivert.log"
 echo "  (pdivert flipped the last payload byte and fixed the ICMP checksum)"
 echo
 
-bold "--- 9. shutdown ---"
+bold "--- 10. shutdown ---"
 p0 "pkill pdivert; /opt/pf/pfctl -f /dev/null; /opt/pf/pfctl -d; echo 'pf disabled'"
 p0 "lsmod | grep '^pf '"
 echo

scripts/vm-run-tests.sh

@@ -22,15 +22,18 @@ deploy() {
 	# showed up as a bogus gate failure.  Retry and verify the copy.
 	local i
 	for i in 1 2 3; do
+		local extra=()
+		[ -x "$REPO/tools/out/pdivert" ] && extra+=("$REPO/tools/out/pdivert")
+		[ -x "$REPO/tools/out/pflogd" ] && extra+=("$REPO/tools/out/pflogd")
 		if scp -q -o ProxyJump=root@192.168.1.242 -o StrictHostKeyChecking=accept-new \
 			-i "$HOME/.ssh/pflab_ed" "$REPO/module/pf.ko" \
-			"$REPO/tools/out/pfctl" "$REPO/tests/confs/"*.conf pf0:/tmp/ 2>/dev/null; then
+			"$REPO/tools/out/pfctl" "${extra[@]}" "$REPO/tests/confs/"*.conf pf0:/tmp/ 2>/dev/null; then
 			break
 		fi
 		sleep 2
 	done
 	# stage onto pf0 /opt/pf via mgmt alias already copied to /tmp
-	ssh "$DEB" "$SSH 'mkdir -p /opt/pf; mv /tmp/pf.ko /tmp/pfctl /opt/pf/ 2>/dev/null; true'" >/dev/null
+	ssh "$DEB" "$SSH 'mkdir -p /opt/pf; mv /tmp/pf.ko /tmp/pfctl /tmp/pdivert /tmp/pflogd /opt/pf/ 2>/dev/null; chmod +x /opt/pf/pfctl /opt/pf/pdivert /opt/pf/pflogd 2>/dev/null; true'" >/dev/null
 	ssh "$DEB" "$SSH 'test -s /opt/pf/pf.ko && test -x /opt/pf/pfctl'" >/dev/null 2>&1 || {
 		echo "deploy: pf.ko/pfctl missing on pf0"; return 1; }
 }