syslogd: Syscall 28 (SYS_sendmsg) in 18 October (i386) snapshot

[Scott Vanderbilt]

Another pledge(2) related issue, this time in syslogd.

Unfortunately, this occurs on an ancient Soekris box where rebuilding 
the syslogd executable will be a non-trivial task. Hopefully I am 
providing enough details to here to allow someone more knowledgeable 
with the information necessary to make a fix:


# dmesg
OpenBSD 5.8-current (GENERIC) #1270: Sun Oct 18 08:03:38 MDT 2015
dera...@i386.openbsd.org:/usr/src/sys/arch/i386/compile/GENERIC
cpu0: Geode(TM) Integrated Processor by National Semi ("Geode by NSC" 
586-class) 267 MHz

cpu0: FPU,TSC,MSR,CX8,CMOV,MMX
real mem  = 267927552 (255MB)
avail mem = 250290176 (238MB)
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0: date 20/50/29, BIOS32 rev. 0 @ 0xf7840
pcibios0 at bios0: rev 2.0 @ 0xf/0x1
pcibios0: pcibios_get_intr_routing - function not supported
pcibios0: PCI IRQ Routing information unavailable.
pcibios0: PCI bus #0 is the last bus
bios0: ROM list: 0xc8000/0x9000
cpu0 at mainbus0: (uniprocessor)
cpu0: TSC disabled
pci0 at mainbus0 bus 0: configuration mode 1 (bios)
pchb0 at pci0 dev 0 function 0 "Cyrix GXm PCI" rev 0x00
sis0 at pci0 dev 6 function 0 "NS DP83815 10/100" rev 0x00, DP83816A: 
irq 10, address 00:00:24:c7:a7:d0

nsphyter0 at sis0 phy 0: DP83815 10/100 PHY, rev. 1
sis1 at pci0 dev 7 function 0 "NS DP83815 10/100" rev 0x00, DP83816A: 
irq 10, address 00:00:24:c7:a7:d1

nsphyter1 at sis1 phy 0: DP83815 10/100 PHY, rev. 1
sis2 at pci0 dev 8 function 0 "NS DP83815 10/100" rev 0x00, DP83816A: 
irq 10, address 00:00:24:c7:a7:d2

nsphyter2 at sis2 phy 0: DP83815 10/100 PHY, rev. 1
gscpcib0 at pci0 dev 18 function 0 "NS SC1100 ISA" rev 0x00
gpio0 at gscpcib0: 64 pins
"NS SC1100 SMI" rev 0x00 at pci0 dev 18 function 1 not configured
pciide0 at pci0 dev 18 function 2 "NS SCx200 IDE" rev 0x01: DMA, channel 
0 wired to compatibility, channel 1 wired to compatibility

wd0 at pciide0 channel 0 drive 0: 
wd0: 1-sector PIO, LBA48, 15247MB, 31227840 sectors
wd0(pciide0:0:0): using PIO mode 4, Ultra-DMA mode 2
geodesc0 at pci0 dev 18 function 5 "NS SC1100 X-Bus" rev 0x00: iid 6 
revision 3 wdstatus 0
ohci0 at pci0 dev 19 function 0 "Compaq USB OpenHost" rev 0x08: irq 11, 
version 1.0, legacy support

