Device or resource busy: '/dev/ttyUSB0'

bartbutenaers commented 1 year ago

Hi everybody,

Here is your poltergeist again ...

My steps:

I build my flow via the sidebar.
I put the WT32-ETH01 in programming mode (i.e. connect IO01 pin to GND).
I power off/on the WT32-ETH01 (to activate the programming mode).
When I deploy my flow via the sidebar, the following error occurs:
```
OSError: [Errno 16] Device or resource busy: '/dev/ttyUSB0'
```

I have registered the issue here, because I "think" it is somehow related to the Node-RED integration. Because:

I cannot solve it by powering off/on my WT32-ETH01 device.
I cannot solve it by pluggin out/in my USB-TTL converter (from my Raspberry Pi 4).
I can solve it by restarting Node-RED.

So I "assume" it is somewhere hanging in a Node-RED child process?

Do I need to do extra tests in case it happens again, to allow you to troubleshoot it.

Sorry to trouble you guys with these difficult questions...

Kind regards, Bart

Here is the full log:

>> IDF_PYTHON_ENV_PATH: /home/pi/.espressif/python_env/idf4.4_py3.9_env
>> mcconfig -d -x localhost:5004 -l -m -p esp32/wt32_eth01 -t deploy
/home/pi/esp-idf/tools/idf.py
# uploading to esp32
[1/5] cd /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build/esp-idf/esptool_py && /home/pi/.espressif/python_env/idf4.4_py3.9_env/bin/python /home/pi/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 partition --type app /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build/partition_table/partition-table.bin /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build/xs_esp32.bin
xs_esp32.bin binary size 0x1744c0 bytes. Smallest app partition is 0x390000 bytes. 0x21bb40 bytes (59%) free.
[2/5] Performing build step for 'bootloader'
[1/1] cd /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build/bootloader/esp-idf/esptool_py && /home/pi/.espressif/python_env/idf4.4_py3.9_env/bin/python /home/pi/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 bootloader 0x1000 /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build/bootloader/bootloader.bin
Bootloader binary size 0x4420 bytes. 0x2be0 bytes (39%) free.
[2/3] cd /home/pi/esp-idf/components/esptool_py && /usr/bin/cmake -D IDF_PATH="/home/pi/esp-idf" -D SERIAL_TOOL="/home/pi/.espressif/python_env/idf4.4_py3.9_env/bin/python /home/pi/esp-idf/components/esptool_py/esptool/esptool.py --chip esp32" -D SERIAL_TOOL_ARGS="--before=default_reset --after=hard_reset write_flash @flash_args" -D WORKING_DIRECTORY="/home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build" -P /home/pi/esp-idf/components/esptool_py/run_serial_tool.cmake
esptool.py esp32 -p /dev/ttyUSB0 -b 921600 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 80m --flash_size 4MB 0x1000 bootloader/bootloader.bin 0x10000 xs_esp32.bin 0x8000 partition_table/partition-table.bin
esptool.py v3.3.2
Serial port /dev/ttyUSB0
Traceback (most recent call last):
  File "/home/pi/.espressif/python_env/idf4.4_py3.9_env/lib/python3.9/site-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
