[<<][pool][>>][..]
Fri Dec 31 18:31:32 EST 2010

udev woes

udev is a pain, or is just how it works on Debian?  Maybe I just don't
understand and this is just a case of not RTFM.  Conceptually it's
simple: there are events and rules, and when a rule matches an event
then it is applied.

However, one physical USB plug-in action triggers a multitude of
events.  And it seems the environment variables that are generated by
the /lib/udev/usb_id program are not available on each trigger.
Frankly I don't care about the complexity under the hood, I just want
to solve this:

  PROBLEM: associate a specific name or symlink to a specific FTDI usb
           serial cable.

After several tries (see previous post) I finally found something that
works: just run the /lib/udev/usb_id program explicitly and match on
an environment variable.  This is what I have in 99-tty.rules:

IMPORT{program}="usb_id --export %p", ENV{ID_SERIAL}=="FTDI_TTL232R_FTDCIX5Z", SYMLINK+="ftdi"


Apparently this is still not correct.  What this does is to give an
alias to the raw USB device.  What you want is a driver to handle
this, and link the device the driver presents.  At the time the event
for this serial device is executed, the ID is gone!


So, let's see what really happens.  It seems that not knowing how the
whole thing works is not an option..  See the output of "udevd
--debug" below as a response to plugging in the FTDI cable.


