分类 Java 相关 下的文章

使用 Java 访问 https 的站点 TLS 协商中的 SNI 问题

上周有同事说他们的 Java 应用连一个新的服务, 总是有连接问题, 但是切换到老的服务一起都正常. 经过查看日志, tcp 抓包, Loader Balancer 验证, 我们发现问题的根源是 TLS 协商中 client_hello 中涉及的 SNI 扩展问题.


问题再现

这个 Java 应用连接一个 Elastic Search 服务, 这个 ES (Elastic Search) 的 endpoint 只支持 https 协议, 平时一切运行正常. 最近这个 ES 服务重新在 K8S 集群上面重新做了一个, 同样只支持 https 协议. 但是在 Java 应用这边, 把 endpoint 改成新的 URL, 可是总是报错. 一开始开发人员以为是新的 ES 可能慢, 或者网络问题, 于是加大了 client 端的 connect timeout & read timeout 时间. 即便增加了很多, 问题还是没有改善.

原因分析

首先, 我们看了出错日志, 发现是连接超时, 也就是连接本身就有问题. 然后我们在客户端抓包, 发现以下情形: 首先 TCP 的三次握手是没有任何问题的. 然后开始协商 TLS 协议, 客户端发送 client hello 包, 服务端 ack client hello, 然后就直接 reset 了这个连接. 然后一切就结束了. 所以, 可以看到是 TLS 协商的问题.
image.png

从这里推断, 我们猜测是客户端发送的 client_hello 里面的一些信息, 在服务端认为不可接受, 所以直接就 reset 了. 首先我们猜测客户端发送的这些加密方法(cipher suites) 在服务端没有一个被接受的. 客户端说我使用 TLSv1.2 协议, 发送了如下的加密方法:
image (1).png
我们查看了这些加密方法, 这些方法正是: io.netty.handler.ssl.SslUtils.java 里面默认的加密方法:
defaultcipher.png
这些加密方法是默认所有加密端都必须接受的, 所以这个不是问题.

又咨询了做加密证书的同事, 他们说这些加密方法服务端肯定是接受的, 都是默认的. 他们猜测这些连接被 reset 的原因很有可能是 SNI 导致的, 对于在K8S新加的 endpoint, 这些都要求客户端在发送 client_hello 的时候, 必须发送 SNI 扩展, 否则直接 reset 连接.

于是重新查看了 TCP dump, 发现确实没有发送 SNI 扩展项. 这就是导致问题的根源.

HTTP 协议中的 host header

在讲 TLS 协议的 SNI 之前, 我们先说一下 HTTP 协议中的 host header. 在早期的 HTTP 协议中, 是没有 host header 的. 一个 HTTP 请求大概是这样的:

GET /index.html HTTP/1.0

在那个时候, 网站还没有那么多, 一般每个网站都有一个独立的 IP. 后来网站越来越多, IPv4逐渐被用光, IPv6 还没被大规模使用, 于是兴起了虚拟主机(Virtual Host), 每个 IP 后边可能有多个网站. 为了区分不同的网站, 于是 HTTP 协议就加了一个 host header 用来区分不同的网站. 于是一个 HTTP 请求大概是这样的:

GET /index.html HTTP/1.0
Host www.tianxiaohui.com

所以, 概括起来就是: Host header 解决了一个 IP 多个网站的问题.

TLS 协议 client_hello 中的 SNI 扩展

如果使用 https 协议, 那么在 TCP 3次握手之后, 就是 TLS 协商, 如果一个 IP 上面有多个网站, 都有不同的证书, 那么如何在 TLS 协商阶段就能区分不同的网站呢? 于是 TLS 协议添加了 SNI (Server Name Indication) 扩展, 在 SNI 扩展里面设置 server_name 的字段值, 通过这个字段值, 服务端在开始握手的时候, 就能知道它要访问具体那个网站.
sni.png

Java 支持 SNI

Java 从 JDK 7 开始支持 SNI. https://docs.oracle.com/javase/7/docs/technotes/guides/security/enhancements-7.html

Server Name Indication (SNI) for JSSE client: The Java SE 7 release supports the Server Name Indication (SNI) extension in the JSSE client. SNI is described in RFC 4366. This enables TLS clients to connect to virtual servers.

Java 中常见的2种连接关于 SNI 的实验

我们的应用使用的是 JDK 8, 那么为什么还缺少 SNI 呢? 这要归因于那段代码使用的是 Netty 库, Netty 对于 TLS 的处理是使用的 JDK 底层 API, 需要自己处理 SNI 这个参数.

