关于Azkaban一次异常启动小记

    事故是上月底的事了，刚才有人又提起这事，还是记录下为好。

    7月28号因为暂停DW上的任务，将Azkaban的Jetty服务暂时停了，下午下班前启动不起来，于是同事跑来找我帮忙看。起初怀疑他又动了不该动的配置导致，查看文件时间都是若干月前的；当时没找到什么原因，从启动日志中看有如下错误，主要原因是“java.lang.IllegalStateException: 100000 increments of period did not get to present time.”这句，但是有些不明所以。

 

14/07/28 19:57:36 INFO impl.StdSchedulerFactory: Quartz scheduler 'QuartzScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
14/07/28 19:57:36 INFO impl.StdSchedulerFactory: Quartz scheduler version: 2.1.6
14/07/28 19:57:36 INFO core.QuartzScheduler: Scheduler QuartzScheduler_$_NON_CLUSTERED started.
2014-07-28 19:57:36.763:WARN:oejw.WebAppContext:Failed startup of context o.e.j.w.WebAppContext{/azkaban,file:/data/srv/azkaban/azkaban_web/app/temp/webapp/},/data/app/azkaban/a
java.lang.IllegalStateException: 100000 increments of period did not get to present time.
    at azkaban.scheduler.ScheduledJob.getNextRuntime(ScheduledJob.java:100)
    at azkaban.scheduler.ScheduledJob.updateTime(ScheduledJob.java:77)
    at azkaban.scheduler.LocalFileScheduleLoader.createScheduledJob(LocalFileScheduleLoader.java:179)
    at azkaban.scheduler.LocalFileScheduleLoader.loadFromFile(LocalFileScheduleLoader.java:144)
    at azkaban.scheduler.LocalFileScheduleLoader.loadSchedule(LocalFileScheduleLoader.java:74)
    at azkaban.scheduler.CronScheduleManager.<init>(CronScheduleManager.java:64)
    at azkaban.app.AzkabanApplication.<init>(AzkabanApplication.java:221)
    at azkaban.web.AzkabanServletContextListener.contextInitialized(AzkabanServletContextListener.java:63)
    at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:771)
    at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:411)
    at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:763)
    at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:247)
    at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1238)
    at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:706)
    at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:480)
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
    at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:39)
    at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186)
    at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:494)
    at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:141)
    at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:145)
    at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:56)
    at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:609)
    at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:540)
    at org.eclipse.jetty.util.Scanner.scan(Scanner.java:403)
    at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:337)
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
    at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:121)
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
    at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:555)
    at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:230)
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
    at org.eclipse.jetty.util.component.AggregateLifeCycle.doStart(AggregateLifeCycle.java:81)
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:58)
    at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:96)
    at org.eclipse.jetty.server.Server.doStart(Server.java:277)
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
    at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1265)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1188)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:468)
    at org.eclipse.jetty.start.Main.start(Main.java:616)
    at org.eclipse.jetty.start.Main.main(Main.java:92)

通过google那个异常，可以在网上找到如下一段代码：

 

    DateTime now = new DateTime();
    DateTime date = new DateTime(scheduledDate);
    int count = 0;
    while (!now.isBefore(date)) {
        if (count > 100000) {
            throw new IllegalStateException("100000 increments of period did not get to present time.");
        }
 
        if (period == null) {
            break;
        }
        else {
            date = date.plus(period);
        }
 
        count += 1;
    }

      但当时也没能太理解究竟是干嘛用，于是放弃。接着反复尝试过几次其他方式后，无果。只能采用逐渐去除配置的方式来检验出错原因：

 

将日志中打印的这两个jobs、cron的配置挪到其他文件夹下，来测试问题出在哪

 

14/07/28 19:57:36 INFO app.AzkabanApplication: schedule.file param not set. Defaulting to /data/srv/azkaban/azkaban_jobs/jobs/jobs.schedule
14/07/28 19:57:36 INFO app.AzkabanApplication: schedule.backup.file param not set. Defaulting to /data/srv/azkaban/azkaban_jobs/jobs/jobs.schedule.backup
14/07/28 19:57:36 INFO app.AzkabanApplication: cron.schedule.file param not set. Defaulting to /data/srv/azkaban/azkaban_jobs/jobs/cron_jobs.schedule
14/07/28 19:57:36 INFO app.AzkabanApplication: cron.schedule.backup.file param not set. Defaulting to /data/srv/azkaban/azkaban_jobs/jobs/cron_jobs.schedule.backup

     黄天不负有心人，很快试出是jobs.schedule的问题，移除之后就能正常启动，贴回来就又会报错。当时已下班，第二天还需要定时任务执行，于是用粗暴的方式建议同事再重新配置遍，陪他苦逼了十几分钟参照原来jobs.schedule中的任务重新配置了遍。

    回家路上还在想这事，为什么报个10万出来？结合网上那段代码，后来意识到，是不是从起始时间算起，每一间隔执行时间段计数一次，大于10万后就抛出异常，防止死循环。结合6月底重启过一次，很正常，以及刚才陪同事配置时job.schedule中的起始时间大约都是2013-12-31；于是掏出手机，打开计算器开始算，因为我记着有每隔5分钟一次的任务，所以，一小时就是12次，于是有

12 X 24(小时) X 30(天) X 6(月) = 51840

12 X 24(小时) X 30(天) X 7(月) = 60480

很遗憾，结果没能对上。回家后VPN到公司服务器，又看了遍jobs.schedule，发现有3分钟一次的任务

 

{
        "id": "dw2_c2.t_oper_rete_online",
        "ignoreDependency": false,
        "recurrence": "3m",
        "time": "2013-12-30.14.55.00.000",
        "timezone": "Asia/Shanghai"
},

 于是又有

 

20（次） X 24(小时) X 30(天) X 6(月) = 86400

20（次） X 24(小时) X 30(天) X 7(月) = 100800

\(^o^)/~ 猜想正确！ 再返回来读下代码就彻底明白了

    DateTime now = new DateTime(); //获取当前时间
    DateTime date = new DateTime(scheduledDate); //获取任务开始时间
    int count = 0;   //定义计数器
    while (!now.isBefore(date)) { //如果当前时间在任务开始时间之后，则进入循环体
        if (count > 100000) {  //计数器大于10万后就抛异常：经过10万次计算出的下一次执行时间未达到当前时间（说的太内涵了，对母语非e文的解读起来有点困难，有木有！）
            throw new IllegalStateException("100000 increments of period did not get to present time.");
        }
 
        if (period == null) { //如果周期为空，直接退出
            break;
        }
        else { //将任务开始时间增加一个周期
            date = date.plus(period);
        }
 
        count += 1;
    }

这下彻底明了了，当时就不需要重新配，只需要把time改为接近当前的一个时间点就可以了。

 

经过这件事，遇到棘手问题，一是要多想想，想不到的，可以采用减少配置的方式来逐渐缩小问题范围，一旦问题找到了，离原因就不远了。办法总比问题多的嘛