add better logging

examples/main.go

@@ -12,11 +12,20 @@ import (
 	"syscall"
 	"time"
 
+	"log/slog"
 	"track-gopher/derby"
 	"track-gopher/web"
 )
 
 func main() {
+	// Create logger
+	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
+	// Use the logger
+	logger.Info("Starting derby race application")
+
 	// Parse command line flags
 	portName := flag.String("port", "/dev/ttyACM0", "Serial port for the derby clock")
 	baudRate := flag.Int("baud", 19200, "Baud rate for the serial port")
@@ -92,10 +101,14 @@ func main() {
 
 // startWebInterface initializes and runs the web interface
 func startWebInterface(clock *derby.DerbyClock, events <-chan derby.Event, webPort int, ctx context.Context) {
+	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
 	// Create and start the web server
 	server, err := web.NewServer(clock, events, webPort)
 	if err != nil {
-		fmt.Printf("Error creating web server: %v\n", err)
+		logger.Error("Error creating web server", "error", err)
 		return
 	}
 
@@ -103,7 +116,7 @@ func startWebInterface(clock *derby.DerbyClock, events <-chan derby.Event, webPo
 
 	// Start the web server
 	if err := server.Start(); err != nil {
-		fmt.Printf("Web server error: %v\n", err)
+		logger.Error("Web server error", "error", err)
 		return
 	}
 
@@ -111,9 +124,8 @@ func startWebInterface(clock *derby.DerbyClock, events <-chan derby.Event, webPo
 	<-ctx.Done()
 
 	// Gracefully shut down the server
-	fmt.Println("Shutting down web server...")
 	if err := server.Stop(); err != nil {
-		fmt.Printf("Error shutting down web server: %v\n", err)
+		logger.Error("Error shutting down web server", "error", err)
 	}
 }
 

web/server.go

@@ -7,8 +7,10 @@ import (
 	"fmt"
 	"io/fs"
 	"log"
+	"log/slog"
 	"net/http"
 	"net/url"
+	"os"
 	"strings"
 	"sync"
 	"time"
@@ -33,10 +35,16 @@ type Server struct {
 	port       int
 	server     *http.Server
 	shutdown   chan struct{}
+	logger     *slog.Logger
 }
 
 // NewServer creates a new web server
 func NewServer(clock *derby.DerbyClock, events <-chan derby.Event, port int) (*Server, error) {
+	// Create logger
+	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		Level: slog.LevelDebug,
+	}))
+
 	// Create server
 	s := &Server{
 		router:     chi.NewRouter(),
@@ -46,6 +54,7 @@ func NewServer(clock *derby.DerbyClock, events <-chan derby.Event, port int) (*S
 		clientsMux: sync.Mutex{},
 		port:       port,
 		shutdown:   make(chan struct{}),
+		logger:     logger,
 	}
 
 	// Set up routes
@@ -115,8 +124,9 @@ func (s *Server) Start() error {
 
 	// Start server in a goroutine
 	go func() {
+		s.logger.Info("Web server starting", "port", s.port)
 		if err := s.server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-			fmt.Printf("HTTP server error: %v\n", err)
+			s.logger.Error("HTTP server error", "error", err)
 		}
 	}()
 
@@ -140,6 +150,8 @@ func (s *Server) Stop() error {
 	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 	defer cancel()
 
+	s.logger.Info("Shutting down web server")
+
 	// Shutdown the HTTP server
 	if s.server != nil {
 		return s.server.Shutdown(ctx)
@@ -170,6 +182,7 @@ func (s *Server) broadcastEvent(event derby.Event) {
 
 	switch event.Type {
 	case derby.EventRaceStart:
+		s.logger.Info("Broadcasting race start event")
 		statusMsg := struct {
 			Status string `json:"status"`
 		}{
@@ -179,6 +192,11 @@ func (s *Server) broadcastEvent(event derby.Event) {
 		message = fmt.Sprintf("event: status\ndata: %s", statusJSON)
 
 	case derby.EventLaneFinish:
+		s.logger.Info("Broadcasting lane finish event",
+			"lane", event.Result.Lane,
+			"time", event.Result.Time,
+			"place", event.Result.FinishPlace)
+
 		// Create a message for lane finish
 		laneData := struct {
 			Lane  int     `json:"lane"`
@@ -193,6 +211,7 @@ func (s *Server) broadcastEvent(event derby.Event) {
 		message = fmt.Sprintf("event: lane-finish\ndata: %s", laneJSON)
 
 	case derby.EventRaceComplete:
+		s.logger.Info("Broadcasting race complete event")
 		statusMsg := struct {
 			Status string `json:"status"`
 		}{
@@ -208,13 +227,20 @@ func (s *Server) broadcastEvent(event derby.Event) {
 
 	// Send to all clients
 	s.clientsMux.Lock()
+	clientCount := len(s.clients)
+	sentCount := 0
 	for clientChan := range s.clients {
 		select {
 		case clientChan <- message:
+			sentCount++
 		default:
-			// Client channel is full, could log this
+			s.logger.Warn("Client channel is full, event not sent")
 		}
 	}
+	s.logger.Info("Event broadcast complete",
+		"sentCount", sentCount,
+		"totalClients", clientCount,
+		"eventType", event.Type)
 	s.clientsMux.Unlock()
 }
 
@@ -280,51 +306,55 @@ func (s *Server) handleEvents() http.HandlerFunc {
 		w.Header().Set("Connection", "keep-alive")
 		w.Header().Set("Access-Control-Allow-Origin", "*")
 
+		// Debug message to confirm connection
+		fmt.Fprintf(w, "event: debug\ndata: {\"message\":\"SSE connection established\"}\n\n")
+
+		// Flush headers to ensure they're sent to the client
+		if flusher, ok := w.(http.Flusher); ok {
+			flusher.Flush()
+		} else {
+			http.Error(w, "Streaming unsupported!", http.StatusInternalServerError)
+			return
+		}
+
 		// Create a channel for this client
 		clientChan := make(chan string, 10)
 
 		// Add client to map with mutex protection
 		s.clientsMux.Lock()
 		s.clients[clientChan] = true
+		clientCount := len(s.clients)
 		s.clientsMux.Unlock()
 
+		s.logger.Info("New client connected",
+			"clientIP", r.RemoteAddr,
+			"totalClients", clientCount)
+
 		// Remove client when connection is closed
 		defer func() {
 			s.clientsMux.Lock()
 			delete(s.clients, clientChan)
+			remainingClients := len(s.clients)
 			s.clientsMux.Unlock()
 			close(clientChan)
-		}()
-
-		// Send initial status
-		status := s.clock.Status()
-		var statusStr string
-		switch status {
-		case derby.StatusIdle:
-			statusStr = "idle"
-		case derby.StatusRunning:
-			statusStr = "running"
-		case derby.StatusFinished:
-			statusStr = "finished"
-		}
 
-		fmt.Fprintf(w, "event: status\ndata: {\"status\": \"%s\"}\n\n", statusStr)
-		w.(http.Flusher).Flush()
+			s.logger.Info("Client disconnected",
+				"clientIP", r.RemoteAddr,
+				"remainingClients", remainingClients)
+		}()
 
-		// Keep the connection open
+		// Keep connection open and send events as they arrive
 		for {
 			select {
-			case message, ok := <-clientChan:
+			case msg, ok := <-clientChan:
 				if !ok {
 					return
 				}
-
-				// Send the message to the client
-				fmt.Fprint(w, message)
-				w.(http.Flusher).Flush()
-
+				fmt.Fprintf(w, "%s\n\n", msg)
+				if flusher, ok := w.(http.Flusher); ok {
+					flusher.Flush()
+				}
 			case <-r.Context().Done():
-				// Client disconnected
 				return
 			}
 		}

web/templates/index.templ

@@ -41,48 +41,74 @@ templ Index() {
 		</div>
 		
 		<script>
+			console.log("Setting up SSE connection...");
+			
 			// Set up SSE connection
 			const eventSource = new EventSource('/api/events');
 			
+			eventSource.onopen = function() {
+				console.log("SSE connection opened");
+			};
+			
+			eventSource.onerror = function(error) {
+				console.error("SSE connection error:", error);
+			};
+			
+			eventSource.addEventListener('debug', function(event) {
+				console.log("Debug event received:", event.data);
+			});
+			
 			eventSource.addEventListener('lane-finish', function(event) {
 				console.log("Lane finish event received:", event.data);
-				const laneFinishData = JSON.parse(event.data);
-				const lane = document.getElementById(`lane-${laneFinishData.lane}`);
-				if (lane) {
-					lane.classList.add('finished');
-					lane.querySelector('.time').textContent = laneFinishData.time.toFixed(4);
-					
-					const placeEl = lane.querySelector('.place');
-					placeEl.textContent = `${getOrdinal(laneFinishData.place)} Place`;
-					placeEl.classList.remove('hidden');
+				try {
+					const laneFinishData = JSON.parse(event.data);
+					const lane = document.getElementById(`lane-${laneFinishData.lane}`);
+					if (lane) {
+						console.log(`Updating lane ${laneFinishData.lane} with time ${laneFinishData.time}`);
+						lane.classList.add('finished');
+						lane.querySelector('.time').textContent = laneFinishData.time.toFixed(4);
+						
+						const placeEl = lane.querySelector('.place');
+						placeEl.textContent = `${getOrdinal(laneFinishData.place)} Place`;
+						placeEl.classList.remove('hidden');
+					} else {
+						console.error(`Lane element not found for lane ${laneFinishData.lane}`);
+					}
+				} catch (error) {
+					console.error("Error processing lane finish event:", error);
 				}
 			});
 			
 			eventSource.addEventListener('status', function(event) {
-				const statusData = JSON.parse(event.data);
-				let statusText = 'Unknown';
-				let statusClass = 'bg-gray-500';
-				
-				if (statusData.status === 'idle') {
-					statusText = 'Ready';
-					statusClass = 'bg-blue-600';
+				console.log("Status event received:", event.data);
+				try {
+					const statusData = JSON.parse(event.data);
+					let statusText = 'Unknown';
+					let statusClass = 'bg-gray-500';
+					
+					if (statusData.status === 'idle') {
+						statusText = 'Ready';
+						statusClass = 'bg-blue-600';
+						
+						// Reset all lanes
+						document.querySelectorAll('.lane').forEach(lane => {
+							lane.classList.remove('finished');
+							lane.querySelector('.time').textContent = '--.--.---';
+							lane.querySelector('.place').classList.add('hidden');
+						});
+					} else if (statusData.status === 'running') {
+						statusText = 'Race Running';
+						statusClass = 'bg-green-600';
+					} else if (statusData.status === 'finished') {
+						statusText = 'Race Complete';
+						statusClass = 'bg-purple-600';
+					}
 					
-					// Reset all lanes
-					document.querySelectorAll('.lane').forEach(lane => {
-						lane.classList.remove('finished');
-						lane.querySelector('.time').textContent = '--.--.---';
-						lane.querySelector('.place').classList.add('hidden');
-					});
-				} else if (statusData.status === 'running') {
-					statusText = 'Race Running';
-					statusClass = 'bg-green-600';
-				} else if (statusData.status === 'finished') {
-					statusText = 'Race Complete';
-					statusClass = 'bg-purple-600';
+					document.getElementById('race-status').textContent = statusText;
+					document.getElementById('race-status').className = `px-4 py-2 rounded-full text-white ${statusClass}`;
+				} catch (error) {
+					console.error("Error processing status event:", error);
 				}
-				
-				document.getElementById('race-status').textContent = statusText;
-				document.getElementById('race-status').className = `px-4 py-2 rounded-full text-white ${statusClass}`;
 			});
 			
 			function getOrdinal(n) {

web/templates/index_templ.go

@@ -37,7 +37,7 @@ func Index() templ.Component {
 		if templ_7745c5c3_Err != nil {
 			return templ_7745c5c3_Err
 		}
-		templ_7745c5c3_Err = templruntime.WriteString(templ_7745c5c3_Buffer, 2, "</div><div class=\"flex justify-center space-x-4\"><button hx-post=\"/api/reset\" hx-swap=\"none\" class=\"bg-blue-500 hover:bg-blue-700 text-white font-bold py-2 px-4 rounded\">Reset Race</button> <button hx-post=\"/api/force-end\" hx-swap=\"none\" class=\"bg-red-500 hover:bg-red-700 text-white font-bold py-2 px-4 rounded\">Force End Race</button></div></div><script>\r\n\t\t\t// Set up SSE connection\r\n\t\t\tconst eventSource = new EventSource('/api/events');\r\n\t\t\t\r\n\t\t\teventSource.addEventListener('lane-finish', function(event) {\r\n\t\t\t\tconsole.log(\"Lane finish event received:\", event.data);\r\n\t\t\t\tconst laneFinishData = JSON.parse(event.data);\r\n\t\t\t\tconst lane = document.getElementById(`lane-${laneFinishData.lane}`);\r\n\t\t\t\tif (lane) {\r\n\t\t\t\t\tlane.classList.add('finished');\r\n\t\t\t\t\tlane.querySelector('.time').textContent = laneFinishData.time.toFixed(4);\r\n\t\t\t\t\t\r\n\t\t\t\t\tconst placeEl = lane.querySelector('.place');\r\n\t\t\t\t\tplaceEl.textContent = `${getOrdinal(laneFinishData.place)} Place`;\r\n\t\t\t\t\tplaceEl.classList.remove('hidden');\r\n\t\t\t\t}\r\n\t\t\t});\r\n\t\t\t\r\n\t\t\teventSource.addEventListener('status', function(event) {\r\n\t\t\t\tconst statusData = JSON.parse(event.data);\r\n\t\t\t\tlet statusText = 'Unknown';\r\n\t\t\t\tlet statusClass = 'bg-gray-500';\r\n\t\t\t\t\r\n\t\t\t\tif (statusData.status === 'idle') {\r\n\t\t\t\t\tstatusText = 'Ready';\r\n\t\t\t\t\tstatusClass = 'bg-blue-600';\r\n\t\t\t\t\t\r\n\t\t\t\t\t// Reset all lanes\r\n\t\t\t\t\tdocument.querySelectorAll('.lane').forEach(lane => {\r\n\t\t\t\t\t\tlane.classList.remove('finished');\r\n\t\t\t\t\t\tlane.querySelector('.time').textContent = '--.--.---';\r\n\t\t\t\t\t\tlane.querySelector('.place').classList.add('hidden');\r\n\t\t\t\t\t});\r\n\t\t\t\t} else if (statusData.status === 'running') {\r\n\t\t\t\t\tstatusText = 'Race Running';\r\n\t\t\t\t\tstatusClass = 'bg-green-600';\r\n\t\t\t\t} else if (statusData.status === 'finished') {\r\n\t\t\t\t\tstatusText = 'Race Complete';\r\n\t\t\t\t\tstatusClass = 'bg-purple-600';\r\n\t\t\t\t}\r\n\t\t\t\t\r\n\t\t\t\tdocument.getElementById('race-status').textContent = statusText;\r\n\t\t\t\tdocument.getElementById('race-status').className = `px-4 py-2 rounded-full text-white ${statusClass}`;\r\n\t\t\t});\r\n\t\t\t\r\n\t\t\tfunction getOrdinal(n) {\r\n\t\t\t\tconst s = [\"th\", \"st\", \"nd\", \"rd\"];\r\n\t\t\t\tconst v = n % 100;\r\n\t\t\t\treturn n + (s[(v-20)%10] || s[v] || s[0]);\r\n\t\t\t}\r\n\t\t</script></body></html>")
+		templ_7745c5c3_Err = templruntime.WriteString(templ_7745c5c3_Buffer, 2, "</div><div class=\"flex justify-center space-x-4\"><button hx-post=\"/api/reset\" hx-swap=\"none\" class=\"bg-blue-500 hover:bg-blue-700 text-white font-bold py-2 px-4 rounded\">Reset Race</button> <button hx-post=\"/api/force-end\" hx-swap=\"none\" class=\"bg-red-500 hover:bg-red-700 text-white font-bold py-2 px-4 rounded\">Force End Race</button></div></div><script>\r\n\t\t\tconsole.log(\"Setting up SSE connection...\");\r\n\t\t\t\r\n\t\t\t// Set up SSE connection\r\n\t\t\tconst eventSource = new EventSource('/api/events');\r\n\t\t\t\r\n\t\t\teventSource.onopen = function() {\r\n\t\t\t\tconsole.log(\"SSE connection opened\");\r\n\t\t\t};\r\n\t\t\t\r\n\t\t\teventSource.onerror = function(error) {\r\n\t\t\t\tconsole.error(\"SSE connection error:\", error);\r\n\t\t\t};\r\n\t\t\t\r\n\t\t\teventSource.addEventListener('debug', function(event) {\r\n\t\t\t\tconsole.log(\"Debug event received:\", event.data);\r\n\t\t\t});\r\n\t\t\t\r\n\t\t\teventSource.addEventListener('lane-finish', function(event) {\r\n\t\t\t\tconsole.log(\"Lane finish event received:\", event.data);\r\n\t\t\t\ttry {\r\n\t\t\t\t\tconst laneFinishData = JSON.parse(event.data);\r\n\t\t\t\t\tconst lane = document.getElementById(`lane-${laneFinishData.lane}`);\r\n\t\t\t\t\tif (lane) {\r\n\t\t\t\t\t\tconsole.log(`Updating lane ${laneFinishData.lane} with time ${laneFinishData.time}`);\r\n\t\t\t\t\t\tlane.classList.add('finished');\r\n\t\t\t\t\t\tlane.querySelector('.time').textContent = laneFinishData.time.toFixed(4);\r\n\t\t\t\t\t\t\r\n\t\t\t\t\t\tconst placeEl = lane.querySelector('.place');\r\n\t\t\t\t\t\tplaceEl.textContent = `${getOrdinal(laneFinishData.place)} Place`;\r\n\t\t\t\t\t\tplaceEl.classList.remove('hidden');\r\n\t\t\t\t\t} else {\r\n\t\t\t\t\t\tconsole.error(`Lane element not found for lane ${laneFinishData.lane}`);\r\n\t\t\t\t\t}\r\n\t\t\t\t} catch (error) {\r\n\t\t\t\t\tconsole.error(\"Error processing lane finish event:\", error);\r\n\t\t\t\t}\r\n\t\t\t});\r\n\t\t\t\r\n\t\t\teventSource.addEventListener('status', function(event) {\r\n\t\t\t\tconsole.log(\"Status event received:\", event.data);\r\n\t\t\t\ttry {\r\n\t\t\t\t\tconst statusData = JSON.parse(event.data);\r\n\t\t\t\t\tlet statusText = 'Unknown';\r\n\t\t\t\t\tlet statusClass = 'bg-gray-500';\r\n\t\t\t\t\t\r\n\t\t\t\t\tif (statusData.status === 'idle') {\r\n\t\t\t\t\t\tstatusText = 'Ready';\r\n\t\t\t\t\t\tstatusClass = 'bg-blue-600';\r\n\t\t\t\t\t\t\r\n\t\t\t\t\t\t// Reset all lanes\r\n\t\t\t\t\t\tdocument.querySelectorAll('.lane').forEach(lane => {\r\n\t\t\t\t\t\t\tlane.classList.remove('finished');\r\n\t\t\t\t\t\t\tlane.querySelector('.time').textContent = '--.--.---';\r\n\t\t\t\t\t\t\tlane.querySelector('.place').classList.add('hidden');\r\n\t\t\t\t\t\t});\r\n\t\t\t\t\t} else if (statusData.status === 'running') {\r\n\t\t\t\t\t\tstatusText = 'Race Running';\r\n\t\t\t\t\t\tstatusClass = 'bg-green-600';\r\n\t\t\t\t\t} else if (statusData.status === 'finished') {\r\n\t\t\t\t\t\tstatusText = 'Race Complete';\r\n\t\t\t\t\t\tstatusClass = 'bg-purple-600';\r\n\t\t\t\t\t}\r\n\t\t\t\t\t\r\n\t\t\t\t\tdocument.getElementById('race-status').textContent = statusText;\r\n\t\t\t\t\tdocument.getElementById('race-status').className = `px-4 py-2 rounded-full text-white ${statusClass}`;\r\n\t\t\t\t} catch (error) {\r\n\t\t\t\t\tconsole.error(\"Error processing status event:\", error);\r\n\t\t\t\t}\r\n\t\t\t});\r\n\t\t\t\r\n\t\t\tfunction getOrdinal(n) {\r\n\t\t\t\tconst s = [\"th\", \"st\", \"nd\", \"rd\"];\r\n\t\t\t\tconst v = n % 100;\r\n\t\t\t\treturn n + (s[(v-20)%10] || s[v] || s[0]);\r\n\t\t\t}\r\n\t\t</script></body></html>")
 		if templ_7745c5c3_Err != nil {
 			return templ_7745c5c3_Err
 		}
@@ -104,7 +104,7 @@ func laneComponent(lane int) templ.Component {
 		var templ_7745c5c3_Var4 string
 		templ_7745c5c3_Var4, templ_7745c5c3_Err = templ.JoinStringErrs("lane-" + string(rune('0'+lane)))
 		if templ_7745c5c3_Err != nil {
-			return templ.Error{Err: templ_7745c5c3_Err, FileName: `web/templates/index.templ`, Line: 105, Col: 45}
+			return templ.Error{Err: templ_7745c5c3_Err, FileName: `web/templates/index.templ`, Line: 131, Col: 45}
 		}
 		_, templ_7745c5c3_Err = templ_7745c5c3_Buffer.WriteString(templ.EscapeString(templ_7745c5c3_Var4))
 		if templ_7745c5c3_Err != nil {
@@ -117,7 +117,7 @@ func laneComponent(lane int) templ.Component {
 		var templ_7745c5c3_Var5 string
 		templ_7745c5c3_Var5, templ_7745c5c3_Err = templ.JoinStringErrs(string(rune('0' + lane)))
 		if templ_7745c5c3_Err != nil {
-			return templ.Error{Err: templ_7745c5c3_Err, FileName: `web/templates/index.templ`, Line: 106, Col: 72}
+			return templ.Error{Err: templ_7745c5c3_Err, FileName: `web/templates/index.templ`, Line: 132, Col: 72}
 		}
 		_, templ_7745c5c3_Err = templ_7745c5c3_Buffer.WriteString(templ.EscapeString(templ_7745c5c3_Var5))
 		if templ_7745c5c3_Err != nil {