通常在 Java 中我们会遇到如下两种 https连接方式: 1) 使用 Java 的 URL连接; 2) 使用 Netty 的连接. 于是我们实验了这2种方式, 在使用Java 的 URL 连接的时候, 它默认是带 SNI 的. 如果使用 Netty 的方式, 就需要手工设置 SslParameter 里面设置主机名. 否则 Netty 不会发送 SNI. 通过 tcp 抓包的方式, 我们可以验证这些信息.
实验代码:

import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.net.InetSocketAddress;
import java.net.MalformedURLException;
import java.net.URL;
import java.util.Collections;

import javax.net.ssl.HttpsURLConnection;
import javax.net.ssl.SNIHostName;
import javax.net.ssl.SSLEngine;
import javax.net.ssl.SSLException;
import javax.net.ssl.SSLParameters;

import io.netty.bootstrap.Bootstrap;
import io.netty.buffer.ByteBufAllocator;
import io.netty.buffer.Unpooled;
import io.netty.channel.Channel;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.EventLoopGroup;
import io.netty.channel.SimpleChannelInboundHandler;
import io.netty.channel.nio.NioEventLoopGroup;
import io.netty.channel.socket.nio.NioSocketChannel;
import io.netty.handler.codec.http.DefaultFullHttpRequest;
import io.netty.handler.codec.http.FullHttpRequest;
import io.netty.handler.codec.http.HttpMethod;
import io.netty.handler.codec.http.HttpVersion;
import io.netty.handler.ssl.SslContext;
import io.netty.handler.ssl.SslContextBuilder;
import io.netty.handler.ssl.SslHandler;
import io.netty.handler.ssl.SslProvider;

public class Test {
    public static void main(String[] args) throws IOException, InterruptedException {
        //Test.testHttpsUrlSni();
        Test.testNettyHttpsSni();
    }

    public static void testHttpsUrlSni() throws IOException {
        URL u = new URL("https://www.tianxiaohui.com/");
        HttpsURLConnection http = (HttpsURLConnection) u.openConnection();
        http.setAllowUserInteraction(true);
        http.setRequestMethod("GET");
        http.connect();

        try (InputStream is = http.getInputStream();
                BufferedReader reader = new BufferedReader(new InputStreamReader(is))) {

            StringBuilder stringBuilder = new StringBuilder();
            String line = null;
            while (null != (line = reader.readLine())) {
                stringBuilder.append(line + "\n");
            }
            System.out.println(stringBuilder.toString());
        }

        System.out.println("***************Https testing completed **************");
    }

    public static void testNettyHttpsSni() throws SSLException, InterruptedException {
        EventLoopGroup childGroup = new NioEventLoopGroup();

        // SSL Parameters to set SNI TLS Extension

        SSLParameters sslParameters = new SSLParameters();
        sslParameters.setServerNames(Collections.singletonList(new SNIHostName("facebook.com")));

        // Build SSLContext for Client
        SslContext sslContext = SslContextBuilder.forClient().sslProvider(SslProvider.JDK).build();

        // SSLEngine with SSL Parameters for SNI
        SSLEngine sslEngine = sslContext.newEngine(ByteBufAllocator.DEFAULT);
        // sslEngine.setSSLParameters(sslParameters);//是否设置在这里

        // SSL Handler
        SslHandler sslHandler = new SslHandler(sslEngine);

        Bootstrap bootstrap = new Bootstrap();
        bootstrap.group(childGroup).channel(NioSocketChannel.class).handler(new SimpleChannelInboundHandler<>() {
            @Override
            protected void channelRead0(ChannelHandlerContext ctx, Object msg) throws Exception {
                // JUST RANDOM CODE TO MAKE TLS REQUEST
                FullHttpRequest fullHttpRequest = new DefaultFullHttpRequest(HttpVersion.HTTP_1_1, HttpMethod.GET, "/",
                        Unpooled.EMPTY_BUFFER);
                ctx.writeAndFlush(fullHttpRequest);
            }
        });

        Channel ch = bootstrap.connect(new InetSocketAddress("tianxiaohui.com", 443)).sync().channel();
        ch.pipeline().addFirst(sslHandler);
    }

错误的使用 CompletionService 导致的内存泄漏

有开发人员发现他们的某些 server 上的业务时间偶尔变长, 再看 gc overhead 指标, 发现已经超过10%, 怀疑内存泄漏. 通过对 GC 日志的分析, heap dump的分析, 我们找到泄漏的根本原因.


