MULTI: Outgoing TUN queue full, dropped packet len

flyvert

Greetings! Long time user of OpenVPN, but my first post on this community.

My Raspberry PI and Debian Stretch based OpenVPN-server that has served me for over five years crashed the other month and I have now rebuilt it using Debian Buster (Linux 5.4.51+ #1333 Mon Aug 10 16:38:02 BST 2020 armv6l GNU/Linux) on the same hardware. I took opportunity to rebuild my PKI and CA with new Easy RSA certs and adopt the new AES-256-GCM cipher and refresh the VPN clients' software (Windows and MacOS).

TUN (routed) tunnels with Windows and MacOS works just fine! 8-)

TAP (bridged) tunnels with Windows 10 (build 1809) does not - the tunnel is negotiated but no traffic pass and the openvpn.log is flooded with "MULTI: Outgoing TUN queue full, dropped packet len" messages until I disconnect the client. :cry:

port 1194
proto tcp
dev tap
ca /etc/openvpn/myeasy-rsa/pki/ca.crt
cert /etc/openvpn/myeasy-rsa/pki/issued/SERVER.crt
key /etc/openvpn/myeasy-rsa/pki/private/SERVER.key
dh /etc/openvpn/myeasy-rsa/pki/dh.pem
server-bridge 10.0.0.40 255.255.255.0 10.0.0.41 10.0.0.49
ifconfig-pool-persist /var/log/openvpn/ipp.txt
push "route 10.0.10.0 255.255.255.0 10.0.0.1"
push "route 10.0.20.0 255.255.255.0 10.0.0.1"
push "route 10.0.30.0 255.255.255.0 10.0.0.1"
keepalive 10 120
tls-auth /etc/openvpn/myeasy-rsa/pki/private/ta.key 0
cipher AES-256-GCM
max-clients 9
user nobody
group nogroup
persist-key
persist-tun
status /var/log/openvpn/openvpn-status.log
log /var/log/openvpn/openvpn.log
verb 3

ETHERNET BRIDGE INTERFACE:

# cat /etc/network/interfaces
auto lo br0 eth0

iface lo inet loopback

iface br0 inet static
 address 10.0.0.40
 netmask 255.255.255.0
 gateway 10.0.0.2
 post-up route add -net 10.0.10.0/24 gw 10.0.0.1
 post-up route add -net 10.0.20.0/24 gw 10.0.0.1
 post-up route add -net 10.0.30.0/24 gw 10.0.0.1
 bridge_ports eth0 tap0
 pre-up openvpn --mktun --dev tap0
 post-down openvpn --rmtun --dev tap0

# brctl show br0
bridge name     bridge id               STP enabled     interfaces
br0             8000.ETH0MAC            no              eth0
                                                        tap0
                                                        
# ifconfig tap0
tap0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether BRIDGEMAC  txqueuelen 100  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

CLIENT LOG:

2020-09-30 08:14:29 OpenVPN 2.5_rc1 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Sep 21 2020
2020-09-30 08:14:29 Windows version 10.0 (Windows 10 or greater) 64bit
2020-09-30 08:14:29 library versions: OpenSSL 1.1.1g  21 Apr 2020, LZO 2.10
Enter Management Password:
2020-09-30 08:14:29 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
2020-09-30 08:14:29 Need hold release from management interface, waiting...
2020-09-30 08:14:29 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
2020-09-30 08:14:29 MANAGEMENT: CMD 'state on'
2020-09-30 08:14:29 MANAGEMENT: CMD 'log all on'
2020-09-30 08:14:29 MANAGEMENT: CMD 'echo all on'
2020-09-30 08:14:29 MANAGEMENT: CMD 'bytecount 5'
2020-09-30 08:14:29 MANAGEMENT: CMD 'hold off'
2020-09-30 08:14:29 MANAGEMENT: CMD 'hold release'
2020-09-30 08:14:29 MANAGEMENT: CMD 'proxy HTTP someproxy.tld proxyport'
2020-09-30 08:14:30 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2020-09-30 08:14:30 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2020-09-30 08:14:30 MANAGEMENT: >STATE:1601446470,RESOLVE,,,,,,
2020-09-30 08:14:30 TCP/UDP: Preserving recently used remote address: [AF_INET]client.proxy.public.ip:proxyport
2020-09-30 08:14:30 Socket Buffers: R=[65536->65536] S=[65536->65536]
2020-09-30 08:14:30 Attempting to establish TCP connection with [AF_INET]client.proxy.public.ip:proxyport [nonblock]
2020-09-30 08:14:30 MANAGEMENT: >STATE:1601446470,TCP_CONNECT,,,,,,
2020-09-30 08:14:31 TCP connection established with [AF_INET]client.proxy.public.ip:proxyport
2020-09-30 08:14:31 Send to HTTP proxy: 'CONNECT vpn.server.tld:serverport HTTP/1.0'
2020-09-30 08:14:31 Send to HTTP proxy: 'Host: vpn.server.tld'
2020-09-30 08:14:32 HTTP proxy returned: 'HTTP/1.1 200 Connection established'
2020-09-30 08:14:34 TCP_CLIENT link local: (not bound)
2020-09-30 08:14:34 TCP_CLIENT link remote: [AF_INET]client.proxy.public.ip:proxyport
2020-09-30 08:14:34 MANAGEMENT: >STATE:1601446474,WAIT,,,,,,
2020-09-30 08:14:34 MANAGEMENT: >STATE:1601446474,AUTH,,,,,,
2020-09-30 08:14:34 TLS: Initial packet from [AF_INET]client.proxy.public.ip:proxyport, sid=758942f6 aeff6c09
2020-09-30 08:14:34 VERIFY OK: depth=1, CN=MY CA
2020-09-30 08:14:34 VERIFY KU OK
2020-09-30 08:14:34 Validating certificate extended key usage
2020-09-30 08:14:34 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2020-09-30 08:14:34 VERIFY EKU OK
2020-09-30 08:14:34 VERIFY OK: depth=0, CN=MyServer
2020-09-30 08:14:34 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
2020-09-30 08:14:34 [MyServer] Peer Connection Initiated with [AF_INET]client.proxy.public.ip:proxyport
2020-09-30 08:14:35 MANAGEMENT: >STATE:1601446475,GET_CONFIG,,,,,,
2020-09-30 08:14:35 SENT CONTROL [MyServer]: 'PUSH_REQUEST' (status=1)
2020-09-30 08:14:35 PUSH: Received control message: 'PUSH_REPLY,route 10.0.10.0 255.255.255.0 10.0.0.1,route 10.0.20.0 255.255.255.0 10.0.0.1,route 10.0.30.0 255.255.255.0 10.0.0.1,route-gateway 10.0.0.40,ping 10,ping-restart 120,ifconfig 10.0.0.41 255.255.255.0,peer-id 0,cipher AES-256-GCM'
2020-09-30 08:14:35 OPTIONS IMPORT: timers and/or timeouts modified
2020-09-30 08:14:35 OPTIONS IMPORT: --ifconfig/up options modified
2020-09-30 08:14:35 OPTIONS IMPORT: route options modified
2020-09-30 08:14:35 OPTIONS IMPORT: route-related options modified
2020-09-30 08:14:35 OPTIONS IMPORT: peer-id set
2020-09-30 08:14:35 OPTIONS IMPORT: adjusting link_mtu to 1658
2020-09-30 08:14:35 OPTIONS IMPORT: data channel crypto options modified
2020-09-30 08:14:35 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-09-30 08:14:35 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-09-30 08:14:35 interactive service msg_channel=608
2020-09-30 08:14:35 ROUTE_GATEWAY router.ip/255.255.254.0 I=7 HWADDR=someMAC
2020-09-30 08:14:35 open_tun
2020-09-30 08:14:35 tap-windows6 device [TAP-Adapter] opened
2020-09-30 08:14:35 TAP-Windows Driver Version 9.24 
2020-09-30 08:14:35 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.0.0.41/255.255.255.0 on interface {BBC5CFE9-179A-4DAE-8CA6-7405CF2CC6A3} [DHCP-serv: 10.0.0.0, lease-time: 31536000]
2020-09-30 08:14:35 Successful ARP Flush on interface [26] {BBC5CFE9-179A-4DAE-8CA6-7405CF2CC6A3}
2020-09-30 08:14:35 MANAGEMENT: >STATE:1601446475,ASSIGN_IP,,10.0.0.41,,,,
2020-09-30 08:14:35 IPv4 MTU set to 1500 on interface 26 using service
2020-09-30 08:14:40 TEST ROUTES: 3/3 succeeded len=3 ret=1 a=0 u/d=up
2020-09-30 08:14:40 MANAGEMENT: >STATE:1601446480,ADD_ROUTES,,,,,,
2020-09-30 08:14:40 C:\WINDOWS\system32\route.exe ADD 10.0.10.0 MASK 255.255.255.0 10.0.0.1
2020-09-30 08:14:40 Route addition via service succeeded
2020-09-30 08:14:40 C:\WINDOWS\system32\route.exe ADD 10.0.20.0 MASK 255.255.255.0 10.0.0.1
2020-09-30 08:14:40 Route addition via service succeeded
2020-09-30 08:14:40 C:\WINDOWS\system32\route.exe ADD 10.0.30.0 MASK 255.255.255.0 10.0.0.1
2020-09-30 08:14:40 Route addition via service succeeded
2020-09-30 08:14:40 Initialization Sequence Completed
2020-09-30 08:14:40 MANAGEMENT: >STATE:1601446480,CONNECTED,SUCCESS,10.0.0.41,client.proxy.public.ip,proxyport,router.ip,64676

SERVER LOG:

Wen Sep 30 08:08:02 2020 TCP connection established with [AF_INET]clients.proxy.public.ip:15393
Wed Sep 30 08:08:04 2020 clients.proxy.public.ip:15393 TLS: Initial packet from [AF_INET]clients.proxy.public.ip:15393, sid=4d8fc061 89ba1885
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 VERIFY OK: depth=1, CN=MY CA
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 VERIFY OK: depth=0, CN=CLIENTNAME
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_VER=2.5_rc1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_PLAT=win
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_PROTO=6
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_NCP=2
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_LZ4=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_LZ4v2=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_LZO=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_COMP_STUB=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_COMP_STUBv2=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_TCPNL=1
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 peer info: IV_GUI_VER=OpenVPN_GUI_11
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Wed Sep 30 08:08:05 2020 clients.proxy.public.ip:15393 [CLIENTNAME] Peer Connection Initiated with [AF_INET]clients.proxy.public.ip:15393
Wed Sep 30 08:08:05 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI_sva: pool returned IPv4=10.0.0.41, IPv6=(Not enabled)
Wed Sep 30 08:08:06 2020 CLIENTNAME/clients.proxy.public.ip:15393 PUSH: Received control message: 'PUSH_REQUEST'
Wed Sep 30 08:08:06 2020 CLIENTNAME/clients.proxy.public.ip:15393 SENT CONTROL [CLIENTNAME]: 'PUSH_REPLY,route 10.0.10.0 255.255.255.0 10.0.0.1,route 10.0.20.0 255.255.255.0 10.0.0.1,route 10.0.30.0 255.255.255.0 10.0.0.1,route-gateway 10.0.0.40,ping 10,ping-restart 120,ifconfig 10.0.0.41 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
Wed Sep 30 08:08:06 2020 CLIENTNAME/clients.proxy.public.ip:15393 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Sep 30 08:08:06 2020 CLIENTNAME/clients.proxy.public.ip:15393 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Sep 30 08:08:06 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI: Learn: CLIENTTAPMAC -> CLIENTNAME/clients.proxy.public.ip:15393
Wed Sep 30 08:08:07 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI: Outgoing TUN queue full, dropped packet len=42
Wed Sep 30 08:08:07 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI: Outgoing TUN queue full ...
Wed Sep 30 08:08:07 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI: Outgoing TUN queue full ...
Wed Sep 30 08:08:07 2020 CLIENTNAME/clients.proxy.public.ip:15393 MULTI: Outgoing TUN queue full ...

Have I made any mistake?

I've searched Internet and seen others struck by the same error messages, but not come across any remedy...

Please help me.

flyvert

Anyone, please?

What is going on? The server is trying to send some bytes to the client, but it looks like it times out after waiting a whole second in some I assume write() call (see red color)

Mon Oct 5 00:24:52 2020 us=975901 STREAM: SET NEXT, buf=[572,0] next=[572,1658] len=-1 maxlen=1658
Mon Oct 5 00:24:52 2020 us=976140 MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_TUN_WRITE
Mon Oct 5 00:24:52 2020 us=976374 MULTI TCP: multi_tcp_action a=TA_TUN_WRITE p=1
Mon Oct 5 00:24:52 2020 us=976740 MULTI TCP: multi_tcp_wait_lite a=TA_TUN_WRITE mi=0x01581d68
Mon Oct 5 00:24:52 2020 us=976996 PO_CTL rwflags=0x0000 ev=8 arg=0x000bc0ec
Mon Oct 5 00:24:52 2020 us=977233 PO_CTL rwflags=0x0002 ev=5 arg=0x000bc050
Mon Oct 5 00:24:52 2020 us=977496 I/O WAIT Tr|TW|Sr|Sw [1/0]
Mon Oct 5 00:24:53 2020 us=979600 event_wait returned 0
Mon Oct 5 00:24:53 2020 us=984284 I/O WAIT status=0x0020
Mon Oct 5 00:24:53 2020 us=985592 MULTI TCP: multi_tcp_dispatch a=TA_TUN_WRITE_TIMEOUT mi=0x01581d68
Mon Oct 5 00:24:53 2020 us=985853 CLIENTNAME/CLIUENTIP:58511 MULTI: Outgoing TUN queue full, dropped packet len=54

flyvert

Solved!!!

I found @chameleon's example (https://forums.openvpn.net/viewtopic.php?f=7&t=30633).

I got my bridged tunnel working by replacing the below in /etc/network/interfaces:
bridge_ports eth0 tap0
pre-up openvpn --mktun --dev tap0
post-down openvpn --rmtun --dev tap0

with just as single line (create a br0 bridge device containing only eth0):
bridge_ports eth0

*AND* adding an openvpn "up" script that adds tap0 to the br0 bridge when the time is ripe:
script-security 2
up openvpn_up

The up script is identical to the one @chameleon posted.
#!/bin/bash
brctl addif br0 $1
ifconfig $1 up

I guess earlier builds of openvpn accepted creation of bridges and adding bridge devices from /etc/network/interfaces while the current build does not.

@chameleon: thanks a bunch for providing useful examples!