Author: claudecode+opus4.6

Connection: close 排障记录

OSG 网关 Tomcat BIO 线程池耗尽导致 keep-alive 连接被提前关闭的排查与修复

问题描述

使用（Tomcat 7.0.39）做了一个 HTTP 转发网关，前端 Nginx 通过 keep-alive 长连接将请求转发到 Tomcat 。观察到 keep-alive 连接在远低于 maxKeepAliveRequests（1000）设定值时就被关闭，通常处理不到 10 个请求后响应中就出现 Connection: close，导致 Nginx 频繁重建 TCP 连接。

环境信息：

组件	版本/配置
Tomcat	7.0.39
Connector	BIO (`protocol="HTTP/1.1"`)
maxThreads	150
maxKeepAliveRequests	1000
前端	Nginx (keep-alive)

最终结论

根因：Tomcat 使用 BIO connector（protocol="HTTP/1.1"），maxThreads=150，而实际 TCP 连接数达到 388。BIO 下每个连接（包括空闲 keep-alive）占一个线程，线程池严重不足，Tomcat 被迫主动关闭 keep-alive 回收线程。

修复：将 protocol="HTTP/1.1" 改为 protocol="org.apache.coyote.http11.Http11NioProtocol"，切换后问题立即消失。

排查过程

第一步：确认 Connection: close 来源是代码还是 Tomcat

分析代码中 Response Header 的处理逻辑。

GateRequestExecutor.isValidGateResponseHeader() 方法过滤了后端返回的以下 header：

// osg-scripts/src/main/groovy/scripts/route/GateRequestExecutor.groovy:471
boolean isValidGateResponseHeader(String name) {
    switch (name.toLowerCase()) {
        case "connection":           // ← 后端返回的 Connection header 被过滤
        case "content-length":
        case "content-encoding":
        case "server":
        case "transfer-encoding":
        case "access-control-allow-origin":
        case "access-control-allow-headers":
            return false
        default:
            return true
    }
}

结论：后端返回的 Connection header 被代码过滤掉了，不会透传给客户端。响应中出现的 Connection: close 只可能来自 Tomcat 自身。

第二步：tcpdump 抓包分析

在服务器上抓取了一个完整的 TCP 连接（从 SYN 到 FIN）。

抓包结果：

来源：10.145.1.100:13032 → 10.1.1.100:80
完整 TCP 三次握手（SYN → SYN-ACK → ACK）
7 个 HTTP 请求，全部 HTTP/1.1，请求头中没有 Connection: close
7 个响应，前 6 个正常，第 7 个响应带 Connection: close
所有 7 个响应状态码均为 200 OK

请求1: POST /api/GetApp     → 200 OK
请求2: POST /api/GetRoute   → 200 OK
请求3: POST /api/GetPage                 → 200 OK
请求4: POST /api/abapi                       → 200 OK
请求5: POST /api/GetGroup   → 200 OK
请求6: POST /api/12345
请求7: POST /api/GetGroup   → 200 OK + Connection: close ⚠️

结论：排除了请求头 Connection: close、HTTP/1.0、非 200 状态码等原因。

第三步：检查 server.xml 配置

grep -i "keepAlive\|Connector" conf/server.xml

确认 maxKeepAliveRequests="1000"。7 个请求远未达到 1000 的上限，排除 maxKeepAliveRequests 耗尽。

同时确认 maxThreads="150"。

第四步：分析 Tomcat 源码

阅读 Tomcat 7.0.39 AbstractHttp11Processor.java 源码，找到所有设置 keepAlive = false 的条件：

#	条件	是否排除
1	`maxKeepAliveRequests` 计数器耗尽	✅ 已排除（7 « 1000）
2	HTTP/1.0 且无 `Connection: keep-alive`	✅ 已排除（HTTP/1.1）
3	请求头中包含 `Connection: close`	✅ 已排除（抓包确认无）
4	`statusDropsConnection(statusCode)` 返回 true	✅ 已排除（全是 200）
5	`response.getErrorException()` 不为 null	❓ 待确认

