基于PDO的SESSION管理bug排查

最新推荐文章于 2025-09-05 16:58:34 发布

weixin_34161029

最新推荐文章于 2025-09-05 16:58:34 发布

阅读量99

点赞数

CC 4.0 BY-SA版权

文章标签： php 数据库 python

原文链接：https://my.oschina.net/merkerxu/blog/150223

文章详细记录了一次在Session管理中遇到的bug排查过程，包括发现并修正Session持久化参数设置错误导致的长连接不起作用问题，以及分析了Session GC函数不当执行导致用户随机登出的根源。最终通过调整Session处理逻辑，解决了随机登出问题，同时也揭示了日志记录的重要性及数据结构一致性对于避免bug的关键作用。

2019独角兽企业重金招聘Python工程师标准>>>

简介

最近做一个小网站，需要用户登录，发现用户登录后经常会莫名其妙随机地自动退出登录。本文简单记录一下这个bug排查的过程，希望以后尽量避免此类错误。

最初代码

SESSION数据是存放在数据库中，利用PDO处理读写过程，实现参考了SO和php手册中关于session的章节，最终的数据表结构和php代码如下:

数据表结构:

CREATE TABLE `sessions` (
  `session_id` varchar(40) NOT NULL DEFAULT '',
  `session_data` text NOT NULL,
  `expire_at` int(11) unsigned NOT NULL,
  UNIQUE KEY `session_id` (`session_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

用PDO实现的session处理：

/*
 * session db handler, based on pdo
 */
class SessionDBHandler
{
    /*
     * session table name
     */
    const SESSION_TABLE = 'sessions';

    /*
     * session data structure
     */
    const FIELD_SESSION_ID      = 'session_id';
    const FIELD_SESSION_DATA    = 'session_data';
    const FIELD_EXPIRE_AT       = 'expire_at';

    /*
     * session db config
     */
    private $config    = null;

    /*
     * session pdo
     */
    private $sess_pdo  = null;

    /*
     * session lifetime
     */
    private $sess_lifetime = 0;

    /*
     * default session max lifetime in seconds
     * max_lifetime  31536000=3600*24*365
     */
    const SESSION_MAX_LIFETIME = 31536000;

    /*
     * init db_conf and session maxlifetime
     * @db_conf array
     * @max_lifetime  int default 31536000=3600*24*365
     */
    public function __construct($db_conf = array(), $max_lifetime = self::SESSION_MAX_LIFETIME)
    {
        $this->config = $db_conf;
        $this->sess_lifetime = $max_lifetime;

        session_set_save_handler(
            array($this, 'sess_open'),
            array($this, 'sess_close'),
            array($this, 'sess_read'),
            array($this, 'sess_write'),
            array($this, 'sess_destroy'),
            array($this, 'sess_gc')
            );
        register_shutdown_function('session_write_close');
    }

    /*
     * the first callback function executed when the session is started
     * automatically or manually with session_start()
     * return TURE for success, FALSE for failure
     */
    public function sess_open($save_path, $session_name)
    {
        if($this->sess_pdo == null)
        {
            if($this->config['unix_socket'])
            {
                $dsn = "mysql:dbname={$this->config['database']};" .
                    "unix_socket={$this->config['unix_socket']}";
            }
            else
            {
                $dsn = "mysql:host={$this->config['host']};port={$this->config['port']};" .
                    "dbname={$this->config['database']}";
            }

            $username = $this->config['username'];
            $password = $this->config['password'];

            $options = array_merge(array(PDO::ATTR_PERSISTENT => $this->config['persistent']), $this->config['options']);

            try
            {
                $this->sess_pdo = new PDO($dsn, $username, $password, $options);
                $this->sess_pdo->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION);
                $this->sess_pdo->setAttribute(PDO::ATTR_EMULATE_PREPARES, false);
                $this->sess_pdo->exec("SET NAMES {$this->config['charset']}");
                $this->sess_pdo->exec("SET character_set_client=binary");
            }
            catch(PDOException $e)
            {
                $this->sess_pdo = null;
                die('error in ' . __METHOD__ . ' : ' . $e->getMessage());
            }
        }

        return true;
    }

    /*
     * executed after the session write callback has been called,
     * also invoked when session_write_close() is called
     * TRUE for success, FALSE for failure
     */
    public function sess_close()
    {
        $this->sess_pdo = null;

        return true;
    }

    /*
     * must always return a session encoded string, or an empty string if no data to read
     * called internally by PHP where session start, before this callback is invoked PHP
     * will invoke the open callback
     */
    public function sess_read($session_id)
    {
        try
        {
            $query = 'SELECT %s FROM %s WHERE %s=? AND %s>=?';
            $query = sprintf($query, self::FIELD_SESSION_DATA, self::SESSION_TABLE,
                self::FIELD_SESSION_ID, self::FIELD_EXPIRE_AT);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->bindValue(2, time());
            $stmt->execute();

            if($stmt->rowCount() == 1)
            {
                list($sess_data) = $stmt->fetch();

                return $sess_data;
            }

            return '';
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ' : ' . $e->getMessage());
        }
    }

    /*
     * called when the session needs to be saved and closed
     * @session_id session ID
     * @data    serialized version of the $_SESSION
     * invoked when php shuts down or explicitly session_write_close is called
     */
    public function sess_write($session_id, $data)
    {
        try
        {
            /*
             * the session_id field must be defined as UNIQUE
             */
            $query = 'INSERT INTO %s (%s, %s, %s) VALUES (?, ?, ?)'.
                " ON DUPLICATE KEY UPDATE %s=VALUES(%s), %s=VALUES(%s)";
            $query = sprintf($query, self::SESSION_TABLE, self::FIELD_SESSION_ID,
                self::FIELD_SESSION_DATA, self::FIELD_EXPIRE_AT,
                self::FIELD_SESSION_DATA, self::FIELD_SESSION_DATA,
                self::FIELD_EXPIRE_AT, self::FIELD_EXPIRE_AT);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->bindValue(2, $data);
            $stmt->bindValue(3, time() + $this->sess_lifetime);
            $stmt->execute();

            return (bool)$stmt->rowCount();
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ' : ' . $e->getMessage());
        }
    }

    /*
     * executed when a session is destroyed with session_destroy or session_regenerate_id
     * return TRUE for success, FALSE for failure
     */
    public function sess_destroy($session_id)
    {
        try
        {
            $query = 'DELETE FROM %s WHERE %s=? LIMIT 1';
            $query = sprintf($query, self::SESSION_TABLE, self::FIELD_SESSION_ID);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->execute();
            return (bool)$stmt->rowCount();
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ': ' . $e->getMessage());
        }
    }

    /*
     * invoked internally by PHP periodically in order to purge old session data.
     * frequency session.gc_probability/session.gc_divisor, the value of lifetime is passed to
     * this call back be set in session.gc_maxlifetime
     * return TRUE for success, FALSE for failure
     */
    public function sess_gc($lifetime)
    {
        try
        {
            $query = "DELETE FROM %s WHERE %s <= NOW()";
            $query = sprintf($query, self::SESSION_TABLE, self::FIELD_EXPIRE_AT);
            $count = $this->sess_pdo->exec($query);
            
            return true;
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ' : ' . $e->getMessage());
        }
    }
}

其中，数据库配置参数数组为:

$DB_CONF        = array(
    'host'      => '127.0.0.1',
    'port'      => '3306',
    'username'  => 'test',
    'password'  => 'test',
    'database'  => 'test',
    'charset'   => 'utf8',
    'persistent'    => true,
    'unix_socket'   => '',
    'options'       => array()
    );

这里在sess_write中利用 INSERT INTO ... ON DUPLICATE KEY UPDATE ... 语句更新session数据，需要将session_id字段声明为UNIQUE。

第一次排查, 误入歧途

最初出现自动退出并没有引起注意，在和前端的同学联调的过程中，登录后退出的问题就充分暴露出来了。在排查的过程中，将连接属性persistent=false，发现退出后就无法登录系统了。这引入了一个新问题，偏离了原bug，但也定位出程序中的一个隐藏bug。为session函数添加了执行日志，并查看mysql中实际执行的语句序列。以sess_write和sess_destroy为例，代码片段为如下:

/*
     * called when the session needs to be saved and closed
     * @session_id session ID
     * @data    serialized version of the $_SESSION
     * invoked when php shuts down or explicitly session_write_close is called
     */
    public function sess_write($session_id, $data)
    {
        try
        {
            /*
             * the session_id field must be defined as UNIQUE
             */
            $query = 'INSERT INTO %s (%s, %s, %s) VALUES (?, ?, ?)'.
                " ON DUPLICATE KEY UPDATE %s=VALUES(%s), %s=VALUES(%s)";
            $query = sprintf($query, self::SESSION_TABLE, self::FIELD_SESSION_ID,
                self::FIELD_SESSION_DATA, self::FIELD_EXPIRE_AT,
                self::FIELD_SESSION_DATA, self::FIELD_SESSION_DATA,
                self::FIELD_EXPIRE_AT, self::FIELD_EXPIRE_AT);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->bindValue(2, $data);
            $stmt->bindValue(3, time() + $this->sess_lifetime);
            $stmt->execute();
	    $write_count = $stmt->rowCount();

	    error_log("sess_write:(records num) write_count=" . $write_count, 3, "/tmp/logout.log");

	    //read data immediately after write
	    $query = 'SELECT %s FROM %s WHERE %s=? AND %s>=?';
            $query = sprintf($query, self::FIELD_SESSION_DATA, self::SESSION_TABLE,
                self::FIELD_SESSION_ID, self::FIELD_EXPIRE_AT);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->bindValue(2, time());
            $stmt->execute();

            list($sess_data) = $stmt->fetch();
	    error_log("sess_write:(read after write) sess_data=" . print_r($sess_data, true), 3, "/tmp/logout.log");

            return (bool)$write_count;
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ' : ' . $e->getMessage());
        }
    }

/*
     * executed when a session is destroyed with session_destroy or session_regenerate_id
     * return TRUE for success, FALSE for failure
     */
    public function sess_destroy($session_id)
    {
        try
        {
            $trace_arr = debug_backtrace();
            $trace_str = '';
            foreach($trace_arr as $index => $trace)
            {
                $trace_str .= '#' . $index . '|file=' . $trace['file'] . '|line=' . $trace['line'] .
                    '|class=' . $trace['class'] . '|function=' . $trace['function'];
            }
            $trace_str .= "\n";
            error_log($trace_str, 3, '/tmp/logout.log');
    
            $query = 'DELETE FROM %s WHERE %s=? LIMIT 1';
            $query = sprintf($query, self::SESSION_TABLE, self::FIELD_SESSION_ID);
            $stmt = $this->sess_pdo->prepare($query);
            $stmt->bindValue(1, $session_id);
            $stmt->execute();
            return (bool)$stmt->rowCount();
        }
        catch(PDOException $e)
        {
            $this->sess_pdo = null;
            die('error in ' . __METHOD__ . ': ' . $e->getMessage());
        }
    }

打开数据库执行语句序列的方法，参考SO上的问答:

mysql> show variables like 'general_log%';
mysql> SET GLOBAL general_log = 'ON';
--查看输出形式和输出文件存放位置
mysql> show variables like '%log_out%';
mysql> show variables like 'general_log_file';

用户登录成功后ssession_start()函数调用的sess_open对应执行的SQL序列为:

Query	SET AUTOCOMMIT=0
Query	SET NAMES utf8
Query	SET character_set_client=binary
Prepare	SELECT session_data FROM sessions WHERE session_id=? AND expire_at>=?
Execute	SELECT session_data FROM sessions WHERE session_id='fd99bece38392b9e7d5fe49cf6de32c8' AND expire_at>='1375685562'
Close stmt

从SQL语句的执行序列中可以发现，一开始就执行了一个

SET AUTOCOMMIT=0

的语句。另一方面，从session处理函数的log中可以看到，每次sess_write之后，可以读到刚写的数据。然而断开连接后就无法读到session数据了。这正好与没有SQL语句序列中不自动提交语句相符和。在sess_open函数中设置每次都自动提交:

$this->sess_pdo->setAttribute(PDO::ATTR_AUTOCOMMIT, true);

此时就发现比较有意思的SQL执行序列:

Query	SET AUTOCOMMIT=0
Query	SET AUTOCOMMIT=1
Query	SET NAMES utf8
Query	SET character_set_client=binary

在InnoDB中, 默认是自动提交的, 可以通过下面的方法查看:

mysql> show variables like '%autocommit%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| autocommit    | ON    | 
+---------------+-------+
1 row in set (0.00 sec)

近一步检查代码，就可发现，原来在sess_open初始化PDO的时候，为了设置长连接参数，使用了一个array_merge操作，问题就出在这里, php手册中说过:

Values in the input array with numeric keys will be renumbered with incrementing keys starting from zero in the result array.

array_merge会对数值型下标重排，这样

array_merge(array(PDO::ATTR_PERSISTENT => $this->config['persistent']), $this->config['options']);

的结果并不是设置了长连接属性值，而是设置了PDO::ATTR_AUTOCOMMIT的值为false，从而导致无法登录的问题。至此，随机退出的问题没解决，反而发现了程序中一个隐藏的bug，长连接参数不起作用。这个bug的修正很直接: 只需要用+替换array_merge就可以了。

偶然发现玄机

可是随机退出的问题还是没有解决，直到今天，查看退出的日志才偶然发现是gc函数的缘故。其实早就该怀疑是gc异常导致的问题，只是受到上面一个bug的影响，一直也没有往这方面多想，再加上sess_gc中记录的日志太粗糙，没有记录删除语句影响的行数，每次都无法直观地看出问题来，记录日志的效果很不好。

sess_gc函数中执行的语句是:

$query = "DELETE FROM %s WHERE %s <= NOW()";
$query = sprintf($query, self::SESSION_TABLE, self::FIELD_EXPIRE_AT);

而数据库表中的数据类型是int。结果就很明显了，gc以php.ini中配置的概率执行，而每次执行的时候都会删除当前登录用户数据，从而造成用户的随机登出的现象。bug的修正也很直接，略去不记了。

小结

通过这次bug追踪，如果对常用函数如array_merge等，理解的不够细致，往往会引入隐藏的bug。日志是为了帮助解决问题的，而在gc函数中只记录了执行的sql语句，而没有记录语句执行所影响的行数，不但不利于排查，反而会让人误以为这里没有问题。此外，导致这次bug最主要的原因，也是容易让人陷入"这里没问题"的思维惯性从而导致很难发现bug的原因：数据结构的定义和操作函数一定要一致。

转载于:https://my.oschina.net/merkerxu/blog/150223