JACOBIN-498 Initial work on new tracing facility (PR #243 from texada…

…ctyl)

JACOBIN-498 Initial work on new tracing facility. This will eventually replace the current logging system. (PR #243 from texadactyl)

src/classloader/classloader.go

@@ -840,12 +840,6 @@ func Init() error {
 
 	// Load the base jmod
 	GetBaseJmodBytes()
-	_, err := GetClassBytes("java.base.jmod", types.StringClassName)
-	if err != nil {
-		msg := fmt.Sprintf("classloader.Init: GetClassBytes failed for java/lang/String in java.base.jmod")
-		_ = log.Log(msg, log.SEVERE)
-		shutdown.Exit(shutdown.JVM_EXCEPTION)
-	}
 
 	// initialize the method area
 	InitMethodArea()

src/globals/globals.go

@@ -102,6 +102,13 @@ type Globals struct {
 	FuncFillInStackTrace func([]any) any
 }
 
+// ---- trace categories
+var TraceInit bool
+var TraceCloadi bool
+var TraceInst bool
+var TraceClass bool
+var TraceVerbose bool
+
 // ----- String Pool
 var StringPoolTable map[string]uint32
 var StringPoolList []string

src/trace/trace.go

@@ -0,0 +1,58 @@
+/*
+ * Jacobin VM - A Java virtual machine
+ * Copyright (c) 2021-2 by the Jacobin authors. All rights reserved.
+ * Licensed under Mozilla Public License 2.0 (MPL 2.0)
+ */
+
+package trace
+
+// The principal logging function. Note it currently logs to stderr.
+// At some future point, might allow the user to specify where logging should go.
+import (
+	"fmt"
+	"os"
+	"sync"
+	"time"
+)
+
+// Should never see an indication of an empty trace message!
+const EmptyMsg = "*** EMPTY LOGGING MESSAGE !!!"
+
+// Mutex for protecting the Log function during multithreading.
+var mutex = sync.Mutex{}
+
+// StartTime is the start time of this instance of the Jacoby VM.
+var StartTime time.Time
+
+// Initialize the trace frame.
+func Init() {
+	StartTime = time.Now()
+}
+
+// Trace is the principal tracing function. Note that it currently
+// writes to stderr. At some future point, this might become an option.
+func Trace(msg string) {
+
+	var err error
+
+	if len(msg) == 0 {
+		msg = EmptyMsg
+	}
+
+	// if the message is more low-level than a WARNING,
+	// prefix it with the elapsed time in millisecs.
+	duration := time.Since(StartTime)
+	var millis = duration.Milliseconds()
+
+	// Lock access to the logging stream to prevent inter-thread overwrite issues
+	mutex.Lock()
+	_, err = fmt.Fprintf(os.Stderr, "[%3d.%03ds] %s\n", millis/1000, millis%1000, msg)
+	mutex.Unlock()
+
+	// Report on stdout if stderr failed
+	if err != nil {
+		_, _ = fmt.Fprintf(os.Stdout, "[%3d.%03ds] *** stderr failed, err: %v\n", millis/1000, millis%1000, err)
+		_, _ = fmt.Fprintf(os.Stdout, "[%3d.%03ds] %s\n", millis/1000, millis%1000, msg)
+	}
+
+}

src/trace/trace_test.go

@@ -0,0 +1,118 @@
+/*
+ * Jacobin VM - A Java virtual machine
+ * Copyright (c) 2021 by the Jacobin authors. All rights reserved.
+ * Licensed under Mozilla Public License 2.0 (MPL 2.0)
+ */
+
+package trace
+
+import (
+	"io"
+	"jacobin/globals"
+	"os"
+	"strings"
+	"testing"
+)
+
+func initialize() {
+	globals.InitGlobals("test")
+	Init()
+}
+
+func TestEmptyTraceMessage(t *testing.T) {
+
+	initialize()
+
+	// Save existing stderr
+	savedStderr := os.Stderr
+
+	// Capture the writing done to stderr in a pipe
+	rdr, wrtr, _ := os.Pipe()
+	os.Stderr = wrtr
+	Trace("")
+	_ = wrtr.Close()
+
+	// Restore stderr to what it was before
+	os.Stderr = savedStderr
+
+	// Collect stderr output bytes --> string
+	outBytes, _ := io.ReadAll(rdr)
+	outString := string(outBytes[:])
+
+	// What we expected?
+	if !strings.Contains(outString, EmptyMsg) { // No
+		t.Errorf("Empty trace message failed: expected [%s] as a subset of [%s]\n", EmptyMsg, outString)
+	}
+
+}
+
+func TestValidTraceMessage(t *testing.T) {
+
+	initialize()
+
+	const expected = "Mary had a little lamb whose fleece was white as snow"
+
+	// Save existing stderr
+	savedStderr := os.Stderr
+
+	// Capture the writing done to stderr in a pipe
+	rdr, wrtr, _ := os.Pipe()
+	os.Stderr = wrtr
+	Trace(expected)
+	_ = wrtr.Close()
+
+	// Restore stderr to what it was before
+	os.Stderr = savedStderr
+
+	// Collect stderr output bytes --> string
+	outBytes, _ := io.ReadAll(rdr)
+	outString := string(outBytes[:])
+
+	// What we expected?
+	if !strings.Contains(outString, expected) { // No
+		t.Errorf("Nonempty trace message failed: expected [%s] as a subset of [%s]\n", EmptyMsg, outString)
+	}
+
+}
+
+func TestFailoverToStdout(t *testing.T) {
+
+	initialize()
+
+	const expected = "Mary had a little lamb whose fleece was white as snow"
+
+	// Save existing stderr
+	savedStderr := os.Stderr
+	savedStdout := os.Stdout
+
+	// Set up stderr from a pipe and then close it
+	_, wrtrErr, _ := os.Pipe()
+	os.Stderr = wrtrErr
+	err := os.Stderr.Close()
+	if err != nil {
+		os.Stderr = savedStderr
+		os.Stdout = savedStdout
+		t.Errorf("Failed to close os.Stderr, err: %v\n", err)
+	}
+
+	// Capture the writing done to stdout in a pipe
+	rdrOut, wrtrOut, _ := os.Pipe()
+	os.Stdout = wrtrOut
+
+	Trace(expected)
+	_ = wrtrOut.Close()
+
+	// Restore stderr to what it was before
+	os.Stderr = savedStderr
+	os.Stdout = savedStdout
+
+	// Collect stderr output bytes --> string
+	outBytes, _ := io.ReadAll(rdrOut)
+	outString := string(outBytes[:])
+
+	// What we expected?
+	if !strings.Contains(outString, expected) { // No
+		t.Errorf("Stdout trace message failed: expected [%s] as a subset of [%s]\n", EmptyMsg, outString)
+	}
+
+}