em driver regression

Thu Apr 8 17:19:00 UTC 2010

On Thu, Apr 8, 2010 at 12:06 PM, Jack Vogel <jfvogel at gmail.com> wrote:
>
>
> On Thu, Apr 8, 2010 at 10:01 AM, Brandon Gooch <jamesbrandongooch at gmail.com>
> wrote:
>>
>> On Thu, Apr 8, 2010 at 11:52 AM, Jack Vogel <jfvogel at gmail.com> wrote:
>> > Mike, I noticed this connection is only 100Mb, that isn't accidental?
>> > And,
>> > is it possible for
>> > you to check a connection at 1Gb and see if the watchdogs don't happen.
>> >
>> > My test engineer is running this code, and we are having trouble
>> > repro'ing
>> > the issue, so any
>> > clues might help. Is the kernel 64 or 32 bit?
>> >
>> > Jack
>> >
>>
>> Not to butt in or anything...
>
> Not butting in :)  OK, so this all looks fine or am I missing something?
>
> Jack
>

This is the dmesg from the system exhibiting the "ip length 328
disagrees with bytes received 332" while attempting to obtain a lease
on the two DHCP-enabled VLANs, and also manifests in the VirtualBox
bridged networking guests.

I can honestly say that other than the output from dhclient and the
VirtualBox issue, I might not have noticed problems otherwise.

For instance, I have a VLAN interface configured to connect to an
"outside" LAN segment and I'm running sshd on that interfaces IP
address (using the new multiple routing table feature as well). I was
able to connect to the sshd instance as usual, and I can make
connections out as in:

# setfib 4 ping google.com

...things seemed OK. Until VirtualBox. Then I started paying attention
to messages scrolling by as my machine booted and saw the dhclient "ip
length" thing (just as Mike Tancsa had) and thought, "It must be the
new em(4) driver".

That's my story :)

I don't know what chip my em(4) device is, how can I check that? Also,
would some type of traffic capture help in this case?

-Brandon

