Problems getting openvpn working (tls-crypt unwrap error: packet too short)

jordanthompson · March 12, 2020, 12:37pm

Hi all,
I am trying to get it set up my router so that I can remotely connect to my hosts inside of my home network from my laptop when I am out and about.
I created the following files from my laptop using instructions from the openvpn guide and copied the server.conf file to the router.

Here is my /etc/config/openwrt file (this is more for reference as it is not used in my manual testing below):

openvpn 'myServer'
        option enabled '1'
        option config '/etc/openvpn/server.conf'

Here is my /etc/openvpn/server.conf file:

verb 3
user nobody
group nogroup
dev tun0
port 1194
proto udp
server 10.13.1.0 255.255.255.0
topology subnet
client-to-client
keepalive 10 120
persist-tun
persist-key
duplicate-cn
push "dhcp-option DNS 8.8.8.8"
push "redirect-gateway def1"
push "persist-tun"
push "persist-key"
<dh>
-----BEGIN DH PARAMETERS-----
bunch of spagheti
-----END DH PARAMETERS-----
</dh>
<tls-crypt>
-----BEGIN OpenVPN Static key V1-----
bunch of spagheti
-----END OpenVPN Static key V1-----
</tls-crypt>
<ca>
-----BEGIN CERTIFICATE-----
bunch of spagheti
-----END CERTIFICATE-----
</ca>
<cert>
-----BEGIN CERTIFICATE-----
bunch of spagheti
-----END CERTIFICATE-----
</cert>
<key>
-----BEGIN PRIVATE KEY-----
bunch of spagheti
-----END PRIVATE KEY-----
</key>

On the laptop side, I have the following in my client.ovpn file:

verb 3
dev tun
nobind
client
remote 72.239.159.85 1194 udp
auth-nocache
remote-cert-tls server
<tls-crypt>
-----BEGIN OpenVPN Static key V1-----
bunch of spagheti
-----END OpenVPN Static key V1-----
</tls-crypt>
<ca>
-----BEGIN CERTIFICATE-----
bunch of spagheti
-----END CERTIFICATE-----
</ca>
<cert>
-----BEGIN CERTIFICATE-----
bunch of spagheti
-----END CERTIFICATE-----
</cert>
<key>
-----BEGIN PRIVATE KEY-----
bunch of spagheti
-----END PRIVATE KEY-----
</key>

Here is the output from running openvpn server manually:

/etc/config# openvpn /etc/openvpn/server.conf
Wed Mar 11 18:25:10 2020 OpenVPN 2.4.5 arm-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
Wed Mar 11 18:25:10 2020 library versions: OpenSSL 1.0.2u  20 Dec 2019, LZO 2.10
Wed Mar 11 18:25:10 2020 Diffie-Hellman initialized with 2048 bit key
Wed Mar 11 18:25:10 2020 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Wed Mar 11 18:25:10 2020 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Mar 11 18:25:10 2020 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Wed Mar 11 18:25:10 2020 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Mar 11 18:25:10 2020 TUN/TAP device tun0 opened
Wed Mar 11 18:25:10 2020 TUN/TAP TX queue length set to 100
Wed Mar 11 18:25:10 2020 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Wed Mar 11 18:25:10 2020 /sbin/ifconfig tun0 10.13.1.1 netmask 255.255.255.0 mtu 1500 broadcast 10.13.1.255
Wed Mar 11 18:25:10 2020 Could not determine IPv4/IPv6 protocol. Using AF_INET
Wed Mar 11 18:25:10 2020 Socket Buffers: R=[163840->163840] S=[163840->163840]
Wed Mar 11 18:25:10 2020 UDPv4 link local (bound): [AF_INET][undef]:1194
Wed Mar 11 18:25:10 2020 UDPv4 link remote: [AF_UNSPEC]
Wed Mar 11 18:25:10 2020 GID set to nogroup
Wed Mar 11 18:25:10 2020 UID set to nobody
Wed Mar 11 18:25:10 2020 MULTI: multi_init called, r=256 v=256
Wed Mar 11 18:25:10 2020 IFCONFIG POOL: base=10.13.1.2 size=252, ipv6=0
Wed Mar 11 18:25:10 2020 Initialization Sequence Completed
Wed Mar 11 18:25:16 2020 tls-crypt unwrap error: packet too short
Wed Mar 11 18:25:16 2020 TLS Error: tls-crypt unwrapping failed from [AF_INET]10.13.0.43:57553
Wed Mar 11 18:25:17 2020 tls-crypt unwrap error: packet too short
Wed Mar 11 18:25:17 2020 TLS Error: tls-crypt unwrapping failed from [AF_INET]10.13.0.43:57553
Wed Mar 11 18:25:18 2020 tls-crypt unwrap error: packet too short
Wed Mar 11 18:25:18 2020 TLS Error: tls-crypt unwrapping failed from [AF_INET]10.13.0.43:57553