statusDropsConnection 触发的状态码：400, 408, 411, 413, 414, 500, 501, 503

第五步：检查生产错误日志

查看 catalina.out 中的错误日志，发现三类频繁出现的异常：

Hystrix 信号量拒绝：could not acquire a semaphore for execution → 映射为 406
ServiceTimeDeny：Sorry Your Openid is denied on currentTime → 映射为 403
JSON 解析异常：com.alibaba.fastjson.JSONException → 在 ServiceAuthority.doVerify() 中被 try-catch 吞掉，不会导致 500

初步怀疑是错误状态码触发了 statusDropsConnection()，但与 tcpdump 中全部 200 的事实矛盾。

第六步：添加调试日志

在 SendResponse.groovy 和 GateServlet.java 中添加 CONNECTION_DEBUG 日志，通过反射读取 Tomcat Http11Processor 内部状态：

采集字段	含义
`keepAlive`	Tomcat 是否保持连接
`keepAliveLeft`	剩余 keepAlive 次数
`error` / `errorException`	内部错误状态
`openSocket` / `keptAlive`	连接状态

日志分别在 BEFORE_WRITE（写响应前）和 AFTER_WRITE（写响应后）两个时机采集，用于判断 keepAlive 是在哪个阶段被设为 false。

日志输出到独立文件 logs/conn-debug.log（logback 中配置独立 appender，logger name = CONNECTION_DEBUG，level = INFO，additivity=false）。

第七步：分析调试日志 — 发现两种模式

部署后采集了 1 秒的日志（3566 行），发现 keepAlive=false 有两种不同的模式：

模式一：BEFORE_WRITE 时 keepAlive 就已经是 false

BEFORE_WRITE uri=/api/ops_hr_getEmployee, keepAlive=false, keepAliveLeft=-1
AFTER_WRITE_RESPONSE uri=/api/ops_hr_getEmployee, finalStatus=200

特征：keepAliveLeft=-1，响应状态码 200，但 keepAlive 在请求解析阶段就被关闭。

模式二：AFTER_WRITE 后 keepAlive 才变为 false

BEFORE_WRITE uri=/api/ckapi, keepAlive=true, keepAliveLeft=993
AFTER_HEADERS uri=/api/ckapi, status=400
AFTER_WRITE  uri=/api/ckapi, keepAlive=false, keepAliveLeft=993

特征：keepAliveLeft 为正数，由 statusDropsConnection(400) 触发。

模式一是大量 200 响应带 Connection: close 的主因，与 tcpdump 观察一致。

第八步：检查服务器连接数和线程数

$ ss -tnp | grep :80 | wc -l
388

$ grep -i "maxThreads" conf/server.xml
maxThreads="150"

关键发现：388 个 TCP 连接，150 个线程。BIO connector 下每个连接（包括空闲 keep-alive）占一个线程，线程池严重超载。

conn-debug.log 中线程名从 http-bio-80-exec-1 到 http-bio-80-exec-187，确认使用 BIO connector。

第九步：确认根因 — BIO 线程池耗尽

BIO connector 的工作模式：

┌─────────────────────────────────────────────────────────┐
│  BIO: 每个 TCP 连接绑定一个线程                            │
│                                                         │
│  连接1 ──→ 线程1 (处理请求 / 空闲等待)                     │
│  连接2 ──→ 线程2 (处理请求 / 空闲等待)                     │
│  ...                                                    │
│  连接150 ──→ 线程150 (处理请求 / 空闲等待)                 │
│  连接151 ──→ ❌ 无可用线程！触发自我保护                    │
│                                                         │
│  自我保护：keepAlive=false, keepAliveLeft=-1              │
│           强制关闭 keep-alive 连接以回收线程               │
└─────────────────────────────────────────────────────────┘

