TLS key negotiation failed to occur within 60 seconds

Given: a virtual server in google. cloud on ubuntu. In it, I try to raise the OpenVPN server. It seems that everything is configured, but when I try to connect from the client, I get the error

TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Google says this error is a crooked brandmower. But I seem to have specified everything. The question is where to dig and what am I doing wrong?

Full log the client

Mon May 22 00:07:15 2017 OpenVPN 2.4.2 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on May 11 2017
Mon May 22 00:07:15 2017 Windows version 6.2 (Windows 8 or greater) 64bit
Mon May 22 00:07:15 2017 library versions: OpenSSL 1.0.2k 26 Jan 2017, LZO 2.10
Enter Management Password:
Mon May 22 00:07:15 2017 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Mon May 22 00:07:15 2017 Need hold release from management interface, waiting...
Mon May 22 00:07:16 2017 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Mon May 22 00:07:16 2017 MANAGEMENT: CMD 'state on'
Mon May 22 00:07:16 2017 MANAGEMENT: CMD 'log all on'
Mon May 22 00:07:16 2017 MANAGEMENT: CMD 'echo all on'
Mon May 22 00:07:16 2017 MANAGEMENT: CMD 'hold off'
Mon May 22 00:07:16 2017 MANAGEMENT: CMD 'hold release'
Mon May 22 00:07:17 2017 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon May 22 00:07:17 2017 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon May 22 00:07:17 2017 TCP/UDP: Preserving recently used remote address: [AF_INET]ХХХ.ХХХ.ХХХ.ХХХ:3000
Mon May 22 00:07:17 2017 Socket Buffers: R=[65536->65536] S=[65536->65536]
Mon May 22 00:07:17 2017 UDP link local: (not bound)
Mon May 22 00:07:17 2017 UDP link remote: [AF_INET]ХХХ.ХХХ.ХХХ.ХХХ:3000
Mon May 22 00:07:17 2017 MANAGEMENT: >STATE:1495400837,WAIT,,,,,,
Mon May 22 00:08:17 2017 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon May 22 00:08:17 2017 TLS Error: TLS handshake failed
Mon May 22 00:08:17 2017 SIGUSR1[soft,tls-error] received, process restarting
Mon May 22 00:08:17 2017 MANAGEMENT: >STATE:1495400897,RECONNECTING,tls-error,,,,,
Mon May 22 00:08:17 2017 Restart pause, 5 second(s)

Full server log