>>
>> 64-bit FreeBSD Stable, 1Gb em(4) connected to Cisco 2960G trunking port.
>>
>> My dmesg:
>>
>> Copyright (c) 1992-2010 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 8.0-STABLE #2 r206210:206343MS: Wed Apr  7 16:18:14 CDT 2010
>>    root at bgooch755.se.edu:/usr/obj/usr/src/sys/DELL755 amd64
>> Timecounter "i8254" frequency 1193182 Hz quality 0
>> CPU: Intel(R) Core(TM)2 Quad CPU    Q6600  @ 2.40GHz (2394.00-MHz K8-class
>> CPU)
>>  Origin = "GenuineIntel"  Id = 0x6fb  Family = 6  Model = f  Stepping = 11
>>
>>  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=0xe3bd<SSE3,DTES64,MON,DS_CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM>
>>  AMD Features=0x20100800<SYSCALL,NX,LM>
>>  AMD Features2=0x1<LAHF>
>>  TSC: P-state invariant
>> real memory  = 8589934592 (8192 MB)
>> avail memory = 8103940096 (7728 MB)
>> ACPI APIC Table: <DELL   B9K    >
>> FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
>> FreeBSD/SMP: 1 package(s) x 4 core(s)
>>  cpu0 (BSP): APIC ID:  0
>>  cpu1 (AP): APIC ID:  1
>>  cpu2 (AP): APIC ID:  2
>>  cpu3 (AP): APIC ID:  3
>> ioapic0: Changing APIC ID to 8
>> ioapic0 <Version 2.0> irqs 0-23 on motherboard
>> lapic0: Forcing LINT1 to edge trigger
>> kbd1 at kbdmux0
>> acpi0: <DELL B9K    > on motherboard
>> acpi0: [ITHREAD]
>> acpi0: Power Button (fixed)
>> Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
>> acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
>> cpu0: <ACPI CPU> on acpi0
>> cpu1: <ACPI CPU> on acpi0
>> cpu2: <ACPI CPU> on acpi0
>> cpu3: <ACPI CPU> on acpi0
>> acpi_hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on
>> acpi0
>> Timecounter "HPET" frequency 14318180 Hz quality 900
>> acpi_button0: <Power Button> on acpi0
>> pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
>> pci0: <ACPI PCI bus> on pcib0
>> pcib1: <ACPI PCI-PCI bridge> irq 16 at device 1.0 on pci0
>> pci1: <ACPI PCI bus> on pcib1
>> vgapci0: <VGA-compatible display> port 0xdc80-0xdcff mem
>> 0xfd000000-0xfdffffff,0xd0000000-0xdfffffff,0xfa000000-0xfbffffff irq
>> 16 at device 0.0 on pci1
>> nvidia0: <GeForce 8400 GS> on vgapci0
>> vgapci0: child nvidia0 requested pci_enable_busmaster
>> vgapci0: child nvidia0 requested pci_enable_io
>> vgapci0: child nvidia0 requested pci_enable_io
>> nvidia0: [ITHREAD]
>> pci0: <simple comms> at device 3.0 (no driver attached)
>> atapci0: <Intel ATA controller> port
>> 0xfe80-0xfe87,0xfe90-0xfe93,0xfea0-0xfea7,0xfeb0-0xfeb3,0xfef0-0xfeff
>> irq 18 at device 3.2 on pci0
>> atapci0: [ITHREAD]
>> ata2: <ATA channel 0> on atapci0
>> ata2: [ITHREAD]
>> ata3: <ATA channel 1> on atapci0
>> ata3: [ITHREAD]
>> pci0: <simple comms, UART> at device 3.3 (no driver attached)
>> em0: <Intel(R) PRO/1000 Network Connection 7.0.1> port 0xecc0-0xecdf
>> mem 0xfebe0000-0xfebfffff,0xfebdb000-0xfebdbfff irq 21 at device 25.0
>> on pci0
>> em0: Using MSI interrupt
>> em0: [FILTER]
>> em0: Ethernet address: 00:1e:4f:d5:84:b7
>> uhci0: <Intel 82801I (ICH9) USB controller> port 0xff20-0xff3f irq 16
>> at device 26.0 on pci0
>> uhci0: [ITHREAD]
>> uhci0: LegSup = 0x2f00
>> usbus0: <Intel 82801I (ICH9) USB controller> on uhci0
>> uhci1: <Intel 82801I (ICH9) USB controller> port 0xff00-0xff1f irq 17
>> at device 26.1 on pci0
>> uhci1: [ITHREAD]
>> uhci1: LegSup = 0x2f00
>> usbus1: <Intel 82801I (ICH9) USB controller> on uhci1
>> ehci0: <Intel 82801I (ICH9) USB 2.0 controller> mem
>> 0xfebd9c00-0xfebd9fff irq 22 at device 26.7 on pci0
>> ehci0: [ITHREAD]
>> usbus2: EHCI version 1.0
>> usbus2: <Intel 82801I (ICH9) USB 2.0 controller> on ehci0
>> hdac0: <Intel 82801I High Definition Audio Controller> mem
>> 0xfebdc000-0xfebdffff irq 16 at device 27.0 on pci0
>> hdac0: HDA Driver Revision: 20100226_0142
>> hdac0: [ITHREAD]
>> pcib2: <ACPI PCI-PCI bridge> irq 16 at device 28.0 on pci0
>> pci2: <ACPI PCI bus> on pcib2
>> uhci2: <Intel 82801I (ICH9) USB controller> port 0xff80-0xff9f irq 23
>> at device 29.0 on pci0
>> uhci2: [ITHREAD]
>> usbus3: <Intel 82801I (ICH9) USB controller> on uhci2
>> uhci3: <Intel 82801I (ICH9) USB controller> port 0xff60-0xff7f irq 17
>> at device 29.1 on pci0
>> uhci3: [ITHREAD]
>> usbus4: <Intel 82801I (ICH9) USB controller> on uhci3
>> uhci4: <Intel 82801I (ICH9) USB controller> port 0xff40-0xff5f irq 18
>> at device 29.2 on pci0
>> uhci4: [ITHREAD]
>> usbus5: <Intel 82801I (ICH9) USB controller> on uhci4
>> ehci1: <Intel 82801I (ICH9) USB 2.0 controller> mem
>> 0xff980800-0xff980bff irq 23 at device 29.7 on pci0
>> ehci1: [ITHREAD]
>> usbus6: EHCI version 1.0
>> usbus6: <Intel 82801I (ICH9) USB 2.0 controller> on ehci1
>> pcib3: <ACPI PCI-PCI bridge> at device 30.0 on pci0
>> pci3: <ACPI PCI bus> on pcib3
>> atapci1: <SiI 3114 SATA150 controller> port
>> 0xc8e0-0xc8e7,0xc8d8-0xc8db,0xc8e8-0xc8ef,0xc8dc-0xc8df,0xc8f0-0xc8ff
>> mem 0xf9dffc00-0xf9dfffff irq 16 at device 0.0 on pci3
>> atapci1: [ITHREAD]
>> ata4: <ATA channel 0> on atapci1
>> ata4: [ITHREAD]
>> ata5: <ATA channel 1> on atapci1
>> ata5: [ITHREAD]
>> ata6: <ATA channel 2> on atapci1
>> ata6: [ITHREAD]
>> ata7: <ATA channel 3> on atapci1
>> ata7: [ITHREAD]
>> pci3: <network, ethernet> at device 2.0 (no driver attached)
>> isab0: <PCI-ISA bridge> at device 31.0 on pci0
>> isa0: <ISA bus> on isab0
>> atapci2: <Intel ICH9 SATA300 controller> port
>> 0xfe00-0xfe07,0xfe10-0xfe13,0xfe20-0xfe27,0xfe30-0xfe33,0xfec0-0xfedf
>> mem 0xff970000-0xff9707ff irq 18 at device 31.2 on pci0
>> atapci2: [ITHREAD]
>> atapci2: AHCI called from vendor specific driver
>> atapci2: AHCI v1.20 controller with 6 3Gbps ports, PM supported
>> ata8: <ATA channel 0> on atapci2
>> ata8: [ITHREAD]
>> ata9: <ATA channel 1> on atapci2
>> ata9: [ITHREAD]
>> ata10: <ATA channel 2> on atapci2
>> ata10: [ITHREAD]
>> ata11: <ATA channel 3> on atapci2
>> ata11: [ITHREAD]
>> ata12: <ATA channel 5> on atapci2
>> ata12: [ITHREAD]
>> pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
>> atrtc0: <AT realtime clock> port 0x70-0x7f irq 8 on acpi0
>> fdc0: <floppy drive controller (FDE)> port 0x3f0-0x3f5,0x3f7 irq 6 drq
>> 2 on acpi0
>> fdc0: [FILTER]
>> uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
>> uart0: [FILTER]
>> orm0: <ISA Option ROMs> at iomem
>> 0xc0000-0xce7ff,0xce800-0xd37ff,0xd3800-0xd57ff,0xd5800-0xd7fff on
>> isa0
>> sc0: <System console> at flags 0x100 on isa0
>> sc0: VGA <16 virtual consoles, flags=0x300>
>> vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
>> atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0
>> atkbd0: <AT Keyboard> irq 1 on atkbdc0
>> kbd0 at atkbd0
>> atkbd0: [GIANT-LOCKED]
>> atkbd0: [ITHREAD]
>> est0: <Enhanced SpeedStep Frequency Control> on cpu0
>> p4tcc0: <CPU Frequency Thermal Control> on cpu0
>> est1: <Enhanced SpeedStep Frequency Control> on cpu1
>> p4tcc1: <CPU Frequency Thermal Control> on cpu1
>> est2: <Enhanced SpeedStep Frequency Control> on cpu2
>> p4tcc2: <CPU Frequency Thermal Control> on cpu2
>> est3: <Enhanced SpeedStep Frequency Control> on cpu3
>> p4tcc3: <CPU Frequency Thermal Control> on cpu3
>> ZFS filesystem version 3
>> ZFS storage pool version 14
>> RTC BIOS diagnostic error 11<memory_size>
>> Timecounters tick every 1.000 msec
>> vboxdrv: fAsync=0 offMin=0x171 offMax=0x360
>> ipfw2 (+ipv6) initialized, divert enabled, nat enabled, rule-based
>> forwarding disabled, default to deny, logging disabled
>> load_dn_sched dn_sched QFQ loaded
>> load_dn_sched dn_sched RR loaded
>> load_dn_sched dn_sched WF2Q+ loaded
>> load_dn_sched dn_sched FIFO loaded
>> load_dn_sched dn_sched PRIO loaded
>> hdac0: HDA Codec #0: Analog Devices AD1984
>> usbus0: 12Mbps Full Speed USB v1.0
>> usbus1: 12Mbps Full Speed USB v1.0
>> usbus2: 480Mbps High Speed USB v2.0
>> usbus3: 12Mbps Full Speed USB v1.0
>> usbus4: 12Mbps Full Speed USB v1.0
>> usbus5: 12Mbps Full Speed USB v1.0
>> usbus6: 480Mbps High Speed USB v2.0
>> pcm0: <HDA Analog Devices AD1984 PCM #0 Analog> at cad 0 nid 1 on hdac0
>> pcm1: <HDA Analog Devices AD1984 PCM #1 Analog> at cad 0 nid 1 on hdac0
>> ugen0.1: <Intel> at usbus0
>> uhub0: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
>> ugen1.1: <Intel> at usbus1
>> uhub1: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1
>> ugen2.1: <Intel> at usbus2
>> uhub2: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus2
>> ugen3.1: <Intel> at usbus3
>> uhub3: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus3
>> ugen4.1: <Intel> at usbus4
>> uhub4: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus4
>> ugen5.1: <Intel> at usbus5
>> uhub5: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus5
>> ugen6.1: <Intel> at usbus6
>> uhub6: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus6
>> uhub0: 2 ports with 2 removable, self powered
>> uhub1: 2 ports with 2 removable, self powered
>> uhub3: 2 ports with 2 removable, self powered
>> uhub4: 2 ports with 2 removable, self powered
>> uhub5: 2 ports with 2 removable, self powered
>> uhub2: 6 ports with 6 removable, self powered
>> uhub6: 6 ports with 6 removable, self powered
>> (noperiph:ata7:0:-1:-1): rescan already queued
>> ugen0.2: <Dell> at usbus0
>> ukbd0: <Dell Dell USB Keyboard, class 0/0, rev 1.10/3.50, addr 2> on
>> usbus0
>> kbd2 at ukbd0
>> ada0 at ata7 bus 0 scbus5 target 0 lun 0
>> ada0: <WDC WD5000AAVS-00ZTB0 01.01B01> ATA-8 SATA 2.x device
>> ada0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes)
>> ada0: 476940MB (976773168 512 byte sectors: 16H 63S/T 16383C)
>> ada1 at ata8 bus 0 scbus6 target 0 lun 0
>> ada1: <WDC WD5001AALS-00L3B2 01.03B01> ATA-8 SATA 2.x device
>> ada1: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
>> ada1: 476940MB (976773168 512 byte sectors: 16H 63S/T 16383C)
>> cd0 at ata10 bus 0 scbus8 target 0 lun 0
>> cd0: <HL-DT-ST DVD-ROM GDRH20N 0D04> Removable CD-ROM SCSI-0 device
>> cd0: 150.000MB/s transfers (SATA 1.x, UDMA5, ATAPI 12bytes, PIO 8192bytes)
>> cd0: Attempt to query device size failed: NOT READY, Medium not present
>> ada2 at ata9 bus 0 scbus7 target 0 lun 0
>> ada2: <WDC WD5001AALS-00L3B2 01.03B01> ATA-8 SATA 2.x device
>> ada2: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
>> ada2: 476940MB (976773168 512 byte sectors: 16H 63S/T 16383C)
>> lapic1: Forcing LINT1 to edge trigger
>> SMP: AP CPU #1 Launched!
>> lapic2: Forcing LINT1 to edge trigger
>> SMP: AP CPU #2 Launched!
>> lapic3: Forcing LINT1 to edge trigger
>> SMP: AP CPU #3 Launched!
>> cd1 at ata11 bus 0 scbus9 target 0 lun 0
>> cd1: <PBDS DVD+-RW DH-16W1S 2D14> Removable CD-ROM SCSI-0 device
>> cd1: 150.000MB/s transfers (SATA 1.x, UDMA5, ATAPI 12bytes, PIO 8192bytes)
>> cd1: cd present [1 x 2048 byte records]
>> ugen0.3: <vendor 0x0461> at usbus0
>> ums0: <vendor 0x0461 USB Optical Mouse, class 0/0, rev 2.00/2.00, addr
>> 3> on usbus0
>> ums0: 3 buttons and [XYZ] coordinates ID=0
>> GEOM_MIRROR: Device mirror/swap launched (2/2).
>> Trying to mount root from zfs:zroot
>> vboxnet0: Ethernet address: 0a:00:27:00:00:00
>> (cd1:ata11:0:0:0): READ TOC/PMA/ATIP. CDB: 43 0 0 0 0 0 0 0 4 0
>> (cd1:ata11:0:0:0): CAM status: SCSI Status Error
>> (cd1:ata11:0:0:0): SCSI status: Check Condition
>> (cd1:ata11:0:0:0): SCSI sense: ILLEGAL REQUEST asc:24,0 (Invalid field in
>> CDB)
>> Waiting (max 60 seconds) for system process `vnlru' to stop...done
>> Waiting (max 60 seconds) for system process `bufdaemon' to stop...done
>> Waiting (max 60 seconds) for system process `syncer' to stop...
>> Syncing disks, vnodes remaining...0 0 0 0 0 done
>> All buffers synced.
>> GEOM_MIRROR: Device swap: provider mirror/swap destroyed.
>> GEOM_MIRROR: Device swap destroyed.
>