Redirect logs to stdout in replay mode and introduce deterministic Th…

…readLocalRandom (#35) * Print logs to console in replay mode. * Redirect logs to stdout in replay mode.
cmu-pasta · Aug 27, 2024 · 2467497 · 2467497
1 parent eabbd5b
commit 2467497
Show file tree

Hide file tree

Showing 10 changed files with 82 additions and 17 deletions.
diff --git a/core/src/main/kotlin/org/pastalab/fray/core/RunContext.kt b/core/src/main/kotlin/org/pastalab/fray/core/RunContext.kt
@@ -86,9 +86,11 @@ class RunContext(val config: Configuration) {
       if (config.exploreMode || config.noExitWhenBugFound) {
         return
       }
-      logger.error("Error found, the recording is saved to ${config.report}/recording_0/")
-      println("Error found, you may find the error report in ${config.report}")
-      config.saveToReportFolder(0)
+      if (!config.isReplay) {
+        logger.error("Error found, the recording is saved to ${config.report}/recording_0/")
+        println("Error found, you may find the error report in ${config.report}")
+        config.saveToReportFolder(0)
+      }
       exitProcess(0)
     }
   }
@@ -160,7 +162,7 @@ class RunContext(val config: Configuration) {
     mainExiting = false
     currentThreadId = t.id
     mainThreadId = t.id
-    registeredThreads[t.id] = ThreadContext(t, registeredThreads.size)
+    registeredThreads[t.id] = ThreadContext(t, registeredThreads.size, this)
     registeredThreads[t.id]?.state = ThreadState.Enabled
     scheduleNextOperation(true)
   }
@@ -186,7 +188,7 @@ class RunContext(val config: Configuration) {
       originalHanlder?.uncaughtException(t, e)
     }
     t.setUncaughtExceptionHandler(handler)
-    registeredThreads[t.id] = ThreadContext(t, registeredThreads.size)
+    registeredThreads[t.id] = ThreadContext(t, registeredThreads.size, this)
     syncManager.createWait(t, 1)
   }
 
@@ -903,4 +905,8 @@ class RunContext(val config: Configuration) {
     }
     return forkJoinPool!!
   }
+
+  fun getThreadLocalRandomProbe(): Int {
+    return registeredThreads[Thread.currentThread().id]!!.localRandomProbe
+  }
 }
diff --git a/core/src/main/kotlin/org/pastalab/fray/core/RuntimeDelegate.kt b/core/src/main/kotlin/org/pastalab/fray/core/RuntimeDelegate.kt
@@ -773,4 +773,11 @@ class RuntimeDelegate(val context: RunContext) : org.pastalab.fray.runtime.Deleg
     entered.set(false)
     return pool
   }
+
+  override fun onThreadLocalRandomGetProbe(probe: Int): Int {
+    if (checkEntered()) return probe
+    val probe = context.getThreadLocalRandomProbe()
+    entered.set(false)
+    return probe
+  }
 }
