site  contact  subhomenews

2.6.33: USB drive detection problem

February 17, 2010 — BarryK
I am testing the 2.6.33-rc8 kernel, and have a problem with detection of USB drives at bootup.

The 'init' script runs 'dmesg' to look for certain messages after the usb-storage kernel module has been loaded, such as:

usb-storage: device found at 3
usb-storage: waiting for device to settle before scanning
usb-storage: device scan complete

However, these are no longer output, so the 'init' script times-out waiting for them, which greatly slows bootup time.

I searched and found that drivers/usb/storage/usb.c in the kernel source was changed at 2.6.33-rc1: 

-   printk(KERN_DEBUG

-      "usb-storage: device found at %dn", us->pusb_dev->devnum);

+   dev_dbg(&us->pusb_intf->dev, "device foundn");



    set_freezable();

    /* Wait for the timeout to expire or for a disconnect */

    if (delay_use > 0) {

-      printk(KERN_DEBUG "usb-storage: waiting for device "

-            "to settle before scanningn");

+      dev_dbg(&us->pusb_intf->dev, "waiting for device to settle "

+            "before scanningn");

       wait_event_freezable_timeout(us->delay_wait,

             test_bit(US_FLIDX_DONT_SCAN, &us->dflags),

             delay_use * HZ);

@@ -832,7 +839,7 @@ static int usb_stor_scan_thread(void * __us)

          mutex_unlock(&us->dev_mutex);

       }

       scsi_scan_host(us_to_host(us));

-      printk(KERN_DEBUG "usb-storage: device scan completen");

+      dev_dbg(&us->pusb_intf->dev, "scan completen");



       /* Should we unbind if no devices were detected? */

    }


Here is the full change file:
http://www.linuxhq.com/kernel/v2.6/33-rc1/drivers/usb/storage/usb.c

- printk(KERN_DEBUG "usb-storage: device scan completen");
+ dev_dbg(&us->pusb_intf->dev, "scan completen");

...this change is something I don't understand. Can any C expert tell me where that new "scan complete" message is going?

I suppose, I could patch usb.c and bring back those printk statements!

Comments

usb-storage debug
Username: BarryK
I thought maybe that I had to turn on debug mode for the usb-storage module, to get those messages. So, I recompiled the kernel, tested it, and do get a lot of information but not those particular messages. I don't know where they are going to.

No Usb boot in 2.6.33?
Username: technosaurus
"Good catch on that one. Not a C guru, but will try & work through it... Is there a separate kernel switch for [i]device debugging[/i] (vice kern_debug)? if not is patching to revert to printk where needed acceptable? I'm sure you aren't the only one who has used this for init also... what other stuff might similar patches have broken? sda, netsetup etc... they tend to change things like that across the board if for a seemingly good reason.

debug_level sysfs
Username: technosaurus
"I thought I remembered seeing something about per device debugging back when you were building the .31 kernel - here is a link mentioning it for iwlwifi http://patchwork.kernel.org/patch/40034/ it talks about debug_level & sysfs... so perhaps the debug messages are going to /sys/bus/usb/drivers I wonder if this is a method to allow turning off printk to speed up boot by not writing so many messages

Nothing in /sys
Username: BarryK
"I poked around in /sys, can't find those messages. I noticed something odd. Running the 2.6.31.5 kernel, I have /sys/module/usb_storage, but in 2.6.33-rc8 the /sys/module/usb_storage directory is missing, even though the module is loaded. ...that seems very wrong. Seems that someone is stuffing up the usb_storage module, just before 2.6.33 final is to be released?

Vala on Gnome Jornal
Username: Dionicio
"http://www.gnomejournal.org/article/80/writing-multimedia-applications-with-vala Maybe of your interest :)

Vala on Gnome Jornal
Username: Raymundo Dionicio
"http://www.gnomejournal.org/article/80/writing-multimedia-applications-with-vala Maybe of your interest :)

USB bugs reports
Username: BarryK
"I have filed bug reports: http://bugzilla.kernel.org/show_bug.cgi?id=15332 http://bugzilla.kernel.org/show_bug.cgi?id=15333