OSError: [Errno 16] Device or resource busy: '/dev/ttyUSB0'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/esp-idf/components/esptool_py/esptool/esptool.py", line 5482, in <module>
    _main()
  File "/home/pi/esp-idf/components/esptool_py/esptool/esptool.py", line 5475, in _main
    main()
  File "/home/pi/esp-idf/components/esptool_py/esptool/esptool.py", line 4782, in main
    esp = esp or get_default_connected_device(ser_list, port=args.port, connect_attempts=args.connect_attempts,
  File "/home/pi/esp-idf/components/esptool_py/esptool/esptool.py", line 115, in get_default_connected_device
    _esp = chip_class(each_port, initial_baud, trace)
  File "/home/pi/esp-idf/components/esptool_py/esptool/esptool.py", line 345, in __init__
    self._port = serial.serial_for_url(port)
  File "/home/pi/.espressif/python_env/idf4.4_py3.9_env/lib/python3.9/site-packages/serial/__init__.py", line 90, in serial_for_url
    instance.open()
  File "/home/pi/.espressif/python_env/idf4.4_py3.9_env/lib/python3.9/site-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno 16] could not open port /dev/ttyUSB0: [Errno 16] Device or resource busy: '/dev/ttyUSB0'
CMake Error at run_serial_tool.cmake:56 (message):
  /home/pi/.espressif/python_env/idf4.4_py3.9_env/bin/python
  /home/pi/esp-idf/components/esptool_py/esptool/esptool.py --chip esp32
  failed

FAILED: CMakeFiles/flash 
cd /home/pi/esp-idf/components/esptool_py && /usr/bin/cmake -D IDF_PATH="/home/pi/esp-idf" -D SERIAL_TOOL="/home/pi/.espressif/python_env/idf4.4_py3.9_env/bin/python /home/pi/esp-idf/components/esptool_py/esptool/esptool.py --chip esp32" -D SERIAL_TOOL_ARGS="--before=default_reset --after=hard_reset write_flash @flash_args" -D WORKING_DIRECTORY="/home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build" -P /home/pi/esp-idf/components/esptool_py/run_serial_tool.cmake
ninja: build stopped: subcommand failed.
ninja failed with exit code 1
Executing action: flash
Running ninja in directory /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/build
Executing "ninja flash"...

bartbutenaers commented 1 year ago

BTW I am using Moddable SDK git commit 2a4641e (from March 21).

phoddie commented 1 year ago

What did you before this? It looks like the serial port was left open from something that occurred before this log.

When this happens, can you dump a list of processes running on your build machine to see if there might be a background process still running?

FWIW – The -t deploy option just downloads the most recently built binary. It doesn't built a binary and it doesn't launch the debugger.

bartbutenaers commented 1 year ago

Meanwhile I had the issue several time, and it seems to occur when I do e.g. this:

I start xsbug-log via my sidebar:
Then xsbug-log starts listening as expected:
Now something happens like I am away too long from my pc, or I refresh my browser tab, ...
And I had another trivial case where it occured, but can't remember now.
When I go back to Ralph's sidebar, my xterm terminal window is empty:
Since my mcu is still connected via a serial wire, I want to start listening to it again to show the messages in my xterm terminal window. So I repeat step 1 again.
But then I get the error that it is still listening.

Before I executed step 5, it seems that process with pid 108770 is using the serial port:

pi@raspberrypi:~ $ ls -l /proc/[0-9]*/fd/* |grep /dev/ttyUSB0
lrwx------ 1 pi pi 64 Mar 28 22:48 /proc/108770/fd/3 -> /dev/ttyUSB0

And that pid corresponds to serial2xsbug

pi@raspberrypi:~ $ ps -ef | grep 108770
pi        108770  108769  0 22:30 ?        00:00:00 serial2xsbug /dev/ttyUSB0 460800 8N1

Below you can find all processes at that time:

pi@raspberrypi:~ $ ps -ef
UID          PID    PPID  C STIME TTY          TIME CMD
root           1       0  0 Mar23 ?        00:00:06 /sbin/init
root           2       0  0 Mar23 ?        00:00:00 [kthreadd]
root           3       2  0 Mar23 ?        00:00:00 [rcu_gp]
root           4       2  0 Mar23 ?        00:00:00 [rcu_par_gp]
root           5       2  0 Mar23 ?        00:00:00 [slub_flushwq]
root           6       2  0 Mar23 ?        00:00:00 [netns]
root           8       2  0 Mar23 ?        00:00:00 [kworker/0:0H-events_highpri]
root          10       2  0 Mar23 ?        00:00:00 [mm_percpu_wq]
root          11       2  0 Mar23 ?        00:00:00 [rcu_tasks_kthre]
root          12       2  0 Mar23 ?        00:00:00 [rcu_tasks_rude_]
root          13       2  0 Mar23 ?        00:00:00 [rcu_tasks_trace]
root          14       2  0 Mar23 ?        00:01:32 [ksoftirqd/0]
root          15       2  0 Mar23 ?        00:02:34 [rcu_preempt]
root          16       2  0 Mar23 ?        00:00:00 [migration/0]
root          17       2  0 Mar23 ?        00:00:00 [cpuhp/0]
root          18       2  0 Mar23 ?        00:00:00 [cpuhp/1]
root          19       2  0 Mar23 ?        00:00:00 [migration/1]
root          20       2  0 Mar23 ?        00:00:31 [ksoftirqd/1]
root          22       2  0 Mar23 ?        00:00:00 [kworker/1:0H-kblockd]
root          23       2  0 Mar23 ?        00:00:00 [cpuhp/2]
root          24       2  0 Mar23 ?        00:00:00 [migration/2]
root          25       2  0 Mar23 ?        00:00:58 [ksoftirqd/2]
root          27       2  0 Mar23 ?        00:00:00 [kworker/2:0H-kblockd]
root          28       2  0 Mar23 ?        00:00:00 [cpuhp/3]
root          29       2  0 Mar23 ?        00:00:00 [migration/3]
root          30       2  0 Mar23 ?        00:02:09 [ksoftirqd/3]
root          32       2  0 Mar23 ?        00:00:00 [kworker/3:0H-kblockd]
root          33       2  0 Mar23 ?        00:00:00 [kdevtmpfs]
root          34       2  0 Mar23 ?        00:00:00 [inet_frag_wq]
root          39       2  0 Mar23 ?        00:00:00 [kauditd]
root          41       2  0 Mar23 ?        00:00:00 [khungtaskd]
root          42       2  0 Mar23 ?        00:00:00 [oom_reaper]
root          43       2  0 Mar23 ?        00:00:00 [writeback]
root          44       2  0 Mar23 ?        00:00:26 [kcompactd0]
root          66       2  0 Mar23 ?        00:00:00 [kblockd]
root          67       2  0 Mar23 ?        00:00:00 [blkcg_punt_bio]
root          68       2  0 Mar23 ?        00:00:00 [watchdogd]
root          70       2  0 Mar23 ?        00:00:03 [kworker/0:1H-kblockd]
root          71       2  0 Mar23 ?        00:00:00 [rpciod]
root          72       2  0 Mar23 ?        00:00:00 [kworker/u9:0-hci0]
root          73       2  0 Mar23 ?        00:00:00 [xprtiod]
root          75       2  0 Mar23 ?        00:00:42 [kswapd0]
root          76       2  0 Mar23 ?        00:00:00 [nfsiod]
root          77       2  0 Mar23 ?        00:00:00 [kthrotld]
root          78       2  0 Mar23 ?        00:00:00 [iscsi_eh]
root          79       2  0 Mar23 ?        00:00:00 [iscsi_conn_clea]
root          80       2  0 Mar23 ?        00:00:00 [nvme-wq]
root          81       2  0 Mar23 ?        00:00:00 [nvme-reset-wq]
root          82       2  0 Mar23 ?        00:00:00 [nvme-delete-wq]
root          84       2  0 Mar23 ?        00:00:00 [DWC Notificatio]
root          85       2  0 Mar23 ?        00:00:00 [uas]
root          86       2  0 Mar23 ?        00:00:00 [vchiq-slot/0]
root          87       2  0 Mar23 ?        00:00:00 [vchiq-recy/0]
root          88       2  0 Mar23 ?        00:00:00 [vchiq-sync/0]
root          89       2  0 Mar23 ?        00:00:00 [zswap-shrink]
root          90       2  0 Mar23 ?        00:00:00 [sdhci]
root          91       2  0 Mar23 ?        00:12:56 [irq/47-mmc0]
root          94       2  0 Mar23 ?        00:00:00 [scsi_eh_0]
root          95       2  0 Mar23 ?        00:00:00 [scsi_tmf_0]
root          96       2  0 Mar23 ?        00:00:05 [kworker/1:1H-kblockd]
root          97       2  0 Mar23 ?        00:00:01 [jbd2/sda2-8]
root          98       2  0 Mar23 ?        00:00:00 [ext4-rsv-conver]
root          99       2  0 Mar23 ?        00:00:00 [mld]
root         100       2  0 Mar23 ?        00:00:00 [ipv6_addrconf]
root         102       2  0 Mar23 ?        00:00:06 [kworker/2:1H-kblockd]
root         123       2  0 Mar23 ?        00:00:04 [kworker/3:1H-kblockd]
root         139       1  0 Mar23 ?        00:00:06 /lib/systemd/systemd-journald
root         165       1  0 Mar23 ?        00:00:01 /lib/systemd/systemd-udevd
root         198       2  0 Mar23 ?        00:00:00 [vchiq-keep/0]
root         204       2  0 Mar23 ?        00:00:00 [SMIO]
root         249       2  0 Mar23 ?        00:00:00 [v3d_bin]
root         250       2  0 Mar23 ?        00:00:00 [v3d_render]
root         251       2  0 Mar23 ?        00:00:00 [v3d_tfu]
root         252       2  0 Mar23 ?        00:00:00 [v3d_csd]
root         253       2  0 Mar23 ?        00:00:00 [v3d_cache_clean]
root         261       2  0 Mar23 ?        00:00:00 [cfg80211]
root         263       2  0 Mar23 ?        00:00:00 [irq/60-feb10000]
root         264       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         266       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         267       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         268       2  0 Mar23 ?        00:00:00 [brcmf_wq/mmc1:0]
root         269       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         270       2  0 Mar23 ?        00:00:00 [brcmf_wdog/mmc1]
root         271       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         272       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         275       2  0 Mar23 ?        00:00:00 [mmal-vchiq]
root         300       2  0 Mar23 ?        00:00:00 [irq/38-vc4 hdmi]
root         302       2  0 Mar23 ?        00:00:00 [irq/39-vc4 hdmi]
root         303       2  0 Mar23 ?        00:00:00 [cec-vc4]
root         304       2  0 Mar23 ?        00:00:00 [irq/35-vc4 hdmi]
root         305       2  0 Mar23 ?        00:00:00 [irq/34-vc4 hdmi]
root         307       2  0 Mar23 ?        00:00:00 [irq/44-vc4 hdmi]
root         308       2  0 Mar23 ?        00:00:00 [irq/45-vc4 hdmi]
root         311       2  0 Mar23 ?        00:00:00 [cec-vc4]
root         312       2  0 Mar23 ?        00:00:00 [irq/41-vc4 hdmi]
root         313       2  0 Mar23 ?        00:00:00 [irq/40-vc4 hdmi]
root         315       2  0 Mar23 ?        00:00:00 [card1-crtc0]
root         317       2  0 Mar23 ?        00:00:00 [card1-crtc1]
root         318       2  0 Mar23 ?        00:00:00 [card1-crtc2]
root         319       2  0 Mar23 ?        00:00:00 [card1-crtc3]
root         320       2  0 Mar23 ?        00:00:00 [card1-crtc4]
root         321       2  0 Mar23 ?        00:00:00 [card1-crtc5]
systemd+     355       1  0 Mar23 ?        00:00:01 /lib/systemd/systemd-timesyncd
avahi        387       1  0 Mar23 ?        00:01:02 avahi-daemon: running [raspberrypi.local]
root         388       1  0 Mar23 ?        00:00:00 /usr/sbin/cron -f
message+     389       1  0 Mar23 ?        00:00:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
avahi        392     387  0 Mar23 ?        00:00:00 avahi-daemon: chroot helper
root         412       1  0 Mar23 ?        00:00:01 /usr/sbin/rsyslogd -n -iNONE
root         431       1  0 Mar23 ?        00:00:01 /lib/systemd/systemd-logind
nobody       437       1  0 Mar23 ?        00:00:03 /usr/sbin/thd --triggers /etc/triggerhappy/triggers.d/ --socket /run/thd.socket --user nobody --deviceglob /dev/input/event*
root         446       1  0 Mar23 ?        00:00:01 /sbin/wpa_supplicant -u -s -O /run/wpa_supplicant
root         481       1  0 Mar23 ?        00:00:07 /usr/sbin/rngd -r /dev/hwrng
root         506       1  0 Mar23 tty1     00:00:00 /bin/login -f
root         511       1  0 Mar23 ?        00:00:00 sshd: /usr/sbin/sshd -D [listener] 0 of 10-100 startups
root         519       1  0 Mar23 ?        00:00:03 wpa_supplicant -B -c/etc/wpa_supplicant/wpa_supplicant.conf -iwlan0
root         533       1  0 Mar23 ?        00:00:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
www-data     534     533  0 Mar23 ?        00:00:00 nginx: worker process
www-data     535     533  0 Mar23 ?        00:00:00 nginx: worker process
www-data     536     533  0 Mar23 ?        00:00:00 nginx: worker process
www-data     537     533  0 Mar23 ?        00:00:00 nginx: worker process
pi           551       1  0 Mar23 ?        00:00:00 /lib/systemd/systemd --user
pi           552     551  0 Mar23 ?        00:00:00 (sd-pam)
pi           566     506  0 Mar23 tty1     00:00:00 -bash
root         586       1  0 Mar23 ?        00:00:00 /usr/bin/hciattach /dev/serial1 bcm43xx 3000000 flow -
root         587       2  0 Mar23 ?        00:00:00 [kworker/u9:2-hci0]
root         599       1  0 Mar23 ?        00:00:00 /usr/libexec/bluetooth/bluetoothd
root         666       1  0 Mar23 ?        00:00:01 /usr/sbin/dhcpcd -w -q
pi         26071     551  0 Mar24 ?        00:00:00 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
root      105163       2  0 19:58 ?        00:00:00 [kworker/u8:1-events_unbound]
root      107008     511  0 21:32 ?        00:00:00 sshd: pi [priv]
pi        107015  107008  0 21:32 ?        00:00:00 sshd: pi@pts/0
pi        107016  107015  0 21:32 pts/0    00:00:00 -bash
root      107901       2  0 21:39 ?        00:00:00 [kworker/u8:2-events_unbound]
pi        108023       1  3 21:41 ?        00:02:03 node-red
root      108302       2  0 21:56 ?        00:00:00 [kworker/3:0-mm_percpu_wq]
root      108562       2  0 22:17 ?        00:00:00 [kworker/0:1-events]
root      108574       2  0 22:18 ?        00:00:02 [kworker/1:4-mm_percpu_wq]
root      108714       2  0 22:29 ?        00:00:00 [kworker/0:2-events]
pi        108717  108023  0 22:29 ?        00:00:00 /bin/bash ./build.sh
pi        108745  108717  0 22:30 ?        00:00:00 /bin/bash /home/pi/Projects/moddable/build/bin/lin/release/mcconfig -d -x localhost:5004 -l -m -p esp32/wt32_eth01 -t xsbug
pi        108751  108745  0 22:30 ?        00:00:00 make -f /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/makefile xsbug
pi        108758  108751  0 22:30 ?        00:00:00 /bin/sh -c PORT_USED=$(grep 'Serial port' /home/pi/Projects/moddable/build/tmp/esp32/wt32_eth01/debug/t5rg16s07b/xsProj-esp32/flashOutput | awk '
pi        108762  108758  0 22:30 ?        00:00:00 node xsbug-log bash -c "XSBUG_PORT=5002 XSBUG_HOST=localhost serial2xsbug /dev/ttyUSB0 460800 8N1"
pi        108769  108762  0 22:30 ?        00:00:00 /bin/sh -c bash -c "XSBUG_PORT=5002 XSBUG_HOST=localhost serial2xsbug /dev/ttyUSB0 460800 8N1"
pi        108770  108769  0 22:30 ?        00:00:00 serial2xsbug /dev/ttyUSB0 460800 8N1
root      108808       2  0 22:33 ?        00:00:00 [kworker/1:2-mm_percpu_wq]
root      108812       2  0 22:33 ?        00:00:00 [kworker/3:2-mm_percpu_wq]
root      108817       2  0 22:33 ?        00:00:00 [kworker/2:0-events]
root      108870       2  0 22:38 ?        00:00:01 [kworker/1:0-events_power_efficient]
root      108882       2  0 22:39 ?        00:00:00 [kworker/2:1-mm_percpu_wq]
root      108910       2  0 22:41 ?        00:00:00 [kworker/u8:0-events_unbound]
root      108924       2  0 22:42 ?        00:00:00 [kworker/3:1-mm_percpu_wq]
root      108940       2  0 22:43 ?        00:00:00 [kworker/1:1-events_freezable]
pi        108964  107016  0 22:45 pts/0    00:00:00 ps -ef

Now you make me doubt again, whether I should have posted issue in the node-red-mcu-plugin repo (because I assume serial2xsbug is spawned by Ralphs sidebar?)...

phoddie commented 1 year ago

Thanks for looking into that. What you show is consistent with the problem. There's one serial port that is used for two different purposes:

When deploying, the ESP-IDF uses the serial port to install/flash the binary (using esptool)
When running, the Moddable SDK uses the serial port for debugging (using serial2xsbug) They cannot both run at the same time because they cannot share the port. When running manually from a single terminal console window, there's no chance of a conflict because you have to manually exit serial2xsbug with Control-C before starting another build.

ralphwetzel commented 1 year ago

Surprise ... for me: The deploy target doesn't terminate serial2xsbug ... as xsbug & all, the two other targets dealing with the serial connection, do!

deploy: 
    if ! test -e $(BIN_DIR)/xs_esp32.bin ; then (echo "Please build before deploy" && exit 1) fi
    @echo "# uploading to $(ESP32_SUBCLASS)"
    -cd $(PROJ_DIR) ; $(DEPLOY_CMD) | tee $(PROJ_DIR)/flashOutput

@phoddie: Do you intend to alter this ... or shall I ensure that serial2xsbug is stopped in that case?

phoddie commented 1 year ago

@ralphwetzel – Huh. I'm not sure what I expect here either. I'll check with the team here.

phoddie commented 1 year ago

After some discussion, the conclusion is to make the default behavior of the deploy, xsbug, and all targets to terminate serial2xsbug. This is a friendly default for the common situation of working with a single device. There were inconsistencies in how this was implemented for different MCUs (ESP8266, ESP32, Pico) and development hosts (macOS, Windows, Linux). These have been updated.

We have an idea for how to provide developers with control over this behavior, as it is not optimal for working with multiple devices. That will be a follow-on.

bartbutenaers commented 1 year ago

@phoddie,

I am going to close this issue, because it didn't occur anymore since I had installed SDK commit c43982f. Thanks again!!

Bart

phoddie / node-red-mcu

Device or resource busy: '/dev/ttyUSB0' #107