  1. 首先看数据趋势, 可以看到业务时间从某个时间点之后变长, CPU 跟着增加, CPU 增加的原因就在于 GC 的耗时增加;
    perfSimple.png
  2. 看 verbose GC log 的具体日志, 我们可以看到 CMS GC 老年代的频率很高, 耗时也很多. 从34s 到52s 就要做3次老年代的 GC, 说明每次回收都无法获得足够多的空闲内存, 只能加快回收.

    2021-11-17T09:39:34.726-0700: 1459219.285: [CMS-concurrent-mark-start]
    2021-11-17T09:39:37.142-0700: 1459221.701: [CMS-concurrent-mark: 2.408/2.416 secs] [Times: user=2.90 sys=0.04, real=2.42 secs] 
    ...
    2021-11-17T09:39:37.434-0700: 1459221.993: [CMS-concurrent-sweep-start]
    2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-sweep: 1.616/1.621 secs] [Times: user=1.90 sys=0.00, real=1.62 secs] 
    2021-11-17T09:39:39.055-0700: 1459223.614: [CMS-concurrent-reset-start]
    2021-11-17T09:39:39.059-0700: 1459223.618: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
    2021-11-17T09:39:41.063-0700: 1459225.622: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1348577K(1433600K)] 1792358K(2170880K), 0.1895637 secs] [Times: user=0.75 sys=0.00, real=0.19 secs] 
    ...
    2021-11-17T09:39:41.253-0700: 1459225.811: [CMS-concurrent-mark-start]
    2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-mark: 2.375/2.379 secs] [Times: user=2.84 sys=0.01, real=2.38 secs] 
    2021-11-17T09:39:43.632-0700: 1459228.191: [CMS-concurrent-preclean-start]
    ...
    2021-11-17T09:39:44.000-0700: 1459228.559: [CMS-concurrent-sweep-start]
    2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-sweep: 1.590/1.590 secs] [Times: user=1.81 sys=0.01, real=1.60 secs] 
    2021-11-17T09:39:45.590-0700: 1459230.149: [CMS-concurrent-reset-start]
    2021-11-17T09:39:45.594-0700: 1459230.153: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
    ...
    2021-11-17T09:39:52.122-0700: 1459236.681: [CMS-concurrent-mark-start]
  3. 捕获一个 heap dump, 从 heap dump 的 leak 分析可以看到 ClassLoader 保持的内存过多, 通常情况下 ClassLoader 只是引用类定义, 但是它可以通过 static 字段引用实例对象. 下面的 ClassLoader 使用了660M+ 内存, 具有很大的可疑. 如果我们不是很确定, 可以有2个办法来确定: 1) 重启服务器, 等服务器稳定运行在做一个 heap dump, 对比二者的这个 ClassLoader 使用的内存数量, 是不是差别比较大. 2) 增大 heap size, 让它一直运行, 直到再出现问题, 这时候这个 ClassLoader 使用的内存会更大.
    leak.png
  4. 从这个 ClassLoader 出发, 我们找到了对象的聚集地: ClassLoader -> BulkGet*Processer Class -> completionService -> CompletionQueue.
    accumulate.pngrefs.png
  5. 那么为什么这个 CompletionQueue 里这么多对象呢? 为什么不能回收?
    原来在代码 BulkGet*Processer 类里面, 定义了一个静态的 CompletionService, 当有 request 要处理的时候, 就把 Task submit 到这个 completionService 里面, 可是这个没有去拿结果. 可是 CompletionService 是要求把结果都要通过 poll 或 take 取出来, 然后才能从 completionQueue 结果集里面去除这个结果. 因为没有去拿这个结果, 结果导致它的 CompletionQueue 的结果越来越多, 最后把老年代占满.

由一个 LB 错误配置导致的 site issue 引发的思考

有个内部员工报了一个 issue, 支付成功之后, 弹出支付成功, 可是还能看到 "支付" 按钮. 过一段时间刷新页面, 还仍旧能看到那个"支付"按钮. 找到对应的开发团队, 开发团队检查之后, 发现整体趋势没有看到任何问题, 特地检查他这一笔, 发现有个事件通知的消息没有消费成功. 到底哪里出问题了? 诊断这种问题从架构/设计/实现技术角度有没有更好的办法?


开发团队仔细检查这笔交易, 发现支付成功之后, 有个支付成功的异步消息需要被某个 service 应用A 去消费, 应用A 消费这个消息的时候, 需要调用下游某个应用B, 可是调用应用B 的时候, 应用B 返回了 403, 导致整个事件没有被成功消费. 索性有不断的重试机制, 过了一段使用后这个事件被成功消费了.

那么问题变成了: 为什么一开始应用B 返回 403, 后来又调用成功了呢?

