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 problem still remainsa config problem pops up (see end of report).
**The diagnosis and
proposed fix**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/`):
```
root@vyos:/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:
```
root@vyos:/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]
vyos@vyos# 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]
vyos@vyos# set system console device usb0b3p1.0
[edit]
vyos@vyos# 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**
I'm unsure if mMy proposed `sed`
callsyntax is oka
yy for my hardware/usecase.
There may be USB buses or multiplexors out there with multiple digit bus IDsBut, wh
ich the current `[[:digit:]]` doesn't track.en 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, Maybe better to usewhich the current `[[:digit:]]
*` in that case` doesn't track.
The backreferences make sure the matched part ends up in the `$result` anywayThis needs enhancement.