欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页

关于Azkaban一次异常启动小记

程序员文章站 2022-06-04 15:50:56
...

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

    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改为接近当前的一个时间点就可以了。

 

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