背景
线上系统使用的数据库是MySQL，使用了replication，单master+多slave。应用程序使用Django框架，库使用了PyMySQL，读数据的操作采用读写分离的策略。
从库发生过几次故障，因此在计划通过代理访问MySQL。代理软件使用Nginx，结构如下图。
这里使用到Nginx stream代理，需要nginx版本支持，见这里。
问题
在测试环境中，部署了Nginx+MySQL后，接到开发的反馈说连接数据库间断性地出错，DBA求助协助调查。
提供的报错信息如下
......
OperationalError: (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")
还有
......
OperationalError(2013, 'Lost connection to MySQL server during query')
排查
之前没有的问题突然出现，觉得很奇怪，想着看能不能重现以下。于是先搭建了一个测试环境，跑个脚本。
测试环境
在出现问题的MySQL服务器上创建临时库和临时表。测试库取名nginx_tcp_test_db，测试表取名nginx_tcp。
mysql> create database nginx_tcp_test_db;
Query OK, 1 row affected (0.01 sec)
mysql> use nginx_tcp_test_db;
Database changed
mysql> show tables;
Empty set (0.00 sec)
mysql> create table nginx_tcp(id int, name varchar(64), location varchar(64), extra blob);
Query OK, 0 rows affected (0.00 sec)
采用PyMySQL编写脚本，脚本的任务很简单：建立新连接，先写入，再读取。
try:
connection = pymysql.connect(
host=_args.host,
user=_args.user,
port=_args.port,
password=_args.password,
db=_args.database,
)
try:
with connection.cursor() as cursor:
connection.begin()
sql = "INSERT INTO `nginx_tcp` (`id`, `name`, `location`, `extra`) VALUES (2, '2', '2', '32');"
cursor.execute(sql)
connection.commit()
with connection.cursor() as cursor:
sql = "SELECT `id`, `name` FROM `nginx_tcp` limit 100"
cursor.execute(sql)
cursor.fetchall()
counter += 1
except Exception as ex:
traceback.print_exc()
end = time.time()
print('Total elapsed {0}, call count: {1}'.format(end-start, counter))
exit(2)
finally:
connection.close()
except Exception as ex:
traceback.print_exc()
end = time.time()
print('Total elapsed {0}, call count: {1}'.format(end - start, counter))
exit(2)
测试
通过Nginx代理到MySQL，执行脚本一段时间后，果然报了错。重复跑几次，总是能在运行一段时间后，调用pymysql.connect方法触发。
pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query ([Errno 104] Connection reset by peer)'
而直接连接MySQL就不会有问题。
重点查看PyMySQL中connect方法，和其中的方法调用关系，为达到直观效果，绘制图形。
from pycallgraph import PyCallGraph
from pycallgraph.output import GraphvizOutput
import pymysql
with PyCallGraph(output=GraphvizOutput()):
pymysql.connect(.....)
发现报错是在读socket的时候发生的错误。
同时查看出问题时候的Nginx日志，发现了大量下面的错误
......
54737 recv() not ready (11: Resource temporarily unavailable)
......
查看系统日志发现这样的错误
# dmesg
TCP: time wait bucket table overflow
.....
这时通过netstat命令，发现确实有很多处于TIME_WAIT状态的连接，源IP为nginx服务器的IP，目的IP为MySQL服务器的IP。
测试脚本总是会主动断开连接，因此nginx上面的TIME_WAIT连接，只能是Nginx代理到MySQL后主动断开连接的结果。在TIME_WAIT数量超过一定限制时，nginx就会拒绝来自客户端的连接。
查看系统的net.ipv4.tcp_max_tw_buckets值，发现设置的偏小。因此增加这个值，同时改小net.ipv4.tcp_fin_timeout这个值，让Nginx主动关闭后的连接处于TIME_WAIT的时间变短。
修改完后再跑测试脚本，单点的情况下就没有出现问题了。
并发测试
解决了一个问题，但是另外一个问题：OperationalError: (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")并没有被重现出来。
于是尝试增叫并发连接。采用最简单的办法，启动多个进程跑之前的脚本。跑了一段时间后，却发现了另外一个问题。
OperationalError(2013, 'Lost connection to MySQL server during query')
老办法，继续查看Nginx的日志，果然有发现：
[crit] 167312#167312: *742108 connect() to 10.10.48.169:6606 failed (99: Cannot assign requested address)
再查看系统TIME_WAIT的连接数量，并没有超过之前的配置。但测试几次后发现，总是在TIME_WAIT接近50000这个值的时候，客户端出现这个错误。
这里自然想到了TCP/IP四元组，即系统通过(local_ip, local_port, remote_ip, remote_port)来标识一条链接，在这里nginx代理到MySQL的场景下，local_ip，remote_ip, remote_port都是确定的，因此瓶颈会在local_port。查看配置net.ipv4.ip_local_port_range，发现范围长度和出现问题的TIME_WAIT数量接近。但是因为TCP支持的端口号是一个16位无符号整数，最大值是65536，其中1024以下的端口还是留给系统服务的，因此用于nginx连接MySQL的端口数量是有限的。
这里考虑三种方法进行扩展：
- 在nginx上配置
SO_REUSEADDR，同时增加后端MySQL数量。 - 在nginx所在的服务器上配置多个IP，让nginx分别去监听这些IP，在将流量代理到MySQL的时候local_ip使用监听的IP。
- 增加nginx服务器，使用DNS轮询多个IP。
第一种显然是可行的，nginx提供了reuseport选项。
第二种可以用多网卡，也可以用单网卡配置多IP。这里采用的是单网卡多IP，但是没有成功，因为发现就算Nginx监听了两个IP，最后代理到MySQL的连接local_ip也只有一个。可能是配置的问题，这里没有深究。
第三种方案没有试验过，应该可行（毕竟主要工作还是排查bug。。。），当然这种情况可能就不需要nginx了。。
剩下的问题
然而还有一个问题OperationalError: (2006, "MySQL server has gone away (error(32, 'Broken pipe'))")无论怎么都无法重现。启用Google大法。
发现网上也有人遇到了类似的问题，见issue。下面有人指出，抛出这个异常一般有两种情况：
- 防火墙问题；
- 查询语句的问题
马上对其进行验证，首先是bad query，脚本如下：
.....
a = "".join(map(chr, (ord('a')+(y%26) for y in range(10000000))))
with connection.cursor() as cursor:
sql = "INSERT INTO `nginx_tcp` (`id`, `name`, `location`, `extra`) VALUES (2, '2', '2', %s)"
connection.commit()
.....
发现，果然复现了
OperationalError(2006, "MySQL server has gone away (error(32, 'Broken pipe'))")
异常。和同事沟通，确定了SQL不会有问题。
还剩下防火墙。同事发现最近服务器发生过迁移，DB和应用之间新增了一个防火墙，防火墙默认会关闭闲置连接（5分钟）。后续的推理就简单了：应用中采用了连接池，当闲置了5分钟的连接被拿出来使用时，就会发生这个问题了。
关闭防火墙后，联系开发同学进行测试，果然，问题不再复现。
后续
为了确保后续的部署不出问题，编写脚本创建连接池进行测试
class ConnectionPool:
def __init__(self, conf, max_pool_size=20):
self.max_pool_size = max_pool_size
self.pool = None
self.initialize_pool(conf)
def initialize_pool(self, conf):
self.pool = Queue.Queue(maxsize=self.max_pool_size)
for _ in range(0, self.max_pool_size):
connection = pymysql.connect(
host=conf.get('host', '127.0.0.1'),
user=conf.get('user'),
port=conf.get('port', 3306),
password=conf.get('password'),
db=conf.get('db')
)
connection.ping()
self.pool.put_nowait(connection)
def get_connection(self):
connection = self.pool.get(True)
connection.ping()
return connection
def return_connection(self, connection):
return self.pool.put_nowait(connection)
def destroy(self):
while not self.is_empty():
self.pool.get().close()
def is_empty(self):
return self.pool.empty()
def test(_args):
counter = 0
config = {....}
pool = ConnectionPool(conf=config)
.....
while True:
connection = pool.get_connection()
.......... do something .........
sleep(2)
pool.return_connection(connection)
总结
这次debug前后花掉了快两天的时间，得到了深刻的教训。
脱离了应用环境的debug就是耍流氓！！！
这次debug没有复现问题的原因就是复现环境和出现问题的环境不一致，导致浪费了大量时间，经验教训一定要牢记！！
欢迎大家关注我的微信公众号《派森公园》
