【全网首发】记一次SSL握手导致业务线程阻塞的案例分析原创
问题描述
产品线反馈RocketMQ某Group ID出现消息堆积，重启后正常，一段时间后再次堆积，近期堆积问题出现的频次有些高，希望能够分析解决下。
分析过程
通过以往消息堆积的案例经验：
● MQ-消息堆积-业务代码异常导致retry队列积压
● MQ-消息堆积-业务线程阻塞案例分析
● 一次RocketMQ ons SDK Bug导致消息不断堆积到重试队列的案例分析
● MQ-消息堆积-JDK Bug导致线程阻塞案例分析
相比RocketMQ和JDK bug，应用代码出现问题的概率更高一些，所以优先从业务层面排查：
● 业务代码抛出了异常导致retry队列堆积，通过【详细信息】没有发现消费失败的情况，所以排除这种情况；
● 业务线程消费慢？或者是卡死了？
线程阻塞？
根据以往经验的总结，分析线程阻塞通常有如下几种思路：
● 根据线程CPU使用率（线程阻塞的情况下，CPU使用率通常很低）
● 通过对RocketMQ Listener执行耗时进行监控：一种检测线程阻塞的实现思路
● 通过对线程池线程执行时间进行监控（不做详细描述）
监控runWorker的退出时间
监控beforeExecute(wt, task)开始执行时间
监控afterExecute(task, thrown)开始执行时间
● 卡死线程的线程栈是不变得，可以通过不断查看线程栈进行分析
在没有任何系统建设的情况下，通过不断查看线程栈是可操作性最高的，下面是堆栈信息：
将【堆栈信息】中的线程浏览了一下，发现非常多的线程都处于上面线程的状态，相比较线程消费慢，现在更倾向于线程卡死了。
接下来分析上图中tid=354457的线程，为了方便分析线程栈，可以使用arthas thread命令，通过不断执行thread 354457来观察线程栈的变化：
通过不断执行，线程都保持上图状态，可以确定线程卡死了。
通过以上线程栈可知，业务代码使用apache httpclient框架发起的SSL请求，在SSL握手的时候发生了阻塞，接下来分析具体阻塞在SSL握手的哪个阶段。
SSL握手
在具体分析SSL握手阻塞在哪个阶段之前，我们先了解下SSL握手过程，以便更好理解代码的实现逻辑。
握手概述
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256说明
- TLS 是双方通信的协议；
- ECDHE和 RSA都是非对称加密算法，用于传递秘钥；ECDHE 是秘钥交换算法，RSA 是签名算法；
- WITH是连接字符串；
- AES-128-GCM 是对称加密算法，也就是后面双方交换应用信息时使用的算法；
- SHA256是消息摘要算法
TLS协议
RSA握手过程
代码分析
业务代码
根据线程栈，使用arthas jad反编译代码，相关代码整理后如下：
SSLSocket握手
SSL握手主要流程：创建Socket、socket建立与服务端连接、SSL握手，主要代码整理如下：
由于【创建Socket】和【socket建立于服务端连接】与问题关联不大，下面主要分析创建SSLSocket和建立SSL握手的过程。
创建SSLSocket
SSLSocketFactoryImpl
public Socket createSocket(Socket s, String host, int port,
boolean autoClose) throws IOException {
return new SSLSocketImpl(context, s, host, port, autoClose);
}
SSLSocketImpl
SSLSocketImpl(SSLContextImpl context, Socket sock, String host,
int port, boolean autoClose) throws IOException {
super(sock);
// We always layer over a connected socket
if (!sock.isConnected()) {
throw new SocketException("Underlying socket is not connected");
}
this.host = host;
this.serverNames =
Utilities.addToSNIServerNameList(this.serverNames, this.host);
init(context, false);
this.autoClose = autoClose;
doneConnect();
}
init
private void init(SSLContextImpl context, boolean isServer) {
sslContext = context;
sess = SSLSessionImpl.nullSession;
handshakeSession = null;
/*
* role is as specified, state is START until after
* the low level connection's established.
*/
roleIsServer = isServer;
connectionState = cs_START;
... ...
enabledCipherSuites =
sslContext.getDefaultCipherSuiteList(roleIsServer);
enabledProtocols =
sslContext.getDefaultProtocolList(roleIsServer);
... ...
input = new AppInputStream(this);
output = new AppOutputStream(this);
}
doneConnect
void doneConnect() throws IOException {
/*
* Save the input and output streams. May be done only after
* java.net actually connects using the socket "self", else
* we get some pretty bizarre failure modes.
*/
sockInput = super.getInputStream();
sockOutput = super.getOutputStream();
/*
* Move to handshaking state, with pending session initialized
* to defaults and the appropriate kind of handshaker set up.
*/
initHandshaker();
}
private void initHandshaker() {
... ...
// state is either cs_START or cs_DATA
if (connectionState == cs_START) {
connectionState = cs_HANDSHAKE;
} else { // cs_DATA
connectionState = cs_RENEGOTIATE;
}
......
handshaker = new ClientHandshaker(this, sslContext,
enabledProtocols,
protocolVersion, connectionState == cs_HANDSHAKE,
secureRenegotiation, clientVerifyData, serverVerifyData);
handshaker.setSNIServerNames(serverNames);
handshaker.setEnabledCipherSuites(enabledCipherSuites);
handshaker.setEnableSessionCreation(enableSessionCreation);
}
startHandshake：建立SSL握手
startHandshake调用performInitialHandshake，主要逻辑如下：
private void performInitialHandshake() throws IOException {
synchronized (handshakeLock) {
if (getConnectionState() == cs_HANDSHAKE) {
kickstartHandshake();
... ...
readRecord(inrec, false);
inrec = null;
}
}
}
kickstartHandshake
发送ClientHello
private synchronized void kickstartHandshake() throws IOException {
... ...
handshaker.activate(null);
// 发送ClientHello
handshaker.kickstart();
}
readRecord
private void readRecord(InputRecord r, boolean needAppData)throws IOException {
int state;
synchronized (readLock) {
while (((state = getConnectionState()) != cs_CLOSED) &&
(state != cs_ERROR) && (state != cs_APP_CLOSED)) {
try {
// 读取服务端响应
r.setAppDataValid(false);
r.read(sockInput, sockOutput);
} catch (SSLProtocolException e) {
... ...
} catch (EOFException eof) {
... ...
}
try {
//解析响应报文
r.decrypt(readAuthenticator, readCipher);
} catch (BadPaddingException e) {
... ...
}
synchronized (this) {
switch (r.contentType()) {
case Record.ct_handshake:
... ...
handshaker.process_record(r, expectingFinished);
expectingFinished = false;
if (handshaker.invalidated) {
handshaker = null;
receivedCCS = false;
if (connectionState == cs_RENEGOTIATE) {
connectionState = cs_DATA;
}
} else if (handshaker.isDone()) {
secureRenegotiation =
handshaker.isSecureRenegotiation();
clientVerifyData = handshaker.getClientVerifyData();
serverVerifyData = handshaker.getServerVerifyData();
sess = handshaker.getSession();
handshakeSession = null;
handshaker = null;
connectionState = cs_DATA;
receivedCCS = false;
if (handshakeListeners != null) {
HandshakeCompletedEvent event =
new HandshakeCompletedEvent(this, sess);
Thread t = new NotifyHandshakeThread(
handshakeListeners.entrySet(), event);
t.start();
}
}
if (needAppData || connectionState != cs_DATA) {
continue;
}
break;
case Record.ct_application_data:
... ...
break;
case Record.ct_alert:
recvAlert(r);
continue;
case Record.ct_change_cipher_spec:
... ...
continue;
default:
... ...
continue;
}
if (connectionState < cs_ERROR) {
checkSequenceNumber(readAuthenticator, r.contentType());
}
return;
}
}
r.close();
return;
}
}
分析结论
通过线程栈及源码分析：SSLSocket已经将ClientHello发送给服务端，当前正阻塞在读取服务端响应，由于设置的socketTimeout没有起作用，在服务端一直没有响应的情况下，线程一直阻塞在读取服务端响应。
结论验证
验证的方式主要想到了以下几种
方式一 问题复现
通过curl模拟请求进行了问题复现
方式二 tcpdump抓包
通过分析tcpdump报文进行验证（未实施）
方式三 打开SSL debug
借助arthas在不重启应用的情况下，动态打开了SSL debug日志，方式如下：
Debug
//将sun.security.ssl.Debug静态属性设置为all
ognl '#cls=@Class@forName("sun.security.ssl.Debug"),#field=#cls.getDeclaredField("args"),#field.setAccessible(true),#field.set(#cls,"all")'
//判断设置是否生效
ognl '@sun.security.ssl.Debug@isOn("handshake")'
ClientHandshaker
//查看debug属性定义信息
ognl '#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),{#field}'
//查看debug属性
ognl '@sun.security.ssl.Handshaker@debug'
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.Handshaker"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
SSLSocketImpl
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.SSLSocketImpl"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.SSLSocketImpl"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.SSLSocketImpl@debug'
InputRecord
//设置isReadOnly
options strict false
ognl '#cls=@Class@forName("sun.security.ssl.InputRecord"),#field=#cls.getDeclaredField("debug"),#override=#field.overrideFieldAccessor,#override.isReadOnly=false'
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.InputRecord"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.InputRecord@debug'
OutputRecord
//设置debug属性
ognl '#deg=@sun.security.ssl.Debug@getInstance("ssl"),#cls=@Class@forName("sun.security.ssl.OutputRecord"),#field=#cls.getDeclaredField("debug"),#modifiers=#field.getClass().getDeclaredField("modifiers"),#modifiers.setAccessible(true),#modifiers.setInt(#field,#field.getModifiers() & ~@java.lang.reflect.Modifier@FINAL),#field.setAccessible(true),#field.set(#cls,#deg)'
//查看debug属性
ognl '@sun.security.ssl.OutputRecord@debug'
方式四 对象状态分析
通过源码分析可知：SSL握手成功的情况下，SSLSocket实例的connectionState==cs_DATA，handshaker==null；握手进行中的时候，connectionState==cs_HANDSHAKE，handshaker==ClientHandshaker。所以通过arthas vmtool分别查看对应SSLSocket实例connectionState、handshaker变量的值就可以判断处SSLSocket处于什么状态。
找出阻塞的SSLSocket
由于业务应用每次请求都创建新的SSLSocket，所以我们只要找出创建时间比较早的SSLSocket，基本都是阻塞的。
通过socket的创建时间，可以找出阻塞的socket。
SSLSocket握手完成
SSLSocket握手未完成
具体阻塞在SSLSocket握手的哪个阶段，可以通过ClientHandshaker属性值进行判断，例如：
客户端发送了ClientHello
● 当服务端响应ServerHello的时候，属性protocolVersion不为空，svr_random不为空，cipherSuite不为默认值SSL_NULL_WITH_NULL_NULL，keyExchange不为默认值K_NULL；
● 当服务端没有响应ServerHello的时候，属性protocolVersion为空，svr_random为空，cipherSuite为默认值SSL_NULL_WITH_NULL_NULL，keyExchange为默认值K_NULL。
● 当服务端响应ServerCertificate的时候，handshaker的session属性的peerCerts字段不为空；
● 当服务端没有响应ServerCertificate的时候，handshaker的session属性的peerCerts字段为空；
● 以上可以结合handshaker的state变量值进行分析
经验总结
优化HttpClient使用方式
- 不使用@Deprecated相关接口及实现类
- HttpClient使用单例形式，而不是每个请求新建一个
- SSLSessionContext参数优化，详情见：SSL Session默认设置导致线程阻塞了几十秒的案例分析
服务端为何没有响应的原因：初步判断是由于客户端频繁SSL握手，触发了服务端的安全策略（未完待续）。
SSLSocket调试
enable debug
● 方式一：JVM启动参数添加-Djavax.net.debug=all
● 方式二：通过arthas动态打开debug
handshakeListeners
通过向SSLSocket注册handshakeListeners，当SSL握手完成的时候可以获取SSL握手完成的通知。。
X509TrustManager
该类的实现类方法checkServerTrusted通常是不做实现的，不过可以在该方法中记录下SSLSocket状态信息以方便问题排查。