在应用A 的日志里, 能看到应用B 返回了 403, 但是日志里面没有抛出任何 error/Exception, 这导致应用A 里很难过滤并聚集这种错误类型. 同时整个处理的 Transaction 虽然失败了, 没有消费成功, 可是这个业务却没有报任何错误. 这种吃掉异常的错误做法导致有问题很难被发现.

在应用A 的日志里, 虽然有些 403, 但是没有给出更多信息. 通常我们的应用都会返回一个 unique 的 logID, 它能唯一定位整个 site 的唯一条业务的日志, 虽然这个 403 在 header 里返回了这个 logID, 但是却没有打印出来, 导致不能很快定位到有问题的下游日志. 所以, 我们推荐在平时返回 2xx 的时候, 这些 logID 可以不打印日志, 但是一旦非 2xx, 打印出请求的 header & payload 以及 response 的 header & payload 非常重要.

尝试在已知的下游应用的日志里面搜索某些特定 ID 去查找服务端的处理日志, 不断的扩大范围, 总是找不到. 这个时候就想在客户端应用A 这边是不是通过抓 tcp 包的形式, 能抓到具体的 request/response. 通常这些下游应用的 endpoint 都可以通过某些管理页面暴露出来, 可是这个 servcie 调用竟然不遵循常规的协议, 没有暴露出来. 只能尝试通过查看网络连接状态的方式去模糊匹配. 由于这个到下游的连接并不多, 也不是长连接(keep-alive) 导致几乎找不到一个模糊匹配的. 最后通过查看Java 的 DNS 的 history 信息, 模糊匹配到一条记录. 这里我们发现几个问题: 1) 如果请求不是特别少, 使用长连接(keep-alive) 没有什么坏处; 2) 遵循常规的协议, 方便大家按照统一的思路去查问题.

通过对找到的这个 endpoint 的 IP 地址抓包, 我们找到了几条返回 403 请求的 response, response header 里面的 logID 帮助我们很快定位到了下游处理这个请求的日志. 非常奇特的是: 这个服务端的 server 竟然是另外一个 service 的server. 也就是说我们使用的 endpoint 是对的, 不过这个 endpoint 的 LB 后面错误挂了另外一个 service 的 server 去处理这个请求. 所幸的是这个是 http 的请求, 不是 https, 我们抓包很容易就能看到具体的 request/response. 如果是 https, 那么就导致要通过代码注入的方式去观察更多日志了.

到此, 如何导致了这个问题, 从 LB 错配之后基本搞明白. 就是 LB 后边错挂了一个 server, 导致如果命中这个 server 那么就有问题, 否则就是好的. 因为是处理异步事件, 不成功会继续尝试, 只要不是一直命中这个错误的 server, 总归会成功.

获得

  1. 有任何错误, 请一定不要吃掉, 请及时报告, 写到日志里面标记出来;
  2. 微服务的环境里如果有调用非 2xx 的response, 最好把 request 的 header & payload 以及 response 的 header & payload 都打印出来, 方便查看原因或重试;
  3. 如果有共同的规范暴露一些信息, 请遵循特定的规范, 它方便拍错.
  4. 大量的微服务, 一定要有办法通过某种方式把日志串起来, 比如通过 logID;
  5. 暴露最近查询的 DNS 非常有必要;
  6. 可以设置某些开关, 打印出错的更多信息.

为什么应用各项指标正常, 却不响应请求了?

收到告警, 发现有个应用里面有 4 台服务器(虚拟,非真实物理服务器)挂了. 幸亏这个服务后面的服务器足够多, 并没有什么影响. 同时去查看这个应用的各项指标, 都是正常. 即使显示挂了的这 4 台, CPU, 内存, tomcat 服务线程, 磁盘等各方面也是正常, 也就是说这 4 台服务器还在不断的主动更新自己的状态, 并且状态良好, 那么为什么检测告警这边认为他们挂了呢?


检测告警服务为什么认为这 4 台服务器挂了?

检测告警这边每分钟都在不断主动检测每台服务器的健康状况, 类似下面的 URL

http://host1.tianxiaohui.com:8080/status/health

每次访问, 总是不能建立连接, 导致检测告警这边认为这几台服务器挂了. 手工测试了一下这个 URL, 确实不能建立连接. 尝试任何其他合理的 URL, 总是不能建立连接.
这个服务根据是否管理端口,是否承接不同的来源的请求等, 实际上开了 4 个 http 端口, 分别是: 8080, 8081, 8082, 8083. 分别对 4 个端口测试, 发现只有 8081 端口还能正常访问. 服务检测只测试 8080, 所以它认为这 4 台服务器挂了.

为什么不能建立 http 连接?

