e100: eth0: e100_request_firmware: Failed to load firmware "e100/d101m_ucode.bin

[Austin English]

Binary package hint: linux-firmware

Upon upgrade of a server running karmic from linux-image-2.6.31-18-generic-pae to linux-image-2.6.31-20-generic-pae, network connectivity was lost. dmesg reports:
[ 77.481635] e100 0000:00:07.0: firmware: requesting e100/d101m_ucode.bin
[ 137.473940] e100: eth0: e100_request_firmware: Failed to load firmware "e100/d101m_ucode.bin": -2

Googling around showed that the firmware may be missing, or not in the correct location, however it is available in:

/lib/firmware/e100/d102e_ucode.bin
/lib/firmware/e100/d101s_ucode.bin
/lib/firmware/e100/d101m_ucode.bin
/lib/firmware/2.6.31-18-generic-pae/e100/d102e_ucode.bin
/lib/firmware/2.6.31-18-generic-pae/e100/d101s_ucode.bin
/lib/firmware/2.6.31-18-generic-pae/e100/d101m_ucode.bin
/lib/firmware/2.6.31-20-generic-pae/e100/d102e_ucode.bin
/lib/firmware/2.6.31-20-generic-pae/e100/d101s_ucode.bin
/lib/firmware/2.6.31-20-generic-pae/e100/d101m_ucode.bin

downgrading to 2.6.31-18 or earlier did not resolve the problem. As a workaround, I added another network card and reassigned the static ip to the new network card.

austin@SERVER1:/$ lsb_release -rd
Description: Ubuntu 9.10
Release: 9.10

austin@SERVER1:/$ apt-cache policy linux-firmware
linux-firmware:
  Installed: 1.26
  Candidate: 1.26
  Version table:
 *** 1.26 0
        500 http://us.archive.ubuntu.com karmic-updates/main Packages
        500 http://us.archive.ubuntu.com karmic-proposed/main Packages
        100 /var/lib/dpkg/status
     1.24 0
        500 http://us.archive.ubuntu.com karmic/main Packages

[Austin English (austinenglish)]

Forgot the lspci of the card:
00:07.0 Ethernet controller: Intel Corporation 82557/8/9/0/1 Ethernet Pro 100 (rev 08)
        Subsystem: Intel Corporation Device 100c
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV+ VGASnoop- ParErr- Stepping- SERR+ FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 64 (2000ns min, 14000ns max), Cache Line Size: 32 bytes
        Interrupt: pin A routed to IRQ 23
        Region 0: Memory at fe87f000 (32-bit, non-prefetchable) [size=4K]
        Region 1: I/O ports at d800 [size=64]
        Region 2: Memory at fe700000 (32-bit, non-prefetchable) [size=1M]
        Expansion ROM at fe600000 [disabled] [size=1M]
        Capabilities: <access denied>
        Kernel driver in use: e100
        Kernel modules: e100

[Chase Douglas (chasedouglas)]

@austin_is:

Please run 'apport-collect -p linux 530348'. This will collect some information and attach it to this bug report.

Thanks

[Austin English (austinenglish)]

AlsaDevices: Error: command ['ls', '-l', '/dev/snd/'] failed with exit code 2: ls: cannot access /dev/snd/: No such file or directory
AplayDevices: Error: [Errno 2] No such file or directory
Architecture: i386
ArecordDevices: Error: [Errno 2] No such file or directory
DistroRelease: Ubuntu 9.10
MachineType: To Be Filled By O.E.M. To Be Filled By O.E.M.
Package: linux (not installed)
PciMultimedia:

ProcCmdLine: root=UUID=eaaae5fe-81ef-469f-994b-e504b1ca9c66 ro quiet splash
ProcEnviron:
 SHELL=/bin/bash
 LANG=en_US.UTF-8
ProcVersionSignature: Ubuntu 2.6.31-20.57-generic-pae
Uname: Linux 2.6.31-20-generic-pae i686
UserGroups:

dmi.bios.date: 01/22/2002
dmi.bios.vendor: American Megatrends Inc.
dmi.bios.version: 0700xx
dmi.board.name: ServerWorks HE-SL
dmi.board.vendor: Tyan Computer Corp.
dmi.board.version: Rev. 1
dmi.chassis.asset.tag: To Be Filled By O.E.M.
dmi.chassis.type: 3
dmi.chassis.vendor: To Be Filled By O.E.M.
dmi.chassis.version: To Be Filled By O.E.M.
dmi.modalias: dmi:bvnAmericanMegatrendsInc.:bvr0700xx:bd01/22/2002:svnToBeFilledByO.E.M.:pnToBeFilledByO.E.M.:pvrToBeFilledByO.E.M.:rvnTyanComputerCorp.:rnServerWorksHE-SL:rvrRev.1:cvnToBeFilledByO.E.M.:ct3:cvrToBeFilledByO.E.M.:
dmi.product.name: To Be Filled By O.E.M.
dmi.product.version: To Be Filled By O.E.M.
dmi.sys.vendor: To Be Filled By O.E.M.

[Chase Douglas (chasedouglas)]

@austin_is:

The firmware loading stage exited with error -ENOENT. This could be cause by:

* Firmware file doesn't exist in correct location (this seems fine given what you've reported above)
* Firmware file is empty (please check in all locations under /lib/firmware)
* Memory pages fail to be allocated for firmware in kernel (unlikely)
* (Maybe) device entries under /dev or /sys could not be allocated (unlikely)
* Something else I've missed?

Can you also post any messages you find in /var/log/syslog that relate to firmware loading for e100? There may be something in there from the udev firmware loading script.

[Austin English (austinenglish)]

austin@SERVER1:/lib$ find . -name *_ucode\.bin | xargs sha1sum | sort
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/2.6.31-16-generic-pae/e100/d102e_ucode.bin
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/2.6.31-17-generic/e100/d102e_ucode.bin
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/2.6.31-17-generic-pae/e100/d102e_ucode.bin
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/2.6.31-18-generic-pae/e100/d102e_ucode.bin
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/2.6.31-20-generic-pae/e100/d102e_ucode.bin
0ba83d215330e99e829963d22c74e6b464016060 ./firmware/e100/d102e_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/2.6.31-16-generic-pae/e100/d101s_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/2.6.31-17-generic/e100/d101s_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/2.6.31-17-generic-pae/e100/d101s_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/2.6.31-18-generic-pae/e100/d101s_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/2.6.31-20-generic-pae/e100/d101s_ucode.bin
894422f2e9bc846530f2f323b5eec38e397b730e ./firmware/e100/d101s_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/2.6.31-16-generic-pae/e100/d101m_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/2.6.31-17-generic/e100/d101m_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/2.6.31-17-generic-pae/e100/d101m_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/2.6.31-18-generic-pae/e100/d101m_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/2.6.31-20-generic-pae/e100/d101m_ucode.bin
bc519e8e13aca054fdeca0f3ce1e29e1a45c3c62 ./firmware/e100/d101m_ucode.bin

[Chase Douglas (chasedouglas)]

@austin_is:

Please apply the attached patch. It adds some additional debug messages to the user-space firmware loader script. After applying the script, reload the e100 module (or restart if needed) to initiate a firmware upload. After that is done, please look in /var/log/syslog for firmware loading messages and paste them here.

P.S. When we are done with testing, you can revert the patch by using 'patch -R'

[Austin English (austinenglish)]

@Chase Douglas:

Something fishy may be going on...those debug messages weren't triggered.

I used:
patch < firmware.sh.patch
modprobe -r e100
modprobe e100
tail /var/log/syslog

which showed:
Mar 2 14:37:04 SERVER1 kernel: [407483.499357] e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
Mar 2 14:37:04 SERVER1 kernel: [407483.499370] e100: Copyright(c) 1999-2006 Intel Corporation
Mar 2 14:37:04 SERVER1 kernel: [407483.499499] e100 0000:00:07.0: PCI->APIC IRQ transform: INT A -> IRQ 23
Mar 2 14:37:04 SERVER1 kernel: [407483.522448] e100 0000:00:07.0: PME# disabled
Mar 2 14:37:04 SERVER1 kernel: [407483.524914] e100: eth0: e100_probe: addr 0xfe87f000, irq 23, MAC addr 00:e0:81:29:37:a0

but none of your extra debug tracing. A full reboot shouldn't be needed to trigger the firmware loader, should it?

[Chase Douglas (chasedouglas)]

@austin_is:

I wouldn't have thought so, but I'm not sure whether a full reboot is required. There still should be output in syslog from the kernel attempting to load the firmware, so if that doesn't show up then my extra debug tracing won't show up either.

