strace – CFC4N的博客

TLS handshake Fatal Alert Close Notify的错误排查

2019-09-09 0 0

Nginx模块fastcgi_cache的几个注意点

在web项目中，大家都已经非常熟悉其架构流程了。都说Cache是万金油，哪里不舒服抹哪里。这些流程中，几乎每个环节都会进行cache。从浏览器到webserver，到cgi程序，到DB数据库，会进行浏览器cache，数据cache，SQL查询的cache等等。对于fastcgi这里的cache，很少被使用。去年年底，我对nginx的fastcgi_cache进行摸索使用。在我的测试过程中，发现一些WIKI以及网络上没被提到的注意点，这里分享一下。这里是我的NGinx配置信息配置这些参数时，注意每个参数的作用域，像fastcgi_cache_path参数，只能在http配置项里配置，而fastcgi_cache_min_uses这个参数，可以在http、server、location三个配置项里配置。这样更灵活的会每个域名、每个匹配的location进行选择性cache了。具体的参数作用域，参考FASTCGI模块的官方WIKI。我为了调试方便，添加了一个『X-Cache-CFC』的http响应头，$upstream_cache_status 变量表示此请求响应来自cache的状态，分别为： MISS 未命中 EXPIRED - expired, request was passed to backend Cache已过期 UPDATING - expired, stale response was used due to proxy/fastcgi_cache_use_stale updating Cache已过期，(被其他nginx子进程)更新中 STALE - expired, stale response was used due to proxy/fastcgi_cache_use_stale Cache已过期，响应数据不合法，被污染 HIT 命中cache 程序代码是Discuz!论坛，随便开启测试了几下，发现/dev/shm/nginx_cache/下没有任何目录建立，也没有文件创建。调试的http header响应头里的X-Cache-CFC 结果一直是MISS。从服务器进程上来看，Nginx cache manager process 跟Nginx cache loader process 进程也正常运行：不知道为何会这样，为何没有cache成功，我以为我配置参数有问题，只好阅读WIKI。发现fastcgi_ignore_headers 参数下解释有这么一段 fastcgi_ignore_headers Syntax: fastcgi_ignore_headers field ... Default: Context: http server location Reference: fastcgi_ignore_headers This directive forbids processing of the named headers from the FastCGI-server reply. It is possible to specify headers like "X-Accel-Redirect", "X-Accel-Expires", "Expires" or "Cache-Control". 也就是说这个参数的值，将会被忽略掉，同样被忽略掉的响应头比如"X-Accel-Redirect", "X-Accel-Expires", "Expires" or "Cache-Control"，而nginx配置中并没有fastcgi_ignore_headers参数的设定，那么问题会不会出现在FASTCGI响应结果里包含了类似"X-Accel-Redirect", "X-Accel-Expires", "Expires" or "Cache-Control"这几个响应头呢？用strace抓包，看了下nginx与fpm进程通讯的数据从抓取的数据包里可以看到，fpm确实返回了包含“Expires”、“Cache-Control”头的http 响应头信息。那么疑问来了： nginx的fastcgi_cache没缓存这条http响应，是因为响应头里包含“Expires”、“Cache-Control”的原因吗？程序里并没有输出“Expires”、“Cache-Control” http header的代码，这是谁输出的呢？既然是fpm响应的时候，就已经有了，那么是php的core模块，还是其他拓展模块输出的？ “Expires:”时间为何是“Thu, 19 Nov 1981 08:52:00 GMT”? 疑问比较多，一个一个查起，先从Nginx的fastcgi_cache没缓存这条http响应查起。我根据测试环境nginx版本1.1.9(ubuntu 12.04默认的)，到nginx官方下了对应版本的源码，搜索了fastcgi参数使用的地方，在http\ngx_http_upstream.c找到了。虽然不能很流程的读懂nginx的代码，但粗略的了解，根据了解的情况加以猜测，再动手测试实验，也得出了结论，确定了nginx的fastcgi_cache的规则。也就是说，fastcgi响应http请求的结果中，响应头包括Expires、Cache-Control、Set-Cookie三个，都会可能不被cache，但不只有这些，别忘了nginx配置中fastcgi_ignore_headers参数设定的部分。以及ngxin的X-ACCEL X-Accel-Redirect、X-Accel-Expires、X-Accel-Charset、X-Accel-Buffering等nginx自定义的响应头。由于这几个不常用，我也没深入研究。通过对nginx的ngx_http_upstream模块代码模糊理解，加猜测，以及写了脚本测试验证，可以得到结论是正确的。即Nginx fastcgi_cache在缓存后端fastcgi响应时，当响应里包含“set-cookie”时，不缓存;当响应头包含Expires时，如果过期时间大于当前服务器时间，则nginx_cache会缓存该响应，否则，则不缓存;当响应头包含Cache-Control时，如果Cache-Control参数值为no-cache、no-store、private中任意一个时，则不缓存，如果Cache-Control参数值为max-age时，会被缓存，且nginx设置的cache的过期时间，就是系统当前时间 + mag-age的值。到了这里，疑问1解决了。那么疑问2、3呢？程序里并没有输出“Expires”、“Cache-Control” http header的代码，这是谁输出的呢？既然是fpm响应的时候，就已经有了，那么是php的core模块，还是其他拓展模块输出的？我精简了代码，只输出一个“hello world”，发现也确实被缓存了。显然，php脚本程序中并没输出http header 的“Expires”、“Cache-Control”，多次测试，最终定位到session_start函数，翻阅源码找到了这些代码：到了这里，知道原因了，是程序调用session_start时，php的session拓展自己输出的。session.cache_limit参数来决定输出包含哪种Expires的header，默认是nocache，修改php.ini的session.cache_limit参数为“none”即可让session模块不再输出这些http 响应头。或在调用session_start之前，使用session_cache_limiter函数来指定下该参数值。那为什么要在使用session时，发Expires、Cache-Control的http response header呢？我猜测了下，需要session时，基本上是用户跟服务器有交互，那么，既然有交互，就意味着用户的每次交互结果也可能不一样，就不能cache这个请求的结果，给返回给这个用户。同时，每个用户的交互结果都是不一样的，nginx也就不能把包含特殊Cache-Control的个人响应cache给其他人提供了。还有一个无聊的问题“Expires:时间为何是Thu, 19 Nov 1981 08:52:00 GMT”？我翻阅了session.c这段代码的添加时间，版本，作者信息，在php官方版本库中找到了这次提交的信息： Revision 17092 - (view) (download) (as text) (annotate) - [select for diffs] Modified Sun Dec 12 14:16:55 1999 UTC (13 years, 2 months ago) by sas File length: 28327 byte(s) Diff to previous 16964 Add cache_limiter and cache_expire options. Rename extern_referer_check to referer_check. 对比session.c两个版本的变更，果然是这块代码。作者是sas，也就是Sascha Schumann， http://php.net/credits.php里可以看到他的大名。关于这个expires过期时间的问题，有人在stackoverflow也提问过，Why is “Expires” 1981?，别人说那天是他生日。这是真的么？如果那天是他生日的话，而他增加session.cache_limiter时是1999年，他才17岁，17岁呀。我17岁时在干嘛？还不知道电脑长啥样，正在玩『超级玛丽』呢。好奇的不是我一个人，还有个帖子是epoch date -- Expires: Thu, 19 Nov 1981 08:52:00也问了。另外两个地址虽然没问，也有人提到那天是他生日了。http://boinc.berkeley.edu/dev/forum_thread.php?id=2514、https://github.com/codeguy/Slim/issues/157，这些帖子都提到说原帖是http://www.phpbuilder.com/lists/php3-list/199911/3159.php ，我无法访问，被跳转到首页了。用http://web.archive.org找到了历史快照，发现上下文关系不大，也不能证明是他生日。我更是好奇的发了两封邮件到他的不同邮箱里问他，不过，目前他还没回复。或许他没收到、没看到，或许懒得回了。N年后，“Expires:时间为何是Thu, 19 Nov 1981 08:52:00 GMT”这个日期，会不会又成了一段奇闻佳话了呢？

