fix bad logging due to wrong []byte used #28

Stop Process TTL goroutine when process is not ready (#28)

- fix issue where the goroutine will continue even though the child
  process is no longer running and the Process' state is not Ready
- fix issue where some logs were going to stdout instead of p.logMonitor
  causing them to not show up in the /logs
- add units to unloading model message

.gitignore

@@ -3,3 +3,4 @@
 build/
 dist/
 .vscode
+.DS_Store

Makefile

@@ -2,6 +2,16 @@
 APP_NAME = llama-swap
 BUILD_DIR = build
 
+# Get the current Git hash
+GIT_HASH := $(shell git rev-parse --short HEAD)
+ifneq ($(shell git status --porcelain),)
+    # There are untracked changes
+    GIT_HASH := $(GIT_HASH)+
+endif
+
+# Capture the current build date in RFC3339 format
+BUILD_DATE := $(shell date -u +"%Y-%m-%dT%H:%M:%SZ")
+
 # Default target: Builds binaries for both OSX and Linux
 all: mac linux simple-responder
 
@@ -18,12 +28,12 @@ test-all:
 # Build OSX binary
 mac:
 	@echo "Building Mac binary..."
-	GOOS=darwin GOARCH=arm64 go build -o $(BUILD_DIR)/$(APP_NAME)-darwin-arm64
+	GOOS=darwin GOARCH=arm64 go build -ldflags="-X main.commit=${GIT_HASH} -X main.version=local_${GIT_HASH} -X main.date=${BUILD_DATE}" -o $(BUILD_DIR)/$(APP_NAME)-darwin-arm64
 
 # Build Linux binary
 linux:
 	@echo "Building Linux binary..."
-	GOOS=linux GOARCH=amd64 go build -o $(BUILD_DIR)/$(APP_NAME)-linux-amd64
+	GOOS=linux GOARCH=amd64 go build -ldflags="-X main.commit=${GIT_HASH} -X main.version=local_${GIT_HASH} -X main.date=${BUILD_DATE}" -o $(BUILD_DIR)/$(APP_NAME)-linux-amd64
 
 # for testing proxy.Process
 simple-responder:
@@ -35,5 +45,19 @@ simple-responder:
 $(BUILD_DIR):
 	mkdir -p $(BUILD_DIR)
 
+# Create a new release tag
+release:
+	@echo "Checking for unstaged changes..."
+	@if [ -n "$(shell git status --porcelain)" ]; then \
+		echo "Error: There are unstaged changes. Please commit or stash your changes before creating a release tag." >&2; \
+		exit 1; \
+	fi
+
+# Get the highest tag in v{number} format, increment it, and create a new tag
+	@highest_tag=$$(git tag --sort=-v:refname | grep -E '^v[0-9]+$$' | head -n 1 || echo "v0"); \
+	new_tag="v$$(( $${highest_tag#v} + 1 ))"; \
+	echo "tagging new version: $$new_tag"; \
+	git tag "$$new_tag";
+
 # Phony targets
 .PHONY: all clean osx linux

README.md

@@ -2,19 +2,32 @@
 
 ![llama-swap header image](header.jpeg)
 
-llama-swap is a golang server that automatically swaps the llama.cpp server on demand. Since [llama.cpp's server](https://github.com/ggerganov/llama.cpp/tree/master/examples/server) can't swap models, let's swap the server instead!
+# Introduction
+llama-swap is an OpenAI API compatible server that gives you complete control over how you use your hardware. It automatically swaps to the configuration of your choice for serving a model. Since [llama.cpp's server](https://github.com/ggerganov/llama.cpp/tree/master/examples/server) can't swap models, let's swap the server instead!
 
 Features:
 
 - ✅ Easy to deploy: single binary with no dependencies
 - ✅ Single yaml configuration file
-- ✅ Automatic switching between models
+- ✅ On-demand model switching
-- ✅ Full control over llama.cpp server settings per model
+- ✅ Full control over server settings per model
 - ✅ OpenAI API support (`v1/completions` and `v1/chat/completions`)
 - ✅ Multiple GPU support
 - ✅ Run multiple models at once with `profiles`
 - ✅ Remote log monitoring at `/log`
 - ✅ Automatic unloading of models from GPUs after timeout
+- ✅ Use any local server that provides an OpenAI compatible API (llama.cpp, vllm, tabblyAPI, etc)
+
+## Releases
+
+Builds for Linux and OSX are available on the [Releases](https://github.com/mostlygeek/llama-swap/releases) page.
+
+### Building from source
+
+1. Install golang for your system
+1. `git clone git@github.com:mostlygeek/llama-swap.git`
+1. `make clean all`
+1. Binaries will be in `build/` subdirectory
 
 ## config.yaml
 
@@ -83,22 +96,22 @@ More [examples](examples/README.md) are available for different use cases.
 
 ## Monitoring Logs
 
-The `/logs` endpoint is available to monitor what llama-swap is doing. It will send the last 10KB of logs. Useful for monitoring the output of llama-server. It also supports streaming of logs.
+Open the `http://<host>/logs` with your browser to get a web interface with streaming logs.
 
-Usage:
+Of course, CLI access is also supported:
 
 ```
 # sends up to the last 10KB of logs
 curl http://host/logs'
 
-# streams logs using chunk encoding
+# streams logs
 curl -Ns 'http://host/logs/stream'
 
+# stream and filter logs with linux pipes
+curl -Ns http://host/logs/stream | grep 'eval time'
+
 # skips history and just streams new log entries
 curl -Ns 'http://host/logs/stream?no-history'
-
-# streams logs using Server Sent Events
-curl -Ns 'http://host/logs/streamSSE'
 ```
 
 ## Systemd Unit Files
@@ -125,9 +138,3 @@ StartLimitInterval=30
 [Install]
 WantedBy=multi-user.target
 ```
-
-## Building from Source
-
-1. Install golang for your system
-1. run `make clean all`
-1. binaries will be built into `build/` directory

examples/benchmark-snakegame/run-benchmark.sh

@@ -22,22 +22,19 @@ for model in "$@"; do
     echo -n "$model,"
 
     for lang in "python" "typescript" "swift"; do
-        response=$(curl -s --url "$url/v1/chat/completions" -d "{\"messages\": [{\"role\": \"system\", \"content\": \"you only write code.\"}, {\"role\": \"user\", \"content\": \"write snake game in $lang\"}], \"temperature\": 0.1, \"model\":\"$model\"}")
+        # expects a llama.cpp after PR https://github.com/ggerganov/llama.cpp/pull/10548
+        # (Dec 3rd/2024)
+        time=$(curl -s --url "$url/v1/chat/completions" -d "{\"messages\": [{\"role\": \"system\", \"content\": \"you only write code.\"}, {\"role\": \"user\", \"content\": \"write snake game in $lang\"}], \"top_k\": 1, \"timings_per_token\":true, \"model\":\"$model\"}" | jq -r .timings.predicted_per_second)
+
         if [ $? -ne 0 ]; then
             time="error"
-        else
+            exit 1
-            time=$(curl -s --url "$url/logs" | grep -oE '\d+(?:\.\d+)? tokens per second' | awk '{print $1}' | tail -n 1)
-            if [ $? -ne 0 ]; then
-                time="error"
-            fi
         fi
 
         if [ "$lang" != "swift" ]; then
-            echo -n "$time,"
+            printf "%0.2f tps," $time
         else
-            echo -n "$time"
+            printf "%0.2f tps\n" $time
         fi
     done
-
-    echo ""
 done

go.mod

@@ -32,9 +32,9 @@ require (
 	github.com/twitchyliquid64/golang-asm v0.15.1 // indirect
 	github.com/ugorji/go/codec v1.2.12 // indirect
 	golang.org/x/arch v0.8.0 // indirect
-	golang.org/x/crypto v0.23.0 // indirect
+	golang.org/x/crypto v0.31.0 // indirect
 	golang.org/x/net v0.25.0 // indirect
-	golang.org/x/sys v0.20.0 // indirect
+	golang.org/x/sys v0.28.0 // indirect
-	golang.org/x/text v0.15.0 // indirect
+	golang.org/x/text v0.21.0 // indirect
 	google.golang.org/protobuf v1.34.1 // indirect
 )

go.sum

@@ -66,14 +66,20 @@ golang.org/x/arch v0.8.0 h1:3wRIsP3pM4yUptoR96otTUOXI367OS0+c9eeRi9doIc=
 golang.org/x/arch v0.8.0/go.mod h1:FEVrYAQjsQXMVJ1nsMoVVXPZg6p2JE2mx8psSWTDQys=
 golang.org/x/crypto v0.23.0 h1:dIJU/v2J8Mdglj/8rJ6UUOM3Zc9zLZxVZwwxMooUSAI=
 golang.org/x/crypto v0.23.0/go.mod h1:CKFgDieR+mRhux2Lsu27y0fO304Db0wZe70UKqHu0v8=
+golang.org/x/crypto v0.31.0 h1:ihbySMvVjLAeSH1IbfcRTkD/iNscyz8rGzjF/E5hV6U=
+golang.org/x/crypto v0.31.0/go.mod h1:kDsLvtWBEx7MV9tJOj9bnXsPbxwJQ6csT/x4KIN4Ssk=
 golang.org/x/net v0.25.0 h1:d/OCCoBEUq33pjydKrGQhw7IlUPI2Oylr+8qLx49kac=
 golang.org/x/net v0.25.0/go.mod h1:JkAGAh7GEvH74S6FOH42FLoXpXbE/aqXSrIQjXgsiwM=
 golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.20.0 h1:Od9JTbYCk261bKm4M/mw7AklTlFYIa0bIp9BgSm1S8Y=
 golang.org/x/sys v0.20.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA=
+golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.15.0 h1:h1V/4gjBv8v9cjcR6+AR5+/cIYK5N/WAgiv4xlsEtAk=
 golang.org/x/text v0.15.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
+golang.org/x/text v0.21.0 h1:zyQAAkrwaneQ066sspRyJaG9VNi/YJ1NfzcGB3hZ/qo=
+golang.org/x/text v0.21.0/go.mod h1:4IBbMaMmOPCJ8SecivzSH54+73PCFmPWxNTLm+vZkEQ=
 google.golang.org/protobuf v1.34.1 h1:9ddQBjfCyZPOHPUiPxpYESBLc+T8P3E+Vo4IbKZgFWg=
 google.golang.org/protobuf v1.34.1/go.mod h1:c6P6GXX6sHbq/GpV6MGZEdwhWPcYBgnhAHhKbcUYpos=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=

llama-swap.go

@@ -9,13 +9,23 @@ import (
 	"github.com/mostlygeek/llama-swap/proxy"
 )
 
+var version string = "0"
+var commit string = "abcd1234"
+var date = "unknown"
+
 func main() {
 	// Define a command-line flag for the port
 	configPath := flag.String("config", "config.yaml", "config file name")
 	listenStr := flag.String("listen", ":8080", "listen ip/port")
+	showVersion := flag.Bool("version", false, "show version of build")
 
 	flag.Parse() // Parse the command-line flags
 
+	if *showVersion {
+		fmt.Printf("version: %s (%s), built at %s\n", version, commit, date)
+		os.Exit(0)
+	}
+
 	config, err := proxy.LoadConfig(*configPath)
 	if err != nil {
 		fmt.Printf("Error loading config: %v\n", err)

proxy/html/logs.html

@@ -0,0 +1,53 @@
+<!DOCTYPE html>
+<html lang="en">
+<head>
+    <meta charset="UTF-8">
+    <meta name="viewport" content="width=device-width, initial-scale=1.0">
+    <title>Logs</title>
+    <style>
+        body {
+            margin: 0;
+            height: 100vh;
+            display: flex;
+            flex-direction: column;
+            font-family: "Courier New", Courier, monospace;
+        }
+        #log-stream {
+            flex: 1;
+            margin: 1em;
+            padding: 10px;
+            background: #f4f4f4;
+            overflow-y: auto;
+            white-space: pre-wrap; /* Ensures line wrapping */
+            word-wrap: break-word; /* Ensures long words wrap */
+        }
+    </style>
+</head>
+<body>
+    <pre id="log-stream">Waiting for logs...
+</pre>
+
+    <script>
+        // Establish an EventSource connection to the SSE endpoint
+        if (typeof(EventSource) !== "undefined") {
+            const eventSource = new EventSource("/logs/streamSSE");
+
+            eventSource.onmessage = function(event) {
+                // Append the new log message to the <pre> element
+                const logStream = document.getElementById('log-stream');
+
+                logStream.textContent += event.data;
+
+                // Auto-scroll to the bottom
+                logStream.scrollTop = logStream.scrollHeight;
+            };
+
+            eventSource.onerror = function(err) {
+                console.error("EventSource failed:", err);
+            };
+        } else {
+            console.error("SSE not supported by this browser.");
+        }
+    </script>
+</body>
+</html>

proxy/logMonitor.go

@@ -46,7 +46,7 @@ func (w *LogMonitor) Write(p []byte) (n int, err error) {
 	w.buffer = w.buffer.Next()
 	w.bufferMu.Unlock()
 
-	w.broadcast(p)
+	w.broadcast(bufferCopy)
 	return n, nil
 }
 

proxy/process.go

@@ -122,17 +122,20 @@ func (p *Process) start() error {
 		// start a goroutine to check every second if
 		// the process should be stopped
 		go func() {
-			ticker := time.NewTicker(time.Second)
-			defer ticker.Stop()
 			maxDuration := time.Duration(p.config.UnloadAfter) * time.Second
 
-			for {
+			for range time.Tick(time.Second) {
-				<-ticker.C
+				if p.state != StateReady {
-				if time.Since(p.lastRequestHandled) > maxDuration {
-					fmt.Fprintf(p.logMonitor, "!!! Unloading model %s, TTL of %d reached.\n", p.ID, p.config.UnloadAfter)
-					p.Stop()
 					return
 				}
+
+				// wait for all inflight requests to complete and ticker
+				p.inFlightRequests.Wait()
+
+				if time.Since(p.lastRequestHandled) > maxDuration {
+					fmt.Fprintf(p.logMonitor, "!!! Unloading model %s, TTL of %ds reached.\n", p.ID, p.config.UnloadAfter)
+					p.Stop()
+				}
 			}
 		}()
 	}
@@ -163,25 +166,25 @@ func (p *Process) Stop() {
 	// will be a source of pain in the future.
 
 	p.cmd.Process.Signal(syscall.SIGTERM)
-	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+	sigtermTimeout, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 	defer cancel()
 
-	done := make(chan error, 1)
+	sigtermNormal := make(chan error, 1)
 	go func() {
-		done <- p.cmd.Wait()
+		sigtermNormal <- p.cmd.Wait()
 	}()
 
 	select {
-	case <-ctx.Done():
+	case <-sigtermTimeout.Done():
-		fmt.Printf("!!! process for %s timed out waiting to stop\n", p.ID)
+		fmt.Fprintf(p.logMonitor, "!!! process for %s timed out waiting to stop\n", p.ID)
 		p.cmd.Process.Kill()
 		p.cmd.Wait()
-	case err := <-done:
+	case err := <-sigtermNormal:
 		if err != nil {
 			if err.Error() != "wait: no child processes" {
 				// possible that simple-responder for testing is just not
 				// existing right, so suppress those errors.
-				fmt.Printf("!!! process for %s stopped with error > %v\n", p.ID, err)
+				fmt.Fprintf(p.logMonitor, "!!! process for %s stopped with error > %v\n", p.ID, err)
 			}
 		}
 	}
@@ -275,7 +278,11 @@ func (p *Process) checkHealthEndpoint(ctxFromStart context.Context) error {
 func (p *Process) ProxyRequest(w http.ResponseWriter, r *http.Request) {
 
 	p.inFlightRequests.Add(1)
-	defer p.inFlightRequests.Done()
+
+	defer func() {
+		p.lastRequestHandled = time.Now()
+		p.inFlightRequests.Done()
+	}()
 
 	if p.CurrentState() != StateReady {
 		if err := p.start(); err != nil {
@@ -285,8 +292,6 @@ func (p *Process) ProxyRequest(w http.ResponseWriter, r *http.Request) {
 		}
 	}
 
-	p.lastRequestHandled = time.Now()
-
 	proxyTo := p.config.Proxy
 	client := &http.Client{}
 	req, err := http.NewRequest(r.Method, proxyTo+r.URL.String(), r.Body)

proxy/process_test.go

@@ -82,18 +82,31 @@ func TestProcess_UnloadAfterTTL(t *testing.T) {
 	process := NewProcess("ttl", 2, config, NewLogMonitorWriter(io.Discard))
 	defer process.Stop()
 
-	req := httptest.NewRequest("GET", "/test", nil)
+	// this should take 4 seconds
+	req1 := httptest.NewRequest("GET", "/slow-respond?echo=1234&delay=1000ms", nil)
+	req2 := httptest.NewRequest("GET", "/test", nil)
+
 	w := httptest.NewRecorder()
 
-	// Proxy the request (auto start)
+	// Proxy the request (auto start) with a slow response that takes longer than config.UnloadAfter
-	process.ProxyRequest(w, req)
+	process.ProxyRequest(w, req1)
 
+	t.Log("sending slow first request (4 seconds)")
+	assert.Equal(t, http.StatusOK, w.Code, "Expected status code %d, got %d", http.StatusOK, w.Code)
+	assert.Contains(t, w.Body.String(), "1234")
+	assert.Equal(t, StateReady, process.CurrentState())
+
+	// ensure the TTL timeout does not race slow requests (see issue #25)
+	t.Log("sending second request (1 second)")
+	time.Sleep(time.Second)
+	w = httptest.NewRecorder()
+	process.ProxyRequest(w, req2)
 	assert.Equal(t, http.StatusOK, w.Code, "Expected status code %d, got %d", http.StatusOK, w.Code)
 	assert.Contains(t, w.Body.String(), expectedMessage)
-
 	assert.Equal(t, StateReady, process.CurrentState())
 
 	// wait 5 seconds
+	t.Log("sleep 5 seconds and check if unloaded")
 	time.Sleep(5 * time.Second)
 	assert.Equal(t, StateStopped, process.CurrentState())
 }

proxy/proxymanager_loghandlers.go

@@ -1,13 +1,34 @@
 package proxy
 
 import (
+	"embed"
 	"fmt"
 	"net/http"
+	"strings"
 
 	"github.com/gin-gonic/gin"
 )
 
+//go:embed html/logs.html
+var logsHTML []byte
+
+// make sure embed is kept there by the IDE auto-package importer
+var _ = embed.FS{}
+
 func (pm *ProxyManager) sendLogsHandlers(c *gin.Context) {
+
+	accept := c.GetHeader("Accept")
+	if strings.Contains(accept, "text/html") {
+		// Set the Content-Type header to text/html
+		c.Header("Content-Type", "text/html")
+
+		// Write the embedded HTML content to the response
+		_, err := c.Writer.Write(logsHTML)
+		if err != nil {
+			c.AbortWithError(http.StatusInternalServerError, fmt.Errorf("failed to write response: %v", err))
+			return
+		}
+	} else {
 		c.Header("Content-Type", "text/plain")
 		history := pm.logMonitor.GetHistory()
 		_, err := c.Writer.Write(history)
@@ -15,6 +36,7 @@ func (pm *ProxyManager) sendLogsHandlers(c *gin.Context) {
 			c.AbortWithError(http.StatusInternalServerError, err)
 			return
 		}
+	}
 }
 
 func (pm *ProxyManager) streamLogsHandler(c *gin.Context) {