分类 Troubleshooting 相关 下的文章

Netty 抛出的 io.netty.util.internal.OutOfDirectMemoryError

最近遇到一个奇怪的Java direct memory 导致的 OutOfDirectMemoryError. 我们的应用程序在启动的时候, 明明设置了-XX:MaxDirectMemorySize=1G, 并且我们有持续的监控数据看到 direct memory 才用了不到10M, 就怎么爆出了io.netty.util.internal.OutOfDirectMemoryError 呢?

症状

日志里看到很多这样的错误:

msg=Root cause=OutOfDirectMemoryError: failed to allocate 4194304 byte(s) of direct memory (used: 1069547527, max: 1073741824)&st=io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 4194304 byte(s) of direct memory (used: 1069547527, max: 1073741824)
    at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:802)
    at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:731)
    at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:649)
    at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:624)
    at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:203)
    at io.netty.buffer.PoolArena.tcacheAllocateSmall(PoolArena.java:173)
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:134)
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:126)
    at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:394)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:188)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)
    at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:140)
    at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:120)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:150)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

初步诊断

上面的错误, 告诉我们以下一些细节:

  1. Java 应用程序的 direct memory 不够用了;
  2. direct memory 最大值是1G (1073741824), 已经使用1G (1069547527);
  3. 本次申请的用量是 4M (4194304 bytes);

大家知道 Java 提供了监控 direct memory 使用量的 MBean, 很多框架也支持持续导出这些数据形成时序 metrics. 下图是通过JDK 自带的 Jconsole 看到的 direct memory MBean 的数据: 6个 DirectByteBuffer, 共使用了49152 bytes.
mbeandirect.png
在服务器上使用 JConsole 不方便, 但是有很多命令行工具可以帮我们查看 MBean. 我们公司的框架暴露了这些数据为时序数据, 通过这些时序数据我们很容易看到, 我们的 direct memory 使用量不足10M. 所以这里矛盾的地方就是虽然我们设置了最大1G 的 direct memory, MBean 暴露的数据显示使用不到10M, 可是 Netty 却一直告诉我们1G 已经用完, 并且抛出 OutOfDirectMemoryError.

读 Netty 代码

根据出错栈, 我们找到了 Netty 的代码: io.netty.util.internal.PlatformDependent.incrementMemoryCounter.

    private static void incrementMemoryCounter(int capacity) {
        if (DIRECT_MEMORY_COUNTER != null) {
            long newUsedMemory = DIRECT_MEMORY_COUNTER.addAndGet(capacity);
            if (newUsedMemory > DIRECT_MEMORY_LIMIT) {
                DIRECT_MEMORY_COUNTER.addAndGet(-capacity);
                throw new OutOfDirectMemoryError("failed to allocate " + capacity
                        + " byte(s) of direct memory (used: " + (newUsedMemory - capacity)
                        + ", max: " + DIRECT_MEMORY_LIMIT + ')');
            }
        }
    }

根据这段代码, 我们注意到: DIRECT_MEMORY_LIMIT 在我们的情况下, 就是我们设置的 MaxDirectMemorySize 的值, 就是1G. DIRECT_MEMORY_COUNTER 就是 Netty 使用的 direct memory 的数量.
我们最初看到的那个 OutOfDirectMemoryError 就是这段代码抛出的. 很明显, 再加上那申请的4M, 就超过了1G 的最大限制. 为了验证我们说的情况, 我们事后做了一个 heap dump, 虽然当时没有抛出OutOfDirectMemoryError, MBean 显示的 direct memory 也只使用了4M多. 可是 DIRECT_MEMORY_COUNTER 的值, 却显示已经使用了490M 多:
heap.png

为什么MBean 报出的 direct memory 使用量和 Netty 的 DIRECT_MEMORY_COUNTER 的值不一样?

为了找出二者之间的差异, 我们要分别看下他们是怎么统计的.

MBean 的 direct memory 的统计方式

JDK 的 BufferPoolMXBean 统计 direct/mapper 的 memory 使用量, 它作为一个接口, 真正的实现类可以在 JDK 找到. sun.management.ManagementFactoryHelper (JDK8) 里面就有一个实现类:

private static BufferPoolMXBean
        createBufferPoolMXBean(final sun.misc.JavaNioAccess.BufferPool pool)
    {
        return new BufferPoolMXBean() {
            private volatile ObjectName objname;  // created lazily
            @Override
            public ObjectName getObjectName() {
                ObjectName result = objname;
                if (result == null) {
                    synchronized (this) {
                        result = objname;
                        if (result == null) {
                            result = Util.newObjectName(BUFFER_POOL_MXBEAN_NAME +
                                ",name=" + pool.getName());
                            objname = result;
                        }
                    }
                }
                return result;
            }
            @Override
            public String getName() {
                return pool.getName();
            }
            @Override
            public long getCount() {
                return pool.getCount();
            }
            @Override
            public long getTotalCapacity() {
                return pool.getTotalCapacity();
            }
            @Override
            public long getMemoryUsed() {
                return pool.getMemoryUsed();
            }
        };
    }

从上面代码可以看出, 真正的使用量, 都是从sun.misc.JavaNioAccess.BufferPool获得, 沿着这个线索找下去, 就在java.nio.Bits里面找到2个BufferPool的真正实现, 分别记录了 direct/mapper 的使用量. 其中, direct memory 的 count, totalCapacity 和 memory used 分别是由 Bits 的 count, totalCapacity 和 reservedMemory记录.