[Austin English (austinenglish)]

I will bring it down for a reboot in a couple hours. If you need any more debugging done not involving a reboot before then, please let me know.

[Austin English (austinenglish)]

Rebooting made no difference in /var/log/syslog.

[Chase Douglas (chasedouglas)]

I'm perplexed. Maybe firmware.sh isn't getting called? I just noticed that there's a recent update to udev that fixes a potential issue with hotplug support. Can you ensure you are running the latest udev package? It should be version 147~-6.1.

[Austin English (austinenglish)]

austin@SERVER1:~$ dpkg -l | grep udev
ii libudev0 147~-6.1 udev library
ii udev 147~-6.1 rule-based device node and kernel event mana

[Chase Douglas (chasedouglas)]

@austin_is:

I'm still stumped, but the one difference I see in my system and yours (I don't have e100, so I can't compare exactly) is that I don't have any firmware in /lib/firmware. My firmware files exist only under the /lib/firmware/`uname -r`/ directory. I don't think that removing the firmware under /lib/firmware should make a difference, but if you are desperate you can try that.

Note: I think you should be able to test this without rebooting. You need to 'rmmod e100 && modprobe e100', but then you need to try bringing it up to load the firmware: 'ifconfig eth0 up'. This is based on a cursory glance over the driver code.

[Austin English (austinenglish)]

Yes, it's not there by default. I was desperate and tried putting it in /lib/firmware/e100 based on a google search and similar results for other distros (fedora, I believe).

Tried it anyway, to be sure:
root@SERVER1:/lib/firmware# rm -rf e100/
root@SERVER1:/lib/firmware# rmmod e100 && modprobe e100
WARNING: All config files need .conf: /etc/modprobe.d/ibm_acpi.modprobe, it will be ignored in a future release.
root@SERVER1:/lib/firmware# ifconfig eth0 up

SIOCSIFFLAGS: No such file or directory

[Chase Douglas (chasedouglas)]

After you tried reloading the firmware, more messages should have shown up in your /var/log/syslog. Can you paste them here? Maybe some different output resulted?

[Austin English (austinenglish)]

Just the usual:

Mar 3 13:36:25 SERVER1 kernel: [73609.467294] e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
Mar 3 13:36:25 SERVER1 kernel: [73609.467304] e100: Copyright(c) 1999-2006 Intel Corporation
Mar 3 13:36:25 SERVER1 kernel: [73609.467410] e100 0000:00:07.0: PCI->APIC IRQ transform: INT A -> IRQ 23
Mar 3 13:36:25 SERVER1 kernel: [73609.490201] e100 0000:00:07.0: PME# disabled
Mar 3 13:36:25 SERVER1 kernel: [73609.492918] e100: eth0: e100_probe: addr 0xfe87f000, irq 23, MAC addr 00:e0:81:29:37:a0
Mar 3 13:36:32 SERVER1 kernel: [73616.536768] e100 0000:00:07.0: firmware: requesting e100/d101m_ucode.bin
Mar 3 13:37:32 SERVER1 kernel: [73676.540676] e100: eth0: e100_request_firmware: Failed to load firmware "e100/d101m_ucode.bin": -2

[Chase Douglas (chasedouglas)]

@austin_is:

Please run 'udevadm monitor --property' and capture the output as you run 'rmmod e100 && modprobe e100 && ifconfig eth0 up'. Paste the output of udevadm here. This should show us an event being passed up from the kernel to initiate a firmware load.

[Austin English (austinenglish)]

root@SERVER1:~# udevadm monitor --property
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[1267652192.053081] remove /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
SUBSYSTEM=net
INTERFACE=eth0
IFINDEX=4
SEQNUM=1200

UDEV [1267652192.053587] remove /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
SUBSYSTEM=net
INTERFACE=eth0
IFINDEX=4
SEQNUM=1200

KERNEL[1267652192.064449] remove /bus/pci/drivers/e100 (drivers)
UDEV_LOG=3
ACTION=remove
DEVPATH=/bus/pci/drivers/e100
SUBSYSTEM=drivers
SEQNUM=1201

KERNEL[1267652192.066681] remove /module/e100 (module)
UDEV_LOG=3
ACTION=remove
DEVPATH=/module/e100
SUBSYSTEM=module
SEQNUM=1202

