LinuxのUSB Driverのdebugやでー！５

さて、USBMONの続き
[root@~]# mount -t debugfs none_debugs /sys/kernel/debug
[root@~]# modprobe usbmon
[root@~]# lsusb
Bus 002 Device 003: ID 0409:0270 NEC Corp.
Bus 002 Device 002: ID 0e0f:0002 VMware, Inc. Virtual USB Hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
root@~]# ls /sys/kernel/debug/usb/usbmon
0s  0u  1s  1t  1u  2s  2t  2u

監視したい、FOMAの携帯はUSB HUBのBus 002に接続されいてるので2uのログを取りだします
[root@~]# cat /sys/kernel/debug/usb/usbmon/2u >acm-FOMA.log
[root@~]# cat acm-FOMA.log
cc5b9880 543302003 C Ii:2:001:1 0:128 1 = 02
cc5b9880 543302086 S Ii:2:001:1 -115:128 2 <
cfb6fe80 543302442 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543302646 C Ci:2:001:0 0 4 = 01010100
cfb6fe80 543302677 S Co:2:001:0 s 23 01 0010 0001 0000 0
cfb6fe80 543302791 C Co:2:001:0 0 0
cfb6fe80 543302823 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543302975 C Ci:2:001:0 0 4 = 01010000
cfb6fe80 543342067 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543342154 C Ci:2:001:0 0 4 = 01010000
cfb6fe80 543367431 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543367533 C Ci:2:001:0 0 4 = 01010000
cfb6fe80 543393363 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543393461 C Ci:2:001:0 0 4 = 01010000
cfb6fe80 543419311 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543419415 C Ci:2:001:0 0 4 = 01010000
cfb6fe80 543419466 S Co:2:001:0 s 23 03 0004 0001 0000 0
cfb6fe80 543419599 C Co:2:001:0 0 0
cfb6fe80 543470705 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543470878 C Ci:2:001:0 0 4 = 03010000
cfb6fe80 543521546 S Co:2:001:0 s 23 01 0014 0001 0000 0
cfb6fe80 543521601 C Co:2:001:0 0 0
cfb6fe80 543521648 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
cfb6fe80 543535285 C Ci:2:000:0 0 18 = 12010002 ffffff40 09047002 00010102 0301
cfb6fe80 543535495 S Co:2:001:0 s 23 03 0004 0001 0000 0
cfb6fe80 543535628 C Co:2:001:0 0 0
cfb6fe80 543586373 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfb6fe80 543586590 C Ci:2:001:0 0 4 = 03010000
cfb6fe80 543637848 S Co:2:001:0 s 23 01 0014 0001 0000 0
cfb6fe80 543638007 C Co:2:001:0 0 0
cfb6fe80 543638069 S Co:2:000:0 s 00 05 0005 0000 0000 0
cfb6fe80 543639340 C Co:2:000:0 0 0
cfb6fe80 543651700 S Ci:2:005:0 s 80 06 0100 0000 0012 18 <
cfb6fe80 543656816 C Ci:2:005:0 0 18 = 12010002 ffffff40 09047002 00010102 0301
cfb6fe80 543656929 S Ci:2:005:0 s 80 06 0600 0000 000a 10 <
cfb6fe80 543660770 C Ci:2:005:0 -32 0
cfb6fe80 543660867 S Ci:2:005:0 s 80 06 0600 0000 000a 10 <
cfb6fe80 543664731 C Ci:2:005:0 -32 0
cfb6fe80 543664826 S Ci:2:005:0 s 80 06 0600 0000 000a 10 <
cfb6fe80 543668730 C Ci:2:005:0 -32 0
cfb6fe80 543668821 S Ci:2:005:0 s 80 06 0200 0000 0009 9 <
cfb6fe80 543673700 C Ci:2:005:0 0 9 = 0902b700 050100c0 32
cfb6fe80 543673799 S Ci:2:005:0 s 80 06 0200 0000 00b7 183 <
cfb6fe80 543680760 C Ci:2:005:0 0 183 = 0902b700 050100c0 32080b00 02028801 00080b02 02028801 00090400 00010288
cfb6fe80 543680922 S Ci:2:005:0 s 80 06 0300 0000 00ff 255 <
cfb6fe80 543688135 C Ci:2:005:0 0 4 = 04030904
cfb6fe80 543688275 S Ci:2:005:0 s 80 06 0302 0409 00ff 255 <
cfb6fe80 543696116 C Ci:2:005:0 0 20 = 14034600 4f004d00 41002000 4e003000 39004100
cfb6fe80 543696277 S Ci:2:005:0 s 80 06 0301 0409 00ff 255 <
cfb6fe80 543704182 C Ci:2:005:0 0 8 = 08034e00 45004300
cfb6fe80 543704321 S Ci:2:005:0 s 80 06 0303 0409 00ff 255 <
cfb6fe80 543712071 C Ci:2:005:0 0 32 = 20033300 35003600 37003500 39003000 32003100 38003600 31003500 39003700
cfb6f080 543713481 S Co:2:005:0 s 00 09 0001 0000 0000 0
cfb6f080 543725104 C Co:2:005:0 0 0
cfbe3d00 544189124 S Co:2:005:0 s 21 22 0000 0000 0000 0
cfbe3d00 544193545 C Co:2:005:0 -32 0
cfbe3d00 544193699 S Co:2:005:0 s 21 20 0000 0000 0007 7 = 80250000 000008
cfbe3d00 544197442 C Co:2:005:0 -32 7 >
cf82f000 544198127 S Co:2:005:0 s 21 22 0000 0002 0000 0
cf82f000 544201425 C Co:2:005:0 -32 0
cf82f000 544201512 S Co:2:005:0 s 21 20 0000 0002 0007 7 = 80250000 000008
cf82f000 544205447 C Co:2:005:0 -32 7 >
cc5b9880 569051454 C Ii:2:001:1 0:128 1 = 02
cc5b9880 569051555 S Ii:2:001:1 -115:128 2 <
cfbe9b80 569051732 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfbe9b80 569051842 C Ci:2:001:0 0 4 = 00010300
cfbe9b80 569051879 S Co:2:001:0 s 23 01 0010 0001 0000 0
cfbe9b80 569051934 C Co:2:001:0 0 0
cfbe9b80 569051959 S Co:2:001:0 s 23 01 0011 0001 0000 0
cfbe9b80 569052010 C Co:2:001:0 0 0
cfbe9b80 569058533 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfbe9b80 569062283 C Ci:2:001:0 0 4 = 00010000
cfbe3f00 569090430 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfbe3f00 569090553 C Ci:2:001:0 0 4 = 00010000
cf8e1300 569116923 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cf8e1300 569117019 C Ci:2:001:0 0 4 = 00010000
cfa14280 569142670 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfa14280 569142816 C Ci:2:001:0 0 4 = 00010000
cfa14d00 569169663 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
cfa14d00 569169754 C Ci:2:001:0 0 4 = 00010000

