<div dir="ltr">We had a weird and frustrating experience last night, 7/18/2018 from roughly 9:00 PM EST and on into 12:45 AM...<br><br>Here's the high-level:<br>2 Amazon instances of our Shibboleth IdP (one is literally a clone which we gave a different elastic ip to - it's our test IdP).<br>CentOS<br>IdP 3.3.2 running on Jetty<br>Been running fine for a year and a half.<br><br>Decided to run updates on OS.<br>We first took AWS snapshots of both servers before updates.<br>During business hours, I updated the "test" IdP VM. Updates completed successfully.<br>Rebooted. Tested. All is well. The exact procedure should be fine to do on Production IdP after hours.<br><br>Ran updates on Production IdP at 8 PM. Success.<br>Restarted Production IdP at 9 PM. Failure. shibbolth-idp not starting. Kept getting "Negative delay" message (see below).<br><br>That was odd, but it got worse.<br><br>Fell back to the non-updated Production IdP snapshot. Same thing, "Negative delay"<br>Tried yet another older snapshot taken back when server was built. "Negative delay"<br><br>Switched Elastic IP of Production to the cloned test IdP since Shibboleth-idp service was still running. That didn't take. Had to restart service. You guessed it, "Negative delay"<br>So now we were dead in the water.<br><br>Through all this, we were looking at logs. The frustrating part was, nothing useful was being logged. idp-process.log was not being written to through this entire ordeal (when restarting service). That was definitely not "normal."<br><br>Our clone had some debugging options turned on and yet idp-process.log on that server was also not budging.<br><br>And then, to top off the night, at around 1:05 AM, ALL of our AWS-based IdPs suddenly simply "worked" - after restarting shibboleth-idp service. Logs were being written to as well.<br><br>They all worked, production, clone, older snapshots (under other IPs so we could compare them all).<br><br>Where am I going with this?<br>1) Any one else experience any issues last night (AWS-based IdPs)? Yes, we created a ticket with them, nothing found yet.<br>2) Could it have been bad metadata from someone? We are federated with Incommon and have about 6 other SPs working successfully.<br>3) With none of the normal shibboleth logs producing any output, what other areas/logs could I troubleshoot?<br>4) "Negative delay"??<br><br><br>The thing is, we obviously had connectivity. It could be (probably is) an AWS thing. The other external variables would be the incoming metadata. It surely seems to be an external influence.<br><br>I'm digging into the issue now with a short night of sleep behind me.<br><br><br><br>[root@AWSanubis xxxxxxx]# service shibboleth-idp status<br>Redirecting to /bin/systemctl status shibboleth-idp.service<br> shibboleth-idp.service - Shibboleth Identity Provider<br>   Loaded: loaded (/etc/systemd/system/shibboleth-idp.service; enabled; vendor preset: disabled)<br>   Active: inactive (dead) since Wed 2018-07-18 23:47:01 EDT; 14min ago<br>  Process: 2166 ExecStart=/usr/bin/java -jar /opt/jetty/start.jar jetty.home=/opt/jetty jetty.base=/opt/shibboleth-idp/jetty-base (code=exited, status=0/SUCCESS)<br> Main PID: 2166 (code=exited, status=0/SUCCESS)<br><br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.xml.XmlConfiguration.configure(XmlConfigura...:259)<br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration...1504)<br>Jul 18 23:47:01 AWSanubis java[2166]: at java.security.AccessController.doPrivileged(Native Method)<br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration....1441)<br>Jul 18 23:47:01 AWSanubis java[2166]: Caused by: java.lang.IllegalArgumentException: Negative delay.<br>Jul 18 23:47:01 AWSanubis java[2166]: at java.util.Timer.schedule(Timer.java:192)<br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.util.RolloverFileOutputStream.scheduleNextR...:216)<br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.util.RolloverFileOutputStream.<init>(Rollov...:182)<br>Jul 18 23:47:01 AWSanubis java[2166]: at org.eclipse.jetty.util.RolloverFileOutputStream.<init>(Rollov...:124)<br>Jul 18 23:47:01 AWSanubis java[2166]: ... 15 more<br><br></div>