1293839146.211444 [14300] event_queue_insert: seq 2176 queued, 'add' 'usb'
1293839146.211471 [14300] udev_monitor_send_device: passed 305 bytes to netlink monitor 0x7f6e3fa9f770
1293839146.211518 [14302] worker_new: seq 2176 running
1293839146.211587 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf490 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2'
1293839146.211648 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf840 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1'
1293839146.211673 [14302] udev_device_new_from_syspath: device 0x7f6e3faafb50 has devpath '/devices/pci0000:00/0000:00:13.2/usb2'
1293839146.211703 [14302] udev_device_new_from_syspath: device 0x7f6e3faafe20 has devpath '/devices/pci0000:00/0000:00:13.2'
1293839146.211719 [14302] udev_device_new_from_syspath: device 0x7f6e3fab00f0 has devpath '/devices/pci0000:00'
1293839146.212018 [14302] udev_rules_apply_to_event: PROGRAM 'check-ptp-camera 06/01/01' /etc/udev/rules.d/025_libgphoto2.rules:967
1293839146.212026 [14302] util_run_program: 'check-ptp-camera 06/01/01' started
1293839146.212874 [14300] event_queue_insert: seq 2177 queued, 'add' 'usb'
1293839146.212897 [14300] event_queue_insert: seq 2178 queued, 'add' 'usb-serial'
1293839146.213105 [14300] event_queue_insert: seq 2179 queued, 'add' 'tty'
1293839146.213221 [14300] udev_monitor_send_device: passed 272 bytes to netlink monitor 0x7f6e3fa9f770
1293839146.213245 [14300] event_queue_insert: seq 2180 queued, 'add' 'usb_device'
1293839146.213255 [14303] worker_new: seq 2179 running
1293839146.213286 [14303] udev_device_new_from_syspath: device 0x7f6e3faae1f0 has devpath '/class/tty/ttyUSB0'
1293839146.213323 [14303] udev_device_new_from_syspath: device 0x7f6e3fab04a0 has devpath '/class/tty'
1293839146.213341 [14303] udev_rules_apply_to_event: LINK 'char/188:0' /lib/udev/rules.d/50-udev-default.rules:2
1293839146.213373 [14303] udev_rules_apply_to_event: IMPORT 'path_id /class/tty/ttyUSB0' /lib/udev/rules.d/60-persistent-serial.rules:9
1293839146.213387 [14303] util_run_program: 'path_id /class/tty/ttyUSB0' started
1293839146.214708 [14303] util_run_program: 'path_id /class/tty/ttyUSB0' returned with exitcode 1
1293839146.214723 [14303] udev_rules_apply_to_event: IMPORT 'usb_id --export /class/tty/ttyUSB0' /lib/udev/rules.d/60-persistent-serial.rules:13
1293839146.214730 [14303] util_run_program: 'usb_id --export /class/tty/ttyUSB0' started
1293839146.215547 [14303] util_run_program: 'usb_id --export /class/tty/ttyUSB0' returned with exitcode 1
1293839146.215588 [14303] udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
1293839146.215602 [14303] udev_rules_apply_to_event: GROUP 20 /lib/udev/rules.d/91-permissions.rules:39
1293839146.215614 [14303] udev_event_execute_rules: no node name set, will use kernel supplied name 'ttyUSB0'
1293839146.215644 [14303] udev_device_update_db: created db link (ttyUSB0 char/188:0)
1293839146.215653 [14303] udev_node_add: creating device node '/dev/ttyUSB0', devnum=188:0, mode=0660, uid=0, gid=20
1293839146.215673 [14302] util_run_program: 'check-ptp-camera 06/01/01' returned with exitcode 1
1293839146.215679 [14303] udev_node_mknod: mknod '/dev/ttyUSB0' 188:0 020660
1293839146.215697 [14303] udev_node_mknod: set permissions '/dev/ttyUSB0' 020660 uid=0 gid=20
1293839146.215697 [14302] udev_rules_apply_to_event: LINK 'char/189:184' /lib/udev/rules.d/50-udev-default.rules:2
1293839146.215715 [14303] node_symlink: creating symlink '/dev/char/188:0' to '../ttyUSB0'
1293839146.215737 [14302] wait_for_file: file '/sys/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/descriptors' appeared after 0 loops
1293839146.215745 [14303] udev_monitor_send_device: passed 285 bytes to socket monitor 0x7f6e3faae1f0
1293839146.215755 [14302] udev_rules_apply_to_event: NAME 'bus/usb/002/057' /lib/udev/rules.d/50-udev-default.rules:29
1293839146.215807 [14303] udev_monitor_send_device: passed -1 bytes to netlink monitor 0x7f6e3fab0310
1293839146.215818 [14303] worker_new: seq 2179 processed with 0
1293839146.215842 [14300] event_queue_delete: seq 2179 done with 0
1293839146.215957 [14302] udev_rules_apply_to_event: IMPORT 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' /lib/udev/rules.d/70-acl.rules:10
1293839146.215968 [14302] util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' started
1293839146.216754 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR=FTDI'
1293839146.216762 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ENC=FTDI'
1293839146.216766 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ID=0403'
1293839146.216769 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL=TTL232R'
1293839146.216773 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ENC=TTL232R'
1293839146.216776 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ID=6001'
1293839146.216780 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_REVISION=0600'
1293839146.216783 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL=FTDI_TTL232R_FTDCIX5Z'
1293839146.216787 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL_SHORT=FTDCIX5Z'
1293839146.216790 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_BUS=usb'
1293839146.216793 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_USB_INTERFACES=:ffffff:'
1293839146.216812 [14302] util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' returned with exitcode 0
1293839146.216866 [14302] udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
1293839146.216876 [14302] udev_rules_apply_to_event: MODE 0664 /lib/udev/rules.d/91-permissions.rules:36
1293839146.216884 [14302] udev_rules_apply_to_event: IMPORT 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' /etc/udev/rules.d/99-tty.rules:2
1293839146.216892 [14302] util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' started
1293839146.217603 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR=FTDI'
1293839146.217614 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ENC=FTDI'
1293839146.217623 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ID=0403'
1293839146.217627 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL=TTL232R'
1293839146.217631 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ENC=TTL232R'
1293839146.217634 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ID=6001'
1293839146.217638 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_REVISION=0600'
1293839146.217641 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL=FTDI_TTL232R_FTDCIX5Z'
1293839146.217644 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL_SHORT=FTDCIX5Z'
1293839146.217648 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_BUS=usb'
1293839146.217652 [14302] util_run_program: '/lib/udev/usb_id' (stdout) 'ID_USB_INTERFACES=:ffffff:'
1293839146.217683 [14302] util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' returned with exitcode 0
1293839146.217700 [14302] udev_rules_apply_to_event: LINK 'pic0' /etc/udev/rules.d/99-tty.rules:2
1293839146.217773 [14302] udev_device_update_db: created db file for '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2' in '/dev/.udev/db/usb:2-1.2'
1293839146.217788 [14302] udev_node_add: creating device node '/dev/bus/usb/002/057', devnum=189:184, mode=0664, uid=0, gid=0
1293839146.217798 [14302] udev_node_mknod: mknod '/dev/bus/usb/002/057' 189:184 020664
1293839146.217810 [14302] udev_node_mknod: set permissions '/dev/bus/usb/002/057' 020664 uid=0 gid=0
1293839146.217828 [14302] node_symlink: creating symlink '/dev/char/189:184' to '../bus/usb/002/057'
1293839146.217849 [14302] link_update: creating link '/dev/pic0' to '/dev/bus/usb/002/057'
1293839146.217861 [14302] node_symlink: creating symlink '/dev/pic0' to 'bus/usb/002/057'
1293839146.217906 [14302] udev_monitor_send_device: passed 578 bytes to socket monitor 0x7f6e3faaf490
1293839146.217927 [14302] udev_monitor_send_device: passed -1 bytes to netlink monitor 0x7f6e3faaf1b0
1293839146.217939 [14302] worker_new: seq 2176 processed with 0
1293839146.217962 [14300] event_queue_delete: seq 2176 done with 0
1293839146.217984 [14300] udev_monitor_send_device: passed 329 bytes to netlink monitor 0x7f6e3fa9f770
1293839146.218050 [14300] udev_monitor_send_device: passed 264 bytes to netlink monitor 0x7f6e3fa9f770
1293839146.218073 [14303] worker_new: seq 2180 running
1293839146.218077 [14302] worker_new: seq 2177 running
1293839146.218136 [14303] udev_device_new_from_syspath: device 0x7f6e3faafb60 has devpath '/class/usb_device/usbdev2.57'
1293839146.218184 [14302] udev_device_new_from_syspath: device 0x7f6e3faafb50 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/2-1.2:1.0'
1293839146.218237 [14303] udev_device_new_from_syspath: device 0x7f6e3faae1f0 has devpath '/class/usb_device'
1293839146.218280 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf840 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2'
1293839146.218321 [14302] udev_device_new_from_syspath: device 0x7f6e3faaec50 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1'
1293839146.218340 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf490 has devpath '/devices/pci0000:00/0000:00:13.2/usb2'
1293839146.218353 [14303] udev_rules_apply_to_event: PROGRAM 'check-ptp-camera 06/01/01' /etc/udev/rules.d/025_libgphoto2.rules:967
1293839146.218361 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf5a0 has devpath '/devices/pci0000:00/0000:00:13.2'
1293839146.218364 [14303] util_run_program: 'check-ptp-camera 06/01/01' started
1293839146.218520 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf6b0 has devpath '/devices/pci0000:00'
1293839146.218560 [14302] udev_rules_apply_to_event: RUN '/sbin/modprobe -b $env{MODALIAS}' /lib/udev/rules.d/80-drivers.rules:7
1293839146.218572 [14302] udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
1293839146.218586 [14302] util_run_program: '/sbin/modprobe -b usb:v0403p6001d0600dc00dsc00dp00icFFiscFFipFF' started
1293839146.219875 [14302] util_run_program: '/sbin/modprobe -b usb:v0403p6001d0600dc00dsc00dp00icFFiscFFipFF' returned with exitcode 0
1293839146.219906 [14302] udev_monitor_send_device: passed 351 bytes to socket monitor 0x7f6e3faa0a30
1293839146.219924 [14302] udev_monitor_send_device: passed -1 bytes to netlink monitor 0x7f6e3faaf1b0
1293839146.219933 [14302] worker_new: seq 2177 processed with 0
1293839146.219949 [14300] event_queue_delete: seq 2177 done with 0
1293839146.220014 [14300] udev_monitor_send_device: passed 191 bytes to netlink monitor 0x7f6e3fa9f770
1293839146.220028 [14302] worker_new: seq 2178 running
1293839146.220093 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf840 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/2-1.2:1.0/ttyUSB0'
1293839146.220141 [14302] udev_device_new_from_syspath: device 0x7f6e3faafe70 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/2-1.2:1.0'
1293839146.220162 [14302] udev_device_new_from_syspath: device 0x7f6e3faafb50 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2'
1293839146.220223 [14302] udev_device_new_from_syspath: device 0x7f6e3faafc60 has devpath '/devices/pci0000:00/0000:00:13.2/usb2/2-1'
1293839146.220266 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf490 has devpath '/devices/pci0000:00/0000:00:13.2/usb2'
1293839146.220283 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf5a0 has devpath '/devices/pci0000:00/0000:00:13.2'
1293839146.220461 [14302] udev_device_new_from_syspath: device 0x7f6e3faaf6b0 has devpath '/devices/pci0000:00'
1293839146.220479 [14302] udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
1293839146.220499 [14302] udev_monitor_send_device: passed 221 bytes to socket monitor 0x7f6e3faaf840
1293839146.220557 [14302] udev_monitor_send_device: passed -1 bytes to netlink monitor 0x7f6e3faaf1b0
1293839146.220566 [14302] worker_new: seq 2178 processed with 0
1293839146.220577 [14300] event_queue_delete: seq 2178 done with 0
1293839146.221144 [14303] util_run_program: 'check-ptp-camera 06/01/01' returned with exitcode 1
1293839146.221160 [14303] udev_rules_apply_to_event: LINK 'char/189:184' /lib/udev/rules.d/50-udev-default.rules:2
1293839146.221249 [14303] udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
1293839146.221261 [14303] udev_event_execute_rules: no node name set, will use kernel supplied name 'usbdev2.57'
1293839146.221282 [14303] udev_device_update_db: created db link (usbdev2.57 char/189:184)
1293839146.221288 [14303] udev_node_add: creating device node '/dev/usbdev2.57', devnum=189:184, mode=0600, uid=0, gid=0
1293839146.221295 [14303] udev_node_mknod: mknod '/dev/usbdev2.57' 189:184 020600
1293839146.221304 [14303] udev_node_mknod: set permissions '/dev/usbdev2.57' 020600 uid=0 gid=0
1293839146.221317 [14303] node_symlink: atomically replace '/dev/char/189:184'
1293839146.221343 [14303] udev_monitor_send_device: passed 289 bytes to socket monitor 0x7f6e3faafb60
1293839146.221401 [14303] udev_monitor_send_device: passed -1 bytes to netlink monitor 0x7f6e3fab0310
1293839146.221410 [14303] worker_new: seq 2180 processed with 0
1293839146.221418 [14300] event_queue_delete: seq 2180 done with 0