printk and dev_dbg
Username: j3
"It looks like dev_dbg is used to allow the message to be generated on debug kernels when the logging level is set to 8, but dev_dbg will be omitted from non-debug kernels. It seems odd that these messages would be switched off unless there's now a better way of detecting the device. Reference: http://kernelnewbies.org/FAQ/LinuxKernelDebug101

mdev -s (busybox)
Username: technosaurus
"Are we just using these to populate /dev from /sys ? busybox can do this using mdev... I know with your recent experiment with busybox this may seem like a bad plan, but "Cross Linux From Scratch" uses it by default ... I couldn't speculate on any speed gains or losses though, nor what it's full capabilities are here are a couple of primers for using busybox mdev http://cross-lfs.org/view/clfs-embedded-0.0.1/x86/bootscripts/mdev.html http://wildanm.wordpress.com/2007/08/21/mdev-mini-udev-in-busybox/

re mdev
Username: BarryK
"Puppy uses a quasi-static system. There is a static /dev, in both initramfs and the main f.s. udevd will create new devnodes on an as-needed basis, when a device driver loads. It does this automatically, don't even need any udev rules (which is one reason why you will find /etc/udev/rules.d is relatively unpopulated in Puppy compared with other distros (most of the files in there were added by rerwin, deemed by him necessary for modems, but my original design only had 2-3 files). This approach is very simple, and is the fastest. All that stuff about mounting a tmpfs on /dev then populating it, is unnecessary.

P1
Username: Dougal
"You're really not going to get any help that way... Both gregkh and akpm are nice fellas, but if you set it to high priority and demand they change it, quoting distro-specific usage, you're not likely to get much help. It would have made more sense to set it to a medium/low priority and just ask what happened (quoting the bit of code that changed).

Re: usb-storage messages
Username: BarryK
"Dougal, Yeah, I know I approached it wrong. I got annoyed by the reply of one of those fellows that "no distros" (other than Puppy) read those log messages. So now I have got their backs up and they won't reconsider. So, I'll just patch the file.

No other distro is smart enough
Username: technosaurus
""No, you should not be grepping kernel logs for init sequences, no other distro needs this. Please file a bug with your distro to fix their code." Yeah Barry didn't you realize that kernel logs were only for leisurely reading - not for anything useful. God forbid you do something a better way that the "big dogs" can't adapt to compete against. I don' think you approached it wrong at all - the flat NO without considering the reason for the request was inappropriate at best and at least inconsistent with the principles of open source. Forcing everyone to use udevd or similar is the equivalent of hard-coding a large kernel module to be enabled on all builds when it is only needed in some.

Hmm...
Username: Chad
"Looking at the log from my Ubuntu Karmic system, I think I see how to get around it... unless 2.6.33 removes those lines too ;) [363247.332791] scsi6 : SCSI emulation for USB Mass Storage devices [363247.333083] usb-storage: device found at 6 [363247.333089] usb-storage: waiting for device to settle before scanning [363252.332872] usb-storage: device scan complete [363252.389611] scsi 6:0:0:0: Direct-Access RIM BlackBerry SD 0003 PQ: 0 ANSI: 4 CCS Assuming the two bookending SCSI lines are there it should be possible to pick apart when scsi gets the mass storage device and the actual scan from the scsi 6:0:0:0... line.

usb-storage patch
Username: BarryK
"Note that I am using 2.6.33-git7 in Quirky 008, and this has a patch to restore the old 'printk' statements in the usb-storage code. Link to source and patches: http://bkhome.org/archive/blog2/201003/2633-git7-kernel.html

RE : Where are they going to
Username: K Godt
"Am at going to compile a "full-featured kernel" and was undecided if i still a) need the prink statements and b) if i could insert them from memory . When i first started to compile kernels two years ago i did thought that these prink messages were introduced by puppy . Now i understand things better . So i delved inside the source with grep and finally came up with : CONFIG_DYNAMIC_DEBUG: This mechanism implicitly [b]enables all[/b] pr_debug() and [b]dev_dbg() calls.[/b] The impact of this compile option is a larger kernel text size of about 2%. Thus, the debugfs filesystem must first be mounted before making use of this feature. # So it would be something like " Traditionally debugfs is supposed to be mounted at /sys/kernel/debug with the following command: [code]mount -t debugfs none /sys/kernel/debug/[/code] That's the recommended place to put it." http://lwn.net/Articles/323307/

