freebsd stable - May 2008 - syslog console log not logging SCSI problems

One of our FreeBSD boxes has a SCSI controller and disk, which showed
problems earlier this week.  There was a lot of of chatter from the
SCSI driver in /var/log/messages and to the console.  However, the
console is unattended and we only discovered the problem subsequently
because /var/log/console.log didn't show any of the chatter.

console.log is otherwise working, and very helpful (e.g. it shows
/etc/rc output at boot which lets us spot daemon failures).

We've rebuilt the machine now (fan failure leading to boot disk
failure), so I can't report the SCSI chatter in question, but here is
the dmesg and syslog.conf.  Any suggestions?

(yes, I know this is 6.2-RELEASE; I'm partway through cvsupping; the
failure was under 6.2p11).

Thanks in advance,

Nick Barnes

dmesg:

Copyright (c) 1992-2007 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
        The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 6.2-RELEASE #0: Fri Jan 12 11:05:30 UTC 2007
    root@dessler.cse.buffalo.edu:/usr/obj/usr/src/sys/SMP
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: Intel(R) Pentium(R) 4 CPU 3.00GHz (3006.01-MHz 686-class CPU)
  Origin = "GenuineIntel"  Id = 0xf4a  Stepping = 10
 
Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
  Features2=0x649d<SSE3,RSVD2,MON,DS_CPL,EST,CNTX-ID,CX16,<b14>>
  AMD Features=0x20100000<NX,LM>
  AMD Features2=0x1<LAHF>
  Logical CPUs per core: 2
real memory  = 2137440256 (2038 MB)
avail memory = 2086498304 (1989 MB)
ACPI APIC Table: <INTEL  D945GTP >
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
 cpu0 (BSP): APIC ID:  0
 cpu1 (AP): APIC ID:  1