diff --git a/core/src/main/kotlin/org/pastalab/fray/core/TestRunner.kt b/core/src/main/kotlin/org/pastalab/fray/core/TestRunner.kt
@@ -20,6 +20,7 @@ class TestRunner(val config: Configuration) {
   }
 
   fun reportProgress(iteration: Int, bugsFound: Int) {
+    if (config.isReplay) return
     if (iteration % currentDivision == 0) {
       print("\u001B[2J")
       print("\u001B[2H")
@@ -89,6 +90,9 @@ class TestRunner(val config: Configuration) {
           println(
               "Error found at iter: $i, Elapsed time: ${(timeSource.markNow() - start).inWholeMilliseconds}ms",
           )
+          if (config.isReplay) {
+            break
+          }
           logger.error("Error found, the recording is saved to ${config.report}/recording_$i/")
           if (!config.exploreMode) {
             config.saveToReportFolder(i)

diff --git a/core/src/main/kotlin/org/pastalab/fray/core/ThreadContext.kt b/core/src/main/kotlin/org/pastalab/fray/core/ThreadContext.kt
@@ -11,7 +11,8 @@ enum class ThreadState {
   Completed,
 }
 
-class ThreadContext(val thread: Thread, val index: Int) {
+class ThreadContext(val thread: Thread, val index: Int, context: RunContext) {
+  val localRandomProbe = context.config.randomnessProvider.nextInt()
   var state = ThreadState.Paused
   var unparkSignaled = false
   var interruptSignaled = false

diff --git a/core/src/main/kotlin/org/pastalab/fray/core/command/Configuration.kt b/core/src/main/kotlin/org/pastalab/fray/core/command/Configuration.kt
@@ -243,13 +243,17 @@ data class Configuration(
     val builder = ConfigurationBuilderFactory.newConfigurationBuilder()
     builder.setConfigurationName("Fray")
     builder.setLoggerContext(LoggerContext("Fray"))
-    val appender =
-        builder
-            .newAppender("log", "File")
-            .addAttribute("fileName", "${report}/fray.log")
-            .addAttribute("append", false)
     val standard = builder.newLayout("PatternLayout")
     standard.addAttribute("pattern", "%d [%t] %-5level: %msg%n%throwable")
+    val appender =
+        if (isReplay) {
+          builder.newAppender("log", "Console").addAttribute("target", "SYSTEM_OUT").add(standard)
+        } else {
+          builder
+              .newAppender("log", "File")
+              .addAttribute("fileName", "${report}/fray.log")
+              .addAttribute("append", false)
+        }
     appender.add(standard)
     builder.add(appender)
     val logger = builder.newLogger("org.pastalab.fray", "INFO")

diff --git a/core/src/main/kotlin/org/pastalab/fray/core/observers/ScheduleVerifier.kt b/core/src/main/kotlin/org/pastalab/fray/core/observers/ScheduleVerifier.kt
@@ -18,16 +18,16 @@ class ScheduleVerifier(val schedules: List<ScheduleRecording>) : ScheduleObserve
     val enabled = enabledSchedules.map { it.index }.toList()
     val operation = scheduled.pendingOperation.toString()
     if (recording.scheduled != scheduledIndex) {
-      //      throw IllegalStateException(
-      //          "Scheduled index mismatch: expected ${recording.scheduled}, got $scheduledIndex")
+      throw IllegalStateException(
+          "Scheduled index mismatch: expected ${recording.scheduled}, got $scheduledIndex")
     }
     if (recording.enabled != enabled) {
-      //      throw IllegalStateException(
-      //          "Enabled schedules mismatch: expected ${recording.enabled}, got $enabled")
+      throw IllegalStateException(
+          "Enabled schedules mismatch: expected ${recording.enabled}, got $enabled")
     }
     if (recording.operation != operation) {
-      //      throw IllegalStateException(
-      //          "Operation mismatch: expected ${recording.operation}, got $operation")
+      throw IllegalStateException(
+          "Operation mismatch: expected ${recording.operation}, got $operation")
     }
     index++
   }

diff --git a/...umentation/base/src/main/kotlin/org/pastalab/fray/instrumentation/base/JDKInstrumenter.kt b/...umentation/base/src/main/kotlin/org/pastalab/fray/instrumentation/base/JDKInstrumenter.kt
@@ -45,6 +45,7 @@ fun instrumentClass(path: String, inputStream: InputStream): ByteArray {
     cv = CountDownLatchInstrumenter(cv)
     cv = MethodHandleNativesInstrumenter(cv)
     cv = TimedWaitInstrumenter(cv)
+    cv = ThreadLocalRandomInstrumenter(cv)
     // MonitorInstrumenter should come second because ObjectInstrumenter will insert more
     // monitors.
     cv = MonitorInstrumenter(cv)

diff --git a/...n/kotlin/org/pastalab/fray/instrumentation/base/visitors/ThreadLocalRandomInstrumenter.kt b/...n/kotlin/org/pastalab/fray/instrumentation/base/visitors/ThreadLocalRandomInstrumenter.kt
@@ -0,0 +1,32 @@
+package org.pastalab.fray.instrumentation.base.visitors
+
+import java.util.concurrent.ThreadLocalRandom
+import org.objectweb.asm.ClassVisitor
+import org.objectweb.asm.MethodVisitor
+import org.pastalab.fray.runtime.Runtime
+
+class ThreadLocalRandomInstrumenter(cv: ClassVisitor) :
+    ClassVisitorBase(cv, ThreadLocalRandom::class.java.name) {
+  override fun instrumentMethod(
+      mv: MethodVisitor,
+      access: Int,
+      name: String,
+      descriptor: String,
+      signature: String?,
+      exceptions: Array<out String>?
+  ): MethodVisitor {
+    if (name == "getProbe") {
+      return MethodExitVisitor(
+          mv,
+          Runtime::onThreadLocalRandomGetProbe,
+          access,
+          name,
+          descriptor,
+          false,
+          false,
+          false,
+      )
+    }
+    return mv
+  }
+}
diff --git a/runtime/src/main/java/org/pastalab/fray/runtime/Delegate.java b/runtime/src/main/java/org/pastalab/fray/runtime/Delegate.java
@@ -277,5 +277,9 @@ public int onObjectHashCode(Object t) {
     public ForkJoinPool onForkJoinPoolCommonPool(ForkJoinPool pool) {
         return pool;
     }
+
+    public int onThreadLocalRandomGetProbe(int probe) {
+        return probe;
+    }
 }
 
diff --git a/runtime/src/main/java/org/pastalab/fray/runtime/Runtime.java b/runtime/src/main/java/org/pastalab/fray/runtime/Runtime.java
@@ -4,6 +4,7 @@
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.ForkJoinPool;
 import java.util.concurrent.Semaphore;
+import java.util.concurrent.ThreadLocalRandom;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.locks.Condition;
 import java.util.concurrent.locks.Lock;
@@ -366,4 +367,9 @@ public static int onObjectHashCode(Object t) {
     public static ForkJoinPool onForkJoinPoolCommonPool(ForkJoinPool pool) {
         return DELEGATE.onForkJoinPoolCommonPool(pool);
     }
+
+    public static int onThreadLocalRandomGetProbe(int probe) {
+        return DELEGATE.onThreadLocalRandomGetProbe(probe);
+    }
+
 }