出力内容は各項目が空白毎に分れています、誤訳するといけないので各自で翻訳してね

以下、Kernel Documentation/usb/usbmon.txtの抜粋
Here is the list of words, from left to right:

- URB Tag. This is used to identify URBs, and is normally an in-kernel address
  of the URB structure in hexadecimal, but can be a sequence number or any
  other unique string, within reason.

- Timestamp in microseconds, a decimal number. The timestamp's resolution
  depends on available clock, and so it can be much worse than a microsecond
  (if the implementation uses jiffies, for example).

- Event Type. This type refers to the format of the event, not URB type.
  Available types are: S - submission, C - callback, E - submission error.

- "Address" word (formerly a "pipe"). It consists of four fields, separated by
  colons: URB type and direction, Bus number, Device address, Endpoint number.
  Type and direction are encoded with two bytes in the following manner:
    Ci Co   Control input and output
    Zi Zo   Isochronous input and output
    Ii Io   Interrupt input and output
    Bi Bo   Bulk input and output
  Bus number, Device address, and Endpoint are decimal numbers, but they may
  have leading zeros, for the sake of human readers.

- URB Status word. This is either a letter, or several numbers separated
  by colons: URB status, interval, start frame, and error count. Unlike the
  "address" word, all fields save the status are optional. Interval is printed
  only for interrupt and isochronous URBs. Start frame is printed only for
  isochronous URBs. Error count is printed only for isochronous callback
  events.

  The status field is a decimal number, sometimes negative, which represents
  a "status" field of the URB. This field makes no sense for submissions, but
  is present anyway to help scripts with parsing. When an error occurs, the
  field contains the error code.

  In case of a submission of a Control packet, this field contains a Setup Tag
  instead of an group of numbers. It is easy to tell whether the Setup Tag is
  present because it is never a number. Thus if scripts find a set of numbers
  in this word, they proceed to read Data Length (except for isochronous URBs).
  If they find something else, like a letter, they read the setup packet before
  reading the Data Length or isochronous descriptors.