waiting for devices to settle :
Username: K Godt
"And further, they do not go somewhere into a log file in /sys/kernel/debug . Attaching an usb-hdd , dmesg shows : [i][21017.321019] usb 1-3: new high-speed USB device number 3 using ehci_hcd [21017.436132] usb 1-3: New USB device found, idVendor=4971, idProduct=1014 [21017.436136] usb 1-3: New USB device strings: Mfr=10, Product=11, SerialNumber=3 [21017.436139] usb 1-3: Product: Touro Mobile 3.0 [21017.436140] usb 1-3: Manufacturer: HitachiGST [21017.436142] usb 1-3: SerialNumber: 21001110150000000758 [21017.437254] scsi14 : usb-storage 1-3:1.0 [21020.451294] scsi 14:0:0:0: Direct-Access HitachiG ST 0000 PQ: 0 ANSI: 6 [21020.451544] sd 14:0:0:0: Attached scsi generic sg6 type 0 [21022.471276] sd 14:0:0:0: [sdd] 976773116 512-byte logical blocks: (500 GB/465 GiB) [21022.472022] sd 14:0:0:0: [sdd] Write Protect is off [21022.472027] sd 14:0:0:0: [sdd] Mode Sense: 27 00 00 00 [21022.472768] sd 14:0:0:0: [sdd] No Caching mode page present [21022.472772] sd 14:0:0:0: [sdd] Assuming drive cache: write through [21022.475390] sd 14:0:0:0: [sdd] No Caching mode page present [21022.475395] sd 14:0:0:0: [sdd] Assuming drive cache: write through [21022.580020] sdd: sdd1 sdd2 sdd3 < sdd5 sdd6 sdd7 sdd8 sdd9 sdd10 > [21022.585396] sd 14:0:0:0: [sdd] No Caching mode page present [21022.585401] sd 14:0:0:0: [sdd] Assuming drive cache: write through [21022.585405] sd 14:0:0:0: [sdd] Attached SCSI disk[/i] * Then [code]echo -n 'module usb_storage +p' >/sys/kernel/debug/dynamic_debug/control[/code] gives me output in dmesg : [21776.119277] dynamic_debug:ddebug_exec_queries: processed 1 queries, with 3 matches, 0 errs [21799.975073] usb 1-3: USB disconnect, device number 3 [21841.849022] usb 1-3: new high-speed USB device number 4 using ehci_hcd [21841.964177] usb 1-3: New USB device found, idVendor=4971, idProduct=1014 . . . . [21841.965484] scsi15 : usb-storage 1-3:1.0 [b][21841.965568] usb-storage 1-3:1.0: waiting for device to settle before scanning[/b] [b][21842.968018] usb-storage 1-3:1.0: starting scan[/b] [21844.979718] scsi 15:0:0:0: Direct-Access HitachiG ST 0000 PQ: 0 ANSI: 6 [21844.979969] sd 15:0:0:0: Attached scsi generic sg6 type 0 [21844.980814] sd 15:0:0:0: [sdd] 976773116 512-byte logical blocks: (500 GB/465 GiB) . . [21844.982311] sd 15:0:0:0: [sdd] No Caching mode page present [21844.982315] sd 15:0:0:0: [sdd] Assuming drive cache: write through [b][21844.983971] usb-storage 1-3:1.0: scan complete[/b] [21844.984688] sd 15:0:0:0: [sdd] No Caching mode page present [21844.984693] sd 15:0:0:0: [sdd] Assuming drive cache: write through [21845.071307] sdd: sdd1 sdd2 sdd3 < sdd5 sdd6 sdd7 sdd8 sdd9 sdd10 > . . [21845.074058] sd 15:0:0:0: [sdd] Attached SCSI disk


Tags: puppy