Bug 207431 - graphics/sane-backends: scanimage triggers ata2: FAILURE - odd-sized DMA transfer attempt
Summary: graphics/sane-backends: scanimage triggers ata2: FAILURE - odd-sized DMA tran...
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 10.2-RELEASE
Hardware: amd64 Any
: --- Affects Some People
Assignee: freebsd-bugs (Nobody)
URL:
Keywords: regression
Depends on:
Blocks:
 
Reported: 2016-02-23 04:47 UTC by Charles Ziegler
Modified: 2022-01-24 17:12 UTC (History)
6 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Charles Ziegler 2016-02-23 04:47:56 UTC
Using xsane, gscan2pdf, or scanimage triggers multiple "ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2". 

Once this occurs saving data to the drive appears to work, but on reboot no longer exist. The system is root-on-zfs.

Furthermore, if subsequent intensive disk activity is attempted then an "ata4: already running!" is issued and the system becomes unusable. Once this occurs writes to other devices like da* appear to be affected, which is why I was unable to record this error. 

The problem is repeatable.

root@Dad:/ # scanimage -L

device `hpaio:/net/HP_LaserJet_3200?ip=10.0.0.204' is a Hewlett-Packard HP_LaserJet_3200 all-in-one

dmesg is

Copyright (c) 1992-2015 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 10.2-RELEASE-p9 #0: Thu Jan 14 01:32:46 UTC 2016
    root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64
FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
VT: running with driver "vga".
module_register: module at91_mci/mmc already exists!
Module at91_mci/mmc failed to register: 17
module_register: module sdhci_bcm/mmc already exists!
Module sdhci_bcm/mmc failed to register: 17
module_register: module sdhci_fdt/mmc already exists!
Module sdhci_fdt/mmc failed to register: 17
module_register: module sdhci_imx/mmc already exists!
Module sdhci_imx/mmc failed to register: 17
module_register: module sdhci_pci/mmc already exists!
Module sdhci_pci/mmc failed to register: 17
module_register: module sdhci_ti/mmc already exists!
Module sdhci_ti/mmc failed to register: 17
module_register: module ti_mmchs/mmc already exists!
Module ti_mmchs/mmc failed to register: 17
module_register: module mmc/mmcsd already exists!
Module mmc/mmcsd failed to register: 17
CPU: Intel(R) Core(TM) i7 CPU         920  @ 2.67GHz (2670.06-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x106a5  Family=0x6  Model=0x1a  Stepping=5
  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=0x98e3bd<SSE3,DTES64,MON,DS_CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,POPCNT>
  AMD Features=0x28100800<SYSCALL,NX,RDTSCP,LM>
  AMD Features2=0x1<LAHF>
  VT-x: PAT,HLT,MTF,PAUSE,EPT,VPID
  TSC: P-state invariant, performance statistics
real memory  = 25769803776 (24576 MB)
avail memory = 24910798848 (23756 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <091911 APIC1516>
FreeBSD/SMP: Multiprocessor System Detected: 8 CPUs
FreeBSD/SMP: 1 package(s) x 4 core(s) x 2 SMT threads
 cpu0 (BSP): APIC ID:  0
 cpu1 (AP): APIC ID:  1
 cpu2 (AP): APIC ID:  2
 cpu3 (AP): APIC ID:  3
 cpu4 (AP): APIC ID:  4
 cpu5 (AP): APIC ID:  5
 cpu6 (AP): APIC ID:  6
 cpu7 (AP): APIC ID:  7
ioapic0 <Version 2.0> irqs 0-23 on motherboard
ioapic1 <Version 2.0> irqs 24-47 on motherboard
random: <Software, Yarrow> initialized
module_register_init: MOD_LOAD (vesa, 0xffffffff80db8ea0, 0) error 19
kbd1 at kbdmux0
acpi0: <091911 RSDT1516> on motherboard
acpi0: Power Button (fixed)
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
cpu2: <ACPI CPU> on acpi0
cpu3: <ACPI CPU> on acpi0
cpu4: <ACPI CPU> on acpi0
cpu5: <ACPI CPU> on acpi0
cpu6: <ACPI CPU> on acpi0
cpu7: <ACPI CPU> on acpi0
attimer0: <AT timer> port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0: <AT realtime clock> port 0x70-0x71 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
Event timer "HPET" frequency 14318180 Hz quality 350
Event timer "HPET1" frequency 14318180 Hz quality 340
Event timer "HPET2" frequency 14318180 Hz quality 340
Event timer "HPET3" frequency 14318180 Hz quality 340
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> at device 1.0 on pci0
pci1: <ACPI PCI bus> on pcib1
pcib2: <ACPI PCI-PCI bridge> at device 3.0 on pci0
pci2: <ACPI PCI bus> on pcib2
vgapci0: <VGA-compatible display> port 0xbc00-0xbc7f mem 0xfa000000-0xfaffffff,0xd0000000-0xdfffffff,0xf8000000-0xf9ffffff irq 24 at device 0.0 on pci2
nvidia0: <GeForce 9600 GT> on vgapci0
vgapci0: child nvidia0 requested pci_enable_io
vgapci0: child nvidia0 requested pci_enable_io
vgapci0: Boot video device
pcib3: <ACPI PCI-PCI bridge> at device 7.0 on pci0
pci3: <ACPI PCI bus> on pcib3
pci0: <base peripheral, interrupt controller> at device 20.0 (no driver attached)
pci0: <base peripheral, interrupt controller> at device 20.1 (no driver attached)
pci0: <base peripheral, interrupt controller> at device 20.2 (no driver attached)
pci0: <base peripheral, interrupt controller> at device 20.3 (no driver attached)
uhci0: <Intel 82801JI (ICH10) USB controller USB-D> port 0xa800-0xa81f irq 16 at device 26.0 on pci0
uhci0: LegSup = 0x2f00
usbus0 on uhci0
uhci1: <Intel 82801JI (ICH10) USB controller USB-E> port 0xa880-0xa89f irq 21 at device 26.1 on pci0
uhci1: LegSup = 0x2f00
usbus1 on uhci1
uhci2: <Intel 82801JI (ICH10) USB controller USB-F> port 0xac00-0xac1f irq 19 at device 26.2 on pci0
uhci2: LegSup = 0x2f00
usbus2 on uhci2
ehci0: <Intel 82801JI (ICH10) USB 2.0 controller USB-B> mem 0xf7fff000-0xf7fff3ff irq 18 at device 26.7 on pci0
usbus3: EHCI version 1.0
usbus3 on ehci0
hdac0: <Intel 82801JI HDA Controller> mem 0xf7ff8000-0xf7ffbfff irq 22 at device 27.0 on pci0
pcib4: <ACPI PCI-PCI bridge> irq 17 at device 28.0 on pci0
pci7: <ACPI PCI bus> on pcib4
pcib5: <ACPI PCI-PCI bridge> irq 18 at device 28.2 on pci0
pci6: <ACPI PCI bus> on pcib5
re0: <RealTek 8168/8111 B/C/CP/D/DP/E/F/G PCIe Gigabit Ethernet> port 0xe800-0xe8ff mem 0xf6eff000-0xf6efffff,0xf6ee0000-0xf6eeffff irq 18 at device 0.0 on pci6
re0: Using 1 MSI-X message
re0: Chip rev. 0x3c000000
re0: MAC rev. 0x00400000
miibus0: <MII bus> on re0
rgephy0: <RTL8169S/8110S/8211 1000BASE-T media interface> PHY 1 on miibus0
rgephy0:  none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, 100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, 1000baseT-FDX-flow-master, auto, auto-flow
re0: Using defaults for TSO: 65518/35/2048
re0: Ethernet address: 00:24:8c:58:f8:b7
pcib6: <ACPI PCI-PCI bridge> irq 19 at device 28.3 on pci0
pci5: <ACPI PCI bus> on pcib6
pci5: <serial bus, FireWire> at device 0.0 (no driver attached)
pcib7: <ACPI PCI-PCI bridge> irq 17 at device 28.4 on pci0
pci4: <ACPI PCI bus> on pcib7
atapci0: <JMicron JMB363 UDMA133 controller> port 0xcc00-0xcc07,0xc880-0xc883,0xc800-0xc807,0xc480-0xc483,0xc400-0xc40f mem 0xfbcfe000-0xfbcfffff irq 16 at device 0.0 on pci4
ahci0: <JMicron JMB363 AHCI SATA controller> at channel -1 on atapci0
ahci0: AHCI v1.00 with 2 3Gbps ports, Port Multiplier supported
ahci0: quirks=0x1<NOFORCE>
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ata2: <ATA channel> at channel 0 on atapci0
uhci3: <Intel 82801JI (ICH10) USB controller USB-A> port 0xa080-0xa09f irq 23 at device 29.0 on pci0
uhci3: LegSup = 0x2f00
usbus4 on uhci3
uhci4: <Intel 82801JI (ICH10) USB controller USB-B> port 0xa400-0xa41f irq 19 at device 29.1 on pci0
uhci4: LegSup = 0x2f00
usbus5 on uhci4
uhci5: <Intel 82801JI (ICH10) USB controller USB-C> port 0xa480-0xa49f irq 18 at device 29.2 on pci0
uhci5: LegSup = 0x2f00
usbus6 on uhci5
ehci1: <Intel 82801JI (ICH10) USB 2.0 controller USB-A> mem 0xf7ffe000-0xf7ffe3ff irq 23 at device 29.7 on pci0
usbus7: EHCI version 1.0
usbus7 on ehci1
pcib8: <ACPI PCI-PCI bridge> at device 30.0 on pci0
pci8: <ACPI PCI bus> on pcib8
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci1: <Intel ICH10 SATA300 controller> port 0x9000-0x9007,0x8c00-0x8c03,0x8880-0x8887,0x8800-0x8803,0x8480-0x848f,0x8400-0x840f irq 20 at device 31.2 on pci0
ata3: <ATA channel> at channel 0 on atapci1
ata4: <ATA channel> at channel 1 on atapci1
atapci2: <Intel ICH10 SATA300 controller> port 0xa000-0xa007,0x9c00-0x9c03,0x9880-0x9887,0x9800-0x9803,0x9480-0x948f,0x9400-0x940f irq 20 at device 31.5 on pci0
ata5: <ATA channel> at channel 0 on atapci2
ata6: <ATA channel> at channel 1 on atapci2
acpi_button0: <Power Button> on acpi0
qpi0: <QPI system bus> on motherboard
pcib9: <QPI Host-PCI bridge> pcibus 255 on qpi0
pci255: <PCI bus> on pcib9
atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
ppc0: cannot reserve I/O port range
coretemp0: <CPU On-Die Thermal Sensors> on cpu0
est0: <Enhanced SpeedStep Frequency Control> on cpu0
coretemp1: <CPU On-Die Thermal Sensors> on cpu1
est1: <Enhanced SpeedStep Frequency Control> on cpu1
coretemp2: <CPU On-Die Thermal Sensors> on cpu2
est2: <Enhanced SpeedStep Frequency Control> on cpu2
coretemp3: <CPU On-Die Thermal Sensors> on cpu3
est3: <Enhanced SpeedStep Frequency Control> on cpu3
coretemp4: <CPU On-Die Thermal Sensors> on cpu4
est4: <Enhanced SpeedStep Frequency Control> on cpu4
coretemp5: <CPU On-Die Thermal Sensors> on cpu5
est5: <Enhanced SpeedStep Frequency Control> on cpu5
coretemp6: <CPU On-Die Thermal Sensors> on cpu6
est6: <Enhanced SpeedStep Frequency Control> on cpu6
coretemp7: <CPU On-Die Thermal Sensors> on cpu7
est7: <Enhanced SpeedStep Frequency Control> on cpu7
random: unblocking device.
usbus0: 12Mbps Full Speed USB v1.0
fuse-freebsd: version 0.4.4, FUSE ABI 7.8
ZFS filesystem version: 5
ZFS storage pool version: features support (5000)
Timecounters tick every 1.000 msec
vboxdrv: fAsync=0 offMin=0x474 offMax=0x6b0
hdacc0: <Analog Devices AD1989B HDA CODEC> at cad 0 on hdac0
hdaa0: <Analog Devices AD1989B Audio Function Group> at nid 1 on hdacc0
pcm0: <Analog Devices AD1989B (Analog 7.1/2.0)> at nid 18,36,22,37 and 23,21,24,20 on hdaa0
pcm1: <Analog Devices AD1989B (Front Analog Headphones)> at nid 17 on hdaa0
pcm2: <Analog Devices AD1989B (Rear Digital)> at nid 27 on hdaa0
pcm3: <Analog Devices AD1989B (Digital)> at nid 29 on hdaa0
usbus1: 12Mbps Full Speed USB v1.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 480Mbps High Speed USB v2.0
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 UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2
ugen3.1: <Intel> at usbus3
uhub3: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3
usbus4: 12Mbps Full Speed USB v1.0
usbus5: 12Mbps Full Speed USB v1.0
usbus6: 12Mbps Full Speed USB v1.0
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 UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus6
usbus7: 480Mbps High Speed USB v2.0
ugen7.1: <Intel> at usbus7
uhub7: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus7
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
uhub2: 2 ports with 2 removable, self powered
uhub4: 2 ports with 2 removable, self powered
uhub5: 2 ports with 2 removable, self powered
uhub6: 2 ports with 2 removable, self powered
ada0 at ata3 bus 0 scbus3 target 1 lun 0
ada0: <WDC WD1001FALS-00E3A0 05.01D05> ATA8-ACS SATA 2.x device
ada0: Serial Number WD-WCATR0294142
cd0 at ata2 bus 0 scbus2 target 0 lun 0
cd0: <Memorex 16X-DDL-IN 1.A3> Removable CD-ROM SCSI device
cd0: 33.300MB/s transfers (UDMA2, ATAPI 12bytes, PIO 65534bytes)
cd0: Attempt to query device size failed: NOT READY, Medium not present
ada0: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
ada0: 953869MB (1953525168 512 byte sectors: 16H 63S/T 16383C)
ada0: Previously was known as ad11
ada1 at ata4 bus 0 scbus4 target 0 lun 0
ada1: <WDC WD1002FAEX-00Z3A0 05.01D05> ATA8-ACS SATA 3.x device
ada1: Serial Number WD-WCATRA972664
ada1: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
ada1: 953869MB (1953525168 512 byte sectors: 16H 63S/T 16383C)
ada1: Previously was known as ad12
ada2 at ata4 bus 0 scbus4 target 1 lun 0
ada2: <ST500DM002-1BD142 KC45> ATA8-ACS SATA 3.x device
ada2: Serial Number Z3T6E3LW
ada2: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)
ada2: 476940MB (976773168 512 byte sectors: 16H 63S/T 16383C)
ada2: quirks=0x1<4K>
ada2: Previously was known as ad13
ada3 at ata5 bus 0 scbus5 target 0 lun 0
ada3: <HDS722525VLSA80 V36OA60A> ATA-6 SATA device
ada3: Serial Number VNRJ3EC6CNB76M
ada3: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes)
ada3: 238475MB (488397168 512 byte sectors: 16H 63S/T 16383C)
ada3: Previously was known as ad14
SMP: AP CPU #1 Launched!
SMP: AP CPU #7 Launched!
SMP: AP CPU #2 Launched!
SMP: AP CPU #6 Launched!
SMP: AP CPU #4 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #5 Launched!
Timecounter "TSC-low" frequency 1335028502 Hz quality 1000
Root mount waiting for: usbus7 usbus3
uhub7: 6 ports with 6 removable, self powered
uhub3: 6 ports with 6 removable, self powered
Root mount waiting for: usbus7 usbus3
ugen7.2: <vendor 0x0424> at usbus7
uhub8: <vendor 0x0424 product 0x2504, class 9/0, rev 2.00/0.01, addr 2> on usbus7
uhub8: MTT enabled
uhub8: 4 ports with 4 removable, self powered
Root mount waiting for: usbus7
ugen1.2: <Logitech> at usbus1
ukbd0: <Logitech Logitech Illuminated Keyboard, class 0/0, rev 2.00/55.03, addr 2> on usbus1
kbd2 at ukbd0
Root mount waiting for: usbus7
ugen1.3: <Logitech> at usbus1
ugen7.3: <Verbatim> at usbus7
umass0: <Verbatim STORE N GO, class 0/0, rev 2.00/1.00, addr 3> on usbus7
umass0:  SCSI over Bulk-Only; quirks = 0xc100
umass0:7:0:-1: Attached to scbus7
da0 at umass-sim0 bus 0 scbus7 target 0 lun 0
da0: <Verbatim STORE N GO 5.00> Removable Direct Access SCSI device
da0: Serial Number 07AA1007830F62B6
da0: 40.000MB/s transfers
da0: 1910MB (3911680 512 byte sectors: 255H 63S/T 243C)
da0: quirks=0x2<NO_6_BYTE>
Root mount waiting for: usbus7
ugen7.4: <vendor 0x058f> at usbus7
umass1: <vendor 0x058f product 0x6362, class 0/0, rev 2.00/1.00, addr 4> on usbus7
umass1:  SCSI over Bulk-Only; quirks = 0x4001
umass1:8:1:-1: Attached to scbus8
Trying to mount root from zfs:rpool/bootenv/R10.2 []...
da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
da1: <Generic USB SD Reader 1.00> Removable Direct Access SCSI device
da1: 40.000MB/s transfers
da1: Attempt to query device size failed: NOT READY, Medium not present
da1: quirks=0x2<NO_6_BYTE>
da2 at umass-sim1 bus 1 scbus8 target 0 lun 1
da2: <Generic USB CF Reader 1.01> Removable Direct Access SCSI device
da2: 40.000MB/s transfers
da2: Attempt to query device size failed: NOT READY, Medium not present
da2: quirks=0x2<NO_6_BYTE>
da3 at umass-sim1 bus 1 scbus8 target 0 lun 2
da3: <Generic USB SM Reader 1.02> Removable Direct Access SCSI device
da3: 40.000MB/s transfers
da3: Attempt to query device size failed: NOT READY, Medium not present
da3: quirks=0x2<NO_6_BYTE>
da4 at umass-sim1 bus 1 scbus8 target 0 lun 3
da4: <Generic USB MS Reader 1.03> Removable Direct Access SCSI device
da4: 40.000MB/s transfers
da4: Attempt to query device size failed: NOT READY, Medium not present
da4: quirks=0x2<NO_6_BYTE>
ugen5.2: <hp> at usbus5
tap0: Ethernet address: 00:bd:fd:38:00:00
tap1: Ethernet address: 00:bd:03:39:00:01
bridge0: Ethernet address: 02:b0:3d:32:65:00
uhid0: <Logitech Logitech Illuminated Keyboard, class 0/0, rev 2.00/55.03, addr 2> on usbus1
ulpt0: <hp photosmart 7700 series, class 0/0, rev 2.00/1.00, addr 2> on usbus5
ulpt0: using bi-directional mode
ums0: <Logitech USB-PS2 Optical Mouse, class 0/0, rev 2.00/27.20, addr 3> on usbus1
ums0: 8 buttons and [XYZT] coordinates ID=0
WARNING: /usr/home/xxxxx/.wine-pipelight was not properly dismounted
ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata2: setting up DMA failed
ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata2: setting up DMA failed
ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata2: setting up DMA failed
ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata2: setting up DMA failed

root@Dad:/ # camcontrol devlist

<Memorex 16X-DDL-IN 1.A3>          at scbus2 target 0 lun 0 (pass0,cd0)
<WDC WD1001FALS-00E3A0 05.01D05>   at scbus3 target 1 lun 0 (ada0,pass1)
<WDC WD1002FAEX-00Z3A0 05.01D05>   at scbus4 target 0 lun 0 (ada1,pass2)
<ST500DM002-1BD142 KC45>           at scbus4 target 1 lun 0 (ada2,pass3)
<HDS722525VLSA80 V36OA60A>         at scbus5 target 0 lun 0 (ada3,pass4)
<Verbatim STORE N GO 5.00>         at scbus7 target 0 lun 0 (da0,pass5)
<Generic USB SD Reader 1.00>       at scbus8 target 0 lun 0 (da1,pass6)
<Generic USB CF Reader 1.01>       at scbus8 target 0 lun 1 (da2,pass7)
<Generic USB SM Reader 1.02>       at scbus8 target 0 lun 2 (da3,pass8)
<Generic USB MS Reader 1.03>       at scbus8 target 0 lun 3 (da4,pass9)

vmstat -i before issuing scanimage
interrupt                          total       rate
irq16: uhci0+                        713          2
irq18: ehci0 uhci5                     2          0
irq19: uhci2 uhci4                   331          0
irq20: hpet0++                      6404         18
irq21: uhci1                         653          1
irq23: uhci3 ehci1                 13114         38
cpu0:timer                         15586         45
irq257: hdac0                        140          0
irq258: re0                          216          0
cpu1:timer                          3300          9
cpu7:timer                          2653          7
cpu2:timer                          4204         12
cpu6:timer                          2898          8
cpu4:timer                          3792         11
cpu3:timer                          2962          8
cpu5:timer                          3240          9
Total                              60208        175

vmstat -i after issuing scanimage
interrupt                          total       rate
irq16: uhci0+                       1056          2
irq18: ehci0 uhci5                     2          0
irq19: uhci2 uhci4                   497          0
irq20: hpet0++                      6966         13
irq21: uhci1                         989          1
irq23: uhci3 ehci1                 18929         37
cpu0:timer                         20852         41
irq257: hdac0                        140          0
irq258: re0                          266          0
cpu1:timer                          4120          8
cpu7:timer                          3400          6
cpu2:timer                          4874          9
cpu6:timer                          3679          7
cpu4:timer                          4547          8
cpu3:timer                          3728          7
cpu5:timer                          4001          7
Total                              78046        154

ps -axld before scanimage

UID  PID PPID CPU PRI NI    VSZ   RSS MWCHAN   STAT TT      TIME COMMAND
  0    0    0   0  -8  0      0  5248 -        DLs   -   0:00.36 [kernel]
  0    1    0   0  20  0   9476   832 wait     ILs   -   0:00.05 - /sbin/init -
  0  156    1   0  52  0  12352  1748 pause    Is    -   0:00.00 |-- adjkerntz 
  0  647    1   0  52  0  16728  2000 select   Is    -   0:00.00 |-- /usr/sbin/
  0  660    1   0  20  0  13624  4692 select   Ss    -   0:00.00 |-- /sbin/devd
 59  666    1   0  21  0  33068  8536 select   Is    -   0:00.02 |-- /usr/sbin/
  0  684    1   0  52  0  14700  2208 sbwait   Is    -   0:00.00 |-- pflogd: [p
 64  686  684   0  20  0  14700  2208 bpf      S     -   0:00.00 | `-- pflogd: 
  0  787    1   0  20  0  14520  2116 select   Ss    -   0:00.01 |-- /usr/sbin/
  0  987    1   0  20  0  26108 18028 select   Ss    -   0:00.14 |-- /usr/sbin/