I can't find a way to do that.  Don't want to read tons of manuals and
get nowhere..  So, how to hack around this?

This is what works, but it's the wrong device.

zoo:~# /lib/udev/usb_id --export /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2
ID_VENDOR=FTDI
ID_VENDOR_ENC=FTDI
ID_VENDOR_ID=0403
ID_MODEL=TTL232R
ID_MODEL_ENC=TTL232R
ID_MODEL_ID=6001
ID_REVISION=0600
ID_SERIAL=FTDI_TTL232R_FTDCIX5Z
ID_SERIAL_SHORT=FTDCIX5Z
ID_BUS=usb
ID_USB_INTERFACES=:ffffff:


However, when you do this:

zoo:/sys/class/tty/ttyUSB0/device# pwd -P
/sys/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/2-1.2:1.0/ttyUSB0

You get almost what's necessary to pass to usb_id.  In the correct
directory, you get:

zoo:/sys/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2# echo `pwd|sed s/\\\\/sys//`
/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2

So also:
zoo:/sys/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2# /lib/udev/usb_id --export `pwd|sed s/\\\\/sys//`

The full magic then goes like this[1]


However, that doesn't seem to work as expected.  The script doesn't
get called for the /class/tty/ttyUSB device.

Hmm.. I don't understand.  Back to the original question:

  - why do these environment variables get lost from usb -> usbserial?
  - why is tha ATTR(serial) not working?
  - why doesn't "udevadm info -a" show attribs?
  - what's with the DB?