为什么其它 3 个端口不能在连接 http 连接? 我们登上其中 1 台服务器, 查看连接状况, 发现特别多的 CLOSE_WAIT 状态的连接. 表明这些连接对方已经发了 FIN 准备断开, 可是我们服务器的进程这边还没发 FIN, 没有断开连接. 再次查看监听的端口方面, 看到如下的情况:

$ ss -l -t -n
State       Recv-Q       Send-Q     Local Address:Port                Peer Address:Port
LISTEN    101            100           *:8080                           *:*
LISTEN      0            100           *:8081                           *:*
LISTEN    101            100           *:8082                           *:*
LISTEN    101            100           *:8083                           *:*

上面只展示了我们监听的 4 个端口部分, 可以看到我们还在监听(listen) 4 个端口(8080, 8081,8082, 8083).

Send-Q 在 listen 的行表示当我们 open 这个 socket 的时候, 设置的 backlog 大小(参看 java.net.ServerSocket的构造函数). Java 默认值是 50, 可以自己设置, Tomcat 默认设置的值是 100, 也就是我们上面看到的值 100.

Recv-Q 表示 listen backlog 现在的连接数, 它表示 Linux 已经完成了 3 次握手, 从 syn backlog 移到 listen backlog, 可是应用程序还没有取走( accept()), 只能待在 listen backlog. 一旦应用程序(Tomcat)接受这个请求(accept()), 那么这个请求就会从 listen backlog 取走, 进入应用程序待处理队列, 同时 listen backlog 释放出一个位置. 通常你看到的这列的值都是 0, 因为应用处理的足够快, 如果是一个稍大值, 就要担心你的应用了.

从上面的结果看出, 我们的应用有问题, 导致 Recv-Q 满了. 通常情况下, Tomcat 处理 I/O 的线程会接收这个请求, 然后把这个请求放到自己的任务队列里, 然后 tomcat worker 线程会到任务队列去取任务执行. 如果这个 listen backlog 满了, 我们就不能再建立新的 tcp 连接, 就是我们遇到的这种情况. 那么我们的 Tomcat 处理 I/O 的线程到底怎么了?

Tomcat 处理 I/O 的线程怎么了?

当时为了做 RCA 分析, 又不影响服务, 我们选择了做 heap dump, 并且立即重启了服务. 从后面的 heap dump 可以看到, 我们的 8080, 8082, 8083 端口的 Tomcat I/O Acceptor 处理线程不见了, 只有 8081 端口的 I/O Acceptor 线程还活着.
tomcat_acceptor.png

不知道什么原因, 另外 3 个 Tomcat I/O 处理线程 Crash 了. 从其它指标看之前有段时间这 4 台机器发生过OOM, 也许相关, 可是相关的 log 已经被覆盖了.

关于 Linux 上 syn backlog, listen backlog, tomcat 处理队列, 参看: http://www.tianxiaohui.com/index.php/default/Tomcat-7-NIO-handling-request-on-Linux.html

有依赖的多层子任务共享固定数值的线程池导致业务卡死的问题

最近遇到多次有依赖的多层子任务共享固定数值的线程池导致业务卡死的问题, 这里简单描述一下这个场景.

如下图所示, 这里有一个请求进来, 它被拆分成 3 个子任务(task0, task1, task2) 分别去执行, 这 3 个子任务都是由一个包含 3 个线程的线程池 Pool_A 去执行. Tomcat 主线程分发完任务之后, 就等待 3 个子任务的完成结果.

同时, 这 3 个子任务由分别每个都派发出 3 个新任务, 所以我们看到 9 个 level 2 层的 sub-task. 同时这 9 个 sub-task 也是交由线程池 Pool_A 去执行.

一种可能产生的如下图的结果是:

  1. 当主线程产生 3 个子任务之后, task0, 和 task1 分别获得一个线程来执行, 并且产生了二层的 6 个子任务, 分别是 task0-0, task0-1, task0-2, task1-0, task1-1, task1-2.
  2. 这时共有 9 个任务, 其中一层任务 task0, task1 分别在执行, 并且在等他们的下层任务的结果, task3 没有被执行(我们假设任务并不是 FIFO 被执行).
  3. 第三个线程从已有的 7 个任务中先后选取了 task0-0, task0-1, task1-0, task1-2 去执行.
  4. 接着第三个线程选取了 第一层任务 task2, 然后接着也产生 3 个子任务, 分别是 task2-0, task2-1, task2-2. 然后它也 block 在了等它的 3 个二层子任务完成.
  5. 到此, 所有线程池 Pool_A 里面的线程全部被用光, 剩下的子任务没有线程在去执行,大家都变成了死等.

threadShares.png