Page MenuHomeVyOS Platform

FTDI cable makes VyOS sagitta latest hang, /dev/serial unpopulated, config system error
Closed, ResolvedPublicBUG

Description

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:         autobuild@vyos.net
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/):

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

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.

Details

Difficulty level
Normal (likely a few hours)
Version
VyOS 1.4-rolling-202110292022
Why the issue appeared?
Design mistake
Is it a breaking change?
Perfectly compatible
Issue type
Bug (incorrect behavior)

Event Timeline

marc_s renamed this task from [Includes proposed fix] FTDI cable makes VyOS sagitta latest hang, /dev/serial unpopulated, config system error to FTDI cable makes VyOS sagitta latest hang, /dev/serial unpopulated, config system error.Oct 30 2021, 2:37 PM
marc_s updated the task description. (Show Details)
c-po changed the task status from Open to In progress.Oct 30 2021, 7:09 PM
c-po claimed this task.
c-po triaged this task as Normal priority.

Awesome report, thanks

c-po changed Why the issue appeared? from Will be filled on close to Design mistake.
c-po changed Is it a breaking change? from Unspecified (possibly destroys the router) to Perfectly compatible.
c-po moved this task from Need Triage to Finished on the VyOS 1.4 Sagitta board.
c-po moved this task from Need Triage to Finished on the VyOS 1.3 Equuleus (1.3.0-epa3) board.