- Setup packet, if present, consists of 5 words: one of each for bmRequestType,
  bRequest, wValue, wIndex, wLength, as specified by the USB Specification 2.0.
  These words are safe to decode if Setup Tag was 's'. Otherwise, the setup
  packet was present, but not captured, and the fields contain filler.

- Number of isochronous frame descriptors and descriptors themselves.
  If an Isochronous transfer event has a set of descriptors, a total number
  of them in an URB is printed first, then a word per descriptor, up to a
  total of 5. The word consists of 3 colon-separated decimal numbers for
  status, offset, and length respectively. For submissions, initial length
  is reported. For callbacks, actual length is reported.

- Data Length. For submissions, this is the requested length. For callbacks,
  this is the actual length.

- Data tag. The usbmon may not always capture data, even if length is nonzero.
  The data words are present only if this tag is '='.

- Data words follow, in big endian hexadecimal format. Notice that they are
  not machine words, but really just a byte stream split into words to make
  it easier to read. Thus, the last word may contain from one to four bytes.
  The length of collected data is limited and can be less than the data length
  report in Data Length word.

うーと、結局USBホストとUSB Device（FOMA携帯）間のやり取りが確認されると言うこと
pepoと

LinuxのUSB Driverのdebugやでー！４

さて、USB Driverのdebugでもう一つ興味があるのがusbmonだ、
使えるようにするには、Kernelのmake menuconfigでCONFIG_USB_MONとCONFIG_DEBUG_FSをYESにするよ
[root@linux-2.6.35.6-pepo]# make menuconfig
CONFIG_USB_MON:                                                         x
  x                                                                         x
  x If you select this option, a component which captures the USB traffic   x
  x between peripheral-specific drivers and HC drivers will be built.       x
  x For more information, see <file:Documentation/usb/usbmon.txt>.          x
  x                                                                         x
  x If unsure, say Y, if allowed, otherwise M.                              x
  x                                                                         x
  x Symbol: USB_MON [=m]                                                    x
  x Prompt: USB Monitor                                                     x
  x   Defined at drivers/usb/mon/Kconfig:5                                  x
  x   Depends on: USB_SUPPORT [=y] && USB [=y]                              x
  x   Location:                                                             x
  x     -> Device Drivers                                                   x
  x       -> USB support (USB_SUPPORT [=y])                                 x
  x         -> Support for Host-side USB (USB [=y])

CONFIG_DEBUG_FS:                                                        x
  x                                                                         x
  x debugfs is a virtual file system that kernel developers use to put      x
  x debugging files into.  Enable this option to be able to read and        x
  x write to these files.                                                   xx
  x                                                                         x
  x For detailed documentation on the debugfs API, see                      x
  x Documentation/DocBook/filesystems.                                      x
  x                                                                         x
  x If unsure, say N.                                                       x
  x                                                                         x
  x Symbol: DEBUG_FS [=y]                                                   x
  x Prompt: Debug Filesystem                                                x
  x   Defined at lib/Kconfig.debug:77                                       x
  x   Depends on: SYSFS [=y]                                                x
  x   Location:                                                             x
  x     -> Kernel hacking