这解释了所有观察到的现象：

现象	解释
随机性	取决于当时线程池的繁忙程度
<10 次请求就关闭	不是 maxKeepAliveRequests 的限制，是线程不够用
200 响应也带 Connection: close	跟请求结果无关，是线程压力导致

第十步：修复验证

修改 server.xml，将 BIO 切换为 NIO：

<!-- 修复前 -->
<Connector port="80" protocol="HTTP/1.1"
           maxThreads="150" maxKeepAliveRequests="1000" ... />

<!-- 修复后 -->
<Connector port="80" protocol="org.apache.coyote.http11.Http11NioProtocol"
           maxThreads="150" maxKeepAliveRequests="1000" ... />

NIO connector 使用 I/O 多路复用，空闲 keep-alive 连接不占线程。150 个线程可以服务数千个 keep-alive 连接。

重启后 Connection: close 提前关闭的问题消失。 ✅

排查中的错误推断

记录排查过程中走过的弯路，供参考：

#	错误推断	实际情况
1	maxKeepAliveRequests=7	tcpdump 显示 7 个请求后关闭，最初猜测配置为 7。实际是 1000
2	Tomcat 高负载自动降低 keepAlive	查阅源码未找到该机制（但 BIO 确实有线程压力保护行为）
3	JSON 解析异常导致 500	`ServiceAuthority.doVerify()` 中 JSONException 被 try-catch 吞掉，不会冒泡
4	错误状态码是主因	`statusDropsConnection` 只影响少量出错请求（模式二），主因是 BIO 线程池耗尽（模式一）

	BIO (`HTTP/1.1`)	NIO (`Http11NioProtocol`)
线程模型	1 连接 = 1 线程	I/O 多路复用，线程仅在有数据时使用
keep-alive 空闲连接	占线程	不占线程
maxThreads=150 能服务的连接	~150	数千
适用场景	低并发、短连接	高并发、长连接

续：切换 NIO 之后剩余的短连接分析（2026-06-08）

切换到 Http11NioProtocol 之后，原先大量”建连即关闭”的 syn/fin 对显著减少，但仍能观察到一部分 TCP 连接生命周期很短、只承载一个请求就被关掉。再次抓包分析。

抓包时间轴

# tcpdump -nn -r /tmp/10.115.39.142.dump -A 'port 46160'

时刻	事件
18:45:38.844133	client SYN
18:45:38.844242	三次握手完成
18:45:38.844259	client 发出 `POST /api/CMSGetServer/?_version=new`
18:45:38.854101 – .854188	server 分多段返回 200 OK（chunked）
18:45:38.854253	client ACK 最后一段
18:45:59.233153	server 主动发 FIN
18:45:59.233264	client 回 FIN-ACK

请求侧关键信息：

User-Agent: Java/25
没有 Connection: close
HTTP/1.1
响应 200 OK，无 Connection: close

关键差异

这个连接并不是”建连后立刻 finish”：

实际存活 20.379 秒
server 端（10.108.4.10:80）先发 FIN
期间只承载 1 个 HTTP 请求

20.4 秒几乎一定是 Tomcat 的 keepAliveTimeout 计时器到期。Tomcat NIO 默认 keepAliveTimeout = connectionTimeout = 20000ms，与抓包 idle 时长完全吻合。

也就是说，server 这一侧的行为是完全正常的：HTTP/1.1 keep-alive，连接处理完一个请求后空闲 20s 没有新请求，服务端按配置主动回收。

真正异常的地方在 client 侧

这条连接只承载 1 个请求就被晾在那里 20s 等回收，相当于”用一次就丢”。这才是切换 NIO 后剩余 syn/fin 对偏多的根本原因——client 没有复用连接。

可能的原因：