zoo:/dev/.udev/db# udevadm info --query=all -p /class/tty/ttyUSB0
P: /class/tty/ttyUSB0
N: ttyUSB0
S: char/188:0
E: UDEV_LOG=3
E: DEVPATH=/class/tty/ttyUSB0
E: MAJOR=188
E: MINOR=0
E: DEVNAME=/dev/ttyUSB0
E: PHYSDEVPATH=/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2/2-1.2:1.0/ttyUSB0
E: PHYSDEVBUS=usb-serial
E: PHYSDEVDRIVER=ftdi_sio
E: SUBSYSTEM=tty
E: DEVLINKS=/dev/char/188:0

zoo:/dev/.udev/db# udevadm info --query=all -p /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2
P: /devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2
N: bus/usb/002/067
S: char/189:194
E: UDEV_LOG=3
E: DEVPATH=/devices/pci0000:00/0000:00:13.2/usb2/2-1/2-1.2
E: MAJOR=189
E: MINOR=194
E: DEVNAME=/dev/bus/usb/002/067
E: DEVTYPE=usb_device
E: DRIVER=usb
E: PHYSDEVBUS=usb
E: PHYSDEVDRIVER=usb
E: DEVICE=/proc/bus/usb/002/067
E: PRODUCT=403/6001/600
E: TYPE=0/0/0
E: BUSNUM=002
E: DEVNUM=067
E: SUBSYSTEM=usb
E: ID_VENDOR=FTDI
E: ID_VENDOR_ENC=FTDI
E: ID_VENDOR_ID=0403
E: ID_MODEL=TTL232R
E: ID_MODEL_ENC=TTL232R
E: ID_MODEL_ID=6001
E: ID_REVISION=0600
E: ID_SERIAL=FTDI_TTL232R_FTDCIX5Z
E: ID_SERIAL_SHORT=FTDCIX5Z
E: ID_BUS=usb
E: ID_USB_INTERFACES=:ffffff:
E: DEVLINKS=/dev/char/189:194




Pfff..  Tried some more.  The hack in [1] doen't work.


[1] http://zwizwa.be/darcs/pool/bin/ttyUSB_id



[Reply][About]
[<<][pool][>>][..]