opening serial port hangs the app

xchetah commented 1 year ago

hello I'm on ubuntu and using multiwii , when I click connect the app hangs , unless I open the port first with another app , like multiwiiconf , or just putty , or any app that use the serial port. then I can connect without problems , but disconnecting then connecting brings this problem back. using multiwii 2.4 on arduino mega (mini) ch340 usb to serial, connected directly through usb cable. the log shows nothing it freezes as the app hangs. any help is apreciated Thanks.

stronnag commented 1 year ago

Receiving help requires logs.

Please provide:

The complete mwp "stderr" log
A directory listing for the device (ls -l /dev/ttyXXn) where ttyXXn represents the device node.
The output of dmesg -H -T from when the device is recognised by the system until mwp hangs.

For the record, mwp works with my MW 2.4 Mega baord, albeit a 2013 model with FTDI USB, e.g:

[Sun Jun  4 07:44:56 2023] usb 3-4.3: new full-speed USB device number 35 using xhci_hcd
[Sun Jun  4 07:44:56 2023] usb 3-4.3: New USB device found, idVendor=0403, idProduct=6001, bcdDevice= 6.00
[Sun Jun  4 07:44:56 2023] usb 3-4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Sun Jun  4 07:44:56 2023] usb 3-4.3: Product: FT232R USB UART
[Sun Jun  4 07:44:56 2023] usb 3-4.3: Manufacturer: FTDI
[Sun Jun  4 07:44:56 2023] usb 3-4.3: SerialNumber: A801WYVK
[Sun Jun  4 07:44:57 2023] usbcore: registered new interface driver ftdi_sio
[Sun Jun  4 07:44:57 2023] usbserial: USB Serial support registered for FTDI USB Serial Device
[Sun Jun  4 07:44:57 2023] ftdi_sio 3-4.3:1.0: FTDI USB Serial Device converter detected
[Sun Jun  4 07:44:57 2023] usb 3-4.3: Detected FT232R
[Sun Jun  4 07:44:57 2023] usb 3-4.3: FTDI USB Serial Device converter now attached to ttyUSB0

and

07:45:03.838956 buildinfo: 2023-05-25T19:50:16Z Linux 6.3.4-zen1-1-zen x86_64 eeyore
07:45:03.838969 toolinfo: gcc version 13.1.1 20230429 (GCC)  / GNU ld (GNU Binutils) 2.40.0 / Vala 0.56.8
07:45:03.838975 version: mwp 5067c15d (development) / 2023-05-20T13:19:59+01:00 6.133.645
07:45:03.839025 "Arch Linux" on eeyore running Linux 6.3.5-zen1-1-zen x86_64
07:45:03.839032 WM: XWayland / gnome
07:45:03.839038 GL: Intel / Mesa Intel(R) HD Graphics 4600 (HSW GT2)
07:45:03.849370 hypervisor: none
07:45:03.849421 GLib2 2.76.3 (dock fallback)
07:45:03.849432 MQTT enabled via the "paho" library
07:45:03.869889 Using fl2ltm 1.0.13 commit:9d6a99c
07:45:03.921896 Using speech api 1 [espeak]
07:45:03.924090 Get map preference
07:45:04.240801 Starting Bing proxy 
07:45:04.446822 External proxy "gmproxy" listening on :36005
07:45:04.457288 External proxy "bproxy" listening on :44853
07:45:04.471613 BB load async map zoom : true
07:45:04.485905 Loaded /home/jrh/.config/mwp/vcols.css
07:45:04.488366 Fixed font true
07:45:04.497639 Delta speed 2.000000
07:45:04.512422 Registered serial device: /dev/ttyUSB0 [0403:6001], Vendor: FTDI, Model: FT232R_USB_UART, Serial: A801WYVK, Driver: ftdi_sio
07:45:04.515611 Show main window
07:45:04.592242 Enabled mag anomaly checking 45⁰, 3s
07:45:04.596247 Host power: 0%, state: Unknown (0), warn: None (1)
07:45:04.596279 mwp will manage power and screen saver / idle
07:45:09.667785 Try connect /dev/ttyUSB0
07:45:09.667994 Connected /dev/ttyUSB0 false
07:45:09.668372 Serial ready
07:45:10.656137 MSP Timeout 10 0 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:11.661553 MSP Timeout 20 10 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:12.664842 MSP Timeout 30 20 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:13.667660 MSP Timeout 40 30 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:14.671773 MSP Timeout 50 40 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:15.675810 MSP Timeout 60 50 0 (MSP_CMDS_IDENT MWP_SERSTATE_NORMAL)
07:45:16.106113 set mrtype=3 cap =10
07:45:16.134094 MSP Error: MSP_CMDS_API_VERSION[1] 
07:45:16.158114 Generate navconf 7 false
07:45:16.158208 Masks arm=1 angle=2 horz=4 ph=40 rth=20 wp=100 cr=0 fs=0
07:45:16.190116 Sensors: Acc Baro Mag GPS  (000f)
07:45:16.190163 MWvers v241 Nav Pr 0 QUADX
07:45:16.190178 switch val == 0000001c (00000006)
07:45:16.190184 init icon 3 8 3 (false)
07:45:16.191464 Timer cycle for 8 items, 48 => 109 bytes
07:45:16.191476 Start poller