isa0 at gscpcib0
isadma0 at isa0
com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
com0: console
com1 at isa0 port 0x2f8/8 irq 3: ns16550a, 16 byte fifo
pckbc0 at isa0 port 0x60/5 irq 1 irq 12
pckbd0 at pckbc0 (kbd slot)
wskbd0 at pckbd0: console keyboard
pcppi0 at isa0 port 0x61
spkr0 at pcppi0
nsclpcsio0 at isa0 port 0x2e/2: NSC PC87366 rev 9: GPIO VLM TMS
gpio1 at nsclpcsio0: 29 pins
gscsio0 at isa0 port 0x15c/2: SC1100 SIO rev 1:
npx0 at isa0 port 0xf0/16: reported by CPUID; using exception 16
usb0 at ohci0: USB revision 1.0
uhub0 at usb0 "Compaq OHCI root hub" rev 1.00/1.00 addr 1
vscsi0 at root
scsibus1 at vscsi0: 256 targets
softraid0 at root
scsibus2 at softraid0: 256 targets
root on wd0a (4a7ad08651285594.a) swap on wd0b dump on wd0b
syslogd(27308): syscall 28
syslogd(25829): syscall 28
#
#
# grep 28 /usr/include/sys/syscall.h
#define SYS_sendmsg 28
[...]
#
# ktrace -di /usr/sbin/syslogd
syslogd: receive_fd: recvmsg: expected received 1 got 0
syslogd: receive_fd: no message header
syslogd: /dev/console
#
# kdump
[...]
 27711 syslogd  CALL  stat(0x39c4fbc0,0x39c4ffc0)
 27711 syslogd  NAMI  "/etc/syslog.conf"
 27711 syslogd  STRU  struct stat { dev=0, ino=291, mode=-rw-r--r-- , 
nlink=1, uid=0<"root">, gid=0<"wheel">, rdev=11582, 
atime=1445195141<"Oct 18 12:05:41 2015">.153570775, 
mtime=1438904602<"Aug  6 16:43:22 2015">.829126996, 
ctime=1438904602<"Aug  6 16:43:22 2015">.829126996, size=1472, blocks=4, 
blksize=16384, flags=0x0, gen=0x53936b06 }

 27711 syslogd  RET   stat 0
 27711 syslogd  CALL  open(0x39c4fbc0,0x4)
 27711 syslogd  NAMI  "/etc/syslog.conf"
 27711 syslogd  RET   open 3
 27711 syslogd  CALL  kbind(0xcf7e63c8,0xc,0xc335e692,0x5423a109)
 27711 syslogd  RET   kbind 0
 27711 syslogd  CALL  sendmsg(8,0xcf7e6450,0)
 27711 syslogd  STRU  struct msghdr { name=0x0, namelen=0, 
iov=0xcf7e647c, iovlen=1, control=0xcf7e646c, controllen=16, flags=0 }

 27711 syslogd  STRU  struct iovec { base=0xcf7e6484, len=4 }
 27711 syslogd  STRU  struct cmsghdr { len=16, level=SOL_SOCKET, 
type=SCM_RIGHTS, data=3 }

 27711 syslogd  GIO   fd 8 wrote 4 bytes
   "\0\0\0\0"
 27711 syslogd  RET   sendmsg 4
 27711 syslogd  CALL  close(3)
 27711 syslogd  RET   close 0
 27711 syslogd  CALL  read(8,0xcf7e66ec,0x4)
  1360 syslogd  CALL  kbind(0xcf7e6888,0xc,0xc335e692,0x5423a109)
  1360 syslogd  RET   kbind 0
  1360 syslogd  CALL  recvmsg(11,0xcf7e6920,0)
  1360 syslogd  GIO   fd 11 read 4 bytes
   "\0\0\0\0"
  1360 syslogd  STRU  struct cmsghdr { len=16, level=SOL_SOCKET, 
type=SCM_RIGHTS, data=12 }
  1360 syslogd  STRU  struct msghdr { name=0x0, namelen=0, 
iov=0xcf7e694c, iovlen=1, control=0xcf7e693c, controllen=16, flags=0 }

  1360 syslogd  STRU  struct iovec { 

Re: syslogd: Syscall 28 (SYS_sendmsg) in 18 October (i386) snapshot

[Sonic]

On Sun, Oct 18, 2015 at 3:22 PM, Scott Vanderbilt  wrote:
> Another pledge(2) related issue, this time in syslogd.

No clue if my bug is related. Attempting to upgrade -current today and I get:
Oct 18 14:29:39 stargate /bsd: ksh(4880): syscall 131
Oct 18 14:29:46 stargate /bsd: ksh(30776): syscall 131
etc.

This is after installing the new kernel and rebooting to build
userland (it may just be an out of sync issue).
However after the reboot, I cannot login as root, I can login as a
user, but cannot "su -", although I can "su" (no dash). Also cannot
run tmux, it crashes.
I've reinstalled the old kernel to get back in sync with the userland.

Chris

Re: syslogd: Syscall 28 (SYS_sendmsg) in 18 October (i386) snapshot

[Doug Hogan]

On Sun, Oct 18, 2015 at 03:42:07PM -0400, Sonic wrote:
> No clue if my bug is related. Attempting to upgrade -current today and I get:
> Oct 18 14:29:39 stargate /bsd: ksh(4880): syscall 131
> Oct 18 14:29:46 stargate /bsd: ksh(30776): syscall 131
> etc.

I don't think it's related since it's complaining about different
syscalls.  You ran into this situation:

Old kernel: accepts "flock" pledge but doesn't require it
Old ksh: no "flock" pledge
New kernel: accepts "flock" and requires it for the syscall
New ksh: added "flock" pledge

You went from old kernel + old ksh to new kernel + old ksh.  It killed
ksh because old ksh didn't request "flock" pledge before calling it.

The solution for me was to rebuild the userland programs that require
"flock" with the old kernel and then reboot with the new kernel.
However, that was yesterday and I did it shortly after that commit.
It's a fast moving target.  You may be better off upgrading from a
snapshot and then rebuilding -current.

Re: syslogd: Syscall 28 (SYS_sendmsg) in 18 October (i386) snapshot

[Theo de Raadt]

> On Sun, Oct 18, 2015 at 03:42:07PM -0400, Sonic wrote:
> > No clue if my bug is related. Attempting to upgrade -current today and I 
> > get:
> > Oct 18 14:29:39 stargate /bsd: ksh(4880): syscall 131
> > Oct 18 14:29:46 stargate /bsd: ksh(30776): syscall 131
> > etc.
> 
> I don't think it's related since it's complaining about different
> syscalls.  You ran into this situation:
> 
> Old kernel: accepts "flock" pledge but doesn't require it
> Old ksh: no "flock" pledge
> New kernel: accepts "flock" and requires it for the syscall
> New ksh: added "flock" pledge
> 
> You went from old kernel + old ksh to new kernel + old ksh.  It killed
> ksh because old ksh didn't request "flock" pledge before calling it.
> 
> The solution for me was to rebuild the userland programs that require
> "flock" with the old kernel and then reboot with the new kernel.
> However, that was yesterday and I did it shortly after that commit.
> It's a fast moving target.

> You may be better off upgrading from a snapshot and then rebuilding -current.

^