Finally found the logs on the client side:

2020-03-12 08:58:16-0400 [HTTPChannel,4266,] Profile approve: profile u'my_host' signed_by=None was previously seen, approval=True
2020-03-12 08:58:16-0400 [HTTPChannel,4266,] OpenVPN my_host_p4530 instantiated
2020-03-12 08:58:16-0400 [HTTPChannel,4266,] pyovpn.client.vpncli.MyOMIServer starting on "u'/Library/Application Support/OpenVPN/sock/ovpn-U2xPchfn6y5Y.sock'"
2020-03-12 08:58:16-0400 [-] (Port None Closed)
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u">INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info"
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'>HOLD:Waiting for hold release'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['state on']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: real-time state notification set to ON'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['echo on']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: real-time echo notification set to ON'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['bytecount 1']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: bytecount interval changed'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['hold off']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: hold flag set to OFF'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['hold release']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: hold release succeeded'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] OpenVPN start: name='my_host_p4530' sev='info' msg='process started successfully'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_5ETRL8o2tmvgmD9X_5', 10] kw={} ret=[{'type': 'PROFILE', 'state': 'connect', 'profile_id': 'my_host_p4530', 'cookie': 'TRAY_CLIENT_anJ0_OV88unPL', 'timestamp': 1584017896}]
2020-03-12 08:58:16-0400 [MyOMIClient,0,] *** API CALL f=xmlrpc_Connect args=[{'new_only': True, 'cookie': 'TRAY_CLIENT_anJ0_OV88unPL', 'profile_id': 'my_host_p4530', 'type': 'static', 'non_interactive': False}, ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT', 'BYTECOUNT'], {}] kw={} ret='sess_my_host_85_p4530_02SXW1WFzcmZXdZU_1'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'>REMOTE:my_host,1194,udp'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] TO OMI: ['remote ACCEPT']
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'SUCCESS: remote command succeeded'
2020-03-12 08:58:16-0400 [HTTPChannel,4267,] *** API CALL f=xmlrpc_Poll args=['sess_my_host_p4530_02SXW1WFzcmZXdZU_1', 10] kw={} ret=[{'active': True, 'timestamp': 1584017896, 'type': 'ACTIVE', 'last': None}]
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'>STATE:1584017896,RESOLVE,,,'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] *** STATE 1584017896,RESOLVE,,,
2020-03-12 08:58:16-0400 [MyOMIClient,0,] FROM OMI: u'>STATE:1584017896,WAIT,,,'
2020-03-12 08:58:16-0400 [MyOMIClient,0,] *** STATE 1584017896,WAIT,,,
2020-03-12 08:58:16-0400 [HTTPChannel,4269,] *** API CALL f=xmlrpc_Poll args=['sess_my_host_p4530_02SXW1WFzcmZXdZU_1', 10] kw={} ret=[{'timestamp': 1584017896, 'state': u'RESOLVE', 'type': 'STATE'}, {'timestamp': 1584017896, 'state': u'WAIT', 'type': 'STATE'}]
2020-03-12 08:58:22-0400 [HTTPChannel,4276,] TO OMI: ['exit']
2020-03-12 08:58:22-0400 [MyOMIClient,0,] OMI Cancel pending deferred ['exit']
2020-03-12 08:58:22-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_my_host_p4530_02SXW1WFzcmZXdZU_1', 10] kw={} ret=[{'active': False, 'timestamp': 1584017902, 'type': 'ACTIVE', 'last': True}]
2020-03-12 08:58:22-0400 [-] OpenVPN my_host_p4530 stop: process stopped with exit code 0
2020-03-12 08:58:22-0400 [-] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_5ETRL8o2tmvgmD9X_5', 10] kw={} ret=[{'timestamp': 1584017902, 'state': 'disconnect', 'profile_id': 'my_host_p4530', 'type': 'PROFILE'}]
2020-03-12 08:58:22-0400 [-] *** API CALL f=xmlrpc_DisconnectAll args=[] kw={} ret=[(True, ('my_host_p4530', 0))]
2020-03-12 08:58:22-0400 [HTTPChannel,4277,] *** API CALL f=xmlrpc_EnumProfiles args=[] kw={} ret=[{'hash': '55a0f7e4168741b258f3f052021d39747cba3bf28a25f36b9b73ae3f1faf9428', 'name': u'my_host', 'global': False, 'host': umy_host', 'snapshot': {'active': {'active': False, 'timestamp': 1584017902, 'type': 'ACTIVE', 'last': True}, 'state': {'timestamp': 1584017896, 'state': 'DISCONNECTED', 'type': 'STATE'}, 'delete_pending': True, 'cookie': 'TRAY_CLIENT_anJ0_OV88unPL', 'bytecount': {'timestamp': 1584017901, 'out': u'70', 'type': 'BYTECOUNT', 'in': u'0'}}, 'owner': u'jrt', 'remote_hosts': [u'my_host'], 'type': ['static'], 'id': u'my_host_p4530', 'access_allowed': True}]
2020-03-12 08:58:22-0400 [HTTPChannel,4278,] *** API CALL f=xmlrpc_Poll args=['sess_my_host_p4530_02SXW1WFzcmZXdZU_1', 10] kw={} ret=[{'timestamp': 1584017902, 'type': 'DELETE_PENDING'}]

Thanks in advance, I would really appreciate any help you could give me!

mk24 · March 12, 2020, 1:10pm

Do the client and server tls-crypt keys match (identical spaghettI)?

trendy · March 12, 2020, 1:13pm

Is the client connecting from the internet of from the lan?
Is the time correct on both devices? I can see one of them shows 11th of March in the logs.
Did you create the certificates on the router or on your PC? Were the files copied with care not to miss any newline feeds or carrier returns?

jordanthompson · March 12, 2020, 2:45pm

@mk24 I assume that the spaghetti tastes the same ;-). They were both created at the same time on my mac using the "autoated script" from Automated script on PC. As they were created on a mac, there should be no issues with line endings

jordanthompson · March 12, 2020, 2:46pm

@trendy I am connecting from the internet via my cellphone hotspot. The times are different because I made multiple runs as I edited the client and tried, then the server and tried.

trendy · March 12, 2020, 2:54pm

Notice this:
server 10.13.1.0 255.255.255.0
on the server.
However the error is coming from an IP outside the subnet.

TLS Error: tls-crypt unwrapping failed from [AF_INET]10.13.0.43:57553

jordanthompson · March 12, 2020, 3:11pm

@trendy Good (amazing?) catch. Unfortunately that is not the issue. Occasionally I connect to the network via network adapter (RJ45) as well as wifi (through my phone's hotspot.). This must have been during one of those instances. The error persists when I remove the network adapter and connect only through the hotspot.

mk24 · March 12, 2020, 3:14pm

Make sure there are no other files in /etc/openvpn named *.conf. OpenVPN will try to parse those files every startup regardless of what file you tell UCI to put on the command line. Recommended practice is not to name any OpenVPN configuration .conf, use a neutral extension like .ovpn instead.

trendy · March 12, 2020, 3:17pm

Yeah, it came to me later that this might be the source address and it might just be a coincidence that the subnets are close. I hope there are no overlaps though, especially from the LTE.
Just in case, can you try to change the server statement to 192.168.8.0 255.255.255.0 or some other subnet?

jordanthompson · March 12, 2020, 3:32pm

@trendy I get the same error. The log line now reads:

Thu Mar 12 11:28:59 2020 us=17032 IFCONFIG POOL: base=192.168.8.2 size=252, ipv6=0
Thu Mar 12 11:28:59 2020 us=17309 Initialization Sequence Completed
Thu Mar 12 11:29:22 2020 us=3636 tls-crypt unwrap error: packet too short
Thu Mar 12 11:29:22 2020 us=3999 TLS Error: tls-crypt unwrapping failed from [AF_INET]unknown IP address:41973

jordanthompson · March 12, 2020, 3:42pm

@mk24 the only file in /etc/openvpn is server.conf. Although I have run it from the commandline for testing, I typically start it from luci which uses /etc/config/openvpn which has the following:

config openvpn 'Home'
        option enabled '1'
        option config '/etc/openvpn/server.conf'

jordanthompson · March 12, 2020, 4:24pm

After running the client manually like this:
/usr/local/sbin/openvpn --log /tmp/openvpn.log --config /Users/jrt/vpn/EasyRSA-v3.0.6/client.ovpn

I found the problem in the (now, very verbose) log:

Thu Mar 12 12:21:27 2020 us=304911 Cannot allocate TUN/TAP dev dynamically

I ran the command as root and I am able to connect. Now the problem lies with setting up the application to run as root on a mac (I am not a mac person).

FWIW, I found the application tunnelblick that seems to be working fine.

Thanks for everyone's help!

system · March 22, 2020, 4:34pm

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.