xchetah commented 1 year ago

dmesg -H -T

[Sun Jun  4 10:51:13 2023] usb 1-1: new full-speed USB device number 6 using xh>
[Sun Jun  4 10:51:13 2023] usb 1-1: New USB device found, idVendor=1a86, idProd>
[Sun Jun  4 10:51:13 2023] usb 1-1: New USB device strings: Mfr=0, Product=2, S>
[Sun Jun  4 10:51:13 2023] usb 1-1: Product: USB Serial
[Sun Jun  4 10:51:13 2023] ch341 1-1:1.0: ch341-uart converter detected
[Sun Jun  4 10:51:14 2023] usb 1-1: ch341-uart converter now attached to ttyUSB0
[Sun Jun  4 10:51:57 2023] usb 1-1: USB disconnect, device number 6
[Sun Jun  4 10:51:57 2023] ch341-uart ttyUSB0: ch341-uart converter now disconn>
[Sun Jun  4 10:51:57 2023] ch341 1-1:1.0: device disconnected
[Sun Jun  4 10:52:02 2023] usb 1-1: new full-speed USB device number 7 using xh>
[Sun Jun  4 10:52:03 2023] usb 1-1: New USB device found, idVendor=1a86, idProd>
[Sun Jun  4 10:52:03 2023] usb 1-1: New USB device strings: Mfr=0, Product=2, S>
[Sun Jun  4 10:52:03 2023] usb 1-1: Product: USB Serial
[Sun Jun  4 10:52:03 2023] ch341 1-1:1.0: ch341-uart converter detected
[Sun Jun  4 10:52:03 2023] usb 1-1: ch341-uart converter now attached to ttyUSB0

mwp stderr

