GS service keeps terminating

[Szczempus]

Hello guys. Recently I have come up with a problem of constalty terminatign GS service on AC180 modem. What is strange ths is not the first drone which runnig a given software and hardware configuration and all previous ones was working just fine. On GS and Drone side there are jetson nanos properly configured.

Compiled driver version: v5.6.4.2_35491.20191025
Wifibroadcast app version: 21.8.27.56115-1

Output from drone:

2024-06-24 09:17:06+0000 [-] Log opened.
2024-06-24 09:17:06+0000 [-] # iw reg set BO
2024-06-24 09:17:06+0000 [-] # ifconfig rtl8812au down
2024-06-24 09:17:06+0000 [-] # iw dev rtl8812au set monitor otherbss
2024-06-24 09:17:06+0000 [-] # ifconfig rtl8812au up
2024-06-24 09:17:06+0000 [-] # iw dev rtl8812au set channel 165 HT20
2024-06-24 09:17:06+0000 [-] Listen for telem stream 1(RX), 2(TX) on 0.0.0.0:14550
2024-06-24 09:17:06+0000 [-] UDPProxyProtocol starting on 14550
2024-06-24 09:17:06+0000 [-] UDPProxyProtocol starting on 14700
2024-06-24 09:17:06+0000 [-] UDPProxyProtocol starting on 56598
2024-06-24 09:17:06+0000 [-] Telem RX: /usr/bin/wfb_rx -p 1 -u 14700 -K /etc/drone.key -k 1 -n 2 rtl8812au
2024-06-24 09:17:06+0000 [-] Telem TX: /usr/bin/wfb_tx -p 2 -u 14701 -K /etc/drone.key -B 20 -G long -S 1 -L 0 -M 1 -k 1 -n 2 -T 0 rtl8812au
2024-06-24 09:17:06+0000 [-] Started telem rx
2024-06-24 09:17:06+0000 [-] Started telem tx
2024-06-24 09:17:06+0000 [-] Listen for video stream 3 on 0.0.0.0:10000
2024-06-24 09:17:06+0000 [-] Started video tx
2024-06-24 09:17:06+0000 [-] Video: /usr/bin/wfb_tx -p 3 -u 10000 -K /etc/drone.key -B 20 -G long -S 1 -L 0 -M 1 -k 8 -n 12 -T 0 rtl8812au
2024-06-24 09:17:06+0000 [-] UDPProxyProtocol starting on 14900
2024-06-24 09:17:06+0000 [-] UDPProxyProtocol starting on 51082
2024-06-24 09:17:06+0000 [-] Tunnel RX: /usr/bin/wfb_rx -p 4 -u 14900 -K /etc/drone.key -k 1 -n 2 rtl8812au
2024-06-24 09:17:06+0000 [-] Tunnel TX: /usr/bin/wfb_tx -p 5 -u 14901 -K /etc/drone.key -B 20 -G long -S 1 -L 0 -M 1 -k 1 -n 2 -T 0 rtl8812au
2024-06-24 09:17:06+0000 [-] Started tunnel rx
2024-06-24 09:17:06+0000 [-] Started tunnel tx
2024-06-24 09:17:06+0000 [-] telem tx: Listen on 14701 for rtl8812au
2024-06-24 09:17:06+0000 [-] video tx: Listen on 10000 for rtl8812au
2024-06-24 09:17:06+0000 [-] telem rx: rtl8812au has DLT_IEEE802_11_RADIO Encap
2024-06-24 09:17:06+0000 [-] tunnel tx: Listen on 14901 for rtl8812au
2024-06-24 09:17:07+0000 [-] tunnel rx: rtl8812au has DLT_IEEE802_11_RADIO Encap
2024-06-24 09:17:35+0000 [-] telem rx: New session detected
2024-06-24 09:17:35+0000 [-] tunnel rx: New session detected
2024-06-24 09:17:50+0000 [-] telem rx: New session detected
2024-06-24 09:18:16+0000 [-] telem rx: New session detected
2024-06-24 09:18:25+0000 [-] telem rx: New session detected
2024-06-24 09:18:26+0000 [-] tunnel rx: unable to decrypt packet #0x0
2024-06-24 09:18:26+0000 [-] tunnel rx: unable to decrypt packet #0x1
2024-06-24 09:18:27+0000 [-] tunnel rx: unable to decrypt packet #0x100
2024-06-24 09:18:27+0000 [-] tunnel rx: unable to decrypt packet #0x101
2024-06-24 09:18:28+0000 [-] tunnel rx: New session detected
2024-06-24 09:18:28+0000 [-] tunnel rx: 1 packets lost
2024-06-24 09:18:58+0000 [-] telem rx: New session detected
2024-06-24 09:18:59+0000 [-] tunnel rx: New session detected
2024-06-24 09:19:15+0000 [-] telem rx: New session detected
2024-06-24 09:19:15+0000 [-] tunnel rx: New session detected
2024-06-24 09:19:31+0000 [-] telem rx: New session detected
2024-06-24 09:19:32+0000 [-] tunnel rx: New session detected
2024-06-24 09:19:47+0000 [-] telem rx: New session detected
2024-06-24 09:19:48+0000 [-] tunnel rx: New session detected

