I am running openvpn-2.5.3-1.2.x86_64 on OpenSUSE Tumbleweed (20211111).
I am currently unable to log into my openvpn server. The initialization and authorization seem to succeed but then I get the following message repeated indefinitely:
2021-11-15 17:23:46 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
2021-11-15 17:23:51 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
In the server log I see basically the same thing except for one PAM related error message ("BACKGROUND: write error on control file"):
Nov 15 17:23:54 server openvpn@server[2982]: 66.666.666.666:52957 PLUGIN_CALL: POST /usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Nov 15 17:23:54 server openvpn@server[2982]: 66.666.666.666:52957 TLS: Username/Password authentication deferred for username '<user>' [CN SET]
Nov 15 17:23:54 server openvpn[2985]: PLUGIN AUTH-PAM: BACKGROUND: received command code: 2
Nov 15 17:23:54 server openvpn@server[2982]: 66.666.666.666:52957 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
Nov 15 17:23:54 server openvpn@server[2982]: 66.666.666.666:52957 [<user>] Peer Connection Initiated with [AF_INET]79.233.165.32:52957
Nov 15 17:23:54 server openvpn[2985]: PLUGIN AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Nov 15 17:23:54 server openvpn[2985]: pam_unix(openvpn:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= user=<user>
Nov 15 17:23:54 server openvpn[2985]: pam_winbind(openvpn:auth): getting password (0x00000010)
Nov 15 17:23:54 server openvpn[2985]: pam_winbind(openvpn:auth): pam_get_item returned a password
Nov 15 17:23:55 server openvpn[2985]: pam_winbind(openvpn:auth): user '<user>' granted access
Nov 15 17:23:55 server openvpn[2985]: pam_winbind(openvpn:account): user '<user>' granted access
Nov 15 17:23:55 server openvpn[2985]: AUTH-PAM: BACKGROUND: write error on control file
Nov 15 17:23:56 server openvpn@server[2982]: 66.666.666.666:52957 PUSH: Received control message: 'PUSH_REQUEST'
Nov 15 17:23:56 server openvpn@server[2982]: 66.666.666.666:52957 PUSH: Received control message: 'PUSH_REQUEST'
Nov 15 17:23:56 server openvpn@server[2982]: 66.666.666.666:52957 PUSH: Received control message: 'PUSH_REQUEST'
I have another server with almost identical setup which does not show that error message and where the connection is established successfully. What am I missing?
Client config:
client
dev tap
dev-node OpenVPN
proto udp
remote <ip-address> 1194
resolv-retry infinite
nobind
persist-key
persist-tun
ca ca.crt
remote-cert-tls server
cipher AES-256-GCM
verb 3
auth-user-pass
pull
mssfix 1432
Server config:
local <ip>
port 1194
proto udp4
dev tap0
ca ca.crt
cert server.crt
key server.key
dh dh.pem
ifconfig-pool-persist ipp.txt
server-bridge 172.20.10.21 255.255.0.0 172.20.42.10 172.20.42.245
push "dhcp-option DNS 172.20.10.10"
push "dhcp-option DNS 172.20.10.11"
client-to-client
keepalive 10 60
cipher AES-256-GCM
user nobody
group nobody
persist-key
persist-tun
status openvpn-status.log
verb 4
plugin /usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so openvpn
verify-client-cert none
username-as-common-name
sndbuf 393216
rcvbuf 393216
push "sndbuf 393216"
push "rcvbuf 393216"
push "keepalive 10 60"
Complete client log:
Tue Nov 16 00:20:07 2021 OpenVPN 2.5.4 Windows-MSVC [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Oct 20 2021
Tue Nov 16 00:20:07 2021 Windows version 10.0 (Windows 10 or greater) 64bit
Tue Nov 16 00:20:07 2021 library versions: OpenSSL 1.1.1l 24 Aug 2021, LZO 2.10
Tue Nov 16 00:20:07 2021 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Tue Nov 16 00:20:07 2021 Need hold release from management interface, waiting...
Tue Nov 16 00:20:08 2021 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'state on'
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'log all on'
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'echo all on'
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'bytecount 5'
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'hold off'
Tue Nov 16 00:20:08 2021 MANAGEMENT: CMD 'hold release'
Tue Nov 16 00:20:14 2021 MANAGEMENT: CMD 'username "Auth" "user"'
Tue Nov 16 00:20:14 2021 MANAGEMENT: CMD 'password [...]'
Tue Nov 16 00:20:14 2021 Control Channel MTU parms [ L:1653 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Tue Nov 16 00:20:14 2021 Data Channel MTU parms [ L:1653 D:1432 EF:121 EB:411 ET:32 EL:3 ]
Tue Nov 16 00:20:14 2021 Local Options String (VER=V4): 'V4,dev-type tap,link-mtu 1581,tun-mtu 1532,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
Tue Nov 16 00:20:14 2021 Expected Remote Options String (VER=V4): 'V4,dev-type tap,link-mtu 1581,tun-mtu 1532,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
Tue Nov 16 00:20:14 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]<ip-address>:1194
Tue Nov 16 00:20:14 2021 Socket Buffers: R=[65536->65536] S=[65536->65536]
Tue Nov 16 00:20:14 2021 UDP link local: (not bound)
Tue Nov 16 00:20:14 2021 UDP link remote: [AF_INET]<ip-address>:1194
Tue Nov 16 00:20:14 2021 MANAGEMENT: >STATE:1637018414,WAIT,,,,,,
Tue Nov 16 00:20:14 2021 MANAGEMENT: >STATE:1637018414,AUTH,,,,,,
Tue Nov 16 00:20:14 2021 TLS: Initial packet from [AF_INET]<ip-address>:1194, sid=
Tue Nov 16 00:20:14 2021 VERIFY OK: depth=1, CN=<url>
Tue Nov 16 00:20:14 2021 VERIFY KU OK
Tue Nov 16 00:20:14 2021 Validating certificate extended key usage
Tue Nov 16 00:20:14 2021 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Nov 16 00:20:14 2021 VERIFY EKU OK
Tue Nov 16 00:20:14 2021 VERIFY OK: depth=0, CN=server
Tue Nov 16 00:20:14 2021 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA256
Tue Nov 16 00:20:14 2021 [server] Peer Connection Initiated with [AF_INET]<ip-address>:1194
Tue Nov 16 00:20:15 2021 MANAGEMENT: >STATE:1637018415,GET_CONFIG,,,,,,
Tue Nov 16 00:20:15 2021 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Nov 16 00:20:20 2021 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Nov 16 00:20:25 2021 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Complete server log:
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: MULTI: multi_create_instance called
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Re-using SSL/TLS context
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Control Channel MTU parms [ L:1653 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Data Channel MTU parms [ L:1653 D:1450 EF:121 EB:411 ET:32 EL:3 ]
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Local Options String (VER=V4): 'V4,dev-type tap,link-mtu 1581,tun-mtu 1532>
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Expected Remote Options String (VER=V4): 'V4,dev-type tap,link-mtu 1581,tu>
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 TLS: Initial packet from [AF_INET]<ip-address>:59057, sid=>
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_VER=2.5.4
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_PLAT=win
Nov 16 00:20:25 a-gate2 openvpn[8029]: AUTH-PAM: BACKGROUND: USER: <user>
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_PROTO=6
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_NCP=2
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_LZ4=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_LZ4v2=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_LZO=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_COMP_STUB=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_COMP_STUBv2=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_TCPNL=1
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_GUI_VER=OpenVPN_GUI_11
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 peer info: IV_SSO=openurl,crtext
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 PLUGIN_CALL: POST /usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so/PL>
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 TLS: Username/Password authentication deferred for username '<user>' [CN SET]
Nov 16 00:20:25 a-gate2 openvpn[8029]: PLUGIN AUTH-PAM: BACKGROUND: received command code: 2
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
Nov 16 00:20:25 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 [<user>] Peer Connection Initiated with [AF_INET]<ip-address>:59057
Nov 16 00:20:25 a-gate2 openvpn[8029]: PLUGIN AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Nov 16 00:20:25 a-gate2 openvpn[8029]: pam_unix(openvpn:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= user=<user>
Nov 16 00:20:25 a-gate2 openvpn[8029]: pam_winbind(openvpn:auth): getting password (0x00000010)
Nov 16 00:20:25 a-gate2 openvpn[8029]: pam_winbind(openvpn:auth): pam_get_item returned a password
Nov 16 00:20:25 a-gate2 openvpn[8029]: pam_winbind(openvpn:auth): user '<user>' granted access
Nov 16 00:20:25 a-gate2 openvpn[8029]: pam_winbind(openvpn:account): user '<user>' granted access
Nov 16 00:20:25 a-gate2 openvpn[8029]: AUTH-PAM: BACKGROUND: write error on control file
Nov 16 00:20:26 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 PUSH: Received control message: 'PUSH_REQUEST'
Nov 16 00:20:31 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 PUSH: Received control message: 'PUSH_REQUEST'
Nov 16 00:20:36 a-gate2 openvpn@config-test[8026]: <ip-address>:59057 PUSH: Received control message: 'PUSH_REQUEST'
Nov 16 00:21:13 a-gate2 openvpn@config-test[8026]: <ip-address>:62955 [<user>] Inactivity timeout (--ping-restart), restarting
Nov 16 00:21:13 a-gate2 openvpn@config-test[8026]: <ip-address>:62955 SIGUSR1[soft,ping-restart] received, client-instance restarting
