生产环境出现nginx502,导致十来分钟系统奔溃（Tp5.1的session bug）

问题概述

使用PHP的ThinkPHP5.1开发框架，生产环境使用宝塔管理，其中nginx直接报错502，继续时间10来分钟。而且通过观察，一段时间又会出现，特别是复杂频繁的操作。

排查数据

nginx抛出502,证明是它的反向代理出错，这个代理php-cgi挂掉了，我用的是php-fpm，出了问题。在宝塔默认php-fpm配置有设置日志输出

[global]
error_log = /www/server/php/72/var/log/php-fpm.log
[www]
slowlog = var/log/slow.log

php-fpm 配置

[global]
pid = /www/server/php/72/var/run/php-fpm.pid
error_log = /www/server/php/72/var/log/php-fpm.log
log_level = notice

[www]
listen = /tmp/php-cgi-72.sock
listen.backlog = -1
listen.allowed_clients = 127.0.0.1
listen.owner = www
listen.group = www
listen.mode = 0666
user = www
group = www
pm = dynamic
pm.status_path = /phpfpm_72_status
pm.max_children = 150
pm.start_servers = 30
pm.min_spare_servers = 30
pm.max_spare_servers = 150
request_terminate_timeout = 100
request_slowlog_timeout = 30
slowlog = var/log/slow.log

机器配置阿里云4 vCPU 8 GiB ( 共享计算型 n1, ecs.n1.large )，

查看php-fpm.log 部分内容

Fu0ZUUtbHNQ0b4nh7d2QN4_LJvtB

这张图显示，有两部分内容：

1、php-fpm worker进程由于处理的程序超过109s左右(环境request_terminate_timeout = 100)，进程发出的signal 15(SIGTERM)。对于signal 15(SIGTERM) 的 SIGTERM，查阅了下，是说：系统会发送一个SIGTERM的信号给对应的程序。当程序接收到该signal后，将会发生以下的事情：

1、程序立刻停止
2、该程序释放相应资源后再停止
3、程序可能仍然继续运行

大部分程序接收到SIGTERM信号后，会先释放自己的资源，然后在停止。但是也有程序可以在接受到信号量后，做一些其他的事情，并且这些事情是可以配置的。如果程序正在等待IO，可能就不会立马做出响应。也就是说，SIGTERM多半是会被阻塞的、忽略。

2、带有请求的具体链接，显示请求太慢，超过了39s(request_slowlog_timeout = 30),记录了log。

查看slow.log 部分内容

Fu0ZUUtbHNQ0b4nh7d2QN4_LJvtB

这张图显示，请求处理只到了框架初始代码和权限验证那块，并没用实际到达业务代码程序。可排除sql慢查询或者业务代码问题。

查看框架的TP5.1 log 部分内容

Fu0ZUUtbHNQ0b4nh7d2QN4_LJvtB

这张图显示，请求处理还没到csrf验证层就阻塞了!!!

面板进程情况

FnfJPvsSClmAGAbKGbCP2bhcVLI7

这张图显示是那个时间段抛出502宕机10来分钟php-fpm记录下来的status。数据显示，请求数量有53441,但是活跃进程数只有1个，并且产生了450个慢查询数量。

Session 阻塞

既然不是慢SQL产生的问题，并且有大量请求没有达到crsf验证层，只到达了crsf层上面的权限验证层，权限又是基于cookies和session的，那就推断是session阻塞引起的。什么会引起session阻塞呢？查阅了资料，并写下面代码在本地测试。

前端js code（三个请求ajax1、ajax2、ajax3同时进行）

<script src="https://cdn.bootcss.com/jquery/3.4.0/jquery.js"></script>
<script>
    var a = 1;
    var b = 1;
    var c = 1;
    function ajax1(){
        $.get('/hello?from=a', function(){
            console.log('a' , a);
            a++;
            ajax1();
        });
    }
    function ajax2(){
        $.get('/hello?from=b', function(){
            console.log('b',b);
            b++;
            ajax2();
        });
    }
    function ajax3(){
        $.get('/hello?from=c', function(){
            console.log('c',c);
            c++;
            ajax3();
        });
    }

    function beginAjax(){
        ajax1();
        ajax2();
        ajax3();
    }
    beginAjax();
</script>

TP5.1后端code

<?php
namespace app\index\controller;

use think\Controller;

class Index extends Controller
{
    public function index()
    {
        return $this->fetch();
    }

    public function hello($name = 'ThinkPHP5')
    {
        session('qanda','1'); //session是tp5.1的定义的方法
        sleep(5);
        return json(['data'=>session_id()]);
    }
}

php-fpm.conf配置

request_slowlog_timeout = 16
request_terminate_timeout = 20

火狐浏览器

火狐浏览器测试，偶尔会出现刚开始返回的session_id不一致问题同时响应的时间a,b,c三个不一样参数请求响应都在5s多一点，不过后面返回的session_id就一致了，同时响应的时间也变为了15s+了。

chrome浏览器

chrome浏览器刚开始返回的session_id就一致，但是耗时较长，后面趋于稳定的15s+。

将测试code放到Laravel6.2测试。

稳定输出5s+，那就是TP5.1的session出现bug了！！！

TP5.1的Session为什么会出现问题

Session阻塞的原因网上大部分说是session_start(),使用完记得session_write_close()。难道TP5.1使用了后没close??? 查看TP5.1源码：

1、 2、 3、

还真是TP5.1没close，这bug就很容易让系统处于502状态，竟然没人遇到过并且修复吗？反映并且提交issue修复！看了下最新的TP6,借鉴Laravel的Session、Cookies组件化了 TP的这个bug也就不存在了。

解决

系统还是要用，修改配置文件，用TP5.1 session锁，code 如下：

return [
    'id'             => '',
    // SESSION_ID的提交变量,解决flash上传跨域
    'var_session_id' => '',
    // SESSION 前缀
    'prefix'         => 'think',
    // 驱动方式 支持redis memcache memcached
    'type'           => '',
    // 是否自动开启 SESSION
    'auto_start'     => true,
    'use_lock'     => true,
];

修改后，响应时间正常了

注意与疑惑

注意

1、查到资料看到不是代码的引起的502，而是环境配置。 https://www.cnblogs.com/zenghansen/p/4647004.html

疑惑

1、为什么执行时间session_write_close不执行，返回时间会累加呢？

参考

本作品采用CC BY-NC-ND 4.0进行许可。转载，请注明原作者 chunpat 及本文源链接。