improve logging

cmd/proxy/main.go

@@ -3,6 +3,7 @@ package main
 import (
 	"bytes"
 	"context"
+	"errors"
 	"flag"
 	"fmt"
 	"io"
@@ -222,7 +223,7 @@ func (server *Server) handleRequest(w http.ResponseWriter, r *http.Request) {
 	ranged := r.Header.Get("Range") != ""
 
 	localStatus, mtime, err := server.checkLocal(w, r, fullpath)
-	slog.With("status", localStatus, "mtime", mtime, "error", err).Debug("local status checked")
+	slog.With("status", localStatus, "mtime", mtime, "error", err, "key", fullpath).Debug("local status checked")
 	if os.IsPermission(err) {
 		http.Error(w, err.Error(), http.StatusForbidden)
 	} else if err != nil {
@@ -403,11 +404,12 @@ func (server *Server) streamOnline(w http.ResponseWriter, r *http.Request, mtime
 
 		if response.ContentLength > 0 {
 			if memoryObject.Offset == int(response.ContentLength) && err != nil {
-				slog.With("length", memoryObject.Offset, "error", err, "upstreamIdx", selectedIdx).Debug("something happened during download. but response body is read as whole. so error is reset to nil")
+				if err != io.EOF {
+					slog.With("length", memoryObject.Offset, "error", err, "upstreamIdx", selectedIdx).Debug("something happened during download. but response body is read as whole. so error is reset to nil")
+				}
 				err = nil
 			}
 		} else if err == io.EOF {
-			slog.With("length", memoryObject.Offset, "error", err, "upstreamIdx", selectedIdx).Debug("something happened during download. content length is not specified and error is a eof. so error is reset to nil")
 			err = nil
 		}
 
@@ -514,7 +516,7 @@ func (server *Server) fastesUpstream(r *http.Request, lastModified time.Time) (r
 			}
 
 			if err != nil {
-				if err != context.Canceled && err != context.DeadlineExceeded {
+				if !errors.Is(err, context.Canceled) && !errors.Is(err, context.DeadlineExceeded) {
 					logger.With("error", err).Warn("upstream has error")
 				}
 				return
@@ -534,14 +536,10 @@ func (server *Server) fastesUpstream(r *http.Request, lastModified time.Time) (r
 
 				for cancelIdx, cancel := range cancelFuncs {
 					if cancelIdx == idx {
-						slog.With("upstreamIdx", cancelIdx).Debug("selected thus not canceled")
 						continue
 					}
-					slog.With("upstreamIdx", cancelIdx).Debug("not selected and thus canceled")
 					cancel()
 				}
-
-				logger.Debug("upstream is selected")
 			})
 
 			logger.Debug("voted")
@@ -549,13 +547,14 @@ func (server *Server) fastesUpstream(r *http.Request, lastModified time.Time) (r
 	}
 
 	wg.Wait()
-	slog.Debug("all upstream returned")
 
 	resultIdx = -1
 	select {
 	case idx := <-selectedCh:
 		resultIdx = idx
+		slog.With("upstreamIdx", resultIdx).Debug("upstream selected")
 	default:
+		slog.Debug("no valid upstream found")
 	}
 
 	return
@@ -564,19 +563,18 @@ func (server *Server) fastesUpstream(r *http.Request, lastModified time.Time) (r
 func (server *Server) tryUpstream(ctx context.Context, upstreamIdx int, r *http.Request, lastModified time.Time) (response *http.Response, chunks chan Chunk, err error) {
 	upstream := server.Upstreams[upstreamIdx]
 
-	logger := slog.With("upstreamIdx", upstreamIdx)
-
 	newpath, matched, err := upstream.GetPath(r.URL.Path)
-	logger.With(
-		"path", newpath,
-		"matched", matched,
-	).Debug("trying upstream")
 	if err != nil {
 		return nil, nil, err
 	}
 	if !matched {
 		return nil, nil, nil
 	}
+	logger := slog.With("upstreamIdx", upstreamIdx, "server", upstream.Server, "path", newpath)
+
+	logger.With(
+		"matched", matched,
+	).Debug("trying upstream")
 
 	newurl := upstream.Server + newpath
 	method := r.Method
@@ -588,9 +586,6 @@ func (server *Server) tryUpstream(ctx context.Context, upstreamIdx int, r *http.
 		return nil, nil, err
 	}
 	if lastModified != zeroTime {
-		logger.With(
-			"mtime", lastModified.Format(time.RFC1123),
-		).Debug("check modified since")
 		request.Header.Set("If-Modified-Since", lastModified.Format(time.RFC1123))
 	}
 
@@ -603,7 +598,6 @@ func (server *Server) tryUpstream(ctx context.Context, upstreamIdx int, r *http.
 	if err != nil {
 		return nil, nil, err
 	}
-	slog.With("status", response.StatusCode).Debug("responded")
 	if response.StatusCode == http.StatusNotModified {
 		return response, nil, nil
 	}
@@ -611,7 +605,7 @@ func (server *Server) tryUpstream(ctx context.Context, upstreamIdx int, r *http.
 		return nil, nil, nil
 	}
 	if response.StatusCode < 200 || response.StatusCode >= 500 {
-		slog.With(
+		logger.With(
 			"url", newurl,
 			"status", response.StatusCode,
 		).Warn("unexpected status")
@@ -643,7 +637,6 @@ func (server *Server) tryUpstream(ctx context.Context, upstreamIdx int, r *http.
 				currentOffset += int64(n)
 			}
 			if response.ContentLength > 0 && currentOffset == response.ContentLength && err == io.EOF || err == io.ErrUnexpectedEOF {
-				logger.Debug("done")
 				return
 			}
 			if err != nil {
@@ -718,5 +711,8 @@ func main() {
 
 	http.HandleFunc("GET /{path...}", server.handleRequest)
 	slog.With("addr", ":8881").Info("serving app")
-	http.ListenAndServe(":8881", nil)
+	if err := http.ListenAndServe(":8881", nil); err != nil {
+		slog.With("error", err).Error("failed to start server")
+		os.Exit(-1)
+	}
 }