User-Agent: Java/25 是 java.net.HttpURLConnection 的默认 UA（Apache HttpClient / OkHttp 都会换成自己的 UA）。HttpURLConnection 的 keep-alive 复用条件很苛刻：
- 必须把响应 InputStream 完整读到 EOF 并 close
- 不能调用 disconnect()（直接关流）
- http.maxConnections（默认 5）和 http.keepAlive=true 都得满足
- 任何一个条件不满足，连接就不进 KeepAliveCache
请求频率与超时不匹配：如果调用方是定时任务/批处理（> 20s 一次），无论池子做得多好，下一次请求来时连接已被回收
短生命周期 JVM：CLI / Job 进程退出时连接池一起销毁，等价于每次都新建

排查方向

优先级	方向	说明
高	确认 client 是谁、用什么 HTTP 库	10.115.39.142 上跑的什么应用？是 `HttpURLConnection` / Apache HttpClient / OkHttp / `RestTemplate`？是否启用连接池
高	看请求间隔分布	server 侧按源 IP+UA 聚合：P50 间隔 > 20s 时再优化复用也救不了
中	server 侧调大超时（兜底）	`keepAliveTimeout="60000"`、`maxKeepAliveRequests="-1"`；权衡 worker/socket 资源
中	client 改造（`HttpURLConnection`）	避免 `disconnect()`、完整消费响应体；或改造为 Apache HttpClient / OkHttp + `PoolingHttpClientConnectionManager`
低	验证	抓同一 client 的连接序列，看是否在打开新连接前已有可复用的 ESTABLISHED 连接

小结

	第一次排查（BIO）	续：NIO 之后剩余的短连接
现象	200 响应也带 `Connection: close`	响应不带 `Connection: close`，但连接只用 1 次
触发方	server (Tomcat 自保护)	server (keep-alive timeout)
时间特征	一条连接处理 < 10 个请求即关闭	单请求 + 20s 空闲 + server FIN
根因	BIO 线程池耗尽	client 没有复用连接
修复方向	server 侧切 NIO	client 侧用连接池；server 侧调大 `keepAliveTimeout` 兜底

Tomcat Connection: close 排障记录

Connection: close 排障记录

目录

问题描述

最终结论

排查过程

第一步：确认 Connection: close 来源是代码还是 Tomcat

第二步：tcpdump 抓包分析

第三步：检查 server.xml 配置

第四步：分析 Tomcat 源码

第五步：检查生产错误日志

第六步：添加调试日志

第七步：分析调试日志 — 发现两种模式

模式一：BEFORE_WRITE 时 keepAlive 就已经是 false

模式二：AFTER_WRITE 后 keepAlive 才变为 false

第八步：检查服务器连接数和线程数

第九步：确认根因 — BIO 线程池耗尽

第十步：修复验证

排查中的错误推断

相关知识

Tomcat BIO vs NIO

statusDropsConnection 触发条件

续：切换 NIO 之后剩余的短连接分析（2026-06-08）

抓包时间轴

关键差异

真正异常的地方在 client 侧

排查方向

小结

Connection: close 排障记录

目录

问题描述

最终结论

排查过程

第一步：确认 Connection: close 来源是 代码还是 Tomcat

第二步：tcpdump 抓包分析

第三步：检查 server.xml 配置

第四步：分析 Tomcat 源码

第五步：检查生产错误日志

第六步：添加调试日志

第七步：分析调试日志 — 发现两种模式

模式一：BEFORE_WRITE 时 keepAlive 就已经是 false

模式二：AFTER_WRITE 后 keepAlive 才变为 false

第八步：检查服务器连接数和线程数

第九步：确认根因 — BIO 线程池耗尽

第十步：修复验证

排查中的错误推断

相关知识

Tomcat BIO vs NIO

statusDropsConnection 触发条件

续：切换 NIO 之后剩余的短连接分析（2026-06-08）

抓包时间轴

关键差异

真正异常的地方在 client 侧

排查方向

小结

第一步：确认 Connection: close 来源是代码还是 Tomcat