问题定位
排查了各种问题,包括:网络、服务、数据库、服务器资源占用,结果都没啥问题。于是我把目标瞄准到了VPN,为啥要确定是否是VPN的问题呢?因为服务A和服务B不在同一个网段内,服务A调用服务B是通过VPN连接的。
于是我先看了下VPN客户端的信息,如下所示。
Tue Jun 15 22:19:59 2021 OpenVPN 2.4.9 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 24 2020 Tue Jun 15 22:19:59 2021 library versions: OpenSSL 1.0.2k-fips 26 Jan 2017, LZO 2.06 Tue Jun 15 22:19:59 2021 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info. Tue Jun 15 22:19:59 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xxx:1194 Tue Jun 15 22:19:59 2021 Socket Buffers: R=[87380->87380] S=[16384->16384] Tue Jun 15 22:19:59 2021 Attempting to establish TCP connection with [AF_INET]xxx.xxx.xxx.xxx:1194 [nonblock] Tue Jun 15 22:20:00 2021 TCP connection established with [AF_INET]xxx.xxx.xxx.xxx:1194 Tue Jun 15 22:20:00 2021 TCP_CLIENT link local: (not bound) Tue Jun 15 22:20:00 2021 TCP_CLIENT link remote: [AF_INET]xxx.xxx.xxx.xxx:1194 Tue Jun 15 22:20:00 2021 TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xxx:1194, sid=500dc68d 98cc6b0a Tue Jun 15 22:20:00 2021 VERIFY OK: depth=1, CN=xxxx.com Tue Jun 15 22:20:00 2021 VERIFY OK: depth=0, CN=xxxx.com Tue Jun 15 22:20:00 2021 Connection reset, restarting [0] Tue Jun 15 22:20:00 2021 SIGUSR1[soft,connection-reset] received, process restarting Tue Jun 15 22:20:00 2021 Restart pause, 5 second(s)
在VPN客户端输出的日志信息中,存在如下一行信息。
Tue Jun 15 22:19:59 2021 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
再来看VPN服务端的日志信息,如下所示。
Tue Jun 15 22:51:22 2021 TCP connection established with [AF_INET]125.71.159.19:42744 Tue Jun 15 22:51:23 2021 125.71.159.19:42744 TLS: Initial packet from [AF_INET]125.71.159.19:42744, sid=a64a2771 594d7351 Tue Jun 15 22:51:23 2021 125.71.159.19:42744 WARNING: Failed to stat CRL file, not (re)loading CRL. Tue Jun 15 22:51:23 2021 125.71.159.19:42744 VERIFY ERROR: depth=0, error=CRL has expired: CN=client01 Tue Jun 15 22:51:23 2021 125.71.159.19:42744 OpenSSL: error:14089086:SSL routines:ssl3_get_client_certificate:certificate verify failed Tue Jun 15 22:51:23 2021 125.71.159.19:42744 TLS_ERROR: BIO read tls_read_plaintext error Tue Jun 15 22:51:23 2021 125.71.159.19:42744 TLS Error: TLS object -> incoming plaintext read error Tue Jun 15 22:51:23 2021 125.71.159.19:42744 TLS Error: TLS handshake failed Tue Jun 15 22:51:23 2021 125.71.159.19:42744 Fatal TLS error (check_tls_errors_co), restarting Tue Jun 15 22:51:23 2021 125.71.159.19:42744 SIGUSR1[soft,tls-error] received, client-instance restarting
在VPN服务端的输出信息中,存在如下一行信息。
Tue Jun 15 22:51:23 2021 125.71.159.19:42744 VERIFY ERROR: depth=0, error=CRL has expired: CN=client01
VPN的客户端和服务端都输出了对应的错误日志信息,基本可以定位到时VPN的问题了。那么,问题来了,具体是什么问题呢?我们继续往下分析。
造成VPN连接失败往往有如下几种原因:
- 客户端与服务端时间不一致,也就是说VPN服务端所在的服务器和VPN客户端所在的服务器时间不一致。
- 证书过期。
- CRL证书过期。
这里,我们可以通过VPN服务端输出的日志信息中的如下信息
Tue Jun 15 22:51:23 2021 125.71.159.19:42744 VERIFY ERROR: depth=0, error=CRL has expired: CN=client01
看到 error=CRL has expired
,看来是CRL证书过期了。
到这里,我们就定位到具体问题了,定位到问题就好办了,接下来,就是要解决问题了。
问题验证
前面我们已经通过error=CRL has expired
,定位到时CRL证书过期引起的VPN不能访问了。如何解决呢?其实很简单,我们继续往下看。
这里,我们需要找到OpenVPN配置文件目录下的easyrsa文件,例如,我这里的easyrsa文件的目录为/etc/openvpn/easy-rsa/3/easyrsa
。
打开这个文件,找到如下信息。
set_var EASYRSA_CA_EXPIRE 3650 set_var EASYRSA_CERT_EXPIRE 825 # new default of 36 months set_var EASYRSA_CERT_RENEW 30 set_var EASYRSA_CRL_DAYS 180
可以看到CRL证书的过期时间为180天。而我,差不多也是在半年前左右安装并配置的VPN,这里也再次验证了确实是CRL证书过期引起的问题。
问题解决
只要定位和明确了问题,就比较好解决了。这里,主要有两种解决方案:
- OpenVPN 2.4新证书撤销列表法。
- 注释掉VPN配置文件的CRL证书选项。
OpenVPN 2.4新证书撤销列表法
这种方法需要执行命令重新生成CRL证书,如下所示。
cd /vpn根目录 ./easyrsa gen-crl #使用EasyRSA的CRL生成新的CRL证书
例如,针对我这里的环境,我执行了如下命令。
cd /etc/openvpn/easy-rsa/3/ ./easyrsa gen-crl
注释掉VPN配置文件的CRL证书选项
这种方式只需要将VPN服务端的配置文件server.conf中关于CRL证书的选项注释掉,例如,我这里执行的命令如下。
vim /etc/openvpn/server.conf
找到如下代码行,并将其注释掉。
crl-verify /etc/openvpn/server/crl.pem
如下所示。
验证解决方案
问题解决后,我们再次启动VPN服务端和客户端,发现VPN服务端输出了如下的日志信息。
Tue Jun 15 23:03:28 2021 client01/125.71.159.19:42748 Connection reset, restarting [0] Tue Jun 15 23:03:28 2021 client01/125.71.159.19:42748 SIGUSR1[soft,connection-reset] received, client-instance restarting Tue Jun 15 23:03:54 2021 TCP connection established with [AF_INET]125.71.159.19:42750 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 TLS: Initial packet from [AF_INET]125.71.159.19:42750, sid=f7bb2dcd 605146c3 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 VERIFY OK: depth=1, CN=xxxx.com Tue Jun 15 23:03:55 2021 125.71.159.19:42750 VERIFY OK: depth=0, CN=client01 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_VER=2.4.9 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_PLAT=linux Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_PROTO=2 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_NCP=2 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_LZ4=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_LZ4v2=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_LZO=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_COMP_STUB=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_COMP_STUBv2=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 peer info: IV_TCPNL=1 Tue Jun 15 23:03:55 2021 125.71.159.19:42750 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA Tue Jun 15 23:03:55 2021 125.71.159.19:42750 [client01] Peer Connection Initiated with [AF_INET]125.71.159.19:42750 Tue Jun 15 23:03:55 2021 client01/125.71.159.19:42750 MULTI_sva: pool returned IPv4=10.3.31.6, IPv6=(Not enabled) Tue Jun 15 23:03:55 2021 client01/125.71.159.19:42750 MULTI: Learn: 10.3.31.6 -> client01/125.71.159.19:42750 Tue Jun 15 23:03:55 2021 client01/125.71.159.19:42750 MULTI: primary virtual IP for client01/125.71.159.19:42750: 10.3.31.6 Tue Jun 15 23:03:56 2021 client01/125.71.159.19:42750 PUSH: Received control message: 'PUSH_REQUEST' Tue Jun 15 23:03:56 2021 client01/125.71.159.19:42750 SENT CONTROL [client01]: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 84.200.69.80,dhcp-option DNS 84.200.70.40,route 10.3.31.1,topology net30,ping 20,ping-restart 60,ifconfig 10.3.31.6 10.3.31.5,peer-id 0,cipher AES-256-GCM' (status=1) Tue Jun 15 23:03:56 2021 client01/125.71.159.19:42750 Data Channel: using negotiated cipher 'AES-256-GCM' Tue Jun 15 23:03:56 2021 client01/125.71.159.19:42750 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key Tue Jun 15 23:03:56 2021 client01/125.71.159.19:42750 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
此时,再次通过VPN客户端服务器向VPN服务端服务器发送请求,连接就成功了。服务A调用服务B也成功了。
至此,整个问题就解决完了。