`AUTH_FAILED` problem during initial device provisioning

[mcamou]

I have an AWS EC2 instance running balenaos-in-container release 2.68.1. I need to run a separate BalenaOS instance in the same host. The Docker container starts up fine. However, it never gets registered with Balena.

If I docker exec -ti <container> bash and run journalctl --follow I get the following messages over and over again:

Jul 20 15:01:09 6621a1e 629ea5729bfc[231]: [event]   Event: Device bootstrap {}
Jul 20 15:01:09 6621a1e resin-supervisor[718]: [event]   Event: Device bootstrap {}
Jul 20 15:01:09 6621a1e 629ea5729bfc[231]: [error]   Unable to get architecture: Error: ENOENT: no such file or directory, open '/mnt/root/mnt/boot/device-type.json'
Jul 20 15:01:09 6621a1e 629ea5729bfc[231]: [error]   Unable to get device type: Error: ENOENT: no such file or directory, open '/mnt/root/mnt/boot/device-type.json'
Jul 20 15:01:09 6621a1e 629ea5729bfc[231]: [info]    New device detected. Provisioning...
Jul 20 15:01:09 6621a1e resin-supervisor[718]: [error]   Unable to get architecture: Error: ENOENT: no such file or directory, open '/mnt/root/mnt/boot/device-type.json'
Jul 20 15:01:09 6621a1e resin-supervisor[718]: [error]   Unable to get device type: Error: ENOENT: no such file or directory, open '/mnt/root/mnt/boot/device-type.json'
Jul 20 15:01:09 6621a1e resin-supervisor[718]: [info]    New device detected. Provisioning...
Jul 20 15:01:09 6621a1e 629ea5729bfc[231]: [event]   Event: Device bootstrap failed, retrying {"delay":30000,"error":{"message":""}}
Jul 20 15:01:09 6621a1e resin-supervisor[718]: [event]   Event: Device bootstrap failed, retrying {"delay":30000,"error":{"message":""}}
Jul 20 15:01:18 6621a1e prepare-openvpn[1447]: prepare-openvpn: [INFO] Balena.io VPN authentication.
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 WARNING: file '/var/volatile/vpn-auth' is group or others accessible
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 OpenVPN 2.4.7 x86_64-poky-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Feb 20 2019
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 library versions: OpenSSL 1.1.1i  8 Dec 2020, LZO 2.10
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]35.169.89.252:443
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 Socket Buffers: R=[131072->131072] S=[16384->16384]
Jul 20 15:01:18 6621a1e openvpn[1463]: Tue Jul 20 15:01:18 2021 Attempting to establish TCP connection with [AF_INET]35.169.89.252:443 [nonblock]
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 TCP connection established with [AF_INET]35.169.89.252:443
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 TCP_CLIENT link local: (not bound)
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 TCP_CLIENT link remote: [AF_INET]35.169.89.252:443
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 TLS: Initial packet from [AF_INET]35.169.89.252:443, sid=1c6e9942 77953491
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 VERIFY OK: depth=1, C=AU, ST=Some-State, O=Internet Widgits Pty Ltd
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 VERIFY KU OK
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 Validating certificate extended key usage
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 VERIFY EKU OK
Jul 20 15:01:19 6621a1e openvpn[1463]: Tue Jul 20 15:01:19 2021 VERIFY OK: depth=0, C=US, ST=WA, O=balena.io, OU=balenaCloud, CN=vpn.balena-cloud.com
Jul 20 15:01:21 6621a1e openvpn[1463]: Tue Jul 20 15:01:21 2021 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Jul 20 15:01:21 6621a1e openvpn[1463]: Tue Jul 20 15:01:21 2021 [vpn.balena-cloud.com] Peer Connection Initiated with [AF_INET]35.169.89.252:443
Jul 20 15:01:22 6621a1e openvpn[1463]: Tue Jul 20 15:01:22 2021 SENT CONTROL [vpn.balena-cloud.com]: 'PUSH_REQUEST' (status=1)
Jul 20 15:01:22 6621a1e openvpn[1463]: Tue Jul 20 15:01:22 2021 AUTH: Received control message: AUTH_FAILED
Jul 20 15:01:22 6621a1e openvpn[1463]: Tue Jul 20 15:01:22 2021 SIGTERM[soft,auth-failure] received, process exiting
Jul 20 15:01:32 6621a1e prepare-openvpn[1480]: prepare-openvpn: [INFO] Balena.io VPN authentication.
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 WARNING: file '/var/volatile/vpn-auth' is group or others accessible
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 OpenVPN 2.4.7 x86_64-poky-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Feb 20 2019
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 library versions: OpenSSL 1.1.1i  8 Dec 2020, LZO 2.10
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]3.227.28.93:443
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 Socket Buffers: R=[131072->131072] S=[16384->16384]
Jul 20 15:01:32 6621a1e openvpn[1503]: Tue Jul 20 15:01:32 2021 Attempting to establish TCP connection with [AF_INET]3.227.28.93:443 [nonblock]
Jul 20 15:01:33 6621a1e openvpn[1503]: Tue Jul 20 15:01:33 2021 TCP connection established with [AF_INET]3.227.28.93:443
Jul 20 15:01:33 6621a1e openvpn[1503]: Tue Jul 20 15:01:33 2021 TCP_CLIENT link local: (not bound)
Jul 20 15:01:33 6621a1e openvpn[1503]: Tue Jul 20 15:01:33 2021 TCP_CLIENT link remote: [AF_INET]3.227.28.93:443
Jul 20 15:01:33 6621a1e openvpn[1503]: Tue Jul 20 15:01:33 2021 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 TLS: Initial packet from [AF_INET]3.227.28.93:443, sid=65da59c0 302d7b29
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 VERIFY OK: depth=1, C=AU, ST=Some-State, O=Internet Widgits Pty Ltd
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 VERIFY KU OK
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 Validating certificate extended key usage
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 VERIFY EKU OK
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 VERIFY OK: depth=0, C=US, ST=WA, O=balena.io, OU=balenaCloud, CN=vpn.balena-cloud.com
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Jul 20 15:01:35 6621a1e openvpn[1503]: Tue Jul 20 15:01:35 2021 [vpn.balena-cloud.com] Peer Connection Initiated with [AF_INET]3.227.28.93:443
Jul 20 15:01:37 6621a1e openvpn[1503]: Tue Jul 20 15:01:37 2021 SENT CONTROL [vpn.balena-cloud.com]: 'PUSH_REQUEST' (status=1)
Jul 20 15:01:37 6621a1e openvpn[1503]: Tue Jul 20 15:01:37 2021 AUTH: Received control message: AUTH_FAILED
Jul 20 15:01:37 6621a1e openvpn[1503]: Tue Jul 20 15:01:37 2021 SIGTERM[soft,auth-failure] received, process exiting

I thought that it might be something to do with the config.json file so I downloaded a new one, but it still does not work.

[mcamou]

I downgraded to 2.45.1 rev2 (which I had installed in the past), and the enrollment worked. I then upgraded it to 2.68.1 rev1 and it continued working. It would seem that there's something wrong with the enrollment code in 2.68.1.