2013-02-28

+14 18 0

webgame中Mysql Deadlock ERROR 1213 (40001)错误的排查历程

案例发现: 从我们正在运营的一款webgame的异常日志中看到一些程序执行MYSQL 语句的报错信息。比较多的是“Deadlock found when trying to get lock; try restarting transaction”,少部分是“Error number: 1205:Lock wait timeout exceeded; try restarting transaction”，如下：从报错的英文上理解，大约是发生了“死锁”，以及“事务锁等待超时”两个错误异常。而且，都是我们后台PHP常驻进程遇到的问题。异常的代码对应行数上，大约可理解为执行SQL语句的一个指令，并无特殊的东西。有经验的程序员，很容易看出来，这不是程序的异常，这是MYSQL事务中，锁竞争的异常，客户端(PHP常驻进程)是没有语法上的错误的。那该如何排查呢？一串疑问：这是什么问题？如何排查？什么时候发生死锁？我怎么知道他发生了？发生之后去哪里排查？如何排查？怎么确定他们对应的事务中的所有SQL语句？分别在哪几个事务中？谁先锁的？谁后锁的？谁没锁到？谁报的死锁错误？死锁是什么？为什么发生了？如何避免？还有哪些因素影响？毫无头绪: 程序间数据交互，上strace神器? 跟踪谁？客户端(php)？你知道哪个客户端会发生这个问题？你知道啥时候会发生？在你开始抓包到抓到死锁的期间，这得是多大的数据量？跟踪谁？服务端(Mysql)？玩笑开大了吧？mysql以进程模式来处理客户端请求，每次都是一个新的进程，strace -ff参数的话，想想日志文件得被创建多少个，数据量会小么？ "万军之中取上将首级"这本事我可没...strace排查这种错误，还是算了吧。这是谁报的错？显然是mysql，那就从根源找起--MYSQL server。抓获现场: 我们要还原案发现场，有幸的时，我们有监控记录BINLOG以及SHOW ENGINE INNODB STATUS。到对应mysql服务器上，执行“show engine innodb status”获取INNODB引擎当前信息，大约如下：这是我精简之后的信息，我抓去了LATEST DETECTED DEADLOCK部分的数据，这部分的数据是INNODB的最后一次发生死锁的信息，更详细的说明见MYSQL官方手册对Standard Monitor and Lock Monitor Output返回结果的解释。 OK,发现一场案例，保存这个INNODB的状态数据备用。迅速到程序异常日志中查看相同时间点是否有死锁发生。果然，我们程序异常日志中记录了这起案例(文章开头的日志)。再到binlog中抓去这个时间段前后10分钟(大约范围)的mysql sql语句执行日志。案情分析： engine status中，大约看出MYSQL记录了两个事务之间发生锁竞争时，遗留的数据，事务1“执行”(注意，这里加了双引号) 发现被修改资源已经被lock_mode X locks了(详情见:INNODB锁模式)，准备等待该资源锁被释放。事务2执行也发现该资源被lock_mode X locks了。最后部分，mysql给了很重要的一个数据“WE ROLL BACK TRANSACTION (1)” MYSQL回滚了事物1。既然mysql回滚了1，那么肯定是事务1的语句触发了死锁，被mysql回滚了，也就是应该为程序中的异常日志所记录的那部分。同时，MYSQL执行了事务2，那么事务2的SQL语句肯定被记录在BINLOG中了。抽丝剥茧: 如何确定事务1、事务2执行了哪些SQL语句呢？根据show engine innodb status的结果，确定事务2被执行的 SQL语句(业务逻辑的role_id唯一标识): REPLACE INTO `role_fight` (`role_id`, `life_max`, `mana_max`, `attack_physical`, `attack_internal`,****) VALUES ('53016', 4967, 3291, 350, 174, ***) 线程ID(mysql的唯一标识): MySQL thread id 122679850 执行时间(时间线):121128 15:59:46 根据这三个标识，以及BINLOG的起始表示“BEGIN、COMMIT”，几乎可以100%确定该事务所包含的SQL语句。 BINLOG信息大约如下: OK,事务2的SQL语句全部找齐了。那么事务1的呢？如何找？根据php的异常报错，确定主要包含的语句SQL信息，以及程序跟踪的代码行数，根据代码逻辑去确定该事务的所有SQL语句。再去BINLOG中找到该用户的该业务的类似BINLOG： (请勿过于纠结上面binlog的thread_id跟show engine innodb status的thread_id一致的问题，这是因为我们程序是常驻进程，mysql连接不断开，不销毁，故一致了。而且，此日志是程序发现死锁之后，被mysql回滚之后，又重新提交的事务，算是不同时间点的相同事务) 案情还原：根据案发现场的两个MYSQL INNODB事务的全部SQL语句，以及形成MYSQL INNODB 死锁的原因(感谢DBA组大雄哥的纠正)，我们大约可以这么还原案情: 事务1： UPDATE `role_fight` SET `last_update_life` = '1354089587' WHERE `role_id` = '53016' UPDATE `role_state` SET `state` = 1 WHERE `role_id` = '53016' 事务2： UPDATE `role_state` SET `pet` = 0, `pet_level` = 0 WHERE `role_id` = '53016' REPLACE INTO `role_fight` (`role_id`, `life_max`, `mana_max`, `attack_physical`, `attack_internal`,****) VALUES ('53016', 4967, 3291, 350, 174, ***) 这四条语句构成了本次事务死锁的全部原因。执行顺序肯定如下: 时间点事务1 事务2 备注 1 begin 2 begin 3 UPDATE `role_state` SET `pet` = 0, `pet_level` = 0 WHERE `role_id` = '53016' 事务2 给 role_state表 role_id 53016记录上 X 锁 4 UPDATE `role_fight` SET `last_update_life` = '1354089587' WHERE `role_id` = '53016' 事务1 给 role_fight表 role_id 53016记录上 X 锁 5 REPLACE INTO `role_fight` (`role_id`, `life_max`, `mana_max`, `attack_physical`, `attack_internal`,****) VALUES ('53016', 4967, 3291, 350, 174, ***) 这里是重点，事务2给role_fight表role_id的记录上 X 锁，发现被其他人(事务1)上锁了，开始等待他人提交事务...等待... 6 UPDATE `role_state` SET `state` = 1 WHERE `role_id` = '53016' 事物1打算给role_state表role_id为53016记录上 X 排它锁，发现被其他事务上了，而且此事务居然还在等他提交，这时MYSQL立刻回滚事务1...(php发现MYSQL返回死锁信息，随记录该信息到异常日志...发送回滚指令...mysql已经“帮”他回滚了...) 7 【执行成功...】事务2发现别人释放锁了，OK，获取X锁，修改成功 8 commit PHP程序发现上一条指令执行完毕，且执行无错，即，发送commit指令，提交事务。好像有个参数%^&#: innodb_lock_wait_timeout参数是干啥的呢？从mysql官方手册上看，此参数是针对锁等待时，一个限定等待时间的参数。跟死锁并无关系，一旦mysql发现死锁，立刻回滚导致死锁的语句。并不会用到该参数。规避方式：缩小事务的语句数量调整SQL语句执行顺序，变“死锁”为“锁等待”，等待一会，总比整个事务回滚掉，全部重新再执行这个流程要强. 其他.请补充关于锁等待: 缩小事务间SQL语句的数量，减小规模吧。当然，提高检索速度，提高查询时间也是首要因素，我们就发现我们的SQL语句中，有几个没有用到索引，导致锁表，导致锁等待发生... 备注: 年底了，冲KPI的，各位见笑了.