Drone config

[common]
mavlink_agg_timeout=0.05
wifi_channel=169
wifi_region='BO'

[drone_mavlink]
%23%20peer='connect:https://127.0.0.1:14550'  # outgoing connection
peer='listen:https://0.0.0.0:14550'   # incoming connection

[drone_video]
peer='listen:https://0.0.0.0:10000'  # listen for video stream (gstreamer on drone) up

Output from GS

un 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Log opened.
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] # iw reg set BO
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] # ifconfig rtl8812au down
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] # iw dev rtl8812au set monitor otherbss
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] # ifconfig rtl8812au up
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] # iw dev rtl8812au set channel 169 HT20
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Connect telem stream 2(RX), 1(TX) to 127.0.0.1:14550
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] UDPProxyProtocol starting on 50397
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] UDPProxyProtocol starting on 14600
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] UDPProxyProtocol starting on 41543
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Telem RX: /usr/bin/wfb_rx -p 2 -u 14600 -K /etc/gs.key -k 1 -n 2 rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Telem TX: /usr/bin/wfb_tx -p 1 -u 14601 -K /etc/gs.key -B 20 -G long -S 1 -L 0 -M 1 -k 1 -n 2 -T 0 rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] AntennaFactory starting on 8001
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Started telem rx
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Started telem tx
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Send video stream 3 to 127.0.0.1:10000
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] AntennaFactory starting on 8002
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Started video rx
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Video: /usr/bin/wfb_rx -p 3 -c 127.0.0.1 -u 10000 -K /etc/gs.key -k 8 -n 12 rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] UDPProxyProtocol starting on 14800
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] UDPProxyProtocol starting on 33005
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Tunnel RX: /usr/bin/wfb_rx -p 5 -u 14800 -K /etc/gs.key -k 1 -n 2 rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Tunnel TX: /usr/bin/wfb_tx -p 4 -u 14801 -K /etc/gs.key -B 20 -G long -S 1 -L 0 -M 1 -k 1 -n 2 -T 0 rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] AntennaFactory starting on 8003
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Started tunnel rx
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] Started tunnel tx
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] telem rx: rtl8812au has DLT_IEEE802_11_RADIO Encap
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] telem tx: Listen on 14601 for rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: rtl8812au has DLT_IEEE802_11_RADIO Encap
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7504
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7505
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7506
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] tunnel tx: Listen on 14801 for rtl8812au
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] tunnel rx: rtl8812au has DLT_IEEE802_11_RADIO Encap
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7507
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7508
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7509
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd750a
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd750b
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7600
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7601
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] telem rx: New session detected
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] telem rx: 3927 packets lost
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7602
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7603
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7604
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: unable to decrypt packet #0xd7605
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] video rx: New session detected
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] tunnel rx: unable to decrypt packet #0x39900
Jun 24 10:02:55 gs wfb-server[3982]: 2024-06-24 10:02:55+0000 [-] tunnel rx: unable to decrypt packet #0x39901
Jun 24 10:02:56 gs wfb-server[3982]: 2024-06-24 10:02:56+0000 [-] video rx: 27573 packets lost
Jun 24 10:02:56 gs wfb-server[3982]: 2024-06-24 10:02:56+0000 [-] tunnel rx: New session detected
Jun 24 10:02:56 gs wfb-server[3982]: 2024-06-24 10:02:56+0000 [-] tunnel rx: 921 packets lost
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] tunnel rx: Error: socket error!
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] video rx: Error: socket error!
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] telem rx: Error: socket error!
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Stopped RX tunnel rx with code 1
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Stopping reactor due to fatal error: A process has ended with a probable error condition: process ended with exit code 1.
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] (UDP Port 14800 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] (UDP Port 33005 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [telemetry.server.AntennaFactory] (TCP Port 8002 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [UDPProxyProtocol (UDP)] (UDP Port 50397 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [telemetry.server.AntennaFactory] (TCP Port 8003 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Stopped RX video rx with code 1
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Stopped RX telem rx with code 1
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled error in Deferred:
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled Error
Jun 24 10:03:03 gs wfb-server[3982]:         Traceback (most recent call last):
Jun 24 10:03:03 gs wfb-server[3982]:         Failure: twisted.internet.error.ProcessTerminated: A process has ended with a probable error condition: process ended with exit code 1.
Jun 24 10:03:03 gs wfb-server[3982]:         
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [UDPProxyProtocol (UDP)] (UDP Port 14600 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [UDPProxyProtocol (UDP)] (UDP Port 41543 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [telemetry.server.AntennaFactory] (TCP Port 8001 Closed)
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Stopped TX telem tx with code 1
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled error in Deferred:
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled Error
Jun 24 10:03:03 gs wfb-server[3982]:         Traceback (most recent call last):
Jun 24 10:03:03 gs wfb-server[3982]:         Failure: twisted.internet.error.ProcessTerminated: A process has ended with a probable error condition: process ended with exit code 1.
Jun 24 10:03:03 gs wfb-server[3982]:         
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Main loop terminated.
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Exiting with code 1
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled error in Deferred:
Jun 24 10:03:03 gs wfb-server[3982]: 2024-06-24 10:03:03+0000 [-] Unhandled Error
Jun 24 10:03:03 gs wfb-server[3982]:         Traceback (most recent call last):
Jun 24 10:03:03 gs wfb-server[3982]:         Failure: twisted.internet.error.ProcessTerminated: A process has ended with a probable error condition: process ended with exit code 1.
Jun 24 10:03:03 gs wfb-server[3982]:

GS config

[common]
mavlink_agg_timeout=0.05
wifi_channel=169
wifi_region='BO'

[gs_mavlink]
%23%20peer='listen:https://0.0.0.0:14550'   # incoming connection
peer='connect:https://127.0.0.1:14550'  # outgoing connection

[gs_video]
peer='connect:https://127.0.0.1:10000'  # outgoing connection for

Do you have any ideas why this is happening?

[svpcom]

See dmesg output. It seems that your card is underpowered and disconnects from usb bus under load

[Szczempus]

On the dmesg output there are no USB power-related errors. I will try to solder my board connections to a separate 5V buck converter and will see if this works.

Dmesg output:

[  +0.117882] usb 1-2.4: new high-speed USB device number 4 using tegra-xusb
[  +0.021029] usb 1-2.4: New USB device found, idVendor=0bda, idProduct=881a
[  +0.000005] usb 1-2.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  +0.000003] usb 1-2.4: Product: 802.11n NIC
[  +0.000004] usb 1-2.4: Manufacturer: Realtek
...
[  +0.030527] 88XXau: loading out-of-tree module taints kernel.
[  +0.011896] smsc95xx v1.0.5
[  +0.076641] smsc95xx 1-3.2:1.0 eth1: register 'smsc95xx' at usb-70090000.xusb-3.2, smsc95xx USB 2.0 Ethernet, 2a:eb:31:06:d8:99
[  +0.000058] usbcore: registered new interface driver smsc95xx
[  +0.005122] smsc95xx 1-3.2:1.0 eth-lan: renamed from eth1
[  +0.281298] usb 1-2.4: 88XXau fc:a3:86:0e:07:da hw_info[d7]
[  +0.002495] usbcore: registered new interface driver rtl88XXau
[  +0.003751] rtl88XXau 1-2.4:1.0 rtl8812au: renamed from wlan0
...
[  +0.999023] tegra-xusb 70090000.xusb: Upgrade port 0 to USB3.0
[  +0.000006] tegra-xusb 70090000.xusb: Upgrade port 1 to USB3.0
[  +0.236904] device rtl8812au entered promiscuous mode
[  +0.077514] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
[  +0.010244] usb 2-1: new SuperSpeed USB device number 2 using tegra-xusb
[  +0.027435] usb 2-1: New USB device found, idVendor=0424, idProduct=5744
[  +0.000007] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=0
[  +0.000003] usb 2-1: Product: USB5744
[  +0.000004] usb 2-1: Manufacturer: Microchip Tech
[  +0.000957] hub 2-1:1.0: USB hub found
[  +0.000080] hub 2-1:1.0: 4 ports detected
[  +0.150494] usb 2-1: usb_suspend_both: status 0
[  +0.000147] usb usb2: usb_suspend_both: status 0
[Jun24 11:45] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.389279] device rtl8812au left promiscuous mode
[  +0.607677] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready
[  +4.196026] device rtl8812au entered promiscuous mode
[  +2.326896] device rtl8812au left promiscuous mode
[  +0.036892] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.100254] device rtl8812au entered promiscuous mode
[  +0.895946] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready
[  +6.461574] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.406786] device rtl8812au left promiscuous mode
[  +0.587620] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready
[  +4.188117] device rtl8812au entered promiscuous mode
[  +2.343003] device rtl8812au left promiscuous mode
[  +0.047299] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.073688] device rtl8812au entered promiscuous mode
[  +0.899893] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready
[  +6.456549] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.411620] device rtl8812au left promiscuous mode
[  +0.583829] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready
[  +4.184055] device rtl8812au entered promiscuous mode
[  +2.334766] device rtl8812au left promiscuous mode
[  +0.040471] IPv6: ADDRCONF(NETDEV_UP): rtl8812au: link is not ready
[  +0.104741] device rtl8812au entered promiscuous mode
[  +0.855973] IPv6: ADDRCONF(NETDEV_CHANGE): rtl8812au: link becomes ready

[svpcom]

Check that wpa_supplicant, dhclient, etc was disabled

[Szczempus]

Yup they are disabled.

[Szczempus]

Resoldering connections of wifi card to 5V 5A buck converter didn't help

[Szczempus]

Okay, this is probably a Jetson Nano related problem. After reflashing rootfs on SBC and reinstalling everything, wifibroadcast started functioning normally.