UDEV [1267652192.066800] remove /bus/pci/drivers/e100 (drivers)
UDEV_LOG=3
ACTION=remove
DEVPATH=/bus/pci/drivers/e100
SUBSYSTEM=drivers
SEQNUM=1201

UDEV [1267652192.066894] remove /module/e100 (module)
UDEV_LOG=3
ACTION=remove
DEVPATH=/module/e100
SUBSYSTEM=module
SEQNUM=1202

KERNEL[1267652192.081752] add /module/e100 (module)
UDEV_LOG=3
ACTION=add
DEVPATH=/module/e100
SUBSYSTEM=module
SEQNUM=1203

KERNEL[1267652192.115095] add /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
SUBSYSTEM=net
INTERFACE=eth0
IFINDEX=5
SEQNUM=1204

KERNEL[1267652192.115257] add /bus/pci/drivers/e100 (drivers)
UDEV_LOG=3
ACTION=add
DEVPATH=/bus/pci/drivers/e100
SUBSYSTEM=drivers
SEQNUM=1205

KERNEL[1267652192.137064] add /devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0 (firmware)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0
SUBSYSTEM=firmware
FIRMWARE=e100/d101m_ucode.bin
SEQNUM=1206

UDEV [1267652192.196645] add /bus/pci/drivers/e100 (drivers)
UDEV_LOG=3
ACTION=add
DEVPATH=/bus/pci/drivers/e100
SUBSYSTEM=drivers
SEQNUM=1205

UDEV [1267652192.227652] add /module/e100 (module)
UDEV_LOG=3
ACTION=add
DEVPATH=/module/e100
SUBSYSTEM=module
SEQNUM=1203

UDEV [1267652192.246883] add /devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0 (firmware)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0
SUBSYSTEM=firmware
FIRMWARE=e100/d101m_ucode.bin
SEQNUM=1206

UDEV [1267652192.249681] add /devices/pci0000:00/0000:00:07.0/net/eth0 (net)
UDEV_LOG=3
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:07.0/net/eth0
SUBSYSTEM=net
INTERFACE=eth0
IFINDEX=5
SEQNUM=1204
ID_VENDOR_FROM_DATABASE=Intel Corporation
ID_MODEL_FROM_DATABASE=82557/8/9/0/1 Ethernet Pro 100
ID_BUS=pci
ID_VENDOR_ID=0x8086
ID_MODEL_ID=0x1229

KERNEL[1267652252.141014] remove /devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0 (firmware)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0
SUBSYSTEM=firmware
FIRMWARE=e100/d101m_ucode.bin
SEQNUM=1207

UDEV [1267652252.141147] remove /devices/pci0000:00/0000:00:07.0/firmware/0000:00:07.0 (firmware)
UDEV_LOG=3
ACTION=remove
DEVPATH=/devices/pci0000:00/0000:00:07.0...

[Chase Douglas (chasedouglas)]

What that shows us is that udev is receiving the proper events for firmware uploading from the kernel. Now, lets find out what udev is doing with them. Execute the following:

1. sudo udevadm control --log-priority debug
2. tail -f /var/log/syslog > udev.log
3. (in another terminal) rmmod e100 && modprobe e100 && ifconfig eth0 up

Attach the udev.log file here. It should contain something like:

Mar 3 17:38:58 cndougla-ubuntu udevd-work[31461]: 'firmware.sh' started

And, hopefully, following messages will also show us what's going on once it runs firmware.sh.

[Austin English (austinenglish)]

