some bugfixes regarding timeouts in test scripts, with simplified code

tools/cooja/java/se/sics/cooja/GUI.java

@@ -34,6 +34,7 @@ import java.awt.Color;
 import java.awt.Component;
 import java.awt.Container;
 import java.awt.Dialog;
+import java.awt.Dialog.ModalityType;
 import java.awt.Dimension;
 import java.awt.Frame;
 import java.awt.GraphicsDevice;
@@ -41,7 +42,6 @@ import java.awt.GraphicsEnvironment;
 import java.awt.Point;
 import java.awt.Rectangle;
 import java.awt.Window;
-import java.awt.Dialog.ModalityType;
 import java.awt.event.ActionEvent;
 import java.awt.event.ActionListener;
 import java.awt.event.ComponentAdapter;
@@ -3051,7 +3051,12 @@ public class GUI extends Observable {
             System.exit(1);
           }
           plugin.updateScript(scriptFile);
+          try {
             plugin.setScriptActive(true);
+          } catch (Exception e) {
+            logger.fatal("Error: " + e.getMessage(), e);
+            System.exit(1);
+          }
           sim.setDelayTime(0);
           sim.startSimulation();
         } else {
@@ -3704,7 +3709,7 @@ public class GUI extends Observable {
   private static void showWarningsDialog(final Frame parent, final String[] warnings) {
     new RunnableInEDT<Boolean>() {
       public Boolean work() {
-        final JDialog dialog = new JDialog((Frame)parent, "Compilation warnings", false);
+        final JDialog dialog = new JDialog(parent, "Compilation warnings", false);
         Box buttonBox = Box.createHorizontalBox();
 
         /* Warnings message list */

tools/cooja/java/se/sics/cooja/plugins/LogScriptEngine.java

@@ -97,6 +97,11 @@ public class LogScriptEngine {
 
   private boolean scriptActive = false;
 
+  private long timeout;
+  private long startTime;
+  private long startRealTime;
+  private long nextProgress;
+
   private interface ScriptLog {
     public void log(String log);
     public void testOK();
@@ -104,6 +109,10 @@ public class LogScriptEngine {
     public void generateMessage(long delay, String msg);
   }
 
+  public LogScriptEngine(Simulation simulation) {
+    this.simulation = simulation;
+  }
+
   /* Only called from the simulation loop */
   private void stepScript() {
     /* Release script - halt simulation */
@@ -130,10 +139,6 @@ public class LogScriptEngine {
     }
   }
 
-  public LogScriptEngine(Simulation simulation) {
-    this.simulation = simulation;
-  }
-
   /* Only called from the simulation loop */
   private void handleNewMoteOutput(Mote mote, int id, long time, String msg) {
     try {
@@ -195,16 +200,6 @@ public class LogScriptEngine {
     }
     scriptActive = false;
 
-    if (semaphoreScript == null) {
-      /*logger.warn("semaphoreScript is not initialized");*/
-    }
-    if (semaphoreSim == null) {
-      /*logger.warn("semaphoreSim is not initialized");*/
-    }
-    if (scriptThread == null) {
-      /*logger.warn("scriptThread is not initialized");*/
-    }
-
     timeoutEvent.remove();
     timeoutProgressEvent.remove();
 
@@ -213,13 +208,17 @@ public class LogScriptEngine {
     engine.put("SHUTDOWN", true);
 
     try {
+      if (semaphoreScript != null) {
         semaphoreScript.release(100);
+      }
     } catch (Exception e) {
     } finally {
       semaphoreScript = null;
     }
     try {
+      if (semaphoreSim != null) {
         semaphoreSim.release(100);
+      }
     } catch (Exception e) {
     } finally {
       semaphoreSim = null;
@@ -235,7 +234,6 @@ public class LogScriptEngine {
       }
     }
     scriptThread = null;
-
   }
 
   public void activateScript(String scriptCode) throws ScriptException {
@@ -245,43 +243,29 @@ public class LogScriptEngine {
     scriptActive = true;
 
     if (semaphoreScript != null) {
-      logger.warn("semaphoreScript is already initialized");
+      logger.warn("Semaphores were not reset correctly");
+      semaphoreScript.release(100);
+      semaphoreScript = null;
     }
     if (semaphoreSim != null) {
-      logger.warn("semaphoreSim is already initialized");
+      logger.warn("Semaphores were not reset correctly");
-    }
+      semaphoreSim.release(100);
-    if (scriptThread != null) {
+      semaphoreSim = null;
-      logger.warn("scriptThread is already initialized");
     }
+    scriptThread = null;
 
     /* Parse current script */
     ScriptParser parser = new ScriptParser(scriptCode);
     String jsCode = parser.getJSCode();
 
-    long timeoutTime = parser.getTimeoutTime();
+    timeout = parser.getTimeoutTime();
-    if (timeoutTime < 0) {
+    if (timeout < 0) {
-      logger.info("No timeout defined, using default (us): " + DEFAULT_TIMEOUT);
+      timeout = DEFAULT_TIMEOUT;
-      timeoutTime = DEFAULT_TIMEOUT;
+      logger.info("Default script timeout in " + (timeout/Simulation.MILLISECOND) + " ms");
+    } else {
+      logger.info("Script timeout in " + (timeout/Simulation.MILLISECOND) + " ms");
     }
 
-    final long duration = timeoutTime;
-    simulation.invokeSimulationThread(new Runnable() {
-      public void run() {
-      	final long startTime = simulation.getSimulationTime();
-      	final long interval = (long) (0.01*5*duration);
-      	
-      	simulation.scheduleEvent(timeoutProgressEvent = new TimeEvent(0) {
-      		public void execute(long t) {
-      			int percent = (int) (5*(t-startTime)/interval);
-      			logger.info("Test script at " + percent + "%");
-      			simulation.scheduleEvent(this, t+interval);
-      		}
-      	}, startTime+interval);
-        
-        simulation.scheduleEvent(timeoutEvent, startTime + duration);
-      }
-    });
-
     engine.eval(jsCode);
 
     /* Setup script control */
@@ -352,7 +336,84 @@ public class LogScriptEngine {
     simulation.getEventCentral().addLogOutputListener(logOutputListener);
 
     /* Create script output logger */
-    engine.put("log", new ScriptLog() {
+    engine.put("log", scriptLog);
+
+    Hashtable<Object, Object> hash = new Hashtable<Object, Object>();
+    engine.put("global", hash);
+    engine.put("sim", simulation);
+    engine.put("gui", simulation.getGUI());
+
+    scriptMote = new ScriptMote();
+    engine.put("node", scriptMote);
+
+    Runnable activate = new Runnable() {
+      public void run() {
+        startRealTime = System.currentTimeMillis();
+        startTime = simulation.getSimulationTime();
+        long endTime = startTime + timeout;
+        nextProgress = startTime + (endTime - startTime)/20;
+
+        timeoutProgressEvent.remove();
+        simulation.scheduleEvent(timeoutProgressEvent, nextProgress);
+        timeoutEvent.remove();
+        simulation.scheduleEvent(timeoutEvent, endTime);
+      }
+    };
+    if (simulation.isRunning()) {
+      simulation.invokeSimulationThread(activate);
+    } else {
+      activate.run();
+    }
+  }
+
+  private TimeEvent timeoutEvent = new TimeEvent(0) {
+    public void execute(long t) {
+      if (!scriptActive) {
+        return;
+      }
+      logger.info("Timeout event @ " + t);
+      engine.put("TIMEOUT", true);
+      stepScript();
+    }
+  };
+  private TimeEvent timeoutProgressEvent = new TimeEvent(0) {
+    public void execute(long t) {
+      nextProgress = t + timeout/20;
+      simulation.scheduleEvent(this, nextProgress);
+
+      double progress = 1.0*(t - startTime)/timeout;
+      long realDuration = System.currentTimeMillis()-startRealTime;
+      double estimatedLeft = 1.0*realDuration/progress - realDuration;
+      if (estimatedLeft == 0) estimatedLeft = 1;
+      logger.info(String.format("Test script at %2.2f%%, done in %2.1f sec", 100*progress, estimatedLeft/1000));
+    }
+  };
+
+  private Runnable stopSimulationRunnable = new Runnable() {
+    public void run() {
+      simulation.stopSimulation();
+    }
+  };
+  private Runnable quitRunnable = new Runnable() {
+    public void run() {
+      simulation.stopSimulation();
+      new Thread() {
+        public void run() {
+          try { Thread.sleep(500); } catch (InterruptedException e) { }
+          simulation.getGUI().doQuit(false);
+        };
+      }.start();
+      new Thread() {
+        public void run() {
+          try { Thread.sleep(2000); } catch (InterruptedException e) { }
+          logger.warn("Killing COOJA");
+          System.exit(1);
+        };
+      }.start();
+    }
+  };
+
+  private ScriptLog scriptLog = new ScriptLog() {
     public void log(String msg) {
       if (scriptLogObserver != null) {
         scriptLogObserver.update(null, msg);
@@ -368,24 +429,6 @@ public class LogScriptEngine {
         logger.warn("Test append failed: " + filename + ": " + e.getMessage());
       }
     }
-      public void testOK() {
-        log("TEST OK\n");
-
-        if (GUI.isVisualized()) {
-          log("[if test was run without visualization, COOJA would now have been terminated]\n");
-          stopSimulation = true;
-          simulation.invokeSimulationThread(stopSimulationRunnable);
-        } else {
-          quitCooja = true;
-          simulation.invokeSimulationThread(quitRunnable);
-        }
-
-        timeoutEvent.remove();
-        timeoutProgressEvent.remove();
-
-        semaphoreSim.release(100);
-        throw new RuntimeException("test script killed");
-      }
     public void writeFile(String filename, String msg) {
       try{
         FileWriter fstream = new FileWriter(filename, false);
@@ -396,8 +439,17 @@ public class LogScriptEngine {
         logger.warn("Write file failed: " + filename + ": " + e.getMessage());
       }
     }
+
+    public void testOK() {
+      log("TEST OK\n");
+      deactive();
+    }
     public void testFailed() {
       log("TEST FAILED\n");
+      deactive();
+    }
+    private void deactive() {
+      deactivateScript();
 
       if (GUI.isVisualized()) {
         log("[if test was run without visualization, COOJA would now have been terminated]\n");
@@ -408,7 +460,6 @@ public class LogScriptEngine {
         simulation.invokeSimulationThread(quitRunnable);
       }
 
-        semaphoreSim.release(100);
       throw new RuntimeException("test script killed");
     }
 
@@ -440,55 +491,5 @@ public class LogScriptEngine {
         }
       });
     }
-    });
-
-    Hashtable<Object, Object> hash = new Hashtable<Object, Object>();
-    engine.put("global", hash);
-    engine.put("sim", simulation);
-    engine.put("gui", simulation.getGUI());
-
-    scriptMote = new ScriptMote();
-    engine.put("node", scriptMote);
-  }
-
-  private TimeEvent timeoutEvent = new TimeEvent(0) {
-    public void execute(long t) {
-    	if (!scriptActive) {
-    		return;
-    	}
-      logger.info("Timeout event @ " + t);
-      engine.put("TIMEOUT", true);
-      stepScript();
-    }
   };
-  private TimeEvent timeoutProgressEvent = new TimeEvent(0) {
-		public void execute(long t) { }
-	};
-  
-  private Runnable stopSimulationRunnable = new Runnable() {
-    public void run() {
-      simulation.stopSimulation();
-      timeoutEvent.remove();
-      timeoutProgressEvent.remove();
-    }
-  };
-  private Runnable quitRunnable = new Runnable() {
-    public void run() {
-      simulation.stopSimulation();
-      new Thread() {
-        public void run() {
-          try { Thread.sleep(500); } catch (InterruptedException e) { }
-          simulation.getGUI().doQuit(false);
-        };
-      }.start();
-      new Thread() {
-        public void run() {
-          try { Thread.sleep(2000); } catch (InterruptedException e) { }
-          logger.warn("Killing COOJA");
-          System.exit(1);
-        };
-      }.start();
-    }
-  };
-
 }

tools/cooja/java/se/sics/cooja/plugins/ScriptRunner.java

@@ -92,8 +92,7 @@ public class ScriptRunner extends VisPlugin {
 
   static boolean headless;
   {
-    GraphicsEnvironment ge = GraphicsEnvironment.getLocalGraphicsEnvironment();
+    headless = GraphicsEnvironment.isHeadless();
-    headless = ge.isHeadless();
     if (!headless) {
       DefaultSyntaxKit.initKit();
     }
@@ -183,11 +182,15 @@ public class ScriptRunner extends VisPlugin {
     toggleButton = new JButton("Activate");
     toggleButton.addActionListener(new ActionListener() {
       public void actionPerformed(ActionEvent ev) {
-        if (toggleButton.getText().equals("Activate")) {
+        try {
+          if (!isActive()) {
             setScriptActive(true);
           } else {
             setScriptActive(false);
           }
+        } catch (Exception e) {
+          logger.fatal("Error: " + e.getMessage(), e);
+        }
       }
     });
 
@@ -276,7 +279,8 @@ public class ScriptRunner extends VisPlugin {
     updateTitle();
   }
 
-  public void setScriptActive(boolean active) {
+  public void setScriptActive(boolean active)
+  throws Exception {
     if (active) {
       /* setScriptActive(true) */
 
@@ -612,7 +616,10 @@ public class ScriptRunner extends VisPlugin {
 
   }
   public void closePlugin() {
+    try {
       setScriptActive(false);
+    } catch (Exception e) {
+    }
   }
 
   public boolean setConfigXML(Collection<Element> configXML, boolean visAvailable) {
@@ -628,14 +635,22 @@ public class ScriptRunner extends VisPlugin {
       } else if ("active".equals(name)) {
         boolean active = Boolean.parseBoolean(element.getText());
         if (GUI.isVisualized()) {
+          try {
             setScriptActive(active);
+          } catch (Exception e) {
+            logger.fatal("Error: " + e.getMessage(), e);
+          }
         }
       }
     }
 
     if (!GUI.isVisualized()) {
       /* Automatically activate script */
+      try {
         setScriptActive(true);
+      } catch (Exception e) {
+        logger.fatal("Error: " + e.getMessage(), e);
+      }
       simulation.setDelayTime(0);
       simulation.startSimulation();
     }