关于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改为接近当前的一个时间点就可以了。
经过这件事,遇到棘手问题,一是要多想想,想不到的,可以采用减少配置的方式来逐渐缩小问题范围,一旦问题找到了,离原因就不远了。办法总比问题多的嘛