2023-06-04T10:54:32+0300 mwp 
2023-06-04T10:54:32+0300 buildinfo: 2023-05-13T17:59:36Z Linux 6.3.2-zen1-1-zen x86_64 buster
2023-06-04T10:54:32+0300 toolinfo: gcc version 8.3.0 (Debian 8.3.0-6)  / GNU ld (GNU Binutils for Debian) 2.31.1 / Vala 0.42.5
2023-06-04T10:54:32+0300 version: mwp d2015f92 () / 2023-05-13T18:56:58+01:00 6.133.645
2023-06-04T10:54:32+0300 "Ubuntu 22.04.2 LTS" on IdeaPad-L3 running Linux 5.15.0-73-generic x86_64
2023-06-04T10:54:32+0300 WM: XWayland / ubuntu-wayland
2023-06-04T10:54:32+0300 GL: Intel / Mesa Intel(R) UHD Graphics (CML GT2)
2023-06-04T10:54:32+0300 hypervisor: none
2023-06-04T10:54:32+0300 GLib2 2.72
2023-06-04T10:54:32+0300 MQTT enabled via the "mosquitto" library
2023-06-04T10:54:32+0300 Failed to find "blackbox_decode" on PATH
2023-06-04T10:54:32+0300 Failed to find "gnuplot" on PATH
2023-06-04T10:54:32+0300 Failed to find "fl2ltm" on PATH
2023-06-04T10:54:32+0300 Failed to find "mavlogdump.py" on PATH
2023-06-04T10:54:32+0300 Using speech api 1 [espeak]
2023-06-04T10:54:32+0300 Get map preference
2023-06-04T10:54:33+0300 Starting Bing proxy 
2023-06-04T10:54:33+0300 BB load async map zoom : true
2023-06-04T10:54:33+0300 Loaded /usr/share/mwp/vcols.css
2023-06-04T10:54:33+0300 Fixed font true
2023-06-04T10:54:33+0300 Delta speed 0.000000
2023-06-04T10:54:33+0300 Registered serial device: /dev/ttyUSB0 [1a86:7523], Vendor: 1a86, Model: USB_Serial, Serial: (null), Driver: ch341
2023-06-04T10:54:33+0300 Show main window
2023-06-04T10:54:33+0300 Host power: 54%, state: Charging (1), warn: None (1)
2023-06-04T10:54:33+0300 GST: "init" <Integrated Camera: Integrated C> </dev/video0>

$ ls -l /dev/ttyUSB0 
crw-rw----+ 1 root dialout 188, 0 Jun  4 10:53 /dev/ttyUSB0

I want to re clarify :

if I connect the cable then open mwp and connect , it connects perfectly , but if I hit disconnect , then connect again it hangs.
closing mwp and reopening it does not connect and hangs on "connect"
the simple solution is to open another app before mwp, lets say putty , and opening the port, closing putty , opening mwp and connecting ,it does connect after this.
it's an arduino mega pro (mini) (cheap chinese clone I guess with ch340)

stronnag commented 1 year ago

It would have been useful to see the whole mwp log (including the successful connect / disconnect). However, it would appear that this problem is because it's a "cheap chinese clone I guess with ch340" and there is a driver / hardware problem.

I can connect / disconnect as much as I want using my anciient / original FTDI Mega, either from a physical (Arch) host or a Ubuntu 22.04 VM.
From the log, it would appear that mwp calls the OS libc open function, which never returns, indicating on OS / driver / hardware issue.

In fact I can reproduce the "hang" by an act of stupidity .... I have a BT device node /dev/rfcomm3 but the BT serial is not powered. The OS will try open() as the device node exists, but as the device is "dead", it hangs in open().

This is somewhat difficult to handle in an event driven UI which must also handle slow but valid devices (the same BT serial when powered). So I'm not sure I will spend much time on it, because these are both edge cases (broken hardware, wanton stupidity) and any solution might be (a) difficult and (b) have undesirable side effects.

stronnag commented 1 year ago

To my surprise, adding O_NDELAY to the OS open appears not to have much bad affects (the slow BT device for the real open case may retry a few messages).

There 's a serial_nonblock branch in the repo if you want to try it. I expect that in the "broken hardware" case, it will automagically disconnect rather than blocking.

stronnag commented 1 year ago

mwptools_6.133.645_amd64.deb.gz (Due to github's stupid policy, you'll have to first gunzip the file.)

xchetah commented 1 year ago

it's working perfectly now , thanks alot , I also noticed two improvements:

less cpu usage or io , I only monitored the cpu temperature , it used to go full to 95 degrees C , now it barely go to 80 sometimes.
data updates are being displaying faster ( higher refresh rate of location data) . I have another question , should I ask here or open new issue?

stronnag commented 1 year ago

I have another question , should I ask here or open new issue?

New discussion or issue please.

stronnag commented 1 year ago

Closing, as fix identified.

stronnag / mwptools

opening serial port hangs the app #145