return new sun.misc.JavaNioAccess.BufferPool() {
    @Override
    public String getName() {
        return "direct";
    }
    @Override
    public long getCount() {
        return Bits.count.get();
    }
    @Override
    public long getTotalCapacity() {
        return Bits.totalCapacity.get();
    }
    @Override
    public long getMemoryUsed() {
        return Bits.reservedMemory.get();
    }
};                       

我们单追踪 Bits.reservedMemory 是怎么 track 已经使用量的:

DirectByteBuffer(int cap) {                   // package-private
        super(-1, 0, cap, cap);
        //省略其它无关代码
        Bits.reserveMemory(size, cap);
  }

从上面的代码可以看到, 每当 java.nio.DirectByteBuffer 初始化的时候, 它都会调用 Bits.reserveMemory 代码去 track 内存使用量. 这样当我们想查看 direct memory 使用量的时候, 只要查看 Bits 的记录数据就好了.

Netty 的 DIRECT_MEMORY_COUNTER 的统计方式

DIRECT_MEMORY_COUNTER 的统计方式比较直观, 它只在 PlatformDependent 内部被使用. 每当想要申请一块新的 direct 内存时候, 它就调用 incrementMemoryCounter 方法去增加 DIRECT_MEMORY_COUNTER 的值.

原因

所以, 虽然他们都以 MaxDirectMemorySize 为最大值, 但是都看不到对方的存在, 都只统计自己知道的使用量. 所以这导致我们看到 MBean 里面暴露的值和真正的使用量并不一样.

扩展 - 有关 ByteBuffer

JDK 里面的ByteBuffer 的数据结构有下图, Buffer 是一个抽象类, 定义了通用的一些方法, 比如 limit(), reset(), mark(), flip(), rewind(), isDirect(), 等. 然后 Buffer 下面定义了 primitive 类型对应的各种 Buffer 类. ByteBuffer 又分为在 heap 的 HeapByteBuffer 和在直接内存的 MappedByteBuffer & DirectByteBuffer. 下面以 R 结尾的 ByteBuffer 代表 read only 的 ByteBuffer.
ByteBuffer.png

扩展 - Netty 自己的 metrics 如何暴露这些数据的

Netty 本来提供了一个 metrics, 只是需要自己把这些 metrics 数据导出. metrics 数据通过PooledByteBufAllocatorMetric 暴露.

查看 DNS 查询记录

要使用外部服务, 就要连接外部 endpoint, 通常我们都是用 FQDN 去连接外部, 偶尔直接使用 IP 地址. 如果使用 FQDN, 那么就涉及 DNS 查询. 通常 DNS 记录都有 TTL (time to live)时限, 时限一过, 就要重新 DNS 查询.
使用 dig 命令可以查看一条 DNS 记录的 ttl:

$ dig +nocmd +noall +answer +ttlid a www.tianxiaohui.com
www.tianxiaohui.com.    389    IN    A    103.144.218.
$ dig +nocmd +noall +answer +ttlid a www.baidu.com
www.baidu.com.        1200    IN    CNAME    www.a.shifen.com.
www.a.shifen.com.    239    IN    CNAME    www.wshifen.com.
www.wshifen.com.    239    IN    A    45.113.192.102
www.wshifen.com.    239    IN    A    45.113.192.101

上面结果第二列就是 ttl, 单位是秒.

如何查看 Linux 上的 DNS 查询

使用 tcpdump 查看 53 端口的流量, 就能查看 DNS 查询记录 (

$ sudo tcpdump -l port 53  # -l 表示使用 buffer
06:29:08.312928 IP 10.226.197.72.40898 > sin-dns.tianxiaohui.com.domain: 42885+ A? firestore.googleapis.com. (42)
06:29:08.422806 IP sin-dns.tianxiaohui.com.domain > 10.226.197.72.40898: 42885 1/0/0 A 142.250.4.95 (58)
06:29:45.507982 IP 10.226.197.72.5013 > sin-dns.tianxiaohui.com.domain: 2509+ A? github.com. (28)
06:29:45.575657 IP sin-dns.tianxiaohui.com.domain > 10.226.197.72.5013: 2509 1/0/0 A 20.205.243.166 (44)
06:29:45.576415 IP 10.226.197.72.42090 > sin-dns.tianxiaohui.com.domain: 64400+ A? github.com. (28)
06:29:45.640234 IP sin-dns.tianxiaohui.com.domain > 10.226.197.72.42090: 64400 1/0/0 A 20.205.243.166 (44)
06:30:05.738311 IP 10.226.197.72.54902 > sin-dns.tianxiaohui.com.domain: 51140+ A? translate.google.com. (38)

如何查看一个 Java 应用程序的 DNS 查询

Java 应用程序的 DNS 最近的查询记录都记录在 InetAddress 类的某个字段中, 所以对这个字段读, 或者你有一个 heap dump, 查看这个字段, 就能查看到最近的 DNS 记录. 详细的方法, 可以查看这段代码:
https://github.com/manecocomph/myJavaAgent/blob/master/src/com/tianxiaohui/java/agent/SampleAgent.java#L191

使用 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. 可以设置某些开关, 打印出错的更多信息.