Mon May 22 00:05:32 2017 us=569158 Current Parameter Settings:
Mon May 22 00:05:32 2017 us=569184 config = '/etc/openvpn/server.conf'
Mon May 22 00:05:32 2017 us=569190 mode = 1
Mon May 22 00:05:32 2017 us=569194 persist_config = DISABLED
Mon May 22 00:05:32 2017 us=569197 persist_mode = 1
Mon May 22 00:05:32 2017 us=569201 show_ciphers = DISABLED
Mon May 22 00:05:32 2017 us=569204 show_digests = DISABLED
Mon May 22 00:05:32 2017 us=569207 show_engines = DISABLED
Mon May 22 00:05:32 2017 us=569210 genkey = DISABLED
Mon May 22 00:05:32 2017 us=569213 key_pass_file = '[UNDEF]'
Mon May 22 00:05:32 2017 us=569216 NOTE: --mute triggered...
Mon May 22 00:05:32 2017 us=569227 278 variation(s) on previous 10 message(s) suppressed by --mute
Mon May 22 00:05:32 2017 us=569231 OpenVPN 2.4.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on May 10 2017
Mon May 22 00:05:32 2017 us=569237 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Mon May 22 00:05:32 2017 us=570878 PKCS#11: pkcs11_initialize - entered
Mon May 22 00:05:32 2017 us=571085 PKCS#11: pkcs11_initialize - return 0-'CKR_OK'
Mon May 22 00:05:32 2017 us=571435 Diffie-Hellman initialized with 2048 bit key
Mon May 22 00:05:32 2017 us=571671 PRNG init md=SHA1 size=36
Mon May 22 00:05:32 2017 us=571721 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon May 22 00:05:32 2017 us=571729 Outgoing Control Channel Authentication: HMAC KEY: 266316ab 6d3a6dd7 d76fcc4c dd52cf9b 4b839cd7
Mon May 22 00:05:32 2017 us=571733 Outgoing Control Channel Authentication: HMAC size=20 block_size=20
Mon May 22 00:05:32 2017 us=571737 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon May 22 00:05:32 2017 us=571742 Incoming Control Channel Authentication: HMAC KEY: 2593a920 d94c8edb 91c82dbd e6d6ec64 bf8fe769
Mon May 22 00:05:32 2017 us=571745 Incoming Control Channel Authentication: HMAC size=20 block_size=20
Mon May 22 00:05:32 2017 us=571749 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 28 bytes
Mon May 22 00:05:32 2017 us=571755 TLS-Auth MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon May 22 00:05:32 2017 us=571759 MTU DYNAMIC mtu=1450, flags=2, 1622 -> 1450
Mon May 22 00:05:32 2017 us=571894 ROUTE_GATEWAY 10.138.0.1
Mon May 22 00:05:32 2017 us=572839 TUN/TAP device tun0 opened
Mon May 22 00:05:32 2017 us=572858 TUN/TAP TX queue length set to 100
Mon May 22 00:05:32 2017 us=572869 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Mon May 22 00:05:32 2017 us=572878 /sbin/ip link set dev tun0 up mtu 1500
Mon May 22 00:05:32 2017 us=573017 PKCS#11: __pkcs11h_forkFixup entry pid=2648, activate_slotevent=1
Mon May 22 00:05:32 2017 us=573041 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=573666 /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Mon May 22 00:05:32 2017 us=573812 PKCS#11: __pkcs11h_forkFixup entry pid=2649, activate_slotevent=1
Mon May 22 00:05:32 2017 us=573837 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=574517 /sbin/ip route add 192.168.0.0/24 via 10.8.0.2
Mon May 22 00:05:32 2017 us=574661 PKCS#11: __pkcs11h_forkFixup entry pid=2650, activate_slotevent=1
Mon May 22 00:05:32 2017 us=574686 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=575735 /sbin/ip route add 192.168.1.0/24 via 10.8.0.2
Mon May 22 00:05:32 2017 us=575881 PKCS#11: __pkcs11h_forkFixup entry pid=2652, activate_slotevent=1
Mon May 22 00:05:32 2017 us=575905 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=576284 /sbin/ip route add 10.10.10.0/24 via 10.8.0.2
Mon May 22 00:05:32 2017 us=576432 PKCS#11: __pkcs11h_forkFixup entry pid=2653, activate_slotevent=1
Mon May 22 00:05:32 2017 us=576456 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=576937 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Mon May 22 00:05:32 2017 us=577076 PKCS#11: __pkcs11h_forkFixup entry pid=2654, activate_slotevent=1
Mon May 22 00:05:32 2017 us=577100 PKCS#11: __pkcs11h_forkFixup return
Mon May 22 00:05:32 2017 us=577484 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon May 22 00:05:32 2017 us=577727 Could not determine IPv4/IPv6 protocol. Using AF_INET
Mon May 22 00:05:32 2017 us=577742 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon May 22 00:05:32 2017 us=577752 UDPv4 link local (bound): [AF_INET][undef]:3000
Mon May 22 00:05:32 2017 us=577757 UDPv4 link remote: [AF_UNSPEC]
Mon May 22 00:05:32 2017 us=577763 GID set to nogroup
Mon May 22 00:05:32 2017 us=577769 UID set to nobody
Mon May 22 00:05:32 2017 us=577776 MULTI: multi_init called, r=256 v=256
Mon May 22 00:05:32 2017 us=577787 IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Mon May 22 00:05:32 2017 us=577797 IFCONFIG POOL LIST
Mon May 22 00:05:32 2017 us=577814 PO_INIT maxevents=4 flags=0x00000002
Mon May 22 00:05:32 2017 us=577829 Initialization Sequence Completed
Mon May 22 00:05:32 2017 us=577833 SCHEDULE: schedule_find_least NULL
Mon May 22 00:05:32 2017 us=577837 PO_CTL rwflags=0x0001 ev=6 arg=0x55eadf2b4180
Mon May 22 00:05:32 2017 us=577840 PO_CTL rwflags=0x0001 ev=5 arg=0x55eadf2b4068
Mon May 22 00:05:32 2017 us=577845 I/O WAIT TR|Tw|SR|Sw [10/0]
Mon May 22 00:05:32 2017 us=577851 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55eadf2b4068 
Mon May 22 00:05:32 2017 us=577855 event_wait returned 1
Mon May 22 00:05:32 2017 us=577858 I/O WAIT status=0x0004
Mon May 22 00:05:32 2017 us=577892 read from TUN/TAP returned 48
Mon May 22 00:05:32 2017 us=577900 SCHEDULE: schedule_find_least NULL
Mon May 22 00:05:32 2017 us=577903 PO_CTL rwflags=0x0001 ev=6 arg=0x55eadf2b4180
Mon May 22 00:05:32 2017 us=577906 NOTE: --mute triggered...