詳しくは下記のKernel Documentationを確認してもらったら良いのだが
root@linux-2.6.35.6-pepo]# less Documentation/usb/usbmon.txt
まずは、どんなんかを紹介
[root@linux-2.6.35.6-pepo]# mount -t debugfs none_debugs /sys/kernel/debug
dfコマンドでは確認出来ないので、mountコマンドでマウント状態確認を
[root@linux-2.6.35.6-pepo]# mount
/proc on /proc type proc (rw,relatime)
/sys on /sys type sysfs (rw,relatime)
udev on /dev type devtmpfs (rw,relatime,size=119700k,nr_inodes=29925,mode=755)
/dev/pts on /dev/pts type devpts (rw,relatime,gid=5,mode=620)
/dev/shm on /dev/shm type tmpfs (rw,relatime)
/proc/bus/usb on /proc/bus/usb type usbfs (rw,relatime)
none on /dev type tmpfs (rw,relatime,mode=755)
tmpfs on / type tmpfs (rw,relatime,size=167936k)
/dev/scd0 on /pepo-cdrom type iso9660 (ro,relatime)
/dev/loop0 on /BINMP type squashfs (ro,relatime)
unionfs on /BINRW type unionfs (rw,relatime,dirs=/UNION=rw:/BINMP=ro)
/dev/loop1 on /USRMP type squashfs (ro,relatime)
unionfs on /usr type unionfs (rw,relatime,dirs=/UNION=rw:/USRMP=ro)
/proc on /proc type proc (rw,relatime)
/sys on /sys type sysfs (rw,relatime)
devpts on /dev/pts type devpts (rw,relatime,gid=5,mode=620)
/dev/sda1 on /mnt/hdd type ext2 (rw)
none_debugs on /sys/kernel/debug type debugfs (rw)

一番最後の行に何やら怪しげなdebugfsがmountされてま
何が分るかは後に続くよ

pepoと

LinuxのUSB Driverのdebugやでー！３

さて、LinuxのUSB Driverの監視が出来るようになったところで
くじらのだんなが開発中のacm-FOMAの実際のlogを見てみる
これはPepoLinuxのUSBへFOMA携帯を接続と取り外しを行った時のログ出力だ

