[erlang]一次erlcron崩溃引起的事故分析

简介:

事故背景

由于误操作在erlcron设置了一个超过3个月后的定时任务。然后第二天之后发现每天的daily reset没有被执行,一些定时任务也没有被执行。瞬间感觉整个人都不好了,怎么无端端就不执行了呢。

通过排查日志,发现了以下报错:

2016-03-22 16:54:32.014 [error] gen_server ecrn_control terminated with reason: no case clause matching {ok,[<0.14123.1577>,<0.13079.1576>,<0.25254.1569>,<0.13402.1577>,...]} in ecrn_control:internal_cancel/1 line 111
2016-03-22 16:54:32.015 [error] CRASH REPORT Process ecrn_control with 0 neighbours exited with reason: no case clause matching {ok,[<0.14123.1577>,<0.13079.1576>,<0.25254.1569>,<0.13402.1577>,...]} in ecrn_control:internal_cancel/1 line 111 in gen_server:terminate/6 line 744

我擦,ecrn_control都崩了,怎么回事。

找到具体出错的代码:

internal_cancel(AlarmRef) ->
    case ecrn_reg:get(AlarmRef) of
        undefined ->
            undefined;
        {ok, [Pid]} ->
            ecrn_agent:cancel(Pid)
    end.

发现调用ecrn_reg:get(AlarmRef)被返回了{ok, List},而且这个List的数据远不止一个。明显在设置那个超过3个月的定时任务的时候,ecrn_reg被注册进了脏数据。

事故重现

先设置几个正常的定时任务

erlcron:cron({{once, 1000}, {io, fwrite, ["Hello, world!~n"]}}).
erlcron:cron({{once, 1000}, {io, fwrite, ["Hello, world!~n"]}}).
erlcron:cron({{once, 1000}, {io, fwrite, ["Hello, world!~n"]}}).

查看observer:start() 可以看到进程树如下:

再设置一个4294968秒之后的定时任务

erlcron:cron({{once, 4294968}, {io, fwrite, ["Hello, world!~n"]}}).

结果就gg了,好多崩溃信息是不是:

22:49:16.818 [error] CRASH REPORT Process <0.5822.64> with 0 neighbours crashed with reason: timeout_value in gen_server:loop/6 line 358
22:49:16.818 [error] Supervisor ecrn_cron_sup had child ecrn_agent started with ecrn_agent:start_link(#Ref<0.0.11.11209>, {{once,4294968},{io,fwrite,["Hello, world!~n"]}}) at <0.5822.64> exit with reason timeout_value in context child_terminated
22:49:16.819 [error] CRASH REPORT Process <0.5701.64> with 0 neighbours crashed with reason: timeout_value in gen_server:loop/6 line 358
22:49:16.821 [error] Supervisor ecrn_cron_sup had child ecrn_agent started with ecrn_agent:start_link(#Ref<0.0.11.11209>, {{once,4294968},{io,fwrite,["Hello, world!~n"]}}) at <0.5701.64> exit with reason timeout_value in context child_terminated
22:49:16.821 [error] CRASH REPORT Process <0.6237.64> with 0 neighbours crashed with reason: timeout_value in gen_server:loop/6 line 358
22:49:16.821 [error] Supervisor ecrn_cron_sup had child ecrn_agent started with ecrn_agent:start_link(#Ref<0.0.11.11209>, {{once,4294968},{io,fwrite,["Hello, world!~n"]}}) at <0.6237.64> exit with reason timeout_value in context child_terminated
22:49:16.821 [error] CRASH REPORT Process <0.5862.64> with 0 neighbours crashed with reason: timeout_value in gen_server:loop/6 line 358
22:49:16.821 [error] Supervisor ecrn_cron_sup had child ecrn_agent started with ecrn_agent:start_link(#Ref<0.0.11.11209>, {{once,4294968},{io,fwrite,["Hello, world!~n"]}}) at <0.5862.64> exit with reason timeout_value in context child_terminated

...(总共有25条)

再看一下进程数:

我擦,为毛原来的 scrn_agent 进程也没有了。

可以发现,erlcron 在尝试了25次设置 这个定时任务之后,也就是 scrn_agent 崩溃了25次之后,原来设置的三个正常的定时任务的scrn_agent 进程也没有掉了。 也就是说,不但我新设置的定时任务没有成功,而且我原来正常的定时任务也没有掉了。

再看一下崩溃日志里面的崩掉的进程号,每一个都是不一样的。可以推算其实原来的报错ecrn_reg:get(AlarmRef)获取到了多个Pid,其实就是这里插入失败的定时任务产生的25个Pid。也就是说,虽然ecrn_agent进程崩溃了,但是ecrn_reg还是保存了这些Pid。所以在取消这些定时任务的时候,ecrn_reg:get(AlarmRef)返回的内容在internal_cancel(AlarmRef)没有被匹配到。

为什么是4294968,其实是2^32

为什么设置了4294968秒后的定时任务就崩溃了。这个数估计很多人很熟悉,2^32=4294967296,而4294968000也就是刚好大于2^32。即,如果设置的定时任务超过了2^32毫秒,在erlcron里面就不支持了。

查看gen_server:loop的源码,找到引起崩溃的代码:

loop(Parent, Name, State, Mod, hibernate, Debug) ->
    proc_lib:hibernate(?MODULE,wake_hib,[Parent, Name, State, Mod, Debug]);
loop(Parent, Name, State, Mod, Time, Debug) ->
    Msg = receive
          Input ->
            Input
      after Time ->
          timeout
      end,
    decode_msg(Msg, Parent, Name, State, Mod, Time, Debug, false).

可以发现引起崩溃的,358行是一段receive代码。也就是说receive是不支持超过2^32大小的。

自测了一下,的确如果receiveafter后面如果是大于等于2^32的数值就会出现bad receive timeout value的报错。查看官方解释,已经明确说明不能大于32位大小。

ExprT is to evaluate to an integer. The highest allowed value is 16#FFFFFFFF, that is, the value must fit in 32 bits. receive..after works exactly as receive, except that if no matching message has arrived within ExprT milliseconds, then BodyT is evaluated instead. The return value of BodyT then becomes the return value of the receive..after expression.

引用自:http://erlang.org/doc/reference_manual/expressions.html

再回到erlcron, 在 ecrn_agent:start_link的时候,ecrn_agent:init执行完ecrn_reg:register(JobRef, self())返回{ok, NewState, Millis}gen_server之后,Millis如果超过2^32gen_server:loop就会引起gen_servertimeout_value异常退出。

%% @private
init([JobRef, Job]) ->
    State = #state{job=Job,
                   alarm_ref=JobRef},
    {DateTime, Actual} = ecrn_control:datetime(),
    NewState = set_internal_time(State, DateTime, Actual),
    case until_next_milliseconds(NewState, Job) of
        {ok, Millis} when is_integer(Millis) ->
            ecrn_reg:register(JobRef, self()),
            {ok, NewState, Millis};
        {error, _}  ->
            {stop, normal}
    end.

最后

这坑踩的,有点郁闷。其实这跟erlcron也没关系,也不是gen_server的问题。而是erlang自身receive不支持2^32引起的。继续往下查其实可以发现,再往下是其它语言写的了。

-module(prim_eval).

%% This module is simply a stub which abstract code gets included in the result
%% of compilation of prim_eval.S, to keep Dialyzer happy.

-export(['receive'/2]).

-spec 'receive'(fun((term()) -> nomatch | T), timeout()) -> T.
'receive'(_, _) ->
    erlang:nif_error(stub).

与君共勉

本文转自 Ron Ngai 博客园博客,原文链接:http://www.cnblogs.com/rond/p/5315204.html  ,如需转载请自行联系原作者

相关文章
|
6月前
|
安全 Unix Linux
操作系统紧急故障修复常见有效方案
操作系统是计算机系统的核心软件之一,如果操作系统出现了紧急故障,将会引起系统的宕机,严重影响业务系统的可用性。因此,对操作系统的紧急故障进行修复是必不可少的。本文将介绍操作系统紧急故障的常见有效方案。
110 1
|
9月前
|
Java 编译器 应用服务中间件
几行代码就可以把系统高崩溃;
几行代码就可以把系统高崩溃;
69 0
J3D在UOS+KIRIN崩溃1:直接原因分析
J3D在UOS+KIRIN崩溃1:直接原因分析
73 0
|
JSON 运维 网络协议
平稳运行半年的系统宕机了,记录一次排错调优的全过程!
最近发生了一件很让人头疼的事情,已经上线半年且平稳运行半年系统在年后早高峰的使用时发生了濒临宕机的情况。访问速度特别慢,后台查到大量time_wait的连接,从代码层面到架构层面到网络层面排查了几天几夜,总算是有了结果。
|
存储 SQL Web App开发
你们的系统真的安全吗?你们系统是不是也有这种诡异的情况呢?
这个文章来源灵感是公司的项目在安全检查的时候,发现了很多 SQL 注入的一些问题还有一些 XSS 攻击问题,SQL 注入我们都是比较了解的,那么什么是 XSS 攻击呢?测试反馈给我的时候我是一脸懵逼呀,现在我们就来说一下什么是 XSS 攻击,以及我们怎么防止它的出现。
日常环境莫名宕机的处理
## 背景 11.21 早上 pd 给讲法务评审的时候,操作日常环境,莫名就 down 机了,而且 pd 反馈经常会这样。(ps : pd 反馈系统请求时间过长,性能很差,后续也会排查解决) 于是排查了一下系统 down 机的原因 ## 原因 查看内存 setenv.sh 设置 if [ $memTotal -le 2048 ]; then SERVICE_OPTS="${SE
1233 0