ioapic0: Changing APIC ID to 2
ioapic0 <Version 2.0> irqs 0-23 on motherboard
kbd1 at kbdmux0
ath_hal: 0.9.17.2 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413)
acpi0: <INTEL D945GTP> on motherboard
acpi0: Power Button (fixed)
Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
cpu0: <ACPI CPU> on acpi0
acpi_perf0: <ACPI CPU Frequency Control> on cpu0
acpi_perf0: failed in PERF_STATUS attach
device_attach: acpi_perf0 attach returned 6
acpi_perf0: <ACPI CPU Frequency Control> on cpu0
acpi_perf0: failed in PERF_STATUS attach
device_attach: acpi_perf0 attach returned 6
cpu1: <ACPI CPU> on acpi0
acpi_perf1: <ACPI CPU Frequency Control> on cpu1
acpi_perf1: failed in PERF_STATUS attach
device_attach: acpi_perf1 attach returned 6
acpi_perf1: <ACPI CPU Frequency Control> on cpu1
acpi_perf1: failed in PERF_STATUS attach
device_attach: acpi_perf1 attach returned 6
acpi_button0: <Sleep Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pci0: <display, VGA> at device 2.0 (no driver attached)
pci0: <multimedia> at device 27.0 (no driver attached)
pcib1: <ACPI PCI-PCI bridge> at device 28.0 on pci0
pci1: <ACPI PCI bus> on pcib1
pcib2: <ACPI PCI-PCI bridge> at device 28.2 on pci0
pci2: <ACPI PCI bus> on pcib2
pcib3: <ACPI PCI-PCI bridge> at device 28.3 on pci0
pci3: <ACPI PCI bus> on pcib3
uhci0: <UHCI (generic) USB controller> port 0x2080-0x209f irq 23 at device
29.0 on pci0
uhci0: [GIANT-LOCKED]
usb0: <UHCI (generic) USB controller> on uhci0
usb0: USB revision 1.0
uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1: <UHCI (generic) USB controller> port 0x2060-0x207f irq 19 at device
29.1 on pci0
uhci1: [GIANT-LOCKED]
usb1: <UHCI (generic) USB controller> on uhci1
usb1: USB revision 1.0
uhub1: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhci2: <UHCI (generic) USB controller> port 0x2040-0x205f irq 18 at device
29.2 on pci0
uhci2: [GIANT-LOCKED]
usb2: <UHCI (generic) USB controller> on uhci2
usb2: USB revision 1.0
uhub2: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhci3: <UHCI (generic) USB controller> port 0x2020-0x203f irq 16 at device
29.3 on pci0
uhci3: [GIANT-LOCKED]
usb3: <UHCI (generic) USB controller> on uhci3
usb3: USB revision 1.0
uhub3: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
ehci0: <Intel 82801GB/R (ICH7) USB 2.0 controller> mem
0x901c4000-0x901c43ff irq 23 at device 29.7 on pci0
ehci0: [GIANT-LOCKED]
usb4: EHCI version 1.0
usb4: companion controllers, 2 ports each: usb0 usb1 usb2 usb3
usb4: <Intel 82801GB/R (ICH7) USB 2.0 controller> on ehci0
usb4: USB revision 2.0
uhub4: Intel EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
pcib4: <ACPI PCI-PCI bridge> at device 30.0 on pci0
pci4: <ACPI PCI bus> on pcib4
ahc0: <Adaptec 29160 Ultra160 SCSI adapter> port 0x1000-0x10ff mem
0x90000000-0x90000fff irq 21 at device 0.0 on pci4
ahc0: [GIANT-LOCKED]
aic7892: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs
fxp0: <Intel 82801GB (ICH7) 10/100 Ethernet> port 0x1100-0x113f mem
0x90001000-0x90001fff irq 20 at device 8.0 on pci4
miibus0: <MII bus> on fxp0
inphy0: <i82562ET 10/100 media interface> on miibus0
inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp0: Ethernet address: 00:16:76:1c:01:2f
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel ICH7 UDMA100 controller> port
0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x20b0-0x20bf irq 18 at device 31.1 on pci0
ata0: <ATA channel 0> on atapci0
ata1: <ATA channel 1> on atapci0
atapci1: <Intel ICH7 SATA300 controller> port
0x20c8-0x20cf,0x20ec-0x20ef,0x20c0-0x20c7,0x20e8-0x20eb,0x20a0-0x20af irq 19 at
device 31.2 on pci0
ata2: <ATA channel 0> on atapci1
ata3: <ATA channel 1> on atapci1
pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
ppc0: <ECP parallel printer port> port 0x378-0x37f,0x778-0x77f irq 7 on
acpi0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/8 bytes threshold
ppbus0: <Parallel port bus> on ppc0
plip0: <PLIP network interface> on ppbus0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on
acpi0
sio0: type 16550A
pmtimer0 on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
sio1: configured irq 3 not in bitmap of probed irqs 0
sio1: port may not be enabled
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
Timecounters tick every 1.000 msec
acd0: CDROM <TSSTcorp CD-ROM SH-C522C/TS02> at ata0-master UDMA33
ad4: 238475MB <Seagate ST3250310AS 3.AAC> at ata2-master SATA150
Waiting 5 seconds for SCSI devices to settle
da0 at ahc0 bus 0 target 6 lun 0
da0: <QUANTUM ATLAS10K3_36_WLS 020W> Fixed Direct Access SCSI-3 device 
da0: 160.000MB/s transfers (80.000MHz, offset 127, 16bit), Tagged Queueing
Enabled
da0: 35074MB (71833096 512 byte sectors: 255H 63S/T 4471C)
SMP: AP CPU #1 Launched!
Trying to mount root from ufs:/dev/ad4s1a

syslog.conf:

# $FreeBSD: src/etc/syslog.conf,v 1.28 2005/03/12 12:31:16 glebius Exp $
#
#       Spaces ARE valid field separators in this file. However,
#       other *nix-like systems still insist on using tabs as field
#       separators. If you are sharing this file between systems, you
#       may want to use only tabs as field separators here.
#       Consult the syslog.conf(5) manpage.
*.err;kern.warning;auth.notice;mail.crit                /dev/console
*.notice;authpriv.none;kern.debug;lpr.info;mail.crit;news.err  
/var/log/messages
security.*;auth.*                               /var/log/security
auth.info;authpriv.info                         /var/log/auth.log
mail.info                                       /var/log/maillog
lpr.info                                        /var/log/lpd-errs
ftp.info                                        /var/log/xferlog
cron.*                                          /var/log/cron
*.=debug                                        /var/log/debug.log
*.emerg                                         *
console.*                                       /var/log/console.log
# uncomment this to enable logging of all log messages to /var/log/all.log
# touch /var/log/all.log and chmod it to mode 600 before it will work
#*.*                                            /var/log/all.log
# uncomment this to enable logging to a remote loghost named loghost
#*.*                                            @loghost
# uncomment these if you're running inn
# news.crit                                     /var/log/news/news.crit
# news.err                                      /var/log/news/news.err
# news.notice                                   /var/log/news/news.notice
!startslip
*.*                                             /var/log/slip.log
!ppp
*.*                                             /var/log/ppp.log

