SpeedTouch 330 fails to load firmware

[Duncan Sands]

(Sent again from an ip address that's not on every spam blacklist on the planet)

On Friday 30 June 2006 23:00, K.L.Dixon wrote:
> On Fri Jun 30 20:17 , Duncan Sands <baldrick at free.fr> sent:
> 
> >I replied to you
> >	http://www.mail-archive.com/speedtouch%40ml.free.fr/msg08036.html
> >but never heard anything more (except indirectly via
> >Pete Zaitcev zaitcev at redhat.com>, about the Oops, which
> >I presume is resolved).  Did you look into the possible
> >causes I mentioned?
> >
> >> and then to:-
> >> https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=187299
> >
> Hi Duncan
> 
> Yes, the Oops was resolved by kernel 2.6.16 and I looked into your other 
> suggestions but I am afraid they did not resolve the problem.  I am now using
> a modem router so am just offering myself as a tester for what I think is a 
> deeper problem.  There is a lot more information in the bugzilla.

Hi Keith, please send replies to the list as well as to me.  It sounds to
me like multiple copies of firmware_helper are running at the same time.
(I already mentioned this possibility in my original email, the bit
about "causing two copies of the firmware loader to be run in parallel",
though I guess my remark was a bit obscure). 
This can cause all the effects you see.  First I should explain that
because different modem versions require different firmware, the modem
first tries to load the following files, only trying the next if the
first load fails (here I give stage 2 files; for stage 1 it is similar):
	speedtch-2.bin.4.00
	speedtch-2.bin.4
	speedtch-2.bin
Here 4 and 00 are the modem major and minor versions.  This way, firmware
that works for all revision 4 modems can be placed in speedtch-2.bin.4,
while firmware that works for and is needed for only, say, revision 4.02
modems can be placed in speedtch-2.bin.4.01, and so on.

Here is how parallel copies of firmware_helper can cause these problems:

(a) corrupt firmware (speedtch_upload_firmware: read BLOCK4 from modem failed (-110)!)
Suppose, for example, one instance of firmware_helper is looking for and finds
speedtch-2.bin.4.  First it writes 1 to the "loading" file.  Then it starts writing
the firmware to the "data" file.  At the same time, another instance is looking for
the same or a different firmware file.  It writes 1 to the "loading" file, causing
the kernel to discard the firmware loaded so far.  The first instance finishes writing
the firmware to "data", then writes 0 to "loading".  At this point, the kernel firmware
subsystem passes the partial firmware file (with the start missing) to the speedtouch
driver.  [The second instance then finishes doing its stuff, such as writing -1 to
"loading", but this has no effect].  The speedtouch driver then tries to upload this
partial firmware file, and needless to say this fails.

(b) request_firmware failure (firmware_loading_store: unexpected value (0)).
This can occur because of the multiple instances writing to "loading" in an
unexpected order.

(c) request_firmware failure, different version (speedtch_find_firmware: no stage 2 firmware found!)
This can occur because one of the copies, that failed to find the file it was
looking for, cancels the upload of a copy that found the right file, by writing
-1 to "loading" before the other guy wrote anything to the "data" file.

I saw all these problems myself on my system when due to a configuration error,
/proc/sys/kernel/hotplug contained /sbin/hotplug rather than /sbin/udevsend,
causing two copies of the firmware loader to be run in parallel.

Not only does this smell like multiple copies of firmware_helper running in
parallel, you can (or so it seems) see it happening in one of your log dumps
(https://bugzilla.redhat.com/bugzilla/attachment.cgi?id=131742):

Jun 29 11:18:36 localhost kernel: speedtch 1-2:1.0: found stage 1 firmware speedtch-1.bin.4.00
Jun 29 11:18:36 localhost firmware_helper[2473]:  devpath /class/firmware/1-2:1.0: Success
Jun 29 11:18:36 localhost firmware_helper[2473]:  Opened /lib/firmware/speedtch-1.bin.4.00: Success
Jun 29 11:18:36 localhost firmware_helper[2473]:  Read /lib/firmware/speedtch-1.bin.4.00: Success
Jun 29 11:18:36 localhost firmware_helper[2473]:  Opened /sys/class/firmware/1-2:1.0/data: Success
Jun 29 11:18:36 localhost firmware_helper[2473]:  Written /sys/class/firmware/1-2:1.0/data: Success
Jun 29 11:18:36 localhost firmware_helper[2476]:  devpath /class/firmware/1-2:1.0: Success
Jun 29 11:18:36 localhost firmware_helper[2476]:  Opened /lib/firmware/speedtch-2.bin.4.00: Success
Jun 29 11:18:36 localhost firmware_helper[2481]:  devpath /class/firmware/1-2:1.0: Success
Jun 29 11:18:36 localhost firmware_helper[2481]:  Failed to open /lib/firmware/speedtch-2.bin.4: No such file or directory
Jun 29 11:18:36 localhost firmware_helper[2481]: Loading of /lib/firmware/speedtch-2.bin.4 for speedtch driver failed: No such file or directory
Jun 29 11:18:36 localhost firmware_helper[2476]:  Read /lib/firmware/speedtch-2.bin.4.00: Success
Jun 29 11:18:36 localhost firmware_helper[2476]:  Opened /sys/class/firmware/1-2:1.0/data: Success
Jun 29 11:18:36 localhost firmware_helper[2476]:  Written /sys/class/firmware/1-2:1.0/data: Success
Jun 29 11:18:36 localhost kernel: speedtch 1-2:1.0: found stage 2 firmware speedtch-2.bin
Jun 29 11:18:36 localhost firmware_helper[2487]:  devpath /class/firmware/1-2:1.0: Success
Jun 29 11:18:36 localhost firmware_helper[2487]:  Failed to open /lib/firmware/speedtch-2.bin: No such file or directory
Jun 29 11:18:36 localhost firmware_helper[2487]: Loading of /lib/firmware/speedtch-2.bin for speedtch driver failed: No such file or directory

It looks like processes 2476 and 2481 are running in parallel, both trying to
load stage 2 firmware.  There is also process 2487, which is also trying to load
stage 2 firmware.

Now the big question is: why these multiple copies?  No idea.  One thing to
check is whether the kernel is firing off multiple copies, or if userspace
is doing it.  You can do this by running udevmonitor, and replugging the
modem while it is running.  Also, please check the contents /proc/sys/kernel/hotplug,
just to reassure me :)

Ciao,

Duncan.

PS: It would be good if a copy of all this went into redhat bugzilla; probably
that could be done with an appropriate Cc line, but I don't know how.