556 1029    1   0  20  0  17136  2964 select   Is    -   0:00.01 |-- /usr/local
  0 1050    1   0  33  0 106908  7388 select   I     -   0:00.02 |-- /usr/local
565 1052    1   0  34  0 105828 13180 select   I     -   0:00.02 |-- /usr/local
  0 1072    1   0  35  0  80348  8080 kqread   Is    -   0:00.02 |-- /usr/local
  0 1102    1   0  52  0  61224  6868 select   Is    -   0:00.00 |-- /usr/sbin/
  0 1105    1   0  20  0  24136  5860 select   Ss    -   0:00.00 |-- sendmail: 
 25 1108    1   0  52  0  24136  5684 pause    Is    -   0:00.00 |-- sendmail: 
  0 1112    1   0  20  0  16616  2332 nanslp   Is    -   0:00.00 |-- /usr/sbin/
560 1182    1   0  21  0  60800  8836 select   Is    -   0:00.25 |-- /usr/local
  0 1183 1182   0  52  0  46236  5724 select   I     -   0:00.15 | `-- hald-run
  0 1212 1183   0  40  0  31924  4000 kqread   I     -   0:00.13 |   |-- hald-a
  0 1224 1183   0  20  0  23300  2776 select   S     -   0:00.15 |   |-- hald-a
  0 1243 1183   0  20  0  23300  2772 select   S     -   0:00.14 |   |-- hald-a
  0 1247 1183   0  20  0  23300  2772 select   S     -   0:00.14 |   |-- hald-a
  0 1250 1183   0  20  0  23300  2772 select   S     -   0:00.14 |   |-- hald-a
  0 1253 1183   0  20  0  23300  2772 select   S     -   0:00.14 |   |-- hald-a
  0 1257 1183   0  20  0  23300  2772 select   S     -   0:00.14 |   `-- hald-a
  0 1170    1   0  22  0  47748  2804 wait     Is   v0   0:00.01 |-- login [pam
  0 1219 1170   0  20  0  23596  3680 pause    I    v0   0:00.03 | `-- -csh (cs
  0 1275 1219   0  20  0  14488  2088 select   S+   v0   0:00.00 |   `-- script
  0 1276 1275   0  20  0  23596  3692 pause    Ss    0   0:00.02 |     `-- /bin
  0 1278 1276   0  20  0  18764  2328 -        R+    0   0:00.00 |       `-- ps
  0 1171    1   0  52  0  14512  2080 ttyin    Is+  v1   0:00.00 |-- /usr/libex
  0 1172    1   0  52  0  14512  2080 ttyin    Is+  v2   0:00.00 |-- /usr/libex
  0 1173    1   0  52  0  14512  2080 ttyin    Is+  v3   0:00.00 |-- /usr/libex
  0 1174    1   0  52  0  14512  2080 ttyin    Is+  v4   0:00.00 |-- /usr/libex
  0 1175    1   0  52  0  14512  2080 ttyin    Is+  v5   0:00.00 |-- /usr/libex
  0 1176    1   0  52  0  14512  2080 ttyin    Is+  v6   0:00.00 |-- /usr/libex
  0 1177    1   0  52  0  14512  2080 ttyin    Is+  v7   0:00.00 `-- /usr/libex
  0    2    0   0 -16  0      0    48 -        DL    -   0:00.08 - [cam]
  0    3    0   0  -8  0      0   176 tx->tx_s DL    -   0:00.03 - [zfskern]
  0    4    0   0 -16  0      0    16 waiting_ DL    -   0:00.00 - [sctp_iterat
  0    5    0   0 -16  0      0    32 umarcl   DL    -   0:00.00 - [pagedaemon]
  0    6    0   0 -16  0      0    16 psleep   DL    -   0:00.00 - [vmdaemon]
  0    7    0   0 155  0      0    16 pgzero   DL    -   0:00.00 - [pagezero]
  0    8    0   0 -16  0      0    32 sdflush  DL    -   0:00.00 - [bufdaemon]
  0    9    0   0  16  0      0    16 syncer   DL    -   0:00.00 - [syncer]
  0   10    0   0 -16  0      0    16 audit_wo DL    -   0:00.00 - [audit]
  0   11    0   0 155  0      0   128 -        RL    -  39:01.59 - [idle]
  0   12    0   0 -72  0      0   384 -        WL    -   0:00.72 - [intr]
  0   13    0   0  -8  0      0    48 -        DL    -   0:00.02 - [geom]
  0   14    0   0 -16  0      0    16 -        DL    -   0:00.02 - [rand_harves
  0   15    0   0 -68  0      0   512 -        DL    -   0:00.19 - [usb]
  0   16    0   0 -20  0      0    16 VBoxIS   DL    -   0:00.00 - [Timer]
  0   17    0   0 -16  0      0    16 vlruwt   DL    -   0:00.00 - [vnlru]
  0  672    0   0 -16  0      0    16 pftm     DL    -   0:00.04 - [pf purge]
  0  722    0   0 -16  0      0   128 sleep    DL    -   0:00.00 - [ng_queue]

ps -axld after scanimage
UID  PID PPID CPU PRI NI    VSZ   RSS MWCHAN   STAT TT      TIME COMMAND
  0    0    0   0  -8  0      0  5248 -        DLs   -   0:00.40 [kernel]
  0    1    0   0  20  0   9476   832 wait     ILs   -   0:00.05 - /sbin/init -
  0  156    1   0  52  0  12352  1748 pause    Is    -   0:00.00 |-- adjkerntz 
  0  647    1   0  52  0  16728  2000 select   Is    -   0:00.00 |-- /usr/sbin/
  0  660    1   0  20  0  13624  4692 select   Is    -   0:00.00 |-- /sbin/devd
 59  666    1   0  21  0  33068  8536 select   Is    -   0:00.02 |-- /usr/sbin/
  0  684    1   0  52  0  14700  2208 sbwait   Is    -   0:00.00 |-- pflogd: [p
 64  686  684   0  20  0  14700  2208 bpf      S     -   0:00.00 | `-- pflogd: 
  0  787    1   0  20  0  14520  2116 select   Is    -   0:00.01 |-- /usr/sbin/
  0  987    1   0  20  0  26108 18028 select   Ss    -   0:00.14 |-- /usr/sbin/
556 1029    1   0  20  0  17136  2976 select   Is    -   0:00.01 |-- /usr/local
  0 1050    1   0  33  0 106908  7388 select   I     -   0:00.02 |-- /usr/local
565 1052    1   0  34  0 105828 13184 select   I     -   0:00.03 |-- /usr/local
  0 1072    1   0  20  0  80348  8156 kqread   Is    -   0:00.02 |-- /usr/local
  0 1102    1   0  52  0  61224  6868 select   Is    -   0:00.00 |-- /usr/sbin/
  0 1105    1   0  20  0  24136  5860 select   Ss    -   0:00.00 |-- sendmail: 
 25 1108    1   0  52  0  24136  5684 pause    Is    -   0:00.00 |-- sendmail: 
  0 1112    1   0  20  0  16616  2332 nanslp   Is    -   0:00.00 |-- /usr/sbin/
560 1182    1   0  21  0  60800  8836 select   Is    -   0:00.26 |-- /usr/local
  0 1183 1182   0  52  0  46236  5724 select   I     -   0:00.15 | `-- hald-run
  0 1212 1183   0  40  0  31924  4000 kqread   I     -   0:00.13 |   |-- hald-a
  0 1224 1183   0  20  0  23300  2776 select   S     -   0:00.17 |   |-- hald-a
  0 1243 1183   0  20  0  23300  2772 select   S     -   0:00.15 |   |-- hald-a
  0 1247 1183   0  20  0  23300  2772 select   S     -   0:00.15 |   |-- hald-a
  0 1250 1183   0  20  0  23300  2772 select   S     -   0:00.15 |   |-- hald-a
  0 1253 1183   0  20  0  23300  2772 select   S     -   0:00.15 |   |-- hald-a
  0 1257 1183   0  20  0  23300  2772 select   S     -   0:00.15 |   `-- hald-a
  0 1170    1   0  22  0  47748  2804 wait     Is   v0   0:00.01 |-- login [pam
  0 1219 1170   0  20  0  23596  3680 pause    I    v0   0:00.03 | `-- -csh (cs
  0 1275 1219   0  20  0  14488  2088 select   S+   v0   0:00.01 |   `-- script
  0 1276 1275   0  20  0  23596  3696 pause    Ss    0   0:00.02 |     `-- /bin
  0 1286 1276   0  20  0  18764  2328 -        R+    0   0:00.00 |       `-- ps
  0 1171    1   0  52  0  14512  2080 ttyin    Is+  v1   0:00.00 |-- /usr/libex
  0 1172    1   0  52  0  14512  2080 ttyin    Is+  v2   0:00.00 |-- /usr/libex
  0 1173    1   0  52  0  14512  2080 ttyin    Is+  v3   0:00.00 |-- /usr/libex
  0 1174    1   0  52  0  14512  2080 ttyin    Is+  v4   0:00.00 |-- /usr/libex
  0 1175    1   0  52  0  14512  2080 ttyin    Is+  v5   0:00.00 |-- /usr/libex
  0 1176    1   0  52  0  14512  2080 ttyin    Is+  v6   0:00.00 |-- /usr/libex
  0 1177    1   0  52  0  14512  2080 ttyin    Is+  v7   0:00.00 `-- /usr/libex
  0    2    0   0 -16  0      0    48 -        DL    -   0:00.09 - [cam]
  0    3    0   0  -8  0      0   176 tx->tx_s DL    -   0:00.03 - [zfskern]
  0    4    0   0 -16  0      0    16 waiting_ DL    -   0:00.00 - [sctp_iterat
  0    5    0   0 -16  0      0    32 umarcl   DL    -   0:00.00 - [pagedaemon]
  0    6    0   0 -16  0      0    16 psleep   DL    -   0:00.00 - [vmdaemon]
  0    7    0   0 155  0      0    16 pgzero   DL    -   0:00.00 - [pagezero]
  0    8    0   0 -16  0      0    32 sdflush  DL    -   0:00.00 - [bufdaemon]
  0    9    0   0  16  0      0    16 syncer   DL    -   0:00.00 - [syncer]
  0   10    0   0 -16  0      0    16 audit_wo DL    -   0:00.00 - [audit]
  0   11    0   0 155  0      0   128 -        RL    -  61:40.76 - [idle]
  0   12    0   0 -72  0      0   384 -        WL    -   0:00.96 - [intr]
  0   13    0   0  -8  0      0    48 -        DL    -   0:00.02 - [geom]
  0   14    0   0 -16  0      0    16 -        DL    -   0:00.03 - [rand_harves
  0   15    0   0 -68  0      0   512 -        DL    -   0:00.22 - [usb]
  0   16    0   0 -20  0      0    16 VBoxIS   DL    -   0:00.00 - [Timer]
  0   17    0   0 -16  0      0    16 vlruwt   DL    -   0:00.00 - [vnlru]
  0  672    0   0 -16  0      0    16 pftm     DL    -   0:00.07 - [pf purge]
  0  722    0   0 -16  0      0   128 sleep    DL    -   0:00.00 - [ng_queue]

When this system runs FreeBSD 8.0-Release it assigns ad* to the drives; xsane and gscan2pdf work just fine.

Feel free to use my system as a test bed for possible solutions.
Comment 1 Charles Ziegler 2016-02-28 05:50:04 UTC
Here is some additional information.

Some testing uncovered the mustek and mustek2 devices in graphics/sane-backends appear to be responsible for these errors. Mustek2 is responsible for the 

"ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
 ata2: setting up DMA failed"

and mustek appears to be responsible for the "ata4: already running!"

If both are commented out in "usr/local/etc/sane.d/dll.conf" then these errors go away and the system appears to behave normally.
Comment 2 Charles Ziegler 2016-02-28 06:21:55 UTC
Correction - mustek and mustek2 should read microtek and microtek2, respectively.
Comment 3 Michael Osipov 2016-10-18 16:20:24 UTC
I can confirm the same issue on 11.0-STABLE with Agfa ScanScan e25:

ata1: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata1: setting up DMA failed
ata1: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata1: setting up DMA failed
ugen0.2: <AGFA> at usbus0
ata1: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata1: setting up DMA failed
ata1: FAILURE - odd-sized DMA transfer attempt 5 % 2
ata1: setting up DMA failed

Any further information needed?
Comment 4 Nathan 2018-08-28 16:19:20 UTC
Has anyone tried since there is a newer version of sane-backends. I don’t have anything to test it with
Comment 5 tech-lists 2022-01-10 08:28:54 UTC
(In reply to Nathan from comment #4)

I'm seeing this exact same error

1. zfs-on-root

2. hardware: https://bsd-hardware.info/?probe=d914e4c500

3. stable/13-n248872-2c7441c86ef: Thu Jan  6 02:34:00 UTC 2022
   root@releng3.nyi.freebsd.org:/usr/obj/usr/src/amd64.amd64/sys/GENERIC  amd64

packages were installed from pkg.freebsd.org

if I run sane-find-scanner -q

this happens:

Jan 10 00:41:29 kernel: ugen4.2: <EPSON EPSON Perfection V37/V370> at usbus4

as expected, but a few seconds later, this happens:

Jan 10 00:50:33 kernel: ata2: FAILURE - odd-sized DMA transfer attempt 5 % 2
Jan 10 00:50:33 kernel: ata2: setting up DMA failed
Jan 10 00:53:36 syslogd: kernel boot file is /boot/kernel/kernel
Jan 10 00:53:36 kernel: ata3: already running!
Jan 10 00:53:36 kernel: ata2: already running!
Jan 10 00:53:36 kernel: spin lock 0xffffffff81cac3c0 (callout) held by 
0xfffffe000f91f3a0 (tid 100003) too long

resulting in a lockup at next write then drops to console, press any key to reboot.
Comment 6 tech-lists 2022-01-10 12:11:27 UTC
maybe this PR needs to be closed and a new one opened? as it was originally logged against releng/10.2 but am seeing it on stable/13
Comment 7 tech-lists 2022-01-10 13:16:13 UTC
(In reply to Charles Ziegler from comment #1)

I've commented out all but epson2 backend but it made no difference in my case.
Comment 8 Vladimir Druzenko freebsd_committer freebsd_triage 2022-01-24 17:12:29 UTC
Try 1.1.1: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=261433