On Thu, May 15, 2008 at 10:14:01AM +0100, Nick Barnes
wrote:
> One of our FreeBSD boxes has a SCSI controller and disk, which showed
> problems earlier this week.  There was a lot of of chatter from the
> SCSI driver in /var/log/messages and to the console.  However, the
> console is unattended and we only discovered the problem subsequently
> because /var/log/console.log didn't show any of the chatter.
> 
> console.log is otherwise working, and very helpful (e.g. it shows
> /etc/rc output at boot which lets us spot daemon failures).
> 
> We've rebuilt the machine now (fan failure leading to boot disk
> failure), so I can't report the SCSI chatter in question, but here is
> the dmesg and syslog.conf.  Any suggestions?
/boot/loader.conf, /boot.config, and /etc/make.conf would also be
useful.

-- 
| Jeremy Chadwick                                jdc at parodius.com |
| Parodius Networking                       http://www.parodius.com/ |
| UNIX Systems Administrator                  Mountain View, CA, USA |
| Making life hard for others since 1977.              PGP: 4BD6C0CB |

At 2008-05-15 09:46:32+0000, Jeremy Chadwick writes:
> On Thu, May 15, 2008 at 10:14:01AM +0100, Nick Barnes wrote:
> > One of our FreeBSD boxes has a SCSI controller and disk, which showed
> > problems earlier this week.  There was a lot of of chatter from the
> > SCSI driver in /var/log/messages and to the console.  However, the
> > console is unattended and we only discovered the problem subsequently
> > because /var/log/console.log didn't show any of the chatter.
> > 
> > console.log is otherwise working, and very helpful (e.g. it shows
> > /etc/rc output at boot which lets us spot daemon failures).
> > 
> > We've rebuilt the machine now (fan failure leading to boot disk
> > failure), so I can't report the SCSI chatter in question, but here
is
> > the dmesg and syslog.conf.  Any suggestions?
> 
> /boot/loader.conf, /boot.config, and /etc/make.conf would also be
> useful.
All empty, except setting kern.maxdsiz in /boot/loader.conf.  Running
GENERIC.

If this happens again, I will retain a copy of /var/log/messages so I
can report the SCSI messages in question, but they aren't as
interesting to me as the fact that they didn't appear in console.log.

Nick B

At 2008-05-15 10:02:03+0000, Jeremy Chadwick writes:
> Another thing I can think of would be your kernel configuration.  Can
> you provide it?
Just GENERIC.

By the way, the need to set kern.maxdsiz - for really big processes -
doesn't seem to be documented anywhere.  I could have sworn it used to
be in the Handbook, but I don't see it there.  I guess it should be
both there and in tuning(7). Rediscovering this switch took me 30
minutes yesterday.

Nick B

Nick Barnes wrote:
 > One of our FreeBSD boxes has a SCSI controller and disk, which showed
 > problems earlier this week.  There was a lot of of chatter from the
 > SCSI driver in /var/log/messages and to the console.  However, the
 > console is unattended and we only discovered the problem subsequently
 > because /var/log/console.log didn't show any of the chatter.

The console.* syslog facility only logs real console output,
i.e. things written to /dev/console.  That does _not_ include
output from the kernel.

For logging kernel output you have to use the kern.* syslog
facility.

Best regards
   Oliver

-- 
Oliver Fromme, secnetix GmbH & Co. KG, Marktplatz 29, 85567 Grafing b. M.
Handelsregister: Registergericht Muenchen, HRA 74606,  Gesch?ftsfuehrung:
secnetix Verwaltungsgesellsch. mbH, Handelsregister: Registergericht M?n-
chen, HRB 125758,  Gesch?ftsf?hrer: Maik Bachmann, Olaf Erb, Ralf Gebhart

FreeBSD-Dienstleistungen, -Produkte und mehr:  http://www.secnetix.de/bsd

"And believe me, as a C++ programmer, I don't hesitate to question
the decisions of language designers.  After a decent amount of C++
exposure, Python's flaws seem ridiculously small." -- Ville Vainio

At 2008-05-20 16:21:01+0000, Oliver Fromme writes:
> Nick Barnes wrote:
>  > One of our FreeBSD boxes has a SCSI controller and disk, which showed
>  > problems earlier this week.  There was a lot of of chatter from the
>  > SCSI driver in /var/log/messages and to the console.  However, the
>  > console is unattended and we only discovered the problem subsequently
>  > because /var/log/console.log didn't show any of the chatter.
> 
> The console.* syslog facility only logs real console output,
> i.e. things written to /dev/console.  That does _not_ include
> output from the kernel.
> 
> For logging kernel output you have to use the kern.* syslog
> facility.
OK.  So when syslogd directs output to the console, it does not also
treat it as console.* output?  Thanks for this explanation. I'll
modify my syslog.conf accordingly.

Nick B