title: ScheduledExecutorService behaving unexpectedly
body: <p>I have the following code snippet, using a <code>ScheduledExecutorService</code> to run every 3'000 milliseconds a check whether it should call a function <code>onOutTimeout()</code> or not. At least that's the idea.</p>
  
  <pre><code> private void launchOutTimeoutChecker(){
      Runnable check = new Runnable() {
          @Override
          public void run() {
              float bonus = 0;
              if(firstOutTime){bonus = timeout_initial_bonus;}
              float temp = System.currentTimeMillis() - lastOutTime;
              if(temp &lt; timeout + bonus){
                  if(Debug.logKeepalivePackets){
                      Log.d("keepalive", "firstOutTime: "+firstOutTime+"\ntime passed: "+temp);
                  }
                  // don't timeout yet, launch new execution
                  launchOutTimeoutChecker(); // yey recursion?!
              } else {
                  if(Debug.logKeepalivePackets){
                      Log.d("keepalive", "TIMEOUT!\nfirstOutTime: "+firstOutTime+"\ntime passed: "+temp);
                  }
                  onOutTimeout();
              }
          }
      };
  
      // before the first message, give a bonus of timeout_initial_bonus
      long bonus = 0;
      if(firstOutTime){bonus = timeout_initial_bonus;}
      long time_out = bonus + timeout;
      futureOut = executorOut.schedule(check, time_out, TimeUnit.MILLISECONDS);
  
      // the task is now scheduled. after the timeout will it check whether it should actually trigger a timeout.
      // the ScheduledFuture could be used to cancel this again
  }
  </code></pre>
  
  <p>Edit: where I set <code>lastOutTime</code> is in the run method of my (runnable) class. The method <code>lastInTimeoutChecker</code> does not print anything.</p>
  
  <pre><code>    @Override
  public void run() {
      // initialize executors that are used in launchOutTimeoutChecker and launchInTimeoutChecker
      executorIn = Executors.newSingleThreadScheduledExecutor();
      executorOut = Executors.newSingleThreadScheduledExecutor();
  
      // start the timers in new threads
      this.lastOutTime = System.currentTimeMillis();
      launchOutTimeoutChecker();
      this.lastInTime = System.currentTimeMillis();
      launchInTimeoutChecker();
  
  }
  </code></pre>
  
  <p>I would expect every 3 seconds to see a log message, because <code>timeout</code> is set to 3, and indeed the log message comes about every 3 seconds. <em>But</em> why is this output saying that the time passed is 0.0?</p>
  
  <pre><code>12-03 20:16:51.049 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:16:54.051 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:16:57.052 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:00.054 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:03.055 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:06.056 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:09.057 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:12.058 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:15.059 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:18.060 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:21.061 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:24.062 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:27.064 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:30.067 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:33.068 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:36.071 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:39.072 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:42.074 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: firstOutTime: false
                                                                            time passed: 0.0
  12-03 20:17:45.076 19578-19658/ch.ethz.inf.vs.a4.minker.einz D/keepalive: TIMEOUT!
                                                                            firstOutTime: false
                                                                            time passed: 131072.0
  </code></pre>
  
  <p>After about a minute, there is finally the message of a timeout, which I would have expected as the first log message. The number of time passed it says there is <strong>always exactly</strong> <code>131072</code> ms.</p>
  
  <p>I don't understand at all how I could go about debugging this. What I did:</p>
  
  <ul>
  <li><p>made sure only one instance of the surrounding class was running. Didn't change much (except that the output was now as you see it, instead of every message being duplicated, but otherwise everything was the same)</p></li>
  <li><p>made sure <code>lastOutTime</code> is only set once, right before calling <code>launchOutTimeoutChecker()</code> for the first time, setting it to <code>System.currentTimeMillis()</code></p></li>
  <li><p>firstOutTime is always false currently, so that part should be irrelevant</p></li>
  <li><p>At first, it worked as expected. Then I ran the same code in debug mode and this happened. Now the output as above also happens when I press the usual run.</p></li>
  <li><p>Rebuilding did not fix it</p></li>
  <li><p>Running it on a real device instead of the emulator exhibits the same behaviour.</p></li>
  <li><p>There doesn't seem to be a notable change in CPU usage or memory usage</p></li>
  </ul>
  
  <p>What is wrong with my code?</p>