>Synopsis: unwind is too noisy on sendto failures / it's misleading
>Category: user
>Environment:
System : OpenBSD 7.2
Details : OpenBSD 7.2 (GENERIC.MP) #7: Sat Feb 25 14:07:21 MST 2023
r...@syspatch-72-arm64.openbsd.org:/usr/src/sys/arch/arm64/compile/GENERIC.MP
Architecture: OpenBSD.arm64
Machine : arm64
>Description:
Happy Easter Weekend! I hope this is my only bug report. I was getting
a lot of "packet too short" log messages in my logs after enabling firewall
rules to not leak dns data. I want unwind to _only_ go to my forwarder and not
anywhere else. Here is a sample anchor rule I applied:
root@polarstern# pfctl -a"unwind leakage" -srules
block return log inet proto udp all user = 48
block return log inet proto tcp all user = 48
block return log inet6 proto udp all user = 48
block return log inet6 proto tcp all user = 48
pass on lo0 inet proto udp all user = 48
pass on lo0 inet proto tcp all user = 48 flags S/SA
pass on em0 inet proto udp from 192.168.177.13 to 192.168.177.13 user = 48
pass on em0 inet proto tcp from 192.168.177.13 to 192.168.177.13 user = 48
flags S/SA
I run my own software in front of unwind like so:
[unwind] --> [delphinusdnsd locally ] -- Internet -> [delphinusdnsd + unbound]
When I see these too short packets I nearly freak out because I think my
software is broken (it's happened before, that yes it was broken). Until I
ktraced this I was none the wiser. Please see the how to repeat section:
>How-To-Repeat:
This shows a ktrace of the resolver of unwind:
7117 unwind CALL socket(AF_INET,0x5002<SOCK_DGRAM|SOCK_NONBLOCK|SOCK_DNS>,0
)
7117 unwind RET socket 7
7117 unwind CALL connect(7,0x1a3ab37350,16)
7117 unwind STRU struct sockaddr { AF_INET, 217.237.151.205:53 }
7117 unwind RET connect 0
7117 unwind CALL sendto(7,0x1a8a1c4c00,0x2c,0,0,0)
7117 unwind RET sendto -1 errno 13 Permission denied
7117 unwind CALL close(7)
7117 unwind RET close 0
7117 unwind CALL getpid()
7117 unwind RET getpid 7117/0x1bcd
7117 unwind CALL sendsyslog(0x7ffffc5004,39,0<>)
7117 unwind GIO fd -1 wrote 39 bytes
0000: 3c 32 37 3e 75 6e 77 69 6e 64 5b 37 31 31 37 5d <27>unwind[7117]
0010: 3a 20 62 61 64 20 70 61 63 6b 65 74 3a 20 74 6f : bad packet: to
0020: 6f 20 73 68 6f 72 74 o short
7117 unwind RET sendsyslog 0
>Fix:
It's rare that I do a fix because often it's not correct so I leave it, but...
here goes: (I have updated to the -current unwind with this on a 7.2 system).
This leaves just one syslog for this:
Apr 7 17:45:43 stern unwind[28804]: check_resolver_done: bad packet: too
short: -1
but it's indicating that it's -1 and thus can be ignored by me. The others
don't indicated the answer_length...
Index: resolver.c
===================================================================
RCS file: /cvs/src/sbin/unwind/resolver.c,v
retrieving revision 1.158
diff -u -p -u -r1.158 resolver.c
--- resolver.c 8 Feb 2023 08:01:25 -0000 1.158
+++ resolver.c 7 Apr 2023 15:32:25 -0000
@@ -954,7 +954,8 @@ resolve_done(struct uw_resolver *res, vo
running_res = --rq->running;
if (answer_len < LDNS_HEADER_SIZE) {
- log_warnx("bad packet: too short");
+ if (answer_len != -1)
+ log_warnx("bad packet: too short");
goto servfail;
}
@@ -1547,7 +1548,8 @@ check_resolver_done(struct uw_resolver *
if (answer_len < LDNS_HEADER_SIZE) {
checked_resolver->state = DEAD;
- log_warnx("%s: bad packet: too short", __func__);
+ if (answer_len != -1)
+ log_warnx("%s: bad packet: too short", __func__);
goto out;
}
@@ -1902,7 +1904,8 @@ trust_anchor_resolve_done(struct uw_reso
char rdata_buf[1024], *ta;
if (answer_len < LDNS_HEADER_SIZE) {
- log_warnx("bad packet: too short");
+ if (answer_len != -1)
+ log_warnx("bad packet: too short");
goto out;
}
dmesg:
OpenBSD 7.2 (GENERIC.MP) #7: Sat Feb 25 14:07:21 MST 2023
r...@syspatch-72-arm64.openbsd.org:/usr/src/sys/arch/arm64/compile/GENERIC.MP
real mem = 8432852992 (8042MB)
avail mem = 8139448320 (7762MB)
random: good seed from bootblocks
mainbus0 at root: ACPI
psci0 at mainbus0: PSCI 1.1, SMCCC 1.2
cpu0 at mainbus0 mpidr 0: ARM Cortex-A72 r0p3
cpu0: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu0: 1024KB 64b/line 16-way L2 cache
cpu0: CRC32,ASID16
cpu1 at mainbus0 mpidr 1: ARM Cortex-A72 r0p3
cpu1: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu1: 1024KB 64b/line 16-way L2 cache
cpu1: CRC32,ASID16
cpu2 at mainbus0 mpidr 2: ARM Cortex-A72 r0p3
cpu2: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu2: 1024KB 64b/line 16-way L2 cache
cpu2: CRC32,ASID16
cpu3 at mainbus0 mpidr 3: ARM Cortex-A72 r0p3
cpu3: 48KB 64b/line 3-way L1 PIPT I-cache, 32KB 64b/line 2-way L1 D-cache
cpu3: 1024KB 64b/line 16-way L2 cache
cpu3: CRC32,ASID16
efi0 at mainbus0: UEFI 2.7
efi0: https://github.com/pftf/RPi4 rev 0x10000
smbios0 at efi0: SMBIOS 3.3.0
smbios0: vendor https://github.com/pftf/RPi4 version "UEFI Firmware v1.21" date
11/13/2020
smbios0: Raspberry Pi Foundation Raspberry Pi 4 Model B
apm0 at mainbus0
ampintc0 at mainbus0 nirq 256, ncpu 4 ipi: 0, 1, 2: "interrupt-controller"
agtimer0 at mainbus0: 54000 kHz
acpi0 at mainbus0: ACPI 6.3
acpi0: sleep states
acpi0: tables DSDT FACP CSRT DBG2 GTDT IORT APIC PPTT BGRT
acpi0: wakeup devices
acpiiort0 at acpi0
"BCM2849" at acpi0 not configured
"BCM2835" at acpi0 not configured
"BCM2854" at acpi0 not configured
"ACPI0004" at acpi0 not configured
xhci0 at acpi0 XHC0 addr 0x600000000/0x1000 irq 175, xHCI 1.0
usb0 at xhci0: USB revision 3.0
uhub0 at usb0 configuration 1 interface 0 "Generic xHCI root hub" rev 3.00/1.00
addr 1
"ACPI0007" at acpi0 not configured
"ACPI0007" at acpi0 not configured
"ACPI0007" at acpi0 not configured
"ACPI0007" at acpi0 not configured
"ACPI0004" at acpi0 not configured
"BCM2848" at acpi0 not configured
"BCM2850" at acpi0 not configured
"BCM2856" at acpi0 not configured
"BCM2845" at acpi0 not configured
"BCM2841" at acpi0 not configured
"BCM2841" at acpi0 not configured
"BCM2838" at acpi0 not configured
"BCM2839" at acpi0 not configured
"BCM2844" at acpi0 not configured
pluart0 at acpi0 URT0 addr 0xfe201000/0x1000 irq 153
"BCM2836" at acpi0 not configured
"BCM2EA6" at acpi0 not configured
"MSFT8000" at acpi0 not configured
sdhc0 at acpi0 SDC1 addr 0xfe300000/0x100 irq 158
sdhc0: base clock frequency unknown
"BCM2855" at acpi0 not configured
bse0 at acpi0 ETH0 addr 0xfd580000/0x10000 irq 189: address dc:a6:32:cc:db:a7
brgphy0 at bse0 phy 1: BCM54210E 10/100/1000baseT PHY, rev. 2
"PNP0C06" at acpi0 not configured
acpitz0 at acpi0: critical temperature is 90 degC
simplefb0 at mainbus0: 640x480, 32bpp
wsdisplay0 at simplefb0 mux 1: console (std, vt100 emulation)
wsdisplay0: screen 1-5 added (std, vt100 emulation)
uhub1 at uhub0 port 1 configuration 1 interface 0 "VIA Labs USB2.0 Hub" rev
2.10/4.21 addr 2
uhidev0 at uhub1 port 4 configuration 1 interface 0 "APC Back-UPS ES 700G
FW:871.O4 .I USB FW:O4" rev 1.10/1.06 addr 3
uhidev0: iclass 3/0, 146 report ids
upd0 at uhidev0
uhid0 at uhidev0 reportid 1: input=0, output=0, feature=1
uhid1 at uhidev0 reportid 2: input=0, output=0, feature=1
uhid2 at uhidev0 reportid 3: input=0, output=0, feature=1
uhid3 at uhidev0 reportid 4: input=0, output=0, feature=1
uhid4 at uhidev0 reportid 5: input=0, output=0, feature=1
uhid5 at uhidev0 reportid 6: input=1, output=0, feature=1
uhid6 at uhidev0 reportid 7: input=0, output=0, feature=2
uhid7 at uhidev0 reportid 8: input=0, output=0, feature=2
uhid8 at uhidev0 reportid 9: input=0, output=0, feature=2
uhid9 at uhidev0 reportid 10: input=0, output=0, feature=1
uhid10 at uhidev0 reportid 11: input=0, output=0, feature=1
uhid11 at uhidev0 reportid 12: input=3, output=0, feature=3
uhid12 at uhidev0 reportid 13: input=0, output=0, feature=1
uhid13 at uhidev0 reportid 14: input=0, output=0, feature=1
uhid14 at uhidev0 reportid 15: input=0, output=0, feature=1
uhid15 at uhidev0 reportid 16: input=0, output=0, feature=1
uhid16 at uhidev0 reportid 17: input=0, output=0, feature=1
uhid17 at uhidev0 reportid 18: input=0, output=0, feature=1
uhid18 at uhidev0 reportid 23: input=0, output=0, feature=2
uhid19 at uhidev0 reportid 24: input=0, output=0, feature=1
uhid20 at uhidev0 reportid 28: input=0, output=0, feature=3
uhid21 at uhidev0 reportid 32: input=0, output=0, feature=2
uhid22 at uhidev0 reportid 34: input=0, output=0, feature=1
uhid23 at uhidev0 reportid 35: input=0, output=0, feature=2
uhid24 at uhidev0 reportid 36: input=0, output=0, feature=2
uhid25 at uhidev0 reportid 37: input=0, output=0, feature=2
uhid26 at uhidev0 reportid 38: input=0, output=0, feature=2
uhid27 at uhidev0 reportid 39: input=0, output=0, feature=1
uhid28 at uhidev0 reportid 40: input=0, output=0, feature=4
uhid29 at uhidev0 reportid 48: input=0, output=0, feature=2
uhid30 at uhidev0 reportid 49: input=0, output=0, feature=2
uhid31 at uhidev0 reportid 50: input=0, output=0, feature=2
uhid32 at uhidev0 reportid 51: input=0, output=0, feature=2
uhid33 at uhidev0 reportid 52: input=0, output=0, feature=1
uhid34 at uhidev0 reportid 53: input=0, output=0, feature=1
uhid35 at uhidev0 reportid 54: input=0, output=0, feature=1
uhid36 at uhidev0 reportid 64: input=0, output=0, feature=1
uhid37 at uhidev0 reportid 65: input=0, output=0, feature=2
uhid38 at uhidev0 reportid 80: input=0, output=0, feature=1
uhid39 at uhidev0 reportid 81: input=0, output=0, feature=1
uhid40 at uhidev0 reportid 96: input=0, output=0, feature=2
uhid41 at uhidev0 reportid 97: input=0, output=0, feature=1
uhid42 at uhidev0 reportid 98: input=0, output=0, feature=4
uhid43 at uhidev0 reportid 120: input=0, output=0, feature=1
uhid44 at uhidev0 reportid 121: input=0, output=0, feature=1
uhid45 at uhidev0 reportid 122: input=0, output=0, feature=4
uhid46 at uhidev0 reportid 123: input=0, output=0, feature=2
uhid47 at uhidev0 reportid 124: input=0, output=0, feature=1
uhid48 at uhidev0 reportid 125: input=0, output=0, feature=1
uhid49 at uhidev0 reportid 126: input=0, output=0, feature=1
uhid50 at uhidev0 reportid 127: input=0, output=0, feature=1
uhid51 at uhidev0 reportid 140: input=0, output=0, feature=1
uhid52 at uhidev0 reportid 141: input=0, output=0, feature=1
uhid53 at uhidev0 reportid 142: input=0, output=0, feature=1
uhid54 at uhidev0 reportid 143: input=0, output=0, feature=1
uhid55 at uhidev0 reportid 144: input=0, output=0, feature=1
uhid56 at uhidev0 reportid 145: input=0, output=0, feature=2
uhid57 at uhidev0 reportid 146: input=0, output=0, feature=2
umass0 at uhub0 port 3 configuration 1 interface 0 "Samsung Flash Drive FIT"
rev 3.10/11.00 addr 4
umass0: using SCSI over Bulk-Only
scsibus0 at umass0: 2 targets, initiator 0
sd0 at scsibus0 targ 1 lun 0: <Samsung, Flash Drive FIT, 1100> removable
serial.090c1000521110001360
sd0: 244752MB, 512 bytes/sector, 501253132 sectors
vscsi0 at root
scsibus1 at vscsi0: 256 targets
softraid0 at root
scsibus2 at softraid0: 256 targets
root on sd0a (081866428dff49a4.a) swap on sd0b dump on sd0b
WARNING: bad clock chip time
WARNING: CHECK AND RESET THE DATE!
usbdevs:
Controller /dev/usb0:
addr 01: 0000:0000 Generic, xHCI root hub
super speed, self powered, config 1, rev 1.00
driver: uhub0
addr 02: 2109:3431 VIA Labs, USB2.0 Hub
high speed, self powered, config 1, rev 4.21
driver: uhub1
addr 03: 051d:0002 APC, Back-UPS ES 700G FW:871.O4 .I USB FW:O4
low speed, power 2 mA, config 1, rev 1.06, iSerial 5B1936T42959
driver: uhidev0
addr 04: 090c:1000 Samsung, Flash Drive FIT
super speed, power 76 mA, config 1, rev 11.00, iSerial 0319521110001360
driver: umass0