[root@~]# tail -f /var/log/debug
Apr 27 22:26:56 epicon kernel: klogd 1.4.1, log source = /proc/kmsg started.
Apr 27 22:29:45 epicon kernel: hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0002
Apr 27 22:29:45 epicon kernel: uhci_hcd 0000:02:00.0: port 1 portsc 0083,00
Apr 27 22:29:45 epicon kernel: hub 2-0:1.0: port 1, status 0101, change 0001, 12 Mb/s
Apr 27 22:29:46 epicon kernel: hub 2-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101
Apr 27 22:29:46 epicon kernel: usb 2-1: new full speed USB device using uhci_hcd and address 8
Apr 27 22:29:48 epicon kernel: usb 2-1: skipped 2 descriptors after configuration
Apr 27 22:29:48 epicon kernel: usb 2-1: skipped 5 descriptors after interface
Apr 27 22:29:48 epicon kernel: usb 2-1: skipped 5 descriptors after interface
Apr 27 22:29:48 epicon kernel: usb 2-1: skipped 3 descriptors after interface
Apr 27 22:29:48 epicon kernel: usb 2-1: default language 0x0409
Apr 27 22:29:48 epicon kernel: usb 2-1: udev 8, busnum 2, minor = 135
Apr 27 22:29:48 epicon kernel: usb 2-1: New USB device found, idVendor=0409, idProduct=0270
Apr 27 22:29:48 epicon kernel: usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Apr 27 22:29:48 epicon kernel: usb 2-1: Product: FOMA N09A
Apr 27 22:29:48 epicon kernel: usb 2-1: Manufacturer: NEC
Apr 27 22:29:48 epicon kernel: usb 2-1: SerialNumber: ****5902186****
Apr 27 22:29:48 epicon kernel: usb 2-1: usb_probe_device
Apr 27 22:29:48 epicon kernel: usb 2-1: configuration #1 chosen from 1 choice
Apr 27 22:29:48 epicon kernel: usb 2-1: adding 2-1:1.0 (config #1, interface 0)
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.0: usb_probe_interface
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.0: usb_probe_interface - got id
Apr 27 22:29:48 epicon kernel: usb 2-1: adding 2-1:1.1 (config #1, interface 1)
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.1: usb_probe_interface
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.1: usb_probe_interface - got id
Apr 27 22:29:48 epicon kernel: usb 2-1: adding 2-1:1.2 (config #1, interface 2)
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.2: usb_probe_interface
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.2: usb_probe_interface - got id
Apr 27 22:29:48 epicon kernel: usb 2-1: adding 2-1:1.3 (config #1, interface 3)
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.3: usb_probe_interface
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.3: usb_probe_interface - got id
Apr 27 22:29:48 epicon kernel: usb 2-1: adding 2-1:1.4 (config #1, interface 4)
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.4: usb_probe_interface
Apr 27 22:29:48 epicon kernel: usbserial_generic 2-1:1.4: usb_probe_interface - got id
Apr 27 22:29:48 epicon kernel: drivers/usb/core/inode.c: creating file '008'
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.0: usb_probe_interface
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.0: usb_probe_interface - got id
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: interfaces are valid
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.0: ttyACM0: USB ACM device
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: acm_control_msg: rq: 0x22 val: 0x0 len: 0x0 result: -32
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: acm_control_msg: rq: 0x20 val: 0x0 len: 0x7 result: -32
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.2: usb_probe_interface
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.2: usb_probe_interface - got id
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: interfaces are valid
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.2: ttyACM1: USB ACM device
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: acm_control_msg: rq: 0x22 val: 0x0 len: 0x0 result: -32
Apr 27 22:29:50 epicon kernel: drivers/usb/class/acm-FOMA.c: acm_control_msg: rq: 0x20 val: 0x0 len: 0x7 result: -32
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.4: usb_probe_interface
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.4: usb_probe_interface - got id
Apr 27 22:29:50 epicon kernel: acm_FOMA 2-1:1.4: no interfaces
Apr 27 22:29:50 epicon kernel: usbcore: registered new interface driver acm_FOMA
Apr 27 22:29:50 epicon kernel: acm_FOMA: v0.26-FOMA.10:USB modems driver for docomo FOMA Cellular phone
Apr 27 22:31:38 epicon kernel: hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0002
Apr 27 22:31:38 epicon kernel: uhci_hcd 0000:02:00.0: port 1 portsc 008a,00
Apr 27 22:31:38 epicon kernel: hub 2-0:1.0: port 1, status 0100, change 0003, 12 Mb/s
Apr 27 22:31:38 epicon kernel: usb 2-1: USB disconnect, address 8
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering device
Apr 27 22:31:38 epicon kernel: usb 2-1: usb_disable_device nuking all URBs
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering interface 2-1:1.0
Apr 27 22:31:38 epicon kernel: drivers/usb/class/acm-FOMA.c: Entering stop_data_traffic
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering interface 2-1:1.1
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering interface 2-1:1.2
Apr 27 22:31:38 epicon kernel: drivers/usb/class/acm-FOMA.c: Entering stop_data_traffic
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering interface 2-1:1.3
Apr 27 22:31:38 epicon kernel: usb 2-1: unregistering interface 2-1:1.4
Apr 27 22:31:38 epicon kernel: hub 2-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x100
これで、何が分るかは後に続くよ

pepoと