2012-12-04

+2 6 0

CodeIgniter框架中关于DB事务处理的设计缺陷

起因：在我们线上的某个业务中，使用较老版本的CodeIgniter框架，其中的DB类中，对DB事物处理部分存在着一个设计上的缺陷，或许也算不上缺陷吧。但他却影响了我们生产环境，导致连锁反应。对业务产生较大影响，且不容易排查。这个问题，我在今年的3月中旬，曾向http://codeigniter.org.cn/的站长Hex 报告过，之后，我也忘记这件事情了。直到今天，我们线上业务又一次以为这个问题，害的我又排查一次。具体原因，各位且先听我慢慢说完。(这个问题同样存在于最新版本Version 2.1.0中) 分析：以CodeIgniter框架Version 2.1.0为例，在system\database\DB_driver.php的CI_DB_driver类中第58行有个$_trans_status属性。同时，这个类的query方法中，有赋值此属性的代码，见文件306、307行这里也给了注释，告诉我们，如果使用了事物处理，那么这属性将成为一个回滚的决定条件。在520行的事物提交方法trans_complete中，如下代码在535行中，如果_trans_status属性如果是false，那么将发生回滚，并且返回false。在我们的业务代码中，由于程序员疏忽，没有判断trans_complete()方法是否正确执行，直接告诉用户操作成功，但实际上，程序已经向DB下达回滚指令，并未成功更新DB记录。当用户执行下一步操作时，程序又发现相应记录并未更新，又提醒用户上个操作没有完成，通知用户重新执行。如此反复... 排查的过程，也是挺有意思的，起初从PHP代码中，总是不能确定问题所在，并没有把焦点放到trans_complete()方法的返回上。直到后来strace抓包分析，才知道是因为此属性而导致了回滚。可以看到，在22:54:08.380085时间点处，发送更新SQL语句指令，在22:54:08.380089时间读取返回结果，得到SQL执行错误，不存在字段"cfc4n_user_lock"；22:54:08.381791和22:54:08.382703两个时间点，PHP发送停止“自动提交”与“开始事务处理”指令，在 22:54:08.433954 发送“事务回滚”指令。配合如上的代码分析，可以清楚的知道，因为“UPDATE `cfc4n_user_info` SET `cfc4n_user_lock` = 1 WHERE `cfc4n_user_id` = '6154' AND `cfc4n_user_lock` = 0”这句SQL执行错误，导致$_trans_status属性被设置为FALSE，当代码提交事务时，被trans_complete()方法判断，认为“上一个事务处理”(下面将仔细分析)中存在SQL语句执行失败，决定回滚事务，不提交。刚刚提到“上一个事务处理”，可能有些朋友不能理解，我们先继续回到代码中来，继续看该属性，同样在trans_complete方法中，542-545行：也可以很容易的从注释中看明白，设置CI的设计者，为了更严谨的处理同一个脚本中，存在多个事务时，事务间彼此关系重要，一荣俱荣，一损俱损。这里的trans_strict属性，是个开关，当 trans_strict为false，便是非严格模式，意味着多个事务之间，彼此关系不重要，不影响。当前一个事务中有SQL语句执行失败，影响不到自己。便将_trans_status 设置为TRUE。毫无疑问，这是个非常周全的考虑。考虑了多个事务之间的关系，保证业务跑在更严谨的代码上。可是，我们的代码中，错误的SQL语句是执行在事务处理以外的，并不是事务之内。按照我们对事务的认识，可以很清晰的知道，事务之外的SQL相比事务之内的SQL来说，事务之内的SQL更重要，之外的可以允许出错，但事务之内的，务必要正确，不受外界干扰。但CI的框架中，因为一个事务以外的语句执行失败，却导致整个事务回滚...当然，我们的程序员没有对事务提交方法的返回做判断，这也是个问题。问题已经很清晰了，那么解决方法想必对你来说，是多么的简单。比如在trans_start方法中，对_trans_status 属性赋值，设置为TRUE，不理会事务外的问题。结束：在不明白对方设计意图的情况下，不能盲目的定义对方的代码评价，不管程序作者的水平如何。比自己强，也不能盲目崇拜；比自己弱，更不能乱加指责；理解读懂设计意图，学习他人优秀的设计思路、代码风格、算法效率，这才是一个好习惯。当然codeigniter框架是优秀的。

2012-04-30

+3 7 0