Iptables

Chain INPUT (policy ACCEPT)
target prot opt source destination 
sshguard all -- anywhere anywhere 
ACCEPT udp -- anywhere anywhere state NEW udp dpt:3000
ACCEPT all -- anywhere anywhere 

Chain FORWARD (policy ACCEPT)
target prot opt source destination 
ACCEPT all -- anywhere anywhere 
ACCEPT all -- anywhere anywhere state RELATED,ESTABLISHED
ACCEPT all -- anywhere anywhere state RELATED,ESTABLISHED

Chain OUTPUT (policy ACCEPT)
target prot opt source destination 
ACCEPT all -- anywhere anywhere 

Chain sshguard (1 references)
target prot opt source destination 

Ifconfig

ens4: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1460
inet 10.138.0.2 netmask 255.255.255.255 broadcast 10.138.0.2
inet6 fe80::4001:aff:fe8a:2 prefixlen 64 scopeid 0x20<link>
ether 42:01:0a:8a:00:02 txqueuelen 1000 (Ethernet)
RX packets 1816 bytes 680720 (680.7 KB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 1528 bytes 277288 (277.2 KB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
inet 127.0.0.1 netmask 255.0.0.0
inet6 ::1 prefixlen 128 scopeid 0x10<host>
loop txqueuelen 1000 (Local Loopback)
RX packets 6 bytes 486 (486.0 B)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 6 bytes 486 (486.0 B)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

tun0: flags=4305<UP,POINTOPOINT,RUNNING,NOARP,MULTICAST> mtu 1500
inet 10.8.0.1 netmask 255.255.255.255 destination 10.8.0.2
inet6 fe80::ede1:41f4:7599:254a prefixlen 64 scopeid 0x20<link>
unspec 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00 txqueuelen 100 (UNSPEC)
RX packets 0 bytes 0 (0.0 B)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 8 bytes 384 (384.0 B)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

Netstat chunk

Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State udp 0 0 0.0.0.0:3000 0.0.0.0:*

Author: Anton Shchyrov, 2017-05-22

1 answers

The problem, indeed, was in the brandmower. But since this is a virtual server, the rules should have been set in the instance control panel, not in iptables.

In total, I allowed the connection to the 3000 udp port in the control panel. And everything worked. I removed all the rules I added from iptables. Here's all that's left

Chain INPUT (policy ACCEPT)
target     prot opt source               destination         
sshguard   all  --  anywhere             anywhere            
Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         
Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         
Chain sshguard (1 references)
target     prot opt source               destination 
 0
Author: Anton Shchyrov, 2017-05-23 17:23:24