Reviewing that log showed the problem:
Mar 4 10:23:22 SERVER1 udevd[313]: seq 1210 queued, 'remove' 'module'
Mar 4 10:23:22 SERVER1 udevd[313]: passed 107 bytes to monitor 0x21c081f0
Mar 4 10:23:22 SERVER1 udevd-work[9630]: seq 1210 running
Mar 4 10:23:22 SERVER1 udevd-work[9630]: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
Mar 4 10:23:22 SERVER1 udevd-work[9630]: passed 95 bytes to monitor 0x21c081f0
Mar 4 10:23:22 SERVER1 udevd-work[9630]: passed -1 bytes to monitor 0x21c10250
Mar 4 10:23:22 SERVER1 udevd-work[9630]: seq 1210 processed with 0
Mar 4 10:23:22 SERVER1 udevd[313]: seq 1210 done with 0
Mar 4 10:23:22 SERVER1 kernel: [148426.666522] e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
Mar 4 10:23:22 SERVER1 kernel: [148426.666532] e100: Copyright(c) 1999-2006 Intel Corporation
Mar 4 10:23:22 SERVER1 kernel: [148426.666638] e100 0000:00:07.0: PCI->APIC IRQ transform: INT A -> IRQ 23
Mar 4 10:23:22 SERVER1 udevd[313]: seq 1211 queued, 'add' 'module'
Mar 4 10:23:22 SERVER1 udevd[313]: passed 104 bytes to monitor 0x21c081f0
Mar 4 10:23:22 SERVER1 udevd-work[9630]: seq 1211 running
Mar 4 10:23:22 SERVER1 udevd-work[9630]: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
Mar 4 10:23:22 SERVER1 udevd-work[9630]: RUN '/usr/local/bin/backup %k%n drive1' /etc/udev/rules.d/usb-backup.rules:34
Mar 4 10:23:22 SERVER1 udevd-work[9630]: '/usr/local/bin/backup e100 drive1' started

The /etc/udev/rules/usb-backup.rules file runs a rsync backup of the computer when a certain usb drive is plugged in. The rule is:
ID_SERIAL_SHORT=="9QM42EXK", ACTION=="add", RUN="/usr/local/bin/backup %k%n drive1"

For some reason, udev is matching the ethernet port to that hard drive, even though the rule doesn't match (ID_SERIAL_SHORT is not the same, or even present).

The network card's info:
root@SERVER1:~# udevadm info --query all --path=/devices/pci0000:00/0000:00:07.0
P: /devices/pci0000:00/0000:00:07.0
E: UDEV_LOG=3
E: DEVPATH=/devices/pci0000:00/0000:00:07.0
E: DRIVER=e100
E: PCI_CLASS=20000
E: PCI_ID=8086:1229
E: PCI_SUBSYS_ID=8086:100C
E: PCI_SLOT_NAME=0000:00:07.0
E: MODALIAS=pci:v00008086d00001229sv00008086sd0000100Cbc02sc00i00
E: SUBSYSTEM=pci

I'm also attaching udev.log.?field.comment=Reviewing that log showed the problem:
Mar 4 10:23:22 SERVER1 udevd[313]: seq 1210 queued, 'remove' 'module'
Mar 4 10:23:22 SERVER1 udevd[313]: passed 107 bytes to monitor 0x21c081f0
Mar 4 10:23:22 SERVER1 udevd-work[9630]: seq 1210 running
Mar 4 10:23:22 SERVER1 udevd-work[9630]: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
Mar 4 10:23:22 SERVER1 udevd-work[9630]: passed 95 bytes to monitor 0x21c081f0
Mar 4 10:23:22 SERVER1 udevd-work[9630]: passed -1 bytes to monitor 0x21c10250
Mar 4 10:23:22 SERVER1 udevd-work[9630]: seq 1210 processed with 0
Mar 4 10:23:22 SERVER1 udevd[313]: seq 1210 done with 0
Mar 4 10:23:22 SERVER1 kernel: [148426.666522] e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
Mar 4 10:23:22 SERVER1 kernel: [148426.666532] e100: Copyright(c) 1999-2006 Intel Corporation
Mar 4 10:23:22 SERVER1 kernel: [148426.666638] e100 ...

[Chase Douglas (chasedouglas)]

I'll still try to help you with your issue, but I'm marking this as invalid as it's a custom udev rule that's causing issues. The purpose of marking it as invalid is to keep our bug report counts against Ubuntu as accurate as possible.

[Chase Douglas (chasedouglas)]

Try this for your rule instead:

ENV{ID_SERIAL_SHORT}=="9QM42EXK", ACTION=="add", RUN="/usr/local/bin/backup %k%n drive1"

From the udev man page:

       The following key names can be used to match against device properties. Some of the keys also match against properties of the parent devices in sysfs, not only the device that has generated the event. If multiple keys that match a parent device are specified in a single rule, all these keys must match at one and the same parent device.

<snip>

       ENV{key}
           Match against a device property value.

[Austin English (austinenglish)]

Sure, understandable. I considered marking it invalid myself, but it seems there may be a bug in udev, if it's considering that a match...Should I file a separate bug (against udev)?

[Austin English (austinenglish)]

Perfect, thanks! This worked in an older release, I suppose udev's gotten smarter. I'll update the rule accordingly.

Thanks for your patience/help!