My first bug report here. Please let me know if I can improve or if you need more information. Happy to test!
System information
Version: VyOS 1.4-rolling-202110292022 Release train: sagitta Built by: [email protected] Built on: Fri 29 Oct 2021 20:22 UTC Build UUID: 676f5f79-8d04-469f-a27b-003a39e7da75 Build commit ID: 4e56bea9436d78 Architecture: x86_64 Boot via: installed image System type: bare metal Hardware vendor: WYSE Hardware model: Z CLASS
The problem
- Attaching an FTDI USB-to-serial cable makes VyOS sagitta latest hang on boot.
- No entries for the FTDI device are created in /dev/serial/...
- Apart from the boot hang, the system can't see or use the FTDI cable for serial console or serial console-server purposes.
- After applying my fix, a config problem pops up (see end of report).
The diagnosis and fix (for my hardware at least)
# Put udev in debug mode $ udevadm control --log-priority=debug # Check logs # I've only included the important parts of the debug log for brevity # Pay special attention to the lines prepended with --> $ journalctl -f -u systemd-udevd # Now attach the FTDI cable! Oct 30 08:53:24 vyos systemd-udevd[649]: 7-3: Device (SEQNUM=2504, ACTION=add) is queued Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:7 Importing properties from results of builtin command 'hwdb --subsystem=pci' Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: hwdb modalias key: "pci:v00001002d00004397sv00001002sd00004397bc0Csc03i10" Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:8 Skipping builtin 'usb_id' in IMPORT key Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:8 Importing properties from results of builtin command 'hwdb --subsystem=usb' Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: hwdb modalias key: "usb:v0403p6001d0600dc00dsc00dp00icFFiscFFipFFin00" Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:15 Skipping builtin 'path_id' in IMPORT key Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:15 Skipping builtin 'usb_id' in IMPORT key --> Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:26 Running PROGRAM '/bin/sh -c 'echo | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'' --> Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: Starting '/bin/sh -c 'echo | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'' --> Oct 30 08:53:24 vyos systemd-udevd[1975]: ttyUSB0: Creating symlink '/dev/serial/by-bus/' to '../ttyUSB0' --> Oct 30 08:54:25 vyos systemd-udevd[649]: ttyUSB0: Worker [1975] processing SEQNUM=2516 is taking a long time --> Oct 30 08:56:25 vyos systemd-udevd[649]: ttyUSB0: Worker [1975] processing SEQNUM=2516 killed --> Oct 30 08:56:25 vyos systemd-udevd[649]: Worker [1975] terminated by signal 9 (KILL) --> Oct 30 08:56:25 vyos systemd-udevd[649]: ttyUSB0: Worker [1975] failed
Confirm that the udev system fails to properly add the FTDI device to the device tree (unpopulated /dev/serial/):
[email protected]:/home/vyos# ls -la /dev/serial/* total 0 drwxr-xr-x 2 root root 40 Oct 30 08:53 . drwxr-xr-x 14 root root 3020 Oct 30 08:53 ..
Back to the udev debug log. From the line ttyUSB0: Starting '/bin/sh -c 'echo | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'' it appears that the ID_PATH isn't echoed correctly. Let's take a look at /etc/udev/rules.d/90-vyos-serial.rules:
# do not edit this file, it will be overwritten on update
ACTION=="remove", GOTO="serial_end"
SUBSYSTEM!="tty", GOTO="serial_end"
SUBSYSTEMS=="pci", ENV{ID_BUS}="pci", ENV{ID_VENDOR_ID}="$attr{vendor}", ENV{ID_MODEL_ID}="$attr{device}"
SUBSYSTEMS=="pci", IMPORT{builtin}="hwdb --subsystem=pci"
SUBSYSTEMS=="usb", IMPORT{builtin}="usb_id", IMPORT{builtin}="hwdb --subsystem=usb"
# /dev/serial/by-path/, /dev/serial/by-id/ for USB devices
KERNEL!="ttyUSB[0-9]*", GOTO="serial_end"
SUBSYSTEMS=="usb-serial", ENV{.ID_PORT}="$attr{port_number}"
IMPORT{builtin}="path_id", IMPORT{builtin}="usb_id"
# Change the name of the usb id to a "more" human redable format.
#
# - $env{ID_PATH} usually is a name like: "pci-0000:00:10.0-usb-0:2.3.3.4:1.0-port0" so we strip the "pci-*"
# portion and only use the usb part
# - Transform the USB "speech" to the tree like structure so we start with "usb0" as root-complex 0.
# (tr -d -) does the replacement
# - Replace the first group after ":" to represent the bus relation (sed -e 0,/:/s//b/) indicated by "b"
# - Replace the next group after ":" to represent the port relation (sed -e 0,/:/s//p/) indicated by "p"
ENV{ID_PATH}=="?*", ENV{.ID_PORT}=="", PROGRAM="/bin/sh -c 'echo $env{ID_PATH:17} | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'", SYMLINK+="serial/by-bus/$result"
ENV{ID_PATH}=="?*", ENV{.ID_PORT}=="?*", PROGRAM="/bin/sh -c 'echo $env{ID_PATH:17} | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'", SYMLINK+="serial/by-bus/$result"I believe here we can see where it goes wrong. The echo $env{ID_PATH:17} | tr -d - | sed -e 0,/:/s//b/ | sed -e 0,/:/s//p/'", SYMLINK+="serial/by-bus/$result command tries to skip the first 16 characters of the full device ID_PATH by using a variable substring bashism $env{ID_PATH:17} which systemd-udevd doesn't understand. By rewriting the last two lines to:
ENV{ID_PATH}=="?*", ENV{.ID_PORT}=="", PROGRAM="/bin/sh -c 'echo $env{ID_PATH} | sed -e \"s/.*\(usb-\)\([[:digit:]]\):\([[:digit:]]\):\(.*\)/usb\2b\3p\4/\"'", SYMLINK+="serial/by-bus/$result"
ENV{ID_PATH}=="?*", ENV{.ID_PORT}=="?*", PROGRAM="/bin/sh -c 'echo $env{ID_PATH} | sed -e \"s/.*\(usb-\)\([[:digit:]]\):\([[:digit:]]\):\(.*\)/usb\2b\3p\4/\"'", SYMLINK+="serial/by-bus/$result"Then, restart systemd-udevd, set debug mode again, and watch the logs:
$ systemctl restart systemd-udevd $ udevadm control --log-priority=debug $ journalctl -f -u systemd-udevd # Now remove and reinsert the FTDI cable! Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: Starting '/bin/sh -c 'echo pci-0000:00:13.0-usb-0:3:1.0 | sed -e "s/.*\(usb-\)\([[:digit:]]\):\([[:digit:]]\):\(.*\)/usb\2b\3p\4/"'' Oct 30 09:14:47 vyos systemd-udevd[1961]: Successfully forked off '(spawn)' as PID 1966. Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: '/bin/sh -c 'echo pci-0000:00:13.0-usb-0:3:1.0 | sed -e "s/.*\(usb-\)\([[:digit:]]\):\([[:digit:]]\):\(.*\)/usb\2b\3p\4/"''(out) 'usb0b3p1.0' Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: Process '/bin/sh -c 'echo pci-0000:00:13.0-usb-0:3:1.0 | sed -e "s/.*\(usb-\)\([[:digit:]]\):\([[:digit:]]\):\(.*\)/usb\2b\3p\4/"'' succeeded. Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: /etc/udev/rules.d/90-vyos-serial.rules:26 LINK 'serial/by-bus/usb0b3p1.0' Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: Creating symlink '/dev/serial/by-bus/usb0b3p1.0' to '../../ttyUSB0' Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: Creating symlink '/dev/serial/by-path/pci-0000:00:13.0-usb-0:3:1.0-port0' to '../../ttyUSB0' Oct 30 09:14:47 vyos systemd-udevd[1961]: ttyUSB0: Creating symlink '/dev/serial/by-id/usb-FTDI_USB_Null_Modem_Cable_FTBRWY18-if00-port0' to '../../ttyUSB0'
You can now see the ID_PATH being parsed in one go by a single sed call. Subsequently, the device is added to the /dev/serial/by-* tree as expected:
[email protected]:/home/vyos# ls -la /dev/serial/* /dev/serial/by-bus: total 0 drwxr-xr-x 2 root root 60 Oct 30 09:14 . drwxr-xr-x 5 root root 100 Oct 30 09:14 .. lrwxrwxrwx 1 root root 13 Oct 30 09:14 usb0b3p1.0 -> ../../ttyUSB0 /dev/serial/by-id: total 0 drwxr-xr-x 2 root root 60 Oct 30 09:14 . drwxr-xr-x 5 root root 100 Oct 30 09:14 .. lrwxrwxrwx 1 root root 13 Oct 30 09:14 usb-FTDI_USB_Null_Modem_Cable_FTBRWY18-if00-port0 -> ../../ttyUSB0 /dev/serial/by-path: total 0 drwxr-xr-x 2 root root 60 Oct 30 09:14 . drwxr-xr-x 5 root root 100 Oct 30 09:14 .. lrwxrwxrwx 1 root root 13 Oct 30 09:14 pci-0000:00:13.0-usb-0:3:1.0-port0 -> ../../ttyUSB0
Not there yet: config system tripup
One bug (?) still persists: when trying to use this FTDI device as a serial console, I get this error:
[edit] [email protected]# set system console device Possible completions: > ttySN TTY device name, regular serial port > usbNbXpY TTY device name, USB based > hvcN Xen console > ttyS0 > ttyS1 > ttyS2 > ttyS3 > usb0b3p1.0 [edit] [email protected]# set system console device usb0b3p1.0 [edit] [email protected]# commit [ system console ] VyOS had an issue completing a command. We are sorry that you encountered a problem while using VyOS. <...> Traceback (most recent call last): File "/usr/libexec/vyos/conf_mode/system_console.py", line 149, in <module> c = get_config() File "/usr/libexec/vyos/conf_mode/system_console.py", line 43, in get_config for device in console['device'].keys(): RuntimeError: dictionary keys changed during iteration [[system console]] failed Commit failed
Caveats
My proposed sed syntax is okay for my hardware/usecase. But, when I take a look at https://docs.vyos.io/en/latest/operation/information.html#hardware-usb there are USB buses or multiplexors out there with multiple character bus IDs, which the current [[:digit:]] doesn't track. This needs enhancement.