Singularity aborts when sending overdue task emails if smtp not configured

[whitedr]

I encountered a situation where I has some scheduled requests that got stuck in a PENDING state. I'm not entirely sure how they got into that state but I think it was related to pausing/unpausing them repeatedly. Once these pending requests existed, I began seeing singularity abort periodically. I tracked it down to this in the log:

2016-04-19T11:45:52.54317 ERROR [2016-04-19 11:45:52,537] com.hubspot.singularity.scheduler.SingularityLeaderOnlyPoller: Caught an exception while running SingularityScheduledJobPoller
2016-04-19T11:45:52.54320 ! java.lang.IllegalStateException: Optional.get() cannot be called on an absent value
2016-04-19T11:45:52.54321 ! at com.google.common.base.Absent.get(Absent.java:47) ~[SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54321 ! at com.hubspot.singularity.smtp.SingularityMailer.getDestination(SingularityMailer.java:317) ~[SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54322 ! at com.hubspot.singularity.smtp.SingularityMailer.prepareTaskMail(SingularityMailer.java:275) ~[SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54324 ! at com.hubspot.singularity.smtp.SingularityMailer.sendTaskOverdueMail(SingularityMailer.java:249) ~[SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54325 ! at com.hubspot.singularity.scheduler.SingularityScheduledJobPoller.runActionOnPoll(SingularityScheduledJobPoller.java:94) ~[SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54325 ! at com.hubspot.singularity.scheduler.SingularityLeaderOnlyPoller.runActionIfLeaderAndMesosIsRunning(SingularityLeaderOnlyPoller.java:108) [SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54326 ! at com.hubspot.singularity.scheduler.SingularityLeaderOnlyPoller.access$000(SingularityLeaderOnlyPoller.java:24) [SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54327 ! at com.hubspot.singularity.scheduler.SingularityLeaderOnlyPoller$1.run(SingularityLeaderOnlyPoller.java:83) [SingularityService-shaded.jar:0.5.0]
2016-04-19T11:45:52.54327 ! at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_45]
2016-04-19T11:45:52.54328 ! at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_45]
2016-04-19T11:45:52.54329 ! at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_45]
2016-04-19T11:45:52.54330 ! at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_45]
2016-04-19T11:45:52.54331 ! at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_45]
2016-04-19T11:45:52.54331 ! at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
2016-04-19T11:45:52.54332 ! at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
2016-04-19T11:45:52.54332 ERROR [2016-04-19 11:45:52,539] com.hubspot.singularity.SingularityAbort: Singularity on prd-useast-mesos-platform-master-02.prd.yb0t.cc is aborting due to UNRECOVERABLE_ERROR
2016-04-19T11:45:52.54333 WARN  [2016-04-19 11:45:52,539] com.hubspot.singularity.SingularityAbort: Couldn't send abort mail because no SMTP configuration is present
2016-04-19T11:45:52.54333 INFO  [2016-04-19 11:45:52,540] com.hubspot.singularity.SingularityAbort: Attempting to flush logs and wait 00:00.100 ...
2016-04-19T11:45:52.65734 I0419 07:45:52.657297  9032 sched.cpp:1805] Asked to abort the driver
2016-04-19T11:45:52.74077 I0419 07:45:52.740716  9003 sched.cpp:1070] Aborting framework 'Singularity'

It looks like it was trying to send notification emails that tasks for these pending requests were overdue. On this particular cluster though, I haven't configured any smtp settings yet it seems to have died in trying to build the email that would be sent.

wrt the odd state of the pending scheduled requests, I was able to clear that by going into zookeeper and manually doing a: rmr /<zkNamespace>/requests/pending I'd like to better understand how those pending requests could have gotten in that state to begin with as well...

[ssalinas]

@dtabwhite A few questions to help debug the smtp issue:

• What version of Singularity are you running?
• Was there any smtp section at all in your config, if so can you share it (feel free to put in dummy creds, just want to see what fields were present/valid or not)

If the smtp section is not present, the poller should not be running at all. However, looking through the code, I realize that if the section is present, but not valid, that it could still be running the poller. I can take a closer look and make it smarter about when to run the poller if needed

As for the requests stuck in pending a few comments/questions on that too:

• Were these pending tasks or pending requests ? A pending task in Singularity means it is waiting for an offer, so if stuck there it could mean something like a lack of matching resources. A pending request in Singularity is just a trigger for the scheduler to do something with a request and it's associated tasks (e.g. Unpausing creates a pending request that will make the scheduler enqueue the next scheduled task)
• Do you have any logs from around the time things started getting stuck?

[Calvinp]

@ssalinas another fix (other than changing the logic for the poller) would be to guard all the public methods in SingularityMailer with a check if the smtpConfiguration is present.
For example, sendTaskOverdueMail() doesn't check if it's present, but queueTaskCompletedMail() does.
We may also want to fix the logic around when the poller starts up, but it might be quicker to simply put those guards in place.

[whitedr]

@ssalinas I'm running singularity 0.5.0. In this particular cluster I don't have any smtp section in my config.yaml. Here is that file (with some info redacted):

enableCorsFilter: true
logging:
  loggers:
    com.hubspot.singularity: TRACE
mesos:
  defaultCpus: 1
  defaultMemory: 128
  frameworkName: Singularity
  frameworkId: Singularity
  frameworkFailoverTimeout: 1000000
  master: zk://<zk server list>/<zk mesos path>
  rackIdAttributeKey: rack_id
  maxMemoryMbPerInstance: 50000
sandboxDefaultsToTaskId: false
server:
  applicationContextPath: "/"
  connector:
    type: http
    port: 7099
  type: simple
ui:
  title: Singularity - us-east-1 - prd
  baseUrl: http://<base url>:7099
zookeeper:
  connectTimeoutMillis: 5000
  retryBaseSleepTimeMilliseconds: 1000
  retryMaxTries: 3
  sessionTimeoutMillis: 60000
  quorum: <zk server list>
  zkNamespace: <zk namespace>

wrt the pending task/request, I believe it was pending requests since they showed up as 3 pending requests on the /status page in the UI. Also, I was able to clear them in zookeeper with rmr /<zkNamespace>/requests/pending. I'm sorry but I don't have the logs from when the pending requests came to being. I will keep an eye out for this happening again and provide additional details if/when possible.

[ssalinas]

Thanks @dtabwhite , after looking a bit more, we found a few instances where we could be more diligent about checking for the presence of the smtp configuration in the SingularityMailer. @Calvinp will be getting a fix in that we can hopefully get into the next release. Let us know when/if you see the pending request issue again and we'll investigate more

[whitedr]

Oh, one more tidbit... I did recently (~12 days ago) update the above cluster to running singularity 0.5.0. The config didn't change when doing that so prior to that upgrade the config still didn't have any smtp settings. I did not see these same exceptions/restarts with the prior version I was on which was 0.4.